[tor-bugs] #22212 [Core Tor/Tor]: [warn] channelpadding_compute_time_until_pad_for_netflow(): Bug: Channel padding timeout scheduled 164729ms in the past. Did the monotonic clock just jump?

[Tor Bug Tracker & Wiki]

#22212: [warn] channelpadding_compute_time_until_pad_for_netflow(): Bug: Channel
padding timeout scheduled 164729ms in the past. Did the monotonic clock
just jump?
--------------------------+------------------------------------
 Reporter:  arma          |          Owner:  mikeperry
     Type:  defect        |         Status:  reopened
 Priority:  Medium        |      Milestone:  Tor: 0.3.2.x-final
Component:  Core Tor/Tor  |        Version:  Tor: 0.3.1.1-alpha
 Severity:  Normal        |     Resolution:
 Keywords:  tor-client    |  Actual Points:
Parent ID:                |         Points:
 Reviewer:                |        Sponsor:  Sponsor2
--------------------------+------------------------------------

Comment (by arma):

 Ok, I think I've found the bug.

 Ingredient one:
 channel_timestamp_active(), channel_timestamp_recv(), and
 channel_timestamp_xmit() are the only functions that update
 chan->timestamp_xfer. They get called when we add stuff to our outbuf or
 read stuff from our inbuf, but they never get called when we flush our
 outbuf, that is, when we actually wrote stuff onto the network.

 Ingredient two:
 channelpadding_send_padding_cell_for_callback(), if called when
 chan->has_queued_writes(chan) is true (i.e. we still have stuff on the
 outbuf still trying to flush), sets chan->next_padding_time back to 0.

 Ingredient three:
 channelpadding_compute_time_until_pad_for_netflow(), if
 chan->next_padding_time is zero, sets it to chan->timestamp_xfer + the
 freshly chosen padding_timeout. And then it promptly checks if it's
 surprisingly long ago, and warns if it is.

 So if it's been 160 seconds since we read any new cells or queued any new
 cells onto the chan (say, because we've been spending the whole time
 flushing queued stuff, but we hadn't finished flushing until now, and the
 other side didn't have anything to say), then timestamp_xfer is going to
 be 160 seconds in the past, and the newly computed next_padding_time will
 be slightly less than 160 seconds in the past, causing us to log_notice
 and then send a padding cell right then -- when in reality we probably
 flushed on that chan way more recently than 160 seconds ago.

 Is the fix to call channel_timestamp_active() from
 connection_or_finished_flushing()? What is chan->timestamp_active *for*,
 anyway?

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