Skip to content
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

Log subproceses stdout and stderr in temp files #1104

Merged

Conversation

MVrachev
Copy link
Collaborator

@MVrachev MVrachev commented Aug 11, 2020

Fixes issues #: #1039, #1119

Description of the changes being introduced by the pull request:

This pr replaces pr #1041.

Logging the stdout and stderr from the test subprocesses into
temporary files clean the console from unnecessary messages from
the server-side such as "code 404, message File not found" or
"GET" queries.

The unit tests are executed in sequential order and that's why
we can reuse one temporary file object for multiple tests.

I have used this pr to remove some redundant functions, comments, and variables.

For this pr I received great help from @jku!
Thanks!

Please verify and check that the pull request fulfills the following
requirements
:

  • The code follows the Code Style Guidelines
  • Tests have been added for the bug fix or new feature
  • Docs have been added for the bug fix or new feature

@MVrachev
Copy link
Collaborator Author

On a successful test run the console logs look like this:
image

I wanted to simulate an error in the subprocess and I changed the name of the server script from simple_server.py to tsimple_server.py and here how the error was logged:
image

@jku
Copy link
Member

jku commented Aug 11, 2020

Two comments from a quick test:

  • the child process output does get buffered for me (so python3 test_updater.py TestUpdater.test_4_refresh does not notice the 404s): we should start the server using "python -u simple_server.py" to prevent buffering
  • the server output should not be warning because warnings are printed by default. Also we don't really know what the messages are and mostly do not care. info or debug level maybe?

@MVrachev
Copy link
Collaborator Author

MVrachev commented Aug 11, 2020

  • the child process output does get buffered for me (so python3 test_updater.py TestUpdater.test_4_refresh does not notice the 404s): we should start the server using "python -u simple_server.py" to prevent buffering

Yes, I checked that and you are right.
The child process buffers.

The solution that I propose is to use two temporary files: one for stdout and one for stderr.
I imagine that there could be an option which will give you control if you want to see the stdout or not.
I propose that by the default, if the stderr temp file has any information in it, then we would print it and the stdout file will be ignored.

  • the server output should not be a warning because warnings are printed by default. Also, we don't really know what the messages are and mostly do not care. info or debug level maybe?

If we separate stderr from stdout as I proposed above, then we can use logger.warning() or logger.error() for stderr and logger.debug() or logger.info() for stdout.
My opinion is that logger.error() is appropriate for stderr and logger.debug() for stdout.

My bigger concern with that approach is how we are going to propagate the cmd option when using tox or even calling the tests with python aggregate_tests.py...

@jku
Copy link
Member

jku commented Aug 11, 2020

The solution that I propose is to use two temporary files: one for stdout and one for stderr.

