Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

🐛 | 3 minute start-up time #1110

Closed
Toqqi opened this issue Oct 22, 2020 · 45 comments · Fixed by #2315
Closed

🐛 | 3 minute start-up time #1110

Toqqi opened this issue Oct 22, 2020 · 45 comments · Fixed by #2315
Labels
bug legacy_v2 Issues, discussions and PRs related to Version 2.x spotify edition Tips Tricks Hacks

Comments

@Toqqi
Copy link
Contributor

Toqqi commented Oct 22, 2020

Bug

phoniebox-startup-scripts.service takes around 3 minutes to start up, then runs fine. I'm looking for help to resolve whatever error is causing the delay.

What I did

I installed the raspberry pi with above mentioned buster image and ran the installer script.

What happened

I takes a long time until the startup sound is played (3 minutes).
From systemd-analyze blame I instantly noticed 2min 57.826s phoniebox-startup-scripts.service.

Then journalctl -u phoniebox-startup-scripts.service -b revealed

Oct 22 11:26:52 raspberrypi systemd[1]: Starting Phoniebox Startup...
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOFOLDERSPATH="/home/pi/RPi-Jukebox-RFID/shared/audiofolders"
Oct 22 11:26:52 raspberrypi bash[315]: PLAYLISTSFOLDERPATH="/home/pi/RPi-Jukebox-RFID/playlists"
Oct 22 11:26:52 raspberrypi bash[315]: SECONDSWIPE="PLAY"
Oct 22 11:26:52 raspberrypi bash[315]: SECONDSWIPEPAUSE="2"
Oct 22 11:26:52 raspberrypi bash[315]: SECONDSWIPEPAUSECONTROLS="ON"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOIFACENAME="Headphone"
Oct 22 11:26:52 raspberrypi bash[315]: VOLUMEMANAGER="mpd"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOVOLCHANGESTEP="3"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOVOLMAXLIMIT="100"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOVOLMINLIMIT="1"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOVOLSTARTUP="5"
Oct 22 11:26:52 raspberrypi bash[315]: VOLCHANGEIDLE="TRUE"
Oct 22 11:26:52 raspberrypi bash[315]: IDLETIMESHUTDOWN="0"
Oct 22 11:26:52 raspberrypi bash[315]: SHOWCOVER="ON"
Oct 22 11:26:52 raspberrypi bash[315]: READWLANIPYN="OFF"
Oct 22 11:26:52 raspberrypi bash[315]: EDITION="plusSpotify"
Oct 22 11:26:52 raspberrypi bash[315]: LANG="en-UK"
Oct 22 11:26:52 raspberrypi bash[315]: VERSION="2.1.1 - 70f989b - master"
Oct 22 11:26:52 raspberrypi bash[315]: CMDVOLUP=""
Oct 22 11:26:52 raspberrypi bash[315]: CMDVOLDOWN=""
Oct 22 11:26:52 raspberrypi bash[315]: CMDNEXT=""
Oct 22 11:26:52 raspberrypi bash[315]: CMDPREV=""
Oct 22 11:26:52 raspberrypi bash[315]: CMDREWIND=""
Oct 22 11:26:52 raspberrypi bash[315]: CMDSEEKFORW=""
Oct 22 11:26:52 raspberrypi bash[315]: CMDSEEKBACK=""
Oct 22 11:26:53 raspberrypi bash[315]: 5
Oct 22 11:26:53 raspberrypi sudo[336]:       pi : TTY=unknown ; PWD=/home/pi/RPi-Jukebox-RFID ; USER=root ; COMMAND=/
Oct 22 11:26:53 raspberrypi sudo[336]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 22 11:26:53 raspberrypi sudo[336]: pam_unix(sudo:session): session closed for user root
Oct 22 11:26:54 raspberrypi sudo[357]:       pi : TTY=unknown ; PWD=/home/pi/RPi-Jukebox-RFID ; USER=root ; COMMAND=/
Oct 22 11:26:54 raspberrypi sudo[357]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 22 11:26:54 raspberrypi sudo[357]: pam_unix(sudo:session): session closed for user root
Oct 22 11:26:54 raspberrypi sudo[374]:       pi : TTY=unknown ; PWD=/home/pi/RPi-Jukebox-RFID ; USER=root ; COMMAND=/
Oct 22 11:26:55 raspberrypi sudo[374]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 22 11:26:55 raspberrypi sudo[374]: pam_unix(sudo:session): session closed for user root
Oct 22 11:29:58 raspberrypi bash[315]: OK MPD 0.19.0
Oct 22 11:29:58 raspberrypi bash[315]: OK
Oct 22 11:29:58 raspberrypi bash[315]: OK
Oct 22 11:29:58 raspberrypi bash[315]: High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
Oct 22 11:29:58 raspberrypi bash[315]:         version 1.25.10; written and copyright by Michael Hipp and others
Oct 22 11:29:58 raspberrypi bash[315]:         free software (LGPL) without any warranty but with best wishes
Oct 22 11:29:59 raspberrypi bash[315]: Directory: /home/pi/RPi-Jukebox-RFID/shared/
Oct 22 11:29:59 raspberrypi bash[315]: Playing MPEG stream 1 of 1: startupsound.mp3 ...
Oct 22 11:29:59 raspberrypi bash[315]: MPEG 1.0 L III cbr64 44100 j-s
Oct 22 11:29:59 raspberrypi bash[315]: Artist:  Phoniebox
Oct 22 11:30:03 raspberrypi bash[315]: [0:04] Decoding of startupsound.mp3 finished.
Oct 22 11:30:03 raspberrypi bash[315]: volume:  5%   repeat: off   random: off   single: off   consume: off
Oct 22 11:30:03 raspberrypi systemd[1]: Started Phoniebox Startup.

I expected this to happen

From other posts, I am seeing that phoniebox-startup-scripts.service only takes around 4 seconds to start.

Further information that might help

Output of tail -n 500 /var/log/syslog

tail -n 500 /var/log/syslog
Oct 22 11:26:51 raspberrypi kernel: [    1.085407] io scheduler mq-deadline registered
Oct 22 11:26:51 raspberrypi kernel: [    1.085434] io scheduler kyber registered
Oct 22 11:26:51 raspberrypi kernel: [    1.088159] bcm2708_fb soc:fb: FB found 1 display(s)
Oct 22 11:26:51 raspberrypi kernel: [    1.097270] Console: switching to colour frame buffer device 82x26
Oct 22 11:26:51 raspberrypi kernel: [    1.102573] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
Oct 22 11:26:51 raspberrypi kernel: [    1.110603] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
Oct 22 11:26:51 raspberrypi kernel: [    1.115718] bcm2835-rng 20104000.rng: hwrng registered
Oct 22 11:26:51 raspberrypi kernel: [    1.118402] vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
Oct 22 11:26:51 raspberrypi kernel: [    1.123492] vc-sm: Videocore shared memory driver
Oct 22 11:26:51 raspberrypi kernel: [    1.126464] gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000
Oct 22 11:26:51 raspberrypi kernel: [    1.147497] brd: module loaded
Oct 22 11:26:51 raspberrypi kernel: [    1.161423] loop: module loaded
Oct 22 11:26:51 raspberrypi kernel: [    1.165389] Loading iSCSI transport class v2.0-870.
Oct 22 11:26:51 raspberrypi kernel: [    1.168461] usbcore: registered new interface driver smsc95xx
Oct 22 11:26:51 raspberrypi kernel: [    1.170665] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Oct 22 11:26:51 raspberrypi kernel: [    1.900815] Core Release: 2.80a
Oct 22 11:26:51 raspberrypi kernel: [    1.902967] Setting default values for core params
Oct 22 11:26:51 raspberrypi kernel: [    1.905089] Finished setting default values for core params
Oct 22 11:26:51 raspberrypi kernel: [    2.107271] Using Buffer DMA mode
Oct 22 11:26:51 raspberrypi kernel: [    2.109349] Periodic Transfer Interrupt Enhancement - disabled
Oct 22 11:26:51 raspberrypi kernel: [    2.111452] Multiprocessor Interrupt Enhancement - disabled
Oct 22 11:26:51 raspberrypi kernel: [    2.113545] OTG VER PARAM: 0, OTG VER FLAG: 0
Oct 22 11:26:51 raspberrypi kernel: [    2.115707] Dedicated Tx FIFOs mode
Oct 22 11:26:51 raspberrypi kernel: [    2.118455] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = d7d14000 dma = 0x57d14000 len=9024
Oct 22 11:26:51 raspberrypi kernel: [    2.122566] FIQ FSM acceleration enabled for :
Oct 22 11:26:51 raspberrypi kernel: [    2.122566] Non-periodic Split Transactions
Oct 22 11:26:51 raspberrypi kernel: [    2.122566] Periodic Split Transactions
Oct 22 11:26:51 raspberrypi kernel: [    2.122566] High-Speed Isochronous Endpoints
Oct 22 11:26:51 raspberrypi kernel: [    2.122566] Interrupt/Control Split Transaction hack enabled
Oct 22 11:26:51 raspberrypi kernel: [    2.131846] dwc_otg: Microframe scheduler enabled
Oct 22 11:26:51 raspberrypi kernel: [    2.132026] WARN::hcd_init_fiq:457: FIQ on core 0
Oct 22 11:26:51 raspberrypi kernel: [    2.133898] WARN::hcd_init_fiq:458: FIQ ASM at c0569268 length 36
Oct 22 11:26:51 raspberrypi kernel: [    2.135763] WARN::hcd_init_fiq:497: MPHI regs_base at dc810000
Oct 22 11:26:51 raspberrypi kernel: [    2.137715] dwc_otg 20980000.usb: DWC OTG Controller
Oct 22 11:26:51 raspberrypi kernel: [    2.139673] dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1
Oct 22 11:26:51 raspberrypi kernel: [    2.141617] dwc_otg 20980000.usb: irq 56, io mem 0x00000000
Oct 22 11:26:51 raspberrypi kernel: [    2.143473] Init: Port Power? op_state=1
Oct 22 11:26:51 raspberrypi kernel: [    2.145350] Init: Power Port (0)
Oct 22 11:26:51 raspberrypi kernel: [    2.147570] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.04
Oct 22 11:26:51 raspberrypi kernel: [    2.151220] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Oct 22 11:26:51 raspberrypi kernel: [    2.153152] usb usb1: Product: DWC OTG Controller
Oct 22 11:26:51 raspberrypi kernel: [    2.155121] usb usb1: Manufacturer: Linux 5.4.51+ dwc_otg_hcd
Oct 22 11:26:51 raspberrypi kernel: [    2.157057] usb usb1: SerialNumber: 20980000.usb
Oct 22 11:26:51 raspberrypi kernel: [    2.159841] hub 1-0:1.0: USB hub found
Oct 22 11:26:51 raspberrypi kernel: [    2.161801] hub 1-0:1.0: 1 port detected
Oct 22 11:26:51 raspberrypi kernel: [    2.164610] dwc_otg: FIQ enabled
Oct 22 11:26:51 raspberrypi kernel: [    2.164624] dwc_otg: NAK holdoff enabled
Oct 22 11:26:51 raspberrypi kernel: [    2.164633] dwc_otg: FIQ split-transaction FSM enabled
Oct 22 11:26:51 raspberrypi kernel: [    2.164650] Module dwc_common_port init
Oct 22 11:26:51 raspberrypi kernel: [    2.165132] usbcore: registered new interface driver usb-storage
Oct 22 11:26:51 raspberrypi kernel: [    2.167466] mousedev: PS/2 mouse device common for all mice
Oct 22 11:26:51 raspberrypi kernel: [    2.170926] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
Oct 22 11:26:51 raspberrypi kernel: [    2.173280] bcm2835-cpufreq: min=700000 max=1000000
Oct 22 11:26:51 raspberrypi kernel: [    2.177081] sdhci: Secure Digital Host Controller Interface driver
Oct 22 11:26:51 raspberrypi kernel: [    2.179091] sdhci: Copyright(c) Pierre Ossman
Oct 22 11:26:51 raspberrypi kernel: [    2.181658] mmc-bcm2835 20300000.mmcnr: could not get clk, deferring probe
Oct 22 11:26:51 raspberrypi kernel: [    2.184598] sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe
Oct 22 11:26:51 raspberrypi kernel: [    2.186977] sdhci-pltfm: SDHCI platform and OF driver helper
Oct 22 11:26:51 raspberrypi kernel: [    2.189682] ledtrig-cpu: registered to indicate activity on CPUs
Oct 22 11:26:51 raspberrypi kernel: [    2.192125] hidraw: raw HID events driver (C) Jiri Kosina
Oct 22 11:26:51 raspberrypi kernel: [    2.194484] usbcore: registered new interface driver usbhid
Oct 22 11:26:51 raspberrypi kernel: [    2.196600] usbhid: USB HID core driver
Oct 22 11:26:51 raspberrypi kernel: [    2.199700] vchiq: vchiq_init_state: slot_zero = (ptrval)
Oct 22 11:26:51 raspberrypi kernel: [    2.203572] [vc_sm_connected_init]: start
Oct 22 11:26:51 raspberrypi kernel: [    2.212426] [vc_sm_connected_init]: end - returning 0
Oct 22 11:26:51 raspberrypi kernel: [    2.216420] Initializing XFRM netlink socket
Oct 22 11:26:51 raspberrypi kernel: [    2.218436] NET: Registered protocol family 17
Oct 22 11:26:51 raspberrypi kernel: [    2.220482] Key type dns_resolver registered
Oct 22 11:26:51 raspberrypi kernel: [    2.223354] registered taskstats version 1
Oct 22 11:26:51 raspberrypi kernel: [    2.225375] Loading compiled-in X.509 certificates
Oct 22 11:26:51 raspberrypi kernel: [    2.238782] uart-pl011 20201000.serial: cts_event_workaround enabled
Oct 22 11:26:51 raspberrypi kernel: [    2.240931] 20201000.serial: ttyAMA0 at MMIO 0x20201000 (irq = 81, base_baud = 0) is a PL011 rev2
Oct 22 11:26:51 raspberrypi kernel: [    2.364713] random: fast init done
Oct 22 11:26:51 raspberrypi kernel: [    3.123909] printk: console [ttyAMA0] enabled
Oct 22 11:26:51 raspberrypi kernel: [    3.132385] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
Oct 22 11:26:51 raspberrypi kernel: [    3.143443] mmc-bcm2835 20300000.mmcnr: mmc_debug:0 mmc_debug2:0
Oct 22 11:26:51 raspberrypi kernel: [    3.151585] mmc-bcm2835 20300000.mmcnr: DMA channel allocated
Oct 22 11:26:51 raspberrypi kernel: [    3.185134] sdhost: log_buf @ (ptrval) (57d13000)
Oct 22 11:26:51 raspberrypi kernel: [    3.224125] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
Oct 22 11:26:51 raspberrypi kernel: [    3.233219] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Oct 22 11:26:51 raspberrypi kernel: [    3.240656] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Oct 22 11:26:51 raspberrypi kernel: [    3.250684] of_cfs_init
Oct 22 11:26:51 raspberrypi kernel: [    3.269757] of_cfs_init: OK
Oct 22 11:26:51 raspberrypi kernel: [    3.274756] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Oct 22 11:26:51 raspberrypi kernel: [    3.283151] Waiting for root device PARTUUID=d6a683cc-02...
Oct 22 11:26:51 raspberrypi kernel: [    3.293456] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
Oct 22 11:26:51 raspberrypi kernel: [    3.333446] mmc0: host does not support reading read-only switch, assuming write-enable
Oct 22 11:26:51 raspberrypi kernel: [    3.348180] mmc0: new high speed SDHC card at address 59b4
Oct 22 11:26:51 raspberrypi kernel: [    3.357128] mmcblk0: mmc0:59b4 USDU1 14.7 GiB
Oct 22 11:26:51 raspberrypi kernel: [    3.367268]  mmcblk0: p1 p2
Oct 22 11:26:51 raspberrypi kernel: [    3.416865] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Oct 22 11:26:51 raspberrypi kernel: [    3.429059] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Oct 22 11:26:51 raspberrypi kernel: [    3.447078] devtmpfs: mounted
Oct 22 11:26:51 raspberrypi kernel: [    3.457748] Freeing unused kernel memory: 492K
Oct 22 11:26:51 raspberrypi kernel: [    3.464220] This architecture does not have kernel memory protection.
Oct 22 11:26:51 raspberrypi kernel: [    3.472666] Run /sbin/init as init process
Oct 22 11:26:51 raspberrypi kernel: [    3.485490] mmc1: new high speed SDIO card at address 0001
Oct 22 11:26:51 raspberrypi kernel: [    4.373682] NET: Registered protocol family 10
Oct 22 11:26:51 raspberrypi kernel: [    4.382128] Segment Routing with IPv6
Oct 22 11:26:51 raspberrypi kernel: [    5.548741] uart-pl011 20201000.serial: no DMA platform data
Oct 22 11:26:51 raspberrypi kernel: [    6.639664] random: systemd: uninitialized urandom read (16 bytes read)
Oct 22 11:26:51 raspberrypi kernel: [    6.674842] random: systemd: uninitialized urandom read (16 bytes read)
Oct 22 11:26:51 raspberrypi kernel: [    6.755378] random: systemd: uninitialized urandom read (16 bytes read)
Oct 22 11:26:51 raspberrypi kernel: [    9.328501] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Oct 22 11:26:51 raspberrypi kernel: [   11.324160] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Oct 22 11:26:51 raspberrypi kernel: [   11.326364] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
Oct 22 11:26:51 raspberrypi kernel: [   11.326389] [vc_sm_connected_init]: start
Oct 22 11:26:51 raspberrypi kernel: [   11.340742] [vc_sm_connected_init]: installed successfully
Oct 22 11:26:51 raspberrypi kernel: [   11.381772] mc: Linux media interface: v0.10
Oct 22 11:26:51 raspberrypi kernel: [   11.511903] videodev: Linux video capture interface: v2.00
Oct 22 11:26:51 raspberrypi kernel: [   11.596319] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Oct 22 11:26:51 raspberrypi kernel: [   11.598476] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Oct 22 11:26:51 raspberrypi kernel: [   11.637561] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
Oct 22 11:26:51 raspberrypi kernel: [   11.649905] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Oct 22 11:26:51 raspberrypi kernel: [   11.672629] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
Oct 22 11:26:51 raspberrypi kernel: [   11.673276] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
Oct 22 11:26:51 raspberrypi kernel: [   11.678392] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
Oct 22 11:26:51 raspberrypi kernel: [   11.680061] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
Oct 22 11:26:51 raspberrypi kernel: [   11.680102] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
Oct 22 11:26:51 raspberrypi kernel: [   11.680129] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
Oct 22 11:26:51 raspberrypi kernel: [   11.680157] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
Oct 22 11:26:51 raspberrypi kernel: [   11.680197] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
Oct 22 11:26:51 raspberrypi kernel: [   11.681392] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
Oct 22 11:26:51 raspberrypi kernel: [   11.689233] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Oct 22 11:26:51 raspberrypi kernel: [   11.767171] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
Oct 22 11:26:51 raspberrypi kernel: [   11.767237] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
Oct 22 11:26:51 raspberrypi kernel: [   11.781010] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
Oct 22 11:26:51 raspberrypi kernel: [   11.781072] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
Oct 22 11:26:51 raspberrypi kernel: [   11.794845] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
Oct 22 11:26:51 raspberrypi kernel: [   11.794927] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
Oct 22 11:26:51 raspberrypi kernel: [   12.036007] snd-rpi-simple soc:sound: pcm5102a-hifi <-> 20203000.i2s mapping ok
Oct 22 11:26:51 raspberrypi kernel: [   13.167965] cfg80211: Loading compiled-in X.509 certificates for regulatory database
Oct 22 11:26:51 raspberrypi kernel: [   13.488033] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
Oct 22 11:26:51 raspberrypi kernel: [   13.724828] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
Oct 22 11:26:51 raspberrypi kernel: [   13.733453] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
Oct 22 11:26:51 raspberrypi kernel: [   13.735519] usbcore: registered new interface driver brcmfmac
Oct 22 11:26:51 raspberrypi kernel: [   13.760959] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43430-sdio.raspberrypi,model-zero-w.txt failed with error -2
Oct 22 11:26:51 raspberrypi kernel: [   14.006435] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
Oct 22 11:26:51 raspberrypi kernel: [   14.006599] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
Oct 22 11:26:51 raspberrypi kernel: [   14.007666] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Oct 22 2019 01:59:28 version 7.45.98.94 (r723000 CY) FWID 01-3b33decd
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in FUSE Control File System being skipped.
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in Huge Pages File System being skipped.
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
Oct 22 11:26:51 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Oct 22 11:26:51 raspberrypi systemd[1]: Started Create Volatile Files and Directories.
Oct 22 11:26:51 raspberrypi systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Oct 22 11:26:51 raspberrypi systemd-udevd[125]: Using default interface naming scheme 'v240'.
Oct 22 11:26:51 raspberrypi systemd[1]: Starting Network Time Synchronization...
Oct 22 11:26:51 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.
Oct 22 11:26:51 raspberrypi systemd[1]: Started Update UTMP about System Boot/Shutdown.
Oct 22 11:26:51 raspberrypi systemd[1]: Started Raise network interfaces.
Oct 22 11:26:51 raspberrypi systemd[1]: Started Network Time Synchronization.
Oct 22 11:26:51 raspberrypi systemd[1]: Reached target System Initialization.
Oct 22 11:26:51 raspberrypi systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Oct 22 11:26:51 raspberrypi systemd[1]: Started Daily Cleanup of Temporary Directories.
Oct 22 11:26:51 raspberrypi systemd[1]: Listening on D-Bus System Message Bus Socket.
Oct 22 11:26:51 raspberrypi systemd[1]: Listening on triggerhappy.socket.
Oct 22 11:26:51 raspberrypi systemd[1]: Reached target Sockets.
Oct 22 11:26:51 raspberrypi systemd[1]: Reached target Basic System.
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
Oct 22 11:26:51 raspberrypi systemd[1]: Starting System Logging Service...
Oct 22 11:26:51 raspberrypi systemd[1]: Starting Login Service...
Oct 22 11:26:51 raspberrypi systemd[1]: Starting Phoniebox Startup Sound...
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in Turn on SSH if /boot/ssh is present being skipped.
Oct 22 11:26:51 raspberrypi systemd[1]: Started Regular background program processing daemon.
Oct 22 11:26:51 raspberrypi systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped.
Oct 22 11:26:51 raspberrypi rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Oct 22 11:26:51 raspberrypi cron[292]: (CRON) INFO (pidfile fd = 3)
Oct 22 11:26:51 raspberrypi rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="287" x-info="https://www.rsyslog.com"] start
Oct 22 11:26:51 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Oct 22 11:26:51 raspberrypi cron[292]: (CRON) INFO (Running @reboot jobs)
Oct 22 11:26:51 raspberrypi systemd[1]: Starting rng-tools.service...
Oct 22 11:26:51 raspberrypi systemd[1]: Starting Deferred execution scheduler...
Oct 22 11:26:52 raspberrypi rng-tools[300]: Starting Hardware RNG entropy gatherer daemon: rngd.
Oct 22 11:26:52 raspberrypi rngd[307]: rngd 2-unofficial-mt.14 starting up...
Oct 22 11:26:52 raspberrypi dhcpcd[294]: dev: loaded udev
Oct 22 11:26:52 raspberrypi systemd[1]: Started D-Bus System Message Bus.
Oct 22 11:26:52 raspberrypi rngd[307]: entropy feed to the kernel ready
Oct 22 11:26:52 raspberrypi kernel: [   19.677176] random: crng init done
Oct 22 11:26:52 raspberrypi kernel: [   19.677201] random: 7 urandom warning(s) missed due to ratelimiting
Oct 22 11:26:52 raspberrypi kernel: [   19.768136] 8021q: 802.1Q VLAN Support v1.8
Oct 22 11:26:52 raspberrypi systemd[1]: Starting Phoniebox Startup...
Oct 22 11:26:52 raspberrypi systemd[1]: Starting WPA supplicant...
Oct 22 11:26:52 raspberrypi systemd[1]: Starting Check for Raspberry Pi EEPROM updates...
Oct 22 11:26:52 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOFOLDERSPATH="/home/pi/RPi-Jukebox-RFID/shared/audiofolders"
Oct 22 11:26:52 raspberrypi bash[315]: PLAYLISTSFOLDERPATH="/home/pi/RPi-Jukebox-RFID/playlists"
Oct 22 11:26:52 raspberrypi bash[315]: SECONDSWIPE="PLAY"
Oct 22 11:26:52 raspberrypi bash[315]: SECONDSWIPEPAUSE="2"
Oct 22 11:26:52 raspberrypi bash[315]: SECONDSWIPEPAUSECONTROLS="ON"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOIFACENAME="Headphone"
Oct 22 11:26:52 raspberrypi bash[315]: VOLUMEMANAGER="mpd"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOVOLCHANGESTEP="3"
Oct 22 11:26:52 raspberrypi bash[315]: AUDIOVOLMAXLIMIT="100"
Oct 22 11:26:53 raspberrypi bash[315]: AUDIOVOLMINLIMIT="1"
Oct 22 11:26:53 raspberrypi bash[315]: AUDIOVOLSTARTUP="5"
Oct 22 11:26:53 raspberrypi bash[315]: VOLCHANGEIDLE="TRUE"
Oct 22 11:26:53 raspberrypi bash[315]: IDLETIMESHUTDOWN="0"
Oct 22 11:26:53 raspberrypi bash[315]: SHOWCOVER="ON"
Oct 22 11:26:53 raspberrypi bash[315]: READWLANIPYN="OFF"
Oct 22 11:26:53 raspberrypi bash[315]: EDITION="plusSpotify"
Oct 22 11:26:53 raspberrypi bash[315]: LANG="en-UK"
Oct 22 11:26:53 raspberrypi bash[315]: VERSION="2.1.1 - 70f989b - master"
Oct 22 11:26:53 raspberrypi bash[315]: CMDVOLUP=""
Oct 22 11:26:53 raspberrypi bash[315]: CMDVOLDOWN=""
Oct 22 11:26:53 raspberrypi bash[315]: CMDNEXT=""
Oct 22 11:26:53 raspberrypi bash[315]: CMDPREV=""
Oct 22 11:26:53 raspberrypi bash[315]: CMDREWIND=""
Oct 22 11:26:53 raspberrypi bash[315]: CMDSEEKFORW=""
Oct 22 11:26:53 raspberrypi bash[315]: CMDSEEKBACK=""
Oct 22 11:26:53 raspberrypi systemd[1]: Started Manage Sound Card State (restore and store).
Oct 22 11:26:53 raspberrypi bash[315]: 5
Oct 22 11:26:53 raspberrypi dhcpcd[294]: wlan0: starting wpa_supplicant
Oct 22 11:26:53 raspberrypi alsactl[332]: alsactl 1.1.8 daemon started
Oct 22 11:26:53 raspberrypi systemd[1]: Starting Save/Restore Sound Card State...
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: Found user 'avahi' (UID 108) and group 'avahi' (GID 113).
Oct 22 11:26:53 raspberrypi systemd[1]: Reached target System Time Synchronized.
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: Successfully dropped root privileges.
Oct 22 11:26:53 raspberrypi systemd[1]: Started Daily apt download activities.
Oct 22 11:26:53 raspberrypi dhcpcd-run-hooks[337]: wlan0: starting wpa_supplicant
Oct 22 11:26:53 raspberrypi systemd[1]: Started Daily man-db regeneration.
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: avahi-daemon 0.7 starting up.
Oct 22 11:26:53 raspberrypi systemd[1]: Started Daily rotation of log files.
Oct 22 11:26:53 raspberrypi wpa_supplicant[317]: Successfully initialized wpa_supplicant
Oct 22 11:26:53 raspberrypi systemd[1]: Started Clean PHP session files every 30 mins.
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: Successfully called chroot().
Oct 22 11:26:53 raspberrypi systemd[1]: Started Daily apt upgrade and clean activities.
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: Successfully dropped remaining capabilities.
Oct 22 11:26:53 raspberrypi systemd[1]: Reached target Timers.
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: No service file found in /etc/avahi/services.
Oct 22 11:26:53 raspberrypi systemd[1]: Started System Logging Service.
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: Network interface enumeration completed.
Oct 22 11:26:53 raspberrypi systemd[1]: phoniebox-startup-sound.service: Control process exited, code=exited, status=1/FAILURE
Oct 22 11:26:53 raspberrypi avahi-daemon[324]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 969770058.
Oct 22 11:26:53 raspberrypi systemd[1]: phoniebox-startup-sound.service: Failed with result 'exit-code'.
Oct 22 11:26:53 raspberrypi systemd[1]: Failed to start Phoniebox Startup Sound.
Oct 22 11:26:53 raspberrypi systemd[1]: Started rng-tools.service.
Oct 22 11:26:53 raspberrypi systemd[1]: Started Deferred execution scheduler.
Oct 22 11:26:53 raspberrypi systemd[1]: Started Check for Raspberry Pi EEPROM updates.
Oct 22 11:26:53 raspberrypi systemd[1]: Started Save/Restore Sound Card State.
Oct 22 11:26:54 raspberrypi kernel: [   21.476476] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
Oct 22 11:26:54 raspberrypi systemd[1]: Reached target Sound Card.
Oct 22 11:26:54 raspberrypi dbus-daemon[306]: [system] Successfully activated service 'org.freedesktop.systemd1'
Oct 22 11:26:54 raspberrypi systemd[1]: Started Login Service.
Oct 22 11:26:54 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Oct 22 11:26:54 raspberrypi systemd[1]: Started WPA supplicant.
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: connected to Access Point `'
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: waiting for carrier
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: waiting for carrier
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: carrier acquired
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: using static address 192.168.1.146/24
Oct 22 11:26:54 raspberrypi avahi-daemon[324]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.146.
Oct 22 11:26:54 raspberrypi avahi-daemon[324]: New relevant interface wlan0.IPv4 for mDNS.
Oct 22 11:26:54 raspberrypi avahi-daemon[324]: Registering new address record for 192.168.1.146 on wlan0.IPv4.
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: adding route to 192.168.1.0/24
Oct 22 11:26:54 raspberrypi dhcpcd[294]: wlan0: adding default route via 192.168.1.1
Oct 22 11:26:55 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Oct 22 11:26:55 raspberrypi kernel: [   23.339914] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Oct 22 11:26:56 raspberrypi dhcpcd[485]: wlan0: carrier lost
Oct 22 11:26:56 raspberrypi dhcpcd[294]: forked to background, child pid 485
Oct 22 11:26:56 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Oct 22 11:26:56 raspberrypi systemd[1]: Reached target Network.
Oct 22 11:26:56 raspberrypi systemd[1]: Starting Permit User Sessions...
Oct 22 11:26:56 raspberrypi avahi-daemon[324]: Withdrawing address record for 192.168.1.146 on wlan0.
Oct 22 11:26:56 raspberrypi avahi-daemon[324]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.146.
Oct 22 11:26:56 raspberrypi avahi-daemon[324]: Interface wlan0.IPv4 no longer relevant for mDNS.
Oct 22 11:26:56 raspberrypi dhcpcd[485]: wlan0: deleting route to 192.168.1.0/24
Oct 22 11:26:56 raspberrypi dhcpcd[485]: wlan0: deleting default route via 192.168.1.1
Oct 22 11:26:56 raspberrypi systemd[1]: Starting Mopidy music server...
Oct 22 11:26:56 raspberrypi systemd[1]: Reached target Network is Online.
Oct 22 11:26:56 raspberrypi systemd[1]: Starting Samba NMB Daemon...
Oct 22 11:26:57 raspberrypi systemd[1]: Starting Lighttpd Daemon...
Oct 22 11:26:57 raspberrypi systemd[1]: Started Phoniebox RFID-Reader Service.
Oct 22 11:26:57 raspberrypi systemd[1]: Started Phoniebox Idle Watchdog Service.
Oct 22 11:26:57 raspberrypi systemd[1]: Started Phoniebox GPIO Control Service.
Oct 22 11:26:57 raspberrypi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Oct 22 11:26:57 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Oct 22 11:26:57 raspberrypi avahi-daemon[324]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::ba27:ebff:fe65:bd23.
Oct 22 11:26:57 raspberrypi avahi-daemon[324]: New relevant interface wlan0.IPv6 for mDNS.
Oct 22 11:26:57 raspberrypi avahi-daemon[324]: Registering new address record for fe80::ba27:ebff:fe65:bd23 on wlan0.*.
Oct 22 11:26:58 raspberrypi systemd[1]: Started Permit User Sessions.
Oct 22 11:26:58 raspberrypi systemd[1]: Started Serial Getty on ttyAMA0.
Oct 22 11:26:58 raspberrypi systemd[1]: Started Getty on tty1.
Oct 22 11:26:58 raspberrypi systemd[1]: Reached target Login Prompts.
Oct 22 11:26:58 raspberrypi systemd[1]: Started Mopidy music server.
Oct 22 11:26:59 raspberrypi dhcpcd[485]: wlan0: carrier acquired
Oct 22 11:26:59 raspberrypi dhcpcd[485]: wlan0: connected to Access Point `wifi_2'
Oct 22 11:26:59 raspberrypi dhcpcd[485]: wlan0: using static address 192.168.1.146/24
Oct 22 11:26:59 raspberrypi avahi-daemon[324]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.146.
Oct 22 11:26:59 raspberrypi avahi-daemon[324]: New relevant interface wlan0.IPv4 for mDNS.
Oct 22 11:26:59 raspberrypi avahi-daemon[324]: Registering new address record for 192.168.1.146 on wlan0.IPv4.
Oct 22 11:26:59 raspberrypi dhcpcd[485]: wlan0: adding route to 192.168.1.0/24
Oct 22 11:26:59 raspberrypi dhcpcd[485]: wlan0: adding default route via 192.168.1.1
Oct 22 11:26:59 raspberrypi systemd[1]: Started OpenBSD Secure Shell server.
Oct 22 11:27:04 raspberrypi systemd[1]: Started Samba NMB Daemon.
Oct 22 11:27:04 raspberrypi systemd[1]: Starting Samba SMB Daemon...
Oct 22 11:27:06 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Oct 22 11:27:06 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Oct 22 11:27:07 raspberrypi PhonieboxGPIOControl[515]: INFO:root:[]
Oct 22 11:27:07 raspberrypi PhonieboxGPIOControl[515]: INFO:root:Ready for taking actions
Oct 22 11:27:07 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Oct 22 11:27:08 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Oct 22 11:27:11 raspberrypi systemd[1]: Started Lighttpd Daemon.
Oct 22 11:27:12 raspberrypi daemon_rfid_reader.py[503]: 2020-10-22 11:27:12,061 - root - INFO - Dir_PATH: /home/pi/RPi-Jukebox-RFID/scripts
Oct 22 11:27:13 raspberrypi daemon_rfid_reader.py[503]: 2020-10-22 11:27:13,492 - root - INFO - >>> NO RFID SIGNAL
Oct 22 11:27:13 raspberrypi daemon_rfid_reader.py[503]: 2020-10-22 11:27:13,499 - root - INFO - >>>  Trigger PAUSE
Oct 22 11:27:13 raspberrypi systemd[686]: Reached target Paths.
Oct 22 11:27:13 raspberrypi systemd[686]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Oct 22 11:27:13 raspberrypi systemd[686]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Oct 22 11:27:13 raspberrypi systemd[686]: Listening on GnuPG network certificate management daemon.
Oct 22 11:27:13 raspberrypi systemd[686]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Oct 22 11:27:13 raspberrypi systemd[686]: Listening on GnuPG cryptographic agent and passphrase cache.
Oct 22 11:27:13 raspberrypi systemd[686]: Starting D-Bus User Message Bus Socket.
Oct 22 11:27:13 raspberrypi systemd[686]: Reached target Timers.
Oct 22 11:27:14 raspberrypi systemd[686]: Listening on D-Bus User Message Bus Socket.
Oct 22 11:27:14 raspberrypi systemd[686]: Reached target Sockets.
Oct 22 11:27:14 raspberrypi systemd[686]: Reached target Basic System.
Oct 22 11:27:14 raspberrypi systemd[1]: Started User Manager for UID 1000.
Oct 22 11:27:14 raspberrypi systemd[1]: Started Session c1 of user pi.
Oct 22 11:27:14 raspberrypi systemd[686]: Starting Music Player Daemon...
Oct 22 11:27:15 raspberrypi daemon_rfid_reader.py[503]: mpd error: Connection refused
Oct 22 11:27:18 raspberrypi systemd[1]: Started Samba SMB Daemon.
Oct 22 11:27:18 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Oct 22 11:27:40 raspberrypi systemd-timesyncd[232]: Synchronized to time server for the first time 178.63.9.212:123 (2.debian.pool.ntp.org).
Oct 22 11:27:43 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:27:49 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:27:56 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:27:57 raspberrypi mpd: exception: Failed to set group 0: Operation not permitted
Oct 22 11:27:57 raspberrypi systemd[686]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Oct 22 11:27:57 raspberrypi systemd[686]: mpd.service: Failed with result 'exit-code'.
Oct 22 11:27:57 raspberrypi systemd[686]: Failed to start Music Player Daemon.
Oct 22 11:27:57 raspberrypi systemd[686]: Reached target Default.
Oct 22 11:27:57 raspberrypi systemd[686]: Startup finished in 34.625s.
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.__main__ Starting Mopidy 3.0.2
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from builtin defaults
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy-local.conf
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy.conf
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from file:///etc/mopidy/mopidy.conf
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from command line options
Oct 22 11:27:57 raspberrypi mopidy[546]: WARNING  [MainThread] mopidy.config Ignoring config section 'iris' because no matching extension was found
Oct 22 11:27:57 raspberrypi mopidy[546]: ERROR    [MainThread] mopidy.internal.log Loading logging config '/etc/mopidy/logging.conf' failed. 'formatters'
Oct 22 11:28:02 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:02 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.__main__ Enabled extensions: spotify, local, m3u, mpd, softwaremixer, http, stream, file
Oct 22 11:28:02 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.__main__ Disabled extensions: none
Oct 22 11:28:08 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy mixer: SoftwareMixer
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Mixer volume set to 30
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy audio
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, SpotifyBackend, LocalBackend
Oct 22 11:28:10 raspberrypi mopidy[546]: INFO     [Audio-2] mopidy.audio.actor Audio output set to "alsasink"
Oct 22 11:28:13 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
Oct 22 11:28:14 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:16 raspberrypi mopidy[546]: INFO     [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
Oct 22 11:28:17 raspberrypi mopidy[546]: INFO     [SpotifyBackend-6] mopidy_spotify.web Logged into Spotify Web API as udun84
Oct 22 11:28:20 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:27 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:33 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:35 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:41 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:48 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:28:52 raspberrypi systemd[1]: Started Session c2 of user pi.
Oct 22 11:28:54 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:00 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:06 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:12 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:18 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:24 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:30 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:37 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:43 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:49 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:55 raspberrypi lighttpd[741]: echo: write error: Broken pipe
Oct 22 11:29:56 raspberrypi mopidy[546]: INFO     [SpotifyBackend-6] mopidy_spotify.playlists Refreshed 26 Spotify playlists
Oct 22 11:29:56 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy core
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy frontends: HttpFrontend, MpdFrontend
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [HttpFrontend-13] mopidy.http.actor HTTP server running at [::ffff:0.0.0.0]:6680
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy_mpd.actor MPD server running at [::ffff:0.0.0.0]:6600
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting GLib mainloop
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MpdSession-15] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56130
Oct 22 11:29:58 raspberrypi mopidy[546]: INFO     [MpdSession-16] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56134
Oct 22 11:29:58 raspberrypi bash[315]: OK MPD 0.19.0
Oct 22 11:29:58 raspberrypi bash[315]: OK
Oct 22 11:29:58 raspberrypi bash[315]: OK
Oct 22 11:29:58 raspberrypi bash[315]: High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
Oct 22 11:29:58 raspberrypi bash[315]: #011version 1.25.10; written and copyright by Michael Hipp and others
Oct 22 11:29:58 raspberrypi bash[315]: #011free software (LGPL) without any warranty but with best wishes
Oct 22 11:29:59 raspberrypi bash[315]: Directory: /home/pi/RPi-Jukebox-RFID/shared/
Oct 22 11:29:59 raspberrypi bash[315]: Playing MPEG stream 1 of 1: startupsound.mp3 ...
Oct 22 11:29:59 raspberrypi bash[315]: MPEG 1.0 L III cbr64 44100 j-s
Oct 22 11:29:59 raspberrypi bash[315]: Artist:  Phoniebox
Oct 22 11:30:00 raspberrypi mopidy[546]: INFO     [MpdSession-17] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56138
Oct 22 11:30:01 raspberrypi mopidy[546]: INFO     [MpdSession-18] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56142
Oct 22 11:30:02 raspberrypi mopidy[546]: INFO     [MpdSession-19] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56146
Oct 22 11:30:03 raspberrypi bash[315]: [0:04] Decoding of startupsound.mp3 finished.
Oct 22 11:30:03 raspberrypi mopidy[546]: INFO     [MpdSession-20] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56150
Oct 22 11:30:03 raspberrypi bash[315]: volume:  5%   repeat: off   random: off   single: off   consume: off
Oct 22 11:30:03 raspberrypi systemd[1]: Started Phoniebox Startup.
Oct 22 11:30:03 raspberrypi systemd[1]: Reached target Multi-User System.
Oct 22 11:30:03 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Oct 22 11:30:03 raspberrypi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Oct 22 11:30:03 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Oct 22 11:30:03 raspberrypi systemd[1]: Startup finished in 4.139s (kernel) + 3min 13.860s (userspace) = 3min 18.000s.
Oct 22 11:30:07 raspberrypi mopidy[546]: INFO     [MpdSession-21] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56154
Oct 22 11:30:08 raspberrypi mopidy[546]: INFO     [MpdSession-22] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56158
Oct 22 11:30:13 raspberrypi mopidy[546]: INFO     [MpdSession-23] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56162
Oct 22 11:30:14 raspberrypi mopidy[546]: INFO     [MpdSession-24] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56166
Oct 22 11:30:19 raspberrypi mopidy[546]: INFO     [MpdSession-25] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56170
Oct 22 11:30:21 raspberrypi mopidy[546]: INFO     [MpdSession-26] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56174
Oct 22 11:30:21 raspberrypi systemd[1]: Configuration file /etc/systemd/system/phoniebox-startup-sound.service is marked executable. Please remove executable permission bits. Proceeding anyway.
Oct 22 11:30:27 raspberrypi mopidy[546]: INFO     [MpdSession-27] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56178
Oct 22 11:30:29 raspberrypi mopidy[546]: INFO     [MpdSession-28] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56182
Oct 22 11:30:34 raspberrypi mopidy[546]: INFO     [MpdSession-29] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:56186

Output of journalctl -u mopidy

-- Logs begin at Thu 2020-10-22 11:26:40 BST, end at Thu 2020-10-22 11:51:54 BST. --
Oct 22 11:26:56 raspberrypi systemd[1]: Starting Mopidy music server...
Oct 22 11:26:58 raspberrypi systemd[1]: Started Mopidy music server.
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.__main__ Starting Mopidy 3.0.2
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from builtin defaults
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mo
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mo
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from file:///etc/mopidy/m
Oct 22 11:27:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.config Loading config from command line options
Oct 22 11:27:57 raspberrypi mopidy[546]: WARNING  [MainThread] mopidy.config Ignoring config section 'iris' because n
Oct 22 11:27:57 raspberrypi mopidy[546]: ERROR    [MainThread] mopidy.internal.log Loading logging config '/etc/mopid
Oct 22 11:28:02 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.__main__ Enabled extensions: spotify, local, m3
Oct 22 11:28:02 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.__main__ Disabled extensions: none
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy mixer: SoftwareMixer
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Mixer volume set to 30
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy audio
Oct 22 11:28:09 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy backends: FileBackend,
Oct 22 11:28:10 raspberrypi mopidy[546]: INFO     [Audio-2] mopidy.audio.actor Audio output set to "alsasink"
Oct 22 11:28:16 raspberrypi mopidy[546]: INFO     [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in o
Oct 22 11:28:17 raspberrypi mopidy[546]: INFO     [SpotifyBackend-6] mopidy_spotify.web Logged into Spotify Web API a
Oct 22 11:29:56 raspberrypi mopidy[546]: INFO     [SpotifyBackend-6] mopidy_spotify.playlists Refreshed 26 Spotify pl
Oct 22 11:29:56 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy core
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting Mopidy frontends: HttpFronten
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [HttpFrontend-13] mopidy.http.actor HTTP server running at [::ffff:
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy_mpd.actor MPD server running at [::ffff:0.0.0.0
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MainThread] mopidy.commands Starting GLib mainloop
Oct 22 11:29:57 raspberrypi mopidy[546]: INFO     [MpdSession-15] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:29:58 raspberrypi mopidy[546]: INFO     [MpdSession-16] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:00 raspberrypi mopidy[546]: INFO     [MpdSession-17] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:01 raspberrypi mopidy[546]: INFO     [MpdSession-18] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:02 raspberrypi mopidy[546]: INFO     [MpdSession-19] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:03 raspberrypi mopidy[546]: INFO     [MpdSession-20] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:07 raspberrypi mopidy[546]: INFO     [MpdSession-21] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:08 raspberrypi mopidy[546]: INFO     [MpdSession-22] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:13 raspberrypi mopidy[546]: INFO     [MpdSession-23] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:14 raspberrypi mopidy[546]: INFO     [MpdSession-24] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:19 raspberrypi mopidy[546]: INFO     [MpdSession-25] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:21 raspberrypi mopidy[546]: INFO     [MpdSession-26] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:27 raspberrypi mopidy[546]: INFO     [MpdSession-27] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:29 raspberrypi mopidy[546]: INFO     [MpdSession-28] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:34 raspberrypi mopidy[546]: INFO     [MpdSession-29] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:35 raspberrypi mopidy[546]: INFO     [MpdSession-30] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:40 raspberrypi mopidy[546]: INFO     [MpdSession-31] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:41 raspberrypi mopidy[546]: INFO     [MpdSession-32] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:47 raspberrypi mopidy[546]: INFO     [MpdSession-33] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:48 raspberrypi mopidy[546]: INFO     [MpdSession-34] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:53 raspberrypi mopidy[546]: INFO     [MpdSession-35] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:54 raspberrypi mopidy[546]: INFO     [MpdSession-36] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:30:59 raspberrypi mopidy[546]: INFO     [MpdSession-37] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:00 raspberrypi mopidy[546]: INFO     [MpdSession-38] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:05 raspberrypi mopidy[546]: INFO     [MpdSession-39] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:06 raspberrypi mopidy[546]: INFO     [MpdSession-40] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:12 raspberrypi mopidy[546]: INFO     [MpdSession-41] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:13 raspberrypi mopidy[546]: INFO     [MpdSession-42] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:18 raspberrypi mopidy[546]: INFO     [MpdSession-43] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:19 raspberrypi mopidy[546]: INFO     [MpdSession-44] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:24 raspberrypi mopidy[546]: INFO     [MpdSession-45] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:25 raspberrypi mopidy[546]: INFO     [MpdSession-46] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:30 raspberrypi mopidy[546]: INFO     [MpdSession-47] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:31 raspberrypi mopidy[546]: INFO     [MpdSession-48] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:37 raspberrypi mopidy[546]: INFO     [MpdSession-49] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:38 raspberrypi mopidy[546]: INFO     [MpdSession-50] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:43 raspberrypi mopidy[546]: INFO     [MpdSession-51] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:44 raspberrypi mopidy[546]: INFO     [MpdSession-52] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:49 raspberrypi mopidy[546]: INFO     [MpdSession-53] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:50 raspberrypi mopidy[546]: INFO     [MpdSession-54] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:55 raspberrypi mopidy[546]: INFO     [MpdSession-55] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:31:56 raspberrypi mopidy[546]: INFO     [MpdSession-56] mopidy_mpd.session New MPD connection from [::ffff:
Oct 22 11:32:02 raspberrypi mopidy[546]: INFO     [MpdSession-57] mopidy_mpd.session New MPD connection from [::ffff:

Software

Base image and version

Output of cat /etc/os-release

PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Branch / Release

master

Installscript

scripts/installscripts/buster-install-default.sh

Hardware

RaspberryPi version

Raspberry Pi Zero W Rev 1.1

RFID Reader

SBC-RFID-RC522

Soundcard

HiFiBerry Miniamp

Other notable hardware

@Toqqi Toqqi added the bug label Oct 22, 2020
@Huseriato
Copy link

Because I had issues with my sd card: Can you test it with a faster card? Are tracks played instantly?

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 22, 2020

I'm using a Transcend 300S 16 GB (Class 10 + UHS-I + UHS-Class 1, Read 95 MB/s, Write 10 MB/s).
I only have slower cards around.
Tracks are played instantly without issues.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 23, 2020

I'm trying to figure out where mpd is hanging now, since I commented out the wait for the mpd startup in
sudo systemd-analyze blame now gives me

         14.029s lighttpd.service
         12.876s smbd.service
          8.528s phoniebox-startup-scripts.service
          6.324s nmbd.service
          6.298s dev-mmcblk0p2.device
          5.569s user@1000.service
          4.782s dhcpcd.service
          2.372s ssh.service
          2.012s networking.service
          1.981s systemd-udev-trigger.service
          1.909s phoniebox-startup-sound.service
          1.796s systemd-timesyncd.service
          1.687s rng-tools.service
          1.568s rpi-eeprom-update.service
          1.550s avahi-daemon.service
          1.501s rsyslog.service
          1.455s systemd-update-utmp-runlevel.service
          1.419s systemd-journald.service
          1.401s atd.service
          1.373s systemd-fsck@dev-disk-by\x2dpartuuid-d6a683cc\x2d01.service
          1.371s mopidy.service
          1.345s systemd-logind.service
          1.264s user-runtime-dir@1000.service
          1.127s systemd-rfkill.service
          1.095s systemd-fsck-root.service
          1.062s systemd-user-sessions.service
           770ms wpa_supplicant.service
           767ms systemd-update-utmp.service
           709ms resolvconf.service
           672ms systemd-tmpfiles-setup.service
           607ms systemd-sysctl.service
           594ms systemd-remount-fs.service
           563ms fake-hwclock.service
           537ms systemd-modules-load.service
           534ms kmod-static-nodes.service
           420ms dev-mqueue.mount
           419ms alsa-restore.service
           391ms systemd-journal-flush.service
           367ms systemd-sysusers.service
           331ms sys-kernel-debug.mount
           323ms systemd-random-seed.service
           320ms run-rpc_pipefs.mount
           280ms sys-kernel-config.mount
           277ms systemd-udevd.service
           264ms console-setup.service
           224ms nfs-config.service
           178ms boot.mount
           153ms systemd-tmpfiles-setup-dev.service
            83ms ifupdown-pre.service

So I can basically exclude an issue with the phoniebox startup script.

I have also removed all Spotify folders and playlists to no effect.

I'm wary about two stretches from the syslog:

Oct 23 10:22:52 raspberrypi mpd: exception: Failed to create pid file "/run/mpd/pid": Permission denied
Oct 23 10:22:52 raspberrypi systemd[710]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Oct 23 10:22:53 raspberrypi systemd[710]: mpd.service: Failed with result 'exit-code'.
Oct 23 10:22:53 raspberrypi systemd[710]: Failed to start Music Player Daemon.
Oct 23 10:22:53 raspberrypi systemd[710]: Reached target Default.
Oct 23 10:22:53 raspberrypi systemd[710]: Startup finished in 35.338s.

and

Oct 23 10:22:53 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.__main__ Starting Mopidy 3.0.2
Oct 23 10:22:53 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.config Loading config from builtin defaults
Oct 23 10:22:53 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy-local.conf
Oct 23 10:22:53 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy.conf
Oct 23 10:22:53 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.config Loading config from file:///etc/mopidy/mopidy.conf
Oct 23 10:22:53 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.config Loading config from command line options
Oct 23 10:22:53 raspberrypi mopidy[538]: ERROR    [MainThread] mopidy.internal.log Loading logging config '/etc/mopidy/logging.conf' failed. 'formatters'
Oct 23 10:23:00 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.__main__ Enabled extensions: iris, file, local, http, m3u, stream, spotify, softwaremixer, mpd
Oct 23 10:23:00 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.__main__ Disabled extensions: none
Oct 23 10:23:06 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Starting Mopidy mixer: SoftwareMixer
Oct 23 10:23:06 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Mixer volume set to 30
Oct 23 10:23:06 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Starting Mopidy audio
Oct 23 10:23:06 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, SpotifyBackend, LocalBackend
Oct 23 10:23:07 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
Oct 23 10:23:07 raspberrypi mopidy[538]: INFO     [Audio-2] mopidy.audio.actor Audio output set to "alsasink"
Oct 23 10:23:13 raspberrypi mopidy[538]: INFO     [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
Oct 23 10:23:14 raspberrypi mopidy[538]: INFO     [SpotifyBackend-6] mopidy_spotify.web Logged into Spotify Web API as *commented out*
Oct 23 10:24:45 raspberrypi mopidy[538]: INFO     [SpotifyBackend-6] mopidy_spotify.playlists Refreshed 26 Spotify playlists
Oct 23 10:24:45 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Starting Mopidy core
Oct 23 10:24:46 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Starting Mopidy frontends: IrisFrontend, HttpFrontend, MpdFrontend
Oct 23 10:24:46 raspberrypi mopidy[538]: INFO     [IrisFrontend-11] mopidy_iris.core Starting Iris 3.52.4
Oct 23 10:24:46 raspberrypi mopidy[538]: INFO     [HttpFrontend-13] mopidy.http.actor HTTP server running at [::ffff:0.0.0.0]:6680
Oct 23 10:24:46 raspberrypi mopidy[538]: INFO     [MainThread] mopidy_mpd.actor MPD server running at [::ffff:0.0.0.0]:6600
Oct 23 10:24:46 raspberrypi mopidy[538]: INFO     [MainThread] mopidy.commands Starting GLib mainloop
Oct 23 10:24:46 raspberrypi mopidy[538]: INFO     [MpdSession-15] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:47524
Oct 23 10:24:48 raspberrypi mopidy[538]: INFO     [MpdSession-16] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:47528
Oct 23 10:24:48 raspberrypi bash[326]: OK MPD 0.19.0
Oct 23 10:24:48 raspberrypi bash[326]: OK
Oct 23 10:24:48 raspberrypi bash[326]: OK

@gstrauss
Copy link

lighttpd should start up very quickly, even on embedded devices, though openssl may pause during initialization while waiting for a newly booted system to generate sufficient entropy.

I'd recommend making sure you are running the latest lighttpd release from Debian buster (lighttpd 1.4.53 + patches), and, if you can, the latest lighttpd from buster-backports (lighttpd 1.4.55)

@s-martin
Copy link
Collaborator

Another idea:
Have you mounted any network drives?
I remember some users had similar issues, because they had mounted a network drive.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 26, 2020

I've been trying to cut down my start up time a bit and right now I'm at roughly 90 seconds. The most time is used to start up Mopidy now.
The biggest impact was disabling the mopidy-spotify playlist refresh on its startup, since I don't need those in my Phoniebox.
@s-martin I have no mounted network drives.
@gstrauss I tried updating lighttpd from buster-backports, but I got a segmentation fault error and went back to 1.4.53.

I wasn't successful in trying to cut down the used mopidy extensions. I just want to play Spotify tracks/albums/playlists with the Phoniebox, but disabling any of the extensions made the box unusable.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 26, 2020

Overclocking the RPi Zero for the initial 60 seconds, I'm now at Startup finished in 4.027s (kernel) + 58.961s (userspace) = 1min 2.988s.
I'll try to keep working on this nevertheless.

@olli83
Copy link

olli83 commented Oct 26, 2020

I am also looking into getting my Phoniebox to start up faster. Only at the beginning of the process and with two very small kids I am a bit slow getting into it (new to playing with a Raspberry...)

@Toqqi

The biggest impact was disabling the mopidy-spotify playlist refresh on its startup, since I don't need those in my Phoniebox.

How is this done? Taking quite some time on mine, too...

Is it still possible to refresh playlists manually when needed? I would like to use a playlists where I can add songs that my kids like just from my Spotify app, but I would be ok to manually refresh the list on the Phoniebox if that gets it to start faster.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 26, 2020

@olli83 I will be able to share the small changes I made in the mopidy-spotify tomorrow.

Regarding the refreshing, I noticed that mopidy-spotify loads all, even just favourited playlists from my Spotify accounts on every startup (e.g. "Refreshed 26 playlists from Spotify").
The lists that are associated to RFID tags are refreshed independently from that through mpc, so I did not notice any negative impact on my way of using the Phoniebox.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 27, 2020

@olli83 I tested this again and actually you just have to set allow_playlists = false in the [spotify] configuration group of /etc/mopidy/mopidy.conf. There is no need to modify mopidy-spotify for this.

@MiczFlor
Copy link
Owner

HI @Toqqi @olli83
could you write your findings into the wiki somewhere? Things get lost in the fire when they are in threads only :)

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 27, 2020

Hi @MiczFlor, I added the bit about skipping the initial Spotify playlist refresh by mopidy-spotify to the Troubleshooting / FAQ section of the wiki. https://github.com/MiczFlor/RPi-Jukebox-RFID/wiki/Troubleshooting-FAQ#spotify-causes-slow-startup-time

@r00tr4v3n
Copy link

Where did you comment out a wait for mpd? I am using the classic version without Spotify and my Raspberry boots 1min+

1min 21.585s phoniebox-startup-scripts.service
         10.248s dhcpcd.service
          2.605s lighttpd.service
          2.541s dev-mmcblk0p2.device
          1.767s nmbd.service
          1.731s smbd.service
           865ms phpsessionclean.service
           820ms user@1000.service
           736ms systemd-fsck@dev-disk-by\x2dpartuuid-ad1a268b\x2d01.service
           735ms avahi-daemon.service
           701ms systemd-udev-trigger.service
           661ms rsyslog.service
           640ms systemd-logind.service
           612ms dphys-swapfile.service
           569ms systemd-timesyncd.service
           556ms networking.service
           550ms ssh.service
           475ms wpa_supplicant.service
           432ms systemd-fsck-root.service
           381ms systemd-journald.service
           379ms rpi-eeprom-update.service
           363ms rng-tools.service
           281ms systemd-remount-fs.service
           267ms systemd-user-sessions.service
           243ms alsa-restore.service
           229ms systemd-udevd.service
           208ms atd.service
           201ms systemd-tmpfiles-setup.service
           185ms systemd-journal-flush.service
           169ms systemd-update-utmp.service
           167ms resolvconf.service
           166ms rc-local.service
           163ms fake-hwclock.service
           141ms run-rpc_pipefs.mount
           133ms systemd-sysctl.service
           131ms sys-kernel-debug.mount
           131ms systemd-update-utmp-runlevel.service
           126ms systemd-modules-load.service
           125ms user-runtime-dir@1000.service
           123ms systemd-sysusers.service
           118ms dev-mqueue.mount
           115ms kmod-static-nodes.service
           113ms systemd-tmpfiles-setup-dev.service
            99ms boot.mount
            97ms systemd-random-seed.service
            85ms systemd-rfkill.service
            79ms sys-kernel-config.mount
            68ms console-setup.service
            58ms mopidy.service
            43ms nfs-config.service
            37ms ifupdown-pre.service

@Huseriato
Copy link

Huseriato commented Oct 30, 2020

What is the command to list this startup time for the services? I found journalctl -b for listing. But this des not show the services. My total startup time is 12 seconds now. Assigning a fixed ip might speed this up a little more, I think. I did not try it, because I don't want to risk loosing the connection to my installation now. ;)

I think the MDP wait is commented out in scripts/startup-script.sg. Here the lines:

#########################################
# wait until mopidy/MPD server is running
STATUS=0
while [ "$STATUS" != "ACTIVE" ]; do STATUS=$(echo -e status\\nclose | nc -w 1 localhost 6600 | grep 'OK MPD'| sed 's/^.*$/ACTIVE/'); done

I commented this out, too. It does not have any negative effect for my setup. I also removed the start sound. This is 4 seconds long and seems so, that you have to wait for it until it's fully played. There are 2 seconds silence at the beginning of the start sound.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 30, 2020

The command to analyze the startup times is sudo systemd-analyze blame

Nice, I'll try to comment out the mpd startup and start sound also to check the impact on the times.

@Huseriato
Copy link

Hmm, interesting that the started services are so different for our installations:

          2.539s apt-daily.service
          2.182s phoniebox-startup-scripts.service
          1.970s man-db.service
          1.106s apt-daily-upgrade.service
           942ms dev-mmcblk0p2.device
           919ms systemd-fsck@dev-sda1.service
           880ms rpi-eeprom-update.service
           688ms logrotate.service
           591ms lighttpd.service
           525ms dphys-swapfile.service
           453ms user@1000.service
           399ms raspi-config.service
           366ms systemd-logind.service
           363ms rsyslog.service
           359ms avahi-daemon.service
           353ms systemd-fsck@dev-disk-by\x2dpartuuid-738a4d67\x2d01.service
           346ms wpa_supplicant.service
           329ms triggerhappy.service
           323ms dhcpcd.service
           247ms ssh.service
           239ms phpsessionclean.service
           238ms keyboard-setup.service
           213ms networking.service
           207ms systemd-udev-trigger.service
           175ms systemd-timesyncd.service
           174ms systemd-fsck-root.service
           159ms systemd-remount-fs.service
           151ms cleanshutd.service
           150ms systemd-journald.service
            93ms atd.service
            92ms resolvconf.service
            92ms media-usb.mount
            87ms kmod-static-nodes.service
            84ms systemd-udevd.service
            84ms systemd-modules-load.service
            82ms run-rpc_pipefs.mount
            80ms mopidy.service
            80ms rng-tools.service
            76ms sys-kernel-debug.mount
            68ms fake-hwclock.service
            66ms systemd-tmpfiles-setup.service
            63ms systemd-tmpfiles-clean.service
            62ms exim4.service
            59ms dev-mqueue.mount
            55ms systemd-sysctl.service
            54ms alsa-restore.service
            53ms systemd-update-utmp.service
            52ms systemd-journal-flush.service
            44ms boot.mount
            43ms systemd-user-sessions.service
            40ms systemd-sysusers.service
            39ms rc-local.service
            39ms systemd-update-utmp-runlevel.service
            38ms systemd-tmpfiles-setup-dev.service
            34ms systemd-rfkill.service
            34ms systemd-random-seed.service
            32ms user-runtime-dir@1000.service
            30ms console-setup.service
            29ms sys-fs-fuse-connections.mount
            24ms sys-kernel-config.mount
            21ms nfs-config.service
            18ms ifupdown-pre.service

I also removed samba (don't know, why there is a service left) and exim4 using apt. I disabled "Wait for Network on Boot" in the raspi-config. That's all I've done so far. I hope this helps.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 30, 2020

I'm also on a RPi Zero W, I suppose that performance goes up considerably depending on the Pi that is used.

@Huseriato
Copy link

Yes, that's true. I meant not the starting time itself, it's more about the service names.

@s-martin Do you know a command or preferred log file to analyse the start up of the phoniebox service better? syslog is not a good option, there is so much stuff going on.

@Toqqi
Copy link
Contributor Author

Toqqi commented Oct 30, 2020

I think the MDP wait is commented out in scripts/startup-script.sg. Here the lines:

#########################################
# wait until mopidy/MPD server is running
STATUS=0
while [ "$STATUS" != "ACTIVE" ]; do STATUS=$(echo -e status\\nclose | nc -w 1 localhost 6600 | grep 'OK MPD'| sed 's/^.*$/ACTIVE/'); done

I commented this out, too. It does not have any negative effect for my setup.

I commented out the wait for MPD, then startup finishes considerably faster, but the player still won't react until MPD and mopidy are running completely. So unfortunately I cannot apply this in my use case (only Spotify player).

@s-martin
Copy link
Collaborator

@Huseriato Unfortunately I don't know a good tool. If there's something difficult to find i usually copy the log via WinSCP to my Windows machine and use Notepad++ to find stuff (and bulk remove noise).

Following things for startup time should be considered:

  • Spotify edition boots much slower than classic, because Mopidy is used. Some users even have to add a precondition via raspi-config to wait for network access, otherwise Spotify would not connect (see various issues here). This could lead to even worse boot times.
  • Pi Zero has only a limited performance, so expect longer boot times there
  • I assume various services of RPi could be disabled to improve boot times, but that's something you have to test thoroughly. Removing Desktop stuff like LibreOffice probably makes sense. Please share your experiences in the wiki.
  • Users reported in the past that mounted network drives could lead to much slower boot times.

Hope this helps and I guess I should add that to the wiki, too. ;)

@Huseriato
Copy link

@Toqqi you're right. Commenting out the MDP wait, leads to wait time after boot is finished until the cards are working. I was so focused on boosting this time, I forgot to test a card immediately.

I'm currently thinking about, if I really need Spotify. I think the box is more reliable, when using local media. I've not integrated a power bank, because I wanted to make the children's room more attractive to the kids. But the box is attachable to a powerbank or a car outlet. So the box is theoretically portable, but is considered to be in the children's room.

@s-martin Thanks for your input. So is it true, that the non spotify version plays the tracks using mpg123? Or how does this work here?

@s-martin
Copy link
Collaborator

mpg123 is just used for startup sounds.

The classic edition uses MPD, spotify edition uses Mopidy.

@r00tr4v3n
Copy link

A new installation improved my startup time from 90s to 30s. Weird.

@arrisde
Copy link

arrisde commented Nov 8, 2020

I have the same issue (+Spotify edition, RPi0W, freshly installed 2.1.1). Future owner will have to stretch all his patience to wait ~3mins for the startup sound :(
@r00tr4v3n, which RPi are you on, and did you install from development or master branch? +Spotify or Classic edition?

@s-martin
Copy link
Collaborator

@arrisde, unfortunately I think RPi Zero and Spotify edition may lead to long boot times, but if you have some improvements to share many Phoniebox users would be interested.

@s-martin
Copy link
Collaborator

s-martin commented Dec 5, 2020

Please check #1174 for some performance improvements especially on Pi Zero

@arne123
Copy link
Collaborator

arne123 commented Jan 13, 2021

I am trying to speed up the boot on the rpi zero as well.

The following steps I did with at least some success:

  • Starting Network stuff after audio stuff (I want music in first place network later)
    
  • upgrading mpd to the new version (0.23 here, the raspbian one is way older)
    In fact I recompile more then one time, after getting some recommendations in the mpd forum 
    There is still potential of further improvements  https://forum.musicpd.org/viewtopic.php?p=12805#p12805
    
  • mpd disabled auto-update
    
  • avoid parallel starting of other services in parallel to mpd 
    this is manly for effective for high cpu load tasks on single cores
    
  • shortened the startup sound (trimmed leading and trailing empty parts)
    

At the moment I have audio available 30s after the boot.
The bootchart looks looks like this:
https://gist.githubusercontent.com/arne123/5a614d01397680cc2eae12344026db6a/raw/476672d48c7e59979b4e4c2cb557479daaec2943/boot.svg

what I still want to do:

  • searching for more services which are not required and can be disabled or postponed after audio
    
  • skip systemd-fsck@dev, or execute it during shutdown (1.7s)
    
  • see if there are some possibilities to shorten the systemd start itself (~3s) 
    especially I see some potential in the generator phase, but I could not find good resource here yet
    
  • see if the kernel period can be shortened (3s) 
    here I see also some potential
    
  • see if dev-mmcblk0p2 can be shortened (7s) 
    actuall this would help a lot, but but maybe there is not so much potential here,
    mainly due to  lack of understanding and missing leverage
    
  • check if the startup script/sound can be modified in some ways 
    e.g. playing sound earlier (in parallel to mpd)(~3s)
    
  • SD-card: 
    initially I thought I bought a good sd card(80MB/s), but I doubt this somehow now.
    is anybody also using an rpi zero w and can compare the boot times for some services?
    Is there some potential in the sd card?
    

my goal is to boot til audio in at least 20s.

br
Arne

@arne123
Copy link
Collaborator

arne123 commented Jan 14, 2021

So I improved some more seconds, basically be removing further plugins from mpd.
Also I am playing the startup sound in parallel to mpd start.

you can find the details here
https://gist.github.com/arne123/b35126771ffe19d73910c83d182ed0b9

Maybe there is still a little more potential in mpd, but not much.
The start of mpd without running mpg123 in parallel just takes 1.4s sec.
I will now focus on the startup script (why it takes 3 sec?) systemd startup and dev-mmcblk0p2 .

@arne123
Copy link
Collaborator

arne123 commented Jan 23, 2021

I finally managed to boot to sound in 20 sec

  • more services have been disabled or reorganized
  • systemd generators which according to my understanding are not of any use at the moment have been disabled
  • the sice of the /lib/udev/hwdb.bin has been reduce by removing all pci device
  • not used kernel modules have been blacklisted

https://gist.githubusercontent.com/arne123/656aeef30ef20edd381d8a63953a817f/raw/d1d9ce34c13113260ef06f26c7f4ca688060557b/boot.svg

A more detailed bootchart can be generated with systemd-bootchart
https://gist.githubusercontent.com/arne123/656aeef30ef20edd381d8a63953a817f/raw/d1d9ce34c13113260ef06f26c7f4ca688060557b/bootchart-20210123-1344.svg

Details:

disabled systemd generators
sudo chmod a-x /lib/systemd/system-generators/systemd-rc-local-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-cryptsetup-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-debug-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-bless-boot-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-hibernate-resume-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-run-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-system-update-generator
sudo chmod a-x /lib/systemd/system-generators/systemd-veritysetup-generator

blacklisted modules:
/etc/modprobe.d/raspi-blacklist.conf
blacklist bcm2835_v4l2
blacklist bcm2835_isp
blacklist bcm2835_codec
blacklist v4l2_mem2mem
blacklist rfkill

@arne123
Copy link
Collaborator

arne123 commented Jan 29, 2021

I got another 5s by compiling a custom kernel, sound in 15s now.

https://gist.githubusercontent.com/arne123/3f85530d23d812c0e2d00da67d1be5c7/raw/aaaa354b7749b54663419b76bc759cf14fdecc90/boot.svg

basically I tried to disable things which I don't need (trace_fs, usb_otg)
and put everything which was loaded as module build-in module (except wifi bcrmfmac, which failed somehow)

If you are interested, here is the kernel config as well:
https://gist.githubusercontent.com/arne123/3f85530d23d812c0e2d00da67d1be5c7/raw/aaaa354b7749b54663419b76bc759cf14fdecc90/.config

I mainly followed the instructions here for cross compiling:
https://www.raspberrypi.org/documentation/linux/kernel/building.md

@splitti
Copy link
Contributor

splitti commented Mar 1, 2021

Hi,

mostly the startup time is caused because of mopidy refreshing the spotify playlists. I wrote some speed hacks here: https://splittscheid.de/phoniebox-schneller-booten-fehler-beheben/

Another option is to try a OS like dietPi. It boots up pretty fast. But i stay at Raspbian and i am searching for more Speed Hacks. The custom kernel sounds good @arne123, i will try that!

@melo0187
Copy link

melo0187 commented Mar 15, 2021

@arne123 can you provide some guidance on how to reproduce your steps?
What did you do to start the network stuff after all the audio things?
And how can you avoid starting other services in parallel to mpd?

I'm using a RPi Zero W with the RC522 RFID reader and the HifiBerry miniamp and it takes 60s until I hear the startup sound and can start using the box.
I already did follow the instructions on @splitti​'s blog (except for setting a static ip, disabling ipv6, sdtweak/overclock and initial_turbo) and removedmpc rescan from startup-scripts.sh so I have no idea left what I could do to get even close to the 20s startup time you achieved.

Any help is greatly appreciated!

For the record my systemd-analyze blame output:

         26.001s mpd.service
         12.665s nmbd.service
         12.052s lighttpd.service
          8.179s dev-mmcblk0p2.device
          7.549s smbd.service
          7.188s phoniebox-startup-scripts.service
          3.783s systemd-timesyncd.service
          3.761s ssh.service
          3.724s networking.service
          3.198s systemd-udev-trigger.service
          2.592s systemd-logind.service
          2.479s cleanshutd.service
          2.136s systemd-rfkill.service
          2.022s avahi-daemon.service
          1.976s systemd-journald.service
          1.741s rpi-eeprom-update.service
          1.719s systemd-user-sessions.service
          1.533s wpa_supplicant.service
          1.431s alsa-restore.service
          1.348s systemd-remount-fs.service
          1.260s user@1000.service
          1.231s atd.service
          1.136s rsyslog.service
          1.050s systemd-update-utmp.service
          1.004s systemd-tmpfiles-setup.service
           808ms dhcpcd.service
           771ms systemd-journal-flush.service
           758ms systemd-sysctl.service
           719ms systemd-fsck-root.service
           656ms systemd-sysusers.service
           625ms fake-hwclock.service
           601ms dev-mqueue.mount
           550ms rc-local.service
           541ms systemd-random-seed.service
           541ms sys-kernel-debug.mount
           539ms systemd-tmpfiles-clean.service
           538ms resolvconf.service
           508ms systemd-modules-load.service
           495ms rng-tools.service
           485ms kmod-static-nodes.service
           436ms user-runtime-dir@1000.service
           386ms systemd-fsck@dev-disk-by\x2dpartuuid-8e16ee7a\x2d01.service
           376ms sys-kernel-config.mount
           368ms systemd-udevd.service
           360ms run-rpc_pipefs.mount
           280ms systemd-tmpfiles-setup-dev.service
           276ms console-setup.service
           248ms systemd-update-utmp-runlevel.service
           218ms nfs-config.service
           132ms boot.mount
           108ms ifupdown-pre.service

@arne123
Copy link
Collaborator

arne123 commented Mar 16, 2021

I think you will have the biggest benefit recompiling mpd.
If you wish, I can provide you the binary I have compiled on my rpi zero.

Then you have to deal with systemd and the systemd configuration files.
I made reorganized many services after sound.target and after network.target
unfortunately I don't know all service files I changed by hard, I need to look them up later.

Probably you don't need avahi-daemon.service, there are also some other services which I don't see on my setup.

@melo0187
Copy link

Hey @arne123 thank you for your reply!
I would be happy to give your mpd binary a try. Am I assuming correctly, that I could just copy it over the original bin in /usr/bin?

Although I know my way around Linux I never found myself dealing with that aspect of the OS before, so I don't know much about systemd and how to tweak it. I just learned about systemd-analyze blame in this issue and haven't installed bootchart yet.
I am assuming that following @splitti​'s FAQ for optimizing boot time changing After=network.target sound.target to read After=sound.target would be enough to start mpd as soon as audio is ready without waiting on network. Is this correct?
What could I do more in that regard?

Thanks again for your input, it is much appreciated.
My son is just hitting 17 months and so I figure reducing the boot time from 60 down to 40 if not 20 seconds would already be very helpful =)

@arne123
Copy link
Collaborator

arne123 commented Mar 16, 2021

systemd-analyze plot > boot.svg will give you an svg where you can get an impression of the dependencies during boot.
(you don't need bootchart unless you are intending to dive in very deep)

Try this mpd: mpd.gz,
hopefully it runs on your device and there are no further dependencies.
I would recommend to keep your original mpd, and put this somewhere else, you can modify the execution command in your systemd unit file: (/lib/systemd/system/mpd.service)

[Service]
Type=notify
EnvironmentFile=/etc/default/mpd
#ExecStart=/usr/bin/mpd --no-daemon $MPDCONF
ExecStart=/home/pi/RPi-Jukebox-RFID/mpd/mpd --no-daemon /etc/mpd.conf

do you use samba to access your box?
If not you can disable it.

@melo0187
Copy link

@arne123 I don't know how to thank you 😂

First of all good catch with the samba service. Since I use the webinterface to upload audio and scp to copy files like the mpd binary you just provided, I won't miss samba.

But most of all thank you for compiling and sharing your mpd binary with me! I have no idea what you did there or how, but it simply works and you just reduced my boot time from ~60 to ~35 seconds 🤯

Thank you so much!

P.S.:

pi@phoniebox:~ $ sudo systemd-analyze blame
          8.824s dev-mmcblk0p2.device
          7.558s phoniebox-startup-scripts.service
          7.197s lighttpd.service
          6.309s dhcpcd.service
          4.851s nmbd.service
          3.754s networking.service
          3.024s systemd-udev-trigger.service
          2.710s systemd-rfkill.service
          2.580s mpd.service
          2.418s systemd-logind.service
          2.125s systemd-journald.service
          2.002s user@1000.service
          1.955s ssh.service
          1.816s wpa_supplicant.service
          1.698s systemd-fsck@dev-disk-by\x2dpartuuid-fdb3324f\x2d01.service
          1.686s systemd-fsck-root.service
          1.221s atd.service
          1.181s cleanshutd.service
          1.158s systemd-tmpfiles-setup.service
          1.141s rng-tools.service
          1.105s systemd-user-sessions.service
          1.063s resolvconf.service
           929ms systemd-remount-fs.service
           878ms systemd-sysctl.service
           755ms sys-kernel-debug.mount
           743ms systemd-update-utmp.service
           741ms run-rpc_pipefs.mount
           717ms systemd-modules-load.service
           658ms alsa-restore.service
           646ms fake-hwclock.service
           619ms kmod-static-nodes.service
           539ms systemd-journal-flush.service
           497ms systemd-sysusers.service
           471ms sys-kernel-config.mount
           465ms systemd-random-seed.service
           444ms user-runtime-dir@1000.service
           430ms systemd-update-utmp-runlevel.service
           411ms dev-mqueue.mount
           374ms systemd-udevd.service
           320ms nfs-config.service
           310ms console-setup.service
           304ms ifupdown-pre.service
           213ms systemd-tmpfiles-setup-dev.service
           143ms boot.mount

@MiczFlor
Copy link
Owner

Hi @arne123
I will give the recompiled mpd a try, too.
Regarding your C++ work, I put together the ideas from the discussions about the future of phoniebox and would like to get your input regarding the little application you wrote in C++.
You can find my question and summary here:
#1329 (comment)
Thanks and all the best, micz

@Lueffe
Copy link

Lueffe commented Mar 17, 2021

@arne123
Thx for the binary. It works fine.
Can you post your meson Build Flags?

@arne123
Copy link
Collaborator

arne123 commented Mar 17, 2021

Sure, I thought I already did, here is the latest:
https://gist.github.com/arne123/b14f9d67ddf3da6fbc91ed1320668f79

To all using that binary, please be aware that the mpd is build on the rpi zero w, with the instruction set armv6l of that specific processor . I believe that newer arm processors are mostly backwards compatible, but you might run into some issues running it on different environments.

Here is the discussion I had in the mpd forum:
https://forum.musicpd.org/viewtopic.php?f=7&t=8469

The conclusion is, that not mpd itself is causing the long start time, but the load of several shared libraries which are mostly not used, so I removed as much as possible of them.

@Toqqi
Copy link
Contributor Author

Toqqi commented Mar 19, 2021

@arne123
Hi, I suppose your recompiled mpd only works for the non-Spotify version of Phoniebox?
I tried to copy over your executable and I think that mopidy uses its own version of mpd (mopidy-mpd extension). Can anyone confirm this?

I will do some research in order to apply your meson build flags to mopidy-mpd.
There still is a OK MPD 0.19.0 in journalctl -u phoniebox-startup-scripts.service -b on my RPi.

Thanks!

@arne123
Copy link
Collaborator

arne123 commented Mar 19, 2021

I never had a deeper look into mopidy yet, but I think that mopidy-mpd is a python based reimplementation of mpd.

From https://github.com/mopidy/mopidy-mpd:

"MPD stands for Music Player Daemon, which is also the name of the original MPD server project. Mopidy does not depend on the original MPD server, but implements the MPD protocol itself, and is thus compatible with most clients built for the original MPD server"

@passuff
Copy link

passuff commented Mar 2, 2022

I have a fresh develop install with spotify. I was wondering about the Startup speed too as I did not yet add anything to the system:

image

So for sure I can disable some services but the first one is most interesting:

image

So most time is consumed while executing startup scripts, right?

Any recommendation how to speed this up? I'm using pi zero 2 and was hoping to get 20s start up time...

@MiczFlor
Copy link
Owner

MiczFlor commented Mar 5, 2022

Have a look at this. The issue is often mpd which takes time to start. And that is inside the startup script. In the following link, there is a version of mpd that has only the necessary dependencies:
#1110 (comment)

Here is a before and after comparison:

From

26.001s mpd.service

To

2.580s mpd.service

@wastlmuc
Copy link
Contributor

wastlmuc commented Aug 30, 2022

Just wanted to add

Sure, I thought I already did, here is the latest: https://gist.github.com/arne123/b14f9d67ddf3da6fbc91ed1320668f79

To all using that binary, please be aware that the mpd is build on the rpi zero w, with the instruction set armv6l of that specific processor . I believe that newer arm processors are mostly backwards compatible, but you might run into some issues running it on different environments.

Here is the discussion I had in the mpd forum: https://forum.musicpd.org/viewtopic.php?f=7&t=8469

The conclusion is, that not mpd itself is causing the long start time, but the load of several shared libraries which are mostly not used, so I removed as much as possible of them.

In case someone wants to rebuild mpd using above approach and following mpd doc , for 0.23.9 you need to add
option('pipewire', type: 'feature', value: 'disabled', description: 'PipeWire support')
option('snapcast', type: 'boolean', value: false, description: 'Snapcast output plugin')
option('openmpt', type: 'feature', value: 'disabled', description: 'OpenMPT decoder plugin')
to medon_options.txt, as provided above.

Additionally for web streaming you need to explicitly set
option('curl', type: 'feature', value: 'enabled', description: 'HTTP client using CURL')
option('mad', type: 'feature', value: 'enabled', description: 'MP3 decoder using libmad')

mad is necessary for playing the streams, as mpg123 cannot deal with web urls.

Make sure you are building the proper config.
meson configure output/release

Hope this helps.

meson_options.txt

@AlvinSchiller
Copy link
Collaborator

The Mopidy refresh problematic is solved in the newest version introduced with #2315

@AlvinSchiller AlvinSchiller linked a pull request Apr 12, 2024 that will close this issue
@s-martin s-martin added legacy_v2 Issues, discussions and PRs related to Version 2.x bug spotify edition and removed documentation labels Apr 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug legacy_v2 Issues, discussions and PRs related to Version 2.x spotify edition Tips Tricks Hacks
Projects
None yet
Development

Successfully merging a pull request may close this issue.