DCHECK in net::HttpCache::MetadataWriter::VerifyResponse
Reported by
p...@yandex-team.ru,
Sep 15 2016
|
||||
Issue descriptionUserAgent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 YaBrowser/16.9.1.466 Yowser/2.5 Safari/537.36 Example URL: Steps to reproduce the problem: 1. Try to open all bookmarks in folder with lots of bookmarks (64 in my case). What is the expected behavior? What went wrong? DHECK is triggered with following message [13016:13045:0915/123554:FATAL:http_cache.cc(254)] Check failed: response_info->was_cached. Full stack is in attached chrome_debug.log. Did this work before? N/A Chrome version: 55.0.2860.0 (Developer Build) (64-bit) Channel: dev OS Version: d9a1945abf1dde3b23e56afb59c24e773340672a-refs/heads/master@{#418193} Flash Version: When DHECK is triggered, associated cache transaction is always in NONE mode. Looks like it is caused by data read errors just a moment before failure [13016:13045:0915/123531:ERROR:http_cache_transaction.cc(2591)] ReadData failed: -407 [13016:13045:0915/123531:ERROR:http_cache_transaction.cc(2591)] ReadData failed: -2
,
Jan 25 2017
Saw the same issue on Android when going through a bunch of urls for offlining. No idea what was the root cause. However this was the first time that I ran into this issue. 01-25 01:23:32.469 16049 16049 I DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr -------- 01-25 01:23:32.559 16049 16049 I DEBUG : Abort message: '[FATAL:http_cache.cc(255)] Check failed: response_info->was_cached.
,
Jan 31 2017
Thanks for the debug log. From a quick look at the code, this seems unusual to have been hit. phmx@yandex-team.ru@, Would it be possible for you to confirm the following from the core file: - What is the value of the argument of net::HttpCache::MetadataWriter::OnIOComplete() and net::HttpCache::MetadataWriter::VerifyResponse() (frame numbers 3 and 2 respectively)
,
Jan 31 2017
Sure, here they are (gdb) fr 3 #3 0x00007ffff5f6172a in (anonymous namespace)::HttpCache::MetadataWriter::VerifyResponse (this=0x52f15a68b60, result=0) at ../../net/http/http_cache.cc:254 254 DCHECK(response_info->was_cached); (gdb) info args this = 0x52f15a68b60 result = 0 (gdb) fr 4 #4 0x00007ffff5f6159d in (anonymous namespace)::HttpCache::MetadataWriter::OnIOComplete (this=0x52f15a68b60, result=0) at ../../net/http/http_cache.cc:272 272 return VerifyResponse(result); (gdb) info args this = 0x52f15a68b60 result = 0 My Chromium build is quite outdated though. I can try to reproduce a problem after pulling the latest sources.
,
Jan 31 2017
yes, it would be great to see if its getting reproduced with the latest source. Also if possible, please check the stack trace for any suspicious error logs e.g. "ReadData failed:" and "Unable to create cache entry". These logs can be found in the http_cache_transaction.cc, functions: HttpCache::Transaction::OnCacheReadError (https://cs.chromium.org/chromium/src/net/http/http_cache_transaction.cc?type=cs&q=http_cache_transact&l=2651) and HttpCache::Transaction::DoCreateEntryComplete (https://cs.chromium.org/chromium/src/net/http/http_cache_transaction.cc?type=cs&q=http_cache_transact&l=1088) Thanks!
,
Jan 31 2017
The log from the origin post shows the errors: [13016:13045:0915/123531:ERROR:http_cache_transaction.cc(2591)] ReadData failed: -407 [13016:13045:0915/123531:ERROR:http_cache_transaction.cc(2591)] ReadData failed: -2 [13016:13045:0915/123554:FATAL:http_cache.cc(254)] Check failed: response_info->was_cached.
,
Jan 31 2017
That's right and I was wondering if we can possibly get the stack trace for these errors. MetadataWriter::OnIOComplete is being invoked with result as 0, leading to the crash but as per the code, anytime HttpCache::Transaction::OnCacheReadError is invoked from DoCacheReadMetadataComplete with a non-zero result, this should not have been possible. So knowing the calling stack and argument value of OnCacheReadError might help in further investigation.
,
Feb 1 2017
A more useful feedback would be to get the netlog associated with the URL that is crashing. The URL can be seen from the core file in frame 2 HttpCache::MetadataWriter::VerifyResponse with the value of request_info_.url and net log can be enabled and saved in a file by starting up the browser with the flag --log-net-log=/tmp/filename.json
,
Feb 2 2017
Sorry for delay. I have reproduced a problem after updating the code. Steps to reproduce: * import bookmarks from attached bookmarks.html file; * right click on `123' bookmark folder, select `Open all bookmarks', agree to open all 64 of them; * wait for DCHECK to be triggered. Attached gdb.log contains backtrace and printed out request_info_.url (which is "https://ru.wikipedia.org/w/load.php?debug=false&lang=ru&modules=startup&only=scripts&skin=vector" in this instance). Collected network log is in netlog.json.gz.
,
Feb 2 2017
Also, after update I don't see any ERROR messages from http_cache_transaction.cc in the browser's stderr output.
,
Feb 2 2017
Thanks for the detailed instructions and logs. This issue is timing dependent since it reproduced most of the times for me but not all times. I think what is happening is that when an HttpCache::Transaction hits the error ERR_CACHE_LOCK_TIMEOUT while getting to an ActiveEntry, which may happen because there are multiple transactions for the same URL simultaneously, then the transaction hits the network and does not write anything in the cache. The consumer of HttpCache::Transaction should not normally be impacted since it is getting the data whether from cache or from network. But in this case the consumer is MetadataWriter which assumes that if everything is going fine then the response should have been in the cache. I also see that MetadataWriter's transaction is supposed to be read-only from the cache (LOAD_ONLY_FROM_CACHE | LOAD_SKIP_CACHE_VALIDATION | LOAD_SKIP_VARY_CHECK) so it should not have actually gone to the network but the error case of ERR_CACHE_LOCK_TIMEOUT actually ignores that the mode was set to READ and unconditionally make the mode as NONE. So the question is, in cases of ERR_CACHE_LOCK_TIMEOUT + Read Only, should the request just fail with an ERR_CACHE_MISS?
,
Feb 2 2017
jkarlin@, Since you've worked with MetadataWriter recently, do you have any thoughts on the above? I think it should be fine to return ERR_CACHE_MISS for cases where ERR_CACHE_LOCK_TIMEOUT happens and the request is Read Only.
,
Feb 2 2017
,
Feb 9 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/3701cde07f15ce076d9005bac70cb6fe65f465bb commit 3701cde07f15ce076d9005bac70cb6fe65f465bb Author: shivanisha <shivanisha@chromium.org> Date: Thu Feb 09 17:43:07 2017 Correct handling of ERR_CACHE_LOCK_TIMEOUT for read only transactions. The investigation of the root cause is detailed in https://bugs.chromium.org/p/chromium/issues/detail?id=647177#c11 BUG= 647177 Review-Url: https://codereview.chromium.org/2671793002 Cr-Commit-Position: refs/heads/master@{#449342} [modify] https://crrev.com/3701cde07f15ce076d9005bac70cb6fe65f465bb/net/http/http_cache.cc [modify] https://crrev.com/3701cde07f15ce076d9005bac70cb6fe65f465bb/net/http/http_cache.h [modify] https://crrev.com/3701cde07f15ce076d9005bac70cb6fe65f465bb/net/http/http_cache_transaction.cc [modify] https://crrev.com/3701cde07f15ce076d9005bac70cb6fe65f465bb/net/http/http_cache_unittest.cc [modify] https://crrev.com/3701cde07f15ce076d9005bac70cb6fe65f465bb/net/http/mock_http_cache.cc [modify] https://crrev.com/3701cde07f15ce076d9005bac70cb6fe65f465bb/net/http/mock_http_cache.h
,
Feb 9 2017
|
||||
►
Sign in to add a comment |
||||
Comment 1 by asanka@chromium.org
, Sep 16 2016Components: -Internals>Network Internals>Network>Cache
Status: Available (was: Unconfirmed)