New issue
Advanced search Search tips

Issue 765869 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Oct 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Fuchsia
Pri: 3
Type: Bug
Proj-Servicification

Blocking:
issue 882906
issue 754861



Sign in to add a comment

URLLoaderImplTest.CantSniffEmptyHtml fails when IO goes pending

Project Member Reported by scottmg@chromium.org, Sep 16 2017

Issue description

This occasionally flakes on Fuchsia, but I suspect it's cross-platform.

Failing run:

[00237.597] 399115.399142> [ RUN      ] URLLoaderImplTest.CantSniffEmptyHtml
[00237.613] 02339.03578> netstack: ErrNotSupported: socket: unknown network protocol: 16
[00237.618] 399115.399142> [3:1106148611:0916/002731.210665:237618694:ERROR:url_loader_impl.cc(62)] PopulateResourceResponse,
[00237.618] 399115.399142> [3:1106148611:0916/002731.210945:237618983:ERROR:loader_util.cc(22)] ShouldSniffContent, mime_type=
[00237.619] 399115.399142> [3:1106148611:0916/002731.211129:237619163:ERROR:loader_util.cc(36)] To buffer: http://127.0.0.1:44126/content-sniffer-test4.html
[00237.619] 399115.399142> [3:1106148611:0916/002731.211297:237619327:ERROR:url_loader_impl.cc(305)] calling ReadMore loc0
[00237.619] 399115.399142> [3:1106148611:0916/002731.211419:237619448:ERROR:url_loader_impl.cc(312)] ReadMorex0,
[00237.619] 399115.399142> [3:1106148611:0916/002731.211536:237619565:ERROR:url_loader_impl.cc(329)] ReadMorex1,
[00237.619] 399115.399142> [3:1106148611:0916/002731.211666:237619699:ERROR:url_loader_impl.cc(345)] ReadMorex2,
[00237.619] 399115.399142> [3:1106148611:0916/002731.211838:237619867:ERROR:url_loader_impl.cc(357)] io was pending
[00237.621] 399115.399142> [3:1106148611:0916/002731.213616:237621645:ERROR:url_loader_impl.cc(440)] DidRead call1
[00237.621] 399115.399142> [3:1106148611:0916/002731.213739:237621768:ERROR:url_loader_impl.cc(394)] DidRead, new_type=text/plain
[00237.621] 399115.399142> [3:1106148611:0916/002731.213848:237621876:ERROR:url_loader_impl.cc(417)] calling ReadMore loc2
[00237.622] 399115.399142> [3:1106148611:0916/002731.213975:237622005:ERROR:url_loader_impl.cc(312)] ReadMorex0, text/plain
[00237.622] 399115.399142> [3:1106148611:0916/002731.214075:237622104:ERROR:url_loader_impl.cc(345)] ReadMorex2, text/plain
[00237.622] 399115.399142> [3:1106148611:0916/002731.214224:237622253:ERROR:url_loader_impl.cc(364)] ReadMorex3, text/plain
[00237.622] 399115.399142> [3:1106148611:0916/002731.214392:237622421:ERROR:url_loader_impl.cc(368)] ReadMorex4, text/plain
[00237.622] 399115.399142> [3:1106148611:0916/002731.214531:237622560:ERROR:url_loader_impl.cc(375)] NotifyCompleted2, text/plain
[00237.622] 399115.399142> [3:1106148611:0916/002731.214632:237622661:ERROR:url_loader_impl.cc(450)] Send2, text/plain
[00237.622] 399115.399142> [3:1106148611:0916/002731.214741:237622770:ERROR:url_loader_impl.cc(498)] SendResponseToClient, text/plain
[00237.623] 399115.399142> [3:1106148611:0916/002731.215361:237623390:ERROR:test_url_loader_client.cc(24)] setting 0x763e339623e8 mime_type=text/plain
[00237.623] 399115.399142> [3:1106148611:0916/002731.215813:237623842:ERROR:url_loader_unittest.cc(431)] mime_type=text/plain
[00237.623] 399115.399142> ../../content/network/url_loader_unittest.cc:432: Failure
[00237.623] 399115.399142> Value of: mime_type().empty()
[00237.623] 399115.399142>   Actual: false
[00237.623] 399115.399142> Expected: true


Here's a normal passing run with the same logs inserted:

