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)
Description
•