Nrunner logging files

[richtja]

I would like to open a discussion about how the log files should be treated in the runner architecture. Especially make a decision if the logs of task inside debug.log should be copied to job.log file. Right now these logs are not copied and the job.log contains only the logs related to the job. My opinion is that this is the right behavior, because we have the logs sorted and related to the specific objects. But I would like to have a discussion about including the task logs to job.log file.

If we decide to implement this feature we have to decide how the logs will looks like with the parallel run of the task. I can see three types of solutions:

• The log will be saved to job.log when the log message is received from the runner. I think that this is a bad solution, because the messages of one task will be mixed with messages of another task due to the parallel run.

• The logs will be copied from debug.log to the job.log after the task has finished. This is a better solution, but the task logs won't correspond to the related job log lines and could be mixed with job log lines related to the different task.

• At the end of the job all test logs will be copied to the job.log, That will create the recap of what happened during the job runtime. But we still have divided the job and task logs.

[beraldoleal]

Hi @richtja for sure there is room for improvements here. Current way, specific task logs gets not so obvious to find for new users.

My comments:

If we decide to implement this feature we have to decide how the logs will looks like with the parallel run of the task. I can see three types of solutions:

* The log will be saved to `job.log` when the log message is received from the runner. I think that this is a bad solution, because the messages of one task will be mixed with messages of another task due to the parallel run.

Indeed.

* The logs will be copied from `debug.log` to the `job.log` after the task has finished. This is a better solution, but the task logs won't correspond to the related job log lines and could be mixed with job log lines related to the different task.

IMO this will create a huge file and duplicated content, what I think we should avoid at any cost. While it is a possibility I like the way it is today, specific logs for specific tasks.

* At the end of the job all test logs will be copied to the `job.log`, That  will create the recap of what happened during the job runtime. But we still have divided the job and task logs.

Not sure if I understood here. "Copied to the job.log" and "still have divided the job and task logs". So are we going to duplicate content as well?

I'm not sure, and for sure we could improve things here, but I like to think that we could improve avocado jobs command, to make this more user friendly, instead of trying to change how we store the logs. In a ideal world, users should not care how logs are stored if we provide a proper UI.

[pevogam]

Hi @richtja, I admit that I am very used to the current workflow where we have both individual debug.log-s and a shared job.log where we can always see the overall run (useful for sharing of a single results file without having to archive and copy the debug.log of thousands of tests, larger scope logging that encompasses smaller scope logging similar to the way DEBUG log level will also cover ERROR, WARNING, and INFO levels instead of being separated in a different file, etc.). But indeed, my perception if more appropriate for serial logging where the timestamped log lines are in a chronological order and we talk about just one essential process.

Considering parallel logging does make things more complicated and advocates for separate files as well as clear separation of the process specific information. Considering also the more complicated parallel scheduling that takes place it makes sense for the overall job to have its own separate log file. So in view of your comments I guess we can stay with separate files, I wasn't aware of some of the points in my original comment. It is still good however to see the opinion of more people, some might propose more solutions. What I used to do with some multiprocessing applications before (related more to scientific computing) is tag each log line with node/process ID/name that are still chronologically ordered together and grep/filter specific process if I want to restrict myself to that process.

[willianrampazzo]

I don't see how putting everything, ordered or not ordered, on a single file would make the user's life easy. We have a new runner architecture that requires new solutions for some parts of Avocado's code. Logging is one of these. In this case, I'm in favor of separating the logging parts on its specific domains.

[pevogam]

I don't see how putting everything, ordered or not ordered, on a single file would make the user's life easy.

Considering something like journalctl we do know that users would eventually prefer a unified entry point into the logging that could be easily filtered despite all the processes logging at the same time. So I wouldn't overgeneralize this statement too much and I think we all prefer to unified logging as users. But as @beraldoleal said, providing a proper interface to the logging makes actual decisions about log files more of an implementation detail. Separation could thus be beneficial here when it comes to file structure organization, all as long as the user could actually have a single entry and only apply filtering to the messages and their respective emitting processes.

[willianrampazzo]

I don't see how putting everything, ordered or not ordered, on a single file would make the user's life easy.

Considering something like journalctl we do know that users would eventually prefer a unified entry point into the logging that could be easily filtered despite all the processes logging at the same time. So I wouldn't overgeneralize this statement too much and I think we all prefer to unified logging as users.

Sorry, I agree with you here if we have a proper way to filter the information needed. Throwing everything on a file without a proper UI to the users won't bring any benefit as we will let the burden of filtering to the users. That was what I meant.

But as @beraldoleal said, providing a proper interface to the logging makes actual decisions about log files more of an implementation detail. Separation could thus be beneficial here when it comes to file structure organization, all as long as the user could actually have a single entry and only apply filtering to the messages and their respective emitting processes.

Yep, that is also my thinking, sorry for not being clear.

[pevogam]

I don't see how putting everything, ordered or not ordered, on a single file would make the user's life easy.

Considering something like journalctl we do know that users would eventually prefer a unified entry point into the logging that could be easily filtered despite all the processes logging at the same time. So I wouldn't overgeneralize this statement too much and I think we all prefer to unified logging as users.

Sorry, I agree with you here if we have a proper way to filter the information needed. Throwing everything on a file without a proper UI to the users won't bring any benefit as we will let the burden of filtering to the users. That was what I meant.

It could temporarily provide users with an easy possibility to use their own grep solution until we have a proper interface but it is not worth it to go this direction and spend previous resources for a temporary solution of a temporary situation. So yes, totally agreed.

[smitterl]

I'd like to pick this discussion up again. My specific use case is where I don't run tests in parallel and I use tail -f job.log to monitor the progress of the execution.

This is useful and sometimes IMO necessary when we have to research issues where one test case execution might impact another (X only fails if Y is run before X); sometimes test might hang or in the logs I can see very early that it's better to cancel the test execution because something went wrong (test can run for a very long time).

[richtja]

Hi @smitterl maybe it will be useful for you to user show option which will print the logs into console. Can you please try this example:

 avocado --show=test run --max-parallel-tasks=1 examples/tests/sleeptest.py examples/tests/passtest.py examples/tests/failtest.py

[richtja]

Hi @smitterl maybe you will be interested in PR #5645 it adds –store-logging-stream=all option which will create full.log file with all avocado logs in one place. IMO, this is exactly what you are looking for.

[smitterl]

Thanks for the addition!