search

owntone / owntone-server

Linux/FreeBSD DAAP (iTunes) and MPD audio server with support for AirPlay 1 and 2 speakers (multiroom), Apple Remote (and compatibles), Chromecast, Spotify and internet radio.
https://owntone.github.io/owntone-server
GNU General Public License v2.0
2.09k stars 237 forks source link

Amazon Music -> Shairport-Sync + Metadata -> OT only shows first song played and never updates after that song ends #1358

Closed derekatkins closed 2 years ago

derekatkins commented 2 years ago

I was using Amazon Music on a Mac to drive OwnTone via Shairport-Sync. I have the metadata pipe enabled.

When I start AmazonMusic and send the output to SP-S that sits in front of OT, I get the metadata for the first song. During that first song I get a progress bar and everything. However, I never get anything for any subsequent songs. The OT UI always shows that first song and never updates after that song ends.

If I pause play and way for a bit, when I restart play of Amazon Music, I get the Source is not providing sufficient data, temporarily suspending playback error, and then if I try to play again it fails and falls back to Internal speakers; when I restart Airplay to Whole House it sends the current metadata over (song title/artist/playtime).

If I click into the metadata popup on the OT WebUI, right now it's actually still counting up. So it's displaying the "first" song title and length, but it says "6:01 / 3:54" (and the "6:01" is counting up as the next song goes).

If I pause play, count to three, and then restart (so it doesn't empty the pipe), the music pauses for a bit but the metadata doesn't update to the new song (but it does keep counting up).

Similar to my other issue, is there a good way to turn on metadata debugging to get OT to print out the metadata it's receiving?

ejurgensen commented 2 years ago

This seems mostly related to the metadata pipe. As mentioned in issue #1357 the implementation of the metadata pipe has changed since 28.2, so I would have to ask you to try updating to that.

derekatkins commented 2 years ago

Okay, I'll try to do that.. Which of course means I need to figure out how to rebuild the RPM from git instead of a release tarball (unless there is a 28.3 coming "soon") ;-)

derekatkins commented 2 years ago

As I mentioned in #1357 the master tarball appears to solve the metadata overload issue. However this issue is still there, so I need to turn up the logging, which I've just done. I'll let you know what I see shortly.

derekatkins commented 2 years ago

Hmm. I set loglevel = spam but I'm not seeing anything metadata related in the log? Indeed, I didn't see ANYTHING in the log, at least until I disconnected from shairport (change the target from whole house to internal speakers), wait 10 seconds or so, then reconnect back to shairport whole house. Now I'm seeing lots of stuff in the log:

[root@owntone ~]# grep -i metadata /var/log/messages
...
Nov 29 11:34:37 owntone owntone[9501]: [2021-11-29 11:34:37] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=aend, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=snua, len=13)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=acre, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=daid, len=16)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=clip, len=15)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=svip, len=14)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=abeg, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pbeg, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pvol, len=21)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=ssnc, code=pvol, len=21)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pvol, len=21)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=ssnc, code=pvol, len=21)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pffr, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=prsm, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pcst, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=PICT, len=49390)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=ssnc, code=PICT, len=49390)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pcen, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pfls, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=ssnc, code=pfls, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=prgr, len=32)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=ssnc, code=prgr, len=32)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Received Shairport metadata progress: 1706683234/1711257912/1717486557 => 103734/244973 ms
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=mdst, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=mper, len=8)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=asal, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Missing or pending Shairport metadata payload (type=core, code=asal, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=asar, len=20)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=core, code=asar, len=20)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=ascp, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=asgn, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Missing or pending Shairport metadata payload (type=core, code=asgn, len=0)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=minm, len=43)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [DEBUG]   player: Applying Shairport metadata (type=core, code=minm, len=43)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=asdk, len=1)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=caps, len=1)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=core, code=astm, len=4)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=mden, len=10)
Nov 29 11:35:19 owntone owntone[9501]: [2021-11-29 11:35:19] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=pffr, len=0)
Nov 29 11:35:20 owntone owntone[9501]: [2021-11-29 11:35:20] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=dapo, len=5)
Nov 29 11:35:20 owntone owntone[9501]: [2021-11-29 11:35:20] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=dapo, len=5)
Nov 29 11:35:20 owntone owntone[9501]: [2021-11-29 11:35:20] [ SPAM]   player: Read Shairport metadata (type=ssnc, code=prsm, len=0)
Nov 29 11:35:21 owntone owntone[9501]: [2021-11-29 11:35:21] [DEBUG]   player: event_read_metadata()
Nov 29 11:35:21 owntone owntone[9501]: [2021-11-29 11:35:21] [DEBUG]   player: event_read_metadata()
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [DEBUG]   player: event_play_metadata()
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [DEBUG]   player: Status update - status: 4, events: 1, caller: metadata_finalize
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [ SPAM]  artwork: Trying pipe metadata from /srv/whole_house/shairport-sync.metadata
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [ SPAM]  artwork: Trying pipe metadata from /srv/whole_house/shairport-sync.metadata
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [DEBUG]   player: event_play_metadata()
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [DEBUG]   player: Status update - status: 4, events: 1, caller: metadata_finalize
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [ SPAM]  artwork: Trying pipe metadata from /srv/whole_house/shairport-sync.metadata
Nov 29 11:35:23 owntone owntone[9501]: [2021-11-29 11:35:23] [ SPAM]  artwork: Trying pipe metadata from /srv/whole_house/shairport-sync.metadata
Nov 29 11:35:31 owntone dnf[9545]: Metadata cache refreshed recently.
Nov 29 11:35:42 owntone owntone[9501]: [2021-11-29 11:35:42] [ SPAM]  artwork: Trying pipe metadata from /srv/whole_house/shairport-sync.metadata
[root@owntone ~]# tail -f /var/log/messages | grep -i metadata

