ROON / HQPLAYER stops when new track sample rate changes

hammer · November 18, 2017, 12:23am

Maybe since the error I see when the music stops is something like “ Roon has lost connection to transport.” But I wonder why it’s only an issue when the file resolution changes…since if it’s a bandwidth issue, the resolution change should not matter. Theoretically…

brian · November 18, 2017, 12:27am

That message means that HQPlayer went through an un-anticipated state transition during a period where Roon expected to be in control of HQPlayer.

For example, it shows if you press “stop” or “next” or “pause” on the HQPlayer interface during Roon playback–Roon sees a transition that it did not deliberately cause, so it releases control + shows that message. That is the main purpose of the message/stopping behavior–to react gracefully if the user tries to take back control while Roon is operating HQPlayer. It seems like that is being triggered at an inappropriate time.

I’m sure you’re not mashing buttons on the HQPlayer side…so this suggests that maybe there’s a situation during one of these rate changes where extra state transitions are flying around. There is a lot going on during that time–maybe the expected transitions are getting out of order some proportion of the time.

Lonek · November 18, 2017, 8:02am

OK, sorry, of course you’re right - I just… I took it a little too far.
Simply, every time I try to use it - almost works…

Benno · November 18, 2017, 1:14pm

Second trial day again no issues, everything just worked fine for several hours.
I should mention that i did not do an OS reboot straight after the Roon update. Could this have caused the error?

Robohips · November 18, 2017, 1:36pm

Would it be useful if I reproduce the error and send you the Roon & HQP log files?

brian · November 18, 2017, 6:51pm

That’s about 30% likely to be useful. Reproducing it here would be much better. But it’s not a bad idea if we don’t have a better one. @eric, can you assist with getting logs into a ticket for this?

Robohips · November 19, 2017, 4:16am

Last night I tried to reproduce this problem and couldn’t after around 30 tracks. Tried again today and it happened on the 3rd track. It stopped on a 44/16 track after playing a 96/24 track and is consistently reproducible now.
Screen shots of HQP and Roon taken at stop point.

Roon & HQP logs

jussi_laako · November 19, 2017, 9:55am

From the HQPlayer log I notice a discrepancy that could be related. Normally command sequence is:

Playlist clear
Playlist add
Play
Pause
Stop

But when things possibly fail it becomes:

Playlist clear
Playlist add
Pause
Play
Stop

And in the latter case the preceding track actually managed to finish playing by reaching end of track, in this case meaning Roon stopped sending data and dropped connection on the data stream. Example case:

2017/11/19 14:44:56 End of track
& 2017/11/19 14:44:56 Next
2017/11/19 14:44:56 Stop request (tail)
& 2017/11/19 14:44:56 Playlist clear
& 2017/11/19 14:44:56 Playlist add URI: http://127.0.0.1:9102/21314e68927d4c42942bba7d1366cfb3/stream.raw
& 2017/11/19 14:44:56 Pause
& 2017/11/19 14:44:56 Play
& 2017/11/19 14:44:56 Stop

So I think the problem is timing whether Roon happens to kill the data stream first and then begins to prepare next track or vice versa. And I get feeling that the latter case where Roon asks stop first before HQPlayer finishes playing the track is what works. However, for normal track transition (non-interactive end-of-track, not next-click) that has the down side that possibly tail of the track gets cut short in the transition, so short amount of audio from end of the track may not be played.

For seamless transition Roon could just call “Playlist add” with a new URL and queued=“1” attribute and let HQPlayer automatically transition to the next track. That will happen when end of the preceding track is reached (connection dropped). IOW, this procedure would match the UPnP’s SetNextTransportURI call.

brian · November 19, 2017, 11:54pm

Playlist clear
Playlist add
Play
Pause
Stop

But when things possibly fail it becomes:

Playlist clear
Playlist add
Pause
Play
Stop

Roon is not sending any Pause commands, just the other four–any idea where that pause command coming from?

This is what it looks like on our end, slightly cleaned for readability:

SENT <?xml version="1.0" encoding="utf-8"?><PlaylistClear />
SENT <?xml version="1.0" encoding="utf-8"?><PlaylistAdd uri="http://127.0.0.1:9102/d51d956e6c76479eb140f71d509002c0/stream.raw" queued="0" />
GOT HTTP REQUEST Head /d51d956e6c76479eb140f71d509002c0/stream.raw
GOT HTTP REQUEST Head /d51d956e6c76479eb140f71d509002c0/stream.raw
State transition Stopped => WaitForHttpGet
SENT <?xml version="1.0" encoding="utf-8"?><Play />
GOT HTTP REQUEST Head /d51d956e6c76479eb140f71d509002c0/stream.raw
GOT <?xml version="1.0" encoding="UTF-8"?><Play result="OK"/>
GOT <?xml version="1.0" encoding="UTF-8"?><Status state="1" track="1" min="0" sec="0" clips="0"/>
GOT <?xml version="1.0" encoding="UTF-8"?><Status state="1" track="1" min="0" sec="0" clips="0"/>

Roon is then stuck in a state where it’s waiting for the HTTP GET for the stream to come–but the GET never comes, so streaming never starts.

Is it possible that pause is happening implicitly after PlaylistAdd internal to HQPlayer and that is racing against our other commands?

I agree that this would be a better approach–we tried this two years ago, and it resulted in a series of difficult to pin down problems at transitions (similar symptom to what’s in this thread).

After a few rounds of trying/failing to fix the problems, I moved us over to the more harsh “stop, clear, play again” approach because it was more reliable, and it was difficult iterating on the issue in public over and over. This has other tradeoffs–the big one being that the DAC is released on transitions unnecessarily which can make pops/clicks for some people.

We have a better system for remote feature-switches now…so could experiment with this approach in a small group and see if we can make it stable again.

jussi_laako · November 20, 2017, 10:05am

At least it used to send Pause before Stop when user stops playback from the GUI. I have not checked recently though…

But in this case, looking at the log I think it is double-Play = Pause. From the log in question here I can see cases in the log where Roon is not sending Stop before playlist operations and cases where it is…

This one looks normal:

& 2017/11/19 14:44:43 Stop

2017/11/19 14:44:43 Network engine stopping…

2017/11/19 14:44:44 Network engine stopped

2017/11/19 14:44:44 Playback engine stopped
& 2017/11/19 14:44:44 Playlist clear
& 2017/11/19 14:44:44 Playlist add URI: http://127.0.0.1:9102/5294420dd9b0416488e8c9cfa67ebf25/stream.raw
2017/11/19 14:44:44 Automatic output rate switching enabled
2017/11/19 14:44:44 Set convolution: 1
& 2017/11/19 14:44:44 Play

2017/11/19 14:44:44 Playback engine running

While this one looks problematic:

2017/11/19 14:44:56 End of track
& 2017/11/19 14:44:56 Next
2017/11/19 14:44:56 Stop request (tail)
& 2017/11/19 14:44:56 Playlist clear
& 2017/11/19 14:44:56 Playlist add URI: http://127.0.0.1:9102/21314e68927d4c42942bba7d1366cfb3/stream.raw
& 2017/11/19 14:44:56 Pause
& 2017/11/19 14:44:56 Play
& 2017/11/19 14:44:56 Stop

2017/11/19 14:44:56 Network engine stopping…

In the latter case playback has not stopped yet and then new play request is fired (while not stopped) and the engine goes to pause function, sees that engine is not anymore in normal playing state and fires “start playback in paused mode”. This happens because on Desktop version the control API is wired to the GUI to keep it in sync with activity and not directly to the engine like in the Embedded version. So likely HQPlayer Embedded behaves nicer in this case.

What was the state of HQPlayer engine when this sequence started? One challenge with this combination of things is that it is not atomic, so one needs to pay attention to what is happening to the previous stream too while issuing this sequence in case the engine is not in stopped mode…

brian · November 21, 2017, 3:45am

<?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>

This is the last state before the sequence. What is state="3" in your world?

jussi_laako · November 21, 2017, 9:38am

State enumerations can be found from ControlInterface.hpp in the source code:
enum State
{
STATE_STOPPED = 0,
STATE_PAUSED,
STATE_PLAYING,
STATE_STOPREQ,
};

STOPREQ is a transitional state when engine is requesting to be stopped. Then the controlling entity will proceed with Stop one way or the other. In normal cases this state happens when end of track is reached. In this case, Roon has terminated the currently ongoing stream. STOPREQ can reach other states only via STOPPED state. When you encounter STOPREQ, you can just wait for the transition to STOPPED to happen.

You can keep the engine hanging in PLAYING state for a short period by keeping the stream connection alive, even if you don’t provide more data over it anymore. Track is considered finished when the connection is dropped (normal HTTP way). HQPlayer will kick out the connection anyway if there’s severe enough delay on providing more data though (~10 seconds).

So for clean automatic transition the new URI should be up on the playlist before the previous disappears through terminated connection.

brian · November 21, 2017, 4:55pm

When was STATE_STOPREQ introduced? I’m pretty sure it was not there in the original interface–it’s missing from the enum on our end. This is probably the problem. We are treating it roughly the same as STOPPED because it’s an unknown/unexpected value.

jussi_laako · November 21, 2017, 5:42pm

Ii has always been there, at least as long as I can possibly remember. The state values come straight from the engine. HQPlayer Embedded introduced an additional state, but that is hidden from the control API and reported as STOPPED, so the number of reported states is the same.

brian · November 21, 2017, 11:02pm

Hm, pretty sure my enum was a mechanical translation of yours, but I don’t have the original header file from 2015 anymore to prove it…

Anyways…I’ve fooled around a little bit more and finally got this to happen once or twice. I’m using an ultraRendu running NAA into a Chord Mojo. It’s upsampling PCM to 384kHz but leaving DSD alone, and I get the failure on 88.2kHz -> DSD transitions, maybe 1 in 10 times.

When Roon hits a sample rate transition it closes the HTTP stream after the last sample at the old rate. Then it waits for HQPlayer transition into “Stopped”. After that, Roon begins the sequence for queueing the next track.

In the current code, where we are treating STOPREQ as STOPPED, this causes us to transition while things are still in flight on the HQPlayer side–this is what you noticed above. I fixed that, and now STOPREQ is treated separately, and we are properly waiting for STOPPED

However–the bug still occurs. This is an example of a transition that I reproduced today after making that change.

It looks like sometimes HQPlayer gets “stuck” in STOPREQ and fails to move on to STOPPED:

00:24:54.921 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="2" clips="0"/>
00:24:55.972 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="3" clips="0"/>
00:24:56.922 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="4" clips="0"/>
00:24:57.872 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="5" clips="0"/>
00:24:58.972 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="6" clips="0"/>
00:24:59.922 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="7" clips="0"/>
00:25:00.872 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="8" clips="0"/>
00:25:01.973 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="9" clips="0"/>
00:25:02.922 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="10" clips="0"/>
00:25:03.972 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="11" clips="0"/>
00:25:04.923 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="12" clips="0"/>
00:25:05.872 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="13" clips="0"/>
00:25:06.019 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/> <-- looks like HQPlayer reached the end
00:25:06.023 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/> <-- of the track here and entered STOPREQ
00:25:06.060 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.122 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.219 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.319 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.419 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.569 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.669 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.769 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.870 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
00:25:06.871 GOT <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>

Minutes later, Roon has received no further state updates. We are looking for a transition into STOPPED in order to proceed. Pressing “Next” in Roon causes playback to continue…so the control connection is clearly still up and in order.

Any idea what’s happening?

jussi_laako · November 21, 2017, 11:46pm

Could be in some very early version, but I’ve been updating the source code package on my web page whenever there are new features (just uploaded one for upcoming 3.19 version). First final release hqp-control source package for HQPlayer 3.8.0 from July 2015 contains this:
enum State
{
STATE_STOPPED = 0,
STATE_PAUSED,
STATE_PLAYING,
STATE_STOPREQ,
STATE_IDLE
};
Now the IDLE state is removed and instead STOPPED is always reported because they are functionally equivalent. HQPlayer Desktop doesn’t have IDLE in first place at all, it is feature of Embedded.

Does it ever happen with local (no NAA) playback? Because tracing this down with NAA adds more variables in play… I wonder which NAA version is in the ultraRendu. HQPlayer logs would tell that…

Typical time for stopping is about 1 - 1.5 seconds. If the audio device is stuck, it can be about 10 - 15 seconds.

For comparison it would be useful to see corresponding logs from both HQPlayer and NAA (networkaudiod trace) to know what is going on. Otherwise it is sort of black box. By default networkaudiod outputs trace to stderr, but can be directed to a file by setting NETWORKAUDIOD_LOGFILE environment variable to point to a file. Usually easiest way to check the NAA co-operation is to run networkaudiod on the same machine where HQPlayer is running, then it is easier to observe. Alternatively manually running networkaudiod over ssh shell on a remote box.

brian · November 22, 2017, 12:20am

Not sure. The reports in this thread seemed to involve NAA. I set it up that way to replicate.

Ok. this is definitely well beyond those timeframes.

At the point where I captured these logs, both were in the stuck state (still reporting STOPREQ), and no further actions were taken.

NAA:

  2017/11/21 19:14:51 networkaudiod Copyright (C) 2011-2017 Jussi Laako / Signalyst. All rights reserved.
  2017/11/21 19:14:51 asoundlib version: 1.1.1
+ 2017/11/21 19:16:32 connection from [::ffff:192.168.1.147]:61497
- 2017/11/21 19:16:32 ALSA backend uninitialized
  2017/11/21 19:16:32 Set channels: 2 (2)
  2017/11/21 19:16:32 ALSA device: hw:0,0
  2017/11/21 19:16:32 ALSA access mode: 3
  2017/11/21 19:16:32 ALSA PCM format: S32_LE
  2017/11/21 19:16:32 ALSA PCM bits: 32
  2017/11/21 19:16:32 ALSA PCM physical width: 32
  2017/11/21 19:16:32 ALSA PCM rates: 32000 - 768000
  2017/11/21 19:16:32 ALSA DSD not supported
  2017/11/21 19:16:32 ALSA rate available: 32000
  2017/11/21 19:16:32 ALSA rate available: 44100
  2017/11/21 19:16:32 ALSA rate available: 48000
  2017/11/21 19:16:32 ALSA rate available: 88200
  2017/11/21 19:16:32 ALSA rate available: 96000
  2017/11/21 19:16:32 ALSA rate available: 176400
  2017/11/21 19:16:32 ALSA rate available: 192000
  2017/11/21 19:16:32 ALSA rate available: 352800
  2017/11/21 19:16:32 ALSA rate available: 384000
  2017/11/21 19:16:32 ALSA rate available: 705600
  2017/11/21 19:16:32 ALSA rate available: 768000
+ 2017/11/21 19:16:32 ALSA backend initialized
  2017/11/21 19:16:32 ALSA PCM format available: 32000/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 44100/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 48000/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 88200/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 96000/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 176400/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 192000/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 352800/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 384000/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 705600/32/2
  2017/11/21 19:16:32 ALSA PCM format available: 768000/32/2
+ 2017/11/21 19:16:32 start 768000/32/2 [pcm]
  2017/11/21 19:16:32 Set channels: 2 (2)
  2017/11/21 19:16:32 Set sampling rate: 768000 (768000)
+ 2017/11/21 19:16:32 ALSA engine starting...
  2017/11/21 19:16:32 ALSA channels: 2 - 2
  2017/11/21 19:16:32 ALSA active channels: 2
  2017/11/21 19:16:32 ALSA number of periods: 2
  2017/11/21 19:16:32 ALSA period times: 125 - 85334
  2017/11/21 19:16:32 ALSA period sizes: 96 - 65536
  2017/11/21 19:16:32 ALSA period time: 50000
  2017/11/21 19:16:32 ALSA period size: 38400
+ 2017/11/21 19:16:32 ALSA engine started at: 768000 (768000)
+ 2017/11/21 19:16:32 ALSA engine running...
  2017/11/21 19:16:32 enter streaming mode
  2017/11/21 19:17:00 leave streaming mode
- 2017/11/21 19:17:00 stop
- 2017/11/21 19:17:00 ALSA engine stopping...
- 2017/11/21 19:17:01 ALSA engine stop request...
- 2017/11/21 19:17:01 ALSA engine stopped
  2017/11/21 19:17:34 begin disconnection
- 2017/11/21 19:17:34 ALSA backend uninitialized
- 2017/11/21 19:17:34 disconnected [::ffff:192.168.1.147]:61497
* 2017/11/21 19:17:40 discovery from [::ffff:192.168.1.147]:49297
* 2017/11/21 19:17:40 discovery from [::ffff:192.168.1.147]:49297
+ 2017/11/21 19:17:41 connection from [::ffff:192.168.1.147]:61499
  2017/11/21 19:17:41 Found ALSA device: hw:0,0 - Mojo: USB Audio
  2017/11/21 19:17:41 begin disconnection
