Tor events logged by bridgestrap but not properly processed
I was looking at the logs for clues to another issue, and found a few surprising logs messages of this form:
2021/09/26 11:33:06 Testing 1 bridge lines.
2021/09/26 11:33:06 1874064e: Creating new TorEventState with $ABCDEF0123456789 bridge identifier.
2021/09/26 11:33:06 C: SIGNAL ACTIVE
2021/09/26 11:33:06 S: 250 OK
2021/09/26 11:33:06 C: SETCONF Bridge="obfs4 [scrubbed] $ABCDEF0123456789"
2021/09/26 11:33:06 S: 250 OK
2021/09/26 11:33:06 Waiting for Tor to give us test results.
2021/09/26 11:33:06 S: 650 ORCONN $ABCDEF0123456789~name LAUNCHED ID=8619
2021/09/26 11:33:06 S: 650 ORCONN $ABCDEF0123456789~name CONNECTED ID=8619
2021/09/26 11:33:06 S: 650 NEWDESC $ABCDEF0123456789~name
2021/09/26 11:34:06 Tor process timed out.
2021/09/26 11:34:06 Tested 1 bridges: 0 (0.0%) functional; 1 (100.0%) dysfunctional.
Clearly bridgestrap is receiving this event, since it's being logged, but despite the identifier (bridge fingerprint) matching, it is not processing the launched, connected, or newdesc event. I looked in previous days' logs to see if there's something wrong with this bridge in particular, but this bridge succeeded in previous days. This also happens for other bridges and it doesn't seem to matter if the bridge is obfs3 or obfs4. When it occurs, it seems to occur for all bridges in the test.
Future tests also seem to succeed so whatever bad state it's getting into seems to be reset when the next test event occurs.