suite logging: restart can write to old log

[oliver-sanders]

The issue is caused by the redirection in daemonize() which latches onto the file handler before the suite logs have been initalised and thus before the logs have been rolled. This means that output after restart can appear in both the log from the previous run.

Initialising the suite logs before the daemonize() function fixes this. I need to test this more thoroughly before putting up a pull request.

Test to detect this issue:

tests/logging/02-duplicates.t

#!/bin/bash
# THIS FILE IS PART OF THE CYLC SUITE ENGINE.
# Copyright (C) 2008-2017 NIWA
#
# This program is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program.  If not, see <http://www.gnu.org/licenses/>.
#-------------------------------------------------------------------------------
. $(dirname $0)/test_header
#-------------------------------------------------------------------------------
set_test_number 3
#-------------------------------------------------------------------------------
install_suite "${TEST_NAME_BASE}" "${TEST_NAME_BASE}"
gcylc ${SUITE_NAME} &
suite_run_ok "${TEST_NAME_BASE}-run" cylc run "${SUITE_NAME}"
while cylc ping "${SUITE_NAME}" 2>/dev/null; do
    sleep 1
done
sleep 8
suite_run_ok "${TEST_NAME_BASE}-restart" cylc restart "${SUITE_NAME}"
while cylc ping "${SUITE_NAME}" 2>/dev/null; do
    sleep 1
done
if [[ -e "${SUITE_RUN_DIR}/work/2/pub/test-succeeded" ]]; then
    ok "${TEST_NAME_BASE}-check"
else
    fail "${TEST_NAME_BASE}-check"
    echo 'OUT - Duplicated Entries:' >&2
    cat "${SUITE_RUN_DIR}/work/2/pub/out-duplication" >&2
    echo 'ERR - Duplicated Entries:' >&2
    cat "${SUITE_RUN_DIR}/work/2/pub/err-duplication" >&2
    echo 'LOG - Duplicated Entries:' >&2
    cat "${SUITE_RUN_DIR}/work/2/pub/log-duplication" >&2
fi

#-------------------------------------------------------------------------------
#purge_suite "${SUITE_NAME}"
exit

tests/logging/02-duplicates/suite.rc

[scheduling]
    cycling mode = integer
    initial cycle point = 1
    [[dependencies]]
        [[[R1/1]]]
            graph = """
                foo:fail => bar
                foo & bar => restart
            """
        [[[R1/2]]]
            graph = """
                restart[-P1] => foo
                foo:fail => bar
                foo & bar => pub
            """
[runtime]
    [[foo]]
        script = false
    [[bar]]
        script = """
cylc reset "${CYLC_SUITE_NAME}" "foo.${CYLC_TASK_CYCLE_POINT}" -s succeeded
"""
    [[restart]]
        script = """
cylc stop "${CYLC_SUITE_NAME}"
"""
    [[pub]]
        script = """
# Extract timestamp lines from logs
for file in $(find "${CYLC_SUITE_RUN_DIR}/log/suite/" -name '*.*'); do
    if $(grep '.*-.*-.*' "${file}"); then
        grep '.*-.*-.*' "${file}" | sort -u > $(basename $file)
    else
        touch $(basename $file)
    fi
done

# Write out duplicate entries to *-duplication files.
sort $(find . -name 'out*') | uniq -d > out-duplication
sort $(find . -name 'err*') | uniq -d > err-duplication
sort $(find . -name 'log*') | uniq -d > log-duplication

# Fail if any of these files contain any content.
if [[ -s out-duplication || -s err-duplication || -s log-duplication ]]; then
    touch 'test-failed'
else
    touch 'test-succeeded'
fi
"""

[hjoliver]

(yes, let's get this fixed and get 7.5.0 out the door...)