🐛 | Single file play (#682) doesn't work with filenames containing ' and append file to playlist ( #785) doesn't work at all

[BerniPi]

Bug

What I did

I tried to play a single file.

What happened

Most files play fine, but files with ' in filename don't. (eg. "Alle Leut'" or "Ein Schneider fing 'ne Maus"

I expected this to happen

It works for all files.

Further information that might help

There is no information in syslog and debug.log (I enabled debugging for Webapp_API and playoutcontrols.

Software

Base image and version

Raspian Buster Lite

Branch / Release

latest develop - classic

Installscript

buster-install-default

Hardware

RaspberryPi version

3B

RFID Reader

None

Soundcard

PCM

Other notable hardware

None

[s-martin]

So what happens, when you try to play the file? Nothig or an error?

Could you also post the results of tail -n 500 /var/log/syslog? Thanks!

[BerniPi]

There is no reaction / no error.
Results of tail syslog:
May 26 22:06:31 phoniebox kernel: [ 0.006668] smp: Brought up 1 node, 4 CPUs
May 26 22:06:31 phoniebox systemd[1]: Started Create Static Device Nodes in /dev.
May 26 22:06:31 phoniebox kernel: [ 0.006680] SMP: Total of 4 processors activated (153.60 BogoMIPS).
May 26 22:06:31 phoniebox kernel: [ 0.006686] CPU: All CPU(s) started in HYP mode.
May 26 22:06:31 phoniebox kernel: [ 0.006691] CPU: Virtualization extensions available.
May 26 22:06:31 phoniebox kernel: [ 0.007664] devtmpfs: initialized
May 26 22:06:31 phoniebox systemd[1]: Reached target Local File Systems (Pre).
May 26 22:06:31 phoniebox kernel: [ 0.020700] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
May 26 22:06:31 phoniebox kernel: [ 0.020937] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
May 26 22:06:31 phoniebox systemd[1]: Starting udev Kernel Device Manager...
May 26 22:06:31 phoniebox kernel: [ 0.020958] futex hash table entries: 1024 (order: 4, 65536 bytes)
May 26 22:06:31 phoniebox systemd[1]: Started udev Kernel Device Manager.
May 26 22:06:31 phoniebox kernel: [ 0.021551] pinctrl core: initialized pinctrl subsystem
May 26 22:06:31 phoniebox kernel: [ 0.022407] NET: Registered protocol family 16
May 26 22:06:31 phoniebox kernel: [ 0.025408] DMA: preallocated 1024 KiB pool for atomic coherent allocations
May 26 22:06:31 phoniebox kernel: [ 0.031094] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
May 26 22:06:31 phoniebox kernel: [ 0.031102] hw-breakpoint: maximum watchpoint size is 8 bytes.
May 26 22:06:31 phoniebox kernel: [ 0.031302] Serial: AMBA PL011 UART driver
May 26 22:06:31 phoniebox kernel: [ 0.033645] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
May 26 22:06:31 phoniebox kernel: [ 0.050039] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-02-12 12:38, variant start
May 26 22:06:31 phoniebox kernel: [ 0.060052] raspberrypi-firmware soc:firmware: Firmware hash is 53a54c770c493957d99bf49762dfabc4eee00e45
May 26 22:06:31 phoniebox systemd[1]: Found device /dev/ttyAMA0.
May 26 22:06:31 phoniebox kernel: [ 0.103213] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
May 26 22:06:31 phoniebox kernel: [ 0.104848] SCSI subsystem initialized
May 26 22:06:31 phoniebox kernel: [ 0.105072] usbcore: registered new interface driver usbfs
May 26 22:06:31 phoniebox kernel: [ 0.105126] usbcore: registered new interface driver hub
May 26 22:06:31 phoniebox kernel: [ 0.105221] usbcore: registered new device driver usb
May 26 22:06:31 phoniebox mtp-probe: checking bus 1, device 3: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
May 26 22:06:31 phoniebox kernel: [ 0.106782] clocksource: Switched to clocksource arch_sys_counter
May 26 22:06:31 phoniebox kernel: [ 0.196725] VFS: Disk quotas dquot_6.6.0
May 26 22:06:31 phoniebox mtp-probe: bus: 1, device: 3 was not an MTP device
May 26 22:06:31 phoniebox kernel: [ 0.196834] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.196984] FS-Cache: Loaded
May 26 22:06:31 phoniebox kernel: [ 0.197190] CacheFiles: Loaded
May 26 22:06:31 phoniebox kernel: [ 0.207233] NET: Registered protocol family 2
May 26 22:06:31 phoniebox kernel: [ 0.208071] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.208108] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
May 26 22:06:31 phoniebox systemd-udevd[160]: Using default interface naming scheme 'v240'.
May 26 22:06:31 phoniebox kernel: [ 0.208219] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.208404] TCP: Hash tables configured (established 8192 bind 8192)
May 26 22:06:31 phoniebox kernel: [ 0.208541] UDP hash table entries: 512 (order: 2, 16384 bytes)
May 26 22:06:31 phoniebox systemd[1]: Found device /dev/disk/by-partuuid/738a4d67-01.
May 26 22:06:31 phoniebox kernel: [ 0.208591] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.208827] NET: Registered protocol family 1
May 26 22:06:31 phoniebox kernel: [ 0.209398] RPC: Registered named UNIX socket transport module.
May 26 22:06:31 phoniebox kernel: [ 0.209404] RPC: Registered udp transport module.
May 26 22:06:31 phoniebox systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
May 26 22:06:31 phoniebox kernel: [ 0.209410] RPC: Registered tcp transport module.
May 26 22:06:31 phoniebox kernel: [ 0.209416] RPC: Registered tcp NFSv4.1 backchannel transport module.
May 26 22:06:31 phoniebox kernel: [ 0.211117] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
May 26 22:06:31 phoniebox kernel: [ 0.214171] Initialise system trusted keyrings
May 26 22:06:31 phoniebox kernel: [ 0.214359] workingset: timestamp_bits=14 max_order=18 bucket_order=4
May 26 22:06:31 phoniebox kernel: [ 0.224116] FS-Cache: Netfs 'nfs' registered for caching
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
May 26 22:06:31 phoniebox kernel: [ 0.224693] NFS: Registering the id_resolver key type
May 26 22:06:31 phoniebox kernel: [ 0.224724] Key type id_resolver registered
May 26 22:06:31 phoniebox kernel: [ 0.224730] Key type id_legacy registered
May 26 22:06:31 phoniebox kernel: [ 0.224746] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
May 26 22:06:31 phoniebox kernel: [ 0.227098] Key type asymmetric registered
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in Huge Pages File System being skipped.
May 26 22:06:31 phoniebox kernel: [ 0.227107] Asymmetric key parser 'x509' registered
May 26 22:06:31 phoniebox kernel: [ 0.227160] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
May 26 22:06:31 phoniebox kernel: [ 0.227312] io scheduler noop registered
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in FUSE Control File System being skipped.
May 26 22:06:31 phoniebox kernel: [ 0.227320] io scheduler deadline registered (default)
May 26 22:06:31 phoniebox kernel: [ 0.227520] io scheduler cfq registered
May 26 22:06:31 phoniebox kernel: [ 0.227528] io scheduler mq-deadline registered (default)
May 26 22:06:31 phoniebox kernel: [ 0.227535] io scheduler kyber registered
May 26 22:06:31 phoniebox systemd[1]: Starting File System Check on /dev/disk/by-partuuid/738a4d67-01...
May 26 22:06:31 phoniebox kernel: [ 0.230709] bcm2708_fb soc:fb: FB found 1 display(s)
May 26 22:06:31 phoniebox kernel: [ 0.239724] Console: switching to colour frame buffer device 82x26
May 26 22:06:31 phoniebox systemd[1]: Starting Load/Save RF Kill Switch Status...
May 26 22:06:31 phoniebox kernel: [ 0.244154] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
May 26 22:06:31 phoniebox systemd-udevd[156]: Using default interface naming scheme 'v240'.
May 26 22:06:31 phoniebox systemd[1]: Started Load/Save RF Kill Switch Status.
May 26 22:06:31 phoniebox systemd-fsck[236]: fsck.fat 4.1 (2017-01-24)
May 26 22:06:31 phoniebox systemd-fsck[236]: /dev/mmcblk0p1: 232 files, 106929/516190 clusters
May 26 22:06:31 phoniebox systemd[1]: Started File System Check on /dev/disk/by-partuuid/738a4d67-01.
May 26 22:06:31 phoniebox systemd[1]: Mounting /boot...
May 26 22:06:31 phoniebox systemd[1]: Mounted /boot.
May 26 22:06:31 phoniebox systemd[1]: Reached target Local File Systems.
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
May 26 22:06:31 phoniebox systemd[1]: Starting Create Volatile Files and Directories...
May 26 22:06:31 phoniebox systemd[1]: Starting Raise network interfaces...
May 26 22:06:31 phoniebox systemd[1]: Starting Set console font and keymap...
May 26 22:06:31 phoniebox systemd[1]: Starting Preprocess NFS configuration...
May 26 22:06:31 phoniebox systemd[1]: nfs-config.service: Succeeded.
May 26 22:06:31 phoniebox systemd[1]: Started Preprocess NFS configuration.
May 26 22:06:31 phoniebox systemd[1]: Started Set console font and keymap.
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped.
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in RPC security service for NFS server being skipped.
May 26 22:06:31 phoniebox systemd[1]: Reached target NFS client services.
May 26 22:06:31 phoniebox systemd[1]: Reached target Remote File Systems (Pre).
May 26 22:06:31 phoniebox systemd[1]: Reached target Remote File Systems.
May 26 22:06:31 phoniebox kernel: [ 0.245204] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
May 26 22:06:31 phoniebox kernel: [ 0.246650] bcm2835-rng 3f104000.rng: hwrng registered
May 26 22:06:31 phoniebox systemd[1]: Started Create Volatile Files and Directories.
May 26 22:06:31 phoniebox kernel: [ 0.247018] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
May 26 22:06:31 phoniebox kernel: [ 0.247533] vc-sm: Videocore shared memory driver
May 26 22:06:31 phoniebox kernel: [ 0.247855] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
May 26 22:06:31 phoniebox kernel: [ 0.258521] brd: module loaded
May 26 22:06:31 phoniebox systemd[1]: Starting Update UTMP about System Boot/Shutdown...
May 26 22:06:31 phoniebox kernel: [ 0.268686] loop: module loaded
May 26 22:06:31 phoniebox systemd[1]: Starting Network Time Synchronization...
May 26 22:06:31 phoniebox kernel: [ 0.269272] Loading iSCSI transport class v2.0-870.
May 26 22:06:31 phoniebox systemd[1]: Started Update UTMP about System Boot/Shutdown.
May 26 22:06:31 phoniebox kernel: [ 0.269933] libphy: Fixed MDIO Bus: probed
May 26 22:06:31 phoniebox kernel: [ 0.270032] usbcore: registered new interface driver lan78xx
May 26 22:06:31 phoniebox kernel: [ 0.270095] usbcore: registered new interface driver smsc95xx
May 26 22:06:31 phoniebox kernel: [ 0.270111] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
May 26 22:06:31 phoniebox systemd[1]: Started Raise network interfaces.
May 26 22:06:31 phoniebox kernel: [ 0.297954] dwc_otg 3f980000.usb: base=(ptrval)
May 26 22:06:31 phoniebox kernel: [ 0.498214] Core Release: 2.80a
May 26 22:06:31 phoniebox kernel: [ 0.498224] Setting default values for core params
May 26 22:06:31 phoniebox systemd[1]: Started Network Time Synchronization.
May 26 22:06:31 phoniebox kernel: [ 0.498255] Finished setting default values for core params
May 26 22:06:31 phoniebox kernel: [ 0.698546] Using Buffer DMA mode
May 26 22:06:31 phoniebox kernel: [ 0.698553] Periodic Transfer Interrupt Enhancement - disabled
May 26 22:06:31 phoniebox systemd[1]: Reached target System Initialization.
May 26 22:06:31 phoniebox kernel: [ 0.698559] Multiprocessor Interrupt Enhancement - disabled
May 26 22:06:31 phoniebox kernel: [ 0.698566] OTG VER PARAM: 0, OTG VER FLAG: 0
May 26 22:06:31 phoniebox kernel: [ 0.698584] Dedicated Tx FIFOs mode
May 26 22:06:31 phoniebox systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
May 26 22:06:31 phoniebox kernel: [ 0.699027] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bad04000 dma = 0xfad04000 len=9024
May 26 22:06:31 phoniebox kernel: [ 0.699052] FIQ FSM acceleration enabled for :
May 26 22:06:31 phoniebox kernel: [ 0.699052] Non-periodic Split Transactions
May 26 22:06:31 phoniebox kernel: [ 0.699052] Periodic Split Transactions
May 26 22:06:31 phoniebox systemd[1]: Started Daily Cleanup of Temporary Directories.
May 26 22:06:31 phoniebox kernel: [ 0.699052] High-Speed Isochronous Endpoints
May 26 22:06:31 phoniebox kernel: [ 0.699052] Interrupt/Control Split Transaction hack enabled
May 26 22:06:31 phoniebox kernel: [ 0.699060] dwc_otg: Microframe scheduler enabled
May 26 22:06:31 phoniebox kernel: [ 0.699113] WARN::hcd_init_fiq:457: FIQ on core 1
May 26 22:06:31 phoniebox systemd[1]: Listening on D-Bus System Message Bus Socket.
May 26 22:06:31 phoniebox kernel: [ 0.699123] WARN::hcd_init_fiq:458: FIQ ASM at 8067fd10 length 36
May 26 22:06:31 phoniebox kernel: [ 0.699133] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
May 26 22:06:31 phoniebox systemd[1]: Listening on mpd.socket.
May 26 22:06:31 phoniebox kernel: [ 0.699149] dwc_otg 3f980000.usb: DWC OTG Controller
May 26 22:06:31 phoniebox kernel: [ 0.699182] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
May 26 22:06:31 phoniebox kernel: [ 0.699216] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
May 26 22:06:31 phoniebox kernel: [ 0.699263] Init: Port Power? op_state=1
May 26 22:06:31 phoniebox systemd[1]: Listening on triggerhappy.socket.
May 26 22:06:31 phoniebox kernel: [ 0.699269] Init: Power Port (0)
May 26 22:06:31 phoniebox kernel: [ 0.699525] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
May 26 22:06:31 phoniebox kernel: [ 0.699536] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
May 26 22:06:31 phoniebox systemd[1]: Reached target Sockets.
May 26 22:06:31 phoniebox kernel: [ 0.699545] usb usb1: Product: DWC OTG Controller
May 26 22:06:31 phoniebox kernel: [ 0.699554] usb usb1: Manufacturer: Linux 4.19.97-v7+ dwc_otg_hcd
May 26 22:06:31 phoniebox kernel: [ 0.699563] usb usb1: SerialNumber: 3f980000.usb
May 26 22:06:31 phoniebox systemd[1]: Reached target Basic System.
May 26 22:06:31 phoniebox kernel: [ 0.700164] hub 1-0:1.0: USB hub found
May 26 22:06:31 phoniebox kernel: [ 0.700209] hub 1-0:1.0: 1 port detected
May 26 22:06:31 phoniebox kernel: [ 0.700799] dwc_otg: FIQ enabled
May 26 22:06:31 phoniebox kernel: [ 0.700805] dwc_otg: NAK holdoff enabled
May 26 22:06:31 phoniebox systemd[1]: Starting Deferred execution scheduler...
May 26 22:06:31 phoniebox kernel: [ 0.700810] dwc_otg: FIQ split-transaction FSM enabled
May 26 22:06:31 phoniebox kernel: [ 0.700821] Module dwc_common_port init
May 26 22:06:31 phoniebox kernel: [ 0.701105] usbcore: registered new interface driver usb-storage
May 26 22:06:31 phoniebox systemd[1]: Starting LSB: Monitoring GPIO shutdown trigger...
May 26 22:06:31 phoniebox kernel: [ 0.701282] mousedev: PS/2 mouse device common for all mice
May 26 22:06:31 phoniebox kernel: [ 0.702135] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
May 26 22:06:31 phoniebox kernel: [ 0.702373] bcm2835-cpufreq: min=600000 max=1200000
May 26 22:06:31 phoniebox kernel: [ 0.702837] sdhci: Secure Digital Host Controller Interface driver
May 26 22:06:31 phoniebox kernel: [ 0.702843] sdhci: Copyright(c) Pierre Ossman
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
May 26 22:06:31 phoniebox kernel: [ 0.703225] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
May 26 22:06:31 phoniebox kernel: [ 0.703640] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
May 26 22:06:31 phoniebox kernel: [ 0.703770] sdhci-pltfm: SDHCI platform and OF driver helper
May 26 22:06:31 phoniebox systemd[1]: Starting rng-tools.service...
May 26 22:06:31 phoniebox kernel: [ 0.705250] ledtrig-cpu: registered to indicate activity on CPUs
May 26 22:06:31 phoniebox systemd[1]: Starting Login Service...
May 26 22:06:31 phoniebox kernel: [ 0.705440] hidraw: raw HID events driver (C) Jiri Kosina
May 26 22:06:31 phoniebox kernel: [ 0.705609] usbcore: registered new interface driver usbhid
May 26 22:06:31 phoniebox kernel: [ 0.705615] usbhid: USB HID core driver
May 26 22:06:31 phoniebox kernel: [ 0.706581] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
May 26 22:06:31 phoniebox systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
May 26 22:06:31 phoniebox kernel: [ 0.708133] [vc_sm_connected_init]: start
May 26 22:06:31 phoniebox kernel: [ 0.716697] [vc_sm_connected_init]: end - returning 0
May 26 22:06:31 phoniebox kernel: [ 0.717845] Initializing XFRM netlink socket
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped.
May 26 22:06:31 phoniebox kernel: [ 0.717869] NET: Registered protocol family 17
May 26 22:06:31 phoniebox kernel: [ 0.717975] Key type dns_resolver registered
May 26 22:06:31 phoniebox kernel: [ 0.718446] Registering SWP/SWPB emulation handler
May 26 22:06:31 phoniebox systemd[1]: Started D-Bus System Message Bus.
May 26 22:06:31 phoniebox kernel: [ 0.719085] registered taskstats version 1
May 26 22:06:31 phoniebox kernel: [ 0.719101] Loading compiled-in X.509 certificates
May 26 22:06:31 phoniebox kernel: [ 0.725691] uart-pl011 3f201000.serial: cts_event_workaround enabled
May 26 22:06:31 phoniebox systemd[1]: Starting Check for Raspberry Pi EEPROM updates...
May 26 22:06:31 phoniebox kernel: [ 0.725771] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
May 26 22:06:31 phoniebox kernel: [ 0.725823] console [ttyAMA0] enabled
May 26 22:06:31 phoniebox systemd[1]: Started Manage Sound Card State (restore and store).
May 26 22:06:31 phoniebox kernel: [ 0.727696] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
May 26 22:06:31 phoniebox kernel: [ 0.727706] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
May 26 22:06:31 phoniebox kernel: [ 0.753961] sdhost: log_buf @ (ptrval) (fad07000)
May 26 22:06:31 phoniebox kernel: [ 0.791520] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.793103] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
May 26 22:06:31 phoniebox systemd[1]: Starting Save/Restore Sound Card State...
May 26 22:06:31 phoniebox kernel: [ 0.794685] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.797525] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
May 26 22:06:31 phoniebox kernel: [ 0.800148] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
May 26 22:06:31 phoniebox kernel: [ 0.801426] of_cfs_init
May 26 22:06:31 phoniebox systemd[1]: Starting WPA supplicant...
May 26 22:06:31 phoniebox kernel: [ 0.801515] of_cfs_init: OK
May 26 22:06:31 phoniebox kernel: [ 0.802103] Waiting for root device PARTUUID=738a4d67-02...
May 26 22:06:31 phoniebox alsactl[320]: alsactl 1.1.8 daemon started
May 26 22:06:31 phoniebox kernel: [ 0.861132] mmc0: host does not support reading read-only switch, assuming write-enable
May 26 22:06:31 phoniebox kernel: [ 0.863016] mmc0: Problem switching card into high-speed mode!
May 26 22:06:31 phoniebox kernel: [ 0.863928] mmc0: new SDHC card at address 0001
May 26 22:06:31 phoniebox kernel: [ 0.865154] mmcblk0: mmc0:0001 ASTC 14.6 GiB
May 26 22:06:31 phoniebox rng-tools[312]: Starting Hardware RNG entropy gatherer daemon: rngd.
May 26 22:06:31 phoniebox kernel: [ 0.867443] mmcblk0: p1 p2
May 26 22:06:31 phoniebox kernel: [ 0.871755] random: fast init done
May 26 22:06:31 phoniebox kernel: [ 0.904288] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
May 26 22:06:31 phoniebox rngd[325]: rngd 2-unofficial-mt.14 starting up...
May 26 22:06:31 phoniebox kernel: [ 0.904337] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
May 26 22:06:31 phoniebox kernel: [ 0.916097] mmc1: new high speed SDIO card at address 0001
May 26 22:06:31 phoniebox kernel: [ 0.917965] devtmpfs: mounted
May 26 22:06:31 phoniebox systemd[1]: Started Regular background program processing daemon.
May 26 22:06:31 phoniebox kernel: [ 0.922895] Freeing unused kernel memory: 1024K
May 26 22:06:31 phoniebox kernel: [ 0.926919] Indeed it is in host mode hprt0 = 00021501
May 26 22:06:31 phoniebox kernel: [ 0.987322] Run /sbin/init as init process
May 26 22:06:31 phoniebox kernel: [ 1.136840] usb 1-1: new high-speed USB device number 2 using dwc_otg
May 26 22:06:31 phoniebox systemd[1]: Condition check resulted in Turn on SSH if /boot/ssh is present being skipped.
May 26 22:06:31 phoniebox kernel: [ 1.136975] Indeed it is in host mode hprt0 = 00001101
May 26 22:06:31 phoniebox kernel: [ 1.377113] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
May 26 22:06:31 phoniebox systemd[1]: Starting dhcpcd on all interfaces...
May 26 22:06:31 phoniebox kernel: [ 1.377129] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
May 26 22:06:31 phoniebox kernel: [ 1.377775] hub 1-1:1.0: USB hub found
May 26 22:06:31 phoniebox kernel: [ 1.377869] hub 1-1:1.0: 5 ports detected
May 26 22:06:31 phoniebox kernel: [ 1.696837] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
May 26 22:06:31 phoniebox kernel: [ 1.827120] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
May 26 22:06:31 phoniebox rngd[325]: entropy feed to the kernel ready
May 26 22:06:31 phoniebox kernel: [ 1.827136] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
May 26 22:06:31 phoniebox kernel: [ 1.829915] smsc95xx v1.0.6
May 26 22:06:31 phoniebox systemd[1]: Starting System Logging Service...
May 26 22:06:31 phoniebox kernel: [ 1.920163] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:93:fe:4f
May 26 22:06:31 phoniebox kernel: [ 2.328783] NET: Registered protocol family 10
May 26 22:06:31 phoniebox kernel: [ 2.330201] Segment Routing with IPv6
May 26 22:06:31 phoniebox kernel: [ 2.574595] uart-pl011 3f201000.serial: no DMA platform data
May 26 22:06:31 phoniebox systemd[1]: Reached target System Time Synchronized.
May 26 22:06:31 phoniebox kernel: [ 3.587682] random: systemd: uninitialized urandom read (16 bytes read)
May 26 22:06:31 phoniebox systemd[1]: Started Daily apt download activities.
May 26 22:06:31 phoniebox systemd[1]: Started Daily man-db regeneration.
May 26 22:06:31 phoniebox systemd[1]: Started Daily rotation of log files.
May 26 22:06:31 phoniebox systemd[1]: Started Clean PHP session files every 30 mins.
May 26 22:06:31 phoniebox systemd[1]: Started Daily apt upgrade and clean activities.
May 26 22:06:31 phoniebox systemd[1]: Reached target Timers.
May 26 22:06:31 phoniebox cron[330]: (CRON) INFO (pidfile fd = 3)
May 26 22:06:31 phoniebox kernel: [ 3.599332] random: systemd: uninitialized urandom read (16 bytes read)
May 26 22:06:31 phoniebox kernel: [ 3.600615] random: systemd: uninitialized urandom read (16 bytes read)
May 26 22:06:31 phoniebox systemd[1]: Started Deferred execution scheduler.
May 26 22:06:31 phoniebox kernel: [ 4.626241] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
May 26 22:06:31 phoniebox kernel: [ 5.330683] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
May 26 22:06:31 phoniebox kernel: [ 5.333234] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
May 26 22:06:31 phoniebox systemd[1]: Started rng-tools.service.
May 26 22:06:31 phoniebox kernel: [ 5.333249] [vc_sm_connected_init]: start
May 26 22:06:31 phoniebox kernel: [ 5.340002] media: Linux media interface: v0.10
May 26 22:06:31 phoniebox kernel: [ 5.340975] [vc_sm_connected_init]: installed successfully
May 26 22:06:31 phoniebox systemd[1]: Started Save/Restore Sound Card State.
May 26 22:06:31 phoniebox kernel: [ 5.399585] videodev: Linux video capture interface: v2.00
May 26 22:06:31 phoniebox kernel: [ 5.613185] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
May 26 22:06:31 phoniebox systemd[1]: Reached target Sound Card.
May 26 22:06:31 phoniebox kernel: [ 5.613190] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
May 26 22:06:31 phoniebox kernel: [ 5.657179] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
May 26 22:06:31 phoniebox kernel: [ 5.661345] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
May 26 22:06:31 phoniebox systemd[1]: Starting Music Player Daemon...
May 26 22:06:31 phoniebox kernel: [ 5.665371] bcm2835_audio soc:audio: card created with 8 channels
May 26 22:06:31 phoniebox kernel: [ 5.676192] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
May 26 22:06:31 phoniebox kernel: [ 5.682998] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
May 26 22:06:31 phoniebox kernel: [ 5.683044] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
May 26 22:06:31 phoniebox cron[330]: (CRON) INFO (Running @reboot jobs)
May 26 22:06:31 phoniebox kernel: [ 5.685582] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
May 26 22:06:31 phoniebox kernel: [ 5.685605] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
May 26 22:06:31 phoniebox kernel: [ 5.691523] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
May 26 22:06:31 phoniebox kernel: [ 5.691562] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
May 26 22:06:31 phoniebox avahi-daemon[314]: Found user 'avahi' (UID 108) and group 'avahi' (GID 113).
May 26 22:06:31 phoniebox kernel: [ 5.868431] cfg80211: Loading compiled-in X.509 certificates for regulatory database
May 26 22:06:31 phoniebox kernel: [ 6.057055] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
May 26 22:06:31 phoniebox kernel: [ 6.164187] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
May 26 22:06:31 phoniebox avahi-daemon[314]: Successfully dropped root privileges.
May 26 22:06:31 phoniebox kernel: [ 6.169983] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
May 26 22:06:31 phoniebox dhcpcd[331]: dev: loaded udev
May 26 22:06:31 phoniebox kernel: [ 6.170259] usbcore: registered new interface driver brcmfmac
May 26 22:06:31 phoniebox kernel: [ 6.414132] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
May 26 22:06:31 phoniebox avahi-daemon[314]: avahi-daemon 0.7 starting up.
May 26 22:06:31 phoniebox kernel: [ 6.414248] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
May 26 22:06:31 phoniebox kernel: [ 6.414931] 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
May 26 22:06:31 phoniebox kernel: [ 8.377299] random: crng init done
May 26 22:06:31 phoniebox kernel: [ 8.377317] random: 7 urandom warning(s) missed due to ratelimiting
May 26 22:06:30 phoniebox rsyslogd: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.1901.0]
May 26 22:06:31 phoniebox kernel: [ 8.936590] 8021q: 802.1Q VLAN Support v1.8
May 26 22:06:30 phoniebox rsyslogd: [origin software="rsyslogd" swVersion="8.1901.0" x-pid="332" x-info="https://www.rsyslog.com"] start
May 26 22:06:31 phoniebox systemd[1]: Started System Logging Service.
May 26 22:06:31 phoniebox systemd[1]: Started Check for Raspberry Pi EEPROM updates.
May 26 22:06:31 phoniebox dhcpcd[331]: wlan0: starting wpa_supplicant
May 26 22:06:31 phoniebox avahi-daemon[314]: Successfully called chroot().
May 26 22:06:31 phoniebox wpa_supplicant[322]: Successfully initialized wpa_supplicant
May 26 22:06:31 phoniebox avahi-daemon[314]: Successfully dropped remaining capabilities.
May 26 22:06:31 phoniebox avahi-daemon[314]: No service file found in /etc/avahi/services.
May 26 22:06:31 phoniebox dhcpcd-run-hooks[360]: wlan0: starting wpa_supplicant
May 26 22:06:31 phoniebox avahi-daemon[314]: Network interface enumeration completed.
May 26 22:06:31 phoniebox avahi-daemon[314]: Server startup complete. Host name is phoniebox.local. Local service cookie is 3249337377.
May 26 22:06:31 phoniebox systemd[1]: Started Login Service.
May 26 22:06:31 phoniebox systemd[1]: Started WPA supplicant.
May 26 22:06:31 phoniebox systemd[1]: Started Avahi mDNS/DNS-SD Stack.
May 26 22:06:31 phoniebox cleanshutd[311]: Starting...
May 26 22:06:31 phoniebox systemd[1]: Started LSB: Monitoring GPIO shutdown trigger.
May 26 22:06:31 phoniebox kernel: [ 9.302040] brcmfmac: power management disabled
May 26 22:06:31 phoniebox dhcpcd[331]: wlan0: connected to Access Point ' May 26 22:06:31 phoniebox dhcpcd[331]: eth0: waiting for carrier May 26 22:06:31 phoniebox dhcpcd[331]: wlan0: waiting for carrier May 26 22:06:31 phoniebox dhcpcd[331]: wlan0: carrier acquired May 26 22:06:31 phoniebox kernel: [ 9.808839] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup May 26 22:06:31 phoniebox dhcpcd[331]: wlan0: carrier lost May 26 22:06:32 phoniebox dhcpcd[331]: wlan0: carrier acquired May 26 22:06:32 phoniebox dhcpcd[331]: wlan0: connected to Access Point iriber'
May 26 22:06:33 phoniebox dhcpcd[331]: wlan0: rebinding lease of 10.1.0.111
May 26 22:06:33 phoniebox dhcpcd[331]: wlan0: leased 10.1.0.111 for 43200 seconds
May 26 22:06:33 phoniebox avahi-daemon[314]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.1.0.111.
May 26 22:06:33 phoniebox avahi-daemon[314]: New relevant interface wlan0.IPv4 for mDNS.
May 26 22:06:33 phoniebox avahi-daemon[314]: Registering new address record for 10.1.0.111 on wlan0.IPv4.
May 26 22:06:33 phoniebox dhcpcd[331]: wlan0: adding route to 10.1.0.0/24
May 26 22:06:33 phoniebox dhcpcd[331]: wlan0: adding default route via 10.1.0.1
May 26 22:06:33 phoniebox systemd[1]: systemd-rfkill.service: Succeeded.
May 26 22:06:34 phoniebox dhcpcd[331]: forked to background, child pid 434
May 26 22:06:34 phoniebox systemd[1]: Started dhcpcd on all interfaces.
May 26 22:06:34 phoniebox systemd[1]: Reached target Network.
May 26 22:06:34 phoniebox systemd[1]: Started Phoniebox RFID-Reader Service.
May 26 22:06:34 phoniebox systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
May 26 22:06:34 phoniebox systemd[1]: Starting OpenBSD Secure Shell server...
May 26 22:06:34 phoniebox systemd[1]: Starting Raspotify...
May 26 22:06:34 phoniebox systemd[1]: Started Phoniebox Rotary Encoder Service.
May 26 22:06:34 phoniebox systemd[438]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
May 26 22:06:34 phoniebox systemd[438]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
May 26 22:06:34 phoniebox systemd[1]: Starting The PHP 7.3 FastCGI Process Manager...
May 26 22:06:34 phoniebox systemd[1]: Reached target Network is Online.
May 26 22:06:34 phoniebox systemd[1]: Starting Lighttpd Daemon...
May 26 22:06:34 phoniebox systemd[1]: Starting Samba NMB Daemon...
May 26 22:06:34 phoniebox systemd[1]: Starting LSB: exim Mail Transport Agent...
May 26 22:06:34 phoniebox systemd[1]: Started Phoniebox GPIO Buttons Service.
May 26 22:06:34 phoniebox systemd[1]: Starting Permit User Sessions...
May 26 22:06:34 phoniebox systemd[1]: Started Phoniebox Idle Watchdog Service.
May 26 22:06:34 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
May 26 22:06:34 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
May 26 22:06:34 phoniebox systemd[1]: Started Raspotify.
May 26 22:06:34 phoniebox systemd[1]: Started Permit User Sessions.
May 26 22:06:34 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:34 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 1.
May 26 22:06:34 phoniebox systemd[1]: Stopped Phoniebox Rotary Encoder Service.
May 26 22:06:34 phoniebox systemd[1]: Started Phoniebox Rotary Encoder Service.
May 26 22:06:34 phoniebox systemd[453]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
May 26 22:06:34 phoniebox systemd[1]: Started Getty on tty1.
May 26 22:06:34 phoniebox systemd[453]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
May 26 22:06:35 phoniebox systemd[1]: Started Serial Getty on ttyAMA0.
May 26 22:06:35 phoniebox systemd[1]: Reached target Login Prompts.
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 2.
May 26 22:06:35 phoniebox systemd[1]: Stopped Phoniebox Rotary Encoder Service.
May 26 22:06:35 phoniebox systemd[1]: Started Phoniebox Rotary Encoder Service.
May 26 22:06:35 phoniebox systemd[474]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
May 26 22:06:35 phoniebox systemd[474]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 3.
May 26 22:06:35 phoniebox systemd[1]: Stopped Phoniebox Rotary Encoder Service.
May 26 22:06:35 phoniebox systemd[1]: Started Phoniebox Rotary Encoder Service.
May 26 22:06:35 phoniebox systemd[502]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
May 26 22:06:35 phoniebox systemd[502]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
May 26 22:06:35 phoniebox systemd[1]: Started OpenBSD Secure Shell server.
May 26 22:06:35 phoniebox librespot[451]: [2020-05-26T21:06:35Z INFO librespot] librespot (raspotify v0.14.0) 3672214 (2020-01-30). Built on 2020-02-16. Build ID: 7pZDdYUK
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 4.
May 26 22:06:35 phoniebox systemd[1]: Stopped Phoniebox Rotary Encoder Service.
May 26 22:06:35 phoniebox systemd[1]: Started Phoniebox Rotary Encoder Service.
May 26 22:06:35 phoniebox systemd[617]: phoniebox-rotary-encoder.service: Failed to execute command: No such file or directory
May 26 22:06:35 phoniebox systemd[617]: phoniebox-rotary-encoder.service: Failed at step EXEC spawning /home/pi/RPi-Jukebox-RFID/scripts/rotary-encoder.py: No such file or directory
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Main process exited, code=exited, status=203/EXEC
May 26 22:06:35 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
May 26 22:06:36 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:36 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Scheduled restart job, restart counter is at 5.
May 26 22:06:36 phoniebox systemd[1]: Stopped Phoniebox Rotary Encoder Service.
May 26 22:06:36 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Start request repeated too quickly.
May 26 22:06:36 phoniebox systemd[1]: phoniebox-rotary-encoder.service: Failed with result 'exit-code'.
May 26 22:06:36 phoniebox systemd[1]: Failed to start Phoniebox Rotary Encoder Service.
May 26 22:06:36 phoniebox systemd[1]: Started Samba NMB Daemon.
May 26 22:06:36 phoniebox systemd[1]: Starting Samba SMB Daemon...
May 26 22:06:38 phoniebox systemd[1]: Started The PHP 7.3 FastCGI Process Manager.
May 26 22:06:38 phoniebox systemd[1]: Started Lighttpd Daemon.
May 26 22:06:38 phoniebox systemd[1]: Started Music Player Daemon.
May 26 22:06:38 phoniebox systemd[1]: Starting Phoniebox Startup...
May 26 22:06:38 phoniebox systemd[1]: Started Samba SMB Daemon.
May 26 22:06:39 phoniebox bash[792]: cat: /home/pi/RPi-Jukebox-RFID/scripts/../settings/WlanIpMailYN: No such file or directory
May 26 22:06:39 phoniebox daemon_rfid_reader.py[435]: Please run RegisterDevice.py first
May 26 22:06:39 phoniebox bash[792]: rm: cannot remove '/home/pi/RPi-Jukebox-RFID/scripts/../settings/global.conf': No such file or directory
May 26 22:06:39 phoniebox systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
May 26 22:06:39 phoniebox systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
May 26 22:06:39 phoniebox bash[792]: AUDIOFOLDERSPATH="/home/pi/RPi-Jukebox-RFID/shared/audiofolders"
May 26 22:06:39 phoniebox bash[792]: PLAYLISTSFOLDERPATH="/home/pi/RPi-Jukebox-RFID/playlists"
May 26 22:06:39 phoniebox bash[792]: SECONDSWIPE="RESTART"
May 26 22:06:39 phoniebox bash[792]: AUDIOIFACENAME="PCM"
May 26 22:06:39 phoniebox bash[792]: AUDIOVOLCHANGESTEP="3"
May 26 22:06:39 phoniebox bash[792]: AUDIOVOLMAXLIMIT="100"
May 26 22:06:39 phoniebox bash[792]: AUDIOVOLMINLIMIT="1"
May 26 22:06:39 phoniebox bash[792]: AUDIOVOLSTARTUP="0"
May 26 22:06:39 phoniebox bash[792]: VOLCHANGEIDLE="TRUE"
May 26 22:06:39 phoniebox bash[792]: IDLETIMESHUTDOWN="0"
May 26 22:06:39 phoniebox bash[792]: SHOWCOVER="ON"
May 26 22:06:39 phoniebox bash[792]: READWLANIPYN="OFF"
May 26 22:06:39 phoniebox bash[792]: EDITION="classic"
May 26 22:06:39 phoniebox bash[792]: LANG="en-UK"
May 26 22:06:39 phoniebox bash[792]: VERSION="2.0 - afa3990 - develop"
May 26 22:06:39 phoniebox bash[792]: 0
May 26 22:06:39 phoniebox systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:39 phoniebox systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 1.
May 26 22:06:39 phoniebox systemd[1]: Stopped Phoniebox RFID-Reader Service.
May 26 22:06:39 phoniebox systemd[1]: Started Phoniebox RFID-Reader Service.
May 26 22:06:40 phoniebox daemon_rfid_reader.py[862]: Please run RegisterDevice.py first
May 26 22:06:40 phoniebox systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
May 26 22:06:40 phoniebox systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
May 26 22:06:40 phoniebox systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:40 phoniebox systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 2.
May 26 22:06:40 phoniebox systemd[1]: Stopped Phoniebox RFID-Reader Service.
May 26 22:06:40 phoniebox systemd[1]: Started Phoniebox RFID-Reader Service.
May 26 22:06:41 phoniebox daemon_rfid_reader.py[866]: Please run RegisterDevice.py first
May 26 22:06:41 phoniebox systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
May 26 22:06:41 phoniebox systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
May 26 22:06:41 phoniebox bash[792]: High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
May 26 22:06:41 phoniebox bash[792]: #011version 1.25.10; written and copyright by Michael Hipp and others
May 26 22:06:41 phoniebox bash[792]: #011free software (LGPL) without any warranty but with best wishes
May 26 22:06:41 phoniebox bash[792]: Directory: /home/pi/RPi-Jukebox-RFID/shared/
May 26 22:06:41 phoniebox bash[792]: Playing MPEG stream 1 of 1: startupsound.mp3 ...
May 26 22:06:41 phoniebox bash[792]: MPEG 1.0 L III vbr 44100 j-s
May 26 22:06:41 phoniebox systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:41 phoniebox systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 3.
May 26 22:06:41 phoniebox systemd[1]: Stopped Phoniebox RFID-Reader Service.
May 26 22:06:41 phoniebox systemd[1]: Started Phoniebox RFID-Reader Service.
May 26 22:06:42 phoniebox daemon_rfid_reader.py[871]: Please run RegisterDevice.py first
May 26 22:06:42 phoniebox systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
May 26 22:06:42 phoniebox systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
May 26 22:06:42 phoniebox systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:42 phoniebox systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 4.
May 26 22:06:42 phoniebox systemd[1]: Stopped Phoniebox RFID-Reader Service.
May 26 22:06:42 phoniebox systemd[1]: Started Phoniebox RFID-Reader Service.
May 26 22:06:43 phoniebox daemon_rfid_reader.py[875]: Please run RegisterDevice.py first
May 26 22:06:43 phoniebox systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE
May 26 22:06:43 phoniebox systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
May 26 22:06:43 phoniebox systemd[1]: phoniebox-rfid-reader.service: Service RestartSec=100ms expired, scheduling restart.
May 26 22:06:43 phoniebox systemd[1]: phoniebox-rfid-reader.service: Scheduled restart job, restart counter is at 5.
May 26 22:06:43 phoniebox systemd[1]: Stopped Phoniebox RFID-Reader Service.
May 26 22:06:43 phoniebox systemd[1]: phoniebox-rfid-reader.service: Start request repeated too quickly.
May 26 22:06:43 phoniebox systemd[1]: phoniebox-rfid-reader.service: Failed with result 'exit-code'.
May 26 22:06:43 phoniebox systemd[1]: Failed to start Phoniebox RFID-Reader Service.
May 26 22:06:44 phoniebox bash[792]: [0:03] Decoding of startupsound.mp3 finished.
May 26 22:06:44 phoniebox systemd[1]: Started Phoniebox Startup.
May 26 22:06:49 phoniebox systemd[1]: Created slice User Slice of UID 1000.
May 26 22:06:49 phoniebox systemd[1]: Starting User Runtime Directory /run/user/1000...
May 26 22:06:49 phoniebox systemd[1]: Started User Runtime Directory /run/user/1000.
May 26 22:06:49 phoniebox systemd[1]: Starting User Manager for UID 1000...
May 26 22:06:50 phoniebox systemd[903]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
May 26 22:06:50 phoniebox systemd[903]: Listening on GnuPG cryptographic agent and passphrase cache.
May 26 22:06:50 phoniebox systemd[903]: Listening on GnuPG network certificate management daemon.
May 26 22:06:50 phoniebox systemd[903]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 26 22:06:50 phoniebox systemd[903]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
May 26 22:06:50 phoniebox systemd[903]: Reached target Sockets.
May 26 22:06:50 phoniebox systemd[903]: Reached target Timers.
May 26 22:06:50 phoniebox systemd[903]: Reached target Paths.
May 26 22:06:50 phoniebox systemd[903]: Reached target Basic System.
May 26 22:06:50 phoniebox systemd[1]: Started User Manager for UID 1000.
May 26 22:06:50 phoniebox systemd[1]: Started Session c1 of user pi.
May 26 22:06:50 phoniebox systemd[903]: Starting Music Player Daemon...
May 26 22:06:52 phoniebox mpd[918]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
May 26 22:06:52 phoniebox systemd[903]: mpd.service: Main process exited, code=exited, status=1/FAILURE
May 26 22:06:52 phoniebox systemd[903]: mpd.service: Failed with result 'exit-code'.
May 26 22:06:52 phoniebox systemd[903]: Failed to start Music Player Daemon.
May 26 22:06:52 phoniebox systemd[903]: Reached target Default.
May 26 22:06:52 phoniebox systemd[903]: Startup finished in 2.667s.
May 26 22:06:59 phoniebox systemd[1]: systemd-fsckd.service: Succeeded.
May 26 22:07:10 phoniebox systemd-timesyncd[268]: Synchronized to time server for the first time 83.167.252.118:123 (2.debian.pool.ntp.org).
May 26 22:07:16 phoniebox exim4[442]: Starting MTA: exim4.
May 26 22:07:16 phoniebox exim4[442]: ALERT: exim paniclog /var/log/exim4/paniclog has non-zero size, mail system possibly broken
May 26 22:07:16 phoniebox systemd[1]: Started LSB: exim Mail Transport Agent.
May 26 22:07:16 phoniebox systemd[1]: Reached target Multi-User System.
May 26 22:07:16 phoniebox systemd[1]: Reached target Graphical Interface.
May 26 22:07:16 phoniebox systemd[1]: Starting Update UTMP about System Runlevel Changes...
May 26 22:07:17 phoniebox systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
May 26 22:07:17 phoniebox systemd[1]: Started Update UTMP about System Runlevel Changes.
May 26 22:07:17 phoniebox systemd[1]: Startup finished in 1.996s (kernel) + 43.400s (userspace) = 45.396s.
May 26 22:07:40 phoniebox lighttpd[777]: cat: /home/pi/RPi-Jukebox-RFID/scripts/../settings/Latest_Folder_Played: No such file or directory
May 26 22:07:40 phoniebox lighttpd[777]: cat: /home/pi/RPi-Jukebox-RFID/scripts/../settings/Latest_Playlist_Played: No such file or directory
May 26 22:07:40 phoniebox lighttpd[777]: cat: /home/pi/RPi-Jukebox-RFID/scripts/../settings/Latest_Folder_Played: No such file or directory
May 26 22:07:46 phoniebox systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
May 26 22:09:01 phoniebox CRON[1979]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
May 26 22:09:07 phoniebox systemd[1]: Starting Clean php session files...
May 26 22:09:08 phoniebox systemd[1]: phpsessionclean.service: Succeeded.
May 26 22:09:08 phoniebox systemd[1]: Started Clean php session files.'

[s-martin]

Probably not directly related to the problem, but you have a lot of errors like

May 26 22:06:40 phoniebox daemon_rfid_reader.py[862]: Please run RegisterDevice.py first
May 26 22:06:40 phoniebox systemd[1]: phoniebox-rfid-reader.service: Main process exited, code=exited, status=1/FAILURE

Do you use an RFID reader or do you intend to use one?

If you don’t intend to use one you could disable the service with

sudo systemctl stop phoniebox-rfid-reader
sudo systemctl disable phoniebox-rfid-reader

[BerniPi]

No, it's my rpi to test. No reader installed.

[s-martin]

I guess it’s a web interface issue, so I asked for the wrong log, sorry.

Could you post the output of sudo tail -n 300 /var/log/lighttpd/error.log?

[BerniPi]

2020-06-01 14:13:01: (server.c.1759) logfiles cycled UID = 0 PID = 982
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Notice:  Undefined index: MAILWLANIPYN in /home/pi/RPi-Jukebox-RFID/htdocs/inc.header.php on line 158
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Notice:  Undefined index: MAILWLANIPADDR in /home/pi/RPi-Jukebox-RFID/htdocs/inc.header.php on line 159
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Warning:  usort() expects exactly 2 parameters, 1 given in /home/pi/RPi-Jukebox-RFID/htdocs/inc.viewFolderTree.php on line 181
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Warning:  usort() expects exactly 2 parameters, 1 given in /home/pi/RPi-Jukebox-RFID/htdocs/inc.viewFolderTree.php on line 181
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Warning:  usort() expects exactly 2 parameters, 1 given in /home/pi/RPi-Jukebox-RFID/htdocs/inc.viewFolderTree.php on line 181
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Warning:  usort() expects exactly 2 parameters, 1 given in /home/pi/RPi-Jukebox-RFID/htdocs/inc.viewFolderTree.php on line 181
2020-06-01 14:13:23: (mod_fastcgi.c.421) FastCGI-stderr: PHP Warning:  usort() expects exactly 2 parameters, 1 given in /home/pi/RPi-Jukebox-RFID/htdocs/inc.viewFolderTree.php on line 181

