Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

AssertionError: assert not self._pending_command_event.is_set() #98

Closed
imbaczek opened this issue Feb 8, 2025 · 10 comments · Fixed by #100
Closed

AssertionError: assert not self._pending_command_event.is_set() #98

imbaczek opened this issue Feb 8, 2025 · 10 comments · Fixed by #100
Labels
bug Something isn't working

Comments

@imbaczek
Copy link

imbaczek commented Feb 8, 2025

Describe the bug

Home Assistant 2025.2 upgraded pyheos and AssertionError: assert not self._pending_command_event.is_set() started happening (traceback below)

To Reproduce

It doesn't happen immediately. The system works for a while triggering playing multiple times before breaking; when it breaks, the player doesn't respond to commands (in HA) anymore AFAICT. The heos app works fine.

Expected behavior

No exceptions happen

Environment (please complete the following information):

  • pyheos version: 1.0.0 (I think? HA 2025.2)
  • python version: 3.13
  • HEOS device model: HEOS 1 HS2
  • HEOS device firmware version: 3.34.620

Logs

n/a

Traceback (if applicable)

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 526, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 762, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<9 lines>...
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 727, in _async_run_long_action
    return await long_task
           ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2794, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2837, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1007, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
        hass, entity, func, data, call.context
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1079, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/heos/media_player.py", line 114, in wrapper
    await func(*args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/heos/media_player.py", line 242, in async_media_stop
    await self._player.stop()
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 361, in stop
    await self.set_state(PlayState.STOP)
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 349, in set_state
    await self.heos.player_set_play_state(self.player_id, state)
  File "/usr/local/lib/python3.13/site-packages/pyheos/command/player.py", line 164, in player_set_play_state
    await self._connection.command(
    ...<4 lines>...
    )
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

Additional context
Add any other context about the problem here.
@imbaczek imbaczek added bug Something isn't working triage Bug has been reported but not evaluated labels Feb 8, 2025
@imbaczek
Copy link
Author

imbaczek commented Feb 8, 2025

got a couple more tracebacks

2025-02-08 21:02:57.002 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 300, in _heart_beat_handler
    await self.command(HeosCommand(COMMAND_HEART_BEAT))
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

2025-02-08 21:02:42.644 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 61, in _on_event
    await callback(message)
  File "/usr/local/lib/python3.13/site-packages/pyheos/heos.py", line 218, in _on_event
    await self._on_event_player(event)
  File "/usr/local/lib/python3.13/site-packages/pyheos/heos.py", line 250, in _on_event_player
    await player._on_event(event, self._options.all_progress_events)
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 275, in _on_event
    await self.refresh_now_playing_media()
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 327, in refresh_now_playing_media
    await self.heos.get_now_playing_media(self.player_id, self.now_playing_media)
  File "/usr/local/lib/python3.13/site-packages/pyheos/command/player.py", line 185, in get_now_playing_media
    result = await self._connection.command(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        HeosCommand(c.COMMAND_GET_NOW_PLAYING_MEDIA, {c.ATTR_PLAYER_ID: player_id})
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

@andrewsayre
Copy link
Owner

@imbaczek Thanks for reporting! Super strange. Would you be able to turn on debugging for the integration in HA and leave it until the issue occurs again and then post all of those logs here? I'd like to see the sequence leading up to this condition - very strange.

@imbaczek
Copy link
Author

imbaczek commented Feb 9, 2025

Yup, managed to grab some:

2025-02-09 08:56:15.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1193000&duration=0"}}
'
2025-02-09 08:56:20.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1198000&duration=0"}}
'
2025-02-09 08:56:25.089 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1203000&duration=0"}}
'
2025-02-09 08:56:30.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1208000&duration=0"}}
'
2025-02-09 08:56:35.089 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1213000&duration=0"}}
'
2025-02-09 08:56:40.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1218000&duration=0"}}
'
2025-02-09 08:56:45.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1223000&duration=0"}}
'
2025-02-09 08:56:50.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1228000&duration=0"}}
'
2025-02-09 08:56:55.091 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1233000&duration=0"}}
'
2025-02-09 08:56:59.567 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=stop&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=stop&pid=1010303184"}}
'
2025-02-09 08:56:59.670 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_state_changed': '{"heos": {"command": "event/player_state_changed", "message": "pid=1010303184&state=stop"}}
'
2025-02-09 08:56:59.671 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Dedication', station='1.FM Bay Smooth Jazz', album='', artist='Boney James', image_url='http://cdn-albums.tunein.com/gn/Z5KVZKQ7Q4d.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=1013000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 53, 14, 340628), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_state_changed
2025-02-09 08:57:00.170 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:57:00.170 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 61, in _on_event
    await callback(message)
  File "/usr/local/lib/python3.13/site-packages/pyheos/heos.py", line 218, in _on_event
    await self._on_event_player(event)
  File "/usr/local/lib/python3.13/site-packages/pyheos/heos.py", line 250, in _on_event_player
    await player._on_event(event, self._options.all_progress_events)
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 275, in _on_event
    await self.refresh_now_playing_media()
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 327, in refresh_now_playing_media
    await self.heos.get_now_playing_media(self.player_id, self.now_playing_media)
  File "/usr/local/lib/python3.13/site-packages/pyheos/command/player.py", line 185, in get_now_playing_media
    result = await self._connection.command(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        HeosCommand(c.COMMAND_GET_NOW_PLAYING_MEDIA, {c.ATTR_PLAYER_ID: player_id})
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError
2025-02-09 08:57:04.253 ERROR (MainThread) [homeassistant.components....] ...: Choose at step 1: choice 1: Error executing script. Unexpected error for call_service at pos 1:
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 526, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 762, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<9 lines>...
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 727, in _async_run_long_action
    return await long_task
           ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2794, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2837, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1007, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
        hass, entity, func, data, call.context
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1079, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/heos/media_player.py", line 114, in wrapper
    await func(*args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/heos/media_player.py", line 227, in async_media_play
    await self._player.play()
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 353, in play
    await self.set_state(PlayState.PLAY)
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 349, in set_state
    await self.heos.player_set_play_state(self.player_id, state)
  File "/usr/local/lib/python3.13/site-packages/pyheos/command/player.py", line 164, in player_set_play_state
    await self._connection.command(
    ...<4 lines>...
    )
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

The worst part is after this happens it's broken until restart 😥

@andrewsayre
Copy link
Owner

Thank you! I've been able to reproduce the assertion error under the following scenario:

  1. A command times out
  2. The response is still received (late, after it gave up waiting for it)
  3. The code stored the response
  4. Next command fails because a response is already set

I'd expect to see a timeout error somewhere in your logs though. Is it possible that happened earlier in what you sent?

@imbaczek
Copy link
Author

imbaczek commented Feb 9, 2025

I don't see any errors in the logs before that. Maybe it's a generic event-arrived-out-of-order or duplicated event or something like that issue...? Just guessing.

This this the log from the whole session playback session:

2025-02-09 08:34:02.011 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://system/heart_beat': '{"heos": {"command": "system/heart_beat", "result": "success", "message": ""}}
'
2025-02-09 08:34:05.618 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=play&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=play&pid=1010303184"}}
'
2025-02-09 08:34:07.016 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=play&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=play&pid=1010303184"}}
'
2025-02-09 08:34:12.629 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:34:12.631 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "", "station": "smoothjazz", "album": "", "artist": "", "image_url": "", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:34:12.633 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='', station='smoothjazz', album='', artist='', image_url='', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:34:12.726 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_state_changed': '{"heos": {"command": "event/player_state_changed", "message": "pid=1010303184&state=play"}}
'
2025-02-09 08:34:12.728 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='', station='smoothjazz', album='', artist='', image_url='', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_state_changed
2025-02-09 08:34:13.500 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:34:13.502 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Take My Heart", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Jimmy Sommers", "image_url": "http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:34:13.503 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:34:14.002 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:34:14.004 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Take My Heart", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Jimmy Sommers", "image_url": "http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:34:14.005 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:34:15.051 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1000&duration=0"}}
'
2025-02-09 08:34:15.052 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=1000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 34, 15, 51591), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:34:20.057 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=6000&duration=0"}}
'
2025-02-09 08:34:25.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=11000&duration=0"}}
'
2025-02-09 08:34:30.052 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=16000&duration=0"}}
'
2025-02-09 08:34:35.052 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=21000&duration=0"}}
'
2025-02-09 08:34:40.058 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=26000&duration=0"}}
'
2025-02-09 08:34:45.052 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=31000&duration=0"}}
'
2025-02-09 08:34:50.057 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=36000&duration=0"}}
'
2025-02-09 08:34:55.057 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=41000&duration=0"}}
'
2025-02-09 08:35:00.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=46000&duration=0"}}
'
2025-02-09 08:35:05.132 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=51000&duration=0"}}
'
2025-02-09 08:35:10.057 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=56000&duration=0"}}
'
2025-02-09 08:35:15.052 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=61000&duration=0"}}
'
2025-02-09 08:35:20.057 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=66000&duration=0"}}
'
2025-02-09 08:35:25.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=71000&duration=0"}}
'
2025-02-09 08:35:30.058 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=76000&duration=0"}}
'
2025-02-09 08:35:35.052 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=81000&duration=0"}}
'
2025-02-09 08:35:40.057 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=86000&duration=0"}}
'
2025-02-09 08:35:45.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=91000&duration=0"}}
'
2025-02-09 08:35:50.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=96000&duration=0"}}
'
2025-02-09 08:35:55.058 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=101000&duration=0"}}
'
2025-02-09 08:36:00.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=106000&duration=0"}}
'
2025-02-09 08:36:05.133 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=111000&duration=0"}}
'
2025-02-09 08:36:05.722 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=play&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=play&pid=1010303184"}}
'
2025-02-09 08:36:05.741 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=stop&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=stop&pid=1010303184"}}
'
2025-02-09 08:36:05.842 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_state_changed': '{"heos": {"command": "event/player_state_changed", "message": "pid=1010303184&state=stop"}}
'
2025-02-09 08:36:05.844 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=1000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 34, 15, 51591), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_state_changed
2025-02-09 08:36:06.347 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:36:06.348 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "192 kbps mp3", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "", "image_url": "", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:36:06.350 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='192 kbps mp3', station='1.FM Bay Smooth Jazz', album='', artist='', image_url='', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:36:06.498 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=play&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=play&pid=1010303184"}}
'
2025-02-09 08:36:08.275 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=stop&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=stop&pid=1010303184"}}
'
2025-02-09 08:36:08.303 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_state_changed': '{"heos": {"command": "event/player_state_changed", "message": "pid=1010303184&state=stop"}}
'
2025-02-09 08:36:08.304 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='192 kbps mp3', station='1.FM Bay Smooth Jazz', album='', artist='', image_url='', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_state_changed
2025-02-09 08:36:17.555 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=play&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=play&pid=1010303184"}}
'
2025-02-09 08:36:17.572 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=play&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=play&pid=1010303184"}}
'
2025-02-09 08:36:20.559 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:36:20.561 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "", "station": "smoothjazz", "album": "", "artist": "", "image_url": "", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:36:20.563 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='', station='smoothjazz', album='', artist='', image_url='', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:36:20.664 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_state_changed': '{"heos": {"command": "event/player_state_changed", "message": "pid=1010303184&state=play"}}
'
2025-02-09 08:36:20.665 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='', station='smoothjazz', album='', artist='', image_url='', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_state_changed
2025-02-09 08:36:21.453 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:36:21.455 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Take My Heart", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Jimmy Sommers", "image_url": "http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:36:21.457 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:36:21.955 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:36:21.958 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Take My Heart", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Jimmy Sommers", "image_url": "http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:36:21.958 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:36:25.058 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=3000&duration=0"}}
'
2025-02-09 08:36:25.060 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Take My Heart', station='1.FM Bay Smooth Jazz', album='', artist='Jimmy Sommers', image_url='http://cdn-albums.tunein.com/gn/ZW7T8MR01Vd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=3000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 36, 25, 58865), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:36:30.054 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=8000&duration=0"}}
'
2025-02-09 08:36:35.053 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=13000&duration=0"}}
'
2025-02-09 08:36:40.058 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=18000&duration=0"}}
'
2025-02-09 08:36:45.054 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=23000&duration=0"}}
'
2025-02-09 08:36:50.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=28000&duration=0"}}
'
2025-02-09 08:36:55.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=33000&duration=0"}}
'
2025-02-09 08:36:58.232 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:36:58.235 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "The Journey", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Nelson Rangell", "image_url": "http://cdn-albums.tunein.com/gn/JHVTM1PCMGd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:36:58.236 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='The Journey', station='1.FM Bay Smooth Jazz', album='', artist='Nelson Rangell', image_url='http://cdn-albums.tunein.com/gn/JHVTM1PCMGd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:36:58.244 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=36000&duration=0"}}
'
2025-02-09 08:36:58.245 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='The Journey', station='1.FM Bay Smooth Jazz', album='', artist='Nelson Rangell', image_url='http://cdn-albums.tunein.com/gn/JHVTM1PCMGd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=36000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 36, 58, 244663), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:37:00.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=38000&duration=0"}}
'
2025-02-09 08:37:05.133 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=43000&duration=0"}}
'
2025-02-09 08:37:10.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=48000&duration=0"}}
'
2025-02-09 08:37:15.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=53000&duration=0"}}
'
2025-02-09 08:37:20.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=58000&duration=0"}}
'
2025-02-09 08:37:25.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=63000&duration=0"}}
'
2025-02-09 08:37:30.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=68000&duration=0"}}
'
2025-02-09 08:37:35.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=73000&duration=0"}}
'
2025-02-09 08:37:40.059 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=78000&duration=0"}}
'
2025-02-09 08:37:45.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=83000&duration=0"}}
'
2025-02-09 08:37:50.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=88000&duration=0"}}
'
2025-02-09 08:37:55.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=93000&duration=0"}}
'
2025-02-09 08:38:00.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=98000&duration=0"}}
'
2025-02-09 08:38:05.136 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=103000&duration=0"}}
'
2025-02-09 08:38:10.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=108000&duration=0"}}
'
2025-02-09 08:38:15.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=113000&duration=0"}}
'
2025-02-09 08:38:20.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=118000&duration=0"}}
'
2025-02-09 08:38:25.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=123000&duration=0"}}
'
2025-02-09 08:38:30.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=128000&duration=0"}}
'
2025-02-09 08:38:35.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=133000&duration=0"}}
'
2025-02-09 08:38:40.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=138000&duration=0"}}
'
2025-02-09 08:38:45.060 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=143000&duration=0"}}
'
2025-02-09 08:38:50.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=148000&duration=0"}}
'
2025-02-09 08:38:55.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=153000&duration=0"}}
'
2025-02-09 08:39:00.062 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=158000&duration=0"}}
'
2025-02-09 08:39:05.134 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=163000&duration=0"}}
'
2025-02-09 08:39:10.063 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=168000&duration=0"}}
'
2025-02-09 08:39:15.062 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=173000&duration=0"}}
'
2025-02-09 08:39:20.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=178000&duration=0"}}
'
2025-02-09 08:39:25.062 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=183000&duration=0"}}
'
2025-02-09 08:39:30.065 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=188000&duration=0"}}
'
2025-02-09 08:39:35.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=193000&duration=0"}}
'
2025-02-09 08:39:40.061 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=198000&duration=0"}}
'
2025-02-09 08:39:45.063 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=203000&duration=0"}}
'
2025-02-09 08:39:50.062 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=208000&duration=0"}}
'
2025-02-09 08:39:55.062 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=213000&duration=0"}}
'
2025-02-09 08:40:00.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=218000&duration=0"}}
'
2025-02-09 08:40:05.131 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=223000&duration=0"}}
'
2025-02-09 08:40:10.064 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=228000&duration=0"}}
'
2025-02-09 08:40:15.065 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=233000&duration=0"}}
'
2025-02-09 08:40:20.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=238000&duration=0"}}
'
2025-02-09 08:40:25.063 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=243000&duration=0"}}
'
2025-02-09 08:40:30.064 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=248000&duration=0"}}
'
2025-02-09 08:40:35.063 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=253000&duration=0"}}
'
2025-02-09 08:40:40.064 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=258000&duration=0"}}
'
2025-02-09 08:40:45.066 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=263000&duration=0"}}
'
2025-02-09 08:40:50.066 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=268000&duration=0"}}
'
2025-02-09 08:40:55.064 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=273000&duration=0"}}
'
2025-02-09 08:41:00.066 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=278000&duration=0"}}
'
2025-02-09 08:41:05.144 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=283000&duration=0"}}
'
2025-02-09 08:41:10.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=288000&duration=0"}}
'
2025-02-09 08:41:15.064 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=293000&duration=0"}}
'
2025-02-09 08:41:20.065 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=298000&duration=0"}}
'
2025-02-09 08:41:25.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=303000&duration=0"}}
'
2025-02-09 08:41:30.069 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=308000&duration=0"}}
'
2025-02-09 08:41:35.065 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=313000&duration=0"}}
'
2025-02-09 08:41:40.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=318000&duration=0"}}
'
2025-02-09 08:41:45.069 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=323000&duration=0"}}
'
2025-02-09 08:41:50.065 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=328000&duration=0"}}
'
2025-02-09 08:41:55.069 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=333000&duration=0"}}
'
2025-02-09 08:42:00.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=338000&duration=0"}}
'
2025-02-09 08:42:05.139 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=343000&duration=0"}}
'
2025-02-09 08:42:10.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=348000&duration=0"}}
'
2025-02-09 08:42:15.069 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=353000&duration=0"}}
'
2025-02-09 08:42:20.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=358000&duration=0"}}
'
2025-02-09 08:42:25.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=363000&duration=0"}}
'
2025-02-09 08:42:30.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=368000&duration=0"}}
'
2025-02-09 08:42:35.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=373000&duration=0"}}
'
2025-02-09 08:42:40.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=378000&duration=0"}}
'
2025-02-09 08:42:45.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=383000&duration=0"}}
'
2025-02-09 08:42:50.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=388000&duration=0"}}
'
2025-02-09 08:42:55.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=393000&duration=0"}}
'
2025-02-09 08:43:00.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=398000&duration=0"}}
'
2025-02-09 08:43:02.629 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:43:02.631 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "The Journey", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "", "image_url": "https://cdn-radiotime-logos.tunein.com/s47723d.png", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:43:02.633 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='The Journey', station='1.FM Bay Smooth Jazz', album='', artist='', image_url='https://cdn-radiotime-logos.tunein.com/s47723d.png', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:43:02.642 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=400000&duration=0"}}
'
2025-02-09 08:43:02.642 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='The Journey', station='1.FM Bay Smooth Jazz', album='', artist='', image_url='https://cdn-radiotime-logos.tunein.com/s47723d.png', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=400000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 43, 2, 642229), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:43:05.138 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=403000&duration=0"}}
'
2025-02-09 08:43:10.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=408000&duration=0"}}
'
2025-02-09 08:43:15.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=413000&duration=0"}}
'
2025-02-09 08:43:20.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=418000&duration=0"}}
'
2025-02-09 08:43:25.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=423000&duration=0"}}
'
2025-02-09 08:43:30.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=428000&duration=0"}}
'
2025-02-09 08:43:32.607 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:43:32.609 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Hey Ya", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Nils", "image_url": "http://cdn-albums.tunein.com/gn/PTNW3WRZ6Hd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:43:32.611 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Hey Ya', station='1.FM Bay Smooth Jazz', album='', artist='Nils', image_url='http://cdn-albums.tunein.com/gn/PTNW3WRZ6Hd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:43:32.625 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=430000&duration=0"}}
'
2025-02-09 08:43:32.625 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Hey Ya', station='1.FM Bay Smooth Jazz', album='', artist='Nils', image_url='http://cdn-albums.tunein.com/gn/PTNW3WRZ6Hd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=430000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 43, 32, 625194), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:43:35.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=433000&duration=0"}}
'
2025-02-09 08:43:40.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=438000&duration=0"}}
'
2025-02-09 08:43:45.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=443000&duration=0"}}
'
2025-02-09 08:43:50.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=448000&duration=0"}}
'
2025-02-09 08:43:55.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=453000&duration=0"}}
'
2025-02-09 08:44:00.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=458000&duration=0"}}
'
2025-02-09 08:44:05.141 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=463000&duration=0"}}
'
2025-02-09 08:44:10.070 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=468000&duration=0"}}
'
2025-02-09 08:44:15.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=473000&duration=0"}}
'
2025-02-09 08:44:20.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=478000&duration=0"}}
'
2025-02-09 08:44:25.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=483000&duration=0"}}
'
2025-02-09 08:44:30.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=488000&duration=0"}}
'
2025-02-09 08:44:35.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=493000&duration=0"}}
'
2025-02-09 08:44:40.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=498000&duration=0"}}
'
2025-02-09 08:44:45.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=503000&duration=0"}}
'
2025-02-09 08:44:50.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=508000&duration=0"}}
'
2025-02-09 08:44:55.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=513000&duration=0"}}
'
2025-02-09 08:45:00.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=518000&duration=0"}}
'
2025-02-09 08:45:05.136 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=523000&duration=0"}}
'
2025-02-09 08:45:10.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=528000&duration=0"}}
'
2025-02-09 08:45:15.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=533000&duration=0"}}
'
2025-02-09 08:45:20.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=538000&duration=0"}}
'
2025-02-09 08:45:25.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=543000&duration=0"}}
'
2025-02-09 08:45:30.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=548000&duration=0"}}
'
2025-02-09 08:45:35.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=553000&duration=0"}}
'
2025-02-09 08:45:40.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=558000&duration=0"}}
'
2025-02-09 08:45:45.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=563000&duration=0"}}
'
2025-02-09 08:45:50.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=568000&duration=0"}}
'
2025-02-09 08:45:55.071 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=573000&duration=0"}}
'
2025-02-09 08:46:00.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=578000&duration=0"}}
'
2025-02-09 08:46:05.137 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=583000&duration=0"}}
'
2025-02-09 08:46:10.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=588000&duration=0"}}
'
2025-02-09 08:46:15.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=593000&duration=0"}}
'
2025-02-09 08:46:20.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=598000&duration=0"}}
'
2025-02-09 08:46:25.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=603000&duration=0"}}
'
2025-02-09 08:46:30.074 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=608000&duration=0"}}
'
2025-02-09 08:46:35.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=614000&duration=0"}}
'
2025-02-09 08:46:40.072 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=618000&duration=0"}}
'
2025-02-09 08:46:45.074 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=623000&duration=0"}}
'
2025-02-09 08:46:50.074 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=629000&duration=0"}}
'
2025-02-09 08:46:55.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=633000&duration=0"}}
'
2025-02-09 08:47:00.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=639000&duration=0"}}
'
2025-02-09 08:47:05.141 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=643000&duration=0"}}
'
2025-02-09 08:47:10.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=649000&duration=0"}}
'
2025-02-09 08:47:15.073 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=654000&duration=0"}}
'
2025-02-09 08:47:20.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=659000&duration=0"}}
'
2025-02-09 08:47:25.074 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=664000&duration=0"}}
'
2025-02-09 08:47:30.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=669000&duration=0"}}
'
2025-02-09 08:47:35.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=674000&duration=0"}}
'
2025-02-09 08:47:40.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=679000&duration=0"}}
'
2025-02-09 08:47:45.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=684000&duration=0"}}
'
2025-02-09 08:47:50.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=689000&duration=0"}}
'
2025-02-09 08:47:55.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=694000&duration=0"}}
'
2025-02-09 08:48:00.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=699000&duration=0"}}
'
2025-02-09 08:48:05.135 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=704000&duration=0"}}
'
2025-02-09 08:48:10.074 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=709000&duration=0"}}
'
2025-02-09 08:48:15.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=714000&duration=0"}}
'
2025-02-09 08:48:20.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=719000&duration=0"}}
'
2025-02-09 08:48:25.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=724000&duration=0"}}
'
2025-02-09 08:48:25.513 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:48:25.515 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Dear Jacqui", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Tim Heintz", "image_url": "http://cdn-albums.tunein.com/gn/R962L8R80Gd.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:48:25.518 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Dear Jacqui', station='1.FM Bay Smooth Jazz', album='', artist='Tim Heintz', image_url='http://cdn-albums.tunein.com/gn/R962L8R80Gd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:48:25.524 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=724000&duration=0"}}
'
2025-02-09 08:48:25.525 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Dear Jacqui', station='1.FM Bay Smooth Jazz', album='', artist='Tim Heintz', image_url='http://cdn-albums.tunein.com/gn/R962L8R80Gd.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=724000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 48, 25, 525074), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:48:30.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=729000&duration=0"}}
'
2025-02-09 08:48:35.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=734000&duration=0"}}
'
2025-02-09 08:48:40.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=739000&duration=0"}}
'
2025-02-09 08:48:45.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=744000&duration=0"}}
'
2025-02-09 08:48:50.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=749000&duration=0"}}
'
2025-02-09 08:48:55.075 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=754000&duration=0"}}
'
2025-02-09 08:49:00.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=759000&duration=0"}}
'
2025-02-09 08:49:05.131 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=764000&duration=0"}}
'
2025-02-09 08:49:10.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=768000&duration=0"}}
'
2025-02-09 08:49:15.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=773000&duration=0"}}
'
2025-02-09 08:49:20.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=778000&duration=0"}}
'
2025-02-09 08:49:25.078 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=783000&duration=0"}}
'
2025-02-09 08:49:30.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=788000&duration=0"}}
'
2025-02-09 08:49:35.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=793000&duration=0"}}
'
2025-02-09 08:49:40.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=798000&duration=0"}}
'
2025-02-09 08:49:45.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=803000&duration=0"}}
'
2025-02-09 08:49:50.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=808000&duration=0"}}
'
2025-02-09 08:49:55.076 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=813000&duration=0"}}
'
2025-02-09 08:50:00.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=818000&duration=0"}}
'
2025-02-09 08:50:05.140 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=824000&duration=0"}}
'
2025-02-09 08:50:10.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=828000&duration=0"}}
'
2025-02-09 08:50:15.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=833000&duration=0"}}
'
2025-02-09 08:50:20.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=838000&duration=0"}}
'
2025-02-09 08:50:25.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=843000&duration=0"}}
'
2025-02-09 08:50:30.078 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=848000&duration=0"}}
'
2025-02-09 08:50:35.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=853000&duration=0"}}
'
2025-02-09 08:50:40.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=858000&duration=0"}}
'
2025-02-09 08:50:45.077 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=863000&duration=0"}}
'
2025-02-09 08:50:50.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=868000&duration=0"}}
'
2025-02-09 08:50:55.078 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=873000&duration=0"}}
'
2025-02-09 08:51:00.080 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=878000&duration=0"}}
'
2025-02-09 08:51:05.134 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=883000&duration=0"}}
'
2025-02-09 08:51:10.078 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=888000&duration=0"}}
'
2025-02-09 08:51:15.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=893000&duration=0"}}
'
2025-02-09 08:51:20.080 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=898000&duration=0"}}
'
2025-02-09 08:51:25.080 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=903000&duration=0"}}
'
2025-02-09 08:51:30.096 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=908000&duration=0"}}
'
2025-02-09 08:51:35.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=913000&duration=0"}}
'
2025-02-09 08:51:40.078 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=918000&duration=0"}}
'
2025-02-09 08:51:45.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=923000&duration=0"}}
'
2025-02-09 08:51:50.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=928000&duration=0"}}
'
2025-02-09 08:51:55.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=933000&duration=0"}}
'
2025-02-09 08:52:00.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=938000&duration=0"}}
'
2025-02-09 08:52:05.138 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=943000&duration=0"}}
'
2025-02-09 08:52:10.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=948000&duration=0"}}
'
2025-02-09 08:52:15.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=953000&duration=0"}}
'
2025-02-09 08:52:20.080 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=958000&duration=0"}}
'
2025-02-09 08:52:25.080 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=963000&duration=0"}}
'
2025-02-09 08:52:30.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=968000&duration=0"}}
'
2025-02-09 08:52:35.080 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=973000&duration=0"}}
'
2025-02-09 08:52:40.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=978000&duration=0"}}
'
2025-02-09 08:52:45.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=983000&duration=0"}}
'
2025-02-09 08:52:50.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=988000&duration=0"}}
'
2025-02-09 08:52:55.079 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=993000&duration=0"}}
'
2025-02-09 08:53:00.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=998000&duration=0"}}
'
2025-02-09 08:53:05.135 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1003000&duration=0"}}
'
2025-02-09 08:53:10.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1008000&duration=0"}}
'
2025-02-09 08:53:14.330 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:53:14.332 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/get_now_playing_media?pid=1010303184': '{"heos": {"command": "player/get_now_playing_media", "result": "success", "message": "pid=1010303184"}, "payload": {"type": "station", "song": "Dedication", "station": "1.FM Bay Smooth Jazz", "album": "", "artist": "Boney James", "image_url": "http://cdn-albums.tunein.com/gn/Z5KVZKQ7Q4d.jpg", "album_id": "s47723", "mid": "http://www.1.fm/tunestream/smoothjazz/listen.pls", "qid": 1, "sid": 3}, "options": [{"play": [{"id": 19, "name": "Add to HEOS Favorites"}]}]}
'
2025-02-09 08:53:14.333 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Dedication', station='1.FM Bay Smooth Jazz', album='', artist='Boney James', image_url='http://cdn-albums.tunein.com/gn/Z5KVZKQ7Q4d.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=None, current_position_updated=None, duration=None, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_changed
2025-02-09 08:53:14.340 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1013000&duration=0"}}
'
2025-02-09 08:53:14.341 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.PLAY: 'play'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Dedication', station='1.FM Bay Smooth Jazz', album='', artist='Boney James', image_url='http://cdn-albums.tunein.com/gn/Z5KVZKQ7Q4d.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=1013000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 53, 14, 340628), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_now_playing_progress
2025-02-09 08:53:20.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1018000&duration=0"}}
'
2025-02-09 08:53:25.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1023000&duration=0"}}
'
2025-02-09 08:53:30.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1028000&duration=0"}}
'
2025-02-09 08:53:35.084 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1033000&duration=0"}}
'
2025-02-09 08:53:40.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1038000&duration=0"}}
'
2025-02-09 08:53:45.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1043000&duration=0"}}
'
2025-02-09 08:53:50.084 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1048000&duration=0"}}
'
2025-02-09 08:53:55.081 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1053000&duration=0"}}
'
2025-02-09 08:54:00.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1058000&duration=0"}}
'
2025-02-09 08:54:05.139 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1063000&duration=0"}}
'
2025-02-09 08:54:10.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1068000&duration=0"}}
'
2025-02-09 08:54:15.082 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1073000&duration=0"}}
'
2025-02-09 08:54:20.085 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1078000&duration=0"}}
'
2025-02-09 08:54:25.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1083000&duration=0"}}
'
2025-02-09 08:54:30.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1088000&duration=0"}}
'
2025-02-09 08:54:35.084 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1093000&duration=0"}}
'
2025-02-09 08:54:40.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1098000&duration=0"}}
'
2025-02-09 08:54:45.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1103000&duration=0"}}
'
2025-02-09 08:54:50.086 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1108000&duration=0"}}
'
2025-02-09 08:54:55.083 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1113000&duration=0"}}
'
2025-02-09 08:55:00.085 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1118000&duration=0"}}
'
2025-02-09 08:55:05.139 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1123000&duration=0"}}
'
2025-02-09 08:55:10.084 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1128000&duration=0"}}
'
2025-02-09 08:55:15.084 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1133000&duration=0"}}
'
2025-02-09 08:55:20.105 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1138000&duration=0"}}
'
2025-02-09 08:55:25.085 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1143000&duration=0"}}
'
2025-02-09 08:55:30.085 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1148000&duration=0"}}
'
2025-02-09 08:55:35.086 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1153000&duration=0"}}
'
2025-02-09 08:55:40.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1158000&duration=0"}}
'
2025-02-09 08:55:45.085 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1163000&duration=0"}}
'
2025-02-09 08:55:50.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1168000&duration=0"}}
'
2025-02-09 08:55:55.086 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1173000&duration=0"}}
'
2025-02-09 08:56:00.086 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1178000&duration=0"}}
'
2025-02-09 08:56:05.142 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1183000&duration=0"}}
'
2025-02-09 08:56:10.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1188000&duration=0"}}
'
2025-02-09 08:56:15.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1193000&duration=0"}}
'
2025-02-09 08:56:20.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1198000&duration=0"}}
'
2025-02-09 08:56:25.089 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1203000&duration=0"}}
'
2025-02-09 08:56:30.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1208000&duration=0"}}
'
2025-02-09 08:56:35.089 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1213000&duration=0"}}
'
2025-02-09 08:56:40.088 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1218000&duration=0"}}
'
2025-02-09 08:56:45.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1223000&duration=0"}}
'
2025-02-09 08:56:50.087 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1228000&duration=0"}}
'
2025-02-09 08:56:55.091 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_progress': '{"heos": {"command": "event/player_now_playing_progress", "message": "pid=1010303184&cur_pos=1233000&duration=0"}}
'
2025-02-09 08:56:59.567 DEBUG (MainThread) [pyheos.connection] Command executed 'heos://player/set_play_state?state=stop&pid=1010303184': '{"heos": {"command": "player/set_play_state", "result": "success", "message": "state=stop&pid=1010303184"}}
'
2025-02-09 08:56:59.670 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_state_changed': '{"heos": {"command": "event/player_state_changed", "message": "pid=1010303184&state=stop"}}
'
2025-02-09 08:56:59.671 DEBUG (MainThread) [pyheos.heos] Event received for player HeosPlayer(name='Small Denon', player_id=1010303184, model='HEOS 1', version='3.34.620', ip_address='192.168.1.21', state=<PlayState.STOP: 'stop'>, now_playing_media=HeosNowPlayingMedia(type=<MediaType.STATION: 'station'>, song='Dedication', station='1.FM Bay Smooth Jazz', album='', artist='Boney James', image_url='http://cdn-albums.tunein.com/gn/Z5KVZKQ7Q4d.jpg', album_id='s47723', media_id='http://www.1.fm/tunestream/smoothjazz/listen.pls', queue_id=1, source_id=3, current_position=1013000, current_position_updated=datetime.datetime(2025, 2, 9, 8, 53, 14, 340628), duration=0, supported_controls=[<ControlType.PLAY: 'play'>, <ControlType.STOP: 'stop'>])): event/player_state_changed
2025-02-09 08:57:00.170 DEBUG (MainThread) [pyheos.connection] Event received: 'event/player_now_playing_changed': '{"heos": {"command": "event/player_now_playing_changed", "message": "pid=1010303184"}}
'
2025-02-09 08:57:00.170 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 61, in _on_event
    await callback(message)
  File "/usr/local/lib/python3.13/site-packages/pyheos/heos.py", line 218, in _on_event
    await self._on_event_player(event)
  File "/usr/local/lib/python3.13/site-packages/pyheos/heos.py", line 250, in _on_event_player
    await player._on_event(event, self._options.all_progress_events)
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 275, in _on_event
    await self.refresh_now_playing_media()
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 327, in refresh_now_playing_media
    await self.heos.get_now_playing_media(self.player_id, self.now_playing_media)
  File "/usr/local/lib/python3.13/site-packages/pyheos/command/player.py", line 185, in get_now_playing_media
    result = await self._connection.command(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        HeosCommand(c.COMMAND_GET_NOW_PLAYING_MEDIA, {c.ATTR_PLAYER_ID: player_id})
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError
2025-02-09 08:57:04.253 ERROR (MainThread) [homeassistant.components....] ...: Choose at step 1: choice 1: Error executing script. Unexpected error for call_service at pos 1: 
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 526, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 762, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<9 lines>...
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 727, in _async_run_long_action
    return await long_task
           ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2794, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2837, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1007, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
        hass, entity, func, data, call.context
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1079, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/heos/media_player.py", line 114, in wrapper
    await func(*args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/heos/media_player.py", line 227, in async_media_play
    await self._player.play()
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 353, in play
    await self.set_state(PlayState.PLAY)
  File "/usr/local/lib/python3.13/site-packages/pyheos/player.py", line 349, in set_state
    await self.heos.player_set_play_state(self.player_id, state)
  File "/usr/local/lib/python3.13/site-packages/pyheos/command/player.py", line 164, in player_set_play_state
    await self._connection.command(
    ...<4 lines>...
    )
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 219, in command
    return await _command_impl()
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/pyheos/connection.py", line 168, in _command_impl
    assert not self._pending_command_event.is_set()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

@andrewsayre andrewsayre mentioned this issue Feb 9, 2025
Merged
5 tasks
@andrewsayre
Copy link
Owner

Thanks for the additional logs. It's possible that the device is sending a duplicate response, though I've never seen that myself. Events wouldn't affect this (those can/are expected to come in at any time, even while a command is in-process).

#100 addresses the issue scenario I described above. I believe it will also fix your scenario too (however it's occurring) as it will now discard (and log) a command response received out of band.

@andrewsayre andrewsayre removed the triage Bug has been reported but not evaluated label Feb 9, 2025
@andrewsayre andrewsayre mentioned this issue Feb 10, 2025
Merged
19 tasks
@andrewsayre
Copy link
Owner

This should be fixed in HA 2025.02.02 coming out this Friday 2/24/2025. Please let me know if it solves it, otherwise open a new issue (as there will be new/better logging for what's going on). Thank you!

@imbaczek
Copy link
Author

Rest assured will test asap!

@andrewsayre
Copy link
Owner

Looks like 2025.02.02 came early! The updated library shipped with that, so give it a shot!

@imbaczek
Copy link
Author

Worked fine for the past 24h. Thanks again!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix handling of command timeouts andrewsayre/pyheos
2 participants
@imbaczek @andrewsayre