Opened 6 years ago

Last modified 11 months ago

#7043 new defect

Tor reports clock jumps when no actual clock jumps occurred

Reported by: joergent Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.3.22-rc
Severity: Normal Keywords: time tor-relay clock-jump vm needs-insight
Cc: opensource@… Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

This is simply not true (verified):

Oct 04 14:54:50.000 [warn] Your system clock just jumped 100 seconds forward; assuming established circuits no longer work.
Oct 04 14:56:40.000 [notice] Giving up on marked_for_close conn that's been flushing for 15s (fd -1, type Socks, state waiting for circuit).
Oct 04 14:56:41.000 [warn] Your system clock just jumped 111 seconds forward; assuming established circuits no longer work.
Oct 04 14:58:21.000 [warn] Your system clock just jumped 100 seconds forward; assuming established circuits no longer work.
Oct 04 14:59:51.000 [notice] Giving up on marked_for_close conn that's been flushing for 15s (fd -1, type Socks, state waiting for circuit).
Oct 04 15:01:31.000 [warn] Your system clock just jumped 100 seconds forward; assuming established circuits no longer work.
Oct 04 15:03:32.000 [warn] Your system clock just jumped 121 seconds forward; assuming established circuits no longer work.

Child Tickets

Change History (16)

comment:1 Changed 6 years ago by nickm

Keywords: tor-relay added
Milestone: Tor: unspecified

That message means that, from Tor's point of view, 100 (or 111, or 121) seconds passed without Tor getting notified of the passage of time. Tor really wants to get notified every second.

Are you on a VM? What OS is this?

comment:2 in reply to:  1 Changed 6 years ago by joergent

Replying to nickm:

That message means that, from Tor's point of view, 100 (or 111, or 121) seconds passed without Tor getting notified of the passage of time. Tor really wants to get notified every second.

Are you on a VM? What OS is this?

It is a plain Linux server, Fedora 17

comment:3 Changed 6 years ago by arma

libevent version?

openntpd / ntpd version?

is the system massively swapping?

comment:4 Changed 6 years ago by rransom

4249#comment:31 is relevant here.

comment:5 in reply to:  4 Changed 6 years ago by joergent

Replying to rransom:

4249#comment:31 is relevant here.

No, not really. It is two different nodes.
However, this node has other CPU-intensive tasks running, but with very low priority 39 + nice 19. Tor should not have any problems with this.

comment:6 in reply to:  3 Changed 6 years ago by joergent

Replying to arma:

libevent version? 2.0.18-1.fc17

openntpd / ntpd version? not installed

is the system massively swapping? no

comment:7 Changed 6 years ago by arma

You have nothing installed to make sure your clock is accurate?

That seems like a poor plan in general.

comment:8 in reply to:  7 Changed 6 years ago by joergent

Replying to arma:

You have nothing installed to make sure your clock is accurate?

That seems like a poor plan in general.

Please, do not make any unwarranted assumptions.
The clock is updated every 8 hours by ntpdate !
Furthermore the incorrect tor log entries were verified by logging the time for every 2 seconds without any jumps

comment:9 Changed 6 years ago by arma

Summary: Incorrectly testing system clockTor reports clock jumps when no actual clock jumps occurred

comment:10 Changed 6 years ago by arma

This bug has happened on and off over the years. We've never fully understood the variety of circumstances that cause it. Usually improving your VM setup, or upgrading your libevent, has been a good way to resolve it.

comment:11 Changed 5 years ago by ln5

FWIW, we see this in FreeBSD jails, currently with tor-0.2.4.17-rc and libevent-2.0.21.

On DFRI3, it's happened about 40 times the last year. They seem to come in chunks, with about 2-4 those days they appear, spread out over 13 days.

DFRI0 has had about 45 of these over 1,5 years, spread out over only 5 days.

comment:12 Changed 5 years ago by cypherpunks

Did you noticed very odd arithmetic:

Oct 04 14:54:50.000 [warn] Your system clock just jumped 100 seconds forward; assuming established circuits no longer work.
Oct 04 14:56:40.000 [notice] Giving up on marked_for_close conn that's been flushing for 15s (fd -1, type Socks, state waiting for circuit).
Oct 04 14:56:41.000 [warn] Your system clock just jumped 111 seconds forward; assuming established circuits no longer work.

clock jumped of 111s since last jump, but [notice] about give up on connection called by run_scheduled_events() from the same second_elapsed_callback() that counts elapsed seconds and warns about clock jumps. That means (now - current_second) was less than 100s just for previous call of second_elapsed_callback(). If it was really jump of clock then difference between timestamps for [notice] and [warn] was more than 1s.

That means time(NULL) returns cached (or something) values, and only sometime updates it (after 1-2 minutes) to real values.

comment:13 Changed 5 years ago by cypherpunks

Another version, something prevents updating of current_second or values changed back, and only after 1-2 minutes nothing stops to update it.

comment:14 Changed 5 years ago by nickm

Part of me wants to use clock_monotonic() and its kin for this situation, but another part of me suspects that a VM that treats time(NULL) in this way is not going to be much kinder to clock_monotonic().

comment:15 Changed 18 months ago by nickm

Keywords: clock-jump vm needs-insight added
Severity: Normal

comment:16 Changed 11 months ago by cypherpunks

Observing

Tor NOTICE: Your system clock just jumped 43422 seconds forward; assuming established circuits no longer work. 
Tor NOTICE: Giving up on marked_for_close conn that's been flushing for 15s (fd 356, type Socks, state open). 

in tor 0.3.2.7-rc on Windows 7 after hibernation.
Does the second message mean the system clock is not monotonic (and harmless)?

Note: See TracTickets for help on using tickets.