But now I don't see anything more. SO.. Either shairport isn't sending anymore metadata, or something else is going on. Indeed, just running:

[root@owntone ~]# tail -f /var/log/messages
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'
Nov 29 11:38:29 owntone owntone[9501]: [2021-11-29 11:38:29] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=29'

... and that's the end, which is from 3 minutes ago, even though music is playing right now through the system and the metadata page in the OT shows 7:54/4:05 (and counting).

I sat there for a while and eventually (without me doing anything) the logging continued:

Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]   player: Player status: playing
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]       db: Starting enum 'SELECT * FROM queue f WHERE id = 117 ORDER BY pos;'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]       db: Running query 'END TRANSACTION;'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=33'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
Nov 29 11:44:33 owntone owntone[9501]: [2021-11-29 11:44:33] [DEBUG]   player: Player status: playing
...

But no metadata in these logs, even though there was yet another song change.

derekatkins commented 2 years ago

One more piece of added information: If I stream Amazon Music my wife's iPhone then the metadata updates properly across songs, so it's probably on the source side and not on the OT side. Although that still doesn't explain why logging stops for 6 minutes.

ejurgensen commented 2 years ago

You can verify whether OwnTone is reading and processing metadata correctly by simply writing to the metadata pipe like shairport-sync does. You can, for instance, run this command, which will change the title (provided OwnTone is playing the associated audio pipe):

echo "<item><type>636f7265</type><code>6d696e6d</code><length>10</length><data encoding="base64">UGFwaXJza2xpcA==</data></item>" > /path/to/pipe.metadata

I will close the issue for now, but let me know if there is an issue on OwnTone's receiving end.

derekatkins commented 2 years ago

I wonder if there is an incompatibility somewhere. I'm doing: cat shairport-sync.metadata | shairport-sync-metadata-reader and I get the following output:

