1338675 - Intermittent netwerk/test/unit/test_bug482934.js | - 2152857618 == 0

Status: RESOLVED DUPLICATE of bug 1343816

(Core :: Networking: Cache, defect)

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=76443328&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/JgW_60xYRc6RtIfcDpXrqA/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Junior [inactive]]

From the log, the cache file is gone after we overwrite the cache.
I'm not sure if I miss some step in the test.

Comment 2

[Junior [inactive]]

Unveil the nspr log to treeherder
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a6920e54cc86f3a325e9d4f9cbe4611519ec817a

Comment 4

[Junior [inactive]]

I'm not sure why the dynamic logging doesn't work for android emulator.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=dbbb3a8b5a266623a1d3e19fbc29c9742417cfcc&selectedJob=77443269

Comment 5

[Intermittent Failures Robot]

18 failures in 833 pushes (0.022 failures/push) were associated with this bug in the last 7 days.  
Repository breakdown:
* mozilla-inbound: 11
* autoland: 4
* graphics: 2
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api15: 18

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1338675&startday=2017-02-13&endday=2017-02-19&tree=all

Comment 6

[Junior [inactive]]

Hello :gbrown,
For debugging, we are trying to unveil PR_LOG for android-4-3 debug build on treeherder.
However, we failed when we tried to use env variable (Comment 2) or change logging pref (Comment 4).
Do you have any suggestions, such as hacking pr_log.c?
(I found bug 1003675 comment 1, but unable to know what to do precisely.)

Thanks.

Comment 7

[Honza Bambas (:mayhemer)]

Depends also on what code you want to debug.  pr_log.c from NSPR is now controlled with the NSPR_LOG_MODULES/FILE env var pair and only logs code in NSPR (low level sockets, polling, file access).  What you probably need is MOZ_LOG and MOZ_LOG_FILE env vars which are handling by a second, higher level logging back end in XPCOM widely used around the platform above/including XPCOM.

Comment 8

[Junior [inactive]]

(In reply to Honza Bambas (:mayhemer) from comment #7)
> Depends also on what code you want to debug.  pr_log.c from NSPR is now
> controlled with the NSPR_LOG_MODULES/FILE env var pair and only logs code in
> NSPR (low level sockets, polling, file access).  What you probably need is
> MOZ_LOG and MOZ_LOG_FILE env vars which are handling by a second, higher
> level logging back end in XPCOM widely used around the platform
> above/including XPCOM.

Thanks for the information about the difference between NSPR_LOG and MOZ_LOG.
To confirm, yes what I need is MOZ_LOG in order to unveil nsHttp/cache/cache2

I have try to use "--setenv MOZ_LOG=..." and use "Services.prefs.setIntPref("logging.cache2", 5);"
Both don't work for xpcshell-test on treeherder for android 4.3, which is the only breakdown platform.

Comment 9

[Geoff Brown [:gbrown] (pto Apr 11-18)]

I haven't tried to enable MOZ_LOG for Android recently. I'm not sure of how to do it, but I should be able to figure it out...will get back to you today.

Comment 10

[Geoff Brown [:gbrown] (pto Apr 11-18)]

"--setenv MOZ_LOG..." sets the MOZ_LOG environment on the test host, but that does not get passed on to the test device's environment. 

I think your setIntPref solution probably generated additional logging, but its not clear to me where that would go - a file on the device, the xpcshell process stdout, ...?

How about this:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8c30cdd370537e19a885784ee9a54679ec338e21

I set MOZ_LOG and MOZ_LOG_FILE to create moz.log on the device, then pulled the file from the device to the test host, storing it in the MOZ_UPLOAD_DIR, so that it appears as an artifact in treeherder's "Job Details" pane. Note that it is important to use "append" in the MOZ_LOG, otherwise each xpcshell instance (each test) will overwrite the file.

Is that good enough for your needs? I suppose it will be inconvenient to match up moz.log content with logcat or a specific test. I might be able to generate a different file for each test, but then that will create a lot of artifacts. It would be nice to get MOZ_LOG content in logcat, but I'm not sure how to do that.

Comment 11

[Junior [inactive]]

> Is that good enough for your needs? I suppose it will be inconvenient to
> match up moz.log content with logcat or a specific test. I might be able to
> generate a different file for each test, but then that will create a lot of
> artifacts. It would be nice to get MOZ_LOG content in logcat, but I'm not
> sure how to do that.

It definitively works well.
It would be better if we can limit those logs into one or some test file.
But absolutely it provides enough information for debugging.

FWIW, the bug of dynamic logging(pref solution) is bug 1233881.

Thanks for your great information, :gbrown

Comment 12

[Junior [inactive]]

The test failed since the cache file in gone after we overwrite the cache file.
http://searchfox.org/mozilla-central/rev/60ae6514e4c559c0c234f0e7aefccb101b8beb2e/netwerk/test/unit/test_bug482934.js#164

I can reproduce in linux if we put a time out for |check_cached_data| for 10 secs.
There's a fundamental bug for customer conditional request.
(That is, it works well for a necko-generated conditional reqeust)

It's under a intermittent since the mFile is caught by MetadataWriteScheduleEvent.
Once the mFile is release, the file is gone. <== need to confirm.

Comment 13

[Junior [inactive]]

Attachment: testForCondIntermittent

the test patch

Also observe that it's nothing to do with the cache re-write.
The disappearance of cache file occurs if we have a customized cond request with a 304 response without a cache file before.

Comment 14

[Junior [inactive]]

Here is the story.

1) Test 1
   we send a custom cond request without a cache file.
   we open a cache entry first
   we get a 304 respond and call CloseCacheEntry

