ejurgensen
commented
3 years ago I think I may have experienced this too with Spotify, but I didn't really dig into to it, since reproduction seemed like it would be difficult.
Closed cdlenfert closed 2 years ago
ejurgensen
commented
3 years ago I think I may have experienced this too with Spotify, but I didn't really dig into to it, since reproduction seemed like it would be difficult.
cdlenfert
commented
3 years ago I've definitely seen it with audio files that sit on an SMB share on my network as well. I came back into the office this morning, use a command to start playback (via JSON API) and it worked. Do you expect that any log level might capture the no-audio issue if I see it happen again? Edit: It's almost like the drive on the SMB share goes to sleep and OT doesn't wake it up (or ask it to access the file) when the track was already in progress. Just a possible scenario in my mind and I have no evidence to this behavior.
ejurgensen
commented
3 years ago I don't know if logs will help, but I think it is worth a shot (best on debug log level). When OwnTone is on "a long break" it actually closes the input source completely, this happens after 10 minutes. So when you restart it should in principle be the same as starting from fresh. Meaning I have no explanation of why your drive doesn't spin up.
cdlenfert
commented
3 years ago I can reproduce this issue almost every day when I come into my office. I don't expect the debug logs to be very helpful in this case, but here they are anyway.
[2021-07-12 07:43:09] [DEBUG] mpd: MPD message: status
[2021-07-12 07:43:09] [DEBUG] player: Player status: playing
[2021-07-12 07:43:09] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2021-07-12 07:43:09] [DEBUG] db: Running query 'SELECT COUNT(*) FROM queue;'
[2021-07-12 07:43:09] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:43:09] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3843 ORDER BY pos;'
[2021-07-12 07:43:09] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:43:09] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3843)
[2021-07-12 07:43:09] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:43:09] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3843)
[2021-07-12 07:43:09] [DEBUG] db: Running query 'SELECT shuffle_pos FROM queue WHERE id = 3843;'
[2021-07-12 07:43:09] [DEBUG] db: Fetch by pos: item (3843) has absolute pos 11
[2021-07-12 07:43:09] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE shuffle_pos = 12 ORDER BY pos;'
[2021-07-12 07:43:09] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:43:09] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:43:09] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:43:12] [DEBUG] raop: send_progress: Sending SET_PARAMETER to 'Hive AirPort Express'
[2021-07-12 07:43:14] [DEBUG] mpd: MPD message: status
[2021-07-12 07:43:14] [DEBUG] player: Player status: playing
[2021-07-12 07:43:14] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2021-07-12 07:43:14] [DEBUG] db: Running query 'SELECT COUNT(*) FROM queue;'
[2021-07-12 07:43:14] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:43:14] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3843 ORDER BY pos;'
[2021-07-12 07:43:14] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:43:14] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3843)
[2021-07-12 07:43:14] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:43:14] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3843)
[2021-07-12 07:43:14] [DEBUG] db: Running query 'SELECT shuffle_pos FROM queue WHERE id = 3843;'
[2021-07-12 07:43:14] [DEBUG] db: Fetch by pos: item (3843) has absolute pos 11
[2021-07-12 07:43:14] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE shuffle_pos = 12 ORDER BY pos;'
[2021-07-12 07:43:14] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:43:14] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:43:14] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:43:14] [DEBUG] mpd: MPD message: status
[2021-07-12 07:43:14] [DEBUG] player: Player status: playingThis just repeats as the front end shows progress and even switches between tracks. However, here is a section of the log that covers the switch between tracks.
[2021-07-12 07:46:30] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:46:31] [ WARN] xcode: Could not read frame: End of file
[2021-07-12 07:46:31] [DEBUG] ffmpeg: Statistics: 4969670 bytes read, 0 seeks
[2021-07-12 07:46:31] [DEBUG] player: event_read_start_next()
[2021-07-12 07:46:31] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3843)
[2021-07-12 07:46:31] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:31] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3843)
[2021-07-12 07:46:31] [DEBUG] db: Running query 'SELECT shuffle_pos FROM queue WHERE id = 3843;'
[2021-07-12 07:46:31] [DEBUG] db: Fetch by pos: item (3843) has absolute pos 11
[2021-07-12 07:46:31] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE shuffle_pos = 12 ORDER BY pos;'
[2021-07-12 07:46:31] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:46:31] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:31] [DEBUG] db: Fetch by pos: fetched item (id=3840, pos=3, file-id=17966)
[2021-07-12 07:46:31] [DEBUG] player: Opening next track: '/mnt/pizero/Pogo_itunes/iTunes Music/Music/Pinback/Autumn of the Seraphs (Bonus Track Version)/Good to Sea.mp3' (id=3840)
[2021-07-12 07:46:31] [ WARN] player: now 0, item_id 3840, now item_id 3843
[2021-07-12 07:46:31] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:31] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3840 ORDER BY pos;'
[2021-07-12 07:46:31] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:31] [DEBUG] player: Setting up input item '/mnt/pizero/Pogo_itunes/iTunes Music/Music/Pinback/Autumn of the Seraphs (Bonus Track Version)/Good to Sea.mp3' (item id 3840)
[2021-07-12 07:46:32] [DEBUG] ffmpeg: Skipping 0 bytes of junk at 2186.
[2021-07-12 07:46:32] [ WARN] ffmpeg: Estimating duration from bitrate, this may be inaccurate
[2021-07-12 07:46:32] [DEBUG] ffmpeg: tb:1/14112000 samplefmt:fltp samplerate:44100 chlayout:0x3
[2021-07-12 07:46:32] [DEBUG] xcode: Created 'in' filter: time_base=1/14112000:sample_rate=44100:sample_fmt=fltp:channel_layout=0x3
[2021-07-12 07:46:32] [DEBUG] xcode: Created 'format' filter: sample_fmts=s32:sample_rates=44100:channel_layouts=0x3
[2021-07-12 07:46:32] [DEBUG] ffmpeg: auto-inserting filter 'auto_resampler_0' between the filter 'in' and the filter 'format'
[2021-07-12 07:46:32] [DEBUG] ffmpeg: ch:2 chl:stereo fmt:fltp r:44100Hz -> ch:2 chl:stereo fmt:s32 r:44100Hz
[2021-07-12 07:46:32] [DEBUG] player: Starting input read loop for item '/mnt/pizero/Pogo_itunes/iTunes Music/Music/Pinback/Autumn of the Seraphs (Bonus Track Version)/Good to Sea.mp3' (item id 3840), seek 0
[2021-07-12 07:46:32] [DEBUG] raop: send_progress: Sending SET_PARAMETER to 'Hive AirPort Express'
[2021-07-12 07:46:32] [DEBUG] player: event_read_eof()
[2021-07-12 07:46:32] [DEBUG] player: Incomplete read, wanted 3528, got 792 (samples=99/time=2244897), deficit 3816
[2021-07-12 07:46:34] [DEBUG] player: event_play_eof()
[2021-07-12 07:46:34] [DEBUG] player: event_play_start()
[2021-07-12 07:46:34] [DEBUG] player: Status update - status: 4, events: 1, caller: event_play_start
[2021-07-12 07:46:34] [DEBUG] mpd: Asynchronous listener callback called with event type 1.
[2021-07-12 07:46:34] [DEBUG] mpd: Notify clients waiting for idle results: 1
[2021-07-12 07:46:34] [DEBUG] mpd: Notify client #0
[2021-07-12 07:46:34] [DEBUG] mpd: Notify client #1
[2021-07-12 07:46:34] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:34] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3840 ORDER BY pos;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:34] [DEBUG] artwork: Artwork request for item 17966 (max_w=600, max_h=600)
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966;'
[2021-07-12 07:46:34] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 ;'
[2021-07-12 07:46:34] [DEBUG] mpd: MPD message: status
[2021-07-12 07:46:34] [DEBUG] web: notify callback reason: 11
[2021-07-12 07:46:34] [DEBUG] web: notify callback reply: 1
[2021-07-12 07:46:34] [DEBUG] player: Player status: playing
[2021-07-12 07:46:34] [DEBUG] web: JSON api request: '/api/player'
[2021-07-12 07:46:34] [DEBUG] player: Player status: playing
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT COUNT(*) FROM queue;'
[2021-07-12 07:46:34] [DEBUG] web: Artwork api request: '/artwork/item/17966'
[2021-07-12 07:46:34] [DEBUG] artwork: Artwork request for item 17966 (max_w=0, max_h=0)
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:34] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3840 ORDER BY pos;'
[2021-07-12 07:46:34] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:34] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 ;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:34] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3840)
[2021-07-12 07:46:34] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:34] [DEBUG] db: Fetch by pos: pos (1) relative to item with id (3840)
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT shuffle_pos FROM queue WHERE id = 3840;'
[2021-07-12 07:46:34] [DEBUG] db: Fetch by pos: item (3840) has absolute pos 12
[2021-07-12 07:46:34] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE shuffle_pos = 13 ORDER BY pos;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:34] [DEBUG] cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2561001589078942337 AND a.max_w = 600 AND a.max_h = 600;'
[2021-07-12 07:46:34] [DEBUG] cache: No results
[2021-07-12 07:46:34] [DEBUG] db: Fetch by pos: fetched item (id=3847, pos=10, file-id=17967)
[2021-07-12 07:46:34] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:34] [DEBUG] db: Fetch by pos: fetched item (id=3847, pos=10, file-id=17967)
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:34] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] mpd: MPD message: replay_gain_status
[2021-07-12 07:46:35] [DEBUG] mpd: MPD message: idle
[2021-07-12 07:46:35] [DEBUG] mpd: MPD message: currentsong
[2021-07-12 07:46:35] [DEBUG] player: Player status: playing
[2021-07-12 07:46:35] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:35] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3840 ORDER BY pos;'
[2021-07-12 07:46:35] [DEBUG] db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:35] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:35] [DEBUG] cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2561001589078942337 AND a.max_w = 0 AND a.max_h = 0;'
[2021-07-12 07:46:35] [DEBUG] cache: No results
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:35] [DEBUG] db: End of query results
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] db: End of query results
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:35] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:35] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_spotify';'
[2021-07-12 07:46:35] [DEBUG] db: No results
[2021-07-12 07:46:35] [DEBUG] spotify: Spotify token still valid
[2021-07-12 07:46:35] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:35] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE file_id = 17966 ORDER BY pos;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_spotify';'
[2021-07-12 07:46:35] [DEBUG] db: No results
[2021-07-12 07:46:35] [DEBUG] spotify: Spotify token still valid
[2021-07-12 07:46:35] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:35] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE file_id = 17966 ORDER BY pos;'
[2021-07-12 07:46:35] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:35] [DEBUG] http: Parameters in request are: q=artist%3APinback%20album%3AAutumn%20of%20the%20Seraphs%20%28Bonus%20Track%20Version%29
[2021-07-12 07:46:35] [ INFO] http: Making request for https://api.spotify.com/v1/search?type=track&limit=1&q=artist%3APinback%20album%3AAutumn%20of%20the%20Seraphs%20%28Bonus%20Track%20Version%29
[2021-07-12 07:46:35] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:35] [DEBUG] http: Parameters in request are: q=artist%3APinback%20album%3AAutumn%20of%20the%20Seraphs%20%28Bonus%20Track%20Version%29
[2021-07-12 07:46:35] [ INFO] http: Making request for https://api.spotify.com/v1/search?type=track&limit=1&q=artist%3APinback%20album%3AAutumn%20of%20the%20Seraphs%20%28Bonus%20Track%20Version%29
[2021-07-12 07:46:36] [DEBUG] artwork: No image tag found in response from source 'Spotify'
[2021-07-12 07:46:36] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_discogs';'
[2021-07-12 07:46:36] [DEBUG] db: No results
[2021-07-12 07:46:36] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_coverartarchive';'
[2021-07-12 07:46:36] [DEBUG] db: No results
[2021-07-12 07:46:36] [DEBUG] db: End of query results
[2021-07-12 07:46:36] [DEBUG] artwork: No artwork found for item 17966
[2021-07-12 07:46:37] [DEBUG] artwork: No image tag found in response from source 'Spotify'
[2021-07-12 07:46:37] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_discogs';'
[2021-07-12 07:46:37] [DEBUG] db: No results
[2021-07-12 07:46:37] [DEBUG] db: Running query 'SELECT value FROM admin a WHERE a.key = 'use_artwork_source_coverartarchive';'
[2021-07-12 07:46:37] [DEBUG] db: No results
[2021-07-12 07:46:37] [DEBUG] db: End of query results
[2021-07-12 07:46:37] [DEBUG] artwork: No artwork found for item 17966
[2021-07-12 07:46:37] [ INFO] raop: Failed to retrieve artwork for file '/mnt/pizero/Pogo_itunes/iTunes Music/Music/Pinback/Autumn of the Seraphs (Bonus Track Version)/Good to Sea.mp3'; no artwork will be sent
[2021-07-12 07:46:37] [DEBUG] db: Running query 'BEGIN TRANSACTION;'
[2021-07-12 07:46:37] [DEBUG] raop: send_progress: Sending SET_PARAMETER to 'Hive AirPort Express'
[2021-07-12 07:46:37] [DEBUG] db: Starting enum 'SELECT * FROM queue f WHERE id = 3840 ORDER BY pos;'
[2021-07-12 07:46:37] [DEBUG] db: Running query 'END TRANSACTION;'
[2021-07-12 07:46:37] [DEBUG] artwork: Artwork request for item 17966 (max_w=600, max_h=600)
[2021-07-12 07:46:37] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966;'
[2021-07-12 07:46:37] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 ;'
[2021-07-12 07:46:37] [DEBUG] db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 2561001589078942337;'
[2021-07-12 07:46:37] [DEBUG] db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337;'
[2021-07-12 07:46:37] [DEBUG] db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 17966 AND f.songalbumid = 2561001589078942337 ;'
[2021-07-12 07:46:37] [DEBUG] cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2561001589078942337 AND a.max_w = 600 AND a.max_h = 600;'
[2021-07-12 07:46:37] [DEBUG] cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 2561001589078942337 AND a.max_w = 600 AND a.max_h = 600;
[2021-07-12 07:46:37] [DEBUG] artwork: Source 'cache' stopped search for artwork for group 2561001589078942337
[2021-07-12 07:46:37] [DEBUG] artwork: No artwork found for item 17966
[2021-07-12 07:46:37] [ INFO] airplay: Failed to retrieve artwork for file '/mnt/pizero/Pogo_itunes/iTunes Music/Music/Pinback/Autumn of the Seraphs (Bonus Track Version)/Good to Sea.mp3'; no artwork will be sent
[2021-07-12 07:46:39] [DEBUG] mpd: MPD message: statusNo sound output during any of this.
ejurgensen
commented
3 years ago Yeah, sorry to say that the log isn't giving me any clues. I don't see anything unusual. I am wondering if the issue only shows up for Airplay 1 speakers? Do you have other outputs that you could test with?
cdlenfert
commented
3 years ago Yes, I'll switch it over to the Alsa output (USB sound card) for a bit and see if the issue persists.
For the record my Airport Express is a 3rd gen (hockey puck style) with the latest firmware, so wouldn't that make it an Airplay 2 device? At least I know that it supports Airplay 2.
ejurgensen
commented
3 years ago It supports both Airplay 1 and 2, and owntone currently defaults to 1 since it is the most well tested. You can use the “raop_disable” setting to force Airplay 2, but for this test using something entirely different like Alsa is better.
cdlenfert
commented
3 years ago So after a week on ALSA as the output I've not had the issue of starting playback without sound output. So this narrows it down for me to something with the 3rd Gen Airport Express (hockey puck style).
ejurgensen
commented
3 years ago Do you have ipv6 enabled? Otherwise it might be worth trying with that disabled.
cdlenfert
commented
3 years ago For OwnTone IPv6 is disabled. (set to "no"). It does look like IPv6 is enabled on the Airport Express, but I'm not sure if that should matter. I can try turning it off.
ejurgensen
commented
3 years ago Did you get around to testing if the issue is also present when Airplay 2 is used? By using the raop_disable setting.
cdlenfert
commented
3 years ago I have not but can try to do so soon. Thanks for the reminder.
On Mon, Jul 26, 2021 at 1:05 AM ejurgensen @.***> wrote:
Did you get around to testing if the issue is also present when Airplay 2 is used? By using the raop_disable setting.
— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/owntone/owntone-server/issues/1280#issuecomment-886434509, or unsubscribe https://github.com/notifications/unsubscribe-auth/AED2GMJ4ISABFRMXJKBOPYLTZUCLHANCNFSM47SNPK5Q .
cdlenfert
commented
3 years ago @ejurgensen I enabled the raop_disable setting to force Airplay 2 playback on my 3rd gen Airport Express. I did it yesterday. This morning when I came in, I started playback and audio was output as expected. So far so good. I'll keep this setup and see if it keeps working for the next few days at least.
cdlenfert
commented
3 years ago After a weekend of being paused, I resumed playback with sound output as expected. Closing this issue. I can re-open if it comes back up or gladly assist if there's any desire to do more testing on the Airtunes (older airplay protocol) streaming sound output issue. Thanks @ejurgensen
cdlenfert
commented
3 years ago @ejurgensen I'm seeing this right now on my home server. Start playback of an already loaded Spotify queue, output is set to a 2nd Gen Airport Express (this is the first wireless N version, not the 3rd Gen). The volume one speaker is set to a level high enough that there should be audible sound output. No audio is coming out, but everything indicates that it should be. Here is the log output around the starting of playback.
[deleted]
and here is the log when it transitions between tracks, but still provides no audio output:
[deleted]
and finally here is the log when I click the "previous" button, and it goes to the beginning of the "playing" track, and instantly audio is output.
[deleted]
ejurgensen
commented
3 years ago This seems to be an Airplay issue, so your current -D flag is hiding what might be the interesting part. If you add "raop,airplay" then hopefully it will show more.
Since the above logs don't reveal anything you can delete them.
derekatkins
commented
2 years ago I've noticed this with my airplay (shairport-sync) targets. The music starts after about 30 seconds or so...
cdlenfert
commented
2 years ago @ejurgensen I've captured some logs around the playback without sound issue. In this case I'm streaming to an Airport Express 3rd Generation (hockey puck style). Everything indicates that playback is in progress, but the AE isn't receiving/outputing any audio data as far as I can tell. As usual, skipping to the beginning of the currently playing track, or forward to the next track gets the sound output going again. Play/Pause doesn't seem to have the same effect and still yields no audio output.
This particular OT server is configured to output to this particular AE via Airplay 2. I find this particular line in the log interesting, because there is no password authentication set up to stream to this AE.
Pairing step 2 response from 'Hive AirPort Express' error: Device returned an authentication failure
Here's the log around the no audio and play/pause attempts
[2021-12-03 08:22:53] [DEBUG] airplay: device_start: Sending GET /info to 'Hive AirPort Express'
[2021-12-03 08:22:53] [DEBUG] airplay: Local address: 10.1.10.123 (LL: no) port 41030
[2021-12-03 08:22:53] [DEBUG] airplay: Status flags from 'Hive AirPort Express' was 4: cable attached 1, one time pairing 0, password 0, PIN 0
[2021-12-03 08:22:53] [DEBUG] airplay: device_start: Sending pair setup 1 to 'Hive AirPort Express'
[2021-12-03 08:22:55] [DEBUG] airplay: device_start: Sending pair setup 2 to 'Hive AirPort Express'
[2021-12-03 08:22:56] [ LOG] airplay: Pairing step 2 response from 'Hive AirPort Express' error: Device returned an authentication failure
[2021-12-03 08:22:56] [DEBUG] airplay: Raw response 0000 07 01 02 06 01 04 ......And here is the log when I skip back to the beginning of the track and audio resumes.
[2021-12-03 08:24:52] [DEBUG] airplay: Status flags from 'Hive AirPort Express' was 4: cable attached 1, one time pairing 0, password 0, PIN 0
[2021-12-03 08:24:52] [DEBUG] airplay: device_start: Sending pair setup 1 to 'Hive AirPort Express'
[2021-12-03 08:24:53] [DEBUG] airplay: device_start: Sending pair setup 2 to 'Hive AirPort Express'
[2021-12-03 08:24:55] [DEBUG] airplay: Ciphering setup of 'Hive AirPort Express' completed succesfully, now using encrypted mode
[2021-12-03 08:24:55] [DEBUG] airplay: pair_success: Sending SETUP (session) to 'Hive AirPort Express'
[2021-12-03 08:24:55] [DEBUG] airplay: pair_success: Sending SETPEERS to 'Hive AirPort Express'
...Yes, that is indeed very interesting! Your observation gave me the idea to run a test program that just does this pairing many times against my APE2. After about 20 attempts I got the same authentication error. So now I can reproduce.
There is some randomness involved in this pairing, which comes from key generation. I suspect some of the random keys might be invalid, but let's see.
Btw shortened your log a bit
ejurgensen
commented
2 years ago @cdlenfert the issue with Airplay 2 pairing authentication failure should now be fixed in master. However, I don't suppose this means that this issue entirely is solved, since it originally seemed to relate Airplay 1? I will still close the issue, because unless more clues turn up, I won't be able to do anything about it.
cdlenfert
commented
2 years ago @ejurgensen Just saw this again this morning at home. This time capturing on an Airport Express 3rd gen (also forcing airplay 2), but I have seen it on a 2nd Gen Airport Express as well and will share those logs when I capture them.
In this scenario, I was streaming OwnTone to my Kitchen speaker (Airport Express 2nd Gen), then paused, then my wife did some direct airplay to the same Kitchen AE2 speaker, then I went into my home office and switched the speaker via http request and toggled play/pause (to resume playing - also via http request). Then no audio could be heard despite playback progressing and volume levels showing as normal. Maybe it's a volume hiccup?
## resuming playback on (home) Office speaker without any sound
[2021-12-09 06:55:19] [DEBUG] player: Player status: paused
[2021-12-09 06:56:06] [DEBUG] spotify: Connection is idle, auto-disconnected
[2021-12-09 07:05:00] [ WARN] player: Timed out after 600 sec without any reading from input source
[2021-12-09 07:05:00] [DEBUG] spotify: stop()
[2021-12-09 07:05:00] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:03] [DEBUG] player: Speaker set: 1 speakers
[2021-12-09 08:36:03] [DEBUG] player: Registered callback to device_activate_cb with id 0 (device 0x15364f8, Office)
[2021-12-09 08:36:03] [DEBUG] player: Number of active callbacks: 1
[2021-12-09 08:36:03] [DEBUG] player: Subscription request for quality 44100/16/2 (now 1 subscribers)
[2021-12-09 08:36:03] [DEBUG] airplay: device_probe: Sending GET /info (probe) to 'Office'
[2021-12-09 08:36:03] [DEBUG] airplay: Local address: 192.168.0.8 (LL: no) port 34436
[2021-12-09 08:36:03] [DEBUG] airplay: Status flags from 'Office' was 1028: cable attached 1, one time pairing 0, password 0, PIN 0
[2021-12-09 08:36:03] [DEBUG] player: Callback request received, id is 0
[2021-12-09 08:36:03] [DEBUG] player: Unsubscription request for quality 44100/16/2 (now 0 subscribers)
[2021-12-09 08:36:03] [DEBUG] player: Making deferred callback to device_activate_cb, id was 0
[2021-12-09 08:36:03] [DEBUG] player: Callback from AirPlay 2 device Office to device_activate_cb (status 1)
[2021-12-09 08:36:03] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:03] [DEBUG] player: Status update - status: 3, events: 12, caller: speaker_generic_bh
[2021-12-09 08:36:04] [DEBUG] player: Player status: paused
[2021-12-09 08:36:04] [DEBUG] player: Restarting track: 'spotify:track:5z0Wa1EiCoaUafx83WszRY' (id=21410, pos=41986)
[2021-12-09 08:36:04] [DEBUG] player: Registered callback to device_activate_cb with id 0 (device 0x15364f8, Office)
[2021-12-09 08:36:04] [DEBUG] player: Number of active callbacks: 1
[2021-12-09 08:36:04] [DEBUG] player: Subscription request for quality 44100/16/2 (now 1 subscribers)
[2021-12-09 08:36:04] [DEBUG] player: Setting up input item 'spotify:track:5z0Wa1EiCoaUafx83WszRY' (item id 21410)
[2021-12-09 08:36:04] [DEBUG] spotify: setup()
[2021-12-09 08:36:04] [DEBUG] airplay: device_start: Sending GET /info to 'Office'
[2021-12-09 08:36:04] [DEBUG] airplay: Local address: 192.168.0.8 (LL: no) port 34438
[2021-12-09 08:36:04] [DEBUG] airplay: Status flags from 'Office' was 1028: cable attached 1, one time pairing 0, password 0, PIN 0
[2021-12-09 08:36:04] [DEBUG] airplay: device_start: Sending pair setup 1 to 'Office'
[2021-12-09 08:36:04] [DEBUG] misc: Connecting to 'spotify' at 104.199.240.237 (port 443)
[2021-12-09 08:36:06] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8810673
[2021-12-09 08:36:06] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 8745366 requested, type 1, returning 8745366
[2021-12-09 08:36:06] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 5935 requested, type 1, returning 5935
[2021-12-09 08:36:06] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 4026 requested, type 1, returning 4026
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8810673
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8810673
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8810673
[2021-12-09 08:36:06] [DEBUG] airplay: device_start: Sending pair setup 2 to 'Office'
[2021-12-09 08:36:06] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8810673
[2021-12-09 08:36:07] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:07] [DEBUG] spotify: Seek to offset 8809648 requested, type 1, returning 8809648
[2021-12-09 08:36:07] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:07] [DEBUG] spotify: Seek to offset 8807907 requested, type 1, returning 8807907
[2021-12-09 08:36:07] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:07] [DEBUG] spotify: Seek to offset 8805859 requested, type 1, returning 8805859
[2021-12-09 08:36:07] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:07] [DEBUG] spotify: Seek to offset 8801763 requested, type 1, returning 8801763
[2021-12-09 08:36:07] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:07] [DEBUG] spotify: Seek to offset 8803811 requested, type 1, returning 8803811
[2021-12-09 08:36:08] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:08] [DEBUG] spotify: Seek to offset 1705437 requested, type 1, returning 1705437
[2021-12-09 08:36:08] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:08] [DEBUG] spotify: Seek to offset 1642662 requested, type 1, returning 1642662
[2021-12-09 08:36:08] [DEBUG] airplay: Ciphering setup of 'Office' completed succesfully, now using encrypted mode
[2021-12-09 08:36:08] [DEBUG] airplay: pair_success: Sending SETUP (session) to 'Office'
[2021-12-09 08:36:08] [DEBUG] airplay: pair_success: Sending SETPEERS to 'Office'
[2021-12-09 08:36:08] [DEBUG] airplay: pair_success: Sending SETUP (stream) to 'Office'
[2021-12-09 08:36:08] [ INFO] airplay: Setting up AirPlay session 2571295923 (192.168.0.8 -> 192.168.0.24)
[2021-12-09 08:36:08] [DEBUG] airplay: Negotiated UDP streaming session; ports d=64606 c=64604 t=64608 e=65526
[2021-12-09 08:36:08] [DEBUG] misc: Connecting to 'AirPlay data' at 192.168.0.24 (port 64606)
[2021-12-09 08:36:08] [DEBUG] misc: Connecting to 'AirPlay events' at 192.168.0.24 (port 65526)
[2021-12-09 08:36:08] [DEBUG] airplay: RTP-Info is seq=152;rtptime=1491986155
[2021-12-09 08:36:08] [DEBUG] airplay: pair_success: Sending RECORD to 'Office'
[2021-12-09 08:36:08] [DEBUG] airplay: Sending volume -26.100000 to 'Office'
[2021-12-09 08:36:08] [DEBUG] airplay: pair_success: Sending SET_PARAMETER (volume) to 'Office'
[2021-12-09 08:36:08] [DEBUG] player: Callback request received, id is 0
[2021-12-09 08:36:08] [DEBUG] player: Making deferred callback to device_activate_cb, id was 0
[2021-12-09 08:36:08] [DEBUG] player: Callback from AirPlay 2 device Office to device_activate_cb (status 2)
[2021-12-09 08:36:08] [DEBUG] player: Registered callback to device_streaming_cb with id 0 (device 0x15364f8, Office)
[2021-12-09 08:36:08] [DEBUG] player: Number of active callbacks: 1
[2021-12-09 08:36:08] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:36:08] [DEBUG] player: Status update - status: 4, events: 13, caller: playback_start_bh
[2021-12-09 08:36:08] [DEBUG] player: 0. Active callback: device_streaming_cb
## Skipping to beginning of playing track and regaining sound
[2021-12-09 08:42:03] [DEBUG] airplay: keep_alive: Sending POST /feedback to 'Office'
[2021-12-09 08:42:28] [DEBUG] airplay: keep_alive: Sending POST /feedback to 'Office'
[2021-12-09 08:42:49] [DEBUG] spotify: stop()
[2021-12-09 08:42:49] [DEBUG] player: event_read_start_next()
[2021-12-09 08:42:49] [DEBUG] player: Opening next track: 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (id=21409)
[2021-12-09 08:42:49] [DEBUG] player: Setting up input item 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (item id 21409)
[2021-12-09 08:42:49] [DEBUG] spotify: setup()
[2021-12-09 08:42:50] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:42:50] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:42:50] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:42:50] [DEBUG] spotify: Seek to offset 8398894 requested, type 1, returning 8398894
[2021-12-09 08:42:50] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:42:50] [DEBUG] spotify: Seek to offset 5354 requested, type 1, returning 5354
[2021-12-09 08:42:51] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:42:51] [DEBUG] spotify: Seek to offset 4026 requested, type 1, returning 4026
[2021-12-09 08:42:51] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:42:51] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:42:51] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:42:51] [DEBUG] player: Starting input read loop for item 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (item id 21409), seek 0
[2021-12-09 08:42:52] [DEBUG] player: event_read_eof()
[2021-12-09 08:42:52] [DEBUG] player: Incomplete read, wanted 17640, got 7792 (samples=1948/time=44172335), deficit 26328
[2021-12-09 08:42:53] [DEBUG] airplay: keep_alive: Sending POST /feedback to 'Office'
[2021-12-09 08:42:53] [DEBUG] player: event_play_eof()
[2021-12-09 08:42:53] [ INFO] raop: Failed to retrieve artwork for file 'spotify:track:2dwvxOHnQjndZLowIR6PiS'; no artwork will be sent
[2021-12-09 08:42:53] [DEBUG] player: event_play_start()
[2021-12-09 08:42:53] [DEBUG] player: Status update - status: 4, events: 1, caller: event_play_start
[2021-12-09 08:42:54] [ INFO] airplay: Failed to retrieve artwork for file 'spotify:track:2dwvxOHnQjndZLowIR6PiS'; no artwork will be sent
[2021-12-09 08:42:54] [DEBUG] airplay: SET_PARAMETER (progress): Sending SET_PARAMETER (progress) to 'Office'
[2021-12-09 08:42:54] [DEBUG] player: Player status: playing
[2021-12-09 08:43:10] [DEBUG] player: Removing callback to device_streaming_cb, id 0
[2021-12-09 08:43:10] [DEBUG] player: Registered callback to device_flush_cb with id 0 (device 0x15364f8, Office)
[2021-12-09 08:43:10] [DEBUG] player: Number of active callbacks: 1
[2021-12-09 08:43:10] [DEBUG] airplay: flush: Sending FLUSH to 'Office'
[2021-12-09 08:43:10] [DEBUG] player: Callback request received, id is 0
[2021-12-09 08:43:10] [DEBUG] player: Making deferred callback to device_flush_cb, id was 0
[2021-12-09 08:43:10] [DEBUG] player: Callback from AirPlay 2 device Office to device_flush_cb (status 2)
[2021-12-09 08:43:10] [DEBUG] player: Registered callback to device_streaming_cb with id 0 (device 0x15364f8, Office)
[2021-12-09 08:43:10] [DEBUG] player: Number of active callbacks: 1
[2021-12-09 08:43:10] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:43:10] [DEBUG] player: Current playing/streaming song already in history
[2021-12-09 08:43:10] [DEBUG] spotify: stop()
[2021-12-09 08:43:10] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:43:10] [DEBUG] player: Opening track: 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (id=21409, seek=0)
[2021-12-09 08:43:10] [DEBUG] player: Setting up input item 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (item id 21409)
[2021-12-09 08:43:10] [DEBUG] spotify: setup()
[2021-12-09 08:43:10] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:43:10] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:43:11] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:43:11] [DEBUG] spotify: Seek to offset 8398894 requested, type 1, returning 8398894
[2021-12-09 08:43:11] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:43:11] [DEBUG] spotify: Seek to offset 5354 requested, type 1, returning 5354
[2021-12-09 08:43:11] [DEBUG] main: Command has 0 pending events
[2021-12-09 08:43:11] [DEBUG] spotify: Seek to offset 4026 requested, type 1, returning 4026
[2021-12-09 08:43:11] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:43:11] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:43:11] [DEBUG] spotify: Seek to offset 0 requested, type 0, returning 8464201
[2021-12-09 08:43:11] [DEBUG] player: Starting input read loop for item 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (item id 21409), seek 0
[2021-12-09 08:43:11] [DEBUG] player: 0. Active callback: device_streaming_cb
[2021-12-09 08:43:11] [DEBUG] player: Restarting track: 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (id=21409, pos=0)
[2021-12-09 08:43:11] [DEBUG] player: Status update - status: 4, events: 13, caller: playback_start_bh
[2021-12-09 08:43:11] [DEBUG] player: Player status: playing (buffering)
[2021-12-09 08:43:11] [DEBUG] player: Resuming input read loop for item 'spotify:track:2dwvxOHnQjndZLowIR6PiS' (item id 21409)
[2021-12-09 08:43:11] [DEBUG] player: event_read_quality()
[2021-12-09 08:43:11] [DEBUG] player: New session values (q=44100/16/2, spr=4410, bufsize=17640)
[2021-12-09 08:43:11] [DEBUG] airplay: Start sync packet sent to 'Office': cur_pos=1510298713, cur_ts=171079.200000000, clock=171079.363761862, rtptime=1510386603
[2021-12-09 08:43:13] [DEBUG] player: event_play_start()
[2021-12-09 08:43:13] [ INFO] raop: Failed to retrieve artwork for file 'spotify:track:2dwvxOHnQjndZLowIR6PiS'; no artwork will be sent
[2021-12-09 08:43:13] [ INFO] airplay: Failed to retrieve artwork for file 'spotify:track:2dwvxOHnQjndZLowIR6PiS'; no artwork will be sent
[2021-12-09 08:43:13] [DEBUG] player: Status update - status: 4, events: 1, caller: event_play_start
[2021-12-09 08:43:13] [DEBUG] airplay: SET_PARAMETER (progress): Sending SET_PARAMETER (progress) to 'Office'
[2021-12-09 08:43:13] [DEBUG] player: Player status: playing
[2021-12-09 08:43:18] [DEBUG] airplay: keep_alive: Sending POST /feedback to 'Office'
Thanks for the notice. There isn't much I can do about it, however, since it is not reproducible, and the logs have nothing that indicate errors. Despite not playing the speaker seems to be replying as expected to all requests. So I have nothing to go on.
cdlenfert
commented
2 years ago No problem. I'll attempt to reproduce my listed steps and see if I can trigger the situation again. When you say "it is not reproducible" did you try the same?
ejurgensen
commented
2 years ago Yes, I couldn't reproduce the issue doing this. I tried switching between an APE2 and a Roku stick, both with Airplay 2.
I don't have logs to share yet, but first would like to find out if anyone else is seeing this issue at all. When I pause OT for an indiscriminate amount of time and resume playback (for example, pause before leaving work for the day, and resume the next morning) OT indicates that it's playing the track I previously paused, but there is no audio output (in this case to an Airport Express, but I also think this make happen on the local ALSA device). It's like OT doesn't actually access the audio file again, but continues through what it knows should be the remaining time on the track. If I manually skip forward to the next track, audio output works as expected.
Here's where it gets fuzzier. I think if I let OT play through a track or 2 in "silent mode", then audio resumes as expected. I also think this happens on Spotify or local library files (though my local library files are actually on an SMB share).
Anyone else seeing this? Recommend a specific log level to try to capture the no audio condition? Thanks