Router: Time initialization fixes and cleanups

Most changes are relevant only if NTP is disabled or failed at startup.

- Require two peers that agree for transports to initialize time
- Briefly ban skewed peer when not initialized, so another peer will be the second sample
- Allow SSU2 to initialize time even for large skews
- Do not allow NTCP2 inbound to initialize time for large skews
- Disable SSU1 time initialization when SSU2 is enabled
- When SSU2 is disabled, allow SSU1 time initialization even for large skews
- Don't adjust to large inbound NTCP2 skews when not initialized
- Round time sent in NTCP2 DateTime block
- Adjust SSU2 skew for RTT
- Don't sort by absolute skew on SSU /peers tab so we can find median
- Only call System.currentTimeMillis() once in RouterClock.setOffset()
- Log tweaks
This commit is contained in:
zzz
2022-12-19 06:45:30 -05:00
parent 51d567ecb4
commit 6092e35b65
9 changed files with 87 additions and 37 deletions

View File

@ -155,7 +155,7 @@ class UDPSorters {
static class SkewComparator extends PeerComparator {
@Override
public int compare(PeerState l, PeerState r) {
long rv = Math.abs(l.getClockSkew()) - Math.abs(r.getClockSkew());
long rv = l.getClockSkew() - r.getClockSkew();
if (rv == 0) // fallback on alpha
return super.compare(l, r);
else

View File

@ -42,6 +42,7 @@ public class RouterClock extends Clock {
/** use system time for this */
private long _lastChanged;
private int _lastStratum;
private long _lastProposedOffset;
private final RouterTimestamper _timeStamper;
/**
@ -109,6 +110,7 @@ public class RouterClock extends Clock {
*/
private synchronized void setOffset(long offsetMs, boolean force, int stratum) {
long delta = offsetMs - _offset;
long systemNow = System.currentTimeMillis();
if (!force) {
if (!_isSystemClockBad && (offsetMs > MAX_OFFSET || offsetMs < 0 - MAX_OFFSET)) {
Log log = getLog();
@ -118,7 +120,7 @@ public class RouterClock extends Clock {
}
// only allow substantial modifications before the first 10 minutes
if (_alreadyChanged && (System.currentTimeMillis() - _startedOn > 10 * 60 * 1000)) {
if (_alreadyChanged && (systemNow - _startedOn > 10 * 60 * 1000)) {
if ( (delta > MAX_LIVE_OFFSET) || (delta < 0 - MAX_LIVE_OFFSET) ) {
Log log = getLog();
if (log.shouldLog(Log.WARN))
@ -137,7 +139,7 @@ public class RouterClock extends Clock {
// only listen to a worse stratum if it's been a while
if (_alreadyChanged && stratum > _lastStratum &&
System.currentTimeMillis() - _lastChanged < MIN_DELAY_FOR_WORSE_STRATUM) {
systemNow - _lastChanged < MIN_DELAY_FOR_WORSE_STRATUM) {
Log log = getLog();
if (log.shouldLog(Log.DEBUG))
log.debug("Ignoring update from a stratum " + stratum +
@ -181,7 +183,7 @@ public class RouterClock extends Clock {
// a previous step adjustment.
// This allows NTP to trump a peer offset after a soft restart
if (_alreadyChanged &&
(stratum >= _lastStratum || System.currentTimeMillis() - _startedOn > 60*1000)) {
(stratum >= _lastStratum || systemNow - _startedOn > 60*1000)) {
// Update the target offset, slewing will take care of the rest
if (delta > 15*1000)
getLog().logAlways(Log.WARN, "Warning - Updating target clock offset to " + offsetMs + "ms from " + _offset + "ms, Stratum " + stratum);
@ -200,19 +202,40 @@ public class RouterClock extends Clock {
}
} else {
Log log = getLog();
if (log.shouldLog(Log.INFO))
log.info("Initializing clock offset to " + offsetMs + "ms, Stratum " + stratum);
_alreadyChanged = true;
if (_context.getBooleanProperty(PROP_DISABLE_ADJUSTMENT)) {
log.error("Clock adjustment disabled", new Exception());
// For setting the clock based on peer skew (DEFAULT_STRATUM)
// we require a simple consensus of two consecutive peers
// to be within 1 minute of each other, and take the average.
if (stratum < DEFAULT_STRATUM ||
(_lastProposedOffset != 0 && Math.abs(_lastProposedOffset - offsetMs) < 60*1000)) {
if (stratum >= DEFAULT_STRATUM && _lastProposedOffset != 0) {
// within 30 sec of each other, take the average
offsetMs = (_lastProposedOffset + offsetMs) / 2;
delta = offsetMs - _offset;
}
if (log.shouldInfo())
log.info("Initializing clock offset to " + offsetMs + "ms, Stratum " + stratum, new Exception());
_alreadyChanged = true;
_lastProposedOffset = 0;
if (_context.getBooleanProperty(PROP_DISABLE_ADJUSTMENT)) {
log.error("Clock adjustment disabled", new Exception());
} else {
_offset = offsetMs;
_desiredOffset = offsetMs;
// this is used by the JobQueue
fireOffsetChanged(delta);
}
} else {
_offset = offsetMs;
_desiredOffset = offsetMs;
// this is used by the JobQueue
fireOffsetChanged(delta);
if (log.shouldInfo())
log.info("Pending clock offset " + offsetMs + "ms, Stratum " + stratum, new Exception());
// so we know we were here
if (offsetMs == 0)
_lastProposedOffset = 1;
else
_lastProposedOffset = offsetMs;
return;
}
}
_lastChanged = System.currentTimeMillis();
_lastChanged = systemNow;
_lastStratum = stratum;
}

View File

@ -204,16 +204,18 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa
long rtt = _context.clock().now() - _con.getCreated();
_peerSkew -= ((rtt / 2) + 500) / 1000;
long diff = 1000*Math.abs(_peerSkew);
if (!_context.clock().getUpdatedSuccessfully()) {
boolean skewOK = diff < Router.CLOCK_FUDGE_FACTOR;
if (skewOK && !_context.clock().getUpdatedSuccessfully()) {
// Adjust the clock one time in desperation
// This isn't very likely, outbound will do it first
// Don't adjust to large skews inbound.
// We are Bob, she is Alice, adjust to match Alice
_context.clock().setOffset(1000 * (0 - _peerSkew), true);
_peerSkew = 0;
if (diff != 0)
_log.logAlways(Log.WARN, "NTP failure, NTCP adjusting clock by " + DataHelper.formatDuration(diff) +
" source router: " + aliceHash);
} else if (diff >= Router.CLOCK_FUDGE_FACTOR) {
_log.logAlways(Log.WARN, "NTP failure, NTCP adjusted clock by " + DataHelper.formatDuration(diff) +
" source router: " + aliceHash.toBase64());
} else if (!skewOK) {
// Only banlist if we know what time it is
_context.banlist().banlistRouter(DataHelper.formatDuration(diff),
aliceHash,

View File

@ -295,7 +295,7 @@ class NTCP2Payload {
}
public int writeData(byte[] tgt, int off) {
DataHelper.toLong(tgt, off, 4, now / 1000);
DataHelper.toLong(tgt, off, 4, (now + 500) / 1000);
return off + 4;
}
}

View File

@ -319,8 +319,8 @@ class OutboundNTCP2State implements EstablishState {
// We are Alice, he is Bob, adjust to match Bob
_context.clock().setOffset(1000 * (0 - _peerSkew), true);
_peerSkew = 0;
_log.logAlways(Log.WARN, "NTP failure, NTCP adjusting clock by " + DataHelper.formatDuration(diff) +
" source router: " + _con.getRemotePeer().calculateHash());
_log.logAlways(Log.WARN, "NTP failure, NTCP adjusted clock by " + DataHelper.formatDuration(diff) +
" source router: " + _con.getRemotePeer().calculateHash().toBase64());
}
changeState(State.OB_GOT_HXY);
_received = 0;

View File

@ -650,7 +650,8 @@ class InboundEstablishState2 extends InboundEstablishState implements SSU2Payloa
if (_timeReceived == 0)
throw new GeneralSecurityException("No DateTime block in Session Request");
// _nextSend is now(), from packetReceived()
_skew = _nextSend - _timeReceived;
_rtt = (int) (_nextSend - _lastSend);
_skew = (_nextSend - _timeReceived) - (_rtt / 2);
if (_skew > MAX_SKEW || _skew < 0 - MAX_SKEW) {
// send another retry with termination
UDPPacket retry = _transport.getBuilder2().buildRetryPacket(this, SSU2Util.REASON_SKEW);
@ -659,7 +660,6 @@ class InboundEstablishState2 extends InboundEstablishState implements SSU2Payloa
}
_sendHeaderEncryptKey2 = SSU2Util.hkdf(_context, _handshakeState.getChainingKey(), "SessCreateHeader");
_currentState = InboundState.IB_STATE_REQUEST_RECEIVED;
_rtt = (int) (_nextSend - _lastSend);
}
/**

View File

@ -382,12 +382,19 @@ class OutboundEstablishState2 extends OutboundEstablishState implements SSU2Payl
// his problem
_context.banlist().banlistRouter(skewString, bob, _x("Excessive clock skew: {0}"));
} else {
boolean skewOK = skew < PacketHandler.MAX_SKEW && skew > (0 - PacketHandler.MAX_SKEW);
if (skewOK && !_context.clock().getUpdatedSuccessfully()) {
if (!_context.clock().getUpdatedSuccessfully()) {
// adjust the clock one time in desperation
_context.clock().setOffset(0 - skew, true);
if (skew != 0)
_log.logAlways(Log.WARN, "NTP failure, UDP adjusting clock by " + skewString);
_log.logAlways(Log.WARN, "NTP failure, SSU2 adjusted clock by " + skewString +
" source router: " + bob.toBase64());
if (!_context.clock().getUpdatedSuccessfully()) {
// clock update was either rejected or is pending.
// ban the router briefly so the other transport does not try it,
// and we will get a 2nd opinion.
_context.banlist().banlistRouter(bob, _x("Excessive clock skew: {0}"), skewString, null, _context.clock().now() + 5*60*1000);
}
} else {
_context.banlist().banlistRouter(skewString, bob, _x("Excessive clock skew: {0}"));
}
@ -635,17 +642,29 @@ class OutboundEstablishState2 extends OutboundEstablishState implements SSU2Payl
if (_timeReceived == 0)
throw new GeneralSecurityException("No DateTime block in Session/Token Request");
// _nextSend is now(), from packetReceived()
_skew = _nextSend - _timeReceived;
if (_requestSentCount == 1)
_rtt = (int) (_nextSend - _requestSentTime);
_skew = (_nextSend - _timeReceived) - (_rtt / 2);
if (!_context.clock().getUpdatedSuccessfully() &&
_timeReceived > BuildTime.getEarliestTime() &&
_timeReceived < BuildTime.getLatestTime()) {
// adjust the clock one time, so we don't have to wait for NTCP to do it
_context.clock().setOffset(0 - _skew, true);
if (_skew != 0) {
String skewString = DataHelper.formatDuration(Math.abs(_skew));
Hash bob = _remotePeer.calculateHash();
_log.logAlways(Log.WARN, "NTP failure, SSU2 adjusted clock by " + skewString +
" source router: " + bob.toBase64());
}
}
// Unlikely, we would have gotten a termination from him and failed already,
// unless our skew limit is stricter than bob's.
if (_skew > MAX_SKEW || _skew < 0 - MAX_SKEW)
throw new GeneralSecurityException("Skew exceeded in Session/Token Request: " + _skew);
throw new GeneralSecurityException("Skew exceeded in Session Created: " + _skew);
_sessReqForReTX = null;
_sendHeaderEncryptKey2 = SSU2Util.hkdf(_context, _handshakeState.getChainingKey(), "SessionConfirmed");
_currentState = OutboundState.OB_STATE_CREATED_RECEIVED;
if (_requestSentCount == 1) {
_rtt = (int) (_nextSend - _requestSentTime);
}
}
/**

View File

@ -611,13 +611,19 @@ class PacketHandler {
}
_context.statManager().addRateData("udp.receivePacketSkew", skew);
if (skewOK && !_context.clock().getUpdatedSuccessfully()) {
if (!_enableSSU2 && !_context.clock().getUpdatedSuccessfully()) {
// adjust the clock one time in desperation
// this doesn't seem to work for big skews, we never get anything back,
// so we have to wait for NTCP to do it
_context.clock().setOffset(0 - skew, true);
if (skew != 0) {
_log.logAlways(Log.WARN, "NTP failure, UDP adjusting clock by " + DataHelper.formatDuration(Math.abs(skew)));
String source;
if (state != null)
source = state.getRemotePeer().toBase64();
else if (outState != null)
source = outState.getRemoteHostId().toString();
else
source = packet.getRemoteHost().toString();
_log.logAlways(Log.WARN, "NTP failure, SSU1 adjusted clock by " + DataHelper.formatDuration(Math.abs(skew)) +
" source " + source);
skew = 0;
}
}

View File

@ -62,7 +62,7 @@ final class RemoteHostId {
if (_ip != null) {
return Addresses.toString(_ip, _port);
} else {
return _peerHash.toString();
return _peerHash.toBase64();
}
}
}