Pyatv: Incorrect state for com.apple.TVMusic

[OGKevin]

Describe the bug
When com.apple.TVMusic is (last) active it seems that the state in home assistant is not updated correctly. However when manually calling services to play/pause/skip etc these work fine, just the reported state is incorrect. From the logs, I can see that the commands have been executed successfully, the state Is just not updated.

I'm not sure if this might have something to do with #812 tho, as the user experience described in there has some overlaps.

To Reproduce
Play music from TVMusic(Apple Music)

Expected behavior
Status is updated accordingly.

System Setup (please complete the following information):

• OS: "Alpine Linux v3.12"
• Python: Python 3.8.5
• pyatv: 0.7.2
  
  
  
  • Apple TV: ATV & ATV4K TVOS 14.0
  
  

Additional context

ATV4K:

Logs

2020-09-26 21:10:41 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.1.63:58344<->192.168.1.42:49153 << Receive: Protobuf: type: SET_STATE_MESSAGE
errorCode: NoError
[setStateMessage] {
  playbackQueue {
    location: 0
    contentItems {
      identifier: "souYYlzPRlCNnyEgyU8/qA\342\210\206kj+qLO8bRaeAu3l4LeIcsg"
      metadata {
        title: "Extroverted Lovers"
        isPlayable: true
        albumName: "Extroverted Lovers - Single"
        trackArtistName: "Jvck James"
        duration: 222.93478458049887
        artworkAvailable: true
        lyricsAvailable: true
        editingStyleFlags: 3
        elapsedTime: -0.389768556
        genre: "R&B/Soul"
        playbackRate: 1.0
        radioStationName: "7AM - Single station"
        radioStationString: "ra.cp-1527268252"
        iTunesStoreIdentifier: 1206533289
        iTunesStoreSubscriptionIdentifier: 1206533289
        iTunesStoreArtistIdentifier: 1206533286
        iTunesStoreAlbumIdentifier: 1206533209
        defaultPlaybackRate: 1.0
        mediaType: Audio
        mediaSubType: Music
        userInfoData: "EXLCUDED"
        artworkURL: "https://is1-ssl.mzstatic.com/image/thumb/Music111/v4/50/8a/8d/508a8d05-b25d-ae23-c09c-f0fab76844b6/artwork.jpg/1200x1200bb.jpg"
        deviceSpecificUserInfoData: "EXLCUDED"
        collectionInfoData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedArchive...
        elapsedTimeTimestamp: 622840240.87658
        artworkIdentifier: "https://is1-ssl.mzstatic.com/image/thumb/Music111/v4/50/8a/8d/508a8d05-b25d-ae23-c09c-f0fab76844b6/artwork.jpg/{w}x{h}{...
        artworkURLTemplatesData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedAr...
        legacyUniqueIdentifier: 1206533289
        88: "0"
      }
    }
    queueIdentifier: "32DA2EA7-FE7D-417F-9777-C6D536C6F823"
  }
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Living Room"
      identifier: 1280262988
    }
    client {
      processIdentifier: 436
      bundleIdentifier: "com.apple.TVMusic"
    }
    player {
      identifier: "Music"
    }
  }
}
85: "F25C84CA-E10C-4D1E-BCDE-55784328C147"

ATV (Included some command logs as well) :

Logs

