ERROR in app: Exception on /alexa [POST]

[zadowsmash]

Hi,

I am trying to configure asksonic with the following:

• Ampache v5.6.0 which has subsonic API v1.13.0 ( I have configured env variable ASKS_SUBSONIC_APIVERSION=1.13.0)
• Python 3.9.16
• Alexa skill configured as per the readme

I can see that the Alexa service is hitting my asksonic instance fine but I get the following errors in the logs and it doesn't work.

20:05:44 web.1  | [2023-04-13 20:05:44 +1000] [15] [INFO] Listening at: http://0.0.0.0:4545 (15)
20:05:44 web.1  | [2023-04-13 20:05:44 +1000] [15] [INFO] Using worker: sync
20:05:44 web.1  | [2023-04-13 20:05:44 +1000] [16] [INFO] Booting worker with pid: 16

20:06:04 web.1  | [2023-04-13 20:06:04,072] ERROR in app: Exception on /alexa [POST]
20:06:04 web.1  | Traceback (most recent call last):
20:06:04 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2051, in wsgi_app
20:06:04 web.1  |     rv = self.handle_user_exception(e)
20:06:04 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1499, in full_dispatch_request
20:06:04 web.1  |     rv = self.dispatch_request()
20:06:04 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1485, in dispatch_request
20:06:04 web.1  |     return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
20:06:04 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask_ask/core.py", line 890, in _flask_view_func
20:06:04 web.1  |     result = self._map_intent_to_view_func(self.request.intent)()
20:06:04 web.1  |   File "/app/asksonic/intents/navigation.py", line 33, in play_artist
20:06:04 web.1  |     tracks = subsonic.artist_tracks(artist, tracks_count)
20:06:04 web.1  |   File "/app/asksonic/utils/subsonic/api.py", line 94, in artist_tracks
20:06:04 web.1  |     albums = self.artist_albums(artist)
20:06:04 web.1  |     found_artist = self.find_artist(artist)
20:06:04 web.1  |   File "/app/asksonic/utils/subsonic/api.py", line 62, in find_artist
20:06:04 web.1  |     return self._find_x('artist', query)
20:06:04 web.1  |   File "/app/asksonic/utils/subsonic/api.py", line 46, in _find_x
20:06:04 web.1  |     result = self.search(
20:06:04 web.1  |   File "/app/asksonic/utils/subsonic/api.py", line 41, in search
20:06:04 web.1  |     return self.search3(query=query, **options)
20:06:04 web.1  |   File "/usr/local/lib/python3.9/site-packages/libsonic/connection.py", line 651, in search3
20:06:04 web.1  |     res = self._doInfoReq(req)
20:06:04 web.1  |   File "/app/asksonic/utils/subsonic/api.py", line 25, in _doInfoReq
20:06:04 web.1  |     return super()._doInfoReq(req)
20:06:04 web.1  |   File "/usr/local/lib/python3.9/site-packages/libsonic/connection.py", line 2783, in _doInfoReq
20:06:04 web.1  |     return dres['subsonic-response']
20:06:04 web.1  | KeyError: 'subsonic-response'

Any suggestions as to why it is not working would be greatly appreciated.

Thanks :)

[srichter]

Looks like it's not getting an expected subsonic response. Could you run the server in debug mode and see what the logs show the request/response to the subsonic server were?

[zadowsmash]

Hi @srichter ,
Thanks for your quick response, I really appreciate it. I tried what you suggested, here is a sanitised/shortened version of the debug log:

