need help with balena-sound setup

drew · March 15, 2021, 8:52pm

Hi everyone! I am trying to run balena-sound project and the experience is not as smooth as I expected.

I am using Raspberry Pi Zero W + Pimoroni Pirate Audio line out DAC hat and this tutorial

BalenaOS version: balenaOS 2.54.2+rev1
Supervisor version: 11.12.4

App Env Vars:

AUDIO_OUTPUT=DAC
BLUETOOTH_DEVICE_NAME=my-hifi
SOUND_DEVICE_NAME=my-hifi
SOUND_DISABLE_AIRPLAY= remove_this_var_to_enable_AIRPLAY
SOUND_DISABLE_SPOTIFY= remove_this_var_to_enable_SPOTIFY
SOUND_MODE= STANDALONE
SOUND_VOLUME=50

Device config vars:

BALENA_HOST_CONFIG_dtoverlay=hifiberry-dac

All the containers are up apart of disabled multiroom-client, multiroom-server, airplay and spotify.

The audio service seems to be down though, as nothing listens on port 4317. The sound-supervisor log (and nmap) confirm this as well:

❯ nmap -p4317,49494,3000 192.168.10.108
Starting Nmap 7.91 ( https://nmap.org ) at 2021-03-15 22:43 EET
Nmap scan report for 192.168.10.108
Host is up (0.0084s latency).

PORT      STATE  SERVICE
3000/tcp  open   ppp
4317/tcp  closed unknown
49494/tcp open   unknown

sound-supervisor log:

...
15.03.21 22:42:39 (+0200)  sound-supervisor  Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
...

audio log:
(funny thing is that the audio service log shows only one recurring message, and nothing more, as follows)

...
15.03.21 22:28:21 (+0200)  audio  Waiting for sound supervisor to start
15.03.21 22:28:26 (+0200)  audio  Waiting for sound supervisor to start
15.03.21 22:28:31 (+0200)  audio  Waiting for sound supervisor to start
...

Please help me to troubleshoot this. I do not even understand where to start digging why it is not working.

Thank you for any attempt to help.

drew · March 15, 2021, 8:56pm

and here is the dmesg log just in case anybody interested:

root@2e28e3c:~# dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.118 (oe-user@oe-host) (gcc version 8.3.0 (GCC)) #1 Sun Aug 16 09:58:55 UTC 2020
[    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi Zero W Rev 1.1
[    0.000000] Memory policy: Data cache writeback
[    0.000000] cma: Reserved 8 MiB at 0x1e400000
[    0.000000] On node 0 totalpages: 126976
[    0.000000]   Normal zone: 1116 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 126976 pages, LIFO batch:31
[    0.000000] random: get_random_bytes called from start_kernel+0x94/0x49c with crng_init=0
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 125860
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:67:98:62 vc_mem.mem_base=0x1fa00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 console=null rootfstype=ext4 rootwait vt.global_cursor_default=0 root=UUID=ba1eadef-ffdc-43e9-90fc-63f5549536d1 rootwait
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 473468K/507904K available (8055K kernel code, 683K rwdata, 2360K rodata, 8640K init, 802K bss, 26244K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xdf800000 - 0xff800000   ( 512 MB)
                   lowmem  : 0xc0000000 - 0xdf000000   ( 496 MB)
                   modules : 0xbf000000 - 0xc0000000   (  16 MB)
                     .text : 0x(ptrval) - 0x(ptrval)   (8056 kB)
                     .init : 0x(ptrval) - 0x(ptrval)   (8640 kB)
                     .data : 0x(ptrval) - 0x(ptrval)   ( 684 kB)
                      .bss : 0x(ptrval) - 0x(ptrval)   ( 803 kB)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] ftrace: allocating 28694 entries in 85 pages
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000031] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
[    0.000092] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
[    0.000220] bcm2835: system timer (irq = 27)
[    0.000642] Console: colour dummy device 80x30
[    0.000721] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
[    0.060374] pid_max: default: 32768 minimum: 301
[    0.060917] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.060949] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.062389] CPU: Testing write buffer coherency: ok
[    0.063740] Setting up static identity map for 0x8200 - 0x8238
[    0.065173] devtmpfs: initialized
[    0.076354] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[    0.076778] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.076822] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.078192] pinctrl core: initialized pinctrl subsystem
[    0.079805] NET: Registered protocol family 16
[    0.083280] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.091086] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[    0.091118] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.091268] Serial: AMBA PL011 UART driver
[    0.094776] bcm2835-mbox 2000b880.mailbox: mailbox enabled
[    0.110700] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-06-01 13:25, variant start_cd
[    0.120716] raspberrypi-firmware soc:firmware: Firmware hash is 6379679d1ec6a8c746d7e77e015f5b56b939976f
[    0.174541] bcm2835-dma 20007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.177180] SCSI subsystem initialized
[    0.177476] usbcore: registered new interface driver usbfs
[    0.177597] usbcore: registered new interface driver hub
[    0.177855] usbcore: registered new device driver usb
[    0.180246] clocksource: Switched to clocksource timer
[    0.294043] VFS: Disk quotas dquot_6.6.0
[    0.294200] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.294519] FS-Cache: Loaded
[    0.294869] CacheFiles: Loaded
[    0.314608] NET: Registered protocol family 2
[    0.315948] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes)
[    0.316034] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    0.316121] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[    0.316223] TCP: Hash tables configured (established 4096 bind 4096)
[    0.316403] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.316446] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.316885] NET: Registered protocol family 1
[    0.318014] RPC: Registered named UNIX socket transport module.
[    0.318043] RPC: Registered udp transport module.
[    0.318057] RPC: Registered tcp transport module.
[    0.318070] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.476560] hw perfevents: no irqs for PMU, sampling events not supported
[    0.476649] hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available
[    0.481453] Initialise system trusted keyrings
[    0.481949] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    0.498166] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.498624] FS-Cache: Netfs 'nfs' registered for caching
[    0.499996] NFS: Registering the id_resolver key type
[    0.500064] Key type id_resolver registered
[    0.500082] Key type id_legacy registered
[    0.500120] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.503065] aufs 4.19.17+-20190211
[    0.508503] Key type asymmetric registered
[    0.508537] Asymmetric key parser 'x509' registered
[    0.508654] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.509130] io scheduler noop registered
[    0.509159] io scheduler deadline registered
[    0.509840] io scheduler cfq registered (default)
[    0.509868] io scheduler mq-deadline registered
[    0.509885] io scheduler kyber registered
[    0.512956] bcm2708_fb soc:fb: FB found 1 display(s)
[    0.519045] Console: switching to colour frame buffer device 82x26
[    0.522162] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[    0.526097] bcm2835-rng 20104000.rng: hwrng registered
[    0.526612] vc-mem: phys_addr:0x00000000 mem_base=0x1fa00000 mem_size:0x20000000(512 MiB)
[    0.527814] vc-sm: Videocore shared memory driver
[    0.528517] gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000
[    0.549344] brd: module loaded
[    0.563495] loop: module loaded
[    0.564565] zram: Added device: zram0
[    0.565454] Loading iSCSI transport class v2.0-870.
[    0.566326] tun: Universal TUN/TAP device driver, 1.6
[    0.566794] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.567240] dwc_otg 20980000.usb: base=(ptrval)
[    0.767761] Core Release: 2.80a
[    0.767803] Setting default values for core params
[    0.767846] Finished setting default values for core params
[    0.968247] Using Buffer DMA mode
[    0.968277] Periodic Transfer Interrupt Enhancement - disabled
[    0.968291] Multiprocessor Interrupt Enhancement - disabled
[    0.968306] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.968401] Dedicated Tx FIFOs mode
[    0.969328] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = de514000 dma = 0x5e514000 len=9024
[    0.969373] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.969409] dwc_otg: Microframe scheduler enabled
[    0.969592] WARN::hcd_init_fiq:457: FIQ on core 0
[    0.969619] WARN::hcd_init_fiq:458: FIQ ASM at c057fdd8 length 36
[    0.969651] WARN::hcd_init_fiq:497: MPHI regs_base at df810000
[    0.969694] dwc_otg 20980000.usb: DWC OTG Controller
[    0.969765] dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1
[    0.969847] dwc_otg 20980000.usb: irq 56, io mem 0x00000000
[    0.969910] Init: Port Power? op_state=1
[    0.969925] Init: Power Port (0)
[    0.970434] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.970463] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.970482] usb usb1: Product: DWC OTG Controller
[    0.970499] usb usb1: Manufacturer: Linux 4.19.118 dwc_otg_hcd
[    0.970516] usb usb1: SerialNumber: 20980000.usb
[    0.971655] hub 1-0:1.0: USB hub found
[    0.971766] hub 1-0:1.0: 1 port detected
[    0.972825] dwc_otg: FIQ enabled
[    0.972836] dwc_otg: NAK holdoff enabled
[    0.972845] dwc_otg: FIQ split-transaction FSM enabled
[    0.972864] Module dwc_common_port init
[    0.973435] usbcore: registered new interface driver usb-storage
[    0.973662] usbcore: registered new interface driver usbserial_generic
[    0.973740] usbserial: USB Serial support registered for generic
[    0.974197] mousedev: PS/2 mouse device common for all mice
[    0.975720] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    0.976180] bcm2835-cpufreq: min=700000 max=1000000
[    0.977064] sdhci: Secure Digital Host Controller Interface driver
[    0.977089] sdhci: Copyright(c) Pierre Ossman
[    0.977728] mmc-bcm2835 20300000.mmcnr: could not get clk, deferring probe
[    0.978469] sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe
[    0.978742] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.979411] ledtrig-cpu: registered to indicate activity on CPUs
[    0.979564] hidraw: raw HID events driver (C) Jiri Kosina
[    0.979890] usbcore: registered new interface driver usbhid
[    0.979910] usbhid: USB HID core driver
[    0.981201] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    0.983122] [vc_sm_connected_init]: start
[    0.986916] vc_vchi_sm_init: failed to open VCHI service (-1)
[    0.986931] [vc_sm_connected_init]: failed to initialize shared memory service
[    0.986971] [vc_sm_connected_init]: end - returning -1
[    0.989682] IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
[    0.989820] IPVS: Connection hash table configured (size=4096, memory=32Kbytes)
[    0.990364] IPVS: ipvs loaded.
[    0.991206] Initializing XFRM netlink socket
[    0.992543] NET: Registered protocol family 10
[    0.994130] Segment Routing with IPv6
[    0.994331] NET: Registered protocol family 17
[    0.994429] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    0.994548] Key type dns_resolver registered
[    0.995953] registered taskstats version 1
[    0.995987] Loading compiled-in X.509 certificates
[    1.003295] uart-pl011 20201000.serial: cts_event_workaround enabled
[    1.003414] 20201000.serial: ttyAMA0 at MMIO 0x20201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    1.005641] mmc-bcm2835 20300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    1.005667] mmc-bcm2835 20300000.mmcnr: DMA channel allocated
[    1.032793] sdhost: log_buf @ (ptrval) (5e513000)
[    1.067150] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.068965] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.070735] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.073753] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.080379] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    1.102822] of_cfs_init
[    1.103043] of_cfs_init: OK
[    1.103794] Warning: unable to open an initial console.
[    1.134151] Freeing unused kernel memory: 8640K
[    1.134183] This architecture does not have kernel memory protection.
[    1.134199] Run /init as init process
[    1.134960] random: fast init done
[    1.173178] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.175204] mmc0: Problem switching card into high-speed mode!
[    1.176051] mmc0: new SDHC card at address 0001
[    1.180071] mmcblk0: mmc0:0001 ASTC 7.45 GiB
[    1.189161]  mmcblk0: p1 p2 p3 p4 < p5 p6 >
[    1.240764] mmc1: new high speed SDIO card at address 0001
[    2.234738] udevd[276]: Starting version 241-166-g511646b+
[    2.247777] udevd[277]: Specified group 'render' unknown
[    2.249431] udevd[277]: Specified group 'kvm' unknown
[    3.014841] udevd[288]: loop1: Failed to substitute variable '$parent', ignoring: No such file or directory
[    3.019433] udevd[283]: loop0: Failed to substitute variable '$parent', ignoring: No such file or directory
[    3.024070] udevd[284]: loop2: Failed to substitute variable '$parent', ignoring: No such file or directory
[    3.034070] udevd[280]: loop3: Failed to substitute variable '$parent', ignoring: No such file or directory
[    3.039348] udevd[285]: loop4: Failed to substitute variable '$parent', ignoring: No such file or directory
[    3.054156] udevd[281]: loop5: Failed to substitute variable '$parent', ignoring: No such file or directory
[    3.059629] udevd[287]: loop6: Failed to substitute variable '$parent', ignoring: No such file or directory
[    4.517505] zram0: detected capacity change from 0 to 125517824
[    7.400832] udevd[283]: Process '/lib/udev/resin_update_state_probe /dev/mmcblk0p2  mmcblk0' failed with exit code 1.
[    7.406074] udevd[288]: Process '/lib/udev/resin_update_state_probe /dev/mmcblk0p3  mmcblk0' failed with exit code 1.
[    8.857857] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    8.859849] udevd[277]: Failed to touch /run/udev/queue: No such file or directory
[    8.864059] udevd[277]: Failed to unlink /run/udev/queue: No such file or directory
[    8.950493] EXT4-fs (mmcblk0p5): mounted filesystem with ordered data mode. Opts: (null)
[    9.113316] udevd: 51 output lines suppressed due to ratelimiting
[   10.173086] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[   10.227254] aufs au_opts_verify:1609:init[1]: dirperm1 breaks the protection by the permission bits on the lower branch
[   10.936328] systemd[1]: System time before build time, advancing clock.
[   12.055399] systemd[1]: /lib/systemd/system/chronyd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/chrony/chronyd.pid \xe2\x86\x92 /run/chrony/chronyd.pid; please update the unit file accordingly.
[   12.511859] random: systemd: uninitialized urandom read (16 bytes read)
[   12.513804] random: systemd: uninitialized urandom read (16 bytes read)
[   12.515944] random: systemd: uninitialized urandom read (16 bytes read)
[   15.751590] EXT4-fs (mmcblk0p6): mounted filesystem with ordered data mode. Opts: (null)
[   18.861811] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[   18.864309] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[   18.864343] [vc_sm_connected_init]: start
[   18.868601] vc_sm_cma_vchi_init: failed to open VCHI service (-1)
[   18.868614] [vc_sm_connected_init]: failed to initialize shared memory service
[   18.884171] media: Linux media interface: v0.10
[   18.999557] videodev: Linux video capture interface: v2.00
[   19.143829] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   19.145781] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   19.151657] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[   19.219758] bcm2835_audio soc:audio: card created with 8 channels
[   19.227067] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[   19.237519] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[   19.305594] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[   19.316125] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[   19.443442] snd-rpi-simple soc:sound: pcm5102a-hifi <-> 20203000.i2s mapping ok
[   20.088858] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   20.203820] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   20.550621] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[   20.566625] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[   20.566960] usbcore: registered new interface driver brcmfmac
[   20.814647] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[   20.829074] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: May  2 2019 02:39:18 version 7.45.98.83 (r714225 CY) FWID 01-e539531f
[   23.659585] zram: Can't change algorithm for initialized device
[   28.051449] Adding 122572k swap on /dev/zram0.  Priority:-2 extents:1 across:122572k SSFS
[   28.288233] random: crng init done
[   28.288264] random: 7 urandom warning(s) missed due to ratelimiting
[   30.842015] uart-pl011 20201000.serial: no DMA platform data
[   35.896036] Bluetooth: Core ver 2.22
[   35.896198] NET: Registered protocol family 31
[   35.896214] Bluetooth: HCI device and connection manager initialized
[   35.896243] Bluetooth: HCI socket layer initialized
[   35.896263] Bluetooth: L2CAP socket layer initialized
[   35.896322] Bluetooth: SCO socket layer initialized
[   35.990539] Bluetooth: HCI UART driver ver 2.3
[   35.990567] Bluetooth: HCI UART protocol H4 registered
[   35.990759] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   35.991078] Bluetooth: HCI UART protocol Broadcom registered
[   39.226758] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   39.226788] Bluetooth: BNEP filters: protocol multicast
[   39.226819] Bluetooth: BNEP socket layer initialized
[   49.610376] i2c /dev entries driver
[   50.737444] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   50.781817] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   50.781860] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
[   51.339128] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   51.339198] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
[   52.575803] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   54.152648] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   54.152714] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
[   56.920919] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   62.481266] Bridge firewalling registered
[   65.970003] IPv6: ADDRCONF(NETDEV_UP): balena0: link is not ready
[   67.185683] IPv6: ADDRCONF(NETDEV_UP): supervisor0: link is not ready
[  135.844018] IPv6: ADDRCONF(NETDEV_UP): br-a6ad853699bd: link is not ready
[ 3774.463637] br-a6ad853699bd: port 1(vethaa8e5bb) entered blocking state
[ 3774.463666] br-a6ad853699bd: port 1(vethaa8e5bb) entered disabled state
[ 3774.465720] device vethaa8e5bb entered promiscuous mode
[ 3774.528454] IPv6: ADDRCONF(NETDEV_UP): vethaa8e5bb: link is not ready
[ 3776.773185] br-a6ad853699bd: port 2(veth3d54daa) entered blocking state
[ 3776.773214] br-a6ad853699bd: port 2(veth3d54daa) entered disabled state
[ 3776.801375] device veth3d54daa entered promiscuous mode
[ 3776.810867] IPv6: ADDRCONF(NETDEV_UP): veth3d54daa: link is not ready
[ 3780.237956] br-a6ad853699bd: port 3(vethd5b6ec7) entered blocking state
[ 3780.237985] br-a6ad853699bd: port 3(vethd5b6ec7) entered disabled state
[ 3780.241123] device vethd5b6ec7 entered promiscuous mode
[ 3780.252549] IPv6: ADDRCONF(NETDEV_UP): vethd5b6ec7: link is not ready
[ 3805.219009] eth0: renamed from vethfbcd251
[ 3805.261981] IPv6: ADDRCONF(NETDEV_CHANGE): vethaa8e5bb: link becomes ready
[ 3805.262262] br-a6ad853699bd: port 1(vethaa8e5bb) entered blocking state
[ 3805.262285] br-a6ad853699bd: port 1(vethaa8e5bb) entered forwarding state
[ 3805.262625] IPv6: ADDRCONF(NETDEV_CHANGE): br-a6ad853699bd: link becomes ready
[ 3830.690035] eth0: renamed from veth725c141
[ 3830.723269] IPv6: ADDRCONF(NETDEV_CHANGE): veth3d54daa: link becomes ready
[ 3830.723561] br-a6ad853699bd: port 2(veth3d54daa) entered blocking state
[ 3830.723584] br-a6ad853699bd: port 2(veth3d54daa) entered forwarding state
[ 3840.259367] eth0: renamed from vethcc07842
[ 3840.282049] IPv6: ADDRCONF(NETDEV_CHANGE): vethd5b6ec7: link becomes ready
[ 3840.282342] br-a6ad853699bd: port 3(vethd5b6ec7) entered blocking state
[ 3840.282365] br-a6ad853699bd: port 3(vethd5b6ec7) entered forwarding state
[ 3883.731719] systemd-udevd[30]: Starting version 241
[ 3899.031327] systemd-udevd[34]: pcmC1D0p: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/pcmC1D0p/id} for writing: Permission denied
[ 3899.169414] systemd-udevd[37]: controlC1: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/controlC1/id} for writing: Permission denied
[ 3934.780230] br-a6ad853699bd: port 2(veth3d54daa) entered disabled state
[ 3934.791383] veth725c141: renamed from eth0
[ 3935.122207] br-a6ad853699bd: port 2(veth3d54daa) entered disabled state
[ 3935.155585] device veth3d54daa left promiscuous mode
[ 3935.155621] br-a6ad853699bd: port 2(veth3d54daa) entered disabled state
[ 3935.181517] br-a6ad853699bd: port 1(vethaa8e5bb) entered disabled state
[ 3935.226677] vethfbcd251: renamed from eth0
[ 3935.569149] br-a6ad853699bd: port 1(vethaa8e5bb) entered disabled state
[ 3935.625897] device vethaa8e5bb left promiscuous mode
[ 3935.625933] br-a6ad853699bd: port 1(vethaa8e5bb) entered disabled state
[35535.217593] br-a6ad853699bd: port 3(vethd5b6ec7) entered disabled state
[35535.221214] vethcc07842: renamed from eth0
[35535.444878] br-a6ad853699bd: port 3(vethd5b6ec7) entered disabled state
[35535.489609] device vethd5b6ec7 left promiscuous mode
[35535.489646] br-a6ad853699bd: port 3(vethd5b6ec7) entered disabled state
[35550.041142] br-a6ad853699bd: port 1(veth7f0ff8a) entered blocking state
[35550.041172] br-a6ad853699bd: port 1(veth7f0ff8a) entered disabled state
[35550.042022] device veth7f0ff8a entered promiscuous mode
[35550.045680] IPv6: ADDRCONF(NETDEV_UP): veth7f0ff8a: link is not ready
[35552.794781] br-a6ad853699bd: port 2(vethd334037) entered blocking state
[35552.794810] br-a6ad853699bd: port 2(vethd334037) entered disabled state
[35552.850684] device vethd334037 entered promiscuous mode
[35552.887944] IPv6: ADDRCONF(NETDEV_UP): vethd334037: link is not ready
[35553.478145] br-a6ad853699bd: port 3(veth60b965d) entered blocking state
[35553.478174] br-a6ad853699bd: port 3(veth60b965d) entered disabled state
[35553.486038] device veth60b965d entered promiscuous mode
[35553.598024] IPv6: ADDRCONF(NETDEV_UP): veth60b965d: link is not ready
[35553.598059] br-a6ad853699bd: port 3(veth60b965d) entered blocking state
[35553.598074] br-a6ad853699bd: port 3(veth60b965d) entered forwarding state
[35553.598350] br-a6ad853699bd: port 3(veth60b965d) entered disabled state
[35603.822859] eth0: renamed from veth8bb5dc5
[35603.905759] IPv6: ADDRCONF(NETDEV_CHANGE): veth7f0ff8a: link becomes ready
[35603.906040] br-a6ad853699bd: port 1(veth7f0ff8a) entered blocking state
[35603.906063] br-a6ad853699bd: port 1(veth7f0ff8a) entered forwarding state
[35632.442473] eth0: renamed from veth22dfee8
[35632.517339] IPv6: ADDRCONF(NETDEV_CHANGE): veth60b965d: link becomes ready
[35632.517632] br-a6ad853699bd: port 3(veth60b965d) entered blocking state
[35632.517654] br-a6ad853699bd: port 3(veth60b965d) entered forwarding state
[35636.546687] eth0: renamed from vetha60e573
[35636.586277] IPv6: ADDRCONF(NETDEV_CHANGE): vethd334037: link becomes ready
[35636.586572] br-a6ad853699bd: port 2(vethd334037) entered blocking state
[35636.586604] br-a6ad853699bd: port 2(vethd334037) entered forwarding state
[35649.008561] systemd-udevd[30]: Starting version 241
[35663.392503] systemd-udevd[39]: pcmC1D0p: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/pcmC1D0p/id} for writing: Permission denied
[35663.672709] systemd-udevd[34]: controlC1: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/controlC1/id} for writing: Permission denied
[35699.863016] br-a6ad853699bd: port 2(vethd334037) entered disabled state
[35699.873714] vetha60e573: renamed from eth0
[35700.102054] br-a6ad853699bd: port 2(vethd334037) entered disabled state
[35700.136658] device vethd334037 left promiscuous mode
[35700.136693] br-a6ad853699bd: port 2(vethd334037) entered disabled state
[35702.416351] br-a6ad853699bd: port 1(veth7f0ff8a) entered disabled state
[35702.452319] veth8bb5dc5: renamed from eth0
[35702.756604] br-a6ad853699bd: port 1(veth7f0ff8a) entered disabled state
[35702.778222] device veth7f0ff8a left promiscuous mode
[35702.778258] br-a6ad853699bd: port 1(veth7f0ff8a) entered disabled state
[161624.726828] br-a6ad853699bd: port 3(veth60b965d) entered disabled state
[161624.733637] veth22dfee8: renamed from eth0
[161624.942062] br-a6ad853699bd: port 3(veth60b965d) entered disabled state
[161625.006032] device veth60b965d left promiscuous mode
[161625.006069] br-a6ad853699bd: port 3(veth60b965d) entered disabled state
[161643.729272] br-a6ad853699bd: port 1(veth03241d0) entered blocking state
[161643.729300] br-a6ad853699bd: port 1(veth03241d0) entered disabled state
[161643.745303] device veth03241d0 entered promiscuous mode
[161643.759339] IPv6: ADDRCONF(NETDEV_UP): veth03241d0: link is not ready
[161644.628497] br-a6ad853699bd: port 2(veth31ffd93) entered blocking state
[161644.628526] br-a6ad853699bd: port 2(veth31ffd93) entered disabled state
[161644.629377] device veth31ffd93 entered promiscuous mode
[161644.630849] IPv6: ADDRCONF(NETDEV_UP): veth31ffd93: link is not ready
[161644.630883] br-a6ad853699bd: port 2(veth31ffd93) entered blocking state
[161644.630900] br-a6ad853699bd: port 2(veth31ffd93) entered forwarding state
[161644.631159] br-a6ad853699bd: port 2(veth31ffd93) entered disabled state
[161647.308288] br-a6ad853699bd: port 3(veth705ade3) entered blocking state
[161647.308317] br-a6ad853699bd: port 3(veth705ade3) entered disabled state
[161647.310789] device veth705ade3 entered promiscuous mode
[161647.343993] IPv6: ADDRCONF(NETDEV_UP): veth705ade3: link is not ready
[161703.610431] eth0: renamed from vetha9f7895
[161703.614438] IPv6: ADDRCONF(NETDEV_CHANGE): veth03241d0: link becomes ready
[161703.614713] br-a6ad853699bd: port 1(veth03241d0) entered blocking state
[161703.614737] br-a6ad853699bd: port 1(veth03241d0) entered forwarding state
[161708.037186] eth0: renamed from vethbd4885e
[161708.092518] IPv6: ADDRCONF(NETDEV_CHANGE): veth31ffd93: link becomes ready
[161708.092804] br-a6ad853699bd: port 2(veth31ffd93) entered blocking state
[161708.092828] br-a6ad853699bd: port 2(veth31ffd93) entered forwarding state
[161735.021202] eth0: renamed from veth2835539
[161735.105873] systemd-udevd[29]: Starting version 241
[161735.169707] IPv6: ADDRCONF(NETDEV_CHANGE): veth705ade3: link becomes ready
[161735.170020] br-a6ad853699bd: port 3(veth705ade3) entered blocking state
[161735.170043] br-a6ad853699bd: port 3(veth705ade3) entered forwarding state
[161753.934887] systemd-udevd[39]: pcmC1D0p: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/pcmC1D0p/id} for writing: Permission denied
[161754.173155] systemd-udevd[34]: controlC1: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/controlC1/id} for writing: Permission denied
[161794.258411] br-a6ad853699bd: port 3(veth705ade3) entered disabled state
[161794.267855] veth2835539: renamed from eth0
[161794.403894] br-a6ad853699bd: port 3(veth705ade3) entered disabled state
[161794.431530] device veth705ade3 left promiscuous mode
[161794.431566] br-a6ad853699bd: port 3(veth705ade3) entered disabled state
[161795.898783] br-a6ad853699bd: port 1(veth03241d0) entered disabled state
[161795.907986] vetha9f7895: renamed from eth0
[161796.431294] br-a6ad853699bd: port 1(veth03241d0) entered disabled state
[161796.461488] device veth03241d0 left promiscuous mode
[161796.461547] br-a6ad853699bd: port 1(veth03241d0) entered disabled state
[166837.370428] br-a6ad853699bd: port 2(veth31ffd93) entered disabled state
[166837.380633] vethbd4885e: renamed from eth0
[166837.598149] br-a6ad853699bd: port 2(veth31ffd93) entered disabled state
[166837.640160] device veth31ffd93 left promiscuous mode
[166837.640196] br-a6ad853699bd: port 2(veth31ffd93) entered disabled state
[166848.709811] br-a6ad853699bd: port 1(vethc4caa54) entered blocking state
[166848.709840] br-a6ad853699bd: port 1(vethc4caa54) entered disabled state
[166848.731102] device vethc4caa54 entered promiscuous mode
[166848.769434] IPv6: ADDRCONF(NETDEV_UP): vethc4caa54: link is not ready
[166850.797715] br-a6ad853699bd: port 2(veth8b0cf81) entered blocking state
[166850.797745] br-a6ad853699bd: port 2(veth8b0cf81) entered disabled state
[166850.806917] device veth8b0cf81 entered promiscuous mode
[166850.835991] IPv6: ADDRCONF(NETDEV_UP): veth8b0cf81: link is not ready
[166851.675328] br-a6ad853699bd: port 3(vethb7aa981) entered blocking state
[166851.675357] br-a6ad853699bd: port 3(vethb7aa981) entered disabled state
[166851.676348] device vethb7aa981 entered promiscuous mode
[166851.687183] IPv6: ADDRCONF(NETDEV_UP): vethb7aa981: link is not ready
[166851.687265] br-a6ad853699bd: port 3(vethb7aa981) entered blocking state
[166851.687281] br-a6ad853699bd: port 3(vethb7aa981) entered forwarding state
[166851.687539] br-a6ad853699bd: port 3(vethb7aa981) entered disabled state
[166899.732588] eth0: renamed from vethe9434d9
[166899.777509] IPv6: ADDRCONF(NETDEV_CHANGE): vethc4caa54: link becomes ready
[166899.777799] br-a6ad853699bd: port 1(vethc4caa54) entered blocking state
[166899.777821] br-a6ad853699bd: port 1(vethc4caa54) entered forwarding state
[166932.079562] eth0: renamed from vethfd6043f
[166932.172993] IPv6: ADDRCONF(NETDEV_CHANGE): vethb7aa981: link becomes ready
[166932.173289] br-a6ad853699bd: port 3(vethb7aa981) entered blocking state
[166932.173310] br-a6ad853699bd: port 3(vethb7aa981) entered forwarding state
[166936.443486] eth0: renamed from vethffdc430
[166936.471858] IPv6: ADDRCONF(NETDEV_CHANGE): veth8b0cf81: link becomes ready
[166936.472227] br-a6ad853699bd: port 2(veth8b0cf81) entered blocking state
[166936.472261] br-a6ad853699bd: port 2(veth8b0cf81) entered forwarding state
[166954.532805] systemd-udevd[29]: Starting version 241
[166973.251278] systemd-udevd[35]: pcmC1D0p: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/pcmC1D0p/id} for writing: Permission denied
[166973.456722] systemd-udevd[38]: controlC1: Failed to open ATTR{/sys/devices/platform/soc/soc:sound/sound/card1/controlC1/id} for writing: Permission denied
[167038.340097] br-a6ad853699bd: port 1(vethc4caa54) entered disabled state
[167038.359452] vethe9434d9: renamed from eth0
[167038.418761] br-a6ad853699bd: port 2(veth8b0cf81) entered disabled state
[167038.425063] vethffdc430: renamed from eth0
[167038.637786] br-a6ad853699bd: port 1(vethc4caa54) entered disabled state
[167038.664477] device vethc4caa54 left promiscuous mode
[167038.664514] br-a6ad853699bd: port 1(vethc4caa54) entered disabled state
[167038.691033] br-a6ad853699bd: port 2(veth8b0cf81) entered disabled state
[167038.722570] device veth8b0cf81 left promiscuous mode
[167038.722606] br-a6ad853699bd: port 2(veth8b0cf81) entered disabled state
root@2e28e3c:~#

