Chromium Spelunking: A Stuck Task
Tags: chromium, cpp
Published: 2023-06-05 18:03:53

The [last installment](https://dev.to/djmitche/chromium-spelunking-threads-and-tasks-21hm) was a bit of a detour from our task -- fetching a URL. But, it was a deliberate one, to learn about things I didn't understand well enough. Before that, I had gotten `churl` up to the point where it crashed because its delegate was NULL. So, let's give it a delegate!

## Delegates

Delegates are a common pattern in Chromium, forming a way for lower-level code to interact with higher-level code. It's a kind of [dependency inversion](https://www.chromium.org/developers/design-documents/cookbook/#dependency-inversion). For example, an embedder like Chrome or Fuchsia provides a delegate (several, in fact) to the content layer, which that content layer uses to call back for embedder-related features like autofill.

In this case, we're providing a delegate to the `URLRequest`, a subclass of [`net::URLRequest::Delegate`](https://source.chromium.org/chromium/chromium/src/+/main:net/url_request/url_request.h;l=115;drc=d097a3e9aea0361fe1dbf30c003d20cf6d635320). Happily, most of the methods have default implementations, and in fact the only _required_ method is `OnReadCompleted`.  My delegate overrides that method as well as `OnConnected` and `OnResponseReceived`, just to log when those events occur. In fact, I copied from [`TestDelegate`](https://source.chromium.org/chromium/chromium/src/+/refs/heads/main:net/url_request/url_request_test_util.h;l=97;drc=02199fc586b3af08fee6a7b188d731f381cd814c), including the `buf_` stuff and the `Read` calls.

So, at this point I have a delegate:

```c++
class ChurlDelegate : public net::URLRequest::Delegate {
 public:
  ChurlDelegate()
    : buf_(base::MakeRefCounted<net::IOBuffer>(kBufferSize)) {}
  ~ChurlDelegate() override {}
  int OnConnected(net::URLRequest* request,
                  const net::TransportInfo& info,
                  net::CompletionOnceCallback callback) override {
    DLOG(ERROR) << "OnConnected";
    return net::URLRequest::Delegate::OnConnected(request, info, std::move(callback));
  }

  void OnResponseStarted(net::URLRequest* request, int net_error) override {
    DLOG(ERROR) << "OnResponseStarted";
    if (net_error != net::OK) {
      DLOG(ERROR) << "Error: " << net_error;
      request->Cancel();
      return;                                                                                                                                                                                                      
    }
    // TODO: print response and headers?

    int bytes_read = request->Read(buf_.get(), kBufferSize);
    if (bytes_read >= 0) {
      DLOG(ERROR) << "Read completed immediately";
      OnReadCompleted(request, bytes_read);
    } else if (bytes_read != net::ERR_IO_PENDING) {
      DLOG(ERROR) << "Error from READ: " << bytes_read;
      request->Cancel();
      return;
    }
  }

  void OnReadCompleted(net::URLRequest* request, int bytes_read) override {
    DLOG(ERROR) << "OnReadCompleted with " << bytes_read << " bytes_read";
    do {
      DLOG(ERROR) << "GOT: " << buf_->data();                                                                                                                                                                      
      bytes_read = request->Read(buf_.get(), kBufferSize);
    } while (bytes_read > 0);
  }
 private:
  scoped_refptr<net::IOBuffer> buf_;
};
```
and the Churl class:
```c++
class Churl {
 public:
  void Fetch() {
    net::URLRequestContextBuilder url_request_context_builder;
    url_request_context_builder.set_user_agent("Dustin's Experiment");
    url_request_context_builder.set_proxy_config_service(
      std::make_unique<ProxyConfigServiceDirect>());

    auto url_request_context = url_request_context_builder.Build();

    auto url_request = url_request_context->CreateRequest(
        GURL("http://httpbin.org/get"), // TODO: get this from command line
        net::RequestPriority::HIGHEST,
        &delegate_,                                                                                                                                                                                                
        net::NetworkTrafficAnnotationTag(net::MutableNetworkTrafficAnnotationTag(TRAFFIC_ANNOTATION_FOR_TESTS)),
        false);
    DLOG(ERROR) << "calling start";
    url_request->Start();
    DLOG(ERROR) << "started";
  }

 private:
  std::unique_ptr<net::URLRequestContext> url_request_context_;
  ChurlDelegate delegate_;
};
```

and all of this created in `main` with
```c++
  Churl churl;
  base::ThreadPool::CreateSingleThreadTaskRunner({})->PostTask(
      FROM_HERE, base::BindOnce(&Churl::Fetch, base::Unretained(&churl)));
```

Note that the delegate is passed to `CreateRequest` as a raw pointer. It's up to me to make sure that the delegate continues to exist for the duration of that request, and it will crash otherwise. Ask me how I know!

I put it into an instance variable in `Churl`, since that `Churl` instance lives until the end of `main`. The receiver for the `Fetch` method needs to be included in the task callback, and that's done with `base::Unretained` to indicate that the callback does not "own" the pointer.

## An Easy Fix

So, the first run fails with this:

```
[0525/191840.310712:FATAL:command_line.cc(247)] Check failed: current_process_commandline_. 
```

A little exploring of other "utility" tools like [`root_store_tool`](https://source.chromium.org/chromium/chromium/src/+/main:net/tools/root_store_tool/root_store_tool.cc;bpv=1;bpt=0) suggests
```c++
  base::CommandLine::Init(argc, argv);                                                                                                                                                                             
```

And indeed, this gets things running -- sort of.
```
[0530/190907.523753:ERROR:churl_bin.cc(190)] URLRequestContext created: 0x7f4874003780
[0530/190907.524119:ERROR:churl_bin.cc(198)] calling start    
[0530/190907.526291:ERROR:churl_bin.cc(200)] started           
```

That's it -- no logging from `OnConnected`. Maybe not so easy?

## Finding a Stuck Task

I am sort of old-fashioned, and I'd rather debug things by running them and watching the output, than using fancy tools like `lldb`. My usual tactic is to add lots of debug logging (in Chromium, `DLOG(ERROR) << "got here 1"`) to narrow down where a problem occurs. In this case, `Start()` started things off, but got "stuck" somewhere.

Looking at [`URLRequest::Start`](https://source.chromium.org/chromium/chromium/src/+/main:net/url_request/url_request.cc;l=536;drc=cf7d13faa2b8a7530c261ca512fcbd0869ed2523), it creates a new job with a job factory, and I can verify that it does, indeed call `StartJob(..)` with this new job by adding a debug print after that line.

That job is a subclass of `URLRequestJob`, but which subclass? Codesearch gives a list of subclasses, and `URLRequestHttpJob` seems a likely suspect. Adding some debug prints there confirms this guess. `URLRequestJob` then calls [`job->Start()`](https://source.chromium.org/chromium/chromium/src/+/main:net/url_request/url_request_http_job.cc;l=252;drc=6bfd45d97e9a780d2d5a6f04be930131848eb0b2).

`URLRequestHttpJob` does its work in a series of callback tasks. Each possible bit of work is a separate method, and any conditionals or loops are accomplished "manually" by conditionally calling or posting a task for a different method. It's almost like assembly language, tracing out all of the conditional jumps and control-flow cycles. In this case, adding debug prints to the beginning of each method quickly shows that [`StartTransactionInternal`](https://source.chromium.org/chromium/chromium/src/+/refs/heads/main:net/url_request/url_request_http_job.cc;l=537;drc=c4efcabd32a851d4d7816206d3c8793a55e9d57e) is the last method called.

### `HttpRequestJob::Start`

The `StartTransactionInternal` method seems to set up a transaction and call its `Start` method with a callback bound to `URLRequestHttpJob::OnStartCompleted`. If the `Start` method finishes immediately, it calls `OnStartCompleted` directly. This answers my question from [the first post](https://dev.to/djmitche/chromium-spelunking-getting-started-n84#big-picture): when a function takes a callback, but does not return `ERR_IO_PENDING`, it also does not invoke the callback and expects its caller to do so. This seems like it would be a source of bugs, if one of those two control-flow paths is rarely taken.

Anyway, `OnStartCompleted` is never called, and one more debug print shows that `Start` is returning `ERR_IO_PENDING` so `Start` should be calling it.

I briefly wondered if this was another problem with [threads and tasks](https://dev.to/djmitche/chromium-spelunking-threads-and-tasks-21hm), where the process was exiting before the task had a chance to run. Maybe `FlushForTesting` sees no tasks running while some kind of IO is pending, and returns? I added a sleep in the main task (`base::PlatformThread::Sleep(base::Seconds(5))`) and `OnStartCompleted` still did not run, so it's nothing quite that simple.

So let's dive one layer deeper. `URLRequestHttpJob` is using a factory to make an instance of an interface, in this case an `HttpTransactionFactory` creating an `HttpTransaction`.There's no easy way to print the class name of an object, but codesearch can (usually) list the subclasses of an interface, so a bit of guess-and-check works. My first guess was an `HttpNetworkTransaction`, but a debug print in its `Start` method did not appear. Then I remembered that the `HttpCache` is a "read-through" cache, and a debug print confirms that the `HttpTransaction` is an [`HttpCache::Transaction`](https://source.chromium.org/chromium/chromium/src/+/main:net/http/http_cache_transaction.h;l=53).

### `HttpTransaction::Start`

The `HttpCache::Transaction` class uses the [DoLoop pattern](https://chromium.googlesource.com/chromium/src/+/master/net/docs/code-patterns.md#doloop). I used a quick vim macro to print the states as they occurred:

```
[0525/195452.887052:ERROR:http_cache_transaction.cc(861)] STATE_GET_BACKEND
[0525/195452.887096:ERROR:http_cache_transaction.cc(866)] STATE_GET_BACKEND_COMPLETE
[0525/195452.887189:ERROR:http_cache_transaction.cc(870)] STATE_INIT_ENTRY
[0525/195452.887230:ERROR:http_cache_transaction.cc(875)] STATE_OPEN_OR_CREATE_ENTRY
[0525/195452.887406:ERROR:http_cache_transaction.cc(880)] STATE_OPEN_OR_CREATE_ENTRY_COMPLETE
[0525/195452.887450:ERROR:http_cache_transaction.cc(902)] STATE_ADD_TO_ENTRY
```

So, it's stuck after `DoAddToEntry`. More debug prints there show that it's returning the `rv` from `cache_->AddTransactionToEntry`. `cache_` is an `HttpCache`, so off we go!

### `HttpCache::AddTransactionToEntry`

```c++
  // Adds a transaction to an ActiveEntry. This method returns ERR_IO_PENDING
  // and the transaction will be notified about completion via its IO callback.
  // In a failure case, the callback will be invoked with ERR_CACHE_RACE.
  int AddTransactionToEntry(ActiveEntry* entry, Transaction* transaction);
```

So, what's the transaction's "IO callback" in this case? It has an `io_callback_` property, and elsewhere in `http_cache.cc` I see `transaction->io_callback().Run(OK)` so at a guess that's what it's calling. But, what is that set to at the time? The `HttpCache::Transaction` constructor sets this to a binding for the `OnIOComplete` method, and it seems it's only set to other things in order to support testing. And that just calls `DoLoop`. And that would log. So, what's going on in the cache that causes it not to call the IO callback?

Adding some _more_ debug prints to `HttpCache`, it seems that [`ProcessQueuedTransactions`](https://source.chromium.org/chromium/chromium/src/+/refs/heads/main:net/http/http_cache.cc;l=1105;drc=b192722970ae854473585f077ed7dd489885e4fd) is executing, and posting a task, but `HttpCache::OnProcessQueuedTransactions` never executes.

I got stuck here for a bit, and decided I'd put in enough work to ask for help.  Pairing with a colleague, we pored over the code, looking for what I might have missed. Nothing jumped out as obviously wrong.

As an experiment, we tried posting another task that just contained a lambda expression logging a message. That task ran! So, this isn't an issue of the thread pool not running tasks.

```c++
  base::SingleThreadTaskRunner::GetCurrentDefault()->PostTask(
      FROM_HERE,
      base::BindOnce(&HttpCache::OnProcessQueuedTransactions, GetWeakPtr(),
                     base::UnsafeDanglingUntriaged(entry)));
```

The `GetWeakPtr()` in the `PostTask` invocation is curious, though -- what happens if that pointer becomes invalid before the task runs? Replacing it with `base::Unretained(this)` "fixes" the issue: the callback gets called. So it seems like the task machinery detects that a weak pointer has been invalidated and drops the task depending on it -- a pretty smart way to avoid use-after-free errors! That means that the `HttpCache` is getting destroyed before this callback can begin.

### `HttpCache` Lifetime

So, let's see if we can figure out what's creating that and how long it lasts. It looks like `HttpCache` is a subclass of `HttpTransactionFactory`, and the `URLRequestContext` references it as `http_transaction_factory_`. That's [set by `URLRequestContextBuilder`](https://source.chromium.org/chromium/chromium/src/+/main:net/url_request/url_request_context_builder.cc;l=519?q=URLRequestContextBuilder&ss=chromium%2Fchromium%2Fsrc).

Ah, the `URLRequestContext` is in a local variable so it is being destroyed while the `URLRequest` is still in progress. So that's no good. Rearranging things to keep the context as an instance variable of the `Churl` class fixes the issue.

Which is not to say it's working, but that's a job for the next post in the series:
```
[0605/175824.724186:ERROR:churl_bin.cc(190)] URLRequestContext created: 0x7fb224002df0
[0605/175824.725417:ERROR:churl_bin.cc(198)] calling start     
[0605/175824.730763:ERROR:churl_bin.cc(200)] started     
[0605/175824.734067:FATAL:current_thread.cc(197)] Check failed: sequence_manager. 
#0 0x7fb23107ca8c base::debug::CollectStackTrace()
#1 0x7fb2310332da base::debug::StackTrace::StackTrace()                                                
#2 0x7fb231033295 base::debug::StackTrace::StackTrace()       
#3 0x7fb230d575f9 logging::LogMessage::~LogMessage()           
#4 0x7fb230d02bac logging::(anonymous namespace)::DCheckLogMessage::~DCheckLogMessage()
#5 0x7fb230d02bd9 logging::(anonymous namespace)::DCheckLogMessage::~DCheckLogMessage()
#6 0x7fb230d028bd logging::CheckError::~CheckError() 
#7 0x7fb230ed6cc2 base::CurrentIOThread::Get()     
#8 0x7fb232194f2d net::SocketPosix::Connect()                                                            
#9 0x7fb232199906 net::TCPSocketPosix::Connect()                                                         
```

[update: it turns out it's also necessary to keep the `URLRequest` in an instance variable]