sometimes get 400's and "Nonce missing or invalid" responses for device session

Bug #1902781 reported by Ian Johnson
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Snap Store Server
Confirmed
Medium
Unassigned

Bug Description

I have seen this happen a couple times a week for a few weeks now in snapd CI spread tests. Example request/response on ubuntu 18.04:

2020-11-03T15:08:41.1939631Z Nov 03 15:08:38 nov031454-094792 snapd[20475]: logger.go:67: DEBUG: > "POST /api/v1/snaps/auth/sessions HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/1337.2.47.1 (series 16; classic; testing) ubuntu/18.04 (amd64) linux/5.4.0-1028-gcp\r\nContent-Length: 3921\r\nAccept: application/json\r\nContent-Type: application/json\r\nAccept-Encoding: gzip\r\n\r\n{\"device-session-request\":\"type: device-session-request\\nbrand-id: generic\\nmodel: generic-classic\\nserial: b46aa1cd-fb44-4996-bb21-7cf3961539bd\\nnonce: 82659305277934806331604416118:1604416118\\ntimestamp: 2020-11-03T15:08:38Z\\nsign-key-sha3-384: R_QdfGzBxwo6wpJM4jev4fvyYXKbmibrmCXxw8JgGgD-CnxLfvPjlQSgXNlzaXav\\n\\nAcLBUgQAAQoABgUCX6FydgAAcugQAAz/JQ0Ohegc72na08572ptcsVWy9fGbi9+b/si7P9wp4LGm\\nhpLdzTtVeV2E3t8qyhwTpdCXWLjWsAM+kZgcUzLMzBZ0wdOKWKj0Qmyn0vXrdoplIp5EebJl9VQ2\\n7OGhL7tNa4q3r/RoBD8+Hod4I1mOGbf83/Y/GaVTYOVrkdM5jVJ8jZV1qp/e1qUozuqDttGMMwgU\\nQP0dJLJU9eNoDZP66//MudnJtbeEJjwQ6f2dVblr+w+ONcObHObm61W7BgD6bJAf9mos2uNHATgW\\nP2rubj0B8vzMcj/M12pQvY359kvWs3KExYG5MDNKXoYNMQIG4nuEL5HH4UURHUEThLZsFBXMd+/q\\nBQDpjGb6J07NUTxMxZEmZWfzSohQocouDdIIbUDr+ehU1gn2nxx96vNZhZ3oCY+B70z4uKk9Tf1u\\nDn94eu9Sf8x7eoWJli18MjloJYB4yiTqrL3fjETLCFjPt9vGHZvOd4M0e5E42y5aEaY+/4HNDIHP\\nIV6t9RCKc3DuCgEu7X549hP+3fP5kKtyoeGz8gysM2cU7mGtUZicW49NNbYUijTDmzq7gCxOi72O\\nNdJKFgf8abme7jT4U336M/+m1SQhN9kw/vF+RqhotuMNnyyd5biuxzspdySwWo722ICcNtaVNk9W\\nOvtdiDY1TfoAl0WrKdEWnpgKNv7J\\n\",\"model-assertion\":\"type: model\\nauthority-id: generic\\nseries: 16\\nbrand-id: generic\\nmodel: generic-classic\\nclassic: true\\ntimestamp: 2017-07-27T00:00:00.0Z\\nsign-key-sha3-384: d-JcZF9nD9eBw7bwMnH61x-bklnQOhQud1Is6o_cn2wTj8EYDi9musrIT9z2MdAa\\n\\nAcLBXAQAAQoABgUCWYuXiAAKCRAdLQyY+/mCiST0D/0XGQauzV2bbTEy6DkrR1jlNbI6x8vfIdS8\\nKvEWYvzOWNhNlVSfwNOkFjs3uMHgCO6/fCg03wGXTyV9D7ZgrMeUzWrYp6EmXk8/LQSaBnff86XO\\n4/vYyfyvEYavhF0kQ6QGg8Cqr0EaMyw0x9/zWEO/Ll9fH/8nv9qcQq8N4AbebNvNxtGsCmJuXpSe\\n2rxl3Dw8XarYBmqgcBQhXxRNpa6/AgaTNBpPOTqgNA8ZtmbZwYLuaFjpZP410aJSs+evSKepy/ce\\n+zTA7RB3384YQVeZDdTudX2fGtuCnBZBAJ+NYlk0t8VFXxyOhyMSXeylSpNSx4pCqmUZRyaf5SDS\\ng1XxJet4IP0stZH1SfPOwc9oE81/bJlKsb9QIQKQRewvtUCLfe9a6Vy/CYd2elvcWOmeANVrJK0m\\nnRaz6VBm09RJTuwUT6vNugXSOCeF7W3WN1RHJuex0zw+nP3eCehxFSr33YrVniaA7zGfjXvS8tKx\\nAINNQB4g2fpfet4na6lPPMYM41WHIHPCMTz/fJQ6dZBSEg6UUZ/GiQhGEfWPBteK7yd9pQ8qB3fj\\nER4UvKnR7hcVI26e3NGNkXP5kp0SFCkV5NQs8rzXzokpB7p/V5Pnqp3Km6wu45cU6UiTZFhR2IMT\\nl+6AMtrS4gDGHktOhwfmOMWqmhvR/INF+TjaWbsB6g==\\n\",\"serial-assertion\":\"type: serial\\nauthority-id: generic\\nbrand-id: generic\\nmodel: generic-classic\\nserial: b46aa1cd-fb44-4996-bb21-7cf3961539bd\\ndevice-key:\\n AcbBTQRWhcGAARAAraYRlEP2HAmeTX5btUUiZbS+MA7Xplnm366cNgMnu+ykg0WGLpJsULvfCDHP\\n 8WugxYQkFFtCkIFggmETMc/v4ivCiyG8We3O7b9zRuakYLEMMz1GqvxGdo7/E7ew275IhqNJEsUb\\n +zw57Fbc8SMnQBh4EyKXLQbqjsAWRpXrx3xZb8Lqtz8/L9RfWLzRFoiORlIj7InPwOq/lVpEM7ru\\n WE17JBfZmLj5zt2TdPLBuLDjlQBtyecsKJ1iu86/Tb7bB+wa5GgFSdP0AI8uDUIh/F3buNwfsR2b\\n aK7hyAPId3YeQueg1w+9KDLhDWUWsRqbwpUHOU6mod3FEjPhIkJqsjqzgViG+CjdkdIVWJMV/J+Q\\n UO6RMwII4YlvVQPjanjKez4oivQRR0AHAqk4sLnskuMcmrGDgnMh9zvH90nPO3qDWzwLrjP722er\\n s99weB9ksq+dn0WSEKcMIBq0irWrgB649LF6MqJGgejINj9JtVKTRzcr/eJj0oEur9JjvrEnTh2V\\n 89jibZPA3zdCt8O1tyo2/y1qieaJ57uc8+OksskAbooD3NbhCtQJ2orkr7Wl0sN1SWdb24CROeB+\\n 9keAwPWIwAAQL5OO0vc9sxbbc/Im1LzJVCI2GX65UWSGbdJvaD4eXtqcnX+MohdulJhFc3z3Dg3E\\n lFqKvnsHmxbyflEAEQEAAQ==\\ndevice-key-sha3-384: R_QdfGzBxwo6wpJM4jev4fvyYXKbmibrmCXxw8JgGgD-CnxLfvPjlQSgXNlzaXav\\ntimestamp: 2020-11-03T15:08:28.453456Z\\nsign-key-sha3-384: wrfougkz3Huq2T_KklfnufCC0HzG7bJ9wP99GV0FF-D3QH3eJtuSRlQc2JhrAoh1\\n\\nAcLBUgQAAQoABgUCX6FybAAA6ooQAA1M2XekEnyw+AKpwtfhjRa4QdlcNX4tUWTmBTF/qR4J3/SB\\nBhKwsQJWhjXkNuxSXDjBtvCaJOSel6oidbjrDrti4dRKiVG6JiCSAEQS2sqolkpYGrGdQeIs+61E\\nNmE69QYy/GrBYG9IWyTjd04FREajpd9IaC8ZL+197EpPEGkucJ5wyj2ucHBBN53ku7v8aY572pDO\\nd4pXp1e78HgyaxMFTdS1HAmMbT3ZFCfyAvCEDTsj7jqwuvkiCm5xh8DVWtTCVaXy+SETLgOq3KME\\n2M4IaXZD/DUxauU5GyfcHUq9Htzq3X+ycLO/0gseCBfT422kQlF9A4CYmzzwqvsmBOx9qIkcy3Mg\\n+G59w9WaOEW+c//lvu2HyYH8sd2rUjTjMpvkemaoN4z0u+v+gl66rbh28y/d8/IV+2gxPpwSC6xk\\n3Cmd+IuVOYQvzst/pOkxlS8EX+m0SeiQnKH04IfuuZCoGmZ+oALFkl77K0I+9xhahLLsTbu+P9dJ\\nlIy5/+VgImOil3QAYfWPD98Vvt0weBhynTCiu/KFX16JDKqLcxurnlMGbVJPBL6eumede6DxM1En\\nvKhhOw9RePBwcJUufFo+sEMHnRShk2UMzu8xkK9l6t/y82D+8UHqXaW8N9NWhqR951mClhP/VLti\\niZNyyc8YFtRFNg3s34XvwxAuJ4nm\\n\"}"
2020-11-03T15:08:41.1984831Z Nov 03 15:08:40 nov031454-094792 snapd[20475]: logger.go:74: DEBUG: < "HTTP/1.1 400 BAD REQUEST\r\nContent-Length: 131\r\nContent-Type: application/json\r\nDate: Tue, 03 Nov 2020 15:08:40 GMT\r\nServer: gunicorn/19.7.1\r\nSnap-Store-Version: 27\r\nX-Request-Id: 23C49F1190AE0A325D3001BB5FA17276112F6089\r\nX-Vcs-Revision: 7b1a1ec\r\nX-View-Name: snapdevicegw.webapi_auth.sessions\r\n\r\n{\"error_list\":[{\"code\":null,\"message\":\"Nonce is missing or invalid.\"}],\"errors\":[\"Nonce is missing or invalid.\"],\"result\":\"error\"}\n"

