Merge 656a591 into cb603b2

WDL/CLI.py

@@ -27,7 +27,7 @@
     write_values_json,
     VERBOSE_LEVEL,
     NOTICE_LEVEL,
-    install_coloredlogs,
+    configure_logger,
     parse_byte_size,
     path_really_within,
 )
@@ -389,6 +389,19 @@ def fill_run_subparser(subparsers):
         action="store_true",
         help="upon failure, print error information JSON to standard output (in addition to standard error logging)",
     )
+    group = run_parser.add_argument_group("logging")
+    group.add_argument(
+        "-v",
+        "--verbose",
+        action="store_true",
+        help="increase logging detail & stream tasks' stderr",
+    )
+    group.add_argument(
+        "--no-color",
+        action="store_true",
+        help="disable colored logging and status bar on terminal (also set by NO_COLOR environment variable)",
+    )
+    group.add_argument("--log-json", action="store_true", help="write all logs in JSON")
     group = run_parser.add_argument_group("configuration")
     group.add_argument(
         "--cfg",
@@ -441,17 +454,6 @@ def fill_run_subparser(subparsers):
         action="store_true",
         help="run all containers as the invoking user uid:gid (more secure, but potentially blocks task commands e.g. apt-get)",
     )
-    run_parser.add_argument(
-        "-v",
-        "--verbose",
-        action="store_true",
-        help="increase logging detail & stream tasks' stderr",
-    )
-    run_parser.add_argument(
-        "--no-color",
-        action="store_true",
-        help="disable colored logging on terminal (also set by NO_COLOR environment variable)",
-    )
     # TODO:
     # way to specify None for an optional value (that has a default)
     return run_parser
@@ -476,6 +478,7 @@ def runner(
     as_me=False,
     no_cache=False,
     error_json=False,
+    log_json=False,
     **kwargs,
 ):
     # set up logging
@@ -487,13 +490,19 @@ def runner(
     else:
         logging.raiseExceptions = False
     if kwargs["no_color"]:
-        # picked up by _util.install_coloredlogs()
+        # picked up by _util.configure_logger()
         os.environ["NO_COLOR"] = os.environ.get("NO_COLOR", "")
+    # log_json setting only comes from command line or environment (not cfg file), because we
+    # need it before loading configuration
+    log_json = log_json or (
+        os.environ.get("MINIWDL__LOGGING__JSON", "").lower().strip()
+        in ("t", "y", "1", "true", "yes")
+    )
     logging.basicConfig(level=level)
     logger = logging.getLogger("miniwdl-run")
 
     with ExitStack() as cleanup:
-        set_status = cleanup.enter_context(install_coloredlogs(logger))
+        set_status = cleanup.enter_context(configure_logger(json=log_json))
 
         if os.geteuid() == 0:
             logger.warning(
@@ -511,6 +520,7 @@ def runner(
             "file_io": {},
             "task_runtime": {},
             "download_cache": {},
+            "logging": {"json": log_json},
         }
         if max_tasks is not None:
             cfg_overrides["scheduler"]["call_concurrency"] = max_tasks
@@ -965,6 +975,7 @@ def fill_run_self_test_subparser(subparsers):
         default=None,
         help="configuration file to load (in preference to file named by MINIWDL_CFG environment, or XDG_CONFIG_{HOME,DIRS}/miniwdl.cfg)",
     )
+    run_parser.add_argument("--log-json", action="store_true", help="write all logs in JSON")
     run_parser.add_argument(
         "--as-me", action="store_true", help="run all containers as the current user uid:gid"
     )
@@ -1031,6 +1042,8 @@ def run_self_test(**kwargs):
     if kwargs["cfg"]:
         argv.append("--cfg")
         argv.append(kwargs["cfg"])
+    if kwargs["log_json"]:
+        argv.append("--log-json")
     try:
         outputs = main(argv)["outputs"]
         assert len(outputs["hello_caller.messages"]) == 2
@@ -1364,7 +1377,7 @@ def localize(
 ):
     logging.basicConfig(level=NOTICE_LEVEL)
     logger = logging.getLogger("miniwdl-localize")
-    with install_coloredlogs(logger) as set_status:
+    with configure_logger() as set_status:
 
         cfg_arg = None
         if cfg:

WDL/_util.py

@@ -32,6 +32,7 @@
 )
 from types import FrameType
 import coloredlogs
+from pythonjsonlogger import jsonlogger
 from pygtail import Pygtail
 import docker
 
@@ -240,6 +241,28 @@ def __str__(self) -> str:
         )
 
 
