aarongable
commented
1 month ago From the full test log, but extracting just the lines relevant to the failed shard:
crl_test.go:67: 17:15:47.544863 6 crl-updater 36fbtw8 Generating CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547385500723}] numChunks=[1]
crl_test.go:67: 17:15:47.548081 6 crl-updater -Lf9oA8 Queried SA for CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547385500723}] expiresAfter=[2024-09-14 11:04:38 +0000 UTC m=+5507330.628751669] expiresBefore=[2024-09-24 11:04:38 +0000 UTC m=+6371330.628751669] numEntries=[1]
crl_test.go:67: 17:15:47.569982 6 crl-updater uPHblAk Generated CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547385500723}] size=[557] hash=[101abd6116f9849e3a3157977bb0aedf92175afe8eae3225e742c6f52dfd670d]
crl_test.go:82: 17:15:47.917617 6 crl-updater 39fglws Generating CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547693645707}] numChunks=[1]
crl_test.go:82: 17:15:47.920974 6 crl-updater womEmQQ Queried SA for CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547693645707}] expiresAfter=[2024-09-14 11:04:38 +0000 UTC m=+5507330.321910629] expiresBefore=[2024-09-24 11:04:38 +0000 UTC m=+6371330.321910629] numEntries=[1]
crl_test.go:82: 17:15:47.933910 3 crl-updater sa64nwY [AUDIT] Generating CRL failed, will retry in 1.051591171s: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547693645707}] err=[closing CRLStorer upload stream: rpc error: code = Unknown desc = crlNumber not strictly increasing: 1720804547693645707 <= 1720804547713446378]
crl_test.go:82: 17:15:48.986287 6 crl-updater 39fglws Generating CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547693645707}] numChunks=[1]
crl_test.go:82: 17:15:48.987623 6 crl-updater womEmQQ Queried SA for CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547693645707}] expiresAfter=[2024-09-14 11:04:38 +0000 UTC m=+5507330.321910629] expiresBefore=[2024-09-24 11:04:38 +0000 UTC m=+6371330.321910629] numEntries=[1]
crl_test.go:82: 17:15:48.991455 3 crl-updater pfimgwI [AUDIT] Generating CRL failed: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547693645707}] err=[closing CRLStorer upload stream: rpc error: code = Unknown desc = crlNumber not strictly increasing: 1720804547693645707 <= 1720804547713446378]This shows the following sequence of events: 1) Successfully generates a CRL with number 1720804547385500723 2) Fails to generate a CRL with number 1720804547693645707 , due to the existence of a CRL with number 1720804547713446378 3) Retries, fails again for the same reason
The obvious question is: where did CRL 77 come from?
The crl_test.go logs show no reference to it, except for the two failure messages. We can conclude that it wasn't generated by crl_test.go.
However, if we look earlier in the integration test output, we can see this collection of log lines:
17:15:47.645084 6 crl-storer ot_S9wI [AUDIT] CRL uploaded: id=[{"issuerID":56183656833365902,"shardIdx":10,"crlNumber":1720804547385500723}] issuerCN=[int rsa c] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]
17:15:47.648832 6 crl-storer n6ir3gY [AUDIT] CRL uploaded: id=[{"issuerID":56183656833365902,"shardIdx":6,"crlNumber":1720804547385500723}] issuerCN=[int rsa c] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]
17:15:47.655829 6 crl-storer sark-w0 [AUDIT] CRL uploaded: id=[{"issuerID":56183656833365902,"shardIdx":9,"crlNumber":1720804547385500723}] issuerCN=[int rsa c] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]
17:15:47.674235 6 boulder-ra zYKfGQA [AUDIT] Revocation request: JSON={"ID":"Do3KclSVzDAwnlkaJ3y1EZV4tT_p8qWipRm3TIBASp8","SerialNumber":"7f74024064d1a002a6a5049d8225bea17c8e","Reason":5,"Method":"subscriber","RequesterID":78}
17:15:47.680739 6 akamai-purger r_LGxg4 [AUDIT] Purge request sent successfully (ID welcome-to-the-purge) (body {"objects":["http://ca.example.org:4002/?body-md5=0968f15b52e71226","http://ca.example.org:4002/MFMwUTBPME0wSzAJBgUrDgMCGgUABBSZIxhd2TJe07rNYa+OT1Fb9KLytgQUjy9tm6pAtmuhgdKoBL4pcwOH35ACEn90AkBk0aACpqUEnYIlvqF8jg==","http://ca.example.org:4002/MFMwUTBPME0wSzAJBgUrDgMCGgUABBSZIxhd2TJe07rNYa%2BOT1Fb9KLytgQUjy9tm6pAtmuhgdKoBL4pcwOH35ACEn90AkBk0aACpqUEnYIlvqF8jg%3D%3D"]}). Purge expected in 153s
17:15:47.727828 6 crl-updater 9u6M0gg Generating CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547713446378}] numChunks=[1]
17:15:47.728552 6 crl-storer nuCwiAw [AUDIT] CRL uploaded: id=[{"issuerID":6762885421992935,"shardIdx":6,"crlNumber":1720804547693645707}] issuerCN=[int rsa b] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]
17:15:47.729154 6 crl-updater 3tP_xQs Queried SA for CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547713446378}] expiresAfter=[2024-09-14 11:04:38 +0000 UTC m=+5507527.655558313] expiresBefore=[2024-09-24 11:04:38 +0000 UTC m=+6371527.655558313] numEntries=[1]
17:15:47.734704 6 crl-storer ltOwHQA [AUDIT] CRL uploaded: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547713446378}] issuerCN=[int rsa a] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[1]
17:15:47.734962 6 crl-updater -NT92Q4 Generated CRL shard: id=[{"issuerID":29947985078257530,"shardIdx":9,"crlNumber":1720804547713446378}] size=[557] hash=[2f861738708e2885c24643f2eb1d1217dcb8e9b55e410ae81dd65e5f5bb687cb]
17:15:47.737068 6 crl-storer 2dCDhQs [AUDIT] CRL uploaded: id=[{"issuerID":6762885421992935,"shardIdx":7,"crlNumber":1720804547693645707}] issuerCN=[int rsa b] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]
17:15:47.741680 6 crl-storer kIHWkgI [AUDIT] CRL uploaded: id=[{"issuerID":6762885421992935,"shardIdx":4,"crlNumber":1720804547693645707}] issuerCN=[int rsa b] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]
17:15:47.742767 6 crl-storer 17HlnwU [AUDIT] CRL uploaded: id=[{"issuerID":6762885421992935,"shardIdx":5,"crlNumber":1720804547693645707}] issuerCN=[int rsa b] thisUpdate=[2024-07-12 17:15:47 +0000 UTC] nextUpdate=[2024-07-21 17:15:46 +0000 UTC] numEntries=[0]What we see here is the following sequence of events: 1) Three log lines (actually many more, but I only kept the last three) from crl-storer, showing it storing some of the CRLs generated by crl_test.go's first run of crl-updater 2) Two log lines from the RA and akamai-purger corresponding to the revocation that crl_test.go does between its two CRL generation cycles 3) Five log lines from crl-updater and crl-storer showing the creation of this single CRL with shardIdx 9 and crlNumber ...77... 4) Three log lines (again many more, but I kept only the first three) from crl-storer, showing it storing some of the CRLs generated by crl_test.go's second run of crl-updater
We know that the log lines in (3) came from the normal instance of crl-updater started by the integration test environment's start.py, because the log lines show up at all. All of the crl-updater log lines created by crl_test.go get captured by the test runner and only printed if something goes wrong (this is why the crl-storer log lines in (1) and (4) aren't interleaved with corresponding crl-updater logs).
So this is just an instance of the integration tests getting unlucky. The crl_test.go integration test raced against the normal semi-random execution of the normal crl-updater, and lost the race.
This does beg the question: why does the CRL uploaded by the normal continuous instance of crl-updater have a slightly larger (i.e. later, since our CRL numbers are just timestamps) number than the one created by crl_test.go's batch process? I think this is simply because there's some delay between the batch process selecting its time and actually doing the work, and there's much less delay in the continuous case. So the continuous process updated one shard in the gap between the batch process picking its time/number and getting around to updating that same shard.
The only real solution I've thought of so far is "don't run crl-updater in continuous mode in the integration test environment". I don't love this idea, because it means that we lose coverage of crl-updater in ./t.sh --start-py, which is legitimately useful. But aside from that, including crl-updater in startservers isn't getting us much, since the only consequence of it going awry is a few log lines, no test failures.
Does anyone have other ideas for how to prevent crl-updater continuous from racing against crl-updater batch in this test?
jsha
Seen here