search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.58k stars 29.91k forks source link

forked_daapd: Entities are not updated after some time #42805

Closed christophkreutzer closed 3 years ago

christophkreutzer commented 3 years ago

The problem

When starting Home Assistant Core, or restarting the integration via settings -> integrations, the forked_daapd integration works fine. After around 1-2 hours, the entities of the integration no longer get updated (e.g. speakers still show as on, even when turned off in forked-daapd or in Home Assistant; or the song currently playing is not updated any longer). Enabling or disabling speakers does still work, but the state is not updated.

There is nothing to be found in settings -> logs. I have been using the forked_daapd integration since 0.111 and the problem persists since then. I think it could be some issue with losing the websocket connection, but have no idea where to start debugging - any pointers are welcome!

Previously, I have been using a custom integration for forked-daapd: https://github.com/johnpdowling/custom_components/tree/master/forked-daapd With this integration no such "hanging" occured (probably because it's pull only).

Environment

Problem-relevant configuration.yaml

Configured via settings -> integrations.

core.config_entries:

{
                "entry_id": "e9189af92cd04ee6b273f92fdb4ce09b",
                "version": 1,
                "domain": "forked_daapd",
                "title": "My Library",
                "data": {
                    "host": "192.168.0.93",
                    "password": "",
                    "port": 3689
                },
                "options": {},
                "system_options": {
                    "disable_new_entities": false
                },
                "source": "zeroconf",
                "connection_class": "local_push",
                "unique_id": "My Library"
            },

Traceback/Error logs

Additional information

forked-daapd - version 27.2 (running on Arch Linux)

I've been using Home Assistant for a while (> 1 year), but not very firm with the codebase and the architecture of HA. I'll try to debug as much as I can, if someone can give me pointers where to start. Thanks!

probot-home-assistant[bot] commented 3 years ago

forked_daapd documentation forked_daapd source (message by IssueLinks)

probot-home-assistant[bot] commented 3 years ago

Hey there @uvjustin, mind taking a look at this issue as its been labeled with an integration (forked_daapd) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

uvjustin commented 3 years ago

Interesting, I haven't seen this at all on my end. The pyforked-daapd library should restart the websocket connection on failure, and there should be a warning message provided on restart. Can you set the logging level for the pyforked-daapd library to debug and report back with any messages? Also, how are you installing forked-daapd? Is it through a package manager or are you compiling it yourself?

christophkreutzer commented 3 years ago

Thanks for your very fast response!

As I've written, I did not find any warnings in the logs. I now did try to enable debug logging, but I'm unsure if I do it correctly. According to: https://www.home-assistant.io/integrations/logger/

logger:
  default: warning
  logs:
    homeassistant.components.forked_daapd: debug
    pyforked-daapd: debug

Is that correct?

I'm running forked-daapd on Arch Linux. Since it's not in the repositories, I install it from AUR with yay: https://aur.archlinux.org/packages/forked-daapd/ that in itself is compiling forked-daapd locally: https://aur.archlinux.org/cgit/aur.git/tree/PKGBUILD?h=forked-daapd

I'm usually leaning towards Debian, but Arch was the only distro where I got a somewhat recent version of forked-daapd for the last years without compiling it manually every time ;-)

How are you installing forked-daapd? It would be certainly possible to set it up in another environment for testing if that could be the cause.

uvjustin commented 3 years ago 
logger:
  default: warning
  logs:
    homeassistant.components.forked_daapd: debug
    pyforked-daapd: debug

Is that correct?

Looks right. but the logging namespace is actually pyforked_daapd with an underscore not a hyphen.

How are you installing forked-daapd? It would be certainly possible to set it up in another environment for testing if that could be the cause.

For Debian the package is out of date but you can build it yourself pretty easily using the instructions here: https://github.com/ejurgensen/forked-daapd/blob/master/INSTALL.md#quick-version-for-debianubuntu-users . Remember to use --with-libwebsockets and probably --enable-chromecast. For Raspbian the author actually maintains an up to date package - you can find it just above the tag in that same link above. I'm currently installing it with that package.

BTW, have you tried seeing if the same thing happens on a long running connection to the player web interface? The web player also uses the same websocket interface.

christophkreutzer commented 3 years ago

Thanks for the correct logging namespace, haven't thought about it. I fixed it at noon and restarted the whole VM. Now I see all the debug messages incoming (HA has been started around 13:50 local time):

2020-11-05 13:51:43 DEBUG (MainThread) [pyforked_daapd] Starting websocket handler
2020-11-05 13:51:43 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'database', 'options', 'queue', 'outputs', 'volume', 'player'}
2020-11-05 13:51:43 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Could not get track info
2020-11-05 13:51:43 DEBUG (MainThread) [pyforked_daapd] Sent notify to http://172.31.83.93:3688/
2020-11-05 13:51:44 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2020-11-05 13:52:13 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 13:52:13 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 13:52:13 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 13:52:14 ERROR (MainThread) [aioharmony.harmonyclient] Zoe: Timeout trying to retrieve current activity.
2020-11-05 13:52:44 ERROR (MainThread) [aioharmony.helpers] get_current_activity was not called due to mismatch in callback type.
2020-11-05 13:54:36 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 13:54:36 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 13:54:36 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 13:57:44 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 13:57:44 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 13:57:44 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 14:01:06 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 14:01:06 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 14:01:06 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 14:04:36 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 14:04:36 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 14:04:36 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 14:08:06 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 14:08:06 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 14:08:06 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 14:12:36 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 14:12:36 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 14:12:36 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-05 14:16:06 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-05 14:16:06 DEBUG (MainThread) [homeassistant.components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-05 19:24:10 DEBUG (MainThread) [pyforked_daapd] PUT request to http://xxx.xx.xx.93:3689/api/outputs/270927335945367 with params None, json payload {'selected': True}.

According to the playlist of my radio station and the last updated track playing it seems the integration hangs since around 14:15. At 19:24 I enabled another speaker and that worked, but the state hasn't been updated afterwards.

I've kept the web interface of forked-daapd open for the whole day (it's now around 9 o'clock in the evening) and it's still updating as it should.

I can't see anything wrong in the logs, it's just like it suddenly seems to stop. I'll try to setup another install of forked-daapd over the weekend (on Debian) and test how it works then.

uvjustin commented 3 years ago

It looks like the last update at 14:16:06 is not completing the update callbacks. We can add some debug statements in to see where it's getting stuck and go from there. Use the component at https://github.com/uvjustin/home-assistant/tree/troubleshoot-forked-daapd . Hopefully we can find where it's getting stuck.

christophkreutzer commented 3 years ago

Thanks for the debugging variant. I copied the whole component to my custom_components folder and activated the logging for it. It seems to be stuck again:

2020-11-08 22:00:52 DEBUG (MainThread) [pyforked_daapd] Starting websocket handler
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'volume', 'options', 'outputs', 'database', 'player', 'queue'}
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Could not get track info
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, outputs, database, player event(s)
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:00:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, outputs, database, player event(s)
2020-11-08 22:00:52 DEBUG (MainThread) [pyforked_daapd] Sent notify to http://172.31.83.93:3688/
2020-11-08 22:00:53 WARNING (MainThread) [slixmpp.basexmpp] Legacy XMPP 0.9 protocol detected.
2020-11-08 22:01:22 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-08 22:01:22 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-08 22:02:48 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:02:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-08 22:02:48 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-08 22:06:48 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:06:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-08 22:06:48 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-08 22:10:29 DEBUG (MainThread) [pyforked_daapd] PUT request to http://172.31.83.93:3689/api/outputs/270927335945367 with params None, json payload {'selected': False}.
2020-11-08 22:10:48 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['outputs', 'volume']}
2020-11-08 22:10:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'outputs', 'volume'}
2020-11-08 22:10:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:10:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting outputs, player event(s)
2020-11-08 22:10:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:10:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:10:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received outputs, player event(s)
2020-11-08 22:10:48 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['outputs', 'volume']
2020-11-08 22:10:48 DEBUG (MainThread) [pyforked_daapd] PUT request to http://172.31.83.93:3689/api/player/pause with params None, json payload None.
2020-11-08 22:10:52 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player']}
2020-11-08 22:10:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player'}
2020-11-08 22:10:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:10:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting player event(s)
2020-11-08 22:10:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:10:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:10:52 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received player event(s)
2020-11-08 22:10:52 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player']
2020-11-08 22:11:11 DEBUG (MainThread) [pyforked_daapd] PUT request to http://172.31.83.93:3689/api/outputs/270927335945367 with params None, json payload {'selected': True}.
2020-11-08 22:11:18 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['outputs', 'volume']}
2020-11-08 22:11:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'outputs', 'volume'}
2020-11-08 22:11:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:11:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting outputs, player event(s)
2020-11-08 22:11:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:11:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:11:18 DEBUG (MainThread) [pyforked_daapd] POST request to http://172.31.83.93:3689/api/queue/items/add with params {'uris': 'library:playlist:7', 'clear': True}, data payload None.
2020-11-08 22:11:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received outputs, player event(s)
2020-11-08 22:11:18 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['outputs', 'volume']
2020-11-08 22:11:18 DEBUG (MainThread) [pyforked_daapd] PUT request to http://172.31.83.93:3689/api/player/play with params None, json payload None.
2020-11-08 22:11:24 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['outputs', 'player', 'volume', 'queue']}
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'outputs', 'queue', 'volume', 'player'}
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Could not get track info
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, outputs, player event(s)
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-08 22:11:24 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, outputs, player event(s)
2020-11-08 22:11:24 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['outputs', 'player', 'volume', 'queue']
2020-11-08 22:11:48 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-08 22:11:48 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}

(it's 22:23 now and no updates until now, but there have been several track changes on the radio channel)

Didn't have any chance to setup another forked-daapd instance until now, but I'll try it in the next few days.

uvjustin commented 3 years ago

Looks like it's probably getting stuck while requesting the queue from the server during the update. I added debug statements to that branch to confirm this - see if you can load that so we can confirm that. If that is the case, I'm not sure why it is hanging there. I would expect the request to fail or eventually timeout instead of hanging. I did see an issue with hanging concurrent requests over at the aiohttp repository, so maybe this is related. We can try creating our own HA clientsession instead of using the default one and see if that helps.

christophkreutzer commented 3 years ago

Looks like it's probably getting stuck while requesting the queue from the server during the update. I added debug statements to that branch to confirm this - see if you can load that so we can confirm that.

It seems like you're right (only the last rows here, it took several hours this time):

2020-11-09 19:03:40 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-09 19:03:40 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-09 19:03:40 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-09 19:03:42 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-09 19:03:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-09 19:03:42 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-09 19:07:42 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-09 19:07:42 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-09 19:07:42 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-09 19:11:12 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-09 19:11:12 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-09 19:11:12 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-09 19:26:16 DEBUG (MainThread) [pyforked_daapd] PUT request to http://xxx.xx.xx.93:3689/api/outputs/270927335945367 with params None, json payload {'selected': True}.

If that is the case, I'm not sure why it is hanging there. I would expect the request to fail or eventually timeout instead of hanging. I did see an issue with hanging concurrent requests over at the aiohttp repository, so maybe this is related. We can try creating our own HA clientsession instead of using the default one and see if that helps.

Do you mean aiohttp no. 3698? Seems strange, especially as it seems to affect HTTPS only there... But I would be happy to try it out :-)

uvjustin commented 3 years ago

Yes, that one. I didn't want to link it here as it's a shot in the dark and there's a good chance it's not related. It does seem to affect mostly SSL but there's one post on there that is not using SSL, and the default clientsession we get is shared with other components which do use SSL. I've pushed a change to that branch that just creates a new clientsession for our component - see if that helps.

christophkreutzer commented 3 years ago

Oops, sorry ;) I "unlinked" it now, but I believe the reference in the aiohttp repo won't be removed...

I've pushed a change to that branch that just creates a new clientsession for our component - see if that helps.

I tried it again last evening (and double checked that it's the new commit), seems it still got stuck after around 2,5 hours :(

2020-11-10 22:19:33 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-10 22:22:39 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-10 22:22:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-10 22:22:39 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-10 22:27:39 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-10 22:27:39 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-10 22:27:39 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-10 22:31:07 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-10 22:31:07 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-10 22:31:07 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue

Should I enable debug logging on aiohttp, too?

For the queue request, would it be possible to define a timeout, so it doesn't get stuck? I'm reading a bit about aiohttp/asyncio at the moment, but I'm still very new to it.

christophkreutzer commented 3 years ago

Well, at least timeouts don't make that much sense on the websocket connection, as it's always closed then... could have thought about that ;)

    aiotimeout = aiohttp.ClientTimeout(total=60, connect=30, sock_connect=30, sock_read=30)
    clientsession = async_create_clientsession(hass,verify_ssl=False,timeout=aiotimeout)

leads to

2020-11-11 13:16:31 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-11 13:16:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-11 13:16:31 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-11 13:17:01 WARNING (MainThread) [pyforked_daapd] Can not connect to WebSocket at http://172.31.83.93:3688/, will retry in 30 seconds.
2020-11-11 13:17:01 WARNING (MainThread) [pyforked_daapd] Error ServerTimeoutError('Timeout on reading data from socket')
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'outputs', 'volume', 'database', 'player', 'options'}
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, outputs, database, player event(s)
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-11 13:17:31 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, outputs, database, player event(s)
2020-11-11 13:17:31 DEBUG (MainThread) [pyforked_daapd] Sent notify to http://172.31.83.93:3688/
2020-11-11 13:18:02 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-11 13:18:02 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-11 13:18:02 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-11 13:18:28 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-11 13:18:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'queue', 'player'}
2020-11-11 13:18:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue

so legitimate websocket connections are timed out, but it will still hang :(

uvjustin commented 3 years ago

There should be a default timeout of 5 minutes already, although we can consider lowering that if that solves any issues. But in your case, the connection never times out, so a lower value wouldn't seem to help. I haven't been able to reproduce the problem so it's hard for me to troubleshoot. I just added a commit that uses separate clientsessions for the updater and the main component. I don't see why that should change anything, but might as well give it a try.

christophkreutzer commented 3 years ago

Yes, that was what I did found out, too. However it doesn't seem to help to lower it (as in my example above), the websocket connection will be timed out and the entities will change to unavailable. They will come back when the connection is re-established after the timeout (that works fine), but somewhen it will still hang on requesting queue.

I did try it with your latest commit, and that doesn't seem to change anything. I had the chance to setup forked-daapd on a Debian LXC container with the instructions by the maintainer, and it seems to have reduced the latency (previously it took several seconds until entity states where updated, e.g. when turning on outputs or changing from paused to playing). Also it seems to take longer now till hanging (around 12 hours last time), but that was also over the night when playback has been paused. I'll try to get some new logs in the next 24 hours over the day with a radio stream playing.

christophkreutzer commented 3 years ago

It seems to take longer if the player is idling (i.e. over night), then usually after at maximum 2 hours when playing it's getting stuck again when requesting the queue.

Otherwise, if I'm testing while forked-daapd is playing, it's usually taking between 30min and 2 hours (several times over the last days). There are no other errors/warnings when the hang occurs, too.

I also did move to Debian forked-daapd LXC container to another host yesterday, and the Home Assistant VM to another NIC, in case it should be some strange network issue - but that doesn't seem to have any impact.

hindsholm commented 3 years ago

Just wanted to let you know, that I have the exact same problem. I am running forked-daapd in Docker using this image https://docs.linuxserver.io/images/docker-daapd and Home Assistant in another Docker container.

uvjustin commented 3 years ago

I realized the most recent shot in the dark (using a different clientsession for the api and the master) really doesn't do anything, since the master only uses the clientsession for the pipe interface (a feature which I think I am the only one using, but that is another topic). We could try using separate clientsessions for the updater and the rest of the component or just create a new clientsession for each connection to see if that helps anything, but to try that we have to use a modified pyforked-daapd library.

uvjustin commented 3 years ago

Can you turn on debug logging on the forked-daapd server itself and provide the logs from when the HA component hangs?

christophkreutzer commented 3 years ago

I just enabled debug logging and restarted everything (forked-daapd and HA Core). Already thought about that before, but somehow missed the option in the config...

I would be happy to try a modified pyforked-daapd version, however I'm not sure how to "integrate" that with the custom component. As I'm running on HassOS it's not that easy to exchange the bundled one, I believe.

christophkreutzer commented 3 years ago

Maybe I have a lead...

HA log:

2020-11-18 21:57:17 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-18 22:01:18 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-18 22:01:18 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-18 22:01:18 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-18 22:01:27 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-18 22:01:27 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-18 22:01:27 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Done requesting queue
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent queue signal
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update queue signal
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update queue event
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue event
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue event
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Sent player signal
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Awaiting queue, player event(s)
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received update player signal
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Set update player event
2020-11-18 22:01:28 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Received queue, player event(s)
2020-11-18 22:01:28 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-18 22:04:57 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-18 22:04:57 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-18 22:04:57 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue

forked-daapd log:

[2020-11-18 22:01:17] [DEBUG]   player: event_play_metadata()
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:17] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 19 ORDER BY pos;'
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'UPDATE queue SET file_id = 12723, song_length = 0, data_kind = 1, media_kind = 1, pos = 0, shuffle_pos = 0, path = 'http://stream.srg-ssr.ch/m/rsp/aacp_96', virtual_path = '/http://stream.srg-ssr.ch/m/rsp/aacp_96', title = 'Radio Swiss Pop', artist = 'Radio Swiss Pop', album_artist = 'Radio Swiss Pop', album = 'www.radioswisspop.ch', composer = NULL,genre = 'Pop Music', time_modified = 1605181822, songalbumid = 2722456655785114155, songartistid = 3933738910568302470, artist_sort = 'Radio Swiss Pop', album_sort = 'Die besten Pophits der letzten 00040 Jahre', album_artist_sort = 'Radio Swiss Pop', year = 0, track = 0, disc = 0, artwork_url = NULL, queue_version = 2422 WHERE id = 19;'
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'INSERT OR REPLACE INTO admin (key, value) VALUES ('queue_version', '2422');'
[2020-11-18 22:01:17] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]      mpd: Asynchronous listener callback called with event type 2.
[2020-11-18 22:01:18] [DEBUG]      mpd: Notify clients waiting for idle results: 2
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 19 ORDER BY pos;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]  artwork: Artwork request for item 12723 (max_w=600, max_h=600)
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723   ;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:01:18] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2722456655785114155 AND a.max_w = 600 AND a.max_h = 600;'
[2020-11-18 22:01:18] [DEBUG]    cache: No results
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:01:18] [DEBUG]       db: End of query results
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE file_id = 12723 ORDER BY pos;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM playlists f WHERE f.id IN (SELECT playlistid FROM playlistitems WHERE filepath = 'http://stream.srg-ssr.ch/m/rsp/aacp_96');'
[2020-11-18 22:01:18] [DEBUG]       db: Starting query 'SELECT f.*, COUNT(pi.id), SUM(pi.filepath NOT NULL AND pi.filepath LIKE 'http%') FROM playlists f LEFT JOIN playlistitems pi ON (f.id = pi.playlistid) WHERE f.id IN (SELECT playlistid FROM playlistitems WHERE filepath = 'http://stream.srg-ssr.ch/m/rsp/aacp_96') GROUP BY f.id  ;'
[2020-11-18 22:01:18] [DEBUG]       db: End of query results
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_discogs';'
[2020-11-18 22:01:18] [DEBUG]       db: No results
[2020-11-18 22:01:18] [DEBUG]  artwork: Source Discogs is disabled
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_coverartarchive';'
[2020-11-18 22:01:18] [DEBUG]       db: No results
[2020-11-18 22:01:18] [DEBUG]  artwork: Source Musicbrainz is disabled
[2020-11-18 22:01:18] [DEBUG]       db: End of query results
[2020-11-18 22:01:18] [DEBUG]  artwork: No artwork found for item 12723
[2020-11-18 22:01:18] [ INFO]     raop: Failed to retrieve artwork for file 'http://stream.srg-ssr.ch/m/rsp/aacp_96'; no artwork will be sent
[2020-11-18 22:01:18] [DEBUG]   player: Status update - status: 4, events: 1, caller: metadata_finalize
[2020-11-18 22:01:18] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2020-11-18 22:01:18] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2020-11-18 22:01:18] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:01:18] [DEBUG]      web: JSON api request: '/api/queue'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM queue;'
[2020-11-18 22:01:18] [DEBUG]   player: Player status: playing
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE 1=1 ORDER BY pos;'
[2020-11-18 22:01:18] [DEBUG]       db: End of queue enum results
[2020-11-18 22:01:18] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:18] [DEBUG]      web: JSON api request: '/api/player'
[2020-11-18 22:01:18] [DEBUG]   player: Player status: playing
[2020-11-18 22:01:25] [DEBUG]   player: event_read_metadata()
[2020-11-18 22:01:25] [DEBUG]   player: Incomplete read, wanted 3528, got 1616 (samples=202/time=4580498), deficit 2672
[2020-11-18 22:01:27] [DEBUG]   player: event_play_metadata()
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 19 ORDER BY pos;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'UPDATE queue SET file_id = 12723, song_length = 0, data_kind = 1, media_kind = 1, pos = 0, shuffle_pos = 0, path = 'http://stream.srg-ssr.ch/m/rsp/aacp_96', virtual_path = '/http://stream.srg-ssr.ch/m/rsp/aacp_96', title = 'Radio Swiss Pop', artist = 'Aloe Blacc & Pegasus', album_artist = 'Radio Swiss Pop', album = 'Greatest Show On Earth', composer = NULL,genre = 'Pop Music', time_modified = 1605181822, songalbumid = 2722456655785114155, songartistid = 3933738910568302470, artist_sort = 'Radio Swiss Pop', album_sort = 'Die besten Pophits der letzten 00040 Jahre', album_artist_sort = 'Radio Swiss Pop', year = 0, track = 0, disc = 0, artwork_url = NULL, queue_version = 2423 WHERE id = 19;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'INSERT OR REPLACE INTO admin (key, value) VALUES ('queue_version', '2423');'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]      mpd: Asynchronous listener callback called with event type 2.
[2020-11-18 22:01:27] [DEBUG]      mpd: Notify clients waiting for idle results: 2
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 19 ORDER BY pos;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]  artwork: Artwork request for item 12723 (max_w=600, max_h=600)
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723   ;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:01:27] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2722456655785114155 AND a.max_w = 600 AND a.max_h = 600;'
[2020-11-18 22:01:27] [DEBUG]    cache: No results
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:01:27] [DEBUG]       db: End of query results
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE file_id = 12723 ORDER BY pos;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM playlists f WHERE f.id IN (SELECT playlistid FROM playlistitems WHERE filepath = 'http://stream.srg-ssr.ch/m/rsp/aacp_96');'
[2020-11-18 22:01:27] [DEBUG]       db: Starting query 'SELECT f.*, COUNT(pi.id), SUM(pi.filepath NOT NULL AND pi.filepath LIKE 'http%') FROM playlists f LEFT JOIN playlistitems pi ON (f.id = pi.playlistid) WHERE f.id IN (SELECT playlistid FROM playlistitems WHERE filepath = 'http://stream.srg-ssr.ch/m/rsp/aacp_96') GROUP BY f.id  ;'
[2020-11-18 22:01:27] [DEBUG]       db: End of query results
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_discogs';'
[2020-11-18 22:01:27] [DEBUG]       db: No results
[2020-11-18 22:01:27] [DEBUG]  artwork: Source Discogs is disabled
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_coverartarchive';'
[2020-11-18 22:01:27] [DEBUG]       db: No results
[2020-11-18 22:01:27] [DEBUG]  artwork: Source Musicbrainz is disabled
[2020-11-18 22:01:27] [DEBUG]       db: End of query results
[2020-11-18 22:01:27] [DEBUG]  artwork: No artwork found for item 12723
[2020-11-18 22:01:27] [ INFO]     raop: Failed to retrieve artwork for file 'http://stream.srg-ssr.ch/m/rsp/aacp_96'; no artwork will be sent
[2020-11-18 22:01:27] [DEBUG]   player: Status update - status: 4, events: 1, caller: metadata_finalize
[2020-11-18 22:01:27] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2020-11-18 22:01:27] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2020-11-18 22:01:27] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:01:27] [DEBUG]      web: JSON api request: '/api/queue'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM queue;'
[2020-11-18 22:01:27] [DEBUG]   player: Player status: playing
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE 1=1 ORDER BY pos;'
[2020-11-18 22:01:27] [DEBUG]       db: End of queue enum results
[2020-11-18 22:01:27] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:01:27] [DEBUG]      web: JSON api request: '/api/player'
[2020-11-18 22:01:27] [DEBUG]   player: Player status: playing
[2020-11-18 22:01:58] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:02:29] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:03:00] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:03:31] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:04:02] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:04:33] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:04:55] [DEBUG]   player: event_read_metadata()
[2020-11-18 22:04:55] [DEBUG]   player: Incomplete read, wanted 3528, got 448 (samples=56/time=1269841), deficit 5752
[2020-11-18 22:04:57] [DEBUG]   player: event_play_metadata()
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 19 ORDER BY pos;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'UPDATE queue SET file_id = 12723, song_length = 0, data_kind = 1, media_kind = 1, pos = 0, shuffle_pos = 0, path = 'http://stream.srg-ssr.ch/m/rsp/aacp_96', virtual_path = '/http://stream.srg-ssr.ch/m/rsp/aacp_96', title = 'Radio Swiss Pop', artist = 'Ja<EB>l', album_artist = 'Radio Swiss Pop', album = 'Waiting For A Sign', composer = NULL,genre = 'Pop Music', time_modified = 1605181822, songalbumid = 2722456655785114155, songartistid = 3933738910568302470, artist_sort = 'Radio Swiss Pop', album_sort = 'Die besten Pophits der letzten 00040 Jahre', album_artist_sort = 'Radio Swiss Pop', year = 0, track = 0, disc = 0, artwork_url = NULL, queue_version = 2424 WHERE id = 19;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'INSERT OR REPLACE INTO admin (key, value) VALUES ('queue_version', '2424');'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]      mpd: Asynchronous listener callback called with event type 2.
[2020-11-18 22:04:57] [DEBUG]      mpd: Notify clients waiting for idle results: 2
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 19 ORDER BY pos;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]  artwork: Artwork request for item 12723 (max_w=600, max_h=600)
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723   ;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:04:57] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2722456655785114155 AND a.max_w = 600 AND a.max_h = 600;'
[2020-11-18 22:04:57] [DEBUG]    cache: No results
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:04:57] [DEBUG]       db: End of query results
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2722456655785114155;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 12723 AND f.songalbumid = 2722456655785114155  ;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE file_id = 12723 ORDER BY pos;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM playlists f WHERE f.id IN (SELECT playlistid FROM playlistitems WHERE filepath = 'http://stream.srg-ssr.ch/m/rsp/aacp_96');'
[2020-11-18 22:04:57] [DEBUG]       db: Starting query 'SELECT f.*, COUNT(pi.id), SUM(pi.filepath NOT NULL AND pi.filepath LIKE 'http%') FROM playlists f LEFT JOIN playlistitems pi ON (f.id = pi.playlistid) WHERE f.id IN (SELECT playlistid FROM playlistitems WHERE filepath = 'http://stream.srg-ssr.ch/m/rsp/aacp_96') GROUP BY f.id  ;'
[2020-11-18 22:04:57] [DEBUG]       db: End of query results
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_discogs';'
[2020-11-18 22:04:57] [DEBUG]       db: No results
[2020-11-18 22:04:57] [DEBUG]  artwork: Source Discogs is disabled
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_coverartarchive';'
[2020-11-18 22:04:57] [DEBUG]       db: No results
[2020-11-18 22:04:57] [DEBUG]  artwork: Source Musicbrainz is disabled
[2020-11-18 22:04:57] [DEBUG]       db: End of query results
[2020-11-18 22:04:57] [DEBUG]  artwork: No artwork found for item 12723
[2020-11-18 22:04:57] [ INFO]     raop: Failed to retrieve artwork for file 'http://stream.srg-ssr.ch/m/rsp/aacp_96'; no artwork will be sent
[2020-11-18 22:04:57] [DEBUG]   player: Status update - status: 4, events: 1, caller: metadata_finalize
[2020-11-18 22:04:57] [DEBUG]      mpd: Asynchronous listener callback called with event type 1.
[2020-11-18 22:04:57] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2020-11-18 22:04:57] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:04:57] [DEBUG]      web: JSON api request: '/api/queue'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM queue;'
[2020-11-18 22:04:57] [DEBUG]   player: Player status: playing
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE 1=1 ORDER BY pos;'
[2020-11-18 22:04:57] [DEBUG]       db: End of queue enum results
[2020-11-18 22:04:57] [DEBUG]       db: Running query 'END TRANSACTION;'
[2020-11-18 22:04:57] [DEBUG]      web: notify callback reason: 38
[2020-11-18 22:04:57] [DEBUG]      web: notify callback reason: 4
[2020-11-18 22:05:44] [DEBUG]     raop: Got retransmit request from 'Chuchi': seqnum 14966 (len 1), last RTP session seqnum 15000 (len 1000)
[2020-11-18 22:06:15] [DEBUG]     raop: Got retransmit request from 'Chuchi': seqnum 18756 (len 1), last RTP session seqnum 18789 (len 1000)

Could the problem be the encoding? The artists name is Jaël, and 0xEB in ISO 8859-1 is ë... but that will not work with UTF-8.

uvjustin commented 3 years ago

Does it always hang on that artist? It doesn't seem like ë is the culprit, as ë also has a UTF-8 representation and the forked-daapd db uses utf-8 and converts to utf-8 here: https://github.com/ejurgensen/forked-daapd/blob/master/src/db.c#L873 . Assuming your logs are unedited, what's interesting is that the lines from the forked-daapd log here:

[2020-11-18 22:01:58] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:02:29] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:03:00] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:03:31] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:04:02] [DEBUG]      web: notify callback reason: 11
[2020-11-18 22:04:33] [DEBUG]      web: notify callback reason: 11

do not result in a callback in the HA component (and there are no follow on queries in the forked-daapd log). Also, [2020-11-18 22:04:57] [DEBUG] web: notify callback reason: 38 [2020-11-18 22:04:57] [DEBUG] web: notify callback reason: 4 is interesting - those callback types don't seem to happen before. Let me think about this some more.

uvjustin commented 3 years ago

As 0.118.0 was just released which uses aiohttp 3.7.1 instead of 3.6.2. Can you check if by any chance that has resolved the issue?

christophkreutzer commented 3 years ago

Does it always hang on that artist? It doesn't seem like ë is the culprit, as ë also has a UTF-8 representation and the forked-daapd db uses utf-8 and converts to utf-8 here: https://github.com/ejurgensen/forked-daapd/blob/master/src/db.c#L873 .

You're right that there is a UTF-8 representation, but at least in the forked-daapd logs it looks like the character is written exactly as the ISO 8859-1 byte 0xEB (or it just looks like that in the log).

Also the last hang occured in the morning around 7 o'clock:

2020-11-19 07:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-19 07:01:22 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
2020-11-19 10:24:43 DEBUG (MainThread) [pyforked_daapd] PUT request to http://172.31.83.189:3689/api/player/volume with params {'volume': 40, 'output_id': '270927335945367'}, json payload None.

And just at that time there was another track starting with Umlauts:

[2020-11-19 07:01:22] [DEBUG]       db: Running query 'UPDATE queue SET file_id = 12723, song_length = 0, data_kind = 1, media_kind = 1, pos = 0, shuffle_pos = 0, path = 'http://stream.srg-ssr.ch/m/rsp/aacp_96', virtual_path = '/http://stream.srg-ssr.ch/m/rsp/aacp_96', title = 'Radio Swiss Pop', artist = 'L<E4><E4>rguet', album_artist = 'Radio Swiss Pop', album = 'F<FC>r immer', composer = NULL,genre = 'Pop Music', time_modified = 1605181822, songalbumid = 2722456655785114155, songartistid = 3933738910568302470, artist_sort = 'Radio Swiss Pop', album_sort = 'Die besten Pophits der letzten 00040 Jahre', album_artist_sort = 'Radio Swiss Pop', year = 0, track = 0, disc = 0, artwork_url = NULL, queue_version = 2459 WHERE id = 21;'

That seems to be reproducible, it just happened again with some special character in the artist attribute.

Assuming your logs are unedited, what's interesting is that the lines from the forked-daapd log here:

Yes, the logs are unedited. It's possible I had another client open at that time. I'm not sure what kind of callback it is, as pyforked-daapd does only handle some of them, iirc.

I'm going to update my HA instance now and update the ticket if it's still reproducible.

christophkreutzer commented 3 years ago

I'm now on HassOS 4.17 and Home Assistant 0.118.0. Was able to reproduce the hanging with another Umlaut:

2020-11-19 22:53:12 DEBUG (MainThread) [pyforked_daapd] Done with callbacks ['player', 'queue']
2020-11-19 22:58:27 DEBUG (MainThread) [pyforked_daapd] Message JSON: {'notify': ['player', 'queue']}
2020-11-19 22:58:27 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Updating {'player', 'queue'}
2020-11-19 22:58:27 DEBUG (MainThread) [custom_components.forked_daapd.media_player] Requesting queue
[2020-11-19 22:58:27] [DEBUG]       db: Running query 'UPDATE queue SET file_id = 12723, song_length = 0, data_kind = 
1, media_kind = 1, pos = 0, shuffle_pos = 0, path = 'http://stream.srg-ssr.ch/m/rsp/aacp_96', virtual_path = '/http://
stream.srg-ssr.ch/m/rsp/aacp_96', title = 'Radio Swiss Pop', artist = 'Sandee', album_artist = 'Radio Swiss Pop', albu
m = 'Bereue n<FC>t', composer = NULL,genre = 'Pop Music', time_modified = 1605181822, songalbumid = 272245665578511415
5, songartistid = 3933738910568302470, artist_sort = 'Radio Swiss Pop', album_sort = 'Die besten Pophits der letzten 0
0040 Jahre', album_artist_sort = 'Radio Swiss Pop', year = 0, track = 0, disc = 0, artwork_url = NULL, queue_version =
 2784 WHERE id = 21;'

Is it possible that the JSON decoding fails when there is an unexpected character in the content? https://github.com/uvjustin/pyforked-daapd/blob/master/pyforked_daapd/__init__.py#L75

I'll try to capture some raw output of the forked-daapd API to analyze that possibility.

uvjustin commented 3 years ago

I see.. Then yes, that's the likely cause of the issue.. we need to dig into forked-daapd itself to see what is going on.

uvjustin commented 3 years ago

Also don't worry about those notify requests with no matching callback in HA. I think those are just from the keep alive pings. Previously fd sent a notify on every ping.. I put in a PR over there to not send an update unless there is actually a new event.

uvjustin commented 3 years ago

So it does seem that the non UTF-8 characters cause the issue. The problem comes when getting metadata from an icecast server here: https://github.com/ejurgensen/forked-daapd/blob/e3308a464b0b6c8fbceaee1bc5ce04a0e91352f2/src/http.c#L348 . It looks like the strings are read in whatever encoding they are without converting to UTF-8. That metadata is then passed along to the db update here: https://github.com/ejurgensen/forked-daapd/blob/e3308a464b0b6c8fbceaee1bc5ce04a0e91352f2/src/db.c#L4770. And that non UTF-8 string eventually gets sent back to our HA component which seems to hang when encountering UTF-8 characters. I'm not sure what the spec for icecast string encoding is - there are code comments below stating that the headers are in ASCII or ISO-8859-1, but I'm not sure about the metadata strings themselves. I couldn't find the spec so I'll have a look at the Icecast code when I get a chance. I'm still not sure why aiohttp/json is hanging. I just made a version of the pypi library using ujson and I will test it on that Radio Swiss Pop stream to see if that changes anything.

uvjustin commented 3 years ago

Just an update: the hanging doesn't have to do with the json parser. I didn't get a chance to chase it down the aiohttp rabbit hole to see why the request is actually hanging, but since we were able to track down the problem on the forked-daapd side, I put in a PR over there to address the issue. Try building forked-daapd from my branch here: https://github.com/uvjustin/forked-daapd/tree/check-utf8-icy-metadata (the only change is to the src/http.c file) and see if that fixes the issue on your end.

christophkreutzer commented 3 years ago

Amazing! Thank you very much for that much work! :)

I hadn't any chance to debug the requests to forked-daapd any further (was thinking about the same as you, trying to debug the json decode of the aiohttp request).

But I can follow your conclusion that it's probably an issue in forked-daapd. Using the iOS Remote app, I've seen it also affects real DAAP clients (sorry, didn't manage to take a screenshot). If some attribute contains invalid encoded data, it seems to be just discarded - so in case of Jaël the app doesn't display an artist, but the other attributes are still there.

I'm trying to build your forked-daapd branch tonight and report back!

christophkreutzer commented 3 years ago

The integration has now been running for 24 hours without any hang :) Seems to be the real cause (and solution). Thank you very much!

Are you going to open a pull request over at the forked-daapd repo? Until then I'll probably keep running on your branch.

But it's still a bit disappointing that we don't know what happens to the aiohttp request. However, that's probably a tougher problem out of scope here.

uvjustin commented 3 years ago

The PR has already been merged into the forked-daapd repo master. Yeah, the problem is not with this component - it seems to be the interaction of aiohttp and a bad web response. You can investigate it some more if you have time. Maybe the content-length is getting reported incorrectly? It might be getting stuck here: https://github.com/aio-libs/aiohttp/blob/9815a7d13a07622a8be3b203fe14c66653453d0b/aiohttp/streams.py#L384 Anyway, since the problem does not seem to be from HA we should close this issue.

christophkreutzer commented 3 years ago

You're right. I'm fine with that. Thanks for your help!