Turn log timestamps back on before running Cylc Play in VIP & VR

CHANGES.md

@@ -9,6 +9,15 @@ creating a new release entry be sure to copy & paste the span tag with the
 `actions:bind` attribute, which is used by a regex to find the text to be
 updated. Only the first match gets replaced, so it's fine to leave the old
 ones in. -->
+
+-------------------------------------------------------------------------------
+## __cylc-8.1.5 (<span actions:bind='release-date'>Upcoming</span>)__
+
+### Fixes
+
+[#5524](https://github.com/cylc/cylc-flow/pull/5524) - Logging includes timestamps
+for `cylc play` when called by `cylc vip` or `cylc vr`.
+
 -------------------------------------------------------------------------------
 ## __cylc-8.1.4 (<span actions:bind='release-date'>Released 2023-05-04</span>)__
 

cylc/flow/loggingutil.py

@@ -333,11 +333,11 @@ def re_formatter(log_string):
     return log_string
 
 
-def disable_timestamps(logger: logging.Logger) -> None:
-    """For readability omit timestamps from logging."""
+def set_timestamps(logger: logging.Logger, enable: bool) -> None:
+    """Enable or disable logging timestamps."""
     for handler in logger.handlers:
         if isinstance(handler.formatter, CylcLogFormatter):
-            handler.formatter.configure(timestamp=False)
+            handler.formatter.configure(timestamp=enable)
 
 
 def setup_segregated_log_streams(

cylc/flow/scripts/clean.py

@@ -67,7 +67,7 @@
 from cylc.flow.exceptions import CylcError, InputError
 import cylc.flow.flags
 from cylc.flow.id_cli import parse_ids_async
-from cylc.flow.loggingutil import disable_timestamps
+from cylc.flow.loggingutil import set_timestamps
 from cylc.flow.option_parsers import (
     WORKFLOW_ID_MULTI_ARG_DOC,
     CylcOptionParser as COP,
@@ -209,7 +209,7 @@ async def run(*ids: str, opts: 'Values') -> None:
 @cli_function(get_option_parser)
 def main(_, opts: 'Values', *ids: str):
     if cylc.flow.flags.verbosity < 2:
-        disable_timestamps(LOG)
+        set_timestamps(LOG, False)
 
     if opts.local_only and opts.remote_only:
         raise InputError(

cylc/flow/scripts/get_resources.py

@@ -43,7 +43,7 @@
 
 from cylc.flow import LOG
 import cylc.flow.flags
-from cylc.flow.loggingutil import disable_timestamps
+from cylc.flow.loggingutil import set_timestamps
 from cylc.flow.option_parsers import CylcOptionParser as COP
 from cylc.flow.resources import get_resources, list_resources
 from cylc.flow.terminal import cli_function
@@ -75,7 +75,7 @@ def get_option_parser():
 @cli_function(get_option_parser)
 def main(parser, opts, resource=None, tgt_dir=None):
     if cylc.flow.flags.verbosity < 2:
-        disable_timestamps(LOG)
+        set_timestamps(LOG, False)
     if not resource or opts.list:
         list_resources()
         sys.exit(0)

cylc/flow/scripts/validate.py

@@ -40,7 +40,7 @@
 )
 import cylc.flow.flags
 from cylc.flow.id_cli import parse_id_async
-from cylc.flow.loggingutil import disable_timestamps
+from cylc.flow.loggingutil import set_timestamps
 from cylc.flow.option_parsers import (
     AGAINST_SOURCE_OPTION,
     WORKFLOW_ID_OR_PATH_ARG_DOC,
@@ -144,7 +144,7 @@ async def wrapped_main(
     profiler.start()
 
     if cylc.flow.flags.verbosity < 2:
-        disable_timestamps(LOG)
+        set_timestamps(LOG, False)
 
     workflow_id, _, flow_file = await parse_id_async(
         workflow_id,

cylc/flow/scripts/validate_install_play.py

@@ -35,7 +35,9 @@
 from cylc.flow.scripts.install import (
     INSTALL_OPTIONS, install_cli as cylc_install, get_source_location
 )
+from cylc.flow import LOG
 from cylc.flow.scheduler_cli import PLAY_OPTIONS
+from cylc.flow.loggingutil import set_timestamps
 from cylc.flow.option_parsers import (
     CylcOptionParser as COP,
     combine_options,
@@ -79,6 +81,7 @@ def get_option_parser() -> COP:
         # no sense in a VIP context.
         if option.kwargs.get('dest') != 'against_source':
             parser.add_option(*option.args, **option.kwargs)
+
     return parser
 
 
@@ -87,10 +90,8 @@ def main(parser: COP, options: 'Values', workflow_id: Optional[str] = None):
     """Run Cylc validate - install - play in sequence."""
     if not workflow_id:
         workflow_id = '.'
-
     orig_source = workflow_id
     source = get_source_location(workflow_id)
-
     log_subcommand('validate', source)
     validate_main(parser, options, str(source))
 
@@ -109,5 +110,6 @@ def main(parser: COP, options: 'Values', workflow_id: Optional[str] = None):
         source=orig_source,
     )
 
+    set_timestamps(LOG, options.log_timestamp)
     log_subcommand('play', workflow_id)
     _play(parser, options, workflow_id)

cylc/flow/scripts/validate_reinstall.py

@@ -48,6 +48,7 @@
 from cylc.flow import LOG
 from cylc.flow.exceptions import ServiceFileError
 from cylc.flow.id_cli import parse_id
+from cylc.flow.loggingutil import set_timestamps
 from cylc.flow.option_parsers import (
     WORKFLOW_ID_ARG_DOC,
     CylcOptionParser as COP,
@@ -177,6 +178,7 @@ def vro_cli(parser: COP, options: 'Values', workflow_id: str):
 
     # run play anyway, to play a stopped workflow:
     else:
+        set_timestamps(LOG, options.log_timestamp)
         cleanup_sysargv(
             'play',
             unparsed_wid,

tests/unit/test_loggingutil.py

@@ -20,6 +20,8 @@
 from time import sleep
 import pytest
 from pytest import param
+import re
+import sys
 from typing import Callable
 from unittest import mock
 
@@ -28,7 +30,8 @@
     RotatingLogFileHandler,
     CylcLogFormatter,
     get_reload_start_number,
-    get_sorted_logs_by_time
+    get_sorted_logs_by_time,
+    set_timestamps,
 )
 
 
@@ -173,3 +176,24 @@ def test_get_reload_number_no_logs(tmp_run_dir: Callable):
     config_log_dir.mkdir(exist_ok=True, parents=True)
     config_logs = get_sorted_logs_by_time(config_log_dir, "*.cylc")
     assert get_reload_start_number(config_logs) == '01'
+
+
+def test_set_timestamps(capsys):
+    """The enable and disable timstamp methods do what they say"""
+    # Setup log handler
+    log_handler = logging.StreamHandler(sys.stderr)
+    log_handler.setFormatter(CylcLogFormatter())
+    LOG.addHandler(log_handler)
+
+    # Log some messages with timestamps on or off:
+    LOG.warning('foo')
+    set_timestamps(LOG, False)
+    LOG.warning('bar')
+    set_timestamps(LOG, True)
+    LOG.warning('baz')
+
+    # Check 1st and 3rd error have something timestamp-like:
+    errors = capsys.readouterr().err.split('\n')
+    assert re.match('^[0-9]{4}', errors[0])
+    assert re.match('^WARNING - bar', errors[1])
+    assert re.match('^[0-9]{4}', errors[2])