Rpi-jukebox-rfid: 馃悰 | 3 minute start-up time
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
```-- Logs begin at Thu 2020-10-22 11:26:40 BST, end at Thu 2020-10-22 11:39:02 BST. --
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 Pointwifi_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
All 25 comments
Because I had issues with my sd card: Can you test it with a faster card? Are tracks played instantly?
Huseriato
on 22 Oct 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
on 22 Oct 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 [email protected]
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 [email protected]
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
Toqqi
on 23 Oct 2020
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)
gstrauss
on 25 Oct 2020
Another idea:
Have you mounted any network drives?
I remember some users had similar issues, because they had mounted a network drive.
s-martin
on 25 Oct 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
on 26 Oct 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.
Toqqi
on 26 Oct 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.
olli83
on 26 Oct 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
on 26 Oct 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.
Toqqi
on 27 Oct 2020
HI @Toqqi @olli83
could you write your findings into the wiki somewhere? Things get lost in the fire when they are in threads only :)
MiczFlor
on 27 Oct 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
Toqqi
on 27 Oct 2020
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 [email protected]
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 [email protected]
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
r00tr4v3n
on 29 Oct 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.
Huseriato
on 30 Oct 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.
Toqqi
on 30 Oct 2020
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 [email protected]
880ms rpi-eeprom-update.service
688ms logrotate.service
591ms lighttpd.service
525ms dphys-swapfile.service
453ms [email protected]
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 [email protected]
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.
Huseriato
on 30 Oct 2020
I'm also on a RPi Zero W, I suppose that performance goes up considerably depending on the Pi that is used.
Toqqi
on 30 Oct 2020
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.
Huseriato
on 30 Oct 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/'); doneI 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).
Toqqi
on 30 Oct 2020
@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. ;)
s-martin
on 30 Oct 2020
@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?
Huseriato
on 30 Oct 2020
mpg123 is just used for startup sounds.
The classic edition uses MPD, spotify edition uses Mopidy.
s-martin
on 30 Oct 2020
A new installation improved my startup time from 90s to 30s. Weird.
r00tr4v3n
on 5 Nov 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?
arrisde
on 8 Nov 2020
@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
on 21 Nov 2020
Related issues
methigel
路
5Comments
s-martin
路
6Comments
toxidle
路
7Comments
laclaro
路
10Comments
elalemanyo
路
10Comments