Opened 7 years ago

Closed 12 months ago

#4834 closed defect (wontfix)

Tor's log lines to stdout don't flush in time for Vidalia to see them?

Reported by: arma Owned by: chiiph
Priority: Medium Milestone:
Component: Archived/Vidalia Version:
Severity: Normal Keywords: archived-closed-2018-07-04
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Erinn has a heisenbug where sometimes her TBB notices Tor's log line about openssl version, and sometimes it doesn't.

My theory is that there's still a gap between when Tor writes logs to stdout, and when Vidalia starts being able to handle log events.

For example: it looks like Tor's stdout logs don't flush at any particular time. So the sequence would be: Vidalia starts Tor, Tor starts with a temporary log to stdout, Vidalia connects over the control port and asks for log events, Vidalia starts ignoring Tor's stdout, Tor closes its temporary logs which flushes all the lines.

One way forward would be to try a Vidalia patch that continues listening to Tor's stdout after it otherwise would start ignoring it; and then see if we get duplicate lines as expected or if we see any new lines we otherwise would have missed. Bonus points if the Vidalia logs label lines as "S" or "E" (stdout or event) to tell which line was which. I'm putting this in the Vidalia component until we've tried this experiment.

Child Tickets

Change History (8)

comment:1 Changed 7 years ago by rtoepfer

Vidalia closes reading of stdout at vidalia/MainWindow.cpp MainWindow::authenticated around line 1485.

The TorProcess::closeStdOut in TorProcess.cpp function does not wait long enough for remaining messages after Vidalia receives Tor's ack for the register events message in the MainWindow::authenticated function. I suggest implementing a preset wait in this function, then moving the closeReadChannel function to occur after this wait. A 250 millisecond wait should be more than adequate. A QTimer wait would also work.

comment:2 Changed 7 years ago by chiiph

Thanks for the suggestion! Would you like to give it a try and make a patch for it? May be another possible solution would be to add a

while(canReadLine()) {
   // read the remaining stdout lines
}

before actually closing the channel.

In case you want to give this a try, please make sure you can reproduce the issue. It's kind of tricky, I wasn't really able to reproduce it.

comment:3 Changed 7 years ago by rtoepfer

I think the bug occurs in this manner: Tor process receives the events registration, Tor process sends a response, OS enforces a context switch, Vidalia process closes read channel, OS enforces a context switch, Tor process flushes remaining bytes.

In this way the bug could not consistently be reproduced. I'll test a fix and post.

comment:4 in reply to:  3 Changed 7 years ago by arma

Replying to rtoepfer:

In this way the bug could not consistently be reproduced. I'll test a fix and post.

There's no need to consistently reproduce the bug. But reproducing it just once would be really helpful, to confirm that it sometimes happens as you describe.

If we can't make it happen this way even once, we should think about looking elsewhere for the bug.

comment:5 in reply to:  description Changed 7 years ago by rtoepfer

Replying to arma:

Erinn has a heisenbug where sometimes her TBB notices Tor's log line about openssl version, and sometimes it doesn't.

My theory is that there's still a gap between when Tor writes logs to stdout, and when Vidalia starts being able to handle log events.

For example: it looks like Tor's stdout logs don't flush at any particular time. So the sequence would be: Vidalia starts Tor, Tor starts with a temporary log to stdout, Vidalia connects over the control port and asks for log events, Vidalia starts ignoring Tor's stdout, Tor closes its temporary logs which flushes all the lines.

One way forward would be to try a Vidalia patch that continues listening to Tor's stdout after it otherwise would start ignoring it; and then see if we get duplicate lines as expected or if we see any new lines we otherwise would have missed. Bonus points if the Vidalia logs label lines as "S" or "E" (stdout or event) to tell which line was which. I'm putting this in the Vidalia component until we've tried this experiment.

arma what are your hardware specs? I suspect the Heisenbug is due to context switches on slower/older hardware.

comment:6 Changed 7 years ago by arma

See report on tor-talk of what looks like this same situation:
http://archives.seul.org/tor/talk/May-2012/msg00186.html

comment:7 Changed 19 months ago by teor

Severity: Normal

Set all open tickets without a severity to "Normal"

comment:8 Changed 12 months ago by teor

Keywords: archived-closed-2018-07-04 added
Resolution: wontfix
Status: newclosed

Close all tickets in archived components

Note: See TracTickets for help on using tickets.