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.

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

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

Closed
derekatkins opened this issue Nov 29, 2021 · 10 comments

Comments

@derekatkins
Copy link
Contributor

derekatkins commented Nov 29, 2021

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
Copy link
Member

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Member

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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

@ejurgensen
Copy link
Member

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
Copy link
Contributor Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants