bassosimone
commented
9 months ago I committed an hotfix in https://github.com/ooni/probe-cli/pull/1351 and documented a more comprehensive fix in https://github.com/ooni/probe/issues/2551.
We can now mark this issue as closed.
TL;DR This issue is about a bug where the
engineresolverperforms a lookup even if the context is canceled. This leads to the component believing that a given resolver is broken where instead a parent-enforced timeout just occurred. This is the root cause preventing ooniprobe from bootstrapping in certain scenarios, including one described below. However, there is also a secondary issue in the code organization (discussed at the end).Scenario Consider the case where OONI is doing a cold bootstrap. In such a case, the
$HOME/.ooniprobe/engine/directory is empty, so we do not have information on which resolvers are WAI. Let us also assume that all the DNS-over-HTTPS resolvers we may want to use are censored. In such a case, the bootstrap would fail during the iplookup.In this fictional scenario, you would see the following logs. The logs have been reordered for readability and reorganized to explain what happens. I will guide you—as well as myself—through the logs.
We start by attempting to lookup using the
cloudflaremethod. Below, I have reordered the logs (which are out of order because different goroutines may be scheduled at different times) to group related lookups together (I have have removed irrelevant logs that would impact on readability and on the ability to understand what happens):So, overall the lookup lasts 7 seconds. This is because we have a 7 seconds timeout, which was included as a reliability fix according to a comment, and which was introduced by https://github.com/ooni/probe-cli/pull/678, addressing issues https://github.com/ooni/probe/issues/1988 and https://github.com/ooni/probe/issues/2013.
You see that
lookup#1,lookup#2andlookup#3all fail withconnection_refused. Insteadlookup#4fails with ageneric_timeout_errorcaused by a four-second per-lookup timeout.But
lookup#5andlookup#6fail before we hit the four seconds mark, because of the overall 7 seconds timeout that bounds the total runtime of the whole iplookup operation. Here we're clearly witnessing a conflict between different timeout policies. (See the end for more thoughts about the timeout conflict.)Also,
lookup#8andlookup#9have timestamps after the log where theiplookupcomponent tells us it has given up, which is an instance of logs being slightly out of order due to the scheduling of goroutines that I mentioned above.However, and this is particularly important,
lookup#9happens to be the system resolver, which I manually tested and know to be working in this fictional network. Unfortunately, because theengineresolvercomponent schedules lookups even when its context deadline has expired, this means that theengineresolverbelieves that the system resolver is not working as intended and marks it as broken. Had not that happened, we would at least have been able to proceed with the bootstrap. This reckoning is what led me to label this issue as the root cause of the bootstrap failing in this scenario.If you're curious, the bootstrap ends like this:
Also, this is the content of
sessionresolver.stateafter this run:Code organization considerations We have several blocks of code that are synchronous and return a result to the caller or time out. The
model.Resolveris a classical example. However, because of this code organization (which, to my defense looks natural in Go and works fine if the network is not working against you), we need to enforce timeouts inside several code blocks, to make the overall runtime bounded. It should be investigated whether a code organization based on pipelines returning information to callers through channels could be more robust and would require less timeouts. I am leaving this comment here just to document my thoughts while I was analyzing this issue, but it's clear that probably this is a different task that may require us to open and discuss on a separate issue.I covered this issue more in detail in https://github.com/ooni/probe/issues/2545.