The last installment 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. 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
. 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
, including the buf_
stuff and the Read
calls.
So, at this point I have a delegate:
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:
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
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
suggests
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
, 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()
.
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
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: 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, 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
.
HttpTransaction::Start
The HttpCache::Transaction
class uses the DoLoop pattern. 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
// 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
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.
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
.
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]
Top comments (0)