There is no error related to pressing "add" or "single file play"

[s-martin]

Could you manually check, if your issue is fixed, if you manually apply the change in #993?

[BerniPi]

Yes, these errors are gone!
Do you can reproduce the behaviour that i encounter?

[s-martin]

So ist the behavior also gone or just the warnings in the log file?

I can't reproduce, because I don't have a working Pi right now.

[BerniPi]

No, the behaviour is the same. Just the warnings are gone.
I don't have time now to investigate it further and i don't use these functions. So it has no high priority for me.

[MiczFlor]

Mental note: investigate escaping single and double quotes for mpd / mpc
https://www.musicpd.org/doc/html/protocol.html#escaping-string-values

String values are quoted with single or double quotes, and special characters within those values must be escaped with the backslash (). Keep in mind that the backslash is also the escape character on the protocol level, which means you may need to use double backslash.

[BerniPi]

I did some further testing. I think that it's a problem with html.
Debugging works with "normal filenames", but there is no single debugging line from "htdocs/api/playlist/playsinglefile.php ", if i try a filename containing '.
Foldernames containing ' are problematic too.

Solution: Don't allow special characters in folder and filenames?

[BerniPi]

OK. Two changes are necessary:
-Everywhere where folder or filenames are used in the webinterface the command htmlspecialchars (https://www.php.net/manual/de/function.htmlspecialchars.php) has to be added. Then the html-code is corrected.

• mpd/mpc is not a problem, but the bash scripts: https://superuser.com/questions/163515/bash-how-to-pass-command-line-arguments-containing-special-characters

The single file play is working for me now. But i'll go to bed now. I will open a pullrequest soon.

[BerniPi]

I also looked into making it possible to use single quotes in folder names, but there are also problems with creating folders in webinterface containing other special characters like double quotes or $

I don't think it's worth the efforts. Better to advice users to not use special characters in foldernames.