We need to add --log TRACE to stem's command line to get controller messages.
atagar recently changed stem to launch tor with logging at debug level, which should show us tor's control messages in the logs.
I have updated these branches with TRACE, and force-pushed.
Trac: Keywords: N/Adeleted, 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 content05/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.
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
The pull requests (other than the deliberate failure) seem to exceed the Travis max log length limitation. I'm not sure whether we need to try a different approach or if we should wait for stem to fix the log spamming on control connection close.
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 legacy/trac#30675 (closed).