failure in pulseaudio if the HDMI TV is temporarily powered off

[Joel-Mckay]

Raspbian Debian Stretch oct 8, 2018 apt update causes a reproducible failure in pulseaudio TV HDMI output if the TV is temporarily powered off.

This did not occur with the older Kernel 4.14.52 (with old firmware), and now also occurs on the current 4.14.70-v7+ #1144 SMP Tue Sep 18 17:34:46 BST 2018 armv7l GNU/Linux

Therefore, it may be related to the current pulseaudio or new raspbian-firmware packages
Symptoms:

1. Upon playing a video sample, there will be no sound.
2. Sound control panel test remains silent
3. Output selection may hang the sound control panel
4. cold-boot power cycle needed to recover sound functionality again

/var/log/syslog
Oct 11 02:46:08 neptune pulseaudio[1430]: [alsa-sink-MAI PCM vc4-hdmi-hifi-0] alsa-sink.c: Error opening PCM device iec958:0: Device or resource busy
Oct 11 02:46:08 neptune pulseaudio[1430]: [pulseaudio] sink-input.c: Failed to create sink input: sink is suspended.
Oct 11 02:46:08 neptune pulseaudio[1430]: [alsa-sink-MAI PCM vc4-hdmi-hifi-0] alsa-sink.c: Error opening PCM device iec958:0: Device or resource busy
Oct 11 02:46:08 neptune pulseaudio[1430]: [pulseaudio] sink-input.c: Failed to create sink input: sink is suspended.
Oct 11 02:46:08 neptune pulseaudio[1430]: [alsa-sink-MAI PCM vc4-hdmi-hifi-0] alsa-sink.c: Error opening PCM device iec958:0: Device or resource busy
Oct 11 02:46:08 neptune pulseaudio[1430]: [alsa-sink-MAI PCM vc4-hdmi-hifi-0] alsa-sink.c: Error opening PCM device iec958:0: Device or resource busy
Oct 11 02:46:08 neptune pulseaudio[1430]: [pulseaudio] sink-input.c: Failed to create sink input: sink is suspended.
Oct 11 02:46:10 neptune kernel: [ 5462.905558] ------------[ cut here ]------------
Oct 11 02:46:10 neptune kernel: [ 5462.905643] WARNING: CPU: 0 PID: 1820 at drivers/gpu/drm/vc4/vc4_crtc.c:668 vc4_crtc_atomic_flush+0x124/0x128 [vc4]
Oct 11 02:46:10 neptune kernel: [ 5462.905652] Modules linked in: cmac rfcomm bnep hci_uart btbcm serdev bluetooth ecdh_generic binfmt_misc joydev evdev spidev brcmfmac brcmutil cfg80211 rfkill snd_bcm2835(C) spi_bcm2835 uio_pdrv_genirq uio i2c_dev sunrpc ip_tables x_tables ipv6 overlay hid_microsoft vc4 drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops cec drm snd_soc_core snd_compress snd_pcm_dmaengine snd_pcm snd_timer snd i2c_bcm2835 fixed
Oct 11 02:46:10 neptune kernel: [ 5462.905738] CPU: 0 PID: 1820 Comm: kworker/u8:0 Tainted: G WC 4.14.52-rt34-v7+ #3
Oct 11 02:46:10 neptune kernel: [ 5462.905740] Hardware name: BCM2835
Oct 11 02:46:10 neptune kernel: [ 5462.905771] Workqueue: events_unbound commit_work [vc4]
Oct 11 02:46:10 neptune kernel: [ 5462.905791] [<8010fdf0>] (unwind_backtrace) from [<8010bf4c>] (show_stack+0x20/0x24)
Oct 11 02:46:10 neptune kernel: [ 5462.905802] [<8010bf4c>] (show_stack) from [<80747eac>] (dump_stack+0xbc/0x100)
Oct 11 02:46:10 neptune kernel: [ 5462.905811] [<80747eac>] (dump_stack) from [<8011dbf0>] (__warn+0xf8/0x110)
Oct 11 02:46:10 neptune kernel: [ 5462.905817] [<8011dbf0>] (__warn) from [<8011dcd8>] (warn_slowpath_null+0x30/0x38)
Oct 11 02:46:10 neptune kernel: [ 5462.905845] [<8011dcd8>] (warn_slowpath_null) from [<7f19cf08>] (vc4_crtc_atomic_flush+0x124/0x128 [vc4])
Oct 11 02:46:10 neptune kernel: [ 5462.905951] [<7f19cf08>] (vc4_crtc_atomic_flush [vc4]) from [<7f163ab0>] (drm_atomic_helper_commit_planes+0x1c4/0x2b0 [drm_kms_helper])
Oct 11 02:46:10 neptune kernel: [ 5462.906029] [<7f163ab0>] (drm_atomic_helper_commit_planes [drm_kms_helper]) from [<7f1a431c>] (vc4_atomic_complete_commit+0x54/0xd8 [vc4])
Oct 11 02:46:10 neptune kernel: [ 5462.906084] [<7f1a431c>] (vc4_atomic_complete_commit [vc4]) from [<7f1a44ec>] (commit_work+0x1c/0x20 [vc4])
Oct 11 02:46:10 neptune kernel: [ 5462.906119] [<7f1a44ec>] (commit_work [vc4]) from [<801384c4>] (process_one_work+0x1fc/0x588)
Oct 11 02:46:10 neptune kernel: [ 5462.906128] [<801384c4>] (process_one_work) from [<801394e8>] (worker_thread+0x60/0x5e4)
Oct 11 02:46:10 neptune kernel: [ 5462.906134] [<801394e8>] (worker_thread) from [<8013ec8c>] (kthread+0x144/0x174)
Oct 11 02:46:10 neptune kernel: [ 5462.906143] [<8013ec8c>] (kthread) from [<80107d54>] (ret_from_fork+0x14/0x20)
Oct 11 02:46:10 neptune kernel: [ 5462.906179] ---[ end trace 0000000000000003 ]---

[popcornmix]

Can you describe how you configured audio to use the MAI PCM vc4 driver?
This isn't a configuration we test, but if you say it was working better and either a kernel bump or a pulse audio bump caused a problem then it would be useful to identify it.

[Joel-Mckay]

I do have the gl module enabled.
The pi3B+ "vc4-hdmi" audio output is set to IEC958, and selected Stereo "S/PDIF connector" output.
Pulseaudio used to work in the Jul firmware release, but now seems broken after the update.

• After a cold boot, if I manually disable and re-enable the IEC958 mode and select the output it seems to work again (for awhile)
• I disable the BCM2835 analog output or it will corrupt the audio quality

We built an RTlinux Rasbian Stretch with a gl compositor MATE desktop for our clubs machine control projects, and the frozen-version can be downloaded here if you wish to investigate the working configuration:
https://sourceforge.net/projects/micrometer-cnc-on-raspberry-pi/

---

sudo amixer
Simple mixer control 'PCM',0
Capabilities: pvolume pvolume-joined pswitch pswitch-joined
Playback channels: Mono
Limits: Playback -10239 - 400
Mono: Playback 399 [100%] [3.99dB] [on]

lsmod
Module Size Used by
cmac 16384 0
rfcomm 45056 14
bnep 20480 2
hci_uart 36864 1
btbcm 16384 1 hci_uart
serdev 20480 1 hci_uart
bluetooth 364544 39 hci_uart,bnep,btbcm,rfcomm
ecdh_generic 28672 1 bluetooth
binfmt_misc 20480 1
joydev 20480 0
evdev 20480 8
spidev 16384 0
brcmfmac 307200 0
brcmutil 16384 1 brcmfmac
cfg80211 593920 1 brcmfmac
rfkill 24576 7 bluetooth,cfg80211
snd_bcm2835 32768 0
spi_bcm2835 16384 0
uio_pdrv_genirq 16384 0
uio 20480 1 uio_pdrv_genirq
i2c_dev 16384 0
sunrpc 311296 1
ip_tables 24576 0
x_tables 32768 1 ip_tables
ipv6 458752 44
overlay 73728 1
hid_microsoft 16384 0
vc4 155648 12
drm_kms_helper 180224 2 vc4
syscopyarea 16384 1 drm_kms_helper
sysfillrect 16384 1 drm_kms_helper
sysimgblt 16384 1 drm_kms_helper
fb_sys_fops 16384 1 drm_kms_helper
cec 45056 1 vc4
drm 385024 5 vc4,drm_kms_helper
snd_soc_core 188416 1 vc4
snd_compress 20480 1 snd_soc_core
snd_pcm_dmaengine 16384 1 snd_soc_core
snd_pcm 98304 4 vc4,snd_pcm_dmaengine,snd_bcm2835,snd_soc_core
snd_timer 32768 1 snd_pcm
snd 69632 7 snd_compress,snd_timer,snd_bcm2835,snd_soc_core,snd_pcm
i2c_bcm2835 16384 0
fixed 16384 0

[popcornmix]

Can you confirm if the breakage was due to the kernel update or pulse audio?
Assuming you are using a raspbian you can downgrade to 4.14.52 with:
sudo rpi-update afc71fd252cc947b50b3140cb3935af9ab0f260d
(you might want to backup first).

[Joel-Mckay]

I found a working setup for the screen standby audio-loss issue with Oct 12, 2018 Pi firmware and kernel:
Note, the device setup is a complete inverse as what worked before (bcm alsa analog audio on HDMI had corrupted noisy audio in Jul), and after an OS image roll back the previous disk-snapshot the behavior became intermittent. (Very bizarre, given it was verified functional previously...)

/boot/config.txt flags that now work:
hdmi_ignore_edid_audio=0
hdmi_force_edid_audio=0
...Enable the onboard ALSA audio (loads snd_bcm2835)
dtparam=audio=on

1. Open audio control panel, and disable all audio output devices
2. In a terminal run: rm ~/.config/pulse/*
3. Shutdown to power-off pi
4. Power-on pi, and login
5. Open audio control panel, and select analog output (make sure other output disabled)
6. Check selected input and outputs screen
7. Click close, and Reboot system

Do not power off the HDMI LCD at any time during this process, or you will need to redo from step 1.

Thanks for your advice.
J

[Joel-Mckay]

Although, the setup above will no longer immediately hang the audio device during TV standby. it does seem to still occur after about 15 minutes after the screen goes dark (although now can be fixed by just rebooting).

I played a stream with vlc on the tv for awhile to see if some other variable is at play.
Then powered off the tv, and turned it back on.
There were no events noted in dmesg. /var/log/syslog, or /var/log/kern.log.
i.e. completely silent like the audio stream that was still running.
;-)

[aiminickwong]

Got it