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

[V2-UI] Move logging to Rust #6817

Merged
merged 32 commits into from Apr 10, 2019

Conversation

Projects
None yet
6 participants
@blorente
Copy link
Contributor

blorente commented Nov 27, 2018

Problem

Currently, Rust calls Python through FFI to handle logging. As we move to the V2 UI, we would like to make the reverse happen, where the V2 engine logs to the UI.

Solution

The Rust code owns logging (which the Python code can forward to) instead of the other way around.

Note that this PR changes some logging formats (adding timestamps, adding PIDs, and possibly a few other minor changes).

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Nov 27, 2018

@stuhood @illicitonion This is not ready for merging yet, I post it in case you want to take a look.

@stuhood

This comment has been minimized.

Copy link
Member

stuhood commented Nov 27, 2018

@blorente : So, I would definitely recommend splitting #6004 into two separate PRs:

  1. Moving logging from python to rust
  2. Integrating the v2-ui with the rust-side logging

I think that maybe this PR tries to dive into 2 without first tackling 1, so I'd recommend inverting that. If this makes sense, I can update the steps in #6004 (comment) to incorporate that split?

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Nov 27, 2018

@stuhood

This comment has been minimized.

Copy link
Member

stuhood commented Nov 27, 2018

I'm imagining something like <Global logger>.subscribe_ux(UI instance)>, but I'm not sure how to do that in Rust, like what kind of reference I need to pass.

The global logging instance would be a static (possibly initialized via lazy_static!).

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Nov 27, 2018

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Nov 27, 2018

@stuhood

This comment has been minimized.

Copy link
Member

stuhood commented Nov 27, 2018

Looks like wrapping the UIs in an Arc is the way to go, I'll learn about those tomorrow.

Either that, or just directly in the static under a Mutex. If you'd like to schedule a pairing session tomorrow with Daniel or I we can talk that through.

@blorente blorente force-pushed the blorente:blorente/move-logging-to-rust branch from f832238 to 2922ed0 Nov 28, 2018

@blorente blorente force-pushed the blorente:blorente/move-logging-to-rust branch 2 times, most recently from a6651a3 to 8cf5ddd Dec 10, 2018

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 15, 2018

