Skip to content

Silence the logs when running the test suite #1039

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
MVrachev opened this issue May 28, 2020 · 7 comments
Closed

Silence the logs when running the test suite #1039

MVrachev opened this issue May 28, 2020 · 7 comments

Comments

@MVrachev
Copy link
Collaborator

MVrachev commented May 28, 2020

Description of issue or feature request:
After my pull request, #1029 had been merged there are annoying messages when running the unit tests:
image.

Current behavior:
Those messages are expected when running the unit tests from tests/test_updater.py for example and as such we don't want to see them in a successful test run.

Expected behavior:
We want to be able to receive the stderr upon errors in the subprocesses, but on a successful tox run I don't expect to see the above error messages.

@MVrachev
Copy link
Collaborator Author

MVrachev commented May 28, 2020

One possible solution I tried is by using logger files, pipeline the stderr from the subprocess to them, and finally read from them (if they are not empty) and put the information to the logger.

The way I did that is by using the setUpClass to create a tmp file.
Create subprocesses running the simple_server.py like that:

subprocess.Popen(command, stderr=log_file)

and finally read from the temp file in the tearDownClass, if the file is non-empty.

Cons: The messages we don't want to see on a successful tox run like:

127.0.0.1 - - [29/May/2020 15:07:48] code 404, message File not found

comes from the stderr of the process too.
Then how do we know when to read from the log file and pass to the logger?

Another question is how should we redirect them.
As log.info as log.error?
If we chose log.info then they won’t be shown if the tests succeed right?
But if we log them as log.error then they will be shown the same way as now

@MVrachev
Copy link
Collaborator Author

MVrachev commented May 29, 2020

Another possible solution is by using try could be by using

pr = subprocess.Popen('ls', stdout=subprocess.PIPE, stderr=subprocess.PIPE)
(output, error) = pr.communicate()
print("OUTPUT IS: ", output)
print("ERROR IS: ", error)

Cons:
From the documentation about Peopen.communicate:

Interact with process: Send data to stdin. Read data from stdout and stderr, until end-of-file is reached. Wait for the process to terminate.

and the result is that when I use this method the test suite freezes if I don't pass a timeout.

@MVrachev
Copy link
Collaborator Author

MVrachev commented May 29, 2020

I have confirmed that those messages 127.0.0.1 - - [29/May/2020 15:07:48] code 404, message File not found come from the stderr.

Overall, the biggest question I see is that if the messages we want to filter are from the stderr too, then how do we distinguish them from the stderr we want to receive?

@lukpueh @joshuagl what would you say on that question?

@joshuagl
Copy link
Member

I believe our goal here is to preserve output from subprocess.Popen, so that we see any errors that may help us to understand any failures we see, such as being unable to find the script we're trying to start in a subprocess as in #1010 (comment)

However, we do not want to pollute the console output with error messages, particularly for expected scenarios.

Other considerations:

  • Do we want to log errors only through Python logging, so that all related errors are visible on a test failure?
    • An additional complication here is whether we should, or how we might, interleave messages from the subprocess with messages from the unit test
  • Do we want to prevent expected error messages, such as a 404 when trying to update the root.json per the expected client workflow when a newer root.json is not available, from being logged?

@MVrachev
Copy link
Collaborator Author

Do we want to log errors only through Python logging, so that all related errors are visible on a test failure?

What I am sure of is that it's important to see all related errors on a test failure.

Do we want to prevent expected error messages, such as a 404 when trying to update the root.json per the expected client workflow when a newer root.json is not available, from being logged?

I feel like those messages could be useful when you integrate TUF in an existing system like Warehouse. Those messages could be used to debug a problem.

@joshuagl
Copy link
Member

joshuagl commented Jun 1, 2020

Do we want to log errors only through Python logging, so that all related errors are visible on a test failure?

What I am sure of is that it's important to see all related errors on a test failure.

Agree with that sentiment.

Do we want to prevent expected error messages, such as a 404 when trying to update the root.json per the expected client workflow when a newer root.json is not available, from being logged?

I feel like those messages could be useful when you integrate TUF in an existing system like Warehouse. Those messages could be used to debug a problem.

Those messages are a symptom of our unit tests, I'm not sure how useful they would be in debugging an integration such as in the case of Warehouse.

the "code 404, message File not found" comes from the simple_server.py's request handler. We may be able to filter those messages in the QuietHTTPRequestHandler, for example we might reasonably be able to ignore 404 messages when the request's path is *.root.json?

Note: the one line of GET ... message is because there are multiple http server implementations in use by the tests and not all of them are silencing gets using a pattern like the QuietHTTPRequestHandler in simple_server.py. Based on the path in the GET message, I'd imagine it's slow_retrieval_server.py that's the culprit here.

@MVrachev
Copy link
Collaborator Author

MVrachev commented Oct 1, 2020

@joshuagl I forgot to use the Fixes keyword in Log subproceses stdout and stderr in temp files #1104 pr to automatically close this one. You can close it.

@joshuagl joshuagl closed this as completed Oct 1, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants