Opened 19 months ago

Last modified 19 months ago

#23570 new defect

Tor sometimes loses the last few log lines on shutdown on macOS

Reported by: teor Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-log, macos
Cc: Actual Points:
Parent ID: Points: 1
Reviewer: Sponsor:

Description

There seems to be a race condition between writing log lines to log files, and some other tor shutdown/free/process termination.

When I'm using chutney on macOS 10.12, I see these log lines in 000a:

Sep 19 10:53:00.280 [notice] Interrupt: we have stopped accepting new connections, and will shut down in 2 seconds. Interrupt again to exit now.
Sep 19 10:53:00.870 [notice] Time to fetch any signatures that we're missing.
Sep 19 10:53:01.871 [notice] Time to publish the consensus and discard old votes
Sep 19 10:53:01.874 [notice] Published ns consensus
Sep 19 10:53:01.876 [notice] Choosing expected valid-after time as 2017-09-19 00:53:10: consensus_set=1, interval=10
Sep 19 10:53:01.876 [notice] Published microdesc consensus
Sep 19 10:53:01.879 [notice] Choosing expected valid-after time as 2017-09-19 00:53:10: consensus_set=1, interval=10
Sep 19 10:53:01.879 [notice] Choosing expected valid-after time as 2017-09-19 00:53:10: consensus_set=1, interval=10

But these lines in 001a:

Sep 19 10:53:00.281 [notice] Interrupt: we have stopped accepting new connections, and will shut down in 2 seconds. Interrupt again to exit now.
Sep 19 10:53:01.037 [notice] Time to publish the consensus and discard old votes
Sep 19 10:53:01.039 [notice] Published ns consensus
Sep 19 10:53:01.040 [notice] Choosing expected valid-after time as 2017-09-19 00:53:10: consensus_set=1, interval=10
Sep 19 10:53:01.041 [notice] Published microdesc consensus
Sep 19 10:53:01.043 [notice] Choosing expected valid-after time as 2017-09-19 00:53:10: consensus_set=1, interval=10
Sep 19 10:53:01.043 [notice] Choosing expected valid-after time as 2017-09-19 00:53:10: consensus_set=1, interval=10
Sep 19 10:53:02.038 [notice] Clean shutdown finished. Exiting.
Sep 19 10:53:02.038 [notice] SIGINT received a second time; exiting now.

But as far as I can tell, both are executing exactly the same code.

Child Tickets

Change History (2)

comment:1 Changed 19 months ago by teor

Adding a sleep(1); before tor_cleanup(); makes the logs flush correctly. I wonder what the race condition is?

comment:2 Changed 19 months ago by teor

Yawning says:

re your logging thing
the routine that frees the log doesn't flush the ones that have callbacks tied to them
so that's probably your issue
butthat was just 5 mins of skimming the code
...
and there may be a sneeky flush somewhere
I'm not sure what makes a log get a callback vs not either
but the cleanup routines def just obliterate all the things
Note: See TracTickets for help on using tickets.