2020-09-26 21:19:27 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.1.63:60242<->192.168.1.45:49154 << Receive: Protobuf: type: SET_STATE_MESSAGE
errorCode: NoError
[setStateMessage] {
  playbackQueue {
    location: 0
    contentItems {
      identifier: "LwPKGb+eRSOjL+xJUKaSyA\342\210\206i037G282RreWzEqugK3eNA"
      metadata {
        title: "Control"
        isPlayable: true
        albumName: "Control - Single"
        trackArtistName: "Jay Silva"
        albumArtistName: "Jay Silva"
        duration: 231.41006802721088
        artworkAvailable: true
        editingStyleFlags: 3
        elapsedTime: -0.388159582
        genre: "R&B/Soul"
        playbackRate: 1.0
        totalTrackCount: 1
        trackNumber: 1
        iTunesStoreIdentifier: 1523337750
        iTunesStoreSubscriptionIdentifier: 1523337750
        iTunesStoreArtistIdentifier: 1425868027
        iTunesStoreAlbumIdentifier: 1523337634
        defaultPlaybackRate: 1.0
        mediaType: Audio
        mediaSubType: Music
        nowPlayingInfoData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedArchive...
        userInfoData: "EXLCUDED".
        deviceSpecificUserInfoData: "EXLCUDED"
        collectionInfoData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedArchive...
        elapsedTimeTimestamp: 622840766.849977
        artworkIdentifier: "Music124/v4/02/d7/3e/02d73e84-1d59-b240-0448-8b4783d6ae6f/5059580080525_cover.jpg"
        isLoading: false
        legacyUniqueIdentifier: 2835798934449945044
        88: "2020"
      }
    }
    queueIdentifier: "F3EBB27D-0E7D-4430-BBE2-0AE5D4770FAA"
  }
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 833
      bundleIdentifier: "com.apple.TVMusic"
    }
    player {
      identifier: "Music"
    }
  }
}
85: "36AA7845-BFD6-4467-9D2C-C89F14710D9E"

2020-09-26 21:46:48 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.1.63:60242<->192.168.1.45:49154 >> Send: Protobuf: type: SEND_COMMAND_MESSAGE
identifier: "0b880ec1-9f6a-438f-a8db-d2f47c0a4bfd"
errorCode: NoError
[sendCommandMessage] {
  command: PreviousTrack
}

2020-09-26 21:48:43 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.1.63:60242<->192.168.1.45:49154 << Receive: Protobuf: type: SET_STATE_MESSAGE
errorCode: NoError
[setStateMessage] {
  playbackState: Playing
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 833
      bundleIdentifier: "com.apple.TVMusic"
    }
    player {
      identifier: "Music"
    }
  }
  playbackStateTimestamp: 622842523.702524
}

[fantomnotabene]

I think it's related

Logger: homeassistant
Source: custom_components/apple_tv/media_player.py:103 
First occurred: 2:57:00 (2 occurrences) 
Last logged: 10:26:38

Error doing job: Exception in callback AppleTvDevice.playstatus_error(<pyatv.mrp.Mr...at 0x66a19f10>, KeyError('com.apple.TVMusic'))
Error doing job: Exception in callback AppleTvDevice.playstatus_error(<pyatv.mrp.Mr...at 0x66a19f10>, KeyError('com...le.TVAirPlay'))
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/config/custom_components/apple_tv/media_player.py", line 160, in playstatus_error
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 296, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 322, in _async_write_ha_state
    attr.update(self.state_attributes or {})
  File "/usr/src/homeassistant/homeassistant/components/media_player/__init__.py", line 809, in state_attributes
    value = getattr(self, attr)
  File "/config/custom_components/apple_tv/media_player.py", line 103, in app_id
    if self.atv.features.in_state(FeatureState.Available, FeatureName.App):
  File "/usr/local/lib/python3.8/site-packages/pyatv/interface.py", line 794, in in_state
    feature = self.get_feature(name)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 652, in get_feature
    player_path = self.psm.playing.player_path
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/player_state.py", line 159, in playing
    return self.states[self.active]
KeyError: 'com.apple.TVMusic'

[postlund]

I will have a look at this soon. I have found a thing that seems to be different in tvOS 14 which makes the device not push application states during connection set up. So it's likely that the problem occurs because the initial state has not been pushed yet.

[postlund]

I will try to make a minor release with the mentioned fix (see #849 for details) tomorrow and bump version in the component. After that you can try it out.

[postlund]

New update is out now, can you verify it works @OGKevin?

[OGKevin]

@postlund I'll give it a try tonight 👍

[fantomnotabene]

If you play music via default app, then run another app and start playing something there, then set aTV to sleep, state in HA will be not idle, but paused with Apple Music's track info
0.7.3 isn't fixing this behaviour
Maybe info for another issue (not related to Apple Music, but to incorrect state):
When you get back from sleep (by pressing menu button on the physical remote), state in HA remains idle until you press play button

[postlund]

@fantomnotabene Sounds like a different issue. Can you write a new issue and include some logs? Probably reproducible with atvremote if you want to use that instead.

[OGKevin]

Can confirm that its fixed 👍

[postlund]

Thanks for verifying! 👍