11:45:42 web.1  | started with pid 12
11:45:47 web.1  |  * Serving Flask app 'asksonic' (lazy loading)
11:45:47 web.1  |  * Environment: development
11:45:47 web.1  |  * Debug mode: on
11:45:47 web.1  |  * Running on all addresses.
11:45:47 web.1  |    WARNING: This is a development server. Do not use it in a production deployment.
11:45:47 web.1  |  * Running on http://172.18.0.10:4545/ (Press CTRL+C to quit)
11:45:47 web.1  |  * Restarting with stat
11:45:48 web.1  |  * Debugger is active!
11:45:48 web.1  |  * Debugger PIN: 718-262-018
11:46:56 web.1  | {"context": {"Advertising": {"advertisingId": "00000000-0000-0000-0000-000000000000", "limitAdTracking": true}, "AudioPlayer": {"playerActivity": "IDLE"}, "Extensions": {"available": {"aplext:backstack:10": {}}}, "System": {"apiAccessToken": "xxx"}, "device": {"deviceId": "amzn1.ask.device.AFxxx", "supportedInterfaces": {"AudioPlayer": {}}}, "user": {"userId": "amzn1.ask.account.AF2FIxxx"}}, "Viewport": {"currentPixelHeight": 800, "currentPixelWidth": 1280, "dpi": 213, "experiences": [{"arcMinuteHeight": 216, "arcMinuteWidth": 346, "canResize": false, "canRotate": false}], "mode": "HUB", "pixelHeight": 800, "pixelWidth": 1280, "shape": "RECTANGLE", "touch": ["SINGLE"], "video": {"codecs": ["H_264_42", "H_264_41"]}}, "Viewports": [{"canRotate": false, "configuration": {"current": {"mode": "HUB", "size": {"pixelHeight": 800, "pixelWidth": 1280, "type": "DISCRETE"}, "video": {"codecs": ["H_264_42", "H_264_41"]}}}, "dpi": 213, "id": "main", "presentationType": "STANDARD", "shape": "RECTANGLE", "type": "APL"}]}, "request": {"dialogState": "STARTED", "intent": {"confirmationStatus": "NONE", "name": "AskSonicShuffleLibraryIntent"}, "locale": "en-AU", "requestId": "amzn1.echo-api.request.4bbc5xxx", "timestamp": "2023-04-14T01:46:53Z", "type": "IntentRequest"}, "session": {"application": {"applicationId": "amzn1.ask.skill.4fc0fxxx"}, "attributes": {}, "new": true, "sessionId": "amzn1.echo-api.session.c379f74d-85xxx", "user": {"userId": "amzn1.ask.account.AF2Fxxx"}}, "version": "1.0"}
11:46:56 web.1  | {"playerActivity": "IDLE"}
11:46:56 web.1  | [2023-04-14 11:46:56,540] DEBUG in navigation: Shuffle Library
11:46:57 web.1  | 172.18.0.6 - - [14/Apr/2023 11:46:57] "POST /alexa HTTP/1.1" 500 -
11:46:57 web.1  | Traceback (most recent call last):
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2069, in __call__
11:46:57 web.1  |     return self.wsgi_app(environ, start_response)
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2054, in wsgi_app
11:46:57 web.1  |     response = self.handle_exception(e)
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2051, in wsgi_app
11:46:57 web.1  |     response = self.full_dispatch_request()
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1501, in full_dispatch_request
11:46:57 web.1  |     rv = self.handle_user_exception(e)
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1499, in full_dispatch_request
11:46:57 web.1  |     rv = self.dispatch_request()
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1485, in dispatch_request
11:46:57 web.1  |     return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/flask_ask/core.py", line 890, in _flask_view_func
11:46:57 web.1  |     result = self._map_intent_to_view_func(self.request.intent)()
11:46:57 web.1  |   File "/asksonic/asksonic/intents/navigation.py", line 25, in play_random_tracks
11:46:57 web.1  |     tracks = subsonic.random_tracks(tracks_count)
11:46:57 web.1  |   File "/asksonic/asksonic/utils/subsonic/api.py", line 81, in random_tracks
11:46:57 web.1  |     tracks = self.getRandomSongs(count)
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/libsonic/connection.py", line 1353, in getRandomSongs
11:46:57 web.1  |     res = self._doInfoReq(req)
11:46:57 web.1  |   File "/asksonic/asksonic/utils/subsonic/api.py", line 25, in _doInfoReq
11:46:57 web.1  |     return super()._doInfoReq(req)
11:46:57 web.1  |   File "/usr/local/lib/python3.9/site-packages/libsonic/connection.py", line 2783, in _doInfoReq
11:46:57 web.1  |     return dres['subsonic-response']
11:46:57 web.1  | KeyError: 'subsonic-response'
11:46:59 web.1  | {"context": {"AudioPlayer": {"playerActivity": "IDLE"}, "Extensions": {"available": {"aplext:backstack:10": {}}}, "System": {"apiAccessToken": "xxx", "apiEndpoint": "https://api.fe.amazonalexa.com", "application": {"applicationId": "amzn1.ask.skill.4fc0xxx"}, "device": {"deviceId": "amzn1.ask.device.AF4VYQCxxx", "supportedInterfaces": {"AudioPlayer": {}}}, "user": {"userId": "amzn1.ask.account.AF2Fxxx"}}, "Viewport": {"currentPixelHeight": 800, "currentPixelWidth": 1280, "dpi": 213, "experiences": [{"arcMinuteHeight": 216, "arcMinuteWidth": 346, "canResize": false, "canRotate": false}], "mode": "HUB", "pixelHeight": 800, "pixelWidth": 1280, "shape": "RECTANGLE", "touch": ["SINGLE"], "video": {"codecs": ["H_264_42", "H_264_41"]}}, "Viewports": [{"canRotate": false, "configuration": {"current": {"mode": "HUB", "size": {"pixelHeight": 800, "pixelWidth": 1280, "type": "DISCRETE"}, "video": {"codecs": ["H_264_42", "H_264_41"]}}}, "dpi": 213, "id": "main", "presentationType": "STANDARD", "shape": "RECTANGLE", "type": "APL"}]}, "request": {"error": {"message": "An exception occurred while dispatching the request to the skill.", "type": "INVALID_RESPONSE"}, "locale": "en-AU", "reason": "ERROR", "requestId": "amzn1.echo-api.request.4eexxx", "timestamp": "2023-04-14T01:46:57Z", "type": "SessionEndedRequest"}, "session": {"application": {"applicationId": "amzn1.ask.skill.4fc0fxxx"}, "attributes": {}, "new": false, "sessionId": "amzn1.echo-api.session.c37xxx", "user": {"userId": "amzn1.ask.account.AF2xxx"}}, "version": "1.0"}
11:46:59 web.1  | {"playerActivity": "IDLE"}
11:46:59 web.1  | 172.18.0.6 - - [14/Apr/2023 11:46:59] "POST /alexa HTTP/1.1" 200 -
11:48:31 web.1  | 172.18.0.6 - - [14/Apr/2023 11:48:31] "GET / HTTP/1.1" 404 -