2) Then Test 2
   we send a request without a cache file
   we get a 200 and write the cache.

3) The mMetadataWritesTimer of test 1 fires (Is set by frecency update)
http://searchfox.org/mozilla-central/rev/90d1cbb4fd3dc249cdc11fe5c3e0394d22d9c680/netwerk/cache2/CacheFileIOManager.cpp#1415
The cache file is doomed since all refcnt to CacheFileHandle are released, which is grab by CacheFile in mScheduledMetadataWrites.

Here is the log:
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeeded() [this=7fbd42b925e0]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7fbd42b925e0]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFile::~CacheFile() [this=7fbd42b925e0]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFileMetadata::~CacheFileMetadata() [this=7fbd42b7a120]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7fbd35f5ad60, refcnt=2]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7fbd42b7a128, size=0]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7fbd35f5ad60, refcnt=1]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFileHandle::~CacheFileHandle() [this=7fbd35f5ad60]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFileIOManager::CloseHandleInternal() [handle=7fbd35f5ad60]"
 0:05.66 PROCESS_OUTPUT: Thread-1 (pid:9633) "[Cache2 I/O]: D/cache2 CacheFileHandle::Log() - entry file [this=7fbd35f5ad60, hash=6ce1ef874cab050dfccc4e24c739c7d2eef5ea05, isDoomed=1, priority=0, closed=0, invalid=0, pinning=1, fileExists=0, fileSize=0, leafName=6CE1EF874CAB050DFCCC4E24C739C7D2EEF5EA05, key=:http://localhost:41838/resource]"

Comment 15

[Junior [inactive]]

Attachment: changeURI-v1

The patch modifies the test which can
1) still test what we want to test
2) make treeherder work without the intermittent alert

I filed bug 1343816 for follow-up

Comment 16

[Michal Novotny [:michal]]

Comment on attachment 8842806 [details] [diff] [review]
changeURI-v1

I'll fix it in bug 1343816.

Comment 17

[Junior [inactive]]

bug 1343816 is resolved and the test is passed for the patch in comment 13.
let's wait for good news from orange factor

Comment 18

[Shian-Yow Wu [:swu]]

If no more crash happened, shall we close this as duplicate of bug 1343816?

Comment 19

[Junior [inactive]]

Looks green in orange factor these three weeks