Closed Bug 693427 Opened 13 years ago Closed 12 years ago

Intermittent TEST-UNEXPECTED-FAIL | xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | test failed (with xpcshell return code: 0) | false == true

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Platform:
x86
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla19

People

(Reporter: mbrubeck, Assigned: rnewman)

References

Details

(Keywords: intermittent-failure, Whiteboard: [qa-])

Attachments

(1 file)

Another proposed fix. v1
5.41 KB, patch
gps
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=6763792&tree=Firefox Rev3 MacOSX Leopard 10.5.8 mozilla-central debug test xpcshell on 2011-10-10 04:28:07 PDT for push aee2bf4eb5f8 builder: mozilla-central_leopard-o-debug_test-xpcshell slave: talos-r3-leopard-012 starttime: 1318246087.84 results: warnings (1) buildid: 20111010025555 builduid: fa23fec4a2ab47c195dcfac0909ab8fc revision: aee2bf4eb5f8 TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler.js | test passed (time: 16292.943ms) TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | running test ... TEST-UNEXPECTED-FAIL | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | test failed (with xpcshell return code: 0), see following log: >>>>>>> ### XPCOM_MEM_LEAK_LOG defined -- logging leaks to /var/folders/Xr/Xr--yJnSEY0U11ET5NZuMU+++TM/-Tmp-/tmpSEzrie/runxpcshelltests_leaks.log Setting the identity for passphrase pldhash: for the table at address 0x1fa9b54, the given entrySize of 52 probably favors chaining over double hashing. TEST-INFO | (xpcshell/head.js) | test 1 pending TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | running event loop TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_noOutput TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_logOnSuccess_false TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 54] false == false TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_logOnSuccess_true TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 84] true == true TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 86] .txt == .txt TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 88] success- == success- TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 89] false == false TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [null : 93] true == true TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [null : 94] 37 != -1 TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_sync_error_logOnError_false TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 122] false == false TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_sync_error_logOnError_true TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 145] true == true TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 147] .txt == .txt TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 149] error- == error- TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 150] false == false TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [null : 154] true == true TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [null : 155] 37 != -1 TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_login_error_logOnError_false TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 184] false == false TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_login_error_logOnError_true TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 207] true == true TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 209] .txt == .txt TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 211] error- == error- TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [onResetFileLog : 212] false == false TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [null : 216] true == true TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | [null : 217] 37 != -1 TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | Starting test_logErrorCleanup_age TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-UNEXPECTED-FAIL | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js | false == true - See following stack: JS frame :: /Users/cltbld/talos-slave/test/build/xpcshell/head.js :: do_throw :: line 453 JS frame :: /Users/cltbld/talos-slave/test/build/xpcshell/head.js :: _do_check_eq :: line 547 JS frame :: /Users/cltbld/talos-slave/test/build/xpcshell/head.js :: do_check_eq :: line 568 JS frame :: /Users/cltbld/talos-slave/test/build/xpcshell/head.js :: do_check_true :: line 582 JS frame :: /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js :: onCleanupLogs :: line 263 JS frame :: resource://services-sync/ext/Observers.js :: <TOP_LEVEL> :: line 163 JS frame :: resource://services-sync/ext/Observers.js :: <TOP_LEVEL> :: line 122 JS frame :: resource:///modules/services-sync/policies.js :: deleteFile :: line 603 TEST-INFO | (xpcshell/head.js) | exiting test WARNING: nsExceptionService ignoring thread destruction after shutdown: file /builds/slave/m-cen-osx-dbg/build/xpcom/base/nsExceptionService.cpp, line 197 WARNING: OOPDeinit() without successful OOPInit(): file /builds/slave/m-cen-osx-dbg/build/toolkit/crashreporter/nsExceptionHandler.cpp, line 1921 nsStringStats => mAllocCount: 4998 => mReallocCount: 412 => mFreeCount: 4998 => mShareCount: 8242 => mAdoptCount: 559 => mAdoptFreeCount: 559 <<<<<<< TEST-INFO | skipping /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_errorhandler_sync_checkServerError.js | skip-if: (os == "mac" && debug) || os == "android"
Component: General → Firefox Sync: Backend
QA Contact: general → sync-backend
Timing issue: if a timer fires slightly too soon, or file mtime resolution is too coarse, we'll end up deleting all our logfiles, so our age-based expiry won't appear to be correct. I bumped the delay from 50ms to 500ms, which should be enough padding, and added some logging to offer some tiny clues if it persists. https://hg.mozilla.org/services/services-central/rev/48c813e57d51 If this -- and the next m-c merge that I'll push in a moment -- both go green, I'll push this to other trees.
Whiteboard: [orange] → [orange][fixed in services?][qa-]
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
https://hg.mozilla.org/mozilla-central/rev/48c813e57d51 Let's see if this helps…
Status: ASSIGNED → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Whiteboard: [orange][fixed in services?][qa-] → [orange][qa-]
Target Milestone: --- → mozilla19
Guess that's a no.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Ah. We create some error logs, then notify an error. The error notifier flushes the error log, then calls for a cleanup. Our test is that the cleanup leaves a file behind. Unfortunately, the mtime of the flushed error log seems to be significantly rounded: 0.97 Sync.ErrorHandler TRACE Output file timestamp: 1351982597000 … 1.02 Sync.ErrorHandler TRACE Output file timestamp: 1351982654000 so if our flush is too close: 1.02 Sync.ErrorHandler DEBUG Log cleanup threshold: 1351982654668 We'll clean up that final log, and the test will fail. We were leaving 1050msec, but the timestamp granularity seems to be approximately ~1sec. In fact, all of our created logs have that same timestamp: 1.02 Sync.ErrorHandler DEBUG > Adding 1351982654000(error-13519826546480.txt) 1.02 Sync.ErrorHandler DEBUG > Adding 1351982654000(error-13519826546481.txt) 1.02 Sync.ErrorHandler DEBUG > Adding 1351982654000(error-13519826546492.txt) Ruh roh! My next proposed fix will be to bump the CLEANUP_DELAY from 1000 to 2000, which will allow the later logfile to roll over into the next second more reliably. If that still causes intermittent failures, we might need to find a way to set lastModified on an nsIFile without hitting NS_ERROR_XPC_CANT_MODIFY_PROP_ON_WN.
Changes: * Fix 'this' scoping in cleanupLogs. Setting _cleaningUpFileLogs and logging would fail. Not good. * Add a bunch of useful trace logging for debugging issues like this. * Bump delay, as mentioned in previous comment.
Attachment #678066 - Flags: review?(gps)
Comment on attachment 678066 [details] [diff] [review] Another proposed fix. v1 Review of attachment 678066 [details] [diff] [review]: ----------------------------------------------------------------- Looks good to me. The code to delete files is not very readable. I reckon this will be refactored (possibly to use promises) some day.
Attachment #678066 - Flags: review?(gps) → review+
https://hg.mozilla.org/services/services-central/rev/9092b49ef08b
Whiteboard: [orange][qa-] → [orange][qa-][fixed in services]
https://hg.mozilla.org/mozilla-central/rev/9092b49ef08b Trying *again*…
Status: REOPENED → RESOLVED
Closed: 12 years ago → 12 years ago
Resolution: --- → FIXED
Whiteboard: [orange][qa-][fixed in services] → [orange][qa-]
Whiteboard: [orange][qa-] → [qa-]
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: