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

Consume Console/Logger singleton/subsystems to prevent interleaving in @console_rules #6004

Closed
kwlzn opened this issue Jun 22, 2018 · 13 comments
Assignees

Comments

@kwlzn
Copy link
Member

kwlzn commented Jun 22, 2018

breakout task from the v2 FE HLD here


After #6571 is completed, we will be in a situation where the @rules that feed @console_rules are rendered using a curses-like UI, but because we will be writing to stderr in an uncoordinated fashion, usage of the existing Console singleton from a @console_rule will cause interleaved output to stderr (ie, log messages will be-mixed-with/corrupt the ascii codes that position the cursor).

To fix this, we should change the implementation of the Console singleton such that it always send to stdout, and either

  1. sends messages on a queue that is consumed and rendered by the rendering loop added to Scheduler::execute in Curses UX renders during @console_rule execution with interleaved console output #6571.
  2. buffers messages until they are explicitly requested by a caller.

Additionally, we should either:

  1. Add a Logger intrinsic that an @rule may Select that will be customized/prefixed for that @rule
  2. Capture all logging (via the python logging module) that happens within the externs that call arbitrary python code
    ... and then render the output of logging the same way we render output from the Console singleton.
@stuhood stuhood changed the title Implement the Logger singleton/subsystem Implement and consume a Logger singleton/subsystem to prevent interleaving in @console_rules Sep 28, 2018
@stuhood stuhood changed the title Implement and consume a Logger singleton/subsystem to prevent interleaving in @console_rules Consume Console/Logger singleton/subsystems to prevent interleaving in @console_rules Sep 28, 2018
@stuhood
Copy link
Member

stuhood commented Sep 28, 2018

Have updated the description. This is blocked by #6571.

@stuhood stuhood added P3 - M2 and removed P3 - M1 labels Sep 28, 2018
stuhood pushed a commit that referenced this issue Oct 25, 2018
Initially connection between engine execution and the swimlane display. Fixes #6571.

Limitations:
1. having the same task show up in the same lane across updates isn't implemented: see #6666.
2. the UI rendering will squash all logging output: see #6004.
@stuhood stuhood removed the blocked label Oct 25, 2018
@stuhood
Copy link
Member

stuhood commented Oct 25, 2018

This is unblocked!

@stuhood stuhood self-assigned this Nov 2, 2018
@stuhood
Copy link
Member

stuhood commented Nov 2, 2018

Starting this one.

@stuhood
Copy link
Member

stuhood commented Nov 4, 2018

Since we want to (sometimes) pipe all logging through the UX by enqueuing it somewhere, we need the ability to flip a switch that will globally affect logging. While we could in theory have this switch and enqueuing exist on the Python side, it feels more natural to me to move logging to rust before/while doing this. So, my strategy for this ticket looks roughly as follows:

  1. Implement a rust log crate Logger that roughly emulates the simplelog CombinedLogger, and delegates to a combination of three other runtime-re-configurable Loggers:
    1. An optional simplelog WriteLogger for a log file (to implement pantsd.log)
    2. An optional simplelog WriteLogger for stderr
    3. A collection of instances of a custom Logger that enqueue items for each running UX instance
  2. Expose methods to re-configure the rust global logger for use by src/python/pants/init/logging.py and by the UX when it enables and disables.
  3. Install and consume the output of the custom UX Logger in the UX loop using an output queue.
  4. Implement a python logging Handler that delegates all logging to the rust log crate, and update src/python/pants/init/logging.py to install this Handler rather than the handlers it currently installs.
  5. Modify the Console singleton to produce output on the same output queue.

Using simplelog is a somewhat arbitrary choice: it's mostly just to get a useful WriteLogger implementation without a bunch of other boilerplate involved.

This implements a portion of the description: when this is implemented, we will not yet have a Logger singleton that can be injected into @rules, but Console will write to the appropriate UX instance, and all standard python and rust logging will be enqueued such that it will not collide with instances of the UX.

@Eric-Arellano
Copy link
Contributor

@stuhood that sounds well thought out to me.

Something I'm a little confused on, who is the consumer of this API? You mention several ways we may want to do logging—log file, stderr, enqueuing, etc. Is the intent that Pants developers choose which of these 3 they want to do when implementing a particular goal? Or Pants users pass something like a CLI flag to set behavior? Something in between?

@stuhood
Copy link
Member

stuhood commented Nov 5, 2018

@Eric-Arellano : The approaches mentioned above are implementation details below the --v2 API: how @rule developers will consume logging will either be via standard python logging (for now), or via an injected Logger singleton.