- 2017/11/21 19:17:41 ALSA backend uninitialized
- 2017/11/21 19:17:41 disconnected [::ffff:192.168.1.147]:61499
+ 2017/11/21 19:17:41 connection from [::ffff:192.168.1.147]:61500
- 2017/11/21 19:17:41 ALSA backend uninitialized
  2017/11/21 19:17:41 ALSA access mode: 3
  2017/11/21 19:17:41 ALSA PCM format: S32_LE
  2017/11/21 19:17:41 ALSA PCM bits: 32
  2017/11/21 19:17:41 ALSA PCM physical width: 32
  2017/11/21 19:17:41 ALSA PCM rates: 32000 - 768000
  2017/11/21 19:17:41 ALSA DSD not supported
  2017/11/21 19:17:41 ALSA rate available: 32000
  2017/11/21 19:17:41 ALSA rate available: 44100
  2017/11/21 19:17:41 ALSA rate available: 48000
  2017/11/21 19:17:41 ALSA rate available: 88200
  2017/11/21 19:17:41 ALSA rate available: 96000
  2017/11/21 19:17:41 ALSA rate available: 176400
  2017/11/21 19:17:41 ALSA rate available: 192000
  2017/11/21 19:17:41 ALSA rate available: 352800
  2017/11/21 19:17:41 ALSA rate available: 384000
  2017/11/21 19:17:41 ALSA rate available: 705600
  2017/11/21 19:17:41 ALSA rate available: 768000
+ 2017/11/21 19:17:41 ALSA backend initialized
  2017/11/21 19:17:41 ALSA PCM format available: 32000/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 44100/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 48000/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 88200/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 96000/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 176400/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 192000/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 352800/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 384000/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 705600/32/2
  2017/11/21 19:17:41 ALSA PCM format available: 768000/32/2
+ 2017/11/21 19:18:21 start 768000/32/2 [pcm]
  2017/11/21 19:18:21 Set channels: 2 (2)
  2017/11/21 19:18:21 Set sampling rate: 768000 (768000)
+ 2017/11/21 19:18:21 ALSA engine starting...
  2017/11/21 19:18:21 ALSA channels: 2 - 2
  2017/11/21 19:18:21 ALSA active channels: 2
  2017/11/21 19:18:21 ALSA number of periods: 2
  2017/11/21 19:18:21 ALSA period times: 125 - 85334
  2017/11/21 19:18:21 ALSA period sizes: 96 - 65536
  2017/11/21 19:18:21 ALSA period time: 50000
  2017/11/21 19:18:21 ALSA period size: 38400
+ 2017/11/21 19:18:21 ALSA engine started at: 768000 (768000)
+ 2017/11/21 19:18:21 ALSA engine running...
  2017/11/21 19:18:21 enter streaming mode
  2017/11/21 19:18:25 leave streaming mode
- 2017/11/21 19:18:25 stop
- 2017/11/21 19:18:25 ALSA engine stopping...
- 2017/11/21 19:18:26 ALSA engine stop request...
- 2017/11/21 19:18:26 ALSA engine stopped
+ 2017/11/21 19:18:26 start 768000/32/2 [pcm]
  2017/11/21 19:18:26 Set channels: 2 (2)
  2017/11/21 19:18:26 Set sampling rate: 768000 (768000)
+ 2017/11/21 19:18:26 ALSA engine starting...
  2017/11/21 19:18:26 ALSA channels: 2 - 2
  2017/11/21 19:18:26 ALSA active channels: 2
  2017/11/21 19:18:26 ALSA number of periods: 2
  2017/11/21 19:18:26 ALSA period times: 125 - 85334
  2017/11/21 19:18:26 ALSA period sizes: 96 - 65536
  2017/11/21 19:18:26 ALSA period time: 50000
  2017/11/21 19:18:26 ALSA period size: 38400
+ 2017/11/21 19:18:26 ALSA engine started at: 768000 (768000)
+ 2017/11/21 19:18:26 ALSA engine running...
  2017/11/21 19:18:26 enter streaming mode
  2017/11/21 19:18:35 leave streaming mode
- 2017/11/21 19:18:35 stop
- 2017/11/21 19:18:35 ALSA engine stopping...
- 2017/11/21 19:18:36 ALSA engine stop request...
- 2017/11/21 19:18:36 ALSA engine stopped

