[V2-UI] Move logging to Rust #6817

blorente · 2018-11-27T15:58:50Z

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 · 2018-11-27T16:00:36Z

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

stuhood · 2018-11-27T19:45:55Z

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

Moving logging from python to rust
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 · 2018-11-27T20:18:22Z

No need, upon reading it again I understand what you mean. The only thing I have doubts about is how the instances of the UX subscribe to logging. 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.

…

On Tue, 27 Nov 2018, 19:45 Stu Hood ***@***.*** wrote: @blorente <https://github.com/blorente> : So, I would definitely recommend splitting #6004 <#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) <#6004 (comment)> to incorporate that split? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6817 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFlvPloInuPVoonoAsDyLsdhbX7U2AEFks5uzZZ3gaJpZM4Y1zI2> .

stuhood · 2018-11-27T20:48:53Z

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 · 2018-11-27T20:57:05Z

Yeah, that I already fought with for this PR, finally understood it. My doubt is what kind of reference to register, like how does ownership of the UXs look. It makes sense that the lifetime of the UX is the same as the call to `execute`, so I have to find out what kind of reference is actually registered in the logger. Once I have that tomorrow, the rest is actually cake.

…

On Tue, 27 Nov 2018, 20:48 Stu Hood ***@***.*** wrote: 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!). — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6817 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFlvPtQDn-vlhChiYHyypVGA4WpqoOzZks5uzaU3gaJpZM4Y1zI2> .

blorente · 2018-11-27T22:25:03Z

Looks like wrapping the UIs in an `Arc` is the way to go, I'll learn about those tomorrow. On Tue, 27 Nov 2018, 20:56 Borja Lorente Escobar <bescobar@twitter.com wrote:

…

Yeah, that I already fought with for this PR, finally understood it. My doubt is what kind of reference to register, like how does ownership of the UXs look. It makes sense that the lifetime of the UX is the same as the call to `execute`, so I have to find out what kind of reference is actually registered in the logger. Once I have that tomorrow, the rest is actually cake. On Tue, 27 Nov 2018, 20:48 Stu Hood ***@***.*** wrote: > 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!). > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#6817 (comment)>, > or mute the thread > <https://github.com/notifications/unsubscribe-auth/AFlvPtQDn-vlhChiYHyypVGA4WpqoOzZks5uzaU3gaJpZM4Y1zI2> > . >

stuhood · 2018-11-27T22:34:41Z

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 · 2018-12-15T09:14:47Z

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 · 2018-12-15T09:26:22Z

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 · 2018-12-17T10:33:19Z

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

blorente · 2018-12-17T10:39:25Z

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

illicitonion

Very exciting! Looking forward to it landing!

src/python/pants/bin/local_pants_runner.py

src/python/pants/bin/pants_runner.py

src/python/pants/engine/native.py

src/python/pants/init/logging.py

src/rust/engine/src/lib.rs

tests/python/pants_test/test_base.py

stuhood

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.

src/python/pants/bin/pants_runner.py

src/python/pants/bin/remote_pants_runner.py

src/python/pants/init/logging.py

src/rust/engine/logging/src/lib.rs

stuhood · 2018-12-21T19:20:56Z

src/rust/engine/logging/src/lib.rs

+
+pub type Logger = logger::Logger;
+
+// TODO My intuition is that these belog here, because putting them outside of the `logging`


Stale comment?

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.

Relevant comment: #6817 (comment)

src/rust/engine/logging/src/logger.rs

### 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 · 2018-12-24T13:14:42Z

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 · 2018-12-24T17:11:02Z

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 · 2018-12-26T07:40:59Z

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 · 2018-12-26T17:27:57Z

@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 · 2019-01-16T18:11:25Z

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).

Otherwise when python GCs the file object, it tries to close the fd, where the engine may already have closed it and re-opened another file re-using the fd

blorente · 2019-04-10T19:43:45Z

Woohoo!

…

On Wed, 10 Apr 2019, 20:42 Daniel Wagner-Hall, ***@***.***> wrote: Merged #6817 <#6817> into master. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6817 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFlvPpc9Sl_Aq4sJD1v2ENgYKNntrhvQks5vfj6QgaJpZM4Y1zI2> .

benjyw · 2019-04-11T22:55:24Z

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 · 2019-04-11T23:49:13Z

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.

blorente force-pushed the blorente/move-logging-to-rust branch from f832238 to 2922ed0 Compare November 28, 2018 13:57

blorente force-pushed the blorente/move-logging-to-rust branch 2 times, most recently from a6651a3 to 8cf5ddd Compare December 10, 2018 16:07

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

illicitonion requested review from illicitonion and stuhood December 17, 2018 11:06

illicitonion reviewed Dec 17, 2018

View reviewed changes

stuhood reviewed Dec 21, 2018

View reviewed changes

stuhood mentioned this pull request Dec 21, 2018

Convert Native into a singleton #6979

Merged

blorente force-pushed the blorente/move-logging-to-rust branch from 6a1fb11 to e1f7c66 Compare December 24, 2018 13:10

blorente force-pushed the blorente/move-logging-to-rust branch from e1f7c66 to 263bdf7 Compare December 26, 2018 16:37

blorente force-pushed the blorente/move-logging-to-rust branch from 263bdf7 to 6447a02 Compare December 26, 2018 17:29

illicitonion mentioned this pull request Dec 28, 2018

Reqwest uses rustls not openssl #7002

Merged

illicitonion and others added 17 commits April 10, 2019 10:51

De-dupe log format, pull out test helper

85d93df

Fix rust fmt

f1ac593

Un-break test

56ae211

Remove unused variable

c4c8e74

Fix py2 which doesn't have a kwarg here

37631de

Review feedback

2b5b3ce

Fix lint

77a92f1

Remove print that doesn't go anywhere

d315f97

Test debugging

7a03b51

More test debugging

e09128e

Run test a few times

796761b

Flush logs

75f00b2

Restore travis yml

5cbb2f4

Cleanup tempdirs

695f169

Misc comments

bb86453

dup fd

118840b

Otherwise when python GCs the file object, it tries to close the fd, where the engine may already have closed it and re-opened another file re-using the fd

Fix test expectations

9d84495

illicitonion force-pushed the blorente/move-logging-to-rust branch from c3fbfbe to 9d84495 Compare April 10, 2019 09:52

illicitonion added 6 commits April 10, 2019 11:53

Remove unused import

2a36fa0

Fix rustfmt

3daa496

Fix test expectations

258b133

Fix one more test

12bc7cf

Address last few comments

8b53076

Fix typo

db253a9

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

blorente mentioned this pull request Jun 20, 2019

[V2 UI] Pipe Rust Logger to the V2 UI #7906

Closed

cosmicexplorer mentioned this pull request Dec 3, 2019

Add option to attach Subsystems to streaming workunits #8720

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[V2-UI] Move logging to Rust #6817

[V2-UI] Move logging to Rust #6817

blorente commented Nov 27, 2018 •

edited by illicitonion

Loading

blorente commented Nov 27, 2018

stuhood commented Nov 27, 2018

blorente commented Nov 27, 2018 via email

stuhood commented Nov 27, 2018

blorente commented Nov 27, 2018 via email

blorente commented Nov 27, 2018 via email

stuhood commented Nov 27, 2018

blorente commented Dec 15, 2018

blorente commented Dec 15, 2018

blorente commented Dec 17, 2018

blorente commented Dec 17, 2018

illicitonion left a comment

stuhood left a comment •

edited

Loading

stuhood Dec 21, 2018

blorente Dec 24, 2018

blorente Dec 24, 2018

blorente commented Dec 24, 2018 •

edited

Loading

cosmicexplorer commented Dec 24, 2018 •

edited

Loading

blorente commented Dec 26, 2018 •

edited

Loading

blorente commented Dec 26, 2018 •

edited

Loading

blorente commented Jan 16, 2019

blorente commented Apr 10, 2019 via email

benjyw commented Apr 11, 2019 •

edited

Loading

stuhood commented Apr 11, 2019


		pub type Logger = logger::Logger;

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

[V2-UI] Move logging to Rust #6817

[V2-UI] Move logging to Rust #6817

Conversation

blorente commented Nov 27, 2018 • edited by illicitonion Loading

Problem

Solution

blorente commented Nov 27, 2018

stuhood commented Nov 27, 2018

blorente commented Nov 27, 2018 via email

stuhood commented Nov 27, 2018

blorente commented Nov 27, 2018 via email

blorente commented Nov 27, 2018 via email

stuhood commented Nov 27, 2018

blorente commented Dec 15, 2018

blorente commented Dec 15, 2018

blorente commented Dec 17, 2018

blorente commented Dec 17, 2018

illicitonion left a comment

Choose a reason for hiding this comment

stuhood left a comment • edited Loading

Choose a reason for hiding this comment

stuhood Dec 21, 2018

Choose a reason for hiding this comment

blorente Dec 24, 2018

Choose a reason for hiding this comment

blorente Dec 24, 2018

Choose a reason for hiding this comment

blorente commented Dec 24, 2018 • edited Loading

cosmicexplorer commented Dec 24, 2018 • edited Loading

blorente commented Dec 26, 2018 • edited Loading

blorente commented Dec 26, 2018 • edited Loading

blorente commented Jan 16, 2019

blorente commented Apr 10, 2019 via email

benjyw commented Apr 11, 2019 • edited Loading

stuhood commented Apr 11, 2019

blorente commented Nov 27, 2018 •

edited by illicitonion

Loading

stuhood left a comment •

edited

Loading

blorente commented Dec 24, 2018 •

edited

Loading

cosmicexplorer commented Dec 24, 2018 •

edited

Loading

blorente commented Dec 26, 2018 •

edited

Loading

blorente commented Dec 26, 2018 •

edited

Loading

benjyw commented Apr 11, 2019 •

edited

Loading