Monitor should gracefully handle old STHs.

[GoogleCodeExporter]

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+Yy4SAIhA
KH4K78BVaiIIzADdq4XNMCbJhksJFgFPyaGeGwbCcDb"

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+fkYpnOaSyfsyqRv7YS3tFNjXPUCNidsAIgA
dFGl9tyiZP5KPIrH/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?

Original issue reported on code.google.com by Oliver.W...@gmail.com on 7 Mar 2014 at 5:44

[GoogleCodeExporter]

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".

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

Original comment by goo...@tom-fitzhenry.me.uk on 7 Mar 2014 at 7:04

[GoogleCodeExporter]

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.

Original comment by alcutter@google.com on 10 Mar 2014 at 5:55

• Changed title: Monitor should gracefully handle old STHs.

[GoogleCodeExporter]

Original comment by er...@google.com on 12 Mar 2014 at 3:42

[GoogleCodeExporter]

Original comment by er...@google.com on 12 Mar 2014 at 3:48

[GoogleCodeExporter]

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/di0R
Wt//FPhURa6mm0i7X0OZZNAMFLZU5Q=","tree_head_signature":"BAMARzBFAiBFnCLVTz7+HHQg
6rS/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/di0R
Wt//FPhURa6mm0i7X0OZZNAMFL
ZU5Q=","tree_head_signature":"BAMARzBFAiAjxJ40yAdf+kMU6/MRi6XqcvAcllcjoXz3moCSEl
oNLQIhAJpwlGouHIxSfkcqDRXcF7Qiui3/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/di0R
Wt//FPhURa6mm0i7X0OZZNAMFLZU5Q=","tree_head_signature":"BAMARzBFAiBFnCLVTz7+HHQg
6rS/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...

Original comment by Oliver.W...@gmail.com on 14 Mar 2014 at 1:58

[GoogleCodeExporter]

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

Original comment by benl@google.com on 18 Mar 2014 at 12:11

[GoogleCodeExporter]

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

Original comment by Oliver.W...@gmail.com on 21 Mar 2014 at 3:08