philippe44
commented
11 months ago Yes, that would be worth a log because "pause" command from remote should be handled
Open nano9g opened 11 months ago
philippe44
commented
11 months ago Yes, that would be worth a log because "pause" command from remote should be handled
nano9g
commented
11 months ago While testing I've observed three distinct states after I start playing. Here are the states and the results when I tap the top of the HomePod in an attempt to pause:
| Top Light | Response when tapped | Log? | |
|---|---|---|---|
| 1 | ⚪️On | Siri starts up | Errors - see Log 1 |
| 2 | ⚫️Off | HomePod makes "bump-bump" error sound | Nothing logged |
| 3 | ⚪️On | Light goes off (second tap plays bump-bump sound and light turns back on) | Nothing logged no matter how many times I tap |
I don't know what triggers state 1; 2 and 3 are the most common.
Most of the time it starts up in state 2 and I can generally get from state 2 to 3 by skipping a track. If things are in state 2, it won't change to state 3 during normal playback -- the track skip is required.
Unfortunately I don't see anything happening in the logs the moment I tap the top of the HomePod unless it's in state 1. When I run in debug I only see _raopcl_send_sync, _rtp_timing_thread, and raopcl_send_chunk messages, and sdebug just adds a billion more raopcl_send_chunk messages.
For what it's worth, all my devices are on the same subnet, so I don't think there should be any routing issues. I also don't have any special firewall configuration on the Raspberry Pi.
Any thoughts on what else I can do to figure out why these commands aren't being received?
[14:35:31.922242] shadowRequest:223 [0xa57780]: spotify play request
D MercurySession.cpp:251: Executing Mercury Request, type SEND
I TrackPlayer.cpp:249: Playing done
I TrackPlayer.cpp:167: Got track ID=ae268a2dc03883055065585a3f2a7e92397e8df6
I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/ae268a2dc03883055065585a3f2a7e92397e8df6?1691174106_I92yDIRsDxUeyqKAWjxGwUTlX4L8tLFpTBOayN63TMU=
I MercurySession.cpp:42: Received packet, command: 178
I MercurySession.cpp:42: Received packet, command: 178
I MercurySession.cpp:42: Received packet, command: 178
I CDNAudioFile.cpp:70: Header and footer bytes received
D MercurySession.cpp:251: Executing Mercury Request, type SEND
I spotify.cpp:235: new track will start at 23274
[14:35:32.221482] shadowRequest:219 [0xa57780]: spotify LOAD request
[14:35:32.354057] raopcl_connect:996 [0x7f7801e6c0]: local interface [IP]
I MercurySession.cpp:42: Received packet, command: 178
[14:35:34.410082] http_read_line:1027 fd: 19 read error: Connection reset by peer
[14:35:34.410090] http_read_line:1032 disconnected on the other end 19
[14:35:34.410168] exec_request:625 [0x7f78022a60]: response : request failed
[14:35:34.410224] exec_request:625 [0x7f78022a60]: response : request failed
[14:35:34.410310] exec_request:618 [0x7f78022a60]: couldn't write request (-1!=278)
D MercurySession.cpp:251: Executing Mercury Request, type SEND
[14:35:34.410850] shadowRequest:223 [0xa57780]: spotify play request
[14:35:34.414402] raopcl_connect:996 [0x7f7801e6c0]: local interface [IP]
[14:35:34.513058] mDNSsearchCallback:351 [0xa57780]: keep missing renderer (Kitchen-HomePod)
I TrackPlayer.cpp:200: Playing
I spotify.cpp:133: trackUniqueId update => ae268a2dc03883055065585a3f2a7e92397e8df6
I MercurySession.cpp:42: Received packet, command: 178
[14:35:38.798799] raopcl_send_chunk:588 [0x7f7801e6c0]: check n:3165591470 p:3165592674 ts:74576969279324 sn:22404
retr: 0, avail: 0, send: 0, select: 0)
I MercurySession.cpp:42: Received packet, command: 181
I MercurySession.cpp:42: Received packet, command: 181
I MercurySession.cpp:42: Received packet, command: 181
[14:35:44.420434] exec_request:625 [0x7f78022a60]: response : request failed
D spotify.cpp:416: keepAlive Kitchen HomePod
D MercurySession.cpp:251: Executing Mercury Request, type SENDI'm a bit confused about the "states" and the logs. What happens if you just do a play and do not touch the HomePod? What type of log do you have?
nano9g
commented
11 months ago I'm a bit confused about the "states" and the logs.
Sorry about that, I must not have done a good job of explaining. The states in the table refer to the behavior of the HomePod after I start playing to it via SpotConnect. I noticed while testing that the behavior wasn't consistent, which is why I ended up with that list.
What happens if you just do a play and do not touch the HomePod?
To be clear, I'm always starting playback fresh from the devices menu in Spotify; I haven't gotten to the point of trying to resume playback by tapping the HomePod since I can't yet tap it to pause.
What type of log do you have?
I'm obtaining logs by interactively running
spotraop-linux-aarch64-static -x spotraop-config.xml -d all=debug (or sdebug). I also am setting all the log options in the config to debug or sdebug just to be sure.
Hopefully that clarifies things, but let me know if you still have questions. 🙂
philippe44
commented
11 months ago Hopefully that clarifies things, but let me know if you still have questions. 🙂
It does but that's surprising to see a few fails/log errors when just trying to play. Do you have other devices like an AirPort express? What are logs on your ATV?
nano9g
commented
11 months ago It does but that's surprising to see a few fails/log errors when just trying to play.
Ah, no, that log exerpt is from the one time I tried to pause and Siri activated. Normally there aren't errors when I just start playing.
Do you have other devices like an AirPort express? What are logs on your ATV?
The only other first-party devices I have are Apple TVs (and Macs). I also have Aether Cones, which support AirPlay. I'll do some testing with those and provide info on whether pausing works and any differences in logging.
philippe44
commented
11 months ago It does but that's surprising to see a few fails/log errors when just trying to play.
Ah, no, that log exerpt is from the one time I tried to pause and Siri activated. Normally there aren't errors when I just start playing.
Ok, so just to be 100% when playback in normal case, there is nothing weird in the log? Sorry, this is confusing 😄
nano9g
commented
11 months ago Ok, so just to be 100% when playback in normal case, there is nothing weird in the log? Sorry, this is confusing 😄
No worries! During normal playback, the debug log looks perfectly ordinary to me, and if I search for "error", nothing turns up.
nano9g
commented
11 months ago I just tested with the Apple TV 4K (the only Apple TV I can test with at the moment since I can't pair the ATV HDs yet 😉) and pausing doesn't work with it either. Just like the HomePod, when I hammer on the pause button, absolutely nothing appears in the log to indicate any awareness of the action.
nano9g
commented
11 months ago I was able to test with an Aether Cone today and something was actually recorded in the log! However, playback didn't pause. (I also opened #17 because the audio never played correctly… no idea whether that's related to the lack of response to the playpause event.)
[16:25:09.574582] ActiveRemoteThread:634 raw active remote: get /ctrl-int/1/playpause http/1.1
host: [raspberry pi].local
active-remote: 3948577553
user-agent: airplay/190.9
[16:25:09.574700] ActiveRemoteThread:668 [0xa56e10]: remote command playpauseVersion 0.1.4 should address the Aether Cone play/pause
nano9g
commented
11 months ago Definite progress with 0.1.4! However, I'm consistently only able to pause/resume once. After resuming playback by tapping on the Cone's button a second time, SpotRaop resumes playback but gets into a weird state where:
Received CDN URL and then doesn't proceed further.exit SpotRaop (I'm running in interactive mode for testing), it hangs after Stop:935 flush renderers… and I have to break to exit. When I hit Ctrl+C, I get a crash with a double free or corruption (fasttop) error and a backtrace - see logs.For both logs, once commands from the Cone stopped being received after the pause/resume, I disconnected via the Spotify devices menu and eventually had to break to quit. The difference is what I did immediately after disconnecting:
Received CDN URL.exit after disconnecting.philippe44
commented
11 months ago You're right indeed, I've been a bit careless with that part of the code where there was a deadlock due to use of recursive mutex (if that sort of things rings a bell for you). Should be fine in 0.1.5
nano9g
commented
11 months ago 0.1.5 is working great with the Cone!
I retested with the HomePod just in case but everything is exactly the same as in the original report. Nothing is ever logged when I tap the top of the HomePod.
When I tap the top of the HomePod mini, I expect the stream to pause. However, SpotConnect currently just keeps playing. (The playing indicator light turns off until the next track starts.)
For what it's worth, volume up/down is handled correctly.
Please let me know if you need any logs or other information. Thanks!