Also, here is my .env file for more context:

# Subsonic server information
ASKS_SUBSONIC_URL=https://my-ampache.example.org
#ASKS_SUBSONIC_PORT=443
#ASKS_SUBSONIC_SERVERPATH=/rest
ASKS_SUBSONIC_APIVERSION=1.13.0
#ASKS_SUBSONIC_APPNAME=py-sonic

# AskSonic server config
#ASKS_HOST=0.0.0.0
ASKS_PORT=4545
#ASKS_ROUTE_PREFIX=/alexa

# AskSonic config
#ASKS_EXTRA_SECRET=
#ASKS_TRACKS_COUNT=50
ASKS_SUBSONIC_USER=ampacheuser
ASKS_SUBSONIC_PASS=xxxxx

I can see a 500 response first but then a 200 later. Is the 404 a minute or so later the arcsonic server trying to hit my ampache/subsonic server? Maybe I have ASKS_SUBSONIC_SERVERPATH set incorrectly?

[srichter]

Sorry, there's actually no debug logging of the subsonic request/response in Asksonic. Can you check your subsonic server and see if it receives the request and outputs any information related to it? You may be able to enable debug logging there for more verbose information.

[zadowsmash]

Hi @srichter

No worries, thanks for the suggestion. This helped me figure out what was happening. The ampache debug logs showed an authentication issue and after some googling I found that I can't auth with the users password and I have to use the users API key. It is now working. Cheers

[srichter]

Glad to hear you got it working!