Monitor should gracefully handle old STHs.

[pphaneuf]

No description provided.

[pphaneuf]

After running the monitor (C++) for a while now, we've noticed strange behaviour.

We've received some STH $A. After a while we've received a newer STH $B and then we've received the old STH $A, again.

Details:
On 14-02-12 GMT the following STH was provided by the log from 03:15 AM to 04:13 AM via http://ct.googleapis.com/pilot/ct/v1/get-sth.
"tree_size":3442201
"timestamp":1392173410286
"sha256_root_hash":"5VXqk6L/v04ZfqTKlfpSTbqh6uRR15hD4VSZl9nwc/A="
"tree_head_signature":"BAMARzBFAiBT8YrMUKLuxhsYw3FN4S2vyNfAEEly+xCrz81v+Yy4SAIhAKH4K78BVaiIIzADdq4XNMCbJhksJFgFPyaGeGwbCcDb"

On 04:15 Am the following STH was provided until 05:00 AM.
"tree_size":3442204
"timestamp":1392177003058
"sha256_root_hash":"TTldt24fAwAn0DkVbrpe4hqhi/pgDBfICWhaUewk828="
"tree_head_signature":"BAMARjBEAiByfbRoOnBFA+fkYpnOaSyfsyqRv7YS3tFNjXPUCNidsAIgAdFGl9tyiZP5KPIrH/zyo2a5Y+UiHXkHYasVINWEbwI="

Then the older STH was delivered by the log on 05:01 AM, again.

In its current implementation the monitor (C++) would treat this as misbehaviour - because we thought this actually is misbehaviour. Is this correct? If so, what happened on your side?

[pphaneuf]

I don't know whether the team running the Google log servers consider this behaviour to be a bug, but the behaviour seems compliant with RFC 6962.

The only relevant requirements on the response of get-sth are:
"Each log MUST produce on demand a Signed Tree Head that is no older than the Maximum Merge Delay."

In the behaviour you observed, the STHs are within the log's MMD[0].

Notably, RFC 6962 does not require that responses to get-sth be in-order (with respect to tree_size). I suspect such a requirement would be too constraining for a distributed system (which production-quality log servers inevitably end up being).

Given this, monitors should gracefully handle old STHs.

Note that "gracefully handle old STHs" doesn't mean ignoring them and asking for a new STH. To see why, suppose upon querying get-sth three times, you receive the following three STHs (all within the MMD):
10:00 --> tree_size: 100
10:30 --> tree_size: 200
11:00 --> tree_size: 150

In this case, a monitor must verify the consistency of (rather than ignore) the STH with tree_size 150, since that may be a log server's attempt at forking.

I think the monitor algorithm described in http://tools.ietf.org/html/rfc6962#section-5.3 sufficiently covers this case ("Fetch the current STH (Section 4.3). Repeat until the STH changes."), but perhaps the term "new STH" used later in the algorithm could be clarified to mean "STH you haven't seen before", to avoid it being interpreted it as "STH with an equal or larger tree_size than the most recent STH".

1. Technically Google have yet to define Pilot's MMD, but I expect it will be greater than 2h10m ... ?

[pphaneuf]

That's interesting... technically it shouldn't really happen with our logs, at least not over a window of that size, but Tom's response is insightful and pretty much on the money.

Thanks for reporting, though. I'll look into what could have caused that.

I've updated the issue summary as this is really a bug against the monitor code.

[pphaneuf]

Thanks for the input. We will patch the monitor accordingly and submit the patch set as usual.

BTW Al, the log server imposed a similar behaviour last Friday, 07-03-14 GMT, but this time the tree size didn't even change.

First time received STH $A:
I0307 19:11:42.732981 18843 http_log_client.cc:124] response = {"tree_size":3555243,"timestamp":1394211557413,"sha256_root_hash":"NeCSrKA6/di0RWt//FPhURa6mm0i7X0OZZNAMFLZU5Q=","tree_head_signature":"BAMARzBFAiBFnCLVTz7+HHQg6rS/6htbpVwrt9UVtSfyvzQ7rj1BhgIhAKZrV14uP4OVRtfOssfMWanSe58aXaPbZGmdXYUeCuTJ"}

First time received STH $B (with a refreshed timestamp and no other changes):
I0307 19:26:54.879812 18843 http_log_client.cc:124] response = {"tree_size":3555243,"timestamp":1394218686555,"sha256_root_hash":"NeCSrKA6/di0RWt//FPhURa6mm0i7X0OZZNAMFL
ZU5Q=","tree_head_signature":"BAMARzBFAiAjxJ40yAdf+kMU6/MRi6XqcvAcllcjoXz3moCSEloNLQIhAJpwlGouHIxSfkcqDRXcF7Qiui3/cMQuynU/SF+laI5b"}

Received STH $A, again:
I0307 20:11:26.318377 18843 http_log_client.cc:124] response = {"tree_size":3555243,"timestamp":1394211557413,"sha256_root_hash":"NeCSrKA6/di0RWt//FPhURa6mm0i7X0OZZNAMFLZU5Q=","tree_head_signature":"BAMARzBFAiBFnCLVTz7+HHQg6rS/6htbpVwrt9UVtSfyvzQ7rj1BhgIhAKZrV14uP4OVRtfOssfMWanSe58aXaPbZGmdXYUeCuTJ"}

Again - as Tom explained - this behaviour is acceptable according to the RFC but I'm eager to know why the pilot log server actually behaves this way :-)
Al, if you find something out I would be happy about any information you can provide. The thing is, I still fear for some intervening proxy-servers (or something similar) from the university network - should not be the case but you know...

[pphaneuf]

See also http://trac.tools.ietf.org/wg/trans/trac/ticket/13.

[pphaneuf]

FYI, we used https the past week and didn't trigger this issue anymore. This does not necessarily render Bens ticket obsolete, of course.