Couldn't see event handler logs in console with Cylc v8.1.4

Cylc Cylc 8 Migration
1

Description

I’m trying to capture a few events when a Cylc workflow is running and dump them in Kafka after processing the data collected. In previous versions of Cylc from v7+ to v8.0.*, I could see the logs in the console when the event handler fails to process the data or dump it in a Kafka topic.

Recently, I tried to test my code with Cylc v8.1.4 and my event handler is failing to dump the events captured to a Kafka topic. Now, I don’t see any logs in the console. I see everything is running smoothly from the Cylc side and no traces of what’s happening in the event handler. This is making debugging a little difficult for me.

So my question is, how can I make my event handler start printing the logs in the same console where Cylc logs are printed? If someone can help me understand what’s changed in the latest version, it’ll be really helpful.

Reproducible Example

I have written a sample program that captures the events from the Cylc workflow and writes them to a file, even though it writes events to a file, no logs are printed in the console. Here’s my sample program code. (FYI, flow.cylc file is not fully updated to v8 but it is working with a few warnings, so I left it as it is for now)

flow.cylc

[meta]
  # Suite metadata.
  title = (Background) Retry Success
  url = www.testsuiteurl.com
  uuid = 158ec4de-4a89-11e9-8646-d663bd378d85
  priority = HIGH
  color = blue
[cylc]
  UTC mode = True
[scheduling]
  initial cycle point = "now"
  [[dependencies]]
    [[[R1]]]
      graph = bgRetrySuccess
[runtime]
  [[bgRetrySuccess]]
    init-script = "sleep 5"
    script = """
              sleep 10
              if [[ $CYLC_TASK_TRY_NUMBER < 2 ]]; then
                  echo "Hello ... aborting!"
                  exit 1
              else
                  echo "Hello World!"
              fi"""
    [[[job]]]
      batch system = background
      execution retry delays = 1*PT10S # retry once after 10-second delays
    [[[meta]]]
      # Task metadata.
      title = (Background) Retry Success task
      priority = LOW
      url = www.testtaskurl.com
      omit = false
      color = red
    [[[events]]]
      handler events = submitted, submission failed, submission timeout, submission retry, started, succeeded, failed, retry, execution timeout, late
      handlers = write_to_file.py --event="%(event)s"

write_to_file.py

#!/usr/bin/env python

import logging
import argparse

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)

parser = argparse.ArgumentParser()
parser.add_argument("--event", type=str, required=True, help="Event argument value")
args = parser.parse_args()

print("Hello, world!")
logger.info("This is an info message")
logger.warning("This is a warning message")
logger.error("This is an error message")

with open("output.txt", "a") as file:
    file.write(f"{args.event}\n")

Cylc logs in the console:

Valid for cylc-8.1.4

 ▪ ■  Cylc Workflow Engine 8.1.4
 ██   Copyright (C) 2008-2023 NIWA
▝▘    & British Crown (Met Office) & Contributors

2023-07-07T03:06:36Z INFO - Extracting job.sh to /home/pbsuser/cylc-run/bg-retry-success/run1/.service/etc/job.sh
2023-07-07T03:06:36Z INFO - Workflow: bg-retry-success/run1
2023-07-07T03:06:36Z WARNING - deprecated items were automatically upgraded in "workflow definition"
2023-07-07T03:06:36Z WARNING -  * (8.0.0) [runtime][bgRetrySuccess][job]execution retry delays -> [runtime][bgRetrySuccess]execution retry delays - value unchanged
2023-07-07T03:06:36Z WARNING -  * (8.0.0) [cylc] -> [scheduler] - value unchanged
2023-07-07T03:06:36Z WARNING - deprecated graph items were automatically upgraded in "workflow definition":
     * (8.0.0) [scheduling][dependencies][X]graph -> [scheduling][graph]X - for X in:
           R1
2023-07-07T03:06:36Z WARNING - deprecated settings found (please replace with [runtime][bgRetrySuccess]platform):
    [runtime][bgRetrySuccess][job]batch system = background