HQPlayer:

* 2017/11/21 19:17:35 Starting...
  2017/11/21 19:17:35 Signalyst HQPlayer Desktop v3.18.2
  2017/11/21 19:17:35 Engine selected: 
* 2017/11/21 19:17:35 Control server started
  2017/11/21 19:17:40 Restore GUI state
  2017/11/21 19:17:40 libDSP version 19.0.1
  2017/11/21 19:17:40 Number of processor cores: 4
  2017/11/21 19:17:40 DSP thread pools disabled
  2017/11/21 19:17:40 Pipelined DSP enabled
  2017/11/21 19:17:40 Audio engine: network
  2017/11/21 19:17:40 Network Audio IPv6 support disabled
  2017/11/21 19:17:40 Discovery from 0.0.0.0
& 2017/11/21 19:17:40 Discovered network audio: name='default' version='Signalyst Network Audio Daemon 3.5.1'  @192.168.1.119:43210
& 2017/11/21 19:17:40 Discovered network audio: name='default' version='Signalyst Network Audio Daemon 3.5.1'  @192.168.1.119:43210
  2017/11/21 19:17:41  Network endpoint: Mojo: USB Audio (hw:0,0)
  2017/11/21 19:17:41 Discovered 1 Network Audio Adapters
  2017/11/21 19:17:41 Set channels: 2 (2)
  2017/11/21 19:17:41 DAC bits: 32
  2017/11/21 19:17:41 SDM packing: 1
+ 2017/11/21 19:17:41 Connect to 192.168.1.119:43210
  2017/11/21 19:17:41 Network format: 32000/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 44100/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 48000/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 88200/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 96000/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 176400/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 192000/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 352800/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 384000/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 705600/32/2 [pcm] 
  2017/11/21 19:17:41 Network format: 768000/32/2 [pcm] 
  2017/11/21 19:17:41 Volume limit: 0
  2017/11/21 19:17:41 Automatic rate family disabled
  2017/11/21 19:17:41 DirectSDM enabled
  2017/11/21 19:17:41 SDM conversion parameters (0, 0)
  2017/11/21 19:17:41 DSD 6 dB gain disabled
  2017/11/21 19:17:41 Initial parallel threads: 8
  2017/11/21 19:17:41 Number of logical cores: 8
  2017/11/21 19:17:41 Set filter: 6
  2017/11/21 19:17:41 Set dither: 5
  2017/11/21 19:17:41 Set filter: 6
  2017/11/21 19:17:41 Set oversampling: 9
  2017/11/21 19:17:41 Set dither: 5
  2017/11/21 19:17:41 Set modulator: 2
  2017/11/21 19:17:41 Automatic output rate switching enabled
  2017/11/21 19:17:41 AutoSDM enabled
  2017/11/21 19:17:41 SDM conversion parameters (0, 0)
  2017/11/21 19:17:41 DSD 6 dB gain disabled
  2017/11/21 19:17:41 Audio engine PCM mode enabled
  2017/11/21 19:17:41 Set filter: 6
  2017/11/21 19:17:41 Set oversampling: 9
  2017/11/21 19:17:41 Set dither: 5
  2017/11/21 19:17:41 Set modulator: 2
  2017/11/21 19:17:41 Automatic output rate switching enabled
* 2017/11/21 19:17:41 Control server started for remote control
& 2017/11/21 19:17:41 Stop
& 2017/11/21 19:17:41 Playlist clear
& 2017/11/21 19:17:41 Set transport (240): C:\Users\brian\AppData\Local\HQPlayer\current.m3u8
# 2017/11/21 19:17:41 clPlaylist::AddURI("http://192.168.1.239:9102/dede33f3d6a7473cb83ae1a4d10ba053/stream.raw"): clStreamReaderHTTP::GetHead(): 404
# 2017/11/21 19:17:41 clMainWindow::setTransport(): clHQPlayerEngine::SetTransport(): failed
& 2017/11/21 19:17:42 Stop
& 2017/11/21 19:18:20 Playlist clear
& 2017/11/21 19:18:20 Playlist clear
& 2017/11/21 19:18:20 Stop
& 2017/11/21 19:18:20 Set transport (240): 
  2017/11/21 19:18:20 Automatic output rate switching enabled
& 2017/11/21 19:18:20 Playlist add URI: http://192.168.1.239:9102/4059064d2edc4539b903831931ec13dd/stream.raw
  2017/11/21 19:18:20 Automatic output rate switching enabled
  2017/11/21 19:18:20 Set convolution: 1
& 2017/11/21 19:18:20 Play
+ 2017/11/21 19:18:20 Playback engine running
- 2017/11/21 19:18:20 Network engine stopping...
  2017/11/21 19:18:20 Set sampling rate: 768000 (768000)
  2017/11/21 19:18:20 Automatic output rate: 768000
  2017/11/21 19:18:20 Rate or blocksize change triggered
  2017/11/21 19:18:20 Rate: 88200, block size: 9408, frame size: 1176
  2017/11/21 19:18:20 Block size: 9408 (sample: 4)
  2017/11/21 19:18:20 Playback engine ratio: 8.70748
  2017/11/21 19:18:20 Filter: poly sinc
  2017/11/21 19:18:21 Dither: triangular probability density function for 32-bit
  2017/11/21 19:18:21 Initialization complete, starting audio engine
+ 2017/11/21 19:18:21 Network engine starting...
  2017/11/21 19:18:21 Network PCM streaming
+ 2017/11/21 19:18:21 Network engine started at: 768000
  2017/11/21 19:18:21 Parallel threads: 8
  2017/11/21 19:18:21 Nested parallelism: 0
  2017/11/21 19:18:21 Parallel pipelines: 4
& 2017/11/21 19:18:24 Stop
- 2017/11/21 19:18:24 Network engine stopping...
- 2017/11/21 19:18:26 Network engine stopped
- 2017/11/21 19:18:26 Playback engine stopped
& 2017/11/21 19:18:26 Playlist clear
& 2017/11/21 19:18:26 Playlist add URI: http://192.168.1.239:9102/f10881fa6a92486aaf59998886856af1/stream.raw
  2017/11/21 19:18:26 Automatic output rate switching enabled
  2017/11/21 19:18:26 Set convolution: 1
& 2017/11/21 19:18:26 Play
+ 2017/11/21 19:18:26 Playback engine running
  2017/11/21 19:18:26 Rate or blocksize change triggered
  2017/11/21 19:18:26 Rate: 88200, block size: 9408, frame size: 1176
  2017/11/21 19:18:26 Block size: 9408 (sample: 4)
  2017/11/21 19:18:26 Playback engine ratio: 8.70748
  2017/11/21 19:18:26 Filter: poly sinc
  2017/11/21 19:18:26 Dither: triangular probability density function for 32-bit
  2017/11/21 19:18:26 Initialization complete, starting audio engine
+ 2017/11/21 19:18:26 Network engine starting...
  2017/11/21 19:18:26 Network PCM streaming
+ 2017/11/21 19:18:26 Network engine started at: 768000
  2017/11/21 19:18:26 Parallel threads: 8
  2017/11/21 19:18:26 Nested parallelism: 0
  2017/11/21 19:18:26 Parallel pipelines: 4
  2017/11/21 19:18:34 End of track
& 2017/11/21 19:18:34 Next
  2017/11/21 19:18:34 Stop request (tail)
- 2017/11/21 19:18:35 Network engine stopping...
& 2017/11/21 19:18:35 Stop
- 2017/11/21 19:18:36 Network engine stopped
- 2017/11/21 19:18:36 Playback engine stopped

Roon (to show protocol level interaction):

