[tor-bugs] #23570 [Core Tor/Tor]: Tor sometimes loses the last few log lines on shutdown on macOS

[Tor Bug Tracker & Wiki]

#23570: Tor sometimes loses the last few log lines on shutdown on macOS
------------------------------+------------------------------
     Reporter:  teor          |      Owner:  (none)
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:  Tor: unspecified
    Component:  Core Tor/Tor  |    Version:
     Severity:  Normal        |   Keywords:  tor-log, macos
Actual Points:                |  Parent ID:
       Points:  1             |   Reviewer:
      Sponsor:                |
------------------------------+------------------------------
 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.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/23570>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online