OpenIndiana Distribution

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.