New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 647177 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Feb 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux
Pri: 2
Type: Bug



Sign in to add a comment

DCHECK in net::HttpCache::MetadataWriter::VerifyResponse

Reported by p...@yandex-team.ru, Sep 15 2016

Issue description

UserAgent: 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
 
chrome_debug.log
8.7 KB View Download

Comment 1 by asanka@chromium.org, Sep 16 2016

Cc: shivanisha@chromium.org gavinp@chromium.org
Components: -Internals>Network Internals>Network>Cache
Status: Available (was: Unconfirmed)

Comment 2 by romax@chromium.org, 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. 

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)


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.
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!
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. 
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.
Labels: Needs-Feedback
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 
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.
netlog.json.gz
1.1 MB Download
gdb.log
21.8 KB View Download
bookmarks.html
50.6 KB View Download
Also, after update I don't see any ERROR messages from http_cache_transaction.cc in the browser's stderr output.
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?
Cc: jkarlin@chromium.org
Owner: shivanisha@chromium.org
Status: Assigned (was: Available)
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.

Status: Fixed (was: Assigned)

Sign in to add a comment