"ssnc" "acre": "4052385387".
"ssnc" "daid": "FF356E4A0C4F0251".
"ssnc" "abeg": "".
"ssnc" "pbeg": "".
"ssnc" "pvol": "-18.00,0.00,-96.30,0.00".
"ssnc" "dapo": "62649".
"ssnc" "dapo": "62649".
"ssnc" "pcst": "1074946012".
Picture received, length 53504 bytes.
"ssnc" "pcen": "1074946012".
"ssnc" "flsr": "1075041051".
"ssnc" "prgr": "1072823093/1074999439/1081230444".
"ssnc" "mdst": "1074999439".
Persistent ID: "be3e0c1cb312f0e0".
Album Name: "".
Artist: "Maroon 5".
Composer: "".
Genre: "".
Title: "Wait".
"ssnc" "mden": "1074999439".
"ssnc" "mdst": "1074999439".
Persistent ID: "be3e0c1cb312f0e0".
Album Name: "".
Artist: "Maroon 5".
Composer: "".
Genre: "".
Title: "Wait".
"ssnc" "mden": "1074999439".
"ssnc" "prgr": "1072822312/1074999439/1081229663".
"ssnc" "pffr": "".
"ssnc" "prsm": "".
"ssnc" "mdst": "1075032175".
Persistent ID: "be3e0c1cb312f0e0".
Album Name: "".
Artist: "Maroon 5".
Composer: "".
Genre: "".
Title: "Wait".
"ssnc" "mden": "1075032175".
"ssnc" "prgr": "1072887752/1075032175/1081295103".
"ssnc" "pvol": "-11.43,0.00,-96.30,0.00".
"ssnc" "mdst": "1081316431".
Persistent ID: "0".
Album Name: "".
Artist: "".
Composer: "".
Genre: "".
Title: "".
"ssnc" "mden": "1081316431".
"ssnc" "pcst": "1081317487".
Picture received, length 0 bytes.
"ssnc" "pcen": "1081317487".
"ssnc" "mdst": "1081342127".
Persistent ID: "bd7531cc0c98ff15".
Album Name: "".
Artist: "Ed Sheeran".
Composer: "".
Genre: "".
Title: "Bad Habits".
"ssnc" "mden": "1081342127".
"ssnc" "prgr": "1081339624/1081342127/1091520550".
"ssnc" "pcst": "1081342127".
Picture received, length 88353 bytes.
"ssnc" "pcen": "1081342127".
"ssnc" "mdst": "1081420975".
Persistent ID: "bd7531cc0c98ff15".
Album Name: "".
Artist: "Ed Sheeran".
Composer: "".
Genre: "".
Title: "Bad Habits".
"ssnc" "mden": "1081420975".
"ssnc" "prgr": "1081364073/1081420975/1091540001".
"ssnc" "mdst": "1081433295".
Persistent ID: "bd7531cc0c98ff15".
Album Name: "".
Artist: "Ed Sheeran".
Composer: "".
Genre: "".
Title: "Bad Habits".
"ssnc" "mden": "1081433295".
"ssnc" "prgr": "1081425252/1081433295/1091601180".
"ssnc" "mdst": "1091602575".
Persistent ID: "0".
Album Name: "".
Artist: "".
Composer: "".
Genre: "".
Title: "".
"ssnc" "mden": "1091602575".
"ssnc" "pcst": "1091608559".
Picture received, length 0 bytes.
"ssnc" "pcen": "1091608559".
"ssnc" "mdst": "1091628271".
Persistent ID: "1c334d4de696d1a7".
Album Name: "".
Artist: "Bruno Mars".
Composer: "".
Genre: "".
Title: "When I Was Your Man".
"ssnc" "mden": "1091628271".
"ssnc" "prgr": "1091625864/1091628271/1101060618".
"ssnc" "pcst": "1091628271".
Picture received, length 56943 bytes.
"ssnc" "pcen": "1091628271".
"ssnc" "mdst": "1091678255".
Persistent ID: "1c334d4de696d1a7".
Album Name: "".
Artist: "Bruno Mars".
Composer: "".
Genre: "".
Title: "When I Was Your Man".
"ssnc" "mden": "1091678255".
"ssnc" "prgr": "1091650513/1091679311/1101080268".
"ssnc" "mdst": "1091696911".
Persistent ID: "1c334d4de696d1a7".
Album Name: "".
Artist: "Bruno Mars".
Composer: "".
Genre: "".
Title: "When I Was Your Man".
"ssnc" "mden": "1091696911".
"ssnc" "prgr": "1091688600/1091696911/1101118355".

This shows me that there is a change... I can see the change from Wait to Bad Habits to When I Was Your Man, but OT isn't reading it or updating itself with the data.. I wonder if the metadata changed between Airplay1 and Airplay2? Let me capture some raw data and upload it manually and see what happens...

derekatkins commented 2 years ago

UGGH.... So it worked manually... And then I restarted shairport-sync and it's all working now... UGGH!

ejurgensen commented 2 years ago

Are you using a permanent pipe or is shairport-sync creating it on the fly? If it is the latter, do you then know when the pipe is created? I'm thinking if there could be a timing issue, i.e. 1) sps start writing audio, 2) ot detects audio, looks for metadata pipe, doesn't find one, 3) sps creates metadata pipe --> too late.

derekatkins commented 2 years ago

I've tried it both ways. While it could be a race condition, I suspect it's something else...

MikeBrady suggested that it might have been an issue going between AP1 and AP2. It's certainly the case that AP1 only supports metadata when the stream starts; updating in-stream is an AP2 feature. However when I first started testing with AP2 it hadn't changed behavior, but then I stopped testing for a while (several hours) and when I came back to it, it worked. So the current theory is that the Mac was caching info about the AP endpoint and had to wait for the cached data to expire before it acknowledged that the endpoint was AP2.

Regardless, it seems to be working now. The only thing I need to check is that it continues working on system reboot / restart.