On playing a new song to the HifiBerry Roon endpoint, it will usually stop streaming at precisely 4 seconds.
This occurs on both streaming (qobuz) and local media files stored on the same computer as the Roon Core.
This does not occur when streaming to from Roon to other network streamers on my network (i.e LG soundbar via Chromcast, Apple TV, Airport Express Airplay)
Detail:
Roon Core 1.8 (814) on Macbook 12" 2015 (11.5.2)
HiFiBerryOS 20210804
Digi 2 Pro
DSP module
Looks like a bug in the pause script. Do you have other players enabled?
Roon player is installed on a few devices. I usually use the player on a Macbook to control most session activity. Occasionally i'll pick up the iphone or ipad.
Sorry, I meant other players in HiFiBerryOS.
No, just Roon.
and WI-fi disabled.
DSP running a room correction (was running without DSP and same issue)
I've not tried without DSP board; as i'm not keen to pull it all apart :-)
I have faced same issue on raspberry pi 4 with Digi2 pro and DSP. I have tried to enable Roon only on HiFiBerry OS 20210804, there is no luck.
I have removed DSP module from Digi 2 Pro and rebooted, this issue was gone.
That's strange as the DSP should not have any impact on this. However, this might help finding the root cause of this bug.
Interesting . . .I will remove my DSP module and confirm my results first chance i have.
I have tried to re-produce again.
Re-produce step:
1. Play music on roon.
2. Stop playing music and close Roon app.
3. Run Roon app and play music again.
journalctl -f /opt/raat/raat_app
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000845] [t1927275472] 848.666 TRACE [lua@0xc01314] [192.168.8.4:48532] GOT [944] {"request":"setup","format":{"sample_type":"pcm","sample_rate":44100,"bits_per_sample":16,"channels":2,"sample_subtype":"none"}}
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000846] [t1927275472] 848.667 TRACE [transport/hifiberry] received update artwork
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000847] [t1927275472] 848.667 TRACE [transport/hifiberry] /tmp/filePl6rL5.jpg file deleted successfully.
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000848] [t1927275472] 848.667 TRACE [transport/hifiberry] image/jpeg
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000849] [t1927275472] 848.668 TRACE [transport/hifiberry] /tmp/fileiYQAV6.jpg
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000850] [t1927275472] 848.668 TRACE [transport/hifiberry] stored artwork at /tmp/fileiYQAV6.jpg
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000851] [t1927275472] 848.668 TRACE [transport/hifiberry] filename /tmp/fileiYQAV6.jpg
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000852] [t1927275472] 848.668 TRACE [mpris] MPRIS artwork watcher called
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000853] [t1927275472] 848.668 TRACE [transport/hifiberry] processed update artwork
Aug 24 22:59:06 hifiberry-shibuya raat_app[726]: [0000854] [t1927275472] 848.673 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Aug 24 22:59:07 hifiberry-shibuya raat_app[726]: [0000855] [t1977611216] 849.557 TRACE [transport/hifiberry] sending pause
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000856] [t1927275472] 857.318 TRACE [alsa] stopped
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000857] [t1927275472] 857.319 TRACE alsa output setup: format is pcm 44100/16/2
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000858] [t1927275472] 857.319 TRACE opening [default] 44100/16/2
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000859] [t1927275472] 857.322 TRACE prefer larger samples = 0
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000860] [t1927275472] 857.323 TRACE [ALSA] [default] using hw pcmformat S16_LE bitspersample 16
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000861] [t1927275472] 857.325 TRACE [ALSA] [default] Requesting 2 periods
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000862] [t1927275472] 857.326 TRACE [ALSA] [default] Requesting 1764 frames/buffer (882 frames/period)
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000863] [t1927275472] 857.327 TRACE [ALSA] [default] Initialized with 2 periods with 882 frames/period and 1764 frames/buffer
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000864] [t1956639696] 857.330 TRACE sched_setscheduler succeeded
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000865] [t1956639696] 857.330 TRACE samples per buf 882 ns per buf 20000000 samplerate 44100
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000866] [t1956639696] 857.330 TRACE 882 samples per buf, 3528 bytes per buf, 3528 bytes per hwbuf
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000867] [t1956639696] 857.330 TRACE [output/alsa] [default] waiting for device to be ready
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000868] [t1956639696] 857.330 TRACE [output/alsa] [default] device is ready
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000869] [t1927275472] 857.338 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [4] {"status":"Success","control":{"button":"pause"}}
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000870] [t1927275472] 857.339 TRACE [lua@0xc01314] [192.168.8.4:48532] got output message {"signal_path": [{"quality": "lossless", "type": "output", "method": "digital"}]}
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000871] [t1927275472] 857.340 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [944] {"status":"OutputMessage","message":{"signal_path":[{"method":"digital","type":"output","quality":"lossless"}]}}
Aug 24 22:59:14 hifiberry-shibuya raat_app[726]: [0000872] [t1927275472] 857.371 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [944] {"status":"Success","audio_port":0,"audio_port_tcp":45119,"clock_port":34507}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000873] [t1927275472] 857.426 TRACE [lua@0xc01314] [192.168.8.4:48532] GOT [947] {"request":"stream","stream_id":354283426,"first_seq":-1,"nak_port":-1,"buffer_size":10,"ready_threshold":0.2}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000874] [t1927275472] 857.426 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [947] {"status":"Buffering"}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000875] [t1927275472] 857.486 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [947] {"status":"Ready"}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000876] [t1927275472] 857.491 TRACE [lua@0xc01314] [192.168.8.4:48532] GOT [948] {"request":"start","min_offset":59727891,"stream_sample":0}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000877] [t1927275472] 857.491 TRACE [lua@0xc01314] [192.168.8.4:48532] Doing ASAP start based on current device clock (min_offset=59727891)
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000878] [t1927275472] 857.492 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [947] {"status":"Playing"}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000879] [t1927275472] 857.492 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [948] {"status":"Success","time":869694672251}
Aug 24 22:59:15 hifiberry-shibuya raat_app[726]: [0000880] [t1956639696] 857.510 TRACE starting playback: now (869693741496ns) + ns_per_buf(20000000ns) = 869713741496ns > 869694672251ns streamsample=0
4 seconds later. playng music was stopped.
Aug 24 22:59:20 hifiberry-shibuya raat_app[726]: [0000881] [t1927275472] 862.482 TRACE [lua@0xc01314] [192.168.8.4:48532] GOT [953] {"request":"end_stream"}
Aug 24 22:59:20 hifiberry-shibuya raat_app[726]: [0000882] [t1927275472] 862.482 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [947] {"status":"Ended"}
Aug 24 22:59:20 hifiberry-shibuya raat_app[726]: [0000883] [t1927275472] 862.483 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [953] {"status":"Success"}
Aug 24 22:59:20 hifiberry-shibuya raat_app[726]: [0000884] [t1927275472] 862.483 TRACE [lua@0xc01314] [192.168.8.4:48532] GOT [954] {"request":"teardown"}
Aug 24 22:59:20 hifiberry-shibuya raat_app[726]: [0000885] [t1927275472] 862.483 TRACE [alsa] teardown
Aug 24 22:59:20 hifiberry-shibuya raat_app[726]: [0000886] [t1927275472] 862.584 TRACE [lua@0xc01314] [192.168.8.4:48532] SENT [944] {"status":"Teardown"}
It seemed someone kill raat stream...
Sorry for my many post. I found following.
# journalctl -f -u beocreate2
-- Journal begins at Tue 2021-08-24 22:15:21 JST. --
Aug 24 23:46:21 hifiberry-shibuya beocreate2[4278]: Beosonic: treble is at 0.5 dB, bass is at 5.2 dB.
Aug 24 23:47:18 hifiberry-shibuya beocreate2[4278]: Checking MPD database update status...
Aug 24 23:47:28 hifiberry-shibuya beocreate2[4278]: Source 'roon' has activated.
Aug 24 23:47:35 hifiberry-shibuya beocreate2[4278]: Source 'roon' has deactivated.
Aug 24 23:48:04 hifiberry-shibuya beocreate2[4278]: Source 'roon' has activated.
Aug 24 23:48:20 hifiberry-shibuya beocreate2[4278]: Checking MPD database update status...
When playing music:
"Source 'roon' has activated." was not appeared.
Playing music was stopped at 4 seconds.
"Source 'roon' has activated." was appeared
Playing music was OK.
Regards,
Masahiro
Yes, this seems to be a bug in the pause script.
Hmm, unfortunately I can't reproduce this here. I've added a bit more logging to the script that might cause this.
You can get it here:
https://raw.githubusercontent.com/hifiberry/hifiberry-os/development/buildroot/package/hifiberry-tools/pause-all
Just download it and replace /opt/hifiberry/bin/pause-all by this version.
Then run the following to get the debug output:
Send the output when the problem occurs.
Sorry for my late response.
Thanks for releasing new pause script. I have replaced "pause-all" file. I found some small typo (Extra double quotations" and fixed them.
Unfortunately, the issue was still happened.
here is journalctl -f | grep pause-all
Sep 05 16:31:30 hifiberry-shibuya raat_app[715]: [0000766] [t1927279568] 2643.598 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 05 16:31:31 hifiberry-shibuya /bin/cat[2495]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:31 hifiberry-shibuya /bin/cat[2510]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:31 hifiberry-shibuya /bin/cat[2512]: pause-all raat (715): 20210905-163130 pause_process done, but playback still active
Sep 05 16:31:33 hifiberry-shibuya /bin/cat[2527]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:34 hifiberry-shibuya /bin/cat[2541]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:35 hifiberry-shibuya /bin/cat[2555]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:37 hifiberry-shibuya /bin/cat[2569]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:38 hifiberry-shibuya /bin/cat[2583]: pause-all raat (715): process 2387 still using the sound card
Sep 05 16:31:38 hifiberry-shibuya /bin/cat[2585]: pause-all raat (715): 20210905-163130 pause via API done, but playback still active
Sep 05 16:31:39 hifiberry-shibuya /bin/cat[2591]: pause-all raat (715): 20210905-163130 20210905-163139 raat - closed
--->>>>4 seconds stop
Sep 05 16:33:11 hifiberry-shibuya raat_app[715]: [0000808] [t1927279568] 2744.136 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 05 16:33:11 hifiberry-shibuya /bin/cat[2645]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:12 hifiberry-shibuya /bin/cat[2660]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:12 hifiberry-shibuya /bin/cat[2662]: pause-all raat (715): 20210905-163311 pause_process done, but playback still active
Sep 05 16:33:13 hifiberry-shibuya /bin/cat[2677]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:14 hifiberry-shibuya /bin/cat[2691]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:16 hifiberry-shibuya /bin/cat[2706]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:17 hifiberry-shibuya /bin/cat[2720]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:19 hifiberry-shibuya /bin/cat[2734]: pause-all raat (715): process 2600 still using the sound card
Sep 05 16:33:19 hifiberry-shibuya /bin/cat[2736]: pause-all raat (715): 20210905-163311 pause via API done, but playback still active
Sep 05 16:33:20 hifiberry-shibuya /bin/cat[2742]: pause-all raat (715): 20210905-163311 20210905-163320 raat - closed
--->>>>4 seconds stop
Sep 05 16:33:30 hifiberry-shibuya raat_app[715]: [0000850] [t1927279568] 2763.300 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 05 16:33:30 hifiberry-shibuya /bin/cat[2774]: pause-all raat (715): 20210905-163330 20210905-163330 raat - closed
---->>>> it was not occurred.
My reproduce step.
Play track then change track in another album.
--> This issue is less but it was happened some time.
Play track, then stop music, then change track in another album.
--> This issue is likely to happen.
Regards,
Masahiro
Ok, it seems that you have 2 different Roon processes running. That's strange, please post the output of
ps -ef | grep -i raat
I have tried to execute ps command.
Pushed play button but playing music has not been started.
# ps -ef | grep -i raat
root 715 1 0 Sep05 ? 00:08:34 /opt/raat/raat_app /etc/hifiberry_raat.conf
root 18259 715 1 08:29 ? 00:00:00 /bin/bash /opt/hifiberry/bin/pause-all raat
root 18373 17890 0 08:29 pts/0 00:00:00 grep -i raat
Playing music has been started.
# ps -ef | grep -i raat
root 715 1 0 Sep05 ? 00:08:34 /opt/raat/raat_app /etc/hifiberry_raat.conf
root 18397 17890 0 08:29 pts/0 00:00:00 grep -i raat
4 second stop was occurred.
Thanks,
Masahiro
Ok, I still don't understand what's causing this, we need to do a bit more debugging. I created another version of the pause-all script, please extract this again to /opt/hifiberry/bin and send the logs.
https://raw.githubusercontent.com/hifiberry/hifiberry-os/development/buildroot/package/hifiberry-tools/pause-all
The interesting line should look like
pause-all raat (XXX): process YYY/ZZZZ still using the sound card
This should give us an idea what other process is using the sound card.
Thanks for your quick replay.
I have tried to use new pause-all script.
4 seconds stop happened.
Following is log.
# journalctl -f | grep pause-all
Sep 07 06:21:04 hifiberry-shibuya raat_app[715]: [0001396] [t1927279568] 138817.383 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 07 06:21:04 hifiberry-shibuya /bin/cat[6792]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:05 hifiberry-shibuya /bin/cat[6822]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:05 hifiberry-shibuya /bin/cat[6824]: pause-all raat (715): 20210907-062104 pause_process done, but playback still active
Sep 07 06:21:06 hifiberry-shibuya /bin/cat[6841]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:08 hifiberry-shibuya /bin/cat[6855]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:09 hifiberry-shibuya /bin/cat[6869]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:10 hifiberry-shibuya /bin/cat[6883]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:12 hifiberry-shibuya /bin/cat[6897]: pause-all raat (715): process 18398/python3 still using the sound card
Sep 07 06:21:12 hifiberry-shibuya /bin/cat[6899]: pause-all raat (715): 20210907-062104 pause via API done, but playback still active
Sep 07 06:21:13 hifiberry-shibuya /bin/cat[6905]: pause-all raat (715): 20210907-062104 20210907-062113 raat - closed
--> 4 seconds stop
Sep 07 06:21:39 hifiberry-shibuya raat_app[715]: [0001438] [t1927279568] 138852.846 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 07 06:21:40 hifiberry-shibuya /bin/cat[6937]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:40 hifiberry-shibuya /bin/cat[6952]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:40 hifiberry-shibuya /bin/cat[6954]: pause-all raat (715): 20210907-062139 pause_process done, but playback still active
Sep 07 06:21:42 hifiberry-shibuya /bin/cat[6969]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:43 hifiberry-shibuya /bin/cat[6983]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:44 hifiberry-shibuya /bin/cat[6997]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:46 hifiberry-shibuya /bin/cat[7015]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:47 hifiberry-shibuya /bin/cat[7029]: pause-all raat (715): process 6910/python3 still using the sound card
Sep 07 06:21:47 hifiberry-shibuya /bin/cat[7031]: pause-all raat (715): 20210907-062139 pause via API done, but playback still active
Sep 07 06:21:48 hifiberry-shibuya /bin/cat[7037]: pause-all raat (715): 20210907-062139 20210907-062148 raat - closed
--> 4 seconds stop
Sep 07 06:22:06 hifiberry-shibuya raat_app[715]: [0001480] [t1927279568] 138879.927 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 07 06:22:07 hifiberry-shibuya /bin/cat[7068]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:07 hifiberry-shibuya /bin/cat[7095]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:07 hifiberry-shibuya /bin/cat[7097]: pause-all raat (715): 20210907-062207 pause_process done, but playback still active
Sep 07 06:22:09 hifiberry-shibuya /bin/cat[7115]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:10 hifiberry-shibuya /bin/cat[7129]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:12 hifiberry-shibuya /bin/cat[7143]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:13 hifiberry-shibuya /bin/cat[7157]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:14 hifiberry-shibuya /bin/cat[7171]: pause-all raat (715): process 7042/python3 still using the sound card
Sep 07 06:22:14 hifiberry-shibuya /bin/cat[7173]: pause-all raat (715): 20210907-062207 pause via API done, but playback still active
Sep 07 06:22:15 hifiberry-shibuya /bin/cat[7179]: pause-all raat (715): 20210907-062207 20210907-062215 raat - closed
--> 4 seconds stop
I have checked pause-all raat (715): process 7042/python3 still using the sound card
The proccess is "python3 /usr/bin/spdifclockgen"
Thank you very much,
Masahiro
I have tested more.
# journalctl -f | grep pause-all
journalctl -f | grep pause-all
Sep 07 08:39:25 hifiberry-shibuya raat_app[715]: [0001905] [t1927279568] 147118.034 TRACE [alsa] stopping other players using /opt/hifiberry/bin/pause-all
Sep 07 08:39:25 hifiberry-shibuya /bin/cat[10746]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:25 hifiberry-shibuya /bin/cat[10761]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:26 hifiberry-shibuya /bin/cat[10763]: pause-all raat (715): 20210907-083925 pause_process done, but playback still active
Sep 07 08:39:27 hifiberry-shibuya /bin/cat[10778]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:28 hifiberry-shibuya /bin/cat[10792]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:30 hifiberry-shibuya /bin/cat[10806]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:31 hifiberry-shibuya /bin/cat[10834]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:32 hifiberry-shibuya /bin/cat[10848]: pause-all raat (715): process 10718/python3 still using the sound card
Sep 07 08:39:32 hifiberry-shibuya /bin/cat[10850]: pause-all raat (715): 20210907-083925 pause via API done, but playback still active
Sep 07 08:39:34 hifiberry-shibuya /bin/cat[10856]: pause-all raat (715): 20210907-083925 20210907-083934 raat - closed
--> 4 seconds stop
Following is the pause-all script with set -x in above test.
++ aplay -l
++ grep -i hifiberry
++ awk '{print $2}'
++ sed s/://
+ CARD=0
++ date +%Y%m%d-%H%M%S
+ DATE1=20210907-083925
+ PLAYER=raat
+ CALLINGPID=715
+ '[' raat == '' ']'
+ '[' -x /opt/hifiberry/bin/report-activation ']'
+ /opt/hifiberry/bin/report-activation playercontrol_player_raat
+ ACNAME=raat
+ case $PLAYER in
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ lsof /dev/snd/pcmC0D0p
++ grep -v COMMAND
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ '[' python3 '!=' '' ']'
+ '[' -x /opt/hifiberry/bin/report-deactivation ']'
+ /opt/hifiberry/bin/report-deactivation playercontrol_player_python3
+ pause_process
+ echo python3
+ case $APP in
+ echo 'don'\''t know how to pause python3'
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ grep -v COMMAND
++ lsof /dev/snd/pcmC0D0p
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ echo 'pause-all raat (715): 20210907-083925 pause_process done, but playback still active'
+ systemd-cat
+ curl -X post http://localhost:81/api/player/pause/raat
+ echo
+ for i in 1 1 1 1 1
+ sleep 1
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ lsof /dev/snd/pcmC0D0p
++ grep -v COMMAND
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ for i in 1 1 1 1 1
+ sleep 1
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ lsof /dev/snd/pcmC0D0p
++ grep -v COMMAND
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ for i in 1 1 1 1 1
+ sleep 1
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ lsof /dev/snd/pcmC0D0p
++ grep -v COMMAND
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ for i in 1 1 1 1 1
+ sleep 1
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ lsof /dev/snd/pcmC0D0p
++ grep -v COMMAND
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ for i in 1 1 1 1 1
+ sleep 1
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS='access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072'
+ '[' 'access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 32768
buffer_size: 131072' == closed ']'
++ lsof /dev/snd/pcmC0D0p
++ grep -v COMMAND
+ PROCESSLINE='python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p
python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p'
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $1}'
+ APP=python3
++ echo python3 10718 root mem CHR 116,16 353 /dev/snd/pcmC0D0p python3 10718 root 6u CHR 116,16 0t0 353 /dev/snd/pcmC0D0p
++ awk '{print $2}'
+ PROCESSID=10718
+ [[ raat == \p\y\t\h\o\n\3\* ]]
+ '[' 10718 == 715 ']'
+ echo 'pause-all raat (715): process 10718/python3 still using the sound card'
+ systemd-cat -p info
+ echo 'pause-all raat (715): 20210907-083925 pause via API done, but playback still active'
+ systemd-cat
+ kill_process
+ '[' 10718 '!=' '' ']'
+ kill 10718
+ sleep 1
++ pgrep
+ PID=
+ '[' '' '!=' '' ']'
+ check_paused
++ cat /proc/asound/card0/pcm0p/sub0/hw_params
+ STATUS=closed
+ '[' closed == closed ']'
++ date +%Y%m%d-%H%M%S
+ DATE2=20210907-083934
+ echo 'pause-all raat (715): 20210907-083925 20210907-083934 raat - closed'
+ systemd-cat -p info
+ exit 0
I hope this may help
Regards,
Masahiro
Ok, looks like there's some other player process running. What players have you enabled?
I have enabled following.
I now think I have an idea what's going on.
Please try the following
systemctl status spdficlockgen
systemctl stop spdficlockgen
cat /etc/hifiberry.state
I have tried your instruction. It seemed it was stopped 4 seconds stop issue.
Here is hifiberry.state. It was same before stopping spdifclockgen.service.
cat /etc/hifiberry.state
CURRENT_PIMODEL=2
CURRENT_MIXER_CONTROL="DSPVolume"
CURRENT_CARD="Digi2 Pro + DSP Module"
CURRENT_HW="card 0"
CURRENT_HW_SHORT=0
CURRENT_SYSNAME="HiFiBerry-Shibuya"
CURRENT_PLAYERS=""
CURRENT_HATINFO="HiFiBerry Digi2 Pro"
CURRENT_FEATURES="pi arm7 dsp spdifnoclock toslink"
CURRENT_DSPTYPE="DSP add-on"
CURRENT_INTPIN="2"
PIVERSION=2
Thank you very much,
Masahiro
Ok, with the DSP add-on a TOSLink monitor was enabled that shouldn't be running on this board. This cause this problem. I'll upload a bugfix soon.
This is great news.
Thanks for your help troublshooting Mashiro and finding the fix HiFiBerry Team.
Should i just wait fo a fix?
I have tried running;
systemctl status spdficlockgen
but i just get this message;
Unit spdficlockgen.service could not be found.
Cheers.
#cat /etc/hifiberry.state
CURRENT_PIMODEL=4
CURRENT_MIXER_CONTROL="DSPVolume"
CURRENT_CARD="Digi2 Pro + DSP Module"
CURRENT_HW="card 0"
CURRENT_HW_SHORT=0
CURRENT_SYSNAME="HiFiBerry"
CURRENT_PLAYERS=""
CURRENT_HATINFO="HiFiBerry Digi2 Pro"
CURRENT_FEATURES="pi bluetooth pi3orlater arm7 dsp spdifnoclock toslink localui"
CURRENT_DSPTYPE="DSP add-on"
CURRENT_INTPIN="2"
PIVERSION=4
Ah, i tried;
systemctl stop spdficlockgen.service
and this seems to have fixed the 'stopping at 4 second' issue.
Thank you very much! My music backed to me with Hifiberry!!!!
I am looking forward to releasing next HifiberryOS.
Thank you very much!
Masahiro