Skip to content

Resolve "Edna2 logs not visible in /var/log/bes/<workflowName>.log"

Wout De Nolf requested to merge 2-edna2-logs-not-visible-in-var-log-bes-workflowname-log into master

Closes #2 (closed)

Example to check what we log from an Edna2 sub-process

from edna2.tasks.AbstractTask import AbstractTask


class MyEdna2Task(AbstractTask):
    """EDNA2 task"""

    def run(self, inData):
        import logging
        logging.error("THIS IS AN ERROR LOG")
        logging.info("THIS IS AN INFO LOG")
        logging.debug("THIS IS AN DEBUG LOG")
        print(f"THIS IS A PRINT: {inData}")
        raise RuntimeError("THIS IS AN ERROR")


def run(**inData):
    """Ewoks task o type 'ppfmethod'"""
    diffractionThumbnail = MyEdna2Task(inData=inData)
    diffractionThumbnail.execute()
    return {"b": 20}


def inject_workflow():
    """Inject a fake BES workflow"""
    import json
    import pathlib
    from bes import flows

    module = pathlib.Path(__file__).stem

    workflow = {
        "graph": {"id": "test_graph"},
        "nodes": [
            {"id": "1", "task_identifier": f"{module}.run", "task_type": "ppfmethod"}
        ],
    }

    flows_dir = pathlib.Path(flows.__file__).parent
    with open(flows_dir / "test_graph.json", "w") as f:
        json.dump(workflow, f, indent=2)

    return "test_graph"


def do_run():
    """BES end-point /RUN/<string:workflowName> emulation"""
    import os
    import sys
    import json

    workflowName = inject_workflow()

    requestDict = {"a": 10}

    os.makedirs("/var/log/bes", exist_ok=True)

    cmd = f"cd {os.getcwd()} && {sys.executable} -m bes.bin.run_ppf_json --inData '{json.dumps(requestDict)}' {workflowName} &"

    os.system(cmd)


if __name__ == "__main__":
    do_run()

Before this MR nothing from the Edna2 task is logged

2024-07-06 23:14:22,090 INFO     ['/home/denolf/projects/bes/src/bes/bin/run_ppf_json.py', '--inData', '{"a": 10}', 'test_graph']
2024-07-06 23:14:22,090 DEBUG    ********************************************************************************
2024-07-06 23:14:22,090 DEBUG    Before json file search
2024-07-06 23:14:22,091 DEBUG    After json file search
2024-07-06 23:14:22,091 DEBUG    Path graph file: /home/denolf/projects/bes/src/bes/flows/test_graph.json
2024-07-06 23:14:22,091 DEBUG    Time last modified json file: 2024-07-06 23:14:21
2024-07-06 23:14:22,092 DEBUG    Before load_graph
2024-07-06 23:14:22,092 DEBUG    After load_graph
2024-07-06 23:14:22,092 DEBUG    Writing graph to path: /var/log/bes/pypushflow/test_graph.pickle
2024-07-06 23:14:22,092 DEBUG    ********************************************************************************
2024-07-06 23:14:22,092 DEBUG    Before execute_graph
2024-07-06 23:14:22,093 INFO     [test_graph] 

Instantiate new workflow 'test_graph'

2024-07-06 23:14:22,093 DEBUG    [test_graph] add reference to actor 'Start'
2024-07-06 23:14:22,093 DEBUG    [test_graph] add reference to actor 'Stop'
2024-07-06 23:14:22,093 DEBUG    [test_graph] add reference to actor 'Stop on error'
2024-07-06 23:14:22,093 DEBUG    [test_graph] [<ErrorHandler> Stop on error] connect to actor 'Stop'
2024-07-06 23:14:22,093 DEBUG    [test_graph] add reference to actor '1'
2024-07-06 23:14:22,093 DEBUG    [test_graph] [<EwoksPythonActor> 1] connect to error handler 'Stop on error'
2024-07-06 23:14:22,093 DEBUG    [test_graph] [<StartActor> Start] connect to actor '1'
2024-07-06 23:14:22,093 DEBUG    [test_graph] [<EwoksPythonActor> 1] connect to actor 'Stop'
2024-07-06 23:14:22,093 INFO     pypushflow concurrency: scaling
2024-07-06 23:14:22,093 INFO     [test_graph] Execution pool ScalingPool ({'max_workers': None, 'pool_type': None})
2024-07-06 23:14:22,093 DEBUG    [test_graph] Thread started for 'Start' (1 threads running)
2024-07-06 23:14:22,094 INFO     [test_graph] [<StartActor> Start] triggered with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['a2050e46-1f97-445c-bd28-5e3561dffe53'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': 'a2050e46-1f97-445c-bd28-5e3561dffe53',
                           'process_id': 69928,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'varinfo': None},
 'a': 10}