[00237.170] 398389.398416> [ RUN      ] URLLoaderImplTest.CantSniffEmptyHtml
[00237.185] 02339.03571> netstack: ErrNotSupported: socket: unknown network protocol: 16
[00237.192] 398389.398416> [3:2106837809:0916/002730.784528:237192559:ERROR:url_loader_impl.cc(62)] PopulateResourceResponse,
[00237.192] 398389.398416> [3:2106837809:0916/002730.784922:237192952:ERROR:loader_util.cc(22)] ShouldSniffContent, mime_type=
[00237.193] 398389.398416> [3:2106837809:0916/002730.785053:237193084:ERROR:loader_util.cc(36)] To buffer: http://127.0.0.1:54125/content-sniffer-test4.html
[00237.193] 398389.398416> [3:2106837809:0916/002730.785157:237193186:ERROR:url_loader_impl.cc(305)] calling ReadMore loc0
[00237.193] 398389.398416> [3:2106837809:0916/002730.785257:237193288:ERROR:url_loader_impl.cc(312)] ReadMorex0,
[00237.193] 398389.398416> [3:2106837809:0916/002730.785368:237193397:ERROR:url_loader_impl.cc(329)] ReadMorex1,
[00237.193] 398389.398416> [3:2106837809:0916/002730.785460:237193490:ERROR:url_loader_impl.cc(345)] ReadMorex2,
[00237.194] 398389.398416> [3:2106837809:0916/002730.786084:237194115:ERROR:url_loader_impl.cc(364)] ReadMorex3,
[00237.194] 398389.398416> [3:2106837809:0916/002730.786262:237194291:ERROR:url_loader_impl.cc(368)] ReadMorex4,
[00237.194] 398389.398416> [3:2106837809:0916/002730.786443:237194473:ERROR:url_loader_impl.cc(375)] NotifyCompleted2,
[00237.194] 398389.398416> [3:2106837809:0916/002730.786561:237194591:ERROR:url_loader_impl.cc(450)] Send2,
[00237.194] 398389.398416> [3:2106837809:0916/002730.786693:237194723:ERROR:url_loader_impl.cc(498)] SendResponseToClient,
[00237.195] 398389.398416> [3:2106837809:0916/002730.787399:237195429:ERROR:test_url_loader_client.cc(24)] setting 0x13b1fd6bd3e8 mime_type=
[00237.196] 398389.398416> [3:2106837809:0916/002730.787998:237196029:ERROR:url_loader_unittest.cc(431)] mime_type=
[00237.198] 398389.398416> [       OK ] URLLoaderImplTest.CantSniffEmptyHtml (26 ms)

I believe it's caused by the Read here https://cs.chromium.org/chromium/src/content/network/url_loader_impl.cc?rcl=04c767fee7b760e04e468016a02582af461ebcb1&l=337 going to pending instead of completing immediately, so it ends up going through OnReadCompleted().

This in turn ends up going through URLLoaderImpl::DidRead(), which does a separate net::SniffMimeType(), which for empty documents appears to be incorrect.
 
Cc: jam@chromium.org
I think it's probably here: https://cs.chromium.org/chromium/src/content/network/url_loader_impl.cc?rcl=b346b061e76751039272dc58f4c69dbe839da178&l=368

I'll try to write a non-flaky test to confirm. jam, do you know if not assigning to mime_type unless made_final_decision makes sense?
The incorrect text/plain comes from https://cs.chromium.org/chromium/src/net/base/mime_sniffer.cc?rcl=b346b061e76751039272dc58f4c69dbe839da178&l=648 . I'm not sure if it shouldn't be setting the mime_type, or if we shouldn't be ignoring the false return value though. I'm inclined towards the latter.

Comment 3 by w...@chromium.org, Sep 17 2017

It looks like the problem boils down to URLLoaderImpl having inconsistent
semantics for zero-sized resources, between async and synchronous
completion - at
https://cs.chromium.org/chromium/src/content/network/url_loader_impl.cc?l=343
synchronous completion only invokes DidRead() if bytes > 0, otherwise it
just tears things down, whereas the OnReadComplete() path calls DidRead()
even for zero-sized content.

Could we move the zero-byte-content special-case into DidRead(), so it is
applied consistently, and remove the check on bytes > 0 in Read()?
Repro in test form in https://chromium-review.googlesource.com/c/chromium/src/+/671767 (no fix yet)
Project Member

Comment 6 by bugdroid1@chromium.org, Oct 10 2017

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

commit 5c651df438206f385213419b7787d3de5dfe4458
Author: Scott Graham <scottmg@chromium.org>
Date: Tue Oct 10 16:46:58 2017

Handle empty in sniff when response goes to pending IO in URLLoaderImpl

In URLLoaderImpl, the sniffing of mime-type was slightly different for
empty documents depending on whether the response went to pending or if
it completed synchronously. Make these the same and add a test to
exercise the asynchronous completion path for empty document mime type
sniffing.

This showed up on the Fuchsia bot, but was cross-platform.

Bug:  765869 
Change-Id: Idfd00cc05f9fb3e54a5c27fdae8aea30e0f4fa56
Test: URLLoaderImplTest.EmptyHtmlIsTextPlain*
Reviewed-on: https://chromium-review.googlesource.com/671767
Reviewed-by: Matt Menke <mmenke@chromium.org>
Commit-Queue: Scott Graham <scottmg@chromium.org>
Cr-Commit-Position: refs/heads/master@{#507692}
[modify] https://crrev.com/5c651df438206f385213419b7787d3de5dfe4458/content/network/url_loader_impl.cc
[modify] https://crrev.com/5c651df438206f385213419b7787d3de5dfe4458/content/network/url_loader_impl.h
[modify] https://crrev.com/5c651df438206f385213419b7787d3de5dfe4458/content/network/url_loader_unittest.cc
[modify] https://crrev.com/5c651df438206f385213419b7787d3de5dfe4458/testing/buildbot/filters/fuchsia.content_unittests.filter

Status: Fixed (was: Started)
Project Member

Comment 8 by bugdroid1@chromium.org, Oct 10 2017

The following revision refers to this bug:
  https://chrome-internal.googlesource.com/infradata/master-manager/+/69808bb102eb4e4224acd760f370044f8e412fa7

commit 69808bb102eb4e4224acd760f370044f8e412fa7
Author: Dirk Pranke <dpranke@google.com>
Date: Tue Oct 10 22:52:44 2017

Comment 9 by laforge@google.com, Nov 7 2017

Components: -Internals>Network>Service Internals>Services>Network
Apologies, applied the wrong component in bulk.
Blocking: 882906

Sign in to add a comment