Improve eliot logging in integration tests. #449
Conversation
This allows automation to not need to special-case the integration tests.
I'm changing the interface of `_magic_folder_runner` to provide the output of the command directly, so replace this caller with the already existing wrapper of these commands.
This allows us to separate out (some of) the eliot logs by test, which makes reading them much easier.
Every caller was doing this already, so just move it into the function. Also add loggin of each call, including the output.
`_MagicTextProtocol` has two purposes: - capture output of a service and log it to eliot - notice when the service has started, and return control to the caller via the callback. The logs from the service want to be associated to with action for the service. However, we don't want the code in the caller to be associated to that action. Thus, we move the callback outside of the action.
Now that we only capture them when asked, we can reasonably write them to the current directory.
This wraps `_MagicTextProtocol`, and ensures that the output is capture in an appropriate action.
|
Note that there are a lot of changes in this PR, but they are split into relatively small commits, that can be reviewed on their own. |
|
@exarkun I'm asking you for a review on this, since I think meejah is out next week. |
|
The macOS integration failure is an intermittent issue that hopefully this and #445 will help debug. |
Codecov Report
@@ Coverage Diff @@
## main #449 +/- ##
=======================================
Coverage 91.08% 91.08%
=======================================
Files 33 33
Lines 2715 2715
Branches 315 315
=======================================
Hits 2473 2473
Misses 170 170
Partials 72 72
Flags with carried forward coverage won't be shown. Click here to find out more. Continue to review full report at Codecov.
|
| def introducer(reactor, tahoe_venv, temp_dir, flog_gatherer, request): | ||
| config = ''' | ||
| with start_task(action_type=u"integration:introducer").context(): |
There was a problem hiding this comment.
I can't recall a time when I've used start_task instead of start_action. I understand that the difference is that start_task will not search out a parent from the Eliot context: it will always be a new top-level action? So "running the introducer" is a top-level action regardless of the Eliot context in which this fixture is invoked?
I'm not sure how to reason about when it makes sense to start a new top-level action (apart from there being no other active action) and when it makes sense to respect the current Eliot context. Do you have a set of rules for this you can share? Or maybe just a comment about this specific case.
There was a problem hiding this comment.
Mostly the reason it is this way is that I played around with various options, looking at the eliot-tree output of test runs with them.
- Partly what is going on is that fixtures are run outside the context of the thing requesting them, particularly session fixtures. One iteration did have a session-scope auto-use fixture that did have a task, that all other session scoped fixtures were child actions of, but that didn't make it easier to read the logs. I do have that for tests, which does work better (though I'm not sure there are fest (i.e. function) scoped fixtures that would capture logs for.
- If you have multiple, mostly unrelated fixtures, that each have an action wrapping them, then each action is going to be a child of the previous one, but the nesting is going to be somewhat arbitrary, and makes the logs harder to read. (One particular example of confusing nesting, in a slightly different context, is that the magic-folder (stdout) logs from restarting the service where in the test that restarted them, even if it kept running into a later test).
|
|
||
|
|
||
| @pytest.fixture(scope='session') | ||
| @log_call(action_type=u"integration:introducer:furl", include_args=["temp_dir"]) |
There was a problem hiding this comment.
Is the net of this PR that the Eliot log no longer contains the introducer furl? Previously log_call would log the return value of this function now it doesn't. Does something else?
| @@ -0,0 +1 @@ | |||
| Add your info here | |||
Cleanup all the existing eliot logging in the integration tests, in preparation for capturing the logs from the services. (see #445)
The main goal here is to ensure that all eliot logs are captured in an appropriate action (in particular one that hasn't been finished, as eliot won't associate messages from after action was finished, when parsing).
This add a bunch of wrappers to the code for running services and commands, to ensure that logs for each process are consistently captured in a given action, and that that action doesn't end until the process does.
This also puts foolscap log capturing behind a pytest option, as I think that is unlikely to be useful to magic-folder developers most of the time.