Make tor's Travis stem job log controller messages from stem and tor
Diagnostics for #29437 (moved).
Activity
changed milestone to %Tor: 0.4.1.x-final
Trac:
Parent Ticket: #29437 (moved)
Child Ticket(s): #30592 (closed), #30675 (closed), #30694 (moved)added 041-backport 041-should actualpoints::0.8 component::core tor/tor milestone::Tor: 0.4.1.x-final owner::teor parent::29437 points::0.1 priority::medium resolution::fixed reviewer::catalyst severity::normal sponsor::31-can status::closed stem teor-merge tor-ci-fail-sometimes type::defect version::tor 0.3.5.1-alpha labels
I based these branches on #30234 (moved), because it hasn't been backported to 0.3.5 yet.
See my pull requests:
- 0.3.5: https://github.com/torproject/tor/pull/1044
- master: https://github.com/torproject/tor/pull/1045
- clean merge
- fail test: https://github.com/torproject/tor/pull/1046
Trac:
Status: new to needs_review
Actualpoints: N/A to 0.1
Version: Tor: 0.2.4.8-alpha to Tor: 0.3.5.1-alphaReplying to teor:
I based these branches on #30234 (moved), because it hasn't been backported to 0.3.5 yet.
See my pull requests:
- 0.3.5: https://github.com/torproject/tor/pull/1044
- master: https://github.com/torproject/tor/pull/1045
- clean merge
- fail test: https://github.com/torproject/tor/pull/1046
Ok, that didn't work.
--log infojust makes stem log info-level errors to the terminal. It doesn't change test/data/tor_log.I'll open a child ticket to sort this out.
Trac:
Status: needs_review to needs_informationWe'll need to revise this after #30592 (closed) merges into stem.
Trac:
Status: needs_information to needs_revisionReplying to teor:
I based these branches on #30234 (moved), because it hasn't been backported to 0.3.5 yet.
See my pull requests:
- 0.3.5: https://github.com/torproject/tor/pull/1044
- master: https://github.com/torproject/tor/pull/1045
- clean merge
- fail test: https://github.com/torproject/tor/pull/1046
I have updated these branches with TRACE, and force-pushed.
Trac:
Keywords: N/A deleted, stem added
Actualpoints: 0.1 to 0.3
Status: needs_revision to needs_review
Summary: Make Travis stem log at info level, and tail the log to Make tor's Travis stem job log controller messages from stem and tor
FWIW, it appears that these are running into stem failures in travis as it stands -- which is exactly what they are supposed to help us diagnose, so those stem failures are not blockers here. I see Stem spamming these messages over and over:
05/28/2019 01:04:45 [INFO] Error while receiving a control message (SocketClosed): empty socket content 05/28/2019 01:04:45 [INFO] Error while receiving a control message (SocketClosed): received exception "I/O operation on closed file."If we have not done so already, let's open a stem ticket to improve the output here: if the socket is closed, we probably shouldn't be retrying over and over.
Hi Nick. For what it's worth those errors generally mean that a prior test crashed or otherwise buggered up its tor instance, causing future tests to be unable to authenticate.
What kind of output would you like to have? If it would be helpful I could make stem abort its test run when authentication begins failing. That would cut down on this kind of 'spam' but when this occurrences the proper next step are to look at the test and tor logs.
-
Replying to atagar:
Hi Nick. For what it's worth those errors generally mean that a prior test crashed or otherwise buggered up its tor instance, causing future tests to be unable to authenticate.
What kind of output would you like to have? If it would be helpful I could make stem abort its test run when authentication begins failing. That would cut down on this kind of 'spam' but when this occurrences the proper next step are to look at the test and tor logs.
I think that the right response might be to abort whatever loop is spinning here rather than retrying it over and over? I wouldn't mind a few messages of this kind per test when something is broken, but spamming them like this tends to fill up CI logs. Anything that would make the output shorter in this case would be cool with me.
-
If anybody want to have a look at the failing case that I was talking about, let's see if there's any info we can get from https://travis-ci.org/torproject/tor/jobs/538005761 ? The log-spamming starts around line 4550
As discussed over IRC the verbosity you're seeing are from trace logging. It's expected when you go to that level of logging that the output will get pretty big. After all, that's kinda the point. ;P
None the less I agree this went overboard. I'll look into disabling logging during the test that's causing that (I've done that elsewhere when a test causes too much trace logs). That said, the primary issue is that Stem lacks an option to log to a file rather than stdout. I'll add that per #30675 (closed).
We can also reduce TRACE output by reducing the number of stem tests (#30694 (moved)).
Trac:
Status: needs_information to newReplying to teor:
Replying to teor:
I based these branches on #30234 (moved), because it hasn't been backported to 0.3.5 yet.
See my pull requests:
- 0.3.5: https://github.com/torproject/tor/pull/1044
- master: https://github.com/torproject/tor/pull/1045
- clean merge
- fail test: https://github.com/torproject/tor/pull/1046
I have updated these branches with TRACE, and force-pushed.
I have updated these branches so they only use the stem tests that run tor (#30694 (moved)), and force-pushed.
This should reduce the TRACE output, but maybe not by enough (we might need to tail the output once #30675 (closed) is implemented).
Trac:
Status: new to needs_review
Actualpoints: 0.3 to 0.4Hi teor. If you're looking for a hack to cut down on the TRACE output then maybe pipe the test output to a 'grep -v SocketClosed'? Only a couple messages account for 90% of the output.
I'll probably add the debug file capability over the weekend. When I do I also plan to adjust whatever test is causing such voluminous logs.
Replying to teor:
Replying to teor:
Replying to teor:
I based these branches on #30234 (moved), because it hasn't been backported to 0.3.5 yet.
See my pull requests:
- 0.3.5: https://github.com/torproject/tor/pull/1044
- master: https://github.com/torproject/tor/pull/1045
- clean merge
- fail test: https://github.com/torproject/tor/pull/1046
I have updated these branches with TRACE, and force-pushed.
I have updated these branches so they only use the stem tests that run tor (#30694 (moved)), and force-pushed.
This should reduce the TRACE output, but maybe not by enough (we might need to tail the output once #30675 (closed) is implemented). It looks like the repetitive log messages are still quite numerous, and might obscure useful information. Maybe we want to do the
grep -vfor now?Trac:
Status: needs_review to needs_revisionReplying to catalyst:
Replying to teor:
Replying to teor:
Replying to teor:
I based these branches on #30234 (moved), because it hasn't been backported to 0.3.5 yet. ... This should reduce the TRACE output, but maybe not by enough (we might need to tail the output once #30675 (closed) is implemented). It looks like the repetitive log messages are still quite numerous, and might obscure useful information. Maybe we want to do the
grep -vfor now?See my pull request:
And test requests:
- 0.4.0: https://github.com/torproject/tor/pull/1110
- 0.4.1: https://github.com/torproject/tor/pull/1111
- master: https://github.com/torproject/tor/pull/1045
And a deliberate fail:
Let's deal with other logging fixes in other tickets.
Trac:
Status: needs_revision to needs_review
Actualpoints: 0.4 to 0.6Hmm, the output is good, but the
| grep -v SocketClosedhides the exit status.I added a commit that sets pipefail.
I'm not going to do a whole bunch of branches all over again.
Here are the updated ones:
0.3.5: https://github.com/torproject/tor/pull/1044And a deliberate fail:
master: https://github.com/torproject/tor/pull/1112This change is going to conflict with #29280 (moved), let's try to merge #29280 (moved) first, then rebase #30591 (moved) on #29280 (moved)'s 0.3.5 branch.
(#29280 (moved) is more complex than #30591 (moved), which is a simple patch on 0.3.5, and a clean merge forward.)
Here's another one that exceeded the Travis max log length https://api.travis-ci.org/v3/job/551341879/log.txt
I tried a fix, but the grep hid the exit status. And I tried pipefail, but that didn't work.
I don't know what else to try, do you have any ideas, catalyst?
Replying to teor:
Hmm, the output is good, but the
| grep -v SocketClosedhides the exit status.I added a commit that sets pipefail.
I'm not going to do a whole bunch of branches all over again.
Here are the updated ones:
0.3.5: https://github.com/torproject/tor/pull/1044And a deliberate fail:
master: https://github.com/torproject/tor/pull/1112Replying to teor:
I tried a fix, but the grep hid the exit status. And I tried pipefail, but that didn't work.
If
/bin/shisdash, it might not haveset -o pipefail, which seems to be abashextension.I don't know what else to try, do you have any ideas, catalyst?
I think there's some useful incantation that threads
echo $?around through a bunch of file descriptors through several layers of subshells, though.e.g.,
$ ( ( ( (echo foo; echo bar; echo baz; false); echo $? >&6 ) | grep -v bar >&7 ) 6>&1 | exit `cat` ) 7>&1 || echo fail foo baz failbut I'm trying to figure out if there's a simpler way to accomplish that file descriptor plumbing.
Hi teor. Why are you trying to use grep for this? We added a --log-file argument specifically to avoid this.
https://trac.torproject.org/projects/tor/ticket/30591 https://gitweb.torproject.org/stem.git/commit/?id=d92936c
Replying to atagar:
Hi teor. Why are you trying to use grep for this? We added a --log-file argument specifically to avoid this.
https://trac.torproject.org/projects/tor/ticket/30591 https://gitweb.torproject.org/stem.git/commit/?id=d92936c
I was trying to keep logging progress during the tests.
But you're right, we should log to a file, then use grep on the log file. (Because there's a limit to how much output Travis will store, even on failure.)
I updated all these pull requests:
And test requests:
- 0.4.0: https://github.com/torproject/tor/pull/1110
- 0.4.1: https://github.com/torproject/tor/pull/1111
- master: https://github.com/torproject/tor/pull/1045
And a deliberate fail:
Trac:
Status: needs_revision to needs_reviewThe log output for this job looks fine, and it fails as expected: https://github.com/torproject/tor/pull/1112
We'll still need to work out how to find the logs from the hang 10 minutes ago, but let's do that once we've put useful information in the logs in #30901 (moved).
Replying to teor:
Replying to atagar:
Hi teor. Why are you trying to use grep for this? We added a --log-file argument specifically to avoid this.
https://trac.torproject.org/projects/tor/ticket/30591 https://gitweb.torproject.org/stem.git/commit/?id=d92936c
I was trying to keep logging progress during the tests.
But you're right, we should log to a file, then use grep on the log file. (Because there's a limit to how much output Travis will store, even on failure.)
I updated all these pull requests:
And test requests:
- 0.4.0: https://github.com/torproject/tor/pull/1110
- 0.4.1: https://github.com/torproject/tor/pull/1111
- master: https://github.com/torproject/tor/pull/1045
And a deliberate fail:
- master: https://github.com/torproject/tor/pull/1112 Thanks! These look good. I think you're right that we might have to wait until we add the logging in #30901 (moved) to get useful information on the hangs.
Trac:
Status: needs_review to merge_ready-
This looks okay to me. We may want further refinements on how we show the log, but it won't hurt anybody to merge this to 0.4.1. Please let me know whether you would prefer to merge now or wait until #30901 (moved) has landed.
Replying to nickm:
This looks okay to me. We may want further refinements on how we show the log, but it won't hurt anybody to merge this to 0.4.1. Please let me know whether you would prefer to merge now or wait until #30901 (moved) has landed.
Let's merge now, because the stem job currently fails with:
The job exceeded the maximum log length, and has been terminated. https://travis-ci.org/torproject/tor/jobs/566642646#L30259
Backported to 0.3.5 and later, because I can merge to master to fix CI. (Also, broken CI blocks me from doing backports.)
Merged #30213 (moved), #29280 (moved), and #30591 (moved) together.
Trac:
Status: merge_ready to closed
Resolution: N/A to fixedmentioned in issue #30651 (closed)
mentioned in issue #30675 (closed)
mentioned in issue #30694 (moved)
mentioned in issue #30698 (closed)
mentioned in issue #30700 (moved)
mentioned in issue #29437 (moved)
mentioned in issue #30592 (closed)
moved to tpo/core/tor#30591 (closed)