So I think we now log everything we need to log (sample: https://asciinema.org/a/4uE48nHD5XyLohLxeMlcrjDjG).

Now it remains to:

  • Figure out the proper formatting
  • Remove pervious Handlers
  • Testing

However, it's close to reviewable.

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 15, 2018

Also, it might be a good time to see if we want to keep the old format. simplelog::WriteLogger automatically outputs the target and timestamp of the log record, which I find very useful. Is that something we should keep?

@blorente blorente changed the title [WIP] [V2-UI] Move logging to Rust [V2-UI] Move logging to Rust Dec 17, 2018

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 17, 2018

I left some TODOs here and there, but I think this is mostly reviewable (cc @illicitonion @stuhood )

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 17, 2018

Also, it doesn't have any tests yet. I'll try to add them on the plane on Wednesday.

@illicitonion illicitonion requested review from illicitonion and stuhood Dec 17, 2018

@illicitonion
Copy link
Contributor

illicitonion left a comment

Very exciting! Looking forward to it landing!

Show resolved Hide resolved src/python/pants/bin/local_pants_runner.py Outdated
Show resolved Hide resolved src/python/pants/bin/pants_runner.py Outdated
Show resolved Hide resolved src/python/pants/engine/native.py Outdated
Show resolved Hide resolved src/python/pants/init/logging.py Outdated
Show resolved Hide resolved src/python/pants/init/logging.py Outdated
Show resolved Hide resolved src/rust/engine/src/lib.rs Outdated
Show resolved Hide resolved src/rust/engine/src/lib.rs Outdated
Show resolved Hide resolved src/rust/engine/src/lib.rs
Show resolved Hide resolved src/rust/engine/src/lib.rs
Show resolved Hide resolved tests/python/pants_test/test_base.py Outdated
@stuhood
Copy link
Member

stuhood left a comment

Thanks @blorente ! Overall, this looks really good. Doing a bit more to clean up the python side of things will be important before landing. As mentioned, I'll open a review to try and clean up Native initialization, which might help here.

Show resolved Hide resolved src/python/pants/bin/pants_runner.py Outdated
Show resolved Hide resolved src/python/pants/bin/remote_pants_runner.py Outdated
Show resolved Hide resolved src/python/pants/init/logging.py Outdated
Show resolved Hide resolved src/python/pants/init/logging.py Outdated
Show resolved Hide resolved src/rust/engine/logging/src/lib.rs Outdated

pub type Logger = logger::Logger;

// TODO My intuition is that these belog here, because putting them outside of the `logging`

This comment has been minimized.

Copy link
@stuhood

stuhood Dec 21, 2018

Member

Stale comment?

This comment has been minimized.

Copy link
@blorente

blorente Dec 24, 2018

Author Contributor

No, this was in response to a comment by @illicitonion with the question of whether this should go on the FFI definition because it's tied to Rust/Python interaction, or whether it should go in the logging lib because it's exclusively relevant to logging. I decided for the latter, and that comment is my reasoning. Can delete it, though.

This comment has been minimized.

Copy link
@blorente

blorente Dec 24, 2018

Author Contributor

Relevant comment: #6817 (comment)

Show resolved Hide resolved src/rust/engine/logging/src/logger.rs

stuhood added a commit that referenced this pull request Dec 22, 2018

Convert Native into a singleton (#6979)
### Problem

Previously the binary blob loaded by the `Native` instance was fetched using `BinaryUtils`, which meant that fetching it required bootstrap options, which put constraints on where in the process you could use the native instance.

But a while back that binary blob was moved to being loaded with python resources, so instantiating the `Native` instance no longer required any configuration... although its API continued to suggest that it did.

### Solution

Move the last remaining argument for `Native.create(..)` to `Scheduler.__init__`, and replace `Native.create(..)` with `Native.instance()`. While it should also be possible now to remove the passing of the `native` instance in a bunch of places, this PR does not do that, in order to avoid conflicts with other in flight PRs.

### Result

The true requirements of loading a `Native` instance are more apparent, and the initialization code in #6817 should be simplified.

@blorente blorente force-pushed the blorente:blorente/move-logging-to-rust branch from 6a1fb11 to e1f7c66 Dec 24, 2018

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 24, 2018

After Stu's fantastic work on #6979, I have fixed most of the comments and TODOs. I need help with the following item: fd99e5d#diff-42b494f83e5fd1826f7b469b00c79cc3R97
Which is a problem with us missing logs at the RemotePantsRunner client level, before we fork. That and the the BinaryRequest for watchman are not logged, and I suspect a second pair of eyes would be good to solve this one. There is a race condition while writing to the pantsd error file which I suspect is a direct consequence of my first attempt at fixing the issue above (fd99e5d).

Other than that, I think the PR is mostly ready, except for the blatant lack of tests, which will be my next step.
An example of the output here

@cosmicexplorer

This comment has been minimized.

Copy link
Contributor

cosmicexplorer commented Dec 24, 2018

There is a race condition while writing to the pantsd error file

Is this the reason why we are missing logs at the RemotePantsRunner client level pre-fork, or is this a separate issue?

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 26, 2018

There is a race condition while writing to the pantsd error file

Is this the reason why we are missing logs at the RemotePantsRunner client level pre-fork, or is this a separate issue?

That is not a direct result of that bug, but rather a result of me try to fix that bug and installing two handlers, here and here. I think that may create a race condition of logs, to the pantsd logfile. (@cosmicexplorer )

@blorente blorente force-pushed the blorente:blorente/move-logging-to-rust branch from e1f7c66 to 263bdf7 Dec 26, 2018

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Dec 26, 2018

@cosmicexplorer Re: the race condition.
Scratch everything that I said, my current hypothesis is that this race condition is related to the stderr redirect. Rust logs twice, once to stderr and once to the pantsd file. If stderr has been redirected to the pantsd file outside of rust, every write there will also be done to the file without explicit synchronisation. This is consistent with the readings of the logs, because every line is logged twice.

This also means that solving the redirection issue (for which I asked help, I will tackle it tomorrow) will very likely solve this race condition as well.

@blorente blorente force-pushed the blorente:blorente/move-logging-to-rust branch from 263bdf7 to 6447a02 Dec 26, 2018

@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Jan 16, 2019

So there's currently two big separate issues blocking this:

  • We miss some logging very early on in the execution. In particular, we miss everything before we connect to pantsd. The likely culprit is that this line doesn't do what I think it does.

  • There is a moment in the forking process when both the parent and the child are writing simultaneously to the pantsd log. This is because by the time the child process has had time to terminate() services post-fork, some logging has happened (because the parent has had time to re-enable them, if understand correctly).

@illicitonion illicitonion force-pushed the blorente:blorente/move-logging-to-rust branch from c3fbfbe to 9d84495 Apr 10, 2019

illicitonion added some commits Apr 10, 2019

@illicitonion illicitonion merged commit 805d36e into pantsbuild:master Apr 10, 2019

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
@blorente

This comment has been minimized.

Copy link
Contributor Author

blorente commented Apr 10, 2019

@benjyw

This comment has been minimized.

Copy link
Contributor

benjyw commented Apr 11, 2019

This appears to have broken CI:
https://travis-ci.org/pantsbuild/pants/jobs/518368669

Specifically, the new regexps expect the leading [ but the emitted logs don't have them.

@stuhood

This comment has been minimized.

Copy link
Member

stuhood commented Apr 11, 2019

This appears to have broken CI:
https://travis-ci.org/pantsbuild/pants/jobs/518368669

Specifically, the new regexps expect the leading [ but the emitted logs don't have them.

As discussed in #slack, this was likely an inconsistency between the shards in your CI run, as master has been green a few times since that landed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.