11/22 00:18:25 Trace: [zoneplayer/hqplayer] In StartStream Format=StreamFormat(channels=2, bitspersample=32, samplerate=88200, isdts=False) State=Stopped
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><Stop result="OK"/>
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><PlaylistClear />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><PlaylistClear result="OK"/>
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><PlaylistAdd uri="http://192.168.1.239:9102/f10881fa6a92486aaf59998886856af1/stream.raw" queued="0" />
11/22 00:18:26 Info: [zoneplayer/hqplayer] GOT REQUEST Head /f10881fa6a92486aaf59998886856af1/stream.raw
11/22 00:18:26 Info: [zoneplayer/hqplayer] GOT REQUEST Head /f10881fa6a92486aaf59998886856af1/stream.raw
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><PlaylistAdd result="OK"/>
11/22 00:18:26 Trace: [zoneplayer/hqplayer] State transition Stopped => WaitForHttp
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><Play />
11/22 00:18:26 Info: [zoneplayer/hqplayer] GOT REQUEST Head /f10881fa6a92486aaf59998886856af1/stream.raw
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><Play result="OK"/>
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetModes />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetModes><ModesItem index="0" name="Auto" value="-1"/><ModesItem index="1" name="PCM" value="0"/><ModesItem index="2" name=
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetFilters />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetFilters><FiltersItem index="0" name="none" value="0"/><FiltersItem index="1" name="IIR" value="1"/><FiltersItem index="2
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetShapers />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetShapers><ShapersItem index="0" name="none" value="0"/><ShapersItem index="1" name="NS1" value="1"/><ShapersItem index="2
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetRates />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetRates><RatesItem index="0" rate="0"/><RatesItem index="1" rate="32000"/><RatesItem index="2" rate="44100"/><RatesItem in
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><VolumeRange />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><VolumeRange enabled="1" min="-60" max="0"/>
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><State />
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><State state="2" mode="0" filter="6" shaper="6" rate="0" volume="0" active_mode="0" active_rate="768000" invert="0" convolut
11/22 00:18:26 Info: [zoneplayer/hqplayer] GOT REQUEST Get /f10881fa6a92486aaf59998886856af1/stream.raw
11/22 00:18:26 Trace: [zoneplayer/hqplayer] State transition WaitForHttp => WaitForFirstTimeChange
11/22 00:18:26 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="0" clips="0"/>
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="1" clips="0"/>
11/22 00:18:27 Trace: [zoneplayer/hqplayer] State transition WaitForFirstTimeChange => Playing
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetModes />
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetModes><ModesItem index="0" name="Auto" value="-1"/><ModesItem index="1" name="PCM" value="0"/><ModesItem index="2" name=
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetFilters />
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetFilters><FiltersItem index="0" name="none" value="0"/><FiltersItem index="1" name="IIR" value="1"/><FiltersItem index="2
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetShapers />
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetShapers><ShapersItem index="0" name="none" value="0"/><ShapersItem index="1" name="NS1" value="1"/><ShapersItem index="2
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><GetRates />
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><GetRates><RatesItem index="0" rate="0"/><RatesItem index="1" rate="32000"/><RatesItem index="2" rate="44100"/><RatesItem in
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><VolumeRange />
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><VolumeRange enabled="1" min="-60" max="0"/>
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] SENT <?xml version="1.0" encoding="utf-8"?><State />
11/22 00:18:27 Trace: [hqp/client] [192.168.1.147:4321] GOT <?xml version="1.0" encoding="UTF-8"?><State state="2" mode="0" filter="6" shaper="6" rate="0" volume="0" active_mode="0" active_rate="768000" invert="0" convolut
11/22 00:18:28 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="2" clips="0"/>
11/22 00:18:29 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="3" clips="0"/>
11/22 00:18:30 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="4" clips="0"/>
11/22 00:18:31 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="5" clips="0"/>
11/22 00:18:32 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="6" clips="0"/>
11/22 00:18:33 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="7" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="2" track="1" min="0" sec="8" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:34 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:35 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:35 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:35 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>
11/22 00:18:35 Trace: [hqp/client] [192.168.1.147:4321] GOT UNSOLICITED <?xml version="1.0" encoding="UTF-8"?><Status state="3" track="0" min="0" sec="0" clips="0"/>

jussi_laako · November 22, 2017, 1:26am

OK, now I know what goes wrong! “Status” subscription messages are fired asynchronously from the engine as it proceeds. But not anymore when it has stopped. If it happens to manage sometime send state=“0” it is because of the asynchronous nature.

For next HQPlayer release I try to make it explicitly fire last Status update for stopped state which should take care of this.

In addition, “State” command asks explicitly state information and happens outside of the engine.

brian · November 22, 2017, 2:27am

Ok, glad it’s worked out. I’ll keep the fix to handle STOPREQ so it rolls out on our end. Let me know if you have an updated version to look at and I can confirm it…I have a pretty good handle on how to reproduce this now.

andybob · November 22, 2017, 3:06am

Fascinating insight into the complexities and processes under the hood. Congratulations Jussi and Brian on busting this bug.