Bug #1871

time() returns zero (and occasionally 1 or 2)

Added by David Woodhouse over 2 years ago. Updated about 1 year ago.

Status:Closed Start date:2011-12-09
Priority:Normal Due date:
Assignee:- % Done:

0%

Category:-
Target version:-
Difficulty:Medium Tags:needs-triage

Description

Debugging a timeout issue with the OpenConnect VPN client, I have observed time(NULL) repeatedly returning zero or small values.

The VPN client calculates how long to wait in select() by working out when the next keepalive is due based on the timestamp of the last received packet and subtracting "now" from it.

I was seeing weird values in the resulting wait period, and debugging printfs have demonstrated that both the 'last_rx' and 'now' variables sometimes inexplicably contain zero. These variables are only ever set from time().

This is a VM running on a Linux host in KVM. The host has been known to stall, which may lead to timing issues in the guest... but I certainly wouldn't expect time(2) to return zero even then.

SunOS openindiana 5.11 oi_151a i86pc i386 i86pc Solaris

This seems to happen for a second at a time, before fixing itself. Here's an example where nothing actually broke because both 'last_rx' and 'now' variables were zero:

DPD calc: now 1323396909, last_rx 1323396909, due 1323396969, next event 60000
After CSTP, timeout 60000
After tun, timeout 60000
No work to do; sleeping for 60000 ms...
After DTLS, timeout 2147483647
Received uncompressed data packet of 104 bytes
DPD calc: now 0, last_rx 0, due 60, next event 60000
After CSTP, timeout 60000
After tun, timeout 60000
After DTLS, timeout 2147483647
DPD calc: now 0, last_rx 0, due 60, next event 60000
After CSTP, timeout 60000
After tun, timeout 60000
After DTLS, timeout 2147483647
DPD calc: now 0, last_rx 0, due 60, next event 60000
Sending uncompressed data packet of 104 bytes
DPD calc: now 0, last_rx 0, due 60, next event 60000
After CSTP, timeout 60000
After tun, timeout 60000
No work to do; sleeping for 60000 ms...
After DTLS, timeout 2147483647
Received uncompressed data packet of 104 bytes
DPD calc: now 1323396911, last_rx 1323396911, due 1323396971, next event 60000

So it almost looks like there are "missing" seconds, which get reported as zero. time(NULL) was returning zero for all of the time it should have been returning 1323396910.

It looks the same elsewhere — other "missing seconds" in my logs are 1323396993, 1323397009, 1323397042, 1323397119, 1323397135, 1323397244, 1323397353, ...

At 1323397366 it gets more interesting — the results from successive time() calls seem to be 1323397366, 0, 1, 2, 1323397370, 1323397371...

Later on in my logs it's much harder to interpret because there wasn't as much regular traffic so there is plenty of time between output anyway.

History

Updated by David Woodhouse over 2 years ago

It seems that gettimeofday() does the same thing for the seconds field, but µs look sane. This debugging output prints both outputs (return value, and value written to pointer argument) of time() and also the result of gettimeofday():

Sending uncompressed data packet of 104 bytes
in keepalive_action now is 1323785958 (1323785958) or 1323785958.165469
No work to do; sleeping for 60000 ms...
Received uncompressed data packet of 104 bytes
in keepalive_action now is 1323785959 (1323785959) or 1323785959.166381
in keepalive_action now is 1323785959 (1323785959) or 1323785959.166534
in keepalive_action now is 1323785959 (1323785959) or 1323785959.166585
Sending uncompressed data packet of 104 bytes
in keepalive_action now is 1323785959 (1323785959) or 1323785959.167435
No work to do; sleeping for 60000 ms...
Received uncompressed data packet of 104 bytes
in keepalive_action now is 0 (0) or 0.190967
in keepalive_action now is 0 (0) or 0.191006
in keepalive_action now is 0 (0) or 0.191013
Sending uncompressed data packet of 104 bytes
in keepalive_action now is 0 (0) or 0.191197
No work to do; sleeping for 60000 ms...
Received uncompressed data packet of 104 bytes
in keepalive_action now is 1323785961 (1323785961) or 1323785961.157745
in keepalive_action now is 1323785961 (1323785961) or 1323785961.157902
in keepalive_action now is 1323785961 (1323785961) or 1323785961.157947
Sending uncompressed data packet of 104 bytes
in keepalive_action now is 1323785961 (1323785961) or 1323785961.158581
No work to do; sleeping for 60000 ms...
Received uncompressed data packet of 104 bytes

Updated by David Woodhouse about 2 years ago

FWIW this is happening in Solaris 11 too. It's CR7121035 and seems to be mostly ignored there too.

Updated by Ken Mays about 1 year ago

  • Status changed from New to Closed

Not OI-specific to build. Closing ticket (fix required upstream).

Also available in: Atom PDF