and another one on ubuntu 14.04:

2020-11-03T15:08:39.0056687Z Nov 03 15:08:35 nov031454-577593 snapd[2985]: logger.go:67: DEBUG: > "POST /api/v1/snaps/auth/sessions HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/1337.2.
2020-11-03T15:08:39.0059261Z Nov 03 15:08:35 nov031454-577593 snapd[2985]: ng1XxJet4IP0stZH1SfPOwc9oE81/bJlKsb9QIQKQRewvtUCLfe9a6Vy/CYd2elvcWOmeANVrJK0m\\nnRaz6VBm09RJTuwUT6vNugXSOCeF7W3WN1RHJuex
2020-11-03T15:08:39.0065011Z Nov 03 15:08:35 nov031454-577593 snapd[2985]: WOwfhRDAbIONnwHe3WsFugd5X8OClUywj\\nY1kOTCyQ+5wITHlk7DwgZ4IX4KxOkRzf4BVzrgh4yW4aVTOc7+nU0wD79KYKoXyMAEphfrd3S6S3\\nc7SQlh/a6Va6MZCteweDvL/OULGh+Z4/uuXPlBFt70Ej4ZDlhb3RAjEyRo7oLsBrz0VouKVEQ1Xk\\n3v9dn7cWww1lhYovv5YvRrSgOmHy\\n\"}"
2020-11-03T15:08:39.0072551Z Nov 03 15:08:38 nov031454-577593 snapd[2985]: logger.go:74: DEBUG: < "HTTP/1.1 400 BAD REQUEST\r\nContent-Length: 131\r\nContent-Type: application/json\r\nDate: Tue, 03 Nov 2020 15:08:38 GMT\r\nServer: gunicorn/19.7.1\r\nSnap-Store-Version: 27\r\nX-Request-Id: 68C40ECF98000A325DF701BB5FA17273124DBFF6\r\nX-Vcs-Revision: 7b1a1ec\r\nX-View-Name: snapdevicegw.webapi_auth.sessions\r\n\r\n{\"error_list\":[{\"code\":null,\"message\":\"Nonce is missing or invalid.\"}],\"errors\":[\"Nonce is missing or invalid.\"],\"result\":\"error\"}\n"

Revision history for this message
Bret Barker (noise) wrote :

On a quick inspection of metrics I'm not seeing slowness/errs on the nonces endpoint nor load issues on the memcached servers. We'll have to dig deeper.

Changed in snapstore-server:
status: New → Confirmed
importance: Undecided → Medium
Revision history for this message
Dan Bungert (dbungert) wrote :

As a user I was able to see this.
$ sudo snap install go --classic
error: cannot install "go": cannot get device session from store: store server returned status 400
       and body "{\"error_list\":[{\"code\":null,\"message\":\"Nonce is missing or
       invalid.\"}],\"errors\":[\"Nonce is missing or invalid.\"],\"result\":\"error\"}\n"

I retried the above a few times, same error every time, waited a few minutes, the install worked.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.