Closed Bug 1781451 Opened 3 years ago Closed 2 months ago

Intermittent dom/push/test/xpcshell/test_unregister_invalid_json.js | single tracking bug

Categories

(Core :: DOM: Push Subscriptions, defect, P3)

defect

Tracking

()

RESOLVED FIXED
140 Branch
Tracking Status
firefox140 --- fixed

People

(Reporter: jmaher, Assigned: saschanaz)

References

Details

(Keywords: intermittent-failure, intermittent-testcase)

Attachments

(1 file)

No description provided.

Additional information about this bug failures and frequency patterns can be found by running: ./mach test-info failure-report --bug 1781451

Severity: normal → S3
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

This is failing with higher-than-usual rate... was there some relevant change around 2024-04? 🤔

Assignee: nobody → krosylight

I suspect this test is in a bad state; bug 1468938 added the expected error message but with the string "request timed out", which I doubt that it was the intention of this test.

Reading again after comment #83, it seems maybe the timeout is the only way to test this currently... But then it seems sometimes the mock service totally missed onUnregister: https://treeherder.mozilla.org/logviewer?job_id=500802339&repo=autoland&lineNumber=4160

[task 2025-03-25T08:30:22.606Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "connect()" [object Object]
[task 2025-03-25T08:30:22.606Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "beginWSSetup()"
[task 2025-03-25T08:30:22.606Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "beginWSSetup: Connecting to" "wss://push.example.org/"
[task 2025-03-25T08:30:22.606Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getByIdentifiers()" ({scope:"https://example.edu/page/1", originAttributes:""})
[task 2025-03-25T08:30:22.607Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsOnStart()"
[task 2025-03-25T08:30:22.607Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllUnexpired()"
[task 2025-03-25T08:30:22.607Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllByPushQuota()"
[task 2025-03-25T08:30:22.607Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "delete()"
[task 2025-03-25T08:30:22.608Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "unregister() " ({pushEndpoint:"https://example.org/update/1", scope:"https://example.edu/page/1", originAttributes:"", pushCount:0, lastPush:0, p256dhPublicKey:(void 0), p256dhPrivateKey:(void 0), authenticationSecret:(void 0), systemRecord:false, appServerKey:(void 0), recentMessageIDs:(void 0), quota:Infinity, ctime:0, channelID:"87902e90-c57e-4d18-8354-013f4a556559", version:1}) 3
[task 2025-03-25T08:30:22.608Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "queueRequest()" ({channelID:"87902e90-c57e-4d18-8354-013f4a556559", messageType:"unregister", code:200})
[task 2025-03-25T08:30:22.608Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "enqueue()"
[task 2025-03-25T08:30:22.609Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "delete: Removing record" "87902e90-c57e-4d18-8354-013f4a556559"
[task 2025-03-25T08:30:22.609Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsSendMessage: Sending message" "{\\"messageType\\":\\"hello\\",\\"broadcasts\\":{},\\"use_webpush\\":true,\\"uaid\\":\\"7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3\\"}"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsOnMessageAvailable()" "{\\"messageType\\":\\"hello\\",\\"status\\":200,\\"uaid\\":\\"7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3\\",\\"use_webpush\\":true}"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "handleHelloReply()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "New _UAID" "7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllUnexpired()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllByPushQuota()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "onTimerFired()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "timeOutRequests()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "reconnect()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "shutdownWS()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "startBackoffTimer()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "startBackoffTimer: Retry in" 150 "Try number" 1
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  TEST-PASS | dom/push/test/xpcshell/test_unregister_invalid_json.js | test_unregister_invalid_json - [test_unregister_invalid_json : 72] Expected error for first invalid JSON response
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getByKeyID()"
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getByKeyID: Got record" null
[task 2025-03-25T08:30:22.611Z] 08:30:22     INFO -  TEST-PASS | dom/push/test/xpcshell/test_unregister_invalid_json.js | test_unregister_invalid_json - [test_unregister_invalid_json : 82] Failed to delete unregistered record - true == true
[task 2025-03-25T08:30:22.612Z] 08:30:22     INFO -  PID 20583 | console.debug: PushService: "unregister()" ({scope:"https://example.net/page/1", originAttributes:""})
[task 2025-03-25T08:30:22.612Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getByIdentifiers()" ({scope:"https://example.net/page/1", originAttributes:""})
[task 2025-03-25T08:30:22.613Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "update: Update successful" "057caa8f-9b99-47ff-891c-adad18ce603e" ({pushEndpoint:"https://example.com/update/2", scope:"https://example.net/page/1", originAttributes:"", pushCount:0, lastPush:0, p256dhPublicKey:{}, p256dhPrivateKey:{crv:"P-256", d:"sTUOrSS4xqfGisBAHEmRobSvFsSZVKgbtYfslZIHhNw", ext:true, key_ops:["deriveBits"], kty:"EC", x:"Y4gR9xv8lhpVIKbi4-hd3MZFXeKg8QH6AQ2JSxDTgLQ", y:"DX3gssKiqr5HIeiPAZ66EQMSKLNo_pqR7BeD7NgQ1hQ"}, authenticationSecret:{0:126, 1:54, 2:97, 3:127, 4:243, 5:29, 6:192, 7:45, 8:145, 9:254, 10:239, 11:214, 12:83, 13:81, 14:164, 15:31}, systemRecord:false, appServerKey:(void 0), recentMessageIDs:(void 0), quota:Infinity, ctime:0, channelID:"057caa8f-9b99-47ff-891c-adad18ce603e", version:1})
[task 2025-03-25T08:30:22.613Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "enqueue()"
[task 2025-03-25T08:30:22.613Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "delete()"
[task 2025-03-25T08:30:22.614Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "unregister() " ({pushEndpoint:"https://example.com/update/2", scope:"https://example.net/page/1", originAttributes:"", pushCount:0, lastPush:0, p256dhPublicKey:{}, p256dhPrivateKey:{crv:"P-256", d:"sTUOrSS4xqfGisBAHEmRobSvFsSZVKgbtYfslZIHhNw", ext:true, key_ops:["deriveBits"], kty:"EC", x:"Y4gR9xv8lhpVIKbi4-hd3MZFXeKg8QH6AQ2JSxDTgLQ", y:"DX3gssKiqr5HIeiPAZ66EQMSKLNo_pqR7BeD7NgQ1hQ"}, authenticationSecret:{0:126, 1:54, 2:97, 3:127, 4:243, 5:29, 6:192, 7:45, 8:145, 9:254, 10:239, 11:214, 12:83, 13:81, 14:164, 15:31}, systemRecord:false, appServerKey:(void 0), recentMessageIDs:(void 0), quota:Infinity, ctime:0, channelID:"057caa8f-9b99-47ff-891c-adad18ce603e", version:1}) 3
[task 2025-03-25T08:30:22.615Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "queueRequest()" ({channelID:"057caa8f-9b99-47ff-891c-adad18ce603e", messageType:"unregister", code:200})
[task 2025-03-25T08:30:22.615Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "enqueue()"
[task 2025-03-25T08:30:22.616Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "beginWSSetup()"
[task 2025-03-25T08:30:22.616Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "beginWSSetup: Connecting to" "wss://push.example.org/"
[task 2025-03-25T08:30:22.616Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsOnStart()"
[task 2025-03-25T08:30:22.619Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllUnexpired()"
[task 2025-03-25T08:30:22.619Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllByPushQuota()"
[task 2025-03-25T08:30:22.619Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "delete: Removing record" "057caa8f-9b99-47ff-891c-adad18ce603e"
[task 2025-03-25T08:30:22.619Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsSendMessage: Sending message" "{\\"messageType\\":\\"hello\\",\\"broadcasts\\":{},\\"use_webpush\\":true}"
[task 2025-03-25T08:30:22.620Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsOnMessageAvailable()" "{\\"messageType\\":\\"hello\\",\\"status\\":200,\\"uaid\\":\\"7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3\\",\\"use_webpush\\":true}"
[task 2025-03-25T08:30:22.620Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "handleHelloReply()"
[task 2025-03-25T08:30:22.621Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "New _UAID" "7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3"
[task 2025-03-25T08:30:22.621Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllUnexpired()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getAllByPushQuota()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "enqueue()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsSendMessage: Sending message" "{\\"channelID\\":\\"057caa8f-9b99-47ff-891c-adad18ce603e\\",\\"messageType\\":\\"unregister\\",\\"code\\":200}"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "wsOnMessageAvailable()" ");alert(1);("
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.warn: PushServiceWebSocket: "wsOnMessageAvailable: Invalid JSON" ");alert(1);(" (new SyntaxError("JSON.parse: unexpected character at line 1 column 1 of the JSON data", "resource://gre/modules/PushServiceWebSocket.sys.mjs", 1141))
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "onTimerFired()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "timeOutRequests()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "reconnect()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "shutdownWS()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "startBackoffTimer()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushServiceWebSocket: "startBackoffTimer: Retry in" 150 "Try number" 1
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  TEST-PASS | dom/push/test/xpcshell/test_unregister_invalid_json.js | test_unregister_invalid_json - [test_unregister_invalid_json : 84] Expected error for second invalid JSON response
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getByKeyID()"
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  PID 20583 | console.debug: PushDB: "getByKeyID: Got record" null
[task 2025-03-25T08:30:22.623Z] 08:30:22     INFO -  TEST-PASS | dom/push/test/xpcshell/test_unregister_invalid_json.js | test_unregister_invalid_json - [test_unregister_invalid_json : 96] Failed to delete unregistered record after receiving invalid JSON - true == true

Compared to the successful run, there's a missing wsOnMessageAvailable with the invalid JSON payload. (It should happen before each "Expected error for first/second invalid JSON response" but there's only one here)

PushService.init is an async function waiting on a queue, thus it should be awaited to make sure the mock service registers before PushService.unregister.

Status: REOPENED → RESOLVED
Closed: 2 years ago2 months ago
Resolution: --- → FIXED
Target Milestone: --- → 140 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: