Resolved: pianod user timeout issue Reported by: a user Date: 2021-08-23 04:59 Trigger sequence: - Choose a Pandora Playlist - Play - Pause - Wait until the song state goes back to 'null' - Request 'getHistory' - Server crashes (error log attached) - Subsequent update: I just realized that it doesn't actually crash. It just kills the current websocket connection and prints the error message. When I reconnect, the service works as before, and even querying the history works again. I think it's some kind of timout problem with Pandora, but I'm not sure. Logs: Source status: 22 Source 2 (pandora/startscript), Source status: 24 ready for Source 2 (pandora/startscript), Source status: 24 ready for Source 2 (pandora/startscript), 2021-08-23 00:07:36: #6: Connection terminated., 2021-08-23 00:07:36: #6: Connection from 172.24.0.1 permitted., 2021-08-23 00:07:36: #6: New cleartext IP4 HTTP connection from 172.24.0.1 port 39820, Source status: 34 Retrieving new playlist for Source 2 (pandora/startscript), Source status: 34 Retrieving new playlist for Source 2 (pandora/startscript), 2021-08-23 00:07:47: Cannot open audio device default/default/default: Cannot open device, [mp3float @ 0x6af0e6c0] Could not update timestamps for skipped samples., 2021-08-23 00:07:51: Cannot open audio device default/default/default: Cannot open device, [mp3float @ 0x6650a4b0] Could not update timestamps for skipped samples., 2021-08-23 00:08:11: #6: Connection terminated., 2021-08-23 00:08:16: #8: Connection terminated., 2021-08-23 00:18:36: #7: Connection terminated., 2021-08-23 00:18:36: #6: Connection from 172.24.0.1 permitted., 2021-08-23 00:18:36: #6: New cleartext IP4 HTTP connection from 172.24.0.1 port 39834, 2021-08-23 00:18:42: #6: Connection terminated., 2021-08-23 00:24:53: #6: Connection from 172.24.0.1 permitted., 2021-08-23 00:24:53: #6: New cleartext IP4 HTTP connection from 172.24.0.1 port 39844, 2021-08-23 00:25:42: #7: Connection from 172.24.0.1 permitted., 2021-08-23 00:25:42: #7: New cleartext IP4 HTTP connection from 172.24.0.1 port 39846, 2021-08-23 00:25:55: #6: Connection terminated., 2021-08-23 00:27:29: #6: Connection from 172.24.0.1 permitted., 2021-08-23 00:27:29: #6: New cleartext IP4 HTTP connection from 172.24.0.1 port 39854, 2021-08-23 00:27:35: #6: Connection terminated., 2021-08-23 00:31:15: Cannot open audio device default/default/default: Cannot open device, 2021-08-23 00:32:24: #7: Connection terminated., 2021-08-23 07:51:47: #6: Connection from 172.24.0.1 permitted., 2021-08-23 07:51:47: #6: New cleartext IP4 HTTP connection from 172.24.0.1 port 39862, 2021-08-23 07:51:50: Request failed: Invalid or expired auth token, Request: {, "syncTime":1629705109,, "userAuthToken":"VIKCZvkDAQVPMHnhhXZlKV4kkOZO6TqQCzoXA3gsx3puZeacvIRbCXYg==",, "stationToken":"1294769955744241033",, "includeExtendedAttributes":true, }, Response: {, "code":1001,, "stat":"fail",, "message":"An unexpected error occurred", }, Request type: Post, URL: http://internal-tuner.pandora.com/services/json/, Parameters:, partner_id : 37, user_id : , method : station.getStation, auth_token : VIKCZvkDAQVPMHnhhXZlKV4kkOZO6TqQCzoXA3gsx3puZeacvIRbCXYg==, Headers:, Content-Type : text/plain, Cookies: None, Body:, d2ba357eb0653b72389a44c98c13aa30a4695739144e84caad0c3829fce38438017328c4231b7847368228167134949e289fc3a7ae04f8401cd89fd109c7ef381cb17d0aa611472041f78e0ff31a452169676f496ca9046b08a0063a1d47548ab6f5bf29c0dfeaabdb0ec950c14ca02cdc0305925862a54d388ebe9af353e2de7380e7ae58e8f6d5aa52a64bce6107f71c02097963ba1a9e2427e1ca78929ef5c8ea236353e4e0a0c965b8e0946845e2, , 2021-08-23 07:51:51: #6: Connection terminated. Notes ----- - `getHistory` and `getQueue` requests should accept negative parameters. This is handled in`sendSongLists` (engineResponder.cpp:45), which swaps the request types for negative numbers. However, it doesn't correct (negate) the index so it is positive when it does so. This would cause negative indexing into a list at line 63, a security risk, misbehavior or crash. Fixed bug to make negative indexes positive when swapping request type. Checking with OP to see if this fits the triggering actions. - Found ratings are provided by Pandora implementation without refreshing seed & ratings cache. Added code to do this. This would not cause this problem. Reviewed seed/ratings handling for potential problems if Pandora seed & ratings request fails. No issues identified; in event of failure, requests for this information should return unrated/non-seed. Reviewed OP-provided backtrace showing code stopped in pandoracomm.cpp after Pandora request has failed due to expired auth key. getHistory request has already completed, the request is being issued as the response contents are being serialized and seeds & ratings are required. Reasons the connection could close now: - asUser is in use - Protocol/encoding error causing the websocket to close. - Memory corruption issue causing `close_after_response` to be `true`. OP indicated GDB session remains open, requested contents of connection context. Reproduced Pandora auth key expiration and traced code after receiving 1001 auth key expired error. Code working as expected and sending response without disconnecting. Received e-mail from user, they are using a 1-second timeout. Rx -- After a long idle period, seed & ratings cache is stale and auth keys expired. Refresh of cache fails, pianod reauthenticates and retries and responds but not before the 1-second timeout. pianod makes no guarantee how *fast* it will respond, just that it *will* respond to all commands/requests. While usually pretty responsive, pianod is essentially single threaded and there are scenarios where it can take longer, especially: - around song transitions & crossfades - preparing responses to complicated queries - if other connected users/sessions are submitting requests - if on public 'net, when connection storms blindly try exploits known for various HTTP servers/IOT devices If you feel you need a timeout, I would suggest 15 to 30 seconds so it only triggers when something is truly wrong. Updated protocol section of documentation.