BenGast · March 16, 2021, 7:54am

Hello everyone,

I have an issue (that might be similar) with the installation on a Pi Zero W:

My DAC is a DAC magic 100.
All the services are running on the dashboard except multiroom-client and multiroom-server (which I believe is normal).
I can connect to bluetooth, but no sound is coming out of both the DAC and HDMI,
I can’t see the device on AirPlay

Thanks in advance for the support,

tmigone · March 16, 2021, 2:26pm

Hi @drew can you reboot your device and share the entire services logs? There is a button to download the logs on the dashboard. That might shed some light on the problem.

Also please check that you are running the latest balenaSound version (i think you are) which is v3.5.2 as previous ones had a bug that prevented audio from working.

tmigone · March 16, 2021, 2:31pm

@bengast, same thing, please ensure you are running the latest version of balenaSound and share your logs so I can take a look.

tmigone · March 16, 2021, 2:33pm

Oh btw, I just noticed the tutorial/guide you linked has outdated instructions that ask you to set dtparam to "audio=off". This is incorrect and I have now fixed the instructions. Please make sure you revert the change if you had done it. Here is the value of my DT parameters for comparison: "i2c_arm=on","spi=on","audio=on".

drew · March 17, 2021, 8:19pm

@tmigone I appreciate your help! please see the attached logs. Not sure how to attach the txt here so just posting it:

17.03.21 21:48:13 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:18 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:23 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:29 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:34 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:35 (+0200) Killing service 'audio sha256:46b8be765bfc0fd29d814699a3d2be55a708eb7f897445db4290e06700f36c82'
17.03.21 21:48:39 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:44 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:48:49 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:49:00 (+0200) Killed service 'audio sha256:46b8be765bfc0fd29d814699a3d2be55a708eb7f897445db4290e06700f36c82'
17.03.21 21:49:00 (+0200) Service exited 'audio sha256:46b8be765bfc0fd29d814699a3d2be55a708eb7f897445db4290e06700f36c82'
17.03.21 21:49:01 (+0200) Killing service 'bluetooth sha256:a9d5faaccb7b5d33364cdf1adbeb55a07ce0ceee0cc443a13f3fe08a5f089173'
17.03.21 21:49:25 (+0200) Killed service 'bluetooth sha256:a9d5faaccb7b5d33364cdf1adbeb55a07ce0ceee0cc443a13f3fe08a5f089173'
17.03.21 21:49:25 (+0200) Service exited 'bluetooth sha256:a9d5faaccb7b5d33364cdf1adbeb55a07ce0ceee0cc443a13f3fe08a5f089173'
17.03.21 21:49:25 (+0200) Killing service 'airplay sha256:29679b9e1f14592d62ed8e895831eb25731c84ae1767a68da6ece9fea5b7874d'
17.03.21 21:49:25 (+0200) Service is already stopped, removing container 'airplay sha256:29679b9e1f14592d62ed8e895831eb25731c84ae1767a68da6ece9fea5b7874d'
17.03.21 21:49:25 (+0200) Killed service 'airplay sha256:29679b9e1f14592d62ed8e895831eb25731c84ae1767a68da6ece9fea5b7874d'
17.03.21 21:49:26 (+0200) Killing service 'multiroom-server sha256:23838c0d6608478de0d9085f341f85d72f316cf75ed9866c975e37285212d391'
17.03.21 21:49:26 (+0200) Service is already stopped, removing container 'multiroom-server sha256:23838c0d6608478de0d9085f341f85d72f316cf75ed9866c975e37285212d391'
17.03.21 21:49:26 (+0200) Killed service 'multiroom-server sha256:23838c0d6608478de0d9085f341f85d72f316cf75ed9866c975e37285212d391'
17.03.21 21:49:26 (+0200) Killing service 'multiroom-client sha256:c9321d0b94894c802db564253a9939bac8c8319919b8fc74cad88a4cd9e1383b'
17.03.21 21:49:26 (+0200) Service is already stopped, removing container 'multiroom-client sha256:c9321d0b94894c802db564253a9939bac8c8319919b8fc74cad88a4cd9e1383b'
17.03.21 21:49:26 (+0200) Killed service 'multiroom-client sha256:c9321d0b94894c802db564253a9939bac8c8319919b8fc74cad88a4cd9e1383b'
17.03.21 21:49:27 (+0200) Killing service 'spotify sha256:339c95b5a4bf395e051a582551f6648aa09cb4c3334a6e5fd7471aaadb53a6a9'
17.03.21 21:49:27 (+0200) Service is already stopped, removing container 'spotify sha256:339c95b5a4bf395e051a582551f6648aa09cb4c3334a6e5fd7471aaadb53a6a9'
17.03.21 21:49:27 (+0200) Killed service 'spotify sha256:339c95b5a4bf395e051a582551f6648aa09cb4c3334a6e5fd7471aaadb53a6a9'
17.03.21 21:49:27 (+0200) Killing service 'upnp sha256:35ea9dd383062abd58299fee6529df8a4df698f061735a416eb18f130a1b7294'
17.03.21 21:49:37 (+0200) Killed service 'upnp sha256:35ea9dd383062abd58299fee6529df8a4df698f061735a416eb18f130a1b7294'
17.03.21 21:49:37 (+0200) Service exited 'upnp sha256:35ea9dd383062abd58299fee6529df8a4df698f061735a416eb18f130a1b7294'
17.03.21 21:49:37 (+0200) Killing service 'sound-supervisor sha256:91b1a1ca335d6bd36779248ce199b6ed85b0313c64e6097e56da75dda0a41bd2'
17.03.21 21:49:40 (+0200) <sound-supervisor> [..................] \ : info lifecycle sound-supervisor@1.0.0~start: sound-sup


17.03.21 21:49:40 (+0200) <sound-supervisor> 
17.03.21 21:49:40 (+0200) <sound-supervisor>    ╭───────────────────────────────────────────────────────────────╮
17.03.21 21:49:40 (+0200) <sound-supervisor>    │                                                               │
17.03.21 21:49:40 (+0200) <sound-supervisor>    │      New major version of npm available! 6.14.8 -> 7.6.3      │
17.03.21 21:49:40 (+0200) <sound-supervisor>    │   Changelog: https://github.com/npm/cli/releases/tag/v7.6.3   │
17.03.21 21:49:40 (+0200) <sound-supervisor>    │               Run npm install -g npm to update!               │
17.03.21 21:49:40 (+0200) <sound-supervisor>    │                                                               │
17.03.21 21:49:40 (+0200) <sound-supervisor>    ╰───────────────────────────────────────────────────────────────╯
17.03.21 21:49:40 (+0200) <sound-supervisor> 
17.03.21 21:49:45 (+0200) Service exited 'sound-supervisor sha256:91b1a1ca335d6bd36779248ce199b6ed85b0313c64e6097e56da75dda0a41bd2'
17.03.21 21:49:45 (+0200) Killed service 'sound-supervisor sha256:91b1a1ca335d6bd36779248ce199b6ed85b0313c64e6097e56da75dda0a41bd2'
17.03.21 21:49:45 (+0200) Rebooting
17.03.21 21:53:33 (+0200) Supervisor starting
17.03.21 21:52:26 (+0200) <audio> 
17.03.21 21:52:27 (+0200) <audio> --- Audio ---
17.03.21 21:52:27 (+0200) <audio> Starting audio service with settings:
17.03.21 21:52:37 (+0200) <audio> - 
17.03.21 21:52:37 (+0200) <audio> - Pulse log level: NOTICE
17.03.21 21:52:37 (+0200) <audio> - Default output: DAC
17.03.21 21:52:37 (+0200) <audio> 
17.03.21 21:52:37 (+0200) <audio> Detected audio cards:
17.03.21 21:52:37 (+0200) <audio> 0 bcm2835-alsa bcm2835_alsa-bcm2835ALSA
17.03.21 21:52:37 (+0200) <audio> 1 dac RPi-simple-snd_rpi_hifiberry_dac
17.03.21 21:52:37 (+0200) <audio> 
17.03.21 21:52:37 (+0200) <audio> 
17.03.21 21:52:57 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:02 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:08 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:13 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:18 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:24 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:29 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:35 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:52:02 (+0200) <bluetooth> Running balena base image entrypoint...
17.03.21 21:52:02 (+0200) <bluetooth> --- Bluetooth ---
17.03.21 21:52:02 (+0200) <bluetooth> Starting bluetooth service with settings:
17.03.21 21:52:02 (+0200) <bluetooth> - Device name: cipherpunk-hifi-office
17.03.21 21:52:02 (+0200) <bluetooth> - HCI interface: hci0
17.03.21 21:52:02 (+0200) <bluetooth> - Pairing mode: SSP
17.03.21 21:52:02 (+0200) <bluetooth> - PIN code: 0000
17.03.21 21:52:02 (+0200) <bluetooth> Available HCI interfaces: hci0
17.03.21 21:52:02 (+0200) <bluetooth> Resetting hci0
17.03.21 21:52:03 (+0200) <bluetooth> Configuring selected interface: hci0
17.03.21 21:52:03 (+0200) <bluetooth> hci0 Set Connectable complete, settings: powered connectable ssp br/edr le secure-conn 
17.03.21 21:52:03 (+0200) <bluetooth> hci0 Set Bondable complete, settings: powered connectable bondable ssp br/edr le secure-conn 
17.03.21 21:52:03 (+0200) <bluetooth> hci0 Set Discoverable complete, settings: powered connectable discoverable bondable ssp br/edr le secure-conn 
17.03.21 21:52:03 (+0200) <bluetooth> hci0 Set Secure Simple Pairing complete, settings: powered connectable discoverable bondable ssp br/edr le secure-conn 
17.03.21 21:52:03 (+0200) <bluetooth> Pairing mode set to 'Secure Simple Pairing Mode (SSPM)'. PIN code is NOT required.
17.03.21 21:52:31 (+0200) <bluetooth> Bluetooth agent started!
17.03.21 21:52:31 (+0200) <bluetooth> Checking for known bluetooth devices...
17.03.21 21:52:57 (+0200) <sound-supervisor> 
17.03.21 21:52:57 (+0200) <sound-supervisor> > sound-supervisor@1.0.0 start /usr/src
17.03.21 21:52:57 (+0200) <sound-supervisor> > node build/index.js
17.03.21 21:52:57 (+0200) <sound-supervisor> 
17.03.21 21:53:20 (+0200) <sound-supervisor> Sound supervisor listening on port 3000
17.03.21 21:53:21 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:53:26 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:53:36 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:53:40 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:45 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:46 (+0200) Starting service 'multiroom-server sha256:23838c0d6608478de0d9085f341f85d72f316cf75ed9866c975e37285212d391'
17.03.21 21:53:47 (+0200) Starting service 'spotify sha256:339c95b5a4bf395e051a582551f6648aa09cb4c3334a6e5fd7471aaadb53a6a9'
17.03.21 21:53:47 (+0200) Starting service 'airplay sha256:29679b9e1f14592d62ed8e895831eb25731c84ae1767a68da6ece9fea5b7874d'
17.03.21 21:53:47 (+0200) Starting service 'multiroom-client sha256:c9321d0b94894c802db564253a9939bac8c8319919b8fc74cad88a4cd9e1383b'
17.03.21 21:53:47 (+0200) Starting service 'upnp sha256:35ea9dd383062abd58299fee6529df8a4df698f061735a416eb18f130a1b7294'
17.03.21 21:53:51 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:53:51 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:53:57 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:03 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:09 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:11 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:54:16 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:21 (+0200) Started service 'upnp sha256:35ea9dd383062abd58299fee6529df8a4df698f061735a416eb18f130a1b7294'
17.03.21 21:54:17 (+0200) <upnp> Starting UPnP plugin...
17.03.21 21:54:17 (+0200) <upnp> Device name: cipherpunk-hifi-office
17.03.21 21:54:17 (+0200) <upnp> Using upnp UUID : 2e28e3c1c58b9965f22691041eb00cd9
17.03.21 21:54:20 (+0200) <upnp> gmediarender 0.0.7-git started [ gmediarender 0.0.7-git (libupnp-1.8.4; glib-2.58.1; gstreamer-1.14.4) ].
17.03.21 21:54:20 (+0200) <upnp> Logging switched off. Enable with --logfile=<filename> (or --logfile=stdout for console)
17.03.21 21:54:23 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:29 (+0200) Started service 'spotify sha256:339c95b5a4bf395e051a582551f6648aa09cb4c3334a6e5fd7471aaadb53a6a9'
17.03.21 21:54:31 (+0200) Started service 'airplay sha256:29679b9e1f14592d62ed8e895831eb25731c84ae1767a68da6ece9fea5b7874d'
17.03.21 21:54:30 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:24 (+0200) <spotify> Spotify is disabled, exiting...
17.03.21 21:54:26 (+0200) <airplay> Airplay is disabled, exiting...
17.03.21 21:54:36 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:38 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:54:43 (+0200) <upnp> Ready for rendering.
17.03.21 21:54:43 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:45 (+0200) Started service 'multiroom-client sha256:c9321d0b94894c802db564253a9939bac8c8319919b8fc74cad88a4cd9e1383b'
17.03.21 21:54:49 (+0200) <multiroom-client> Starting multi-room client...
17.03.21 21:54:50 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:54:52 (+0200) Service exited 'spotify sha256:339c95b5a4bf395e051a582551f6648aa09cb4c3334a6e5fd7471aaadb53a6a9'
17.03.21 21:54:52 (+0200) Started service 'multiroom-server sha256:23838c0d6608478de0d9085f341f85d72f316cf75ed9866c975e37285212d391'
17.03.21 21:54:52 (+0200) <multiroom-client> snapclient v0.23.0
17.03.21 21:54:52 (+0200) <multiroom-client> Mode: STANDALONE
17.03.21 21:54:52 (+0200) <multiroom-client> Target snapcast server: 192.168.10.108
17.03.21 21:54:52 (+0200) <multiroom-client> Multi-room client disabled. Exiting...
17.03.21 21:54:53 (+0200) Service exited 'airplay sha256:29679b9e1f14592d62ed8e895831eb25731c84ae1767a68da6ece9fea5b7874d'
17.03.21 21:54:56 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:02 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:04 (+0200) Service exited 'multiroom-server sha256:23838c0d6608478de0d9085f341f85d72f316cf75ed9866c975e37285212d391'
17.03.21 21:55:04 (+0200) Service exited 'multiroom-client sha256:c9321d0b94894c802db564253a9939bac8c8319919b8fc74cad88a4cd9e1383b'
17.03.21 21:54:51 (+0200) <multiroom-server> Multi-room server blacklisted for raspberry-pi. Exiting...
17.03.21 21:55:08 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:08 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:55:13 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:18 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:24 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:29 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:34 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:39 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:43 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:55:44 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:49 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:55:55 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:00 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:05 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:11 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:16 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:21 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:23 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:56:26 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:31 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:37 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:42 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:47 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:52 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:56:57 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:02 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:08 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:08 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:57:13 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:18 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:23 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:28 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:34 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:39 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:44 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:49 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:54 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:57:58 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:57:59 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:05 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:10 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:15 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:21 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:26 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:31 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:36 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:42 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:47 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:52 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:58:53 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:58:57 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:02 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:07 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:13 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:18 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:23 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:28 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:34 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:39 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:44 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:49 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 21:59:53 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 21:59:54 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:00 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:05 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:10 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:15 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:20 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:25 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:31 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:36 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:41 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:46 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:51 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:57 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:00:58 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 22:01:02 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:07 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:12 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:17 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:23 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:28 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:33 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:38 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:43 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:48 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:54 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:01:59 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:04 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:08 (+0200) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
17.03.21 22:02:09 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:14 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:20 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:25 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:30 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:35 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:41 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:46 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:51 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:02:56 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:01 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:07 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:12 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:17 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:20 (+0200) <sound-supervisor> (node:34) UnhandledPromiseRejectionWarning: Error: Timeout after 600000ms
17.03.21 22:03:20 (+0200) <sound-supervisor>     at Timeout._onTimeout (/usr/src/node_modules/ts-retry-promise/dist/timeout.js:10:20)
17.03.21 22:03:20 (+0200) <sound-supervisor>     at listOnTimeout (internal/timers.js:554:17)
17.03.21 22:03:20 (+0200) <sound-supervisor>     at processTimers (internal/timers.js:497:7)
17.03.21 22:03:20 (+0200) <sound-supervisor> (node:34) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
17.03.21 22:03:20 (+0200) <sound-supervisor> (node:34) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
17.03.21 22:03:22 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:28 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:33 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:38 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:44 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:49 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:54 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:03:59 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:04:04 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:04:09 (+0200) <audio> Waiting for sound supervisor to start
17.03.21 22:04:15 (+0200) <audio> Waiting for sound supervisor to start

Please let me know if you see anything…
Thanks,

And yes, my release version is v3.5.2

PS: regarding setting dtparam to "audio=off" - I am not sure what is that… I am pretty sure I did not do anything like that, I did not even see it in that tutorial (lol).
Where can I check those parameters btw?

BenGast · March 18, 2021, 8:31am

Hello @tmigone,

Thanks for the reply!

Sorry but I can’t find where to see the balenaSound version. What I see on the dashboard is:

HOST OS VERSION balenaOS 2.54.2+rev1 development
SUPERVISOR VERSION 11.12.4

Note that now I can see the device on AirPlay (I probably had not wait enough last time) but still no sound coming out of the DAC from AirPlay or Bluetooth.

My logs are below.

Best,

BenGast

18.03.21 07:43:04 (+0000) Killing service 'bluetooth sha256:9d0130048b894cac4d99cf6ce5d21912304f1ceb478d43f6560e851648250340'
18.03.21 07:43:36 (+0000) Killed service 'bluetooth sha256:9d0130048b894cac4d99cf6ce5d21912304f1ceb478d43f6560e851648250340'
18.03.21 07:43:37 (+0000) Service exited 'bluetooth sha256:9d0130048b894cac4d99cf6ce5d21912304f1ceb478d43f6560e851648250340'
18.03.21 07:43:40 (+0000) Killing service 'audio sha256:675bf46baaed9077f43ab99a6e4221e5193bbbfcc0094213ea0cd3855f427da5'
18.03.21 07:43:46 (+0000) <sound-supervisor> Malformed packet!
18.03.21 07:43:53 (+0000) Service exited 'audio sha256:675bf46baaed9077f43ab99a6e4221e5193bbbfcc0094213ea0cd3855f427da5'
18.03.21 07:43:53 (+0000) Killed service 'audio sha256:675bf46baaed9077f43ab99a6e4221e5193bbbfcc0094213ea0cd3855f427da5'
18.03.21 07:43:55 (+0000) Killing service 'sound-supervisor sha256:cf4ab8e1e8e2a4748234136dbe7388e989eba3d0a2a9d93bc6a67b1e412f0a22'
18.03.21 07:44:07 (+0000) Service exited 'sound-supervisor sha256:cf4ab8e1e8e2a4748234136dbe7388e989eba3d0a2a9d93bc6a67b1e412f0a22'
18.03.21 07:44:07 (+0000) Killed service 'sound-supervisor sha256:cf4ab8e1e8e2a4748234136dbe7388e989eba3d0a2a9d93bc6a67b1e412f0a22'
18.03.21 07:44:07 (+0000) <sound-supervisor> [..................] \ : info lifecycle sound-supervisor@1.0.0~start: sound-sup


18.03.21 07:44:11 (+0000) Killing service 'upnp sha256:1ed195c21fe6cffb27c9c55785b3a0957647e6bbf39273cc50050d476b8a4087'
18.03.21 07:44:26 (+0000) Service exited 'upnp sha256:1ed195c21fe6cffb27c9c55785b3a0957647e6bbf39273cc50050d476b8a4087'
18.03.21 07:44:26 (+0000) Killed service 'upnp sha256:1ed195c21fe6cffb27c9c55785b3a0957647e6bbf39273cc50050d476b8a4087'
18.03.21 07:44:27 (+0000) Killing service 'airplay sha256:e5f40a0fb08c860fbaa1c9bee5ebffdc5ad05b12bf34de9e73484fcf5164cbb1'
18.03.21 07:44:44 (+0000) Killed service 'airplay sha256:e5f40a0fb08c860fbaa1c9bee5ebffdc5ad05b12bf34de9e73484fcf5164cbb1'
18.03.21 07:44:44 (+0000) Service exited 'airplay sha256:e5f40a0fb08c860fbaa1c9bee5ebffdc5ad05b12bf34de9e73484fcf5164cbb1'
18.03.21 07:44:46 (+0000) Killing service 'spotify sha256:6de7cabb846bbb2a577908404f8a0fb6ef828f8a2b35cf2ba1ac4dd6d423025f'
18.03.21 07:45:03 (+0000) Killed service 'spotify sha256:6de7cabb846bbb2a577908404f8a0fb6ef828f8a2b35cf2ba1ac4dd6d423025f'
18.03.21 07:45:03 (+0000) Service exited 'spotify sha256:6de7cabb846bbb2a577908404f8a0fb6ef828f8a2b35cf2ba1ac4dd6d423025f'
18.03.21 07:45:05 (+0000) Killing service 'multiroom-client sha256:f527af91c53873b069f9c20e4b70e15fd772049267302a38412cc2cf85ad7e99'
18.03.21 07:45:05 (+0000) Service is already stopped, removing container 'multiroom-client sha256:f527af91c53873b069f9c20e4b70e15fd772049267302a38412cc2cf85ad7e99'
18.03.21 07:45:05 (+0000) Killed service 'multiroom-client sha256:f527af91c53873b069f9c20e4b70e15fd772049267302a38412cc2cf85ad7e99'
18.03.21 07:45:06 (+0000) Killing service 'multiroom-server sha256:66cfcbb9e90bc7057d4c090b24554179e272350e0b632133ea6f63bd24cf23c7'
18.03.21 07:45:06 (+0000) Service is already stopped, removing container 'multiroom-server sha256:66cfcbb9e90bc7057d4c090b24554179e272350e0b632133ea6f63bd24cf23c7'
18.03.21 07:45:06 (+0000) Killed service 'multiroom-server sha256:66cfcbb9e90bc7057d4c090b24554179e272350e0b632133ea6f63bd24cf23c7'
18.03.21 07:45:06 (+0000) Rebooting
18.03.21 07:49:04 (+0000) Supervisor starting
18.03.21 07:47:30 (+0000) <bluetooth> Running balena base image entrypoint...
18.03.21 07:47:30 (+0000) <bluetooth> --- Bluetooth ---
18.03.21 07:47:30 (+0000) <bluetooth> Starting bluetooth service with settings:
18.03.21 07:47:30 (+0000) <bluetooth> - Device name: balenaOS 9b0c
18.03.21 07:47:30 (+0000) <bluetooth> - HCI interface: hci0
18.03.21 07:47:30 (+0000) <bluetooth> - Pairing mode: SSP
18.03.21 07:47:30 (+0000) <bluetooth> - PIN code: 0000
18.03.21 07:47:31 (+0000) <bluetooth> Available HCI interfaces: hci0
18.03.21 07:47:31 (+0000) <bluetooth> Resetting hci0
18.03.21 07:47:31 (+0000) <bluetooth> Configuring selected interface: hci0
18.03.21 07:47:31 (+0000) <bluetooth> hci0 Set Connectable complete, settings: powered connectable ssp br/edr le secure-conn 
18.03.21 07:47:31 (+0000) <bluetooth> hci0 Set Bondable complete, settings: powered connectable bondable ssp br/edr le secure-conn 
18.03.21 07:47:32 (+0000) <bluetooth> hci0 Set Discoverable complete, settings: powered connectable discoverable bondable ssp br/edr le secure-conn 
18.03.21 07:47:32 (+0000) <bluetooth> hci0 Set Secure Simple Pairing complete, settings: powered connectable discoverable bondable ssp br/edr le secure-conn 
18.03.21 07:47:32 (+0000) <bluetooth> Pairing mode set to 'Secure Simple Pairing Mode (SSPM)'. PIN code is NOT required.
18.03.21 07:47:46 (+0000) <bluetooth> Bluetooth agent started!
18.03.21 07:48:07 (+0000) <audio> 
18.03.21 07:48:09 (+0000) <audio> --- Audio ---
18.03.21 07:48:09 (+0000) <audio> Starting audio service with settings:
18.03.21 07:48:09 (+0000) <audio> - Pulse log level: NOTICE
18.03.21 07:48:09 (+0000) <audio> - Default output: AUTO
18.03.21 07:48:09 (+0000) <audio> 
18.03.21 07:48:09 (+0000) <audio> Detected audio cards:
18.03.21 07:48:10 (+0000) <audio> 0 ALSA bcm2835_alsa-bcm2835ALSA
18.03.21 07:48:10 (+0000) <audio> 1 C1 USB-Audio-CambridgeAudioDAC100USB1
18.03.21 07:48:10 (+0000) <audio> 
18.03.21 07:48:10 (+0000) <audio> 
18.03.21 07:48:31 (+0000) <audio> Waiting for sound supervisor to start
18.03.21 07:48:33 (+0000) <audio> Setting audio routing rules. Note that this can be changed after startup.
18.03.21 07:48:33 (+0000) <audio> Routing 'balena-sound.input' to 'balena-sound.output'.
18.03.21 07:48:33 (+0000) <audio> Routing 'balena-sound.output' to 'alsa_output.C1.analog-stereo'.
18.03.21 07:48:33 (+0000) <audio> W: [pulseaudio] main.c: This program is not intended to be run as root (unless --system is specified).
18.03.21 07:48:39 (+0000) <audio> E: [pulseaudio] module-loopback.c: No such sink.
18.03.21 07:48:39 (+0000) <audio> E: [pulseaudio] module.c: Failed to load module "module-loopback" (argument: "source="balena-sound.output.monitor" sink="alsa_output.C1.analog-stereo""): initialization failed.
18.03.21 07:48:39 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:39 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:39 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> E: [pulseaudio] main.c: Sink alsa_output.C1.analog-stereo does not exist.
18.03.21 07:48:40 (+0000) <audio> W: [pulseaudio] server-lookup.c: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11
18.03.21 07:48:40 (+0000) <audio> W: [pulseaudio] main.c: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11
18.03.21 07:47:48 (+0000) <sound-supervisor> 
18.03.21 07:47:48 (+0000) <sound-supervisor> > sound-supervisor@1.0.0 start /usr/src
18.03.21 07:47:48 (+0000) <sound-supervisor> > node build/index.js
18.03.21 07:47:48 (+0000) <sound-supervisor> 
18.03.21 07:48:30 (+0000) <sound-supervisor> Sound supervisor listening on port 3000
18.03.21 07:48:32 (+0000) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.1.115:4317
18.03.21 07:48:37 (+0000) <sound-supervisor> Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.1.115:4317
18.03.21 07:48:47 (+0000) <sound-supervisor> Connected to PulseAudio at 192.168.1.115:4317
18.03.21 07:48:47 (+0000) <sound-supervisor> Server protocol version: 33
18.03.21 07:48:47 (+0000) <sound-supervisor> Client protocol version: 33
18.03.21 07:47:43 (+0000) <airplay> Starting AirPlay plugin...
18.03.21 07:47:43 (+0000) <airplay> Device name: balenaSound AirPlay 9b0c
18.03.21 07:47:50 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:47:56 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:04 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:13 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:19 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:25 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:31 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:37 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:43 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:48 (+0000) <airplay> Waiting for audioblock to start...
18.03.21 07:48:49 (+0000) <airplay> Shairport-sync started. Device is discoverable as balenaSound AirPlay 9b0c
18.03.21 07:47:43 (+0000) <spotify> Starting Spotify plugin...
18.03.21 07:47:43 (+0000) <spotify> Device name: balenaSound Spotify 9b0c
18.03.21 07:47:43 (+0000) <spotify> [2021-03-18T07:47:43Z INFO  librespot] librespot (raspotify v0.14.0) 6aac8a6 (2020-07-24). Built on 2020-07-26. Build ID: wPNyqn0m
18.03.21 07:49:18 (+0000) Starting service 'multiroom-server sha256:66cfcbb9e90bc7057d4c090b24554179e272350e0b632133ea6f63bd24cf23c7'
18.03.21 07:49:18 (+0000) Starting service 'upnp sha256:1ed195c21fe6cffb27c9c55785b3a0957647e6bbf39273cc50050d476b8a4087'
18.03.21 07:49:18 (+0000) Starting service 'multiroom-client sha256:f527af91c53873b069f9c20e4b70e15fd772049267302a38412cc2cf85ad7e99'
18.03.21 07:49:40 (+0000) Started service 'upnp sha256:1ed195c21fe6cffb27c9c55785b3a0957647e6bbf39273cc50050d476b8a4087'
18.03.21 07:49:38 (+0000) <upnp> Starting UPnP plugin...
18.03.21 07:49:38 (+0000) <upnp> Device name: balenaSound UPnP 9b0c
18.03.21 07:49:39 (+0000) <upnp> gmediarender 0.0.7-git started [ gmediarender 0.0.7-git (libupnp-1.8.4; glib-2.58.1; gstreamer-1.14.4) ].
18.03.21 07:49:39 (+0000) <upnp> Logging switched off. Enable with --logfile=<filename> (or --logfile=stdout for console)
18.03.21 07:49:53 (+0000) Started service 'multiroom-client sha256:f527af91c53873b069f9c20e4b70e15fd772049267302a38412cc2cf85ad7e99'
18.03.21 07:49:51 (+0000) <multiroom-client> Starting multi-room client...
18.03.21 07:49:51 (+0000) <multiroom-client> Mode: STANDALONE
18.03.21 07:49:51 (+0000) <multiroom-client> Target snapcast server: 192.168.1.115
18.03.21 07:49:51 (+0000) <multiroom-client> Multi-room client disabled. Exiting...
18.03.21 07:49:53 (+0000) <upnp> Ready for rendering.
18.03.21 07:49:57 (+0000) Started service 'multiroom-server sha256:66cfcbb9e90bc7057d4c090b24554179e272350e0b632133ea6f63bd24cf23c7'
18.03.21 07:49:56 (+0000) <multiroom-server> Multi-room server blacklisted for raspberry-pi. Exiting...
18.03.21 07:50:04 (+0000) Service exited 'multiroom-client sha256:f527af91c53873b069f9c20e4b70e15fd772049267302a38412cc2cf85ad7e99'
18.03.21 07:50:09 (+0000) Service exited 'multiroom-server sha256:66cfcbb9e90bc7057d4c090b24554179e272350e0b632133ea6f63bd24cf23c7'
18.03.21 08:04:38 (+0000) <audio> W: [pulseaudio] module-loopback.c: Cannot set requested source latency of 66.67 ms, adjusting to 65.00 ms

drew · March 23, 2021, 3:26pm

@tmigone Could you please elaborate, where to check these variables you told about: "i2c_arm=on","spi=on","audio=on".
I don’t see where and how to set them…

drew · March 23, 2021, 3:40pm

Ok, nvm, found them in Device configuration variables, they are set by default:

So everything is right, but it still does not work. Any ideas why?

drew · March 24, 2021, 6:11pm

Ok, so what I see here is kinda funny…

Sound-supervisor (listens on port 3000):
Error connecting to audio block - Retry failed: connect ECONNREFUSED 192.168.10.108:4317
Audio (does not listen on port 4317, but):
Waiting for sound supervisor to start

Apart of jokes, this probably (not sure) means that something wrong with audio service rather then with sound supervisor (I may be wrong though…)

Audio also finds both of my sound cards (Pi’s and DAC), which is promising…:

24.03.21 19:52:01 (+0200)  audio  Waiting for sound supervisor to start
24.03.21 19:55:02 (+0200)  audio  
24.03.21 19:55:02 (+0200)  audio  --- Audio ---
24.03.21 19:55:02 (+0200)  audio  Starting audio service with settings:
24.03.21 19:55:10 (+0200)  audio  - 
24.03.21 19:55:10 (+0200)  audio  - Pulse log level: NOTICE
24.03.21 19:55:10 (+0200)  audio  - Default output: DAC
24.03.21 19:55:10 (+0200)  audio  
24.03.21 19:55:10 (+0200)  audio  Detected audio cards:
24.03.21 19:55:10 (+0200)  audio  0 bcm2835-alsa bcm2835_alsa-bcm2835ALSA
24.03.21 19:55:10 (+0200)  audio  1 dac RPi-simple-snd_rpi_hifiberry_dac
24.03.21 19:55:11 (+0200)  audio  
24.03.21 19:55:11 (+0200)  audio  
24.03.21 19:55:27 (+0200)  audio  Waiting for sound supervisor to start
24.03.21 19:55:33 (+0200)  audio  Waiting for sound supervisor to start
24.03.21 19:55:39 (+0200)  audio  Waiting for sound supervisor to start

But aplay -L issued in audio container returns nothing:

root@35dd599263fc:/usr/src# aplay -L
Illegal instruction (core dumped)
root@35dd599263fc:/usr/src# aplay -l
**** List of PLAYBACK Hardware Devices ****
Illegal instruction (core dumped)
root@35dd599263fc:/usr/src#

I’am not sure what is wrong at this stage? is my Pimoroni Pirat Hat broken? Anyone please help me to see the light! lol

klutchell · March 25, 2021, 8:12pm

Hey @bengast and @drew, you can make sure you’re running the latest balenaSound by following these steps:

navigate to GitHub - balenalabs/balena-sound: Build a single or multi-room streamer for an existing audio device using a Raspberry Pi! Supports Bluetooth, Airplay and Spotify Connect
select Deploy with Balena
select your existing balena-sound app

Another way to accomplish this would be to download or clone the source from Github and use the balena CLI to push to your existing app. Either method will make sure your app is up-to-date.

drew · March 26, 2021, 4:14pm

@klutchell,

Confirming, this is done.

Here is the release build log from the UI under my balena-sound/releases tab:

[Info]              Starting build for balena-sound, user g_a_s_
[Info]              Dashboard link: https://dashboard.balena-cloud.com/apps/1807565/devices
[Info]              Building on arm05
[Info]              Pulling previous images for caching purposes...
[Success]           Successfully pulled cache images
[Info]              Starting to build multiroom-client
[Info]              Starting to build audio
[Info]              Starting to build multiroom-server
[Info]              Starting to build sound-supervisor
[Info]              Starting to build airplay
[Info]              Starting to build spotify
[Info]              Starting to build upnp
[Info]              Starting to build bluetooth
[Success]           Successfully built service multiroom-client
[Success]           Successfully built service airplay
[Success]           Successfully built service multiroom-server
[Success]           Successfully built service spotify
[Success]           Successfully built service upnp
[Success]           Successfully built service bluetooth
[Success]           Successfully built service sound-supervisor
[Success]           Successfully built service audio
[Info]              Generating image deltas from release 7bfe41d7242fa642e416b4bfb8301b4f (id: 1729495)
[Success]           Successfully generated image deltas
[Info]              Uploading images
[Success]           Successfully uploaded images
[Error]             Error:: It is necessary that each release that has a release version1 and has a status that is equal to "success" and is not invalidated, belongs to an application that owns exactly one release that has a release version2 that is equal to the release version1 and has a status that is equal to "success" and is not invalidated.
[Info]              Built on arm05
[Success]           Release successfully created!
[Info]              Release: 030f9252a7b4de5a7f80a59adaaf6c7c (id: 1744080)
[Info]              Build finished in 6 minutes, 42 seconds

Strange thing though, build log says it’s done in 6 minutes, 42 sec, but the UI says build process is still running… already 20min

do not know if it’s normal…

BenGast · March 27, 2021, 9:30am

Hello @klutchell,

Indeed I was probably running an older version.

After following the steps above, I can connect from my phone to BT and Airplay and I have sound coming out of the USB DAC.

I now have another problem specific to bluetooth but I will post on another thread.

Thanks for the help.

Best,

BenGast

drew · March 27, 2021, 7:06pm

@klutchell well, I guess this is not normal:

I have no idea why new releases would not succeed. Neither balena push nor the gui button work… Removed the entire application, doing everything from scrach (using deploy button on the github balena-sound page). Typing all the variables again((((((

drew · March 29, 2021, 3:16pm

Ok, I did it from scratch and now it works… with bluetooth… kinda… But the lag is impossibly long and from time to time the sound breaks and the record is sticking like the old vinyl - so frustrating…

That is why I decided to move UPnP way with BubbleUPnp. Which does not work … The app finds my balena-sound host but when I press Play, there is no sound and the Play button does not change to Pause (as it does when I choose the ‘local renderer’)…

The upnp service container log:

29.03.21 18:13:01 (+0300)  upnp  Starting UPnP plugin...
29.03.21 18:13:01 (+0300)  upnp  Device name: cipherpunk-hifi-office
29.03.21 18:13:01 (+0300)  upnp  Using upnp UUID : 89fec2ab819f905da22037cfbee4765d
29.03.21 18:13:41 (+0300)  upnp  gmediarender 0.0.7-git started [ gmediarender 0.0.7-git (libupnp-1.8.4; glib-2.58.1; gstreamer-1.14.4) ].
29.03.21 18:13:41 (+0300)  upnp  Logging switched off. Enable with --logfile=<filename> (or --logfile=stdout for console)
29.03.21 18:14:06 (+0300)  upnp  Ready for rendering.
29.03.21 18:15:11 (+0300)  upnp  ERROR [2021-03-29 15:15:11.635989 | gstreamer] uridecodebin1: Error: Your GStreamer installation is missing a plug-in. (Debug: gsturidecodebin.c(988): no_more_pads_full (): /GstPlayBin:play/GstURIDecodeBin:uridecodebin1:
29.03.21 18:15:11 (+0300)  upnp  no suitable plugins found:
29.03.21 18:15:11 (+0300)  upnp  gstdecodebin2.c(4640): gst_decode_bin_expose (): /GstPlayBin:play/GstURIDecodeBin:uridecodebin1/GstDecodeBin:decodebin1:
29.03.21 18:15:11 (+0300)  upnp  no suitable plugins found:
29.03.21 18:15:11 (+0300)  upnp  Missing decoder: MPEG-4 AAC (audio/mpeg, mpegversion=(int)4, framed=(boolean)true, stream-format=(string)raw, level=(string)2, base-profile=(string)lc, profile=(string)lc, codec_data=(buffer)12100000000000000000000000000000, rate=(int)44100, channels=(int)2)
29.03.21 18:15:11 (+0300)  upnp  )
29.03.21 18:16:06 (+0300)  upnp  ERROR [2021-03-29 15:16:06.088873 | gstreamer] uridecodebin1: Error: Your GStreamer installation is missing a plug-in. (Debug: gsturidecodebin.c(988): no_more_pads_full (): /GstPlayBin:play/GstURIDecodeBin:uridecodebin1:
29.03.21 18:16:06 (+0300)  upnp  no suitable plugins found:
29.03.21 18:16:06 (+0300)  upnp  gstdecodebin2.c(4640): gst_decode_bin_expose (): /GstPlayBin:play/GstURIDecodeBin:uridecodebin1/GstDecodeBin:decodebin1:
29.03.21 18:16:06 (+0300)  upnp  no suitable plugins found:
29.03.21 18:16:06 (+0300)  upnp  Missing decoder: MPEG-4 AAC (audio/mpeg, mpegversion=(int)4, framed=(boolean)true, stream-format=(string)raw, level=(string)2, base-profile=(string)lc, profile=(string)lc, codec_data=(buffer)12100000000000000000000000000000, rate=(int)44100, channels=(int)2)
29.03.21 18:16:06 (+0300)  upnp  )

Does the UPnP need any special configuration?
I’d appreciate any ideas what is wrong.

tmigone · April 1, 2021, 8:51pm

@bengast, @drew For future reference, it looks like both of you were hitting [this](raspberrypi: audio service not starting) bug which was fixed in v3.5.2.

@drew, that upnp error is something new. I’ll create a GitHub issue to track progress on a fix for it. I’m not 100% sure from the error logs alone what the problem is but I’ll try to replicate it and let you know. Would you mind sharing what type of content you tried to play? Is it a video or audio?

tmigone · April 1, 2021, 8:51pm

Issue here: upnp: missing plugin · Issue #435 · balenalabs/balena-sound · GitHub

drew · April 2, 2021, 6:32pm

@timgone, written my answers at the github issue page you posted. Thank you for your help!