You can do that but I don't think it's necessarily worth the effort:

  • what simple_server.py considers stderr/stdout might not map to our categories anyway (as an example: we might expect the server to print errors in some situations: then it's not an error for us)
  • all of simple_server.py output is mostly debugging aid anyway: We'll want to look at it only when something isn't going the way we expected
  • if you separate the streams, you no longer know if the stderr line came before the stdout line...

I think dumping all the server output to debug or info is fine

@jku
Copy link
Member

jku commented Aug 18, 2020

You know what: we should think about combining (or re-ordering) this PR and issue #1111 .

If we had this in utils.py (edited after chat with Martin):

class TestServerProcess():
 
  # starts server, sets up the TempFile, waits for server response before returning
  def __init__(self, server='simple_server.py', port, extra_args=None, timeout=10)
  
  # logs contents of TempFile with given logger, truncates buffer
  def flush_log(self, logger)
  
  # handles kill() and communicate() on the subprocess
  def kill(self)

I think this PR could be vastly smaller and easier to modify later, AND we would have the infra needed by #1111

@MVrachev
Copy link
Collaborator Author

MVrachev commented Sep 2, 2020

I am working to create an abstraction that will handle the subprocess and the temporary files used for logging.
While I am doing this I will release a couple of commits and I will mark this pr as a draft before it's ready for full review.

@MVrachev MVrachev marked this pull request as draft September 2, 2020 15:52
@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch from 94291b6 to e7f56d0 Compare September 3, 2020 13:31
@MVrachev
Copy link
Collaborator Author

MVrachev commented Sep 3, 2020

I have pushed the initial set of commits in which I created the class which handles the server subprocess and the temporary files used for logging.

I have decided to use logging.info for logging in the flus_log function because stdout and stderr are logged together and thus it seems like a reasonable default value.

On a successful test right now no logs like code 404, message File not found or "GET" queries are reported.

I am planning to push at least 1 commit more in which I will remove or reword some of the test comments.

@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch from e7f56d0 to b35a536 Compare September 3, 2020 13:44
tests/test_download.py Outdated Show resolved Hide resolved
tests/utils.py Outdated Show resolved Hide resolved
tests/test_download.py Outdated Show resolved Hide resolved
@jku
Copy link
Member

jku commented Sep 7, 2020

Looks good, thanks! I'll take this for a test run later to see what the output looks like

@MVrachev
Copy link
Collaborator Author

MVrachev commented Sep 9, 2020

I don't know why but when I run python test_arbitrary_package_attack.py I get a resource warning even though I have closed the temporary_log_file in the clean function:
/home/mvrachev/src/tuf/.editable_both/lib/python3.6/posixpath.py:86: ResourceWarning: unclosed file <_io.FileIO name=5 mode='rb+' closefd=True> for b in map(os.fspath, p):

Same for every file where I am using this new abstraction...

@jku
Copy link
Member

jku commented Sep 9, 2020

I don't know why but when I run python test_arbitrary_package_attack.py I get a resource warning even though I have closed the temporary_log_file in the clean function:
/home/mvrachev/src/tuf/.editable_both/lib/python3.6/posixpath.py:86: ResourceWarning: unclosed file <_io.FileIO name=5 mode='rb+' closefd=True> for b in map(os.fspath, p):

I'm guessing this is not your unclosed file -- updater currently leaves unclosed files on pretty much every "error" situation I think. Maybe check if same warning appears on develop branch? If it does then you don't need to handle it here.

You can also get more details on the warning with PYTHONTRACEMALLOC=50 if you want

@MVrachev
Copy link
Collaborator Author

MVrachev commented Sep 9, 2020

I don't know why but when I run python test_arbitrary_package_attack.py I get a resource warning even though I have closed the temporary_log_file in the clean function:
/home/mvrachev/src/tuf/.editable_both/lib/python3.6/posixpath.py:86: ResourceWarning: unclosed file <_io.FileIO name=5 mode='rb+' closefd=True> for b in map(os.fspath, p):

I'm guessing this is not your unclosed file -- updater currently leaves unclosed files on pretty much every "error" situation I think. Maybe check if same warning appears on develop branch? If it does then you don't need to handle it here.

You can also get more details on the warning with PYTHONTRACEMALLOC=50 if you want

Yes, those warnings are visible in the develop branch too.

@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch from a9997e1 to cf404d2 Compare September 9, 2020 16:23
tests/utils.py Outdated Show resolved Hide resolved
tests/test_proxy_use.py Outdated Show resolved Hide resolved
tests/utils.py Outdated Show resolved Hide resolved
@jku
Copy link
Member

jku commented Sep 14, 2020

I left a few comments, otherwise I think it looks good

@trishankatdatadog
Copy link
Member

Just wanted to say: thanks for doing all this tedious but necessary work! 🥇

@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch 3 times, most recently from 5c6eb9f to 1eb38a9 Compare September 17, 2020 10:40
@MVrachev MVrachev marked this pull request as ready for review September 17, 2020 10:47
@MVrachev
Copy link
Collaborator Author

Together with the great help of @jku, we have been elaborating over those changes in the last couple of weeks and now I think this pr is ready for a review!

I have rebased and cleared the commit history to make more sense for a newcomer.

This pr hides the logs from the server because it's using logger.info() to log information from the stdout and stderr of the server subprocesses. That's why it's better to merge this pr after #1145 which will provide a way to receive logs with info logging level. This shouldn't be a problem to receive a review.

Copy link
Member

@joshuagl joshuagl left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for this great set of cleanups @MVrachev. I added a few minor comments and questions, but this is pretty much ready to merge. Excellent PR.

tests/test_download.py Show resolved Hide resolved
tests/test_proxy_use.py Outdated Show resolved Hide resolved
tests/test_updater.py Outdated Show resolved Hide resolved
tests/utils.py Outdated Show resolved Hide resolved
@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch from 1eb38a9 to e338cb9 Compare September 23, 2020 15:23
@MVrachev
Copy link
Collaborator Author

I rebased my changes upon the latest changes in develop and changed the second commit Log subproceses stdout and stderr in temp files with the comments from Joshua.

@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch from e338cb9 to 9e384b9 Compare September 24, 2020 10:06
@MVrachev
Copy link
Collaborator Author

MVrachev commented Sep 24, 2020

I have decided that because I am working in the same code area I will use this pr to fix the issue #1119 too and that's what the last commit is all about.

Copy link
Member

@jku jku left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

Maybe you are aware but I'll mention for future commits: instead of

For reference read:
#1119

you can do Fixes #1119 (or use a few other keywords) to auto-close on merge -- obviously it's useful only if you know the issue should be closed when commit is merged.

Also, the format Fixes issue #N does not seem to work -- this is why this PR cover letter is probably not going to trigger auto-closing either.

@MVrachev
Copy link
Collaborator Author

LGTM.

Maybe you are aware but I'll mention for future commits: instead of

For reference read:
#1119

you can do Fixes #1119 (or use a few other keywords) to auto-close on merge -- obviously it's useful only if you know the issue should be closed when commit is merged.

Also, the format Fixes issue #N does not seem to work -- this is why this PR cover letter is probably not going to trigger auto-closing either.

Thanks!
That's what motivated me to create pr #1152.

Copy link
Member

@joshuagl joshuagl left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is an excellent set of changes, thank you. I'd like to see a minor fixup of a docstring. After that, I think this is good to merge.

tests/utils.py Outdated Show resolved Hide resolved
@joshuagl
Copy link
Member

joshuagl commented Oct 1, 2020

Looks good, thanks Martin. Could you rebase and squash/fixup b9ef099 into e7a8a78?

Logging the stdout and stderr from the test subprocesses into
temporary files clean the console from unnecessary messages from
the server-side such as "code 404, message File not found" or
"GET" queries.

I have decided to create TestServerProcess class that will handle
the server subprocess creation and redirection to a temporary file
object. That way that code can be reused in more than 10 files.

Also, I have cleaned some parts of the unit test to make them more
readable and efficient with the new abstraction.

The unit tests are executed in sequential order and that's why
we can reuse one temporary file object for multiple tests.

Signed-off-by: Martin Vrachev <[email protected]>
Signed-off-by: Martin Vrachev <[email protected]>
I don't see a need to leave a comment about what setupClass,
tearDownClass, setup and tearDown functions do.
There is documentation that describes that.
Additionally, the links referenced in the comments are from
Python 2 is deprecated.

Signed-off-by: Martin Vrachev <[email protected]>
Fixes an issue where rmtree tries to access and consequently remove
a temp folder where the server has opened a file already.
This results in error:
"PermissionError: [WinError 32] The process cannot access the file
because it is being used by another process"

For reference read:
theupdateframework#1119

Signed-off-by: Martin Vrachev <[email protected]>
@MVrachev MVrachev force-pushed the silence-log-with-temp-files branch from b9ef099 to e2ccfdb Compare October 1, 2020 10:41
@MVrachev
Copy link
Collaborator Author

MVrachev commented Oct 1, 2020

Updated.

@joshuagl
Copy link
Member

joshuagl commented Oct 1, 2020

Awesome work, thanks @MVrachev

@joshuagl joshuagl merged commit fb2eaa5 into theupdateframework:develop Oct 1, 2020
@MVrachev MVrachev deleted the silence-log-with-temp-files branch October 5, 2020 10:06
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

Successfully merging this pull request may close these issues.

4 participants