2023-07-07T03:06:36Z INFO - Scheduler: url=tcp://pbsserver:43045 pid=30923
2023-07-07T03:06:36Z INFO - Workflow publisher: url=tcp://pbsserver:43087
2023-07-07T03:06:36Z INFO - Run: (re)start number=1, log rollover=1
2023-07-07T03:06:36Z INFO - Cylc version: 8.1.4
2023-07-07T03:06:36Z INFO - Run mode: live
2023-07-07T03:06:36Z INFO - Initial point: 20230707T0306Z
2023-07-07T03:06:36Z INFO - Final point: None
2023-07-07T03:06:36Z INFO - Cold start from 20230707T0306Z
2023-07-07T03:06:36Z INFO - New flow: 1 (original flow from 20230707T0306Z) 2023-07-07 03:06:36
2023-07-07T03:06:36Z INFO - [20230707T0306Z/bgRetrySuccess waiting(runahead) job:00 flows:1] => waiting
2023-07-07T03:06:36Z INFO - [20230707T0306Z/bgRetrySuccess waiting job:00 flows:1] => waiting(queued)
2023-07-07T03:06:36Z INFO - [20230707T0306Z/bgRetrySuccess waiting(queued) job:00 flows:1] => waiting
2023-07-07T03:06:36Z INFO - [20230707T0306Z/bgRetrySuccess waiting job:01 flows:1] => preparing
2023-07-07T03:06:37Z INFO - [20230707T0306Z/bgRetrySuccess preparing job:01 flows:1] submitted to localhost:background[30939]
2023-07-07T03:06:37Z INFO - [20230707T0306Z/bgRetrySuccess preparing job:01 flows:1] => submitted
2023-07-07T03:06:37Z INFO - [20230707T0306Z/bgRetrySuccess submitted job:01 flows:1] health: submission timeout=None, polling intervals=PT15M,...
2023-07-07T03:06:43Z INFO - [20230707T0306Z/bgRetrySuccess submitted job:01 flows:1] => running
2023-07-07T03:06:43Z INFO - [20230707T0306Z/bgRetrySuccess running job:01 flows:1] health: execution timeout=None, polling intervals=PT15M,...
2023-07-07T03:06:53Z INFO - [20230707T0306Z/bgRetrySuccess running job:01 flows:1] => waiting
2023-07-07T03:06:53Z WARNING - [20230707T0306Z/bgRetrySuccess waiting job:01 flows:1] retrying in PT10S (after 2023-07-07T03:07:03Z)
2023-07-07T03:07:03Z INFO - xtrigger satisfied: _cylc_retry_20230707T0306Z/bgRetrySuccess = wall_clock(trigger_time=1688699223.810117)
2023-07-07T03:07:03Z INFO - [20230707T0306Z/bgRetrySuccess waiting job:01 flows:1] => waiting(queued)
2023-07-07T03:07:03Z INFO - [20230707T0306Z/bgRetrySuccess waiting(queued) job:01 flows:1] => waiting
2023-07-07T03:07:03Z INFO - [20230707T0306Z/bgRetrySuccess waiting job:02 flows:1] => preparing
2023-07-07T03:07:04Z INFO - [20230707T0306Z/bgRetrySuccess preparing job:02 flows:1] submitted to localhost:background[31080]
2023-07-07T03:07:04Z INFO - [20230707T0306Z/bgRetrySuccess preparing job:02 flows:1] => submitted
2023-07-07T03:07:04Z INFO - [20230707T0306Z/bgRetrySuccess submitted job:02 flows:1] health: submission timeout=None, polling intervals=PT15M,...
2023-07-07T03:07:10Z INFO - [20230707T0306Z/bgRetrySuccess submitted job:02 flows:1] => running
2023-07-07T03:07:10Z INFO - [20230707T0306Z/bgRetrySuccess running job:02 flows:1] health: execution timeout=None, polling intervals=PT15M,...
2023-07-07T03:07:20Z INFO - [20230707T0306Z/bgRetrySuccess running job:02 flows:1] => succeeded
2023-07-07T03:07:21Z INFO - Workflow shutting down - AUTOMATIC
2023-07-07T03:07:22Z INFO - DONE

Expected Behaviour

When I tried running the same event handler file directly, it prints all the logs (both print/logging). I want these logs to be printed along with cylc logs in the console.

Console output:

[pbsuser@pbsserver 2.bg-retry-success]$ python write_to_file.py --event='test'
Hello, world!
2023-07-07 03:06:25,615 - INFO - This is an info message
2023-07-07 03:06:25,616 - WARNING - This is a warning message
2023-07-07 03:06:25,616 - ERROR - This is an error message
[pbsuser@pbsserver 2.bg-retry-success]$
2

Hello,

If you run the workflow in --debug mode you will see the command being run, it’s exit status and any stdout/err created:

2023-07-07T14:29:16Z DEBUG - [(('event-handler-00', 'started'), 1) cmd] write_to_file.py --event="started"
    [(('event-handler-00', 'started'), 1) ret_code] 0
    [(('event-handler-00', 'started'), 1) out] Hello, world!
    [(('event-handler-00', 'started'), 1) err]
    2023-07-07 15:29:16,408 - INFO - This is an info message
    2023-07-07 15:29:16,409 - WARNING - This is a warning message
    2023-07-07 15:29:16,409 - ERROR - This is an error message

E.G. cylc vip --debug.

Note, that event handlers are called as subprocesses, not run within the Cylc scheduler process itself so you cannot write to the Cylc [log] from an event handler log directly, but any stdout/err will be captured.