2024-07-06 23:14:22,094 INFO     [test_graph] [<StartActor> Start] started
2024-07-06 23:14:22,094 INFO     [test_graph] [<StartActor> Start] finished
2024-07-06 23:14:22,094 DEBUG    [test_graph] Thread started for '1' (2 threads running)
2024-07-06 23:14:22,094 INFO     [test_graph] [<EwoksPythonActor> 1] triggered with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['a2050e46-1f97-445c-bd28-5e3561dffe53'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': 'a2050e46-1f97-445c-bd28-5e3561dffe53',
                           'process_id': 69928,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'node_attrs': {'task_identifier': 'test.run',
                             'task_type': 'ppfmethod'},
              'node_id': '1',
              'varinfo': None},
 'a': 10}
2024-07-06 23:14:22,094 INFO     [test_graph] [<EwoksPythonActor> 1] started
2024-07-06 23:14:22,094 DEBUG    [test_graph] [<EwoksPythonActor> 1] asynchronous execution of 'ewoksppf.ppfrunscript.run'
2024-07-06 23:14:22,094 INFO     pypushflow concurrency: process
2024-07-06 23:14:22,094 INFO     pypushflow process pool context: 'NoneType'
2024-07-06 23:14:22,099 DEBUG    [test_graph] Thread ended for 'Start' (1 threads running)
2024-07-06 23:14:22,099 DEBUG    [test_graph] [<StopActor> Stop] wait for scheduler threads to be finished
2024-07-06 23:14:22,239 INFO     [test_graph] [<EwoksPythonActor> 1] finished
2024-07-06 23:14:22,239 DEBUG    [test_graph] [<EwoksPythonActor> 1] trigger actor 'Stop' with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['a2050e46-1f97-445c-bd28-5e3561dffe53'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': 'a2050e46-1f97-445c-bd28-5e3561dffe53',
                           'process_id': 69928,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'node_attrs': {'task_identifier': 'test.run',
                             'task_type': 'ppfmethod'},
              'node_id': '1',
              'varinfo': None},
 '_ppfdict': {'a': 10, 'b': 20}}
2024-07-06 23:14:22,240 DEBUG    [test_graph] Thread started for 'Stop' (2 threads running)
2024-07-06 23:14:22,240 INFO     [test_graph] [<StopActor> Stop] triggered with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['a2050e46-1f97-445c-bd28-5e3561dffe53'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': 'a2050e46-1f97-445c-bd28-5e3561dffe53',
                           'process_id': 69928,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'node_attrs': {'task_identifier': 'test.run',
                             'task_type': 'ppfmethod'},
              'node_id': '1',
              'varinfo': None},
 '_ppfdict': {'a': 10, 'b': 20}}
2024-07-06 23:14:22,240 DEBUG    [test_graph] Thread ended for 'Stop' (1 threads running)
2024-07-06 23:14:22,240 DEBUG    [test_graph] Thread ended for '1' (0 threads running)
2024-07-06 23:14:22,240 DEBUG    [test_graph] [<StopActor> Stop] scheduler threads are finished
2024-07-06 23:14:22,240 DEBUG    [test_graph] [<StopActor> Stop] finished

After this MR everything is logged

2024-07-06 23:16:40,072 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] ['/home/denolf/projects/bes/src/bes/bin/run_ppf_json.py', '--inData', '{"a": 10}', 'test_graph']
2024-07-06 23:16:40,072 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] ********************************************************************************
2024-07-06 23:16:40,072 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] Before json file search
2024-07-06 23:16:40,073 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] After json file search
2024-07-06 23:16:40,073 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] Path graph file: /home/denolf/projects/bes/src/bes/flows/test_graph.json
2024-07-06 23:16:40,073 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] Time last modified json file: 2024-07-06 23:16:39
2024-07-06 23:16:40,073 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] Before load_graph
2024-07-06 23:16:40,074 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] Graph has no "schema_version": assume version "1.0"
2024-07-06 23:16:40,074 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] After load_graph
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] Writing graph to path: /var/log/bes/pypushflow/test_graph.pickle
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] ********************************************************************************
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] Before execute_graph
2024-07-06 23:16:40,075 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [job '1f4ace84-35e5-4404-b1ec-6c224689f897'] job started
2024-07-06 23:16:40,075 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] 

Instantiate new workflow 'test_graph'

2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] add reference to actor 'Start'
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] add reference to actor 'Stop'
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] add reference to actor 'Stop on error'
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<ErrorHandler> Stop on error] connect to actor 'Stop'
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] add reference to actor '1'
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] connect to error handler 'Stop on error'
2024-07-06 23:16:40,075 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StartActor> Start] connect to actor '1'
2024-07-06 23:16:40,076 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] connect to actor 'Stop'
2024-07-06 23:16:40,076 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [job '1f4ace84-35e5-4404-b1ec-6c224689f897'] [workflow 'test_graph'] workflow started
2024-07-06 23:16:40,076 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] pypushflow concurrency: scaling
2024-07-06 23:16:40,076 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Execution pool ScalingPool ({'max_workers': None, 'pool_type': None})
2024-07-06 23:16:40,076 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Thread started for 'Start' (1 threads running)
2024-07-06 23:16:40,076 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StartActor> Start] triggered with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['1f4ace84-35e5-4404-b1ec-6c224689f897'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': '1f4ace84-35e5-4404-b1ec-6c224689f897',
                           'process_id': 70167,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'varinfo': None},
 'a': 10}
