Add logging for request blocking by the RedirectToFileResourceHandler.

Add logging for request blocking by the RedirectToFileResourceHandler.

BUG=None

Committed: https://crrev.com/521af15b4e629ad6c9fdad74ec5299cd868ed64a
Cr-Commit-Position: refs/heads/master@{#441260}

[Randy Smith (Not in Mondays), 2016-12-16 22:30:44]

rdsmith@chromium.org changed reviewers:
+ csharrison@chromium.org, mmenke@chromium.org

[Randy Smith (Not in Mondays), 2016-12-16 22:30:45]

It seems like this is worth the minimal amount of time to throw the CL together.
 Charles, Matt: Whichever of you feels like reviewing it/gets to it first.

[Randy Smith (Not in Mondays), 2016-12-16 22:30:57]

The CQ bit was checked by rdsmith@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-16 22:32:48]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-16 23:14:26]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-16 23:14:26]

Dry run: Try jobs failed on following builders:
  cast_shell_linux on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/cast_shell_linu...)

[Randy Smith (Not in Mondays), 2016-12-17 14:52:08]

The CQ bit was checked by rdsmith@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-17 14:52:17]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-17 15:21:35]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-17 15:21:36]

Dry run: Try jobs failed on following builders:
  cast_shell_linux on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/cast_shell_linu...)

[Randy Smith (Not in Mondays), 2016-12-17 22:01:43]

On 2016/12/16 22:30:45, Randy Smith - Not in Mondays wrote:
> It seems like this is worth the minimal amount of time to throw the CL
together.
>  Charles, Matt: Whichever of you feels like reviewing it/gets to it first.

Hold off on reviewing this--there are subtleties here.  I'll ping again when I
have try jobs working.

[Randy Smith (Not in Mondays), 2016-12-17 22:56:55]

The CQ bit was checked by rdsmith@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-17 22:57:07]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-17 23:45:26]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-17 23:45:27]

Dry run: This issue passed the CQ dry run.

[Randy Smith (Not in Mondays), 2016-12-20 16:51:42]

The CQ bit was checked by rdsmith@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-12-20 16:52:10]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-20 18:31:13]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-12-20 18:31:13]

Dry run: This issue passed the CQ dry run.

[Randy Smith (Not in Mondays), 2016-12-20 18:36:11]

rdsmith@chromium.org changed required reviewers:
+ mmenke@chromium.org

[Randy Smith (Not in Mondays), 2016-12-20 18:36:12]

Ready for review: PTAL?  Charles, I'm afraid you're now an optional reviewer,
since there are some subtleties so I want Matt to take a look.

Notes:
* This ran me into an interesting issue, which is that
URLRequest::LogBlockedBy() should be called at about the same time as the
handler defers the request, but the same is not true for
URLRequest::LogUnblocked().  That's because ResourceControler::Resume() resumes
from the top of the RH stack, and when a RH resumes, what it should do (and what
RedirectToFileResourceHandler does) is finish passing the request down the
ResourceHandler chain and only then call ResourceController::Resume().  I'm
neither clear if there's a better way to handle this nor how this should be
handled in the new RH refactor (which I think is going to make this worse since
the calls into the RH methods are default deferred).  So for now I'm just
calling it out here and I'll try to include it in my ongoing throughs about RH
refactors.

* Because of the above, I did a somewhat more through investigation of
RedirectToFileResourceHandler to see if I could make certain statements about if
the RTFRH had been the one deferring at all locations where LogUnblocked()
should be called.  I concluded that all such locations were indeed only reached
if the RTFRH had previously deferred the request.  Given that I decided that I
wanted to change ResumeIfDeferred() to be unilateral with a DCHECK, and did so. 
But that's the subtly that I'd like Matt to take a look at and see if he finds
any gotchas.

[mmenke, 2017-01-03 20:38:31]

This seems like a good idea.  I believe I didn't add this in the first place
because I thought the class recursively both deferred and called deferrable
methods on the next handler at the same time, but looks like that isn't
happening (So either I was wrong or it has since changed.

https://codereview.chromium.org/2586543003/diff/60001/content/browser/loader/...
File content/browser/loader/redirect_to_file_resource_handler.cc (right):

https://codereview.chromium.org/2586543003/diff/60001/content/browser/loader/...
content/browser/loader/redirect_to_file_resource_handler.cc:258: bool defer =
false;
Why'd you remove the DCHECK(did_defer_);?

[Randy Smith (Not in Mondays), 2017-01-03 22:43:09]

The CQ bit was checked by rdsmith@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-01-03 22:43:32]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Randy Smith (Not in Mondays), 2017-01-03 22:43:59]

Good point; thanks for questioning me on the DCHECK.

Any other thoughts?

