Hi,
Thanks for your response.
I couldn’t attach the log file so I’ve pasted it below.
Steps taken:
- Play a song midway through an album.
- Used the WiiM Ultra’s previous/next dial, previous/next touch controls, previous/next remote controls several times but with no effect (other than Audirvana’s pause button flashes).
- Then (near then end) successfully paused/unpaused/paused using the WiiM Ultra’s play/pause button.
(FYI the WiiM Ultra’s transport controls work ok using TidalConnect from a smartphone but understand that’s a different protocol.)
(Also I should note the WiiM Ultra displays the elapsed time and time remaining which might explain the seek times. I think perhaps the TRANSITIONING entries are the skip track commands?)
2024-09-12 08:48:20.935 [info]: ============= Started Logging, Audirvana Studio 2.8.4 (20804) =============
2024-09-12 08:48:21.010 [info]: Running on Windows 11 (22631)
2024-09-12 08:48:22.133 [info]: UPnP stack initialized using specified interface: {308DAC28-9FEF-4609-ACD4-E75049E57473}
2024-09-12 08:48:22.298 [info]: RemoteServer: Server started and advertised on port 52203
2024-09-12 08:48:22.357 [info]: UPnP web server started on 192.168.0.3:49152
2024-09-12 08:48:22.969 [error]: UPnP Error 401 getting audio dB volume
2024-09-12 08:48:40.161 [error]: Tidal getAlbumDescription error: 404 {“status”:404,“subStatus”:2001,“userMessage”:“Review or album with id [232583279] not found”}
2024-09-12 08:48:40.281 [error]: Tidal getAlbumSimilarAlbums error: 404 {“status”:404,“subStatus”:2001,“userMessage”:“Similar albums for or album with id [232583279] not found”}
2024-09-12 08:48:40.404 [error]: Tidal getAlbumDescription error: 404 {“status”:404,“subStatus”:2001,“userMessage”:“Review or album with id [232583279] not found”}
2024-09-12 08:48:47.453 [debug]: UPnP Received AVTransportURI change to http://192.168.0.3:49152/audirvana/audio_f_7.wav
2024-09-12 08:48:47.453 [debug]: UPnP AVTransportURI change notification DISCARDED as in starting phase
2024-09-12 08:48:47.453 [debug]: UPnP Received updated transport actions:Play
2024-09-12 08:48:47.862 [debug]: UPnP setPlayingBuffer discarded
2024-09-12 08:48:47.862 [debug]: UPnP Received new transport state STOPPED
2024-09-12 08:48:47.951 [debug]: UPnP Success setting AVTransportURI to http://192.168.0.3:49152/audirvana/audio_f_0.wav
2024-09-12 08:48:47.963 [debug]: UPnP Received AVTransportURI change to http://192.168.0.3:49152/audirvana/audio_f_0.wav
2024-09-12 08:48:47.963 [debug]: UPnP AVTransportURI change notification DISCARDED as in starting phase
2024-09-12 08:48:47.980 [debug]: UPnP Received new transport state STOPPED
2024-09-12 08:48:48.561 [debug]: UPnP Send info for file audio_f_0.wav from buffer 0 trackId 0
2024-09-12 08:48:48.562 [debug]: UPnP open file /audirvana/audio_f_0.wav
2024-09-12 08:48:48.562 [debug]: UPnP webserver: seek 0 bytes from 1 from buffer 0
2024-09-12 08:48:48.562 [debug]: UPnP sent WAVE header with fileLength 49161548 audio data 49161504 from buffer 0 trackId 0
2024-09-12 08:48:48.562 [debug]: UPnP received audio data request from 0 for 1048532 loaded 7938000 from buffer 0 trackId 0
2024-09-12 08:48:48.562 [debug]: UPnP sending audio from 0:0 playing 0:0 loaded to 0:45 from 0 for 1048532 requested 1048532 loaded 7938000 from buffer 0 trackId 0
2024-09-12 08:48:48.562 [debug]: UPnP received audio data request from 1048532 for 1048576 loaded 7938000 from buffer 0 trackId 0
2024-09-12 08:48:48.562 [debug]: UPnP sending audio from 0:5 playing 0:0 loaded to 0:45 from 1048532 for 1048576 requested 1048576 loaded 7938000 from buffer 0 trackId 0
2024-09-12 08:48:48.646 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:48.647 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:48.768 [debug]: UPnP received audio data request from 2097108 for 1048576 loaded 7938000 from buffer 0 trackId 0
2024-09-12 08:48:48.768 [debug]: UPnP sending audio from 0:11 playing 0:0 loaded to 0:45 from 2097108 for 1048576 requested 1048576 loaded 7938000 from buffer 0 trackId 0
2024-09-12 08:48:48.889 [debug]: UPnP received audio data request from 3145684 for 1048576 loaded 8820000 from buffer 0 trackId 0
2024-09-12 08:48:48.889 [debug]: UPnP sending audio from 0:17 playing 0:0 loaded to 0:50 from 3145684 for 1048576 requested 1048576 loaded 8820000 from buffer 0 trackId 0
2024-09-12 08:48:48.999 [debug]: UPnP received audio data request from 4194260 for 1048576 loaded 10584000 from buffer 0 trackId 0
2024-09-12 08:48:48.999 [debug]: UPnP sending audio from 0:23 playing 0:0 loaded to 1:0 from 4194260 for 1048576 requested 1048576 loaded 10584000 from buffer 0 trackId 0
2024-09-12 08:48:49.100 [debug]: UPnP received audio data request from 5242836 for 1048576 loaded 10584000 from buffer 0 trackId 0
2024-09-12 08:48:49.100 [debug]: UPnP sending audio from 0:29 playing 0:0 loaded to 1:0 from 5242836 for 1048576 requested 1048576 loaded 10584000 from buffer 0 trackId 0
2024-09-12 08:48:49.193 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:49.194 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:48:49.200 [debug]: UPnP received audio data request from 6291412 for 1048576 loaded 10584000 from buffer 0 trackId 0
2024-09-12 08:48:49.200 [debug]: UPnP sending audio from 0:35 playing 0:0 loaded to 1:0 from 6291412 for 1048576 requested 1048576 loaded 10584000 from buffer 0 trackId 0
2024-09-12 08:48:49.210 [debug]: UPnP Exiting playing start polling loop with 44 attempts remaining
2024-09-12 08:48:49.295 [debug]: UPnP received audio data request from 7339988 for 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:49.295 [debug]: UPnP sending audio from 0:41 playing 0:0 loaded to 1:5 from 7339988 for 1048576 requested 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:49.379 [debug]: UPnP received audio data request from 8388564 for 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:49.379 [debug]: UPnP sending audio from 0:47 playing 0:0 loaded to 1:5 from 8388564 for 1048576 requested 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:49.474 [debug]: UPnP received audio data request from 9437140 for 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:49.474 [debug]: UPnP sending audio from 0:53 playing 0:0 loaded to 1:5 from 9437140 for 1048576 requested 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:49.576 [debug]: UPnP received audio data request from 10485716 for 1048576 loaded 11466000 from buffer 0 trackId 0
2024-09-12 08:48:50.087 [debug]: UPnP sending audio from 0:59 playing 0:0 loaded to 1:20 from 10485716 for 1048576 requested 1048576 loaded 14112000 from buffer 0 trackId 0
2024-09-12 08:48:50.094 [debug]: UPnP received audio data request from 11534292 for 1048576 loaded 14112000 from buffer 0 trackId 0
2024-09-12 08:48:50.094 [debug]: UPnP sending audio from 1:5 playing 0:0 loaded to 1:20 from 11534292 for 1048576 requested 1048576 loaded 14112000 from buffer 0 trackId 0
2024-09-12 08:48:50.196 [debug]: UPnP received audio data request from 12582868 for 1048576 loaded 15876000 from buffer 0 trackId 0
2024-09-12 08:48:50.197 [debug]: UPnP sending audio from 1:11 playing 0:0 loaded to 1:30 from 12582868 for 1048576 requested 1048576 loaded 15876000 from buffer 0 trackId 0
2024-09-12 08:48:50.292 [debug]: UPnP received audio data request from 13631444 for 1048576 loaded 15876000 from buffer 0 trackId 0
2024-09-12 08:48:50.292 [debug]: UPnP sending audio from 1:17 playing 0:0 loaded to 1:30 from 13631444 for 1048576 requested 1048576 loaded 15876000 from buffer 0 trackId 0
2024-09-12 08:48:50.416 [debug]: UPnP received audio data request from 14680020 for 1048576 loaded 17640000 from buffer 0 trackId 0
2024-09-12 08:48:50.416 [debug]: UPnP sending audio from 1:23 playing 0:0 loaded to 1:40 from 14680020 for 1048576 requested 1048576 loaded 17640000 from buffer 0 trackId 0
2024-09-12 08:48:50.523 [debug]: UPnP received audio data request from 15728596 for 1048576 loaded 17640000 from buffer 0 trackId 0
2024-09-12 08:48:50.523 [debug]: UPnP sending audio from 1:29 playing 0:0 loaded to 1:40 from 15728596 for 1048576 requested 1048576 loaded 17640000 from buffer 0 trackId 0
2024-09-12 08:48:52.945 [debug]: UPnP received audio data request from 16777172 for 1048576 loaded 33516000 from buffer 0 trackId 0
2024-09-12 08:48:52.945 [debug]: UPnP sending audio from 1:35 playing 0:2 loaded to 3:10 from 16777172 for 1048576 requested 1048576 loaded 33516000 from buffer 0 trackId 0
2024-09-12 08:48:54.430 [debug]: FLAC decoder: HTTP reader returned less bytes 943 than requested 8192
2024-09-12 08:48:54.433 [debug]: UPnP send setNextAVTransportURI for track Transform
2024-09-12 08:48:54.521 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:54.522 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:54.695 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:54.695 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:48:54.899 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:54.900 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:54.955 [debug]: UPnP Success setting NextAVTransportURI to http://192.168.0.3:49152/audirvana/audio_f_1.wav
2024-09-12 08:48:55.014 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:55.015 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:48:56.693 [debug]: UPnP received audio data request from 17825748 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:48:56.693 [debug]: UPnP sending audio from 1:41 playing 0:6 loaded to 4:38 from 17825748 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:48:57.177 [debug]: FLAC decoder: HTTP reader returned less bytes 1115 than requested 8192
2024-09-12 08:48:58.028 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:58.029 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:58.188 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:58.189 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:48:58.286 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:58.287 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:58.391 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:58.392 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:48:58.502 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:58.503 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:58.597 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:58.598 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:48:58.695 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:48:58.696 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:48:58.798 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:48:58.799 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:00.486 [debug]: UPnP received audio data request from 18874324 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:00.486 [debug]: UPnP sending audio from 1:46 playing 0:10 loaded to 4:38 from 18874324 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:04.226 [debug]: UPnP received audio data request from 19922900 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:04.226 [debug]: UPnP sending audio from 1:52 playing 0:13 loaded to 4:38 from 19922900 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:08.016 [debug]: UPnP received audio data request from 20971476 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:08.016 [debug]: UPnP sending audio from 1:58 playing 0:17 loaded to 4:38 from 20971476 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:11.803 [debug]: UPnP received audio data request from 22020052 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:11.803 [debug]: UPnP sending audio from 2:4 playing 0:21 loaded to 4:38 from 22020052 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:15.541 [debug]: UPnP received audio data request from 23068628 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:15.541 [debug]: UPnP sending audio from 2:10 playing 0:24 loaded to 4:38 from 23068628 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:19.280 [debug]: UPnP received audio data request from 24117204 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:19.280 [debug]: UPnP sending audio from 2:16 playing 0:28 loaded to 4:38 from 24117204 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:23.067 [debug]: UPnP received audio data request from 25165780 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:23.067 [debug]: UPnP sending audio from 2:22 playing 0:32 loaded to 4:38 from 25165780 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:25.846 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:25.847 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:25.940 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:25.941 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:26.805 [debug]: UPnP received audio data request from 26214356 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:26.806 [debug]: UPnP sending audio from 2:28 playing 0:35 loaded to 4:38 from 26214356 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:28.498 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:28.499 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:28.802 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:28.803 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:31.211 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:31.212 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:31.366 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:31.367 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:31.670 [debug]: UPnP received audio data request from 27262932 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:31.670 [debug]: UPnP sending audio from 2:34 playing 0:41 loaded to 4:38 from 27262932 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:34.437 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:34.439 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:34.540 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:34.541 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:34.650 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:34.651 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:34.745 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:34.746 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:37.201 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:37.202 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:37.309 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:37.310 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:37.407 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:37.407 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:37.509 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:37.510 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:37.609 [debug]: UPnP received audio data request from 28311508 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:37.609 [debug]: UPnP sending audio from 2:40 playing 0:47 loaded to 4:38 from 28311508 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:37.622 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:37.622 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:37.715 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:37.717 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:37.815 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:37.816 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:37.918 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:37.919 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:38.018 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:38.019 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:38.125 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:38.126 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:38.226 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime
2024-09-12 08:49:38.227 [debug]: UPnP Received new transport state TRANSITIONING
2024-09-12 08:49:38.339 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:38.340 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:41.648 [debug]: UPnP Received updated transport actions:Play,Stop
2024-09-12 08:49:41.649 [debug]: UPnP Received new transport state PAUSED_PLAYBACK
2024-09-12 08:49:44.067 [debug]: UPnP Received updated transport actions:Stop,Seek,X_DLNA_SeekTime,Pause
2024-09-12 08:49:44.068 [debug]: UPnP Received new transport state PLAYING
2024-09-12 08:49:45.853 [debug]: UPnP received audio data request from 29360084 for 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:45.853 [debug]: UPnP sending audio from 2:46 playing 0:52 loaded to 4:38 from 29360084 for 1048576 requested 1048576 loaded 49161504 from buffer 0 trackId 0
2024-09-12 08:49:47.032 [debug]: UPnP Received updated transport actions:Play,Stop
2024-09-12 08:49:47.033 [debug]: UPnP Received new transport state PAUSED_PLAYBACK