+class StructuredLogMessageJSONFormatter(jsonlogger.JsonFormatter):
+    "JSON formatter for StructuredLogMessages"
+
+    def format(self, rec: logging.LogRecord) -> str:
+        if isinstance(rec.msg, StructuredLogMessage):
+            ans = {"level": rec.levelname, "message": rec.msg.message}
+            for k, v in rec.msg.kwargs.items():
+                if k not in ans:
+                    ans[k] = v
+            rec.msg = ans
+        return super().format(rec)
+
+    def add_fields(
+        self, log_record: Dict[str, Any], record: logging.LogRecord, message_dict: Dict[str, Any]
+    ) -> None:
+        super().add_fields(log_record, record, message_dict)
+        log_record["timestamp"] = round(record.created, 3)
+        log_record["source"] = record.name
+        log_record["level"] = record.levelname
+        log_record["levelno"] = record.levelno
+
+
 VERBOSE_LEVEL = 15
 __all__.append("VERBOSE_LEVEL")
 logging.addLevelName(VERBOSE_LEVEL, "VERBOSE")
@@ -328,90 +351,103 @@ def set_status(self, new_status: List[str]) -> None:
 
 
 LOGGING_FORMAT = "%(asctime)s.%(msecs)03d %(name)s %(levelname)s %(message)s"
-LOGGING_FORMAT_STDERR = "%(asctime)s.%(msecs)03d %(name)s %(message)s"
+COLORED_LOGGING_FORMAT = "%(asctime)s.%(msecs)03d %(name)s %(message)s"  # colors obviate levelname
 __all__.append("LOGGING_FORMAT")
 
 
 @export
 @contextmanager
-def install_coloredlogs(
-    logger: logging.Logger, force: bool = False
+def configure_logger(
+    force_tty: bool = False, json: bool = False
 ) -> Iterator[Callable[[str], None]]:
     """
-    contextmanager to set up our logger customizations; yields a function to set the status line at
+    contextmanager to set up the root/stderr logger; yields a function to set the status line at
     the bottom of the screen (if stderr isatty, else it does nothing)
     """
-    level_styles = {}
-    field_styles = {}
-    fmt = LOGGING_FORMAT
-    enable = force or (sys.stderr.isatty() and "NO_COLOR" not in os.environ)
-
-    if enable:
-        level_styles = dict(coloredlogs.DEFAULT_LEVEL_STYLES)
-        level_styles["debug"]["color"] = 242
-        level_styles["notice"] = {"color": "green", "bold": True}
-        level_styles["error"]["bold"] = True
-        level_styles["warning"]["bold"] = True
-        level_styles["info"] = {}
-        field_styles = dict(coloredlogs.DEFAULT_FIELD_STYLES)
-        field_styles["asctime"] = {"color": "blue"}
-        field_styles["name"] = {"color": "magenta"}
-        fmt = LOGGING_FORMAT_STDERR
-
-        # monkey-patch _StatusLineStandardErrorHandler over coloredlogs.StandardErrorHandler for
-        # coloredlogs.install() to instantiate
-        coloredlogs.StandardErrorHandler = _StatusLineStandardErrorHandler
-        sys.stderr.write(ANSI.HIDE_CURSOR)  # hide cursor
+    logger = logging.getLogger()
 
-    try:
-        coloredlogs.install(
-            level=logger.getEffectiveLevel(),
-            logger=logger,
-            level_styles=level_styles,
-            field_styles=field_styles,
-            fmt=fmt,
-        )
-        yield (
-            lambda status: _StatusLineStandardErrorHandler._singleton.set_status(  # pyre-fixme
-                status
+    if json:
+        logger.handlers[0].setFormatter(StructuredLogMessageJSONFormatter())
+        yield (lambda ignore: None)
+    else:
+        level_styles = {}
+        field_styles = {}
+        fmt = LOGGING_FORMAT
+        tty = force_tty or (sys.stderr.isatty() and "NO_COLOR" not in os.environ)
+
+        if tty:
+            level_styles = dict(coloredlogs.DEFAULT_LEVEL_STYLES)
+            level_styles["debug"]["color"] = 242
+            level_styles["notice"] = {"color": "green", "bold": True}
+            level_styles["error"]["bold"] = True
+            level_styles["warning"]["bold"] = True
+            level_styles["info"] = {}
+            field_styles = dict(coloredlogs.DEFAULT_FIELD_STYLES)
+            field_styles["asctime"] = {"color": "blue"}
+            field_styles["name"] = {"color": "magenta"}
+            fmt = COLORED_LOGGING_FORMAT
+
+            # monkey-patch _StatusLineStandardErrorHandler over coloredlogs.StandardErrorHandler for
+            # coloredlogs.install() to instantiate
+            coloredlogs.StandardErrorHandler = _StatusLineStandardErrorHandler
+            sys.stderr.write(ANSI.HIDE_CURSOR)  # hide cursor
+
+        try:
+            coloredlogs.install(
+                level=logger.getEffectiveLevel(),
+                logger=logger,
+                level_styles=level_styles,
+                field_styles=field_styles,
+                fmt=fmt,
             )
-            if _StatusLineStandardErrorHandler._singleton
-            else None
-        )
-    finally:
-        if enable:
-            sys.stderr.write(ANSI.CLEAR)  # wipe the status line
-            sys.stderr.write(ANSI.SHOW_CURSOR)  # un-hide cursor
+            yield (
+                lambda status: _StatusLineStandardErrorHandler._singleton.set_status(  # pyre-fixme
+                    status
+                )
+                if _StatusLineStandardErrorHandler._singleton
+                else None
+            )
+        finally:
+            if tty:
+                sys.stderr.write(ANSI.CLEAR)  # wipe the status line
+                sys.stderr.write(ANSI.SHOW_CURSOR)  # un-hide cursor
 
 
 @export
 @contextmanager
 def PygtailLogger(
-    logger: logging.Logger, filename: str, prefix: str = "2| "
+    logger: logging.Logger, filename: str, callback: Optional[Callable[[str], None]] = None
 ) -> Iterator[Callable[[], None]]:
     """
     Helper for streaming task stderr into logger using pygtail. Context manager yielding a function
     which reads the latest lines from the file and writes them into logger at verbose level. This
     function also runs automatically on context exit.
 
-    Truncates lines at 4KB in case writer goes haywire.
+    Stops if it sees a line greater than 4KB, in case writer goes haywire.
     """
     pygtail = None
     if logger.isEnabledFor(VERBOSE_LEVEL):
         pygtail = Pygtail(filename, full_lines=True)
+    logger2 = logger.getChild("stderr")
+
+    def default_callback(line: str) -> None:
+        assert len(line) <= 4096, "line > 4KB"
+        logger2.verbose(line.rstrip())  # pyre-fixme
+
+    callback = callback or default_callback
 
     def poll() -> None:
         nonlocal pygtail
         if pygtail:
             try:
                 for line in pygtail:
-                    logger.verbose((prefix + line.rstrip())[:4096])  # pyre-ignore
-            except:
+                    callback(line)
+            except Exception as exn:
                 # cf. https://github.com/bgreenlee/pygtail/issues/48
-                logger.verbose(  # pyre-ignore
-                    "incomplete log stream due to the following exception; see %s",
-                    filename,
-                    exc_info=sys.exc_info(),
+                logger.warning(
+                    StructuredLogMessage(
+                        "log stream is incomplete", filename=filename, error=str(exn)
+                    )
                 )
                 pygtail = None
 
@@ -600,12 +636,19 @@ def do1(path1: str, bits: int) -> None:
 
 @export
 @contextmanager
-def LoggingFileHandler(logger: logging.Logger, filename: str) -> Iterator[logging.FileHandler]:
+def LoggingFileHandler(
+    logger: logging.Logger, filename: str, json: bool = False
+) -> Iterator[logging.FileHandler]:
     """
     Context manager which opens a logging.FileHandler and adds it to the logger; on exit, closes
     the log file and removes the handler.
     """
     fh = logging.FileHandler(filename)
+    fh.setFormatter(
+        StructuredLogMessageJSONFormatter()
+        if json
+        else logging.Formatter(LOGGING_FORMAT, datefmt="%Y-%m-%d %H:%M:%S")
+    )
     try:
         logger.addHandler(fh)
         yield fh

WDL/runtime/_statusbar.py

@@ -86,7 +86,7 @@ def abort() -> None:
 
 @contextmanager
 def enable(set_status: Optional[Callable[[List[str]], None]]) -> Iterator[None]:
-    # set_status comes from .._util.install_coloredlogs to set the status bar contents
+    # set_status comes from .._util.configure_logger to set the status bar contents
     t0 = time.time()
 
     def update() -> None:
@@ -101,11 +101,15 @@ def update() -> None:
                 # feedback sooner:
                 spinner = [ANSI.BRED, " ABORT ", ANSI.RESET]
             msg = (
-                ["    "]
+                [
+                    "    ",
+                    ANSI.BOLD,
+                    f"{datetime.timedelta(seconds=int(elapsed))} elapsed    ",
+                    ANSI.RESET,
+                ]
                 + spinner
                 + [
                     ANSI.BOLD,
-                    f"    {datetime.timedelta(seconds=int(elapsed))} elapsed",
                     "    ",
                     "tasks finished: " + str(_counters["tasks_finished"]),
                     ", ready: "