See the high level design from https://docs.google.com/document/d/1Hn73YlhTPROlULTMa_3A-Fdv7hAPiHFII8rvXri5l7E/edit?usp=sharing for more info on what more explicit logging would look like, with a Logger singleton.

@illicitonion
Copy link
Contributor

Sounds reasonable :) A few more moving parts than I'd like, but I can't point at any that I'd get rid of, so...

@Eric-Arellano
Copy link
Contributor

@stuhood Google doc complains I need permission. Mind giving read access to all with link?

@stuhood
Copy link
Member

stuhood commented Nov 6, 2018

@stuhood Google doc complains I need permission. Mind giving read access to all with link?

It should be accessible to everyone on pants-devel@. Unfortunately, the doc was created internally, so I can't do more than that with this one. I'll continue to remind folks to create this kind of doc with their personal accounts though.

@stuhood
Copy link
Member

stuhood commented Nov 9, 2018

@Eric-Arellano : Were you able to see it using your pants-devel@ account?

@Eric-Arellano
Copy link
Contributor

@illicitonion and @blorente had some great discussion V2 logging in #7729 (comment) that I'm copying here.

I just had a bunch of discussion with @blorente about this...

I think this is a reasonable short-term hack, but I have some different ideas for the long term.

I think that there are two use-cases for this logging:

  1. Show some watcher (either a user, or travis) that pants isn't hanging.
  2. Give enough useful information that if one particular test is hanging, the user knows which test to debug.

There are two "modes" of pants running:

a. A user is running streaming to a live TTY.
b. Pants is running piped to something that isn't a live TTY.

The v2 UI is meant to solve both 1 and 2, for case a.
This is manually re-implementing the heavy-hitters portion of the v2 UI. Ideally, we wouldn't be > manually implementing this for every console_rule (or rule type in general).

I think the solution I'd like to see long term is something along the lines of:
Remove this logging.
When streaming to a live TTY, we just rely on the v2 UI to display this information.
When not streaming to a live TTY (either on travis, or when piping to a file, or whatever), we periodically dump the heavy hitters to stderr. Maybe every (configurable) 30 seconds, or maybe when the heavy hitters we'd be displaying change, or maybe some combination of the two.

Until the v2 UI lands, I'm happy to add this logging, but I think it's an until-v2-ui hack rather than the right long-term solution...

Eric-Arellano added a commit that referenced this issue May 15, 2019
… is finished (#7729)

We want to add logging to `./pants test` when using V2 both as a matter of UI and to avoid Travis timeouts of not receiving input for 10+ minutes.

Eventually, we should be doing this via a `Logging` singleton, similar to the `Console` singleton, per #6004. This acts as a temporary workaround in the meantime.

### Result
```
$ ./pants --no-v1 --v2 test tests/python/pants_test/util:strutil tests/python/pants_test/util:dirutil tests/python/pants_test/util:contextutil tests/python/pants_test/util:tarutil tests/python/pants_test/util:argutil tests/python/pants_test/util:collections
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:strutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:dirutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:argutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:contextutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:tarutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:collections
18:53:57 [INFO] Tests succeeded: tests/python/pants_test/util:argutil
18:53:59 [INFO] Tests succeeded: tests/python/pants_test/util:collections
18:53:59 [INFO] Tests succeeded: tests/python/pants_test/util:strutil
18:53:59 [INFO] Tests succeeded: tests/python/pants_test/util:tarutil
18:54:00 [INFO] Tests failed: tests/python/pants_test/util:contextutil
18:54:03 [INFO] Tests failed: tests/python/pants_test/util:dirutil
tests/python/pants_test/util:strutil stdout:
============================= test session starts ==============================
platform darwin -- Python 3.6.8, pytest-3.6.4, py-1.8.0, pluggy-0.7.1
rootdir: /Users/eric/DocsLocal/code/projects/pants/.pants.d/process-executionTYuLur, inifile:
plugins: timeout-1.2.1, cov-2.4.0
collected 5 items

pants_test/util/test_strutil.py .....                                    [100%]

=========================== 5 passed in 0.07 seconds ===========================

tests/python/pants_test/util:dirutil stdout:
...
```
@blorente
Copy link
Contributor

Broken off a small self-contained part of this in #7906

@stuhood stuhood mentioned this issue Oct 2, 2019
@stuhood
Copy link
Member

stuhood commented Jan 8, 2020

@gshuflin fixed this a while back! Thanks Greg.

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

5 participants