https://codereview.chromium.org/2586543003/diff/60001/content/browser/loader/...
File content/browser/loader/redirect_to_file_resource_handler.cc (right):

https://codereview.chromium.org/2586543003/diff/60001/content/browser/loader/...
content/browser/loader/redirect_to_file_resource_handler.cc:258: bool defer =
false;
On 2017/01/03 20:38:29, mmenke wrote:
> Why'd you remove the DCHECK(did_defer_);?

Because I was putting in the same DCHECK in Resume().  But that's not always
run, so yeah, it should be here too.  Re-inserted.

[mmenke, 2017-01-03 22:44:54]

On 2017/01/03 22:43:59, Randy Smith - Not in Mondays wrote:
> Good point; thanks for questioning me on the DCHECK.
> 
> Any other thoughts?

Nope, this LGTM.

[commit-bot: I haz the power, 2017-01-03 23:40:48]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-01-03 23:40:49]

Dry run: This issue passed the CQ dry run.

[Randy Smith (Not in Mondays), 2017-01-04 00:07:41]

The CQ bit was checked by rdsmith@chromium.org

[commit-bot: I haz the power, 2017-01-04 00:08:16]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-01-04 00:13:54]

CQ is committing da patch.

Bot data: {"patchset_id": 100001, "attempt_start_ts": 1483488461703390,
"parent_rev": "244609779da83d3ff6952bee04a2bb04baef8640", "commit_rev":
"dcfca594f51026a5939bf0f41c6ff43fecca604d"}

[commit-bot: I haz the power, 2017-01-04 00:14:24]

Description was changed from

==========
Add logging for request blocking by the RedirectToFileResourceHandler.

BUG=None
==========

to

==========
Add logging for request blocking by the RedirectToFileResourceHandler.

BUG=None

Review-Url: https://codereview.chromium.org/2586543003
==========

[commit-bot: I haz the power, 2017-01-04 00:14:25]

Committed patchset #6 (id:100001)

[commit-bot: I haz the power, 2017-01-04 00:16:51]

Description was changed from

==========
Add logging for request blocking by the RedirectToFileResourceHandler.

BUG=None

Review-Url: https://codereview.chromium.org/2586543003
==========

to

==========
Add logging for request blocking by the RedirectToFileResourceHandler.

BUG=None

Committed: https://crrev.com/521af15b4e629ad6c9fdad74ec5299cd868ed64a
Cr-Commit-Position: refs/heads/master@{#441260}
==========

[commit-bot: I haz the power, 2017-01-04 00:16:52]

Patchset 6 (id:??) landed as
https://crrev.com/521af15b4e629ad6c9fdad74ec5299cd868ed64a
Cr-Commit-Position: refs/heads/master@{#441260}

[mmenke, 2017-01-06 17:56:17]

https://codereview.chromium.org/2586543003/diff/100001/content/browser/loader...
File content/browser/loader/redirect_to_file_resource_handler.cc (right):

https://codereview.chromium.org/2586543003/diff/100001/content/browser/loader...
content/browser/loader/redirect_to_file_resource_handler.cc:319: Resume();
Randy:  This looks like a bug to me:

If this is called from OnReadCompleted, and BufIsFull(), we set did_defer_ to
true in OnReadCompleted before calling this method.  Then if we write the entire
buffer synchronously in this loop, we end up here (write_cursor_ ==
buf_->offset(), !buf_write_pending_, BufIsFull() are all true)....And then we
call Resume().  But we haven't yet deferred the request!

Am I missing something?  This issue existed before this CL.

[Randy Smith (Not in Mondays), 2017-01-09 21:55:27]

https://codereview.chromium.org/2586543003/diff/100001/content/browser/loader...
File content/browser/loader/redirect_to_file_resource_handler.cc (right):

https://codereview.chromium.org/2586543003/diff/100001/content/browser/loader...
content/browser/loader/redirect_to_file_resource_handler.cc:319: Resume();
On 2017/01/06 17:56:17, mmenke wrote:
> Randy:  This looks like a bug to me:
> 
> If this is called from OnReadCompleted, and BufIsFull(), we set did_defer_ to
> true in OnReadCompleted before calling this method.  Then if we write the
entire
> buffer synchronously in this loop, we end up here (write_cursor_ ==
> buf_->offset(), !buf_write_pending_, BufIsFull() are all true)....And then we
> call Resume().  But we haven't yet deferred the request!
> 
> Am I missing something?  This issue existed before this CL.

Nice catch.  This looks like a bug in RTFRH, but not one that is going to be
tripped--at least, it looks to me as if writer_->Write() below will always
return either an error or ERR_IO_PENDING, which means we'll never go around the
loop.   I've filed http://crbug.com/679483 to track it, but I don't think we
need to fix it with high priority (unless I'm missing a synchronous return path
from the called functions).