2024-07-06 23:16:40,076 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StartActor> Start] started
2024-07-06 23:16:40,076 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StartActor> Start] finished
2024-07-06 23:16:40,076 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Thread started for '1' (2 threads running)
2024-07-06 23:16:40,077 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] triggered with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['1f4ace84-35e5-4404-b1ec-6c224689f897'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': '1f4ace84-35e5-4404-b1ec-6c224689f897',
                           'process_id': 70167,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'node_attrs': {'task_identifier': 'test.run',
                             'task_type': 'ppfmethod'},
              'node_id': '1',
              'varinfo': None},
 'a': 10}
2024-07-06 23:16:40,077 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] started
2024-07-06 23:16:40,077 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] asynchronous execution of 'ewoksppf.ppfrunscript.run'
2024-07-06 23:16:40,077 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] pypushflow concurrency: process
2024-07-06 23:16:40,077 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] pypushflow process pool context: 'NoneType'
2024-07-06 23:16:40,082 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Thread ended for 'Start' (1 threads running)
2024-07-06 23:16:40,083 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StopActor> Stop] wait for scheduler threads to be finished
2024-07-06 23:16:40,084 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [job '1f4ace84-35e5-4404-b1ec-6c224689f897'] [workflow 'test_graph'] [node '1'] [task 'test.run'] task started
2024-07-06 23:16:40,154 ERROR [1f4ace84-35e5-4404-b1ec-6c224689f897] THIS IS AN ERROR LOG
2024-07-06 23:16:40,155 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] THIS IS AN INFO LOG
2024-07-06 23:16:40,155 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] THIS IS AN DEBUG LOG
2024-07-06 23:16:40,157 ERROR [1f4ace84-35e5-4404-b1ec-6c224689f897] THIS IS AN ERROR
2024-07-06 23:16:40,158 ERROR [1f4ace84-35e5-4404-b1ec-6c224689f897] Traceback (most recent call last):
  File "/home/denolf/projects/edna2/src/edna2/tasks/AbstractTask.py", line 55, in run
    billiard.Process.run(self)
  File "/home/denolf/virtualenvs/bes/lib/python3.12/site-packages/billiard/process.py", line 110, in run
    self._target(*self._args, **self._kwargs)
  File "/home/denolf/projects/edna2/src/edna2/tasks/AbstractTask.py", line 111, in executeRun
    outData = self.run(inData)
              ^^^^^^^^^^^^^^^^
  File "/home/denolf/projects/edna2/test.py", line 13, in run
    raise RuntimeError("THIS IS AN ERROR")
RuntimeError: THIS IS AN ERROR

2024-07-06 23:16:40,158 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [job '1f4ace84-35e5-4404-b1ec-6c224689f897'] [workflow 'test_graph'] [node '1'] [task 'test.run'] task finished
2024-07-06 23:16:40,158 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] finished
2024-07-06 23:16:40,159 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<EwoksPythonActor> 1] trigger actor 'Stop' with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['1f4ace84-35e5-4404-b1ec-6c224689f897'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': '1f4ace84-35e5-4404-b1ec-6c224689f897',
                           'process_id': 70167,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'node_attrs': {'task_identifier': 'test.run',
                             'task_type': 'ppfmethod'},
              'node_id': '1',
              'varinfo': None},
 '_ppfdict': {'a': 10, 'b': 20}}
2024-07-06 23:16:40,159 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Thread started for 'Stop' (2 threads running)
2024-07-06 23:16:40,159 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StopActor> Stop] triggered with inData =
 {'_noinput': {'execinfo': {'contexts': {'job': ['1f4ace84-35e5-4404-b1ec-6c224689f897'],
                                        'workflow': ['test_graph']},
                           'engine': 'ppf',
                           'host_name': 'ideapad3',
                           'job_id': '1f4ace84-35e5-4404-b1ec-6c224689f897',
                           'process_id': 70167,
                           'user_name': 'denolf',
                           'workflow_id': 'test_graph'},
              'node_attrs': {'task_identifier': 'test.run',
                             'task_type': 'ppfmethod'},
              'node_id': '1',
              'varinfo': None},
 '_ppfdict': {'a': 10, 'b': 20}}
2024-07-06 23:16:40,159 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Thread ended for 'Stop' (1 threads running)
2024-07-06 23:16:40,159 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] Thread ended for '1' (0 threads running)
2024-07-06 23:16:40,159 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StopActor> Stop] scheduler threads are finished
2024-07-06 23:16:40,159 DEBUG [1f4ace84-35e5-4404-b1ec-6c224689f897] [test_graph] [<StopActor> Stop] finished
2024-07-06 23:16:40,168 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [job '1f4ace84-35e5-4404-b1ec-6c224689f897'] [workflow 'test_graph'] workflow finished
2024-07-06 23:16:40,168 INFO  [1f4ace84-35e5-4404-b1ec-6c224689f897] [job '1f4ace84-35e5-4404-b1ec-6c224689f897'] job finished
Edited by Wout De Nolf

Merge request reports