Adding Internals>Network label, which is about as good a label as we have for stuff in content/browser/loader.  

Dumping on triager for more characterization.

Randy: I'm not sure I understand your Comment #2.

And we have Blink>Loader :D

avayvad:  Could you please give more details?  What logs are you referring to, what warning are you referring to?

c#3: My understanding was that stuff in content/browser/loader was supposed to be in the Internals>Network category.  This may be a failure further up the stack (in blink) but it's exhibiting itself in RDHI, so I figured a bit more characterization on that side of the fence was appropriate.  I figured it was appropriate to ask the triager to look at the logs and figure out the basics of where the cancellation request was coming from and why the renderer (?) was cancelling a request that didn't exist.

c#4: Almost certainly the logs from DVLOG(1), since that's where the message in question is coming from.  Having said that, I don't know how to retrieve those logs on Android (logcat?).  I'm pretty sure the warning is either https://chromium.googlesource.com/chromium/src/+blame/master/content/browser/loader/resource_dispatcher_host_impl.cc#1769 or https://chromium.googlesource.com/chromium/src/+blame/master/content/browser/loader/resource_dispatcher_host_impl.cc#1970

Oh, I didn't notice there were two of those. It's the first one, line 1769.

The logs look somewhat like this once the video is being played on the page:

V/chromium(13423): [VERBOSE1:resource_loader.cc(371)] OnReadCompleted: "https://project-1912052061267295165.firebaseapp.com/sintel.mp4" bytes_read = 16384
V/chromium(13423): [VERBOSE1:url_request_job.cc(565)] ReadRawDataComplete() "https://project-1912052061267295165.firebaseapp.com/sintel.mp4" pre bytes read = 16384 pre total = 1441792 post total = 1441792
V/chromium(13423): [VERBOSE1:resource_loader.cc(371)] OnReadCompleted: "https://project-1912052061267295165.firebaseapp.com/sintel.mp4" bytes_read = 16384
V/chromium(13423): [VERBOSE1:url_request_job.cc(565)] ReadRawDataComplete() "https://project-1912052061267295165.firebaseapp.com/sintel.mp4" pre bytes read = 13439 pre total = 1455231 post total = 1455231
V/chromium(13423): [VERBOSE1:resource_loader.cc(371)] OnReadCompleted: "https://project-1912052061267295165.firebaseapp.com/sintel.mp4" bytes_read = 13439
V/chromium(13423): [VERBOSE1:resource_loader.cc(371)] OnReadCompleted: "https://project-1912052061267295165.firebaseapp.com/sintel.mp4" bytes_read = 0
V/chromium(13423): [VERBOSE1:resource_loader.cc(662)] ResponseCompleted: https://project-1912052061267295165.firebaseapp.com/sintel.mp4
V/chromium(13423): [VERBOSE1:resource_dispatcher_host_impl.cc(1769)] Canceling a request that wasn't found

The way I do it to get the logs (you need Android build setup, of course):

1. ninja -C out/Debug chrome_public_apk_incremental && ./out/Debug/bin/install_chrome_public_apk_incremental -v
2. ./build/android/adb_chrome_public_command_line --enable-logging --v=1
3. ./build/android/adb_run_chrome_public https://project-1912052061267295165.firebaseapp.com/without-hack-timer.html
4. Play the video on the page.
5. adb logcat -s chromium | grep -v gpu_channel # removes the noise from GPU logs

To add Android setup to your Linux checkout, follow the instructions: https://www.chromium.org/developers/how-tos/android-build-instructions (no need to have a new checkout, just add "target_os = [ 'android' ]" to your .gclient file and follow from there.

I haven't actually tried it on a Linux build, might be there's the same issue.

So far I have 2 cases.

1 - EVERY request would call cancel when it completed.  This is because WebURLLoaderImpl does not reset the request ID when it completes and WebURLLoaderImpl::~WebURLLoaderImpl always calls cancel in it's destructor.

https://cs.chromium.org/chromium/src/content/child/web_url_loader_impl.cc?sq=package:chromium&l=752

I think it is safe to set request_id_ to -1 as soon as OnCompletedRequest comes in and that clears it up (would love for a sanity check from someone who knows the code better).  It looks like the WebURLLoaderImpl instance is deleted as a result of the didFinishLoading call in the OnCompletedRequest handler so it needs to be cleared before that to be effective.

2 - It looks like in the case of zero-length responses, WebURLLoaderImpl is being destroyed during the WebURLLoaderImpl::Context::OnReceivedResponse handler before the request completed message comes in.

Still tracking down the client handler that cancels the request in the didReceiveResponse handler for this case but presumably it would be better for it to wait for the request completed message instead.

The 0-byte case is for pings and beacons.  They don't expect (want or need) a response so as soon as OnResponseReceived is called they destroy the request which issues a cancel.  In this case, the net stack already knows the request completed and removed it from the pending request queue, the requestCompleted message that was sent from net just hasn't been processed by the renderer yet.

Basically:
- Net generates ResponseReceived message
- Net generates RequestComplete message and removes request from pending queue
- Renderer receives ResponseReceived message
- Renderer destroys request because it doesn't need anything else
- Renderer sends cancel message because it hasn't processed the RequestComplete message yet

The use case looks fine to me and in general it looks like the warning message is subject to a bit of a race anyway for cases where net completes the request and the renderer cancels one before it has realized that net has completed it.

My vote is to:
- Fix the situation where EVERY request is issuing cancel messages
- Remove the DVLOG message since there are valid cases where it will happen

Thanks for digging in and figuring this out, Pat!  So at base it sounds like an unavoidable IPC race--the cancel is sent in response to the ResponseReceived message (and in the abstract can be sent at any time), and passes the RequestComplete message going the other way.  Given that, I think I agree that the ResourceDispatcherHostImpl should accept the responsibility of handling cancel messages for non-existent requests.  Include a comment at the removed DCHECK location as to the case being handled?

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8b3bca182ef878e7f6579bc067dbfae85887e521

commit 8b3bca182ef878e7f6579bc067dbfae85887e521
Author: pmeenan <pmeenan@chromium.org>
Date: Fri Sep 09 12:25:54 2016

Eliminate spurious request cancelations

This fixes the situation where every request is canceled even after it
has completed successfully.  The cancels were not harming anything and
were dropped on the floor but the additional messages were useless.

BUG= 642172 

Review-Url: https://codereview.chromium.org/2303733004
Cr-Commit-Position: refs/heads/master@{#417565}

[modify] https://crrev.com/8b3bca182ef878e7f6579bc067dbfae85887e521/content/browser/loader/resource_dispatcher_host_impl.cc
[modify] https://crrev.com/8b3bca182ef878e7f6579bc067dbfae85887e521/content/child/resource_dispatcher.cc
[modify] https://crrev.com/8b3bca182ef878e7f6579bc067dbfae85887e521/content/child/resource_dispatcher_unittest.cc