Suite log upgrade.

[oliver-sanders]

Closes #846
Closes #1446
To be merged after metomi/rose#1955

Suite logging is now handled by the logging module. Log files are symlinked rather than renamed and are rolled over together as soon as any one reaches the size threshold.

Note:

• Suite log file are now named with a timestamp (e.g. log.20160808T1245)
  • cylc cat-log updated to handle new naming system
  • cylc gui updated to handle new naming system
  • rose bush to be updated by rose bush: add rotated log files to the "cylc files" menu metomi/rose#1955
• Output sent to stdout/stderr will still appear in the log files though will not receive the same formatting or trigger log file rolling
• Multi-line log messages should now be written in a single log entry with line breaks \n which will be automatically expanded to \n\t (customisable)

Results of profiling for the 'busy' suite (over one cycle) show no significant change

branch    memory @ begin run while loop (kiB)    cpu (s)
--------------------------------------------------------
846...    51492                                  444.486
846...    51484                                  437.548
846...    54028                                  444.332
master    54000                                  455.467
master    53436                                  441.757
master    51412                                  433.747

Hopefully I have caught all the relevant print / sys.std???.write() statements (if any remain the messages will still make it to the suite logs).

@hjoliver Please review / reassign
@arjclark Please review / reassign

[oliver-sanders]

Resolved conflicts.

[hjoliver]

The TODO comment is obsolete?

[hjoliver]

Looks good, tests as working. A minor problem, and a question:

• Travis CI says pep8 failed (I cloned your branch, rebased it, and pushed it to my fork: https://travis-ci.org/hjoliver/cylc/builds/154324103#L364 )
• Should we timestamp stdout messages too (currently just log and err are timestamped)?

[oliver-sanders]

• Tests were passing with our outdated pep8, have updated to pass on Travis
• We could format stdout if desired, should be fairly quick, if so do we want it formatted the same way as log and err (i.e '%(asctime)s %(levelname)-2s - %(message)s')?

[hjoliver]

We could format stdout if desired,..

I can't really think of a good reason not to. @cylc/core - any opinions on this?

[oliver-sanders]

One point to consider is that many tests use cmp_ok on stdout. If we add timestamps this will no longer work, could potentially be fixed by cylc run suite --no-timestamps or something similar.

[oliver-sanders]

No opinions hopefully means no objections?
Ignore accidental close.

[arjclark]

No opinions hopefully means no objections.

Wouldn't count on it...

[hjoliver]

No opinions hopefully means no objections.

Wouldn't count on it...

@arjclark - can you follow through on this comment? This is a nice improvement as is, so I don't mind if we leave stdout as is, format it with this PR, or add formatting later.

[arjclark]

can you follow through on this comment?

We're in the middle of holidays at the moment with people all over the place so I suspect a few of us haven't had time to read this yet. Personally, it makes sense to me to do what @oliver-sanders is suggesting though 👍

[arjclark]

Now discussed and we're happy with @oliver-sanders's proposal.

[oliver-sanders]

The out log is now formatted the same way as err and log. Only one test was broken which I have fixed by adding a greps-ok function.

[hjoliver]

A couple of problems noticed:

• If I try to run a suite that is already running, the "port file exists" error runs into trouble:

$ cylc run states
No handlers could be found for logger "err"
Traceback (most recent call last):
  File "/home/oliverh/cylc/cylc.git/bin/cylc-run", line 31, in <module>
    main(is_restart=False)
  File "/home/oliverh/cylc/cylc.git/lib/cylc/scheduler_cli.py", line 71, in main
    scheduler.start()
  File "/home/oliverh/cylc/cylc.git/lib/cylc/scheduler.py", line 229, in start
    self._check_port_file_does_not_exist(self.suite)
  File "/home/oliverh/cylc/cylc.git/lib/cylc/scheduler.py", line 357, in _check_port_file_does_not_exist
    "ERROR, port file exists: %s" % port_file_path)
cylc.scheduler.SchedulerError: 'ERROR, port file exists: /home/oliverh/.cylc/ports/states'

• Some messages seem to go to log and err without any priority (also on master, but we could fix it here). On this branch they're also being prefixed by a tab character, which looks odd. E.g. from running examples/task-states/:

2016-09-04T21:47:14Z ERROR - [bad_good.2012-08-09T00] -submission failed
2016-09-04T21:47:14Z CRITICAL - [m_x.2012-08-08T00] -(current:running)> Task job script received signal EXIT at 2016-09-04T21:47:12Z
2016-09-04T21:47:14Z CRITICAL - [m_x.2012-08-08T00] -(current:running)> failed at 2016-09-04T21:47:12Z
2016-09-04T21:47:18Z ERROR - [bad2.2012-08-09T00] -2016-09-04T21:47:18Z [job-submit cmd] (prepare job file)
    2016-09-04T21:47:18Z [job-submit ret_code] 1
    2016-09-04T21:47:18Z [job-submit err] No module named fail

[oliver-sanders]

• The traceback was introduced by cylc.rundb: replace state dump #1827, have included a fix in this PR (256381a).
• Fixed No handlers could be found for logger "err" message from the same output. These messages occur where logging code is executed where the suite logging has not been initiated and should not be present in output.
• Addressed the output formatting issue seen in the task-states suite (see below)

Changes made to job-submit log lines:

• Timestamps removed
• Blank lines removed

Old:

2016-09-07T17:03:49+01 DEBUG - 2016-09-07T17:03:48+01 [jobs-submit cmd] cylc jobs-submit --debug -- /home/h06/osanders/cylc-run/task-states/log/job 20120809T0000+01/bad/01 20120810T0000+01/foo/01
2016-09-07T17:03:48+01 [jobs-submit ret_code] 0
2016-09-07T17:03:48+01 [jobs-submit out]

[TASK JOB SUMMARY]2016-09-07T17:03:48+01|20120809T0000+01/bad/01|0|32280
[TASK JOB COMMAND]2016-09-07T17:03:48+01|20120809T0000+01/bad/01|[STDOUT] 32280

New:

2016-09-07T16:50:23+01 DEBUG - [jobs-submit cmd] cylc jobs-submit --debug -- /home/h06/osanders/cylc-run/task-states/log/job 20120808T0000+01/m2/01
    [jobs-submit ret_code] 0
    [jobs-submit out]
    [TASK JOB SUMMARY]2016-09-07T16:50:23+01|20120808T0000+01/m2/01|0|24912
    [TASK JOB COMMAND]2016-09-07T16:50:23+01|20120808T0000+01/m2/01|[STDOUT] 24912

[hjoliver]

Looks good, just one very minor issue now: double ERROR on attempting to start an already-running suite:

$ cylc run --no-detach states
ERROR - ERROR: port file exists: /home/oliverh/.cylc/ports/states
...

[oliver-sanders]

Fixed ERROR - ERROR: message, resolved conflicts.

[hjoliver]

All good here, over to @arjclark

[oliver-sanders]

Rebased.