search

SimulPiscator / AirSane

Publish SANE scanners to MacOS, Android, and Windows via Apple AirScan.
GNU General Public License v3.0
247 stars 26 forks source link

airsaned.service fails to start on boot (solved with service start delay) #55

Closed hiatsu0 closed 3 years ago

hiatsu0 commented 3 years ago

Installed AirSane with the commands listed at the bottom of this post and came across an issue that airsaned.service fails to start on reboot with the following error:

sudo systemctl status airsaned
● airsaned.service - AirSane Imaging Service
   Loaded: loaded (/lib/systemd/system/airsaned.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Wed 2021-04-07 17:07:28 BST; 2min 32s ago
  Process: 527 ExecStart=/usr/local/bin/airsaned --interface=${INTERFACE} --base-port=${BASE_PORT} --access-log=${ACCESS_LOG} --hotplug=${HOTPLUG} --mdn
 Main PID: 527 (code=exited, status=255/EXCEPTION)

Apr 07 17:07:27 raspi3 systemd[1]: Started AirSane Imaging Service.
Apr 07 17:07:28 raspi3 airsaned[527]: server finished with error status -1, last error was 99: Cannot assign requested address
Apr 07 17:07:28 raspi3 systemd[1]: airsaned.service: Main process exited, code=exited, status=255/EXCEPTION
Apr 07 17:07:28 raspi3 systemd[1]: airsaned.service: Failed with result 'exit-code'.

Simply commanding sudo systemctl start airsaned manually after boot made everything work again without errors:

● airsaned.service - AirSane Imaging Service
   Loaded: loaded (/lib/systemd/system/airsaned.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2021-04-07 17:10:54 BST; 2s ago
 Main PID: 713 (airsaned)
    Tasks: 5 (limit: 2062)
   CGroup: /system.slice/airsaned.service
           └─713 /usr/local/bin/airsaned --interface=* --base-port=8090 --access-log= --hotplug=true --mdns-announce=true --local-scanners-only=true --o

Apr 07 17:10:54 raspi3 systemd[1]: Started AirSane Imaging Service.

So I figured there needed to be a delay for some reason and indeed, after adding ExecStartPre=/bin/sleep 15 before line ExecStart=... in service file /lib/systemd/system/airsaned.service made airsaned start without errors even on boot.

My install notes:

sudo apt-get install libsane-dev libjpeg-dev libpng-dev
sudo apt-get install libavahi-client-dev libusb-1.*-dev
sudo apt-get install git cmake g++
git clone https://github.com/SimulPiscator/AirSane.git
mkdir AirSane-build && cd AirSane-build
cmake ../AirSane
make
sudo apt install sane-utils
sane-find-scanner
sudo usermod -G lp saned
sudo -u saned scanimage -L
sudo apt install avahi-daemon
#cd AirSane-build/
sudo make install
sudo systemctl enable airsaned
sudo systemctl start airsaned
sudo systemctl status airsaned
sudo nano /etc/sane.d/dll.conf  #commenting out unused scanners
airsaned --help
sudo nano /lib/systemd/system/airsaned.service  #adding "ExecStartPre=/bin/sleep 15" before ExecStart
hiatsu0 commented 3 years ago

Only now found out there was an existing closed issue already: https://github.com/SimulPiscator/AirSane/issues/33

SimulPiscator commented 3 years ago

Thank you for your comments. Rather than adding "ExecStartPre=/bin/sleep 15" now, I'll reopen this issue and wait for comments from other users before changing anything.

hiatsu0 commented 3 years ago

Let me know if there are any log files I could grab when I boot without the ExecStartPre and it fails. The system here is Raspberry Pi 3B+ running Raspbian 10 (buster), Linux 5.10.17-v7+ #1403.

SimulPiscator commented 3 years ago

I have a Raspberry Pi 2 running Buster and the same kernel as you do, and do not experience any problems. The output of "sudo journalctl" would be most helpful for debugging your problem.

LXR85 commented 3 years ago

I have a Raspberry Zero W and just recompiled from sources and I have the very same issue as @hiatsu0

LXR85 commented 3 years ago 
$ sudo journalctl
-- Logs begin at Thu 2019-02-14 10:12:03 GMT, end at Fri 2021-07-09 22:09:35 BST. --
Feb 14 10:12:03 raspberrypi kernel: Booting Linux on physical CPU 0x0
Feb 14 10:12:03 raspberrypi kernel: Linux version 5.10.17+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1421 Thu May 27 13:58:02 BST 2021
Feb 14 10:12:03 raspberrypi kernel: CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Jul 09 21:17:01 raspberrypi kernel: CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Jul 09 21:17:01 raspberrypi kernel: OF: fdt: Machine model: Raspberry Pi Zero W Rev 1.1
Jul 09 21:17:01 raspberrypi kernel: Memory policy: Data cache writeback
Jul 09 21:17:01 raspberrypi kernel: Reserved memory: created CMA memory pool at 0x17c00000, size 64 MiB
Jul 09 21:17:01 raspberrypi kernel: OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
Jul 09 21:17:01 raspberrypi kernel: Zone ranges:
Jul 09 21:17:01 raspberrypi kernel:   Normal   [mem 0x0000000000000000-0x000000001bffffff]
Jul 09 21:17:01 raspberrypi kernel: Movable zone start for each node
Jul 09 21:17:01 raspberrypi kernel: Early memory node ranges
Jul 09 21:17:01 raspberrypi kernel:   node   0: [mem 0x0000000000000000-0x000000001bffffff]
Jul 09 21:17:01 raspberrypi kernel: Initmem setup node 0 [mem 0x0000000000000000-0x000000001bffffff]
Jul 09 21:17:01 raspberrypi kernel: On node 0 totalpages: 114688
Jul 09 21:17:01 raspberrypi kernel:   Normal zone: 1008 pages used for memmap
Jul 09 21:17:01 raspberrypi kernel:   Normal zone: 0 pages reserved
Jul 09 21:17:01 raspberrypi kernel:   Normal zone: 114688 pages, LIFO batch:31
Jul 09 21:17:01 raspberrypi kernel: pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Jul 09 21:17:01 raspberrypi kernel: pcpu-alloc: [0] 0
Jul 09 21:17:01 raspberrypi kernel: Built 1 zonelists, mobility grouping on.  Total pages: 113680
Jul 09 21:17:01 raspberrypi kernel: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswa
Jul 09 21:17:01 raspberrypi kernel: Kernel parameter elevator= does not have any effect anymore.
                                    Please use sysfs to set IO scheduler for individual devices.
Jul 09 21:17:01 raspberrypi kernel: Dentry cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: Inode-cache hash table entries: 32768 (order: 5, 131072 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: mem auto-init: stack:off, heap alloc:off, heap free:off
Jul 09 21:17:01 raspberrypi kernel: Memory: 374456K/458752K available (8638K kernel code, 1324K rwdata, 2816K rodata, 420K init, 837K bss, 18760K reserved, 65536K cma-reserved)
Jul 09 21:17:01 raspberrypi kernel: SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Jul 09 21:17:01 raspberrypi kernel: ftrace: allocating 30576 entries in 60 pages
Jul 09 21:17:01 raspberrypi kernel: ftrace: allocated 60 pages with 4 groups
Jul 09 21:17:01 raspberrypi kernel: NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
Jul 09 21:17:01 raspberrypi kernel: random: get_random_bytes called from start_kernel+0x324/0x564 with crng_init=0
Jul 09 21:17:01 raspberrypi kernel: sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
Jul 09 21:17:01 raspberrypi kernel: clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
Jul 09 21:17:01 raspberrypi kernel: bcm2835: system timer (irq = 27)
Jul 09 21:17:01 raspberrypi kernel: Console: colour dummy device 80x30
Jul 09 21:17:01 raspberrypi kernel: printk: console [tty1] enabled
Jul 09 21:17:01 raspberrypi kernel: Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Jul 09 21:17:01 raspberrypi kernel: pid_max: default: 32768 minimum: 301
Jul 09 21:17:01 raspberrypi kernel: LSM: Security Framework initializing
Jul 09 21:17:01 raspberrypi kernel: Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: Disabling memory control group subsystem
Jul 09 21:17:01 raspberrypi kernel: CPU: Testing write buffer coherency: ok
Jul 09 21:17:01 raspberrypi kernel: Setting up static identity map for 0x8200 - 0x8238
Jul 09 21:17:01 raspberrypi kernel: devtmpfs: initialized
Jul 09 21:17:01 raspberrypi kernel: VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Jul 09 21:17:01 raspberrypi kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
Jul 09 21:17:01 raspberrypi kernel: futex hash table entries: 256 (order: -1, 3072 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: pinctrl core: initialized pinctrl subsystem
Jul 09 21:17:01 raspberrypi kernel: NET: Registered protocol family 16
Jul 09 21:17:01 raspberrypi kernel: DMA: preallocated 1024 KiB pool for atomic coherent allocations
Jul 09 21:17:01 raspberrypi kernel: audit: initializing netlink subsys (disabled)
Jul 09 21:17:01 raspberrypi kernel: thermal_sys: Registered thermal governor 'step_wise'
Jul 09 21:17:01 raspberrypi kernel: hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Jul 09 21:17:01 raspberrypi kernel: hw-breakpoint: maximum watchpoint size is 4 bytes.
Jul 09 21:17:01 raspberrypi kernel: Serial: AMBA PL011 UART driver
Jul 09 21:17:01 raspberrypi kernel: audit: type=2000 audit(0.100:1): state=initialized audit_enabled=0 res=1
Jul 09 21:17:01 raspberrypi kernel: bcm2835-mbox 2000b880.mailbox: mailbox enabled
Jul 09 21:17:01 raspberrypi kernel: raspberrypi-firmware soc:firmware: Attached to firmware from 2021-05-27T14:04:13, variant start
Jul 09 21:17:01 raspberrypi kernel: raspberrypi-firmware soc:firmware: Firmware hash is 7d9a298cda813f747b51fe17e1e417e7bf5ca94d
Jul 09 21:17:01 raspberrypi kernel: bcm2835-dma 20007000.dma: DMA legacy API manager, dmachans=0x1
Jul 09 21:17:01 raspberrypi kernel: SCSI subsystem initialized
Jul 09 21:17:01 raspberrypi kernel: usbcore: registered new interface driver usbfs
Jul 09 21:17:01 raspberrypi kernel: usbcore: registered new interface driver hub
Jul 09 21:17:01 raspberrypi kernel: usbcore: registered new device driver usb
Jul 09 21:17:01 raspberrypi kernel: clocksource: Switched to clocksource timer
Jul 09 21:17:01 raspberrypi kernel: VFS: Disk quotas dquot_6.6.0
Jul 09 21:17:01 raspberrypi kernel: VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Jul 09 21:17:01 raspberrypi kernel: FS-Cache: Loaded
Jul 09 21:17:01 raspberrypi kernel: CacheFiles: Loaded
Jul 09 21:17:01 raspberrypi kernel: NET: Registered protocol family 2
Jul 09 21:17:01 raspberrypi kernel: tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: TCP established hash table entries: 4096 (order: 2, 16384 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: TCP bind hash table entries: 4096 (order: 2, 16384 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: TCP: Hash tables configured (established 4096 bind 4096)
Jul 09 21:17:01 raspberrypi kernel: UDP hash table entries: 256 (order: 0, 4096 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: UDP-Lite hash table entries: 256 (order: 0, 4096 bytes, linear)
Jul 09 21:17:01 raspberrypi kernel: NET: Registered protocol family 1
Jul 09 21:17:01 raspberrypi kernel: RPC: Registered named UNIX socket transport module.
Jul 09 21:17:01 raspberrypi kernel: RPC: Registered udp transport module.
Jul 09 21:17:01 raspberrypi kernel: RPC: Registered tcp transport module.
Jul 09 21:17:01 raspberrypi kernel: RPC: Registered tcp NFSv4.1 backchannel transport module.
Jul 09 21:17:01 raspberrypi kernel: hw perfevents: no irqs for PMU, sampling events not supported
Jul 09 21:17:01 raspberrypi kernel: hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available
Jul 09 21:17:01 raspberrypi kernel: Initialise system trusted keyrings
Jul 09 21:17:01 raspberrypi kernel: workingset: timestamp_bits=14 max_order=17 bucket_order=3
Jul 09 21:17:01 raspberrypi kernel: zbud: loaded
Jul 09 21:17:01 raspberrypi kernel: FS-Cache: Netfs 'nfs' registered for caching
Jul 09 21:17:01 raspberrypi kernel: NFS: Registering the id_resolver key type
Jul 09 21:17:01 raspberrypi kernel: Key type id_resolver registered
Jul 09 21:17:01 raspberrypi kernel: Key type id_legacy registered
Jul 09 21:17:01 raspberrypi kernel: nfs4filelayout_init: NFSv4 File Layout Driver Registering...
Jul 09 21:17:01 raspberrypi kernel: Key type asymmetric registered
Jul 09 21:17:01 raspberrypi kernel: Asymmetric key parser 'x509' registered
Jul 09 21:17:01 raspberrypi kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
Jul 09 21:17:01 raspberrypi kernel: io scheduler mq-deadline registered
Jul 09 21:17:01 raspberrypi kernel: io scheduler kyber registered
Jul 09 21:17:01 raspberrypi kernel: bcm2708_fb soc:fb: FB found 1 display(s)
Jul 09 21:17:01 raspberrypi kernel: Console: switching to colour frame buffer device 82x26
Jul 09 21:17:01 raspberrypi kernel: random: fast init done
Jul 09 21:17:01 raspberrypi kernel: bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
Jul 09 21:17:01 raspberrypi kernel: bcm2835-rng 20104000.rng: hwrng registered
Jul 09 21:17:01 raspberrypi kernel: vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
Jul 09 21:17:01 raspberrypi kernel: gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000
Jul 09 21:17:01 raspberrypi kernel: brd: module loaded
Jul 09 21:17:01 raspberrypi kernel: loop: module loaded
Jul 09 21:17:01 raspberrypi kernel: Loading iSCSI transport class v2.0-870.
Jul 09 21:17:01 raspberrypi kernel: libphy: Fixed MDIO Bus: probed
Jul 09 21:17:01 raspberrypi kernel: usbcore: registered new interface driver smsc95xx
Jul 09 21:17:01 raspberrypi kernel: dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Jul 09 21:17:01 raspberrypi kernel: Core Release: 2.80a
Jul 09 21:17:01 raspberrypi kernel: Setting default values for core params
Jul 09 21:17:01 raspberrypi kernel: Finished setting default values for core params
Jul 09 21:17:01 raspberrypi kernel: Using Buffer DMA mode
Jul 09 21:17:01 raspberrypi kernel: Periodic Transfer Interrupt Enhancement - disabled
Jul 09 21:17:01 raspberrypi kernel: Multiprocessor Interrupt Enhancement - disabled
Jul 09 21:17:01 raspberrypi kernel: OTG VER PARAM: 0, OTG VER FLAG: 0
Jul 09 21:17:01 raspberrypi kernel: Dedicated Tx FIFOs mode
Jul 09 21:17:01 raspberrypi kernel:
Jul 09 21:17:01 raspberrypi kernel: WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = d7d14000 dma = 0x97d14000 len=9024
Jul 09 21:17:01 raspberrypi kernel: FIQ FSM acceleration enabled for :
                                    Non-periodic Split Transactions
                                    Periodic Split Transactions
                                    High-Speed Isochronous Endpoints
                                    Interrupt/Control Split Transaction hack enabled
Jul 09 21:17:01 raspberrypi kernel: dwc_otg: Microframe scheduler enabled
Jul 09 21:17:01 raspberrypi kernel:
Jul 09 21:17:01 raspberrypi kernel: WARN::hcd_init_fiq:457: FIQ on core 0
Jul 09 21:17:01 raspberrypi kernel:
Jul 09 21:17:01 raspberrypi kernel: WARN::hcd_init_fiq:458: FIQ ASM at c0652330 length 36
Jul 09 21:17:01 raspberrypi kernel:
Jul 09 21:17:01 raspberrypi kernel: WARN::hcd_init_fiq:497: MPHI regs_base at dc810000
Jul 09 21:17:01 raspberrypi kernel: dwc_otg 20980000.usb: DWC OTG Controller
Jul 09 21:17:01 raspberrypi kernel: dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1
Jul 09 21:17:01 raspberrypi kernel: dwc_otg 20980000.usb: irq 56, io mem 0x00000000
Jul 09 21:17:01 raspberrypi kernel: Init: Port Power? op_state=1
Jul 09 21:17:01 raspberrypi kernel: Init: Power Port (0)
Jul 09 21:17:01 raspberrypi kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
Jul 09 21:17:01 raspberrypi kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jul 09 21:17:01 raspberrypi kernel: usb usb1: Product: DWC OTG Controller
Jul 09 21:17:01 raspberrypi kernel: usb usb1: Manufacturer: Linux 5.10.17+ dwc_otg_hcd
Jul 09 21:17:02 raspberrypi kernel: usb usb1: SerialNumber: 20980000.usb
Jul 09 21:17:02 raspberrypi kernel: hub 1-0:1.0: USB hub found
Jul 09 21:17:02 raspberrypi kernel: hub 1-0:1.0: 1 port detected
Jul 09 21:17:02 raspberrypi kernel: dwc_otg: FIQ enabled
Jul 09 21:17:02 raspberrypi kernel: dwc_otg: NAK holdoff enabled
Jul 09 21:17:02 raspberrypi kernel: dwc_otg: FIQ split-transaction FSM enabled
Jul 09 21:17:02 raspberrypi kernel: Module dwc_common_port init
Jul 09 21:17:02 raspberrypi kernel: usbcore: registered new interface driver usb-storage
Jul 09 21:17:02 raspberrypi kernel: mousedev: PS/2 mouse device common for all mice
Jul 09 21:17:02 raspberrypi kernel: bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
Jul 09 21:17:02 raspberrypi kernel: sdhci: Secure Digital Host Controller Interface driver
Jul 09 21:17:02 raspberrypi kernel: sdhci: Copyright(c) Pierre Ossman
Jul 09 21:17:02 raspberrypi kernel: mmc-bcm2835 20300000.mmcnr: could not get clk, deferring probe
Jul 09 21:17:02 raspberrypi kernel: sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe
Jul 09 21:17:02 raspberrypi kernel: sdhci-pltfm: SDHCI platform and OF driver helper
Jul 09 21:17:02 raspberrypi kernel: ledtrig-cpu: registered to indicate activity on CPUs
Jul 09 21:17:02 raspberrypi kernel: hid: raw HID events driver (C) Jiri Kosina
Jul 09 21:17:02 raspberrypi kernel: usbcore: registered new interface driver usbhid
Jul 09 21:17:02 raspberrypi kernel: usbhid: USB HID core driver
Jul 09 21:17:02 raspberrypi kernel: Initializing XFRM netlink socket
Jul 09 21:17:02 raspberrypi kernel: NET: Registered protocol family 17
Jul 09 21:17:02 raspberrypi kernel: Key type dns_resolver registered
Jul 09 21:17:02 raspberrypi kernel: registered taskstats version 1
Jul 09 21:17:02 raspberrypi kernel: Loading compiled-in X.509 certificates
Jul 09 21:17:02 raspberrypi kernel: uart-pl011 20201000.serial: cts_event_workaround enabled
Jul 09 21:17:02 raspberrypi kernel: 20201000.serial: ttyAMA0 at MMIO 0x20201000 (irq = 81, base_baud = 0) is a PL011 rev2
Jul 09 21:17:02 raspberrypi kernel: bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
Jul 09 21:17:02 raspberrypi kernel: mmc-bcm2835 20300000.mmcnr: mmc_debug:0 mmc_debug2:0
Jul 09 21:17:02 raspberrypi kernel: mmc-bcm2835 20300000.mmcnr: DMA channel allocated
Jul 09 21:17:02 raspberrypi kernel: sdhost: log_buf @ (ptrval) (97d13000)
Jul 09 21:17:02 raspberrypi kernel: mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
Jul 09 21:17:02 raspberrypi kernel: mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Jul 09 21:17:02 raspberrypi kernel: mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Jul 09 21:17:02 raspberrypi kernel: of_cfs_init
Jul 09 21:17:02 raspberrypi kernel: of_cfs_init: OK
Jul 09 21:17:02 raspberrypi kernel: mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Jul 09 21:17:02 raspberrypi kernel: Waiting for root device PARTUUID=1d5609af-02...
Jul 09 21:17:02 raspberrypi kernel: mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
Jul 09 21:17:02 raspberrypi kernel: mmc0: host does not support reading read-only switch, assuming write-enable
Jul 09 21:17:02 raspberrypi kernel: mmc0: new high speed SDHC card at address b368
Jul 09 21:17:02 raspberrypi kernel: mmcblk0: mmc0:b368 SD    7.51 GiB
Jul 09 21:17:02 raspberrypi kernel:  mmcblk0: p1 p2
Jul 09 21:17:02 raspberrypi kernel: EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
Jul 09 21:17:02 raspberrypi kernel: EXT4-fs (mmcblk0p2): write access will be enabled during recovery
Jul 09 21:17:02 raspberrypi kernel: mmc1: new high speed SDIO card at address 0001
Jul 09 21:17:02 raspberrypi kernel: Indeed it is in host mode hprt0 = 00021501
Jul 09 21:17:02 raspberrypi kernel: usb 1-1: new high-speed USB device number 2 using dwc_otg
Jul 09 21:17:02 raspberrypi kernel: Indeed it is in host mode hprt0 = 00001101
Jul 09 21:17:02 raspberrypi kernel: usb 1-1: New USB device found, idVendor=04e8, idProduct=3434, bcdDevice= 1.00
Jul 09 21:17:02 raspberrypi kernel: usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jul 09 21:17:02 raspberrypi kernel: usb 1-1: Product: SCX-4623 Series
Jul 09 21:17:02 raspberrypi kernel: usb 1-1: Manufacturer: Samsung
Jul 09 21:17:02 raspberrypi kernel: usb 1-1: SerialNumber: Z316BAAS900492Z
Jul 09 21:17:02 raspberrypi kernel: random: crng init done
Jul 09 21:17:02 raspberrypi kernel: EXT4-fs (mmcblk0p2): recovery complete
Jul 09 21:17:02 raspberrypi kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Jul 09 21:17:02 raspberrypi kernel: VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Jul 09 21:17:02 raspberrypi kernel: devtmpfs: mounted
Jul 09 21:17:02 raspberrypi kernel: Freeing unused kernel memory: 420K
Jul 09 21:17:02 raspberrypi kernel: Kernel memory protection not selected by kernel config.
Jul 09 21:17:02 raspberrypi kernel: Run /sbin/init as init process
Jul 09 21:17:02 raspberrypi kernel:   with arguments:
Jul 09 21:17:02 raspberrypi kernel:     /sbin/init
Jul 09 21:17:02 raspberrypi kernel:   with environment:
Jul 09 21:17:02 raspberrypi kernel:     HOME=/
Jul 09 21:17:02 raspberrypi kernel:     TERM=linux
Jul 09 21:17:02 raspberrypi systemd[1]: System time before build time, advancing clock.
Jul 09 21:17:02 raspberrypi kernel: NET: Registered protocol family 10
Jul 09 21:17:02 raspberrypi kernel: Segment Routing with IPv6
Jul 09 21:17:02 raspberrypi systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD
Jul 09 21:17:02 raspberrypi systemd[1]: Detected architecture arm.
Jul 09 21:17:02 raspberrypi systemd[1]: Set hostname to <raspberrypi>.
Jul 09 21:17:02 raspberrypi systemd[1]: Listening on Syslog Socket.
Jul 09 21:17:02 raspberrypi systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Jul 09 21:17:02 raspberrypi systemd[1]: Created slice system-systemd\x2dfsck.slice.
Jul 09 21:17:02 raspberrypi systemd[1]: Listening on Journal Socket.
Jul 09 21:17:02 raspberrypi systemd[1]: Mounting POSIX Message Queue File System...
Jul 09 21:17:02 raspberrypi systemd[1]: Starting Set the console keyboard layout...
Jul 09 21:17:02 raspberrypi systemd[1]: Mounting RPC Pipe File System...
Jul 09 21:17:02 raspberrypi systemd[1]: Mounting Kernel Configuration File System...
Jul 09 21:17:02 raspberrypi systemd[1]: Condition check resulted in FUSE Control File System being skipped.
Jul 09 21:17:02 raspberrypi systemd[1]: Starting Apply Kernel Variables...
Jul 09 21:17:02 raspberrypi systemd[1]: Mounted Kernel Configuration File System.
Jul 09 21:17:02 raspberrypi systemd[1]: Started File System Check Daemon to report status.
Jul 09 21:17:02 raspberrypi systemd[1]: Started Apply Kernel Variables.
Jul 09 21:17:02 raspberrypi systemd-journald[83]: Journal started
Jul 09 21:17:02 raspberrypi systemd-journald[83]: Runtime journal (/run/log/journal/f0cd00bb6a7547ec91d7d6997e730d23) is 8.0M, max 21.5M, 13.4M free.
Jul 09 21:17:02 raspberrypi systemd[1]: Started Journal Service.
Jul 09 21:17:02 raspberrypi systemd[1]: Started File System Check on Root Device.
Jul 09 21:17:02 raspberrypi fake-hwclock[88]: Fri  9 Jul 20:17:01 UTC 2021
Jul 09 21:17:02 raspberrypi systemd-fsck[96]: e2fsck 1.44.5 (15-Dec-2018)
Jul 09 21:17:02 raspberrypi systemd-fsck[96]: rootfs: clean, 66702/472000 files, 658190/1902336 blocks
Jul 09 21:17:02 raspberrypi systemd[1]: Starting Remount Root and Kernel File Systems...
Jul 09 21:17:03 raspberrypi systemd[1]: Started Set the console keyboard layout.
Jul 09 21:17:04 raspberrypi kernel: EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Jul 09 21:17:04 raspberrypi systemd[1]: Started Remount Root and Kernel File Systems.
Jul 09 21:17:04 raspberrypi systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
Jul 09 21:17:04 raspberrypi systemd[1]: Starting Load/Save Random Seed...
Jul 09 21:17:04 raspberrypi systemd[1]: Starting Flush Journal to Persistent Storage...
Jul 09 21:17:04 raspberrypi systemd[1]: Starting Create System Users...
Jul 09 21:17:04 raspberrypi systemd[1]: Started udev Coldplug all Devices.
Jul 09 21:17:04 raspberrypi systemd[1]: Starting Helper to synchronize boot up for ifupdown...
Jul 09 21:17:04 raspberrypi systemd[1]: Started Helper to synchronize boot up for ifupdown.
Jul 09 21:17:04 raspberrypi systemd[1]: Started Load/Save Random Seed.
Jul 09 21:17:04 raspberrypi systemd-journald[83]: Runtime journal (/run/log/journal/f0cd00bb6a7547ec91d7d6997e730d23) is 8.0M, max 21.5M, 13.4M free.
Jul 09 21:17:04 raspberrypi systemd[1]: Started Flush Journal to Persistent Storage.
Jul 09 21:17:04 raspberrypi systemd[1]: Started Create System Users.
Jul 09 21:17:05 raspberrypi systemd[1]: Starting Create Static Device Nodes in /dev...
Jul 09 21:17:05 raspberrypi systemd[1]: Started Create Static Device Nodes in /dev.
Jul 09 21:17:05 raspberrypi systemd[1]: Reached target Local File Systems (Pre).
Jul 09 21:17:05 raspberrypi systemd[1]: Starting udev Kernel Device Manager...
Jul 09 21:17:05 raspberrypi systemd[1]: Started udev Kernel Device Manager.
Jul 09 21:17:07 raspberrypi kernel: mc: Linux media interface: v0.10
Jul 09 21:17:07 raspberrypi kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:07 raspberrypi kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver
Jul 09 21:17:07 raspberrypi kernel: [vc_sm_connected_init]: start
Jul 09 21:17:07 raspberrypi kernel: [vc_sm_connected_init]: installed successfully
Jul 09 21:17:07 raspberrypi kernel: videodev: Linux video capture interface: v2.00
Jul 09 21:17:08 raspberrypi kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:08 raspberrypi kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:08 raspberrypi kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:08 raspberrypi kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:08 raspberrypi kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:08 raspberrypi kernel: bcm2835_audio bcm2835_audio: there is not valid maps for state default
Jul 09 21:17:08 raspberrypi kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
Jul 09 21:17:08 raspberrypi kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
Jul 09 21:17:08 raspberrypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10
Jul 09 21:17:08 raspberrypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode
Jul 09 21:17:08 raspberrypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11
Jul 09 21:17:08 raspberrypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode
Jul 09 21:17:08 raspberrypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12
Jul 09 21:17:08 raspberrypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp
Jul 09 21:17:10 raspberrypi kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database
Jul 09 21:17:11 raspberrypi systemd[1]: Found device /dev/disk/by-partuuid/1d5609af-01.
Jul 09 21:17:11 raspberrypi kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
Jul 09 21:17:11 raspberrypi systemd-udevd[114]: Process '/usr/bin/setfacl -m g:scanner:rw ' failed with exit code 2.
Jul 09 21:17:11 raspberrypi systemd-udevd[117]: Process '/usr/bin/setfacl -m g:scanner:rw ' failed with exit code 2.
Jul 09 21:17:11 raspberrypi kernel: brcmfmac: F1 signature read @0x18000000=0x1541a9a6
Jul 09 21:17:11 raspberrypi kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
Jul 09 21:17:11 raspberrypi kernel: usbcore: registered new interface driver brcmfmac
Jul 09 21:17:11 raspberrypi kernel: usblp 1-1:1.1: usblp0: USB Bidirectional printer dev 2 if 1 alt 0 proto 2 vid 0x04E8 pid 0x3434
Jul 09 21:17:11 raspberrypi kernel: usbcore: registered new interface driver usblp
Jul 09 21:17:11 raspberrypi kernel: brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43430-sdio.raspberrypi,model-zero-w.txt failed with error -2
Jul 09 21:17:12 raspberrypi kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
Jul 09 21:17:12 raspberrypi kernel: brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
Jul 09 21:17:12 raspberrypi kernel: 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
Jul 09 21:17:14 raspberrypi systemd[1]: Condition check resulted in Huge Pages File System being skipped.
Jul 09 21:17:14 raspberrypi systemd[1]: Condition check resulted in FUSE Control File System being skipped.
Jul 09 21:17:14 raspberrypi systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
Jul 09 21:17:14 raspberrypi systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
Jul 09 21:17:14 raspberrypi systemd[1]: Starting File System Check on /dev/disk/by-partuuid/1d5609af-01...
Jul 09 21:17:16 raspberrypi systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Jul 09 21:17:16 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Jul 09 21:17:16 raspberrypi systemd-udevd[123]: Using default interface naming scheme 'v240'.
Jul 09 21:17:16 raspberrypi systemd-udevd[116]: Process '/usr/bin/setfacl -m g:scanner:rw ' failed with exit code 2.
Jul 09 21:17:17 raspberrypi systemd-fsck[176]: fsck.fat 4.1 (2017-01-24)
Jul 09 21:17:17 raspberrypi systemd-fsck[176]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
Jul 09 21:17:17 raspberrypi systemd-fsck[176]:  Automatically removing dirty bit.
Jul 09 21:17:17 raspberrypi systemd-fsck[176]: Performing changes.
Jul 09 21:17:17 raspberrypi systemd-fsck[176]: /dev/mmcblk0p1: 265 files, 97579/516190 clusters
Jul 09 21:17:17 raspberrypi systemd[1]: Started File System Check on /dev/disk/by-partuuid/1d5609af-01.
Jul 09 21:17:17 raspberrypi systemd[1]: Mounting /boot...
Jul 09 21:17:17 raspberrypi systemd[1]: Mounted /boot.
Jul 09 21:17:17 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.
Jul 09 21:17:17 raspberrypi systemd[1]: Reached target Local File Systems.
Jul 09 21:17:17 raspberrypi systemd[1]: Starting Create Volatile Files and Directories...
Jul 09 21:17:18 raspberrypi systemd[1]: Starting Set console font and keymap...
Jul 09 21:17:18 raspberrypi systemd[1]: Starting Preprocess NFS configuration...
Jul 09 21:17:18 raspberrypi systemd[1]: Starting Raise network interfaces...
Jul 09 21:17:18 raspberrypi systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
Jul 09 21:17:18 raspberrypi systemd[1]: Started Set console font and keymap.
Jul 09 21:17:18 raspberrypi systemd[1]: nfs-config.service: Succeeded.
Jul 09 21:17:18 raspberrypi systemd[1]: Started Preprocess NFS configuration.
Jul 09 21:17:18 raspberrypi systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped.
Jul 09 21:17:18 raspberrypi systemd[1]: Condition check resulted in RPC security service for NFS server being skipped.
Jul 09 21:17:18 raspberrypi systemd[1]: Reached target NFS client services.
Jul 09 21:17:18 raspberrypi systemd[1]: Reached target Remote File Systems (Pre).
Jul 09 21:17:18 raspberrypi systemd[1]: Reached target Remote File Systems.
Jul 09 21:17:19 raspberrypi systemd[1]: Started Create Volatile Files and Directories.
Jul 09 21:17:19 raspberrypi systemd[1]: Starting Network Time Synchronization...
Jul 09 21:17:19 raspberrypi systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jul 09 21:17:20 raspberrypi systemd[1]: Started Update UTMP about System Boot/Shutdown.
Jul 09 21:17:20 raspberrypi systemd[1]: Started Raise network interfaces.
Jul 09 21:17:20 raspberrypi systemd-timesyncd[223]: System clock time unset or jumped backwards, restoring from recorded timestamp: Fri 2021-07-09 21:23:21 BST
Jul 09 21:23:21 raspberrypi systemd[1]: Started Network Time Synchronization.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target System Time Synchronized.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target System Initialization.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Jul 09 21:23:21 raspberrypi systemd[1]: Started CUPS Scheduler.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Paths.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on saned incoming socket.
Jul 09 21:23:21 raspberrypi systemd[1]: Started Daily rotation of log files.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on D-Bus System Message Bus Socket.
Jul 09 21:23:21 raspberrypi systemd[1]: Started Daily Cleanup of Temporary Directories.
Jul 09 21:23:21 raspberrypi systemd[1]: Started Daily man-db regeneration.
Jul 09 21:23:21 raspberrypi systemd[1]: Started Daily apt download activities.
Jul 09 21:23:21 raspberrypi systemd[1]: Started Daily apt upgrade and clean activities.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Timers.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on CUPS Scheduler.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on triggerhappy.socket.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Sockets.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Basic System.
Jul 09 21:23:21 raspberrypi systemd[1]: Starting Configure Bluetooth Modems connected by UART...
Jul 09 21:23:22 raspberrypi systemd[1]: Started CUPS Scheduler.
Jul 09 21:23:22 raspberrypi systemd[1]: Reached target Printer.
Jul 09 21:23:22 raspberrypi systemd[1]: Started D-Bus System Message Bus.
Jul 09 21:23:22 raspberrypi systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Jul 09 21:23:22 raspberrypi systemd[1]: Started AirSane Imaging Service.
Jul 09 21:23:22 raspberrypi systemd[1]: Starting Check for Raspberry Pi EEPROM updates...
Jul 09 21:23:22 raspberrypi systemd[1]: Starting dphys-swapfile - set up, mount/unmount, and delete a swap file...
Jul 09 21:23:23 raspberrypi systemd[1]: Starting triggerhappy global hotkey daemon...
Jul 09 21:23:23 raspberrypi systemd[1]: Starting System Logging Service...
Jul 09 21:23:23 raspberrypi rpi-eeprom-update[281]: This tool only works with a Raspberry Pi 4
Jul 09 21:23:23 raspberrypi thd[286]: Found socket passed from systemd
Jul 09 21:23:23 raspberrypi systemd[1]: Started Regular background program processing daemon.
Jul 09 21:23:23 raspberrypi cron[300]: (CRON) INFO (pidfile fd = 3)
Jul 09 21:23:23 raspberrypi kernel: uart-pl011 20201000.serial: no DMA platform data
Jul 09 21:23:23 raspberrypi systemd[1]: Starting Login Service...
Jul 09 21:23:23 raspberrypi cron[300]: (CRON) INFO (Running @reboot jobs)
Jul 09 21:23:23 raspberrypi systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
Jul 09 21:23:24 raspberrypi rsyslogd[296]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Jul 09 21:23:24 raspberrypi dbus-daemon[261]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.1' (uid=109 pid=279 comm="/us
Jul 09 21:23:24 raspberrypi rsyslogd[296]:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="296" x-info="https://www.rsyslog.com"] start
Jul 09 21:23:24 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Jul 09 21:23:24 raspberrypi systemd[1]: Starting WPA supplicant...
Jul 09 21:23:24 raspberrypi systemd[1]: Condition check resulted in Turn on SSH if /boot/ssh is present being skipped.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting rng-tools.service...
Jul 09 21:23:24 raspberrypi systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Found user 'avahi' (UID 108) and group 'avahi' (GID 113).
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully dropped root privileges.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: avahi-daemon 0.7 starting up.
Jul 09 21:23:24 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.Avahi'
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully called chroot().
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully dropped remaining capabilities.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: No service file found in /etc/avahi/services.
Jul 09 21:23:24 raspberrypi rng-tools[320]: Starting Hardware RNG entropy gatherer daemon: rngd.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Network interface enumeration completed.
Jul 09 21:23:24 raspberrypi rngd[324]: rngd 2-unofficial-mt.14 starting up...
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 3208820741.
Jul 09 21:23:25 raspberrypi systemd[1]: Started triggerhappy global hotkey daemon.
Jul 09 21:23:25 raspberrypi systemd[1]: Started System Logging Service.
Jul 09 21:23:25 raspberrypi rngd[324]: entropy feed to the kernel ready
Jul 09 21:23:25 raspberrypi dbus-daemon[261]: [system] Activating systemd to hand-off: service name='org.freedesktop.ColorManager' unit='colord.service' requested by ':1.3' (uid=0 pid=259 comm="/usr/sbin/cupsd -l
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Timers.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on CUPS Scheduler.
Jul 09 21:23:21 raspberrypi systemd[1]: Listening on triggerhappy.socket.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Sockets.
Jul 09 21:23:21 raspberrypi systemd[1]: Reached target Basic System.
Jul 09 21:23:21 raspberrypi systemd[1]: Starting Configure Bluetooth Modems connected by UART...
Jul 09 21:23:22 raspberrypi systemd[1]: Started CUPS Scheduler.
Jul 09 21:23:22 raspberrypi systemd[1]: Reached target Printer.
Jul 09 21:23:22 raspberrypi systemd[1]: Started D-Bus System Message Bus.
Jul 09 21:23:22 raspberrypi systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Jul 09 21:23:22 raspberrypi systemd[1]: Started AirSane Imaging Service.
Jul 09 21:23:22 raspberrypi systemd[1]: Starting Check for Raspberry Pi EEPROM updates...
Jul 09 21:23:22 raspberrypi systemd[1]: Starting dphys-swapfile - set up, mount/unmount, and delete a swap file...
Jul 09 21:23:23 raspberrypi systemd[1]: Starting triggerhappy global hotkey daemon...
Jul 09 21:23:23 raspberrypi systemd[1]: Starting System Logging Service...
Jul 09 21:23:23 raspberrypi rpi-eeprom-update[281]: This tool only works with a Raspberry Pi 4
Jul 09 21:23:23 raspberrypi thd[286]: Found socket passed from systemd
Jul 09 21:23:23 raspberrypi systemd[1]: Started Regular background program processing daemon.
Jul 09 21:23:23 raspberrypi cron[300]: (CRON) INFO (pidfile fd = 3)
Jul 09 21:23:23 raspberrypi kernel: uart-pl011 20201000.serial: no DMA platform data
Jul 09 21:23:23 raspberrypi systemd[1]: Starting Login Service...
Jul 09 21:23:23 raspberrypi cron[300]: (CRON) INFO (Running @reboot jobs)
Jul 09 21:23:23 raspberrypi systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
Jul 09 21:23:24 raspberrypi rsyslogd[296]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.1901.0]
Jul 09 21:23:24 raspberrypi dbus-daemon[261]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.1' (uid=109 pid=279 comm="/us
Jul 09 21:23:24 raspberrypi rsyslogd[296]:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="296" x-info="https://www.rsyslog.com"] start
Jul 09 21:23:24 raspberrypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Jul 09 21:23:24 raspberrypi systemd[1]: Starting WPA supplicant...
Jul 09 21:23:24 raspberrypi systemd[1]: Condition check resulted in Turn on SSH if /boot/ssh is present being skipped.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting rng-tools.service...
Jul 09 21:23:24 raspberrypi systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Found user 'avahi' (UID 108) and group 'avahi' (GID 113).
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully dropped root privileges.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: avahi-daemon 0.7 starting up.
Jul 09 21:23:24 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.Avahi'
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully called chroot().
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully dropped remaining capabilities.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: No service file found in /etc/avahi/services.
Jul 09 21:23:24 raspberrypi rng-tools[320]: Starting Hardware RNG entropy gatherer daemon: rngd.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Network interface enumeration completed.
Jul 09 21:23:24 raspberrypi rngd[324]: rngd 2-unofficial-mt.14 starting up...
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 3208820741.
Jul 09 21:23:25 raspberrypi systemd[1]: Started triggerhappy global hotkey daemon.
Jul 09 21:23:25 raspberrypi systemd[1]: Started System Logging Service.
Jul 09 21:23:25 raspberrypi rngd[324]: entropy feed to the kernel ready
Jul 09 21:23:25 raspberrypi dbus-daemon[261]: [system] Activating systemd to hand-off: service name='org.freedesktop.ColorManager' unit='colord.service' requested by ':1.3' (uid=0 pid=259 comm="/usr/sbin/cupsd -l
Jul 09 21:23:25 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Jul 09 21:23:25 raspberrypi systemd[1]: Started Check for Raspberry Pi EEPROM updates.
Jul 09 21:23:25 raspberrypi systemd[1]: Started rng-tools.service.
Jul 09 21:23:25 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.systemd1'
Jul 09 21:23:26 raspberrypi dphys-swapfile[283]: want /var/swap=100MByte, checking existing: keeping it
Jul 09 21:23:26 raspberrypi systemd-logind[302]: New seat seat0.
Jul 09 21:23:26 raspberrypi dhcpcd[322]: dev: loaded udev
Jul 09 21:23:26 raspberrypi wpa_supplicant[314]: Successfully initialized wpa_supplicant
Jul 09 21:23:26 raspberrypi kernel: 8021q: 802.1Q VLAN Support v1.8
Jul 09 21:23:26 raspberrypi kernel: Adding 102396k swap on /var/swap.  Priority:-2 extents:2 across:307200k SSFS
Jul 09 21:23:27 raspberrypi raspi-config[271]: Checking if shift key is held down:Error opening '/dev/input/event*': No such file or directory
Jul 09 21:23:27 raspberrypi raspi-config[271]:  No. Switching to ondemand scaling governor.
Jul 09 21:23:27 raspberrypi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Jul 09 21:23:27 raspberrypi systemd[1]: Started dphys-swapfile - set up, mount/unmount, and delete a swap file.
Jul 09 21:23:27 raspberrypi systemd[1]: Started WPA supplicant.
Jul 09 21:23:27 raspberrypi systemd[1]: Started Login Service.
Jul 09 21:23:27 raspberrypi systemd[1]: Starting Manage, Install and Generate Color Profiles...
Jul 09 21:23:27 raspberrypi dhcpcd[322]: wlan0: starting wpa_supplicant
Jul 09 21:23:27 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Jul 09 21:23:27 raspberrypi dhcpcd-run-hooks[356]: wlan0: starting wpa_supplicant
Jul 09 21:23:27 raspberrypi systemd[1]: Started Make remote CUPS printers available locally.
Jul 09 21:23:28 raspberrypi kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
Jul 09 21:23:28 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.ColorManager'
Jul 09 21:23:28 raspberrypi systemd[1]: Started Manage, Install and Generate Color Profiles.
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: Core ver 2.22
Jul 09 21:23:28 raspberrypi kernel: NET: Registered protocol family 31
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI device and connection manager initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI socket layer initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: L2CAP socket layer initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: SCO socket layer initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART driver ver 2.3
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART protocol H4 registered
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART protocol Broadcom registered
Jul 09 21:23:28 raspberrypi btuart[258]: bcm43xx_init
Jul 09 21:23:28 raspberrypi btuart[258]: Flash firmware /lib/firmware/brcm/BCM43430A1.hcd
Jul 09 21:23:28 raspberrypi btuart[258]: Set BDADDR UART: b8:27:eb:8d:a2:90
Jul 09 21:23:28 raspberrypi btuart[258]: Set Controller UART speed to 3000000 bit/s
Jul 09 21:23:28 raspberrypi btuart[258]: Device setup complete
Jul 09 21:23:28 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
Jul 09 21:23:28 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Jul 09 21:23:29 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.
Jul 09 21:23:29 raspberrypi systemd[1]: Created slice system-bthelper.slice.
Jul 09 21:23:29 raspberrypi dhcpcd[322]: wlan0: connected to Access Point `'
Jul 09 21:23:29 raspberrypi systemd[1]: Starting Raspberry Pi bluetooth helper...
Jul 09 21:23:29 raspberrypi bthelper[371]: Raspberry Pi BDADDR already set
Jul 09 21:23:29 raspberrypi dhcpcd[322]: wlan0: waiting for carrier
Jul 09 21:23:29 raspberrypi systemd[1]: Started Raspberry Pi bluetooth helper.
Jul 09 21:23:30 raspberrypi systemd[1]: Starting Bluetooth service...
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Bluetooth daemon 5.50
Jul 09 21:23:30 raspberrypi systemd[1]: Started Bluetooth service.
Jul 09 21:23:30 raspberrypi systemd[1]: Reached target Bluetooth.
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Starting SDP server
Jul 09 21:23:30 raspberrypi kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Jul 09 21:23:30 raspberrypi kernel: Bluetooth: BNEP filters: protocol multicast
Jul 09 21:23:30 raspberrypi kernel: Bluetooth: BNEP socket layer initialized
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Bluetooth management interface 1.18 initialized
Jul 09 21:23:30 raspberrypi dbus-daemon[261]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.9' (uid=0 pid=387 comm="/usr/
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Sap driver initialization failed.
Jul 09 21:23:30 raspberrypi bluetoothd[387]: sap-server: Operation not permitted (1)
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Failed to set privacy: Rejected (0x0b)
Jul 09 21:23:30 raspberrypi systemd[1]: Starting Hostname Service...
Jul 09 21:23:30 raspberrypi dhcpcd[322]: wlan0: carrier acquired
Jul 09 21:23:30 raspberrypi kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jul 09 21:23:30 raspberrypi dhcpcd[322]: wlan0: connected to Access Point `Um die Ecke'
Jul 09 21:23:31 raspberrypi dhcpcd[322]: DUID 00:01:00:01:26:d1:11:70:b8:27:eb:72:5d:6f
Jul 09 21:23:31 raspberrypi dhcpcd[322]: wlan0: IAID eb:72:5d:6f
Jul 09 21:23:31 raspberrypi dhcpcd[322]: wlan0: adding address fe80::d584:b3db:5b2a:9246
Jul 09 21:23:31 raspberrypi avahi-daemon[309]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::d584:b3db:5b2a:9246.
Jul 09 21:23:31 raspberrypi avahi-daemon[309]: New relevant interface wlan0.IPv6 for mDNS.
Jul 09 21:23:31 raspberrypi avahi-daemon[309]: Registering new address record for fe80::d584:b3db:5b2a:9246 on wlan0.*.
Jul 09 21:23:31 raspberrypi dhcpcd[322]: wlan0: soliciting an IPv6 router
Jul 09 21:23:31 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jul 09 21:23:31 raspberrypi systemd[1]: Started Hostname Service.
Jul 09 21:23:32 raspberrypi dhcpcd[322]: wlan0: rebinding lease of 192.168.178.39
Jul 09 21:23:32 raspberrypi dhcpcd[322]: wlan0: probing address 192.168.178.39/24
Jul 09 21:23:33 raspberrypi colord[355]: failed to get session [pid 259]: No data available
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: Router Advertisement from fe80::464e:6dff:fe41:436e
Jul 09 21:23:33 raspberrypi kernel: ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: adding address 2a01:c22:b0e2:6300:2f:94cd:7719:412/64
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::d584:b3db:5b2a:9246.
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2a01:c22:b0e2:6300:2f:94cd:7719:412.
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Registering new address record for 2a01:c22:b0e2:6300:2f:94cd:7719:412 on wlan0.*.
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Withdrawing address record for fe80::d584:b3db:5b2a:9246 on wlan0.
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: adding route to 2a01:c22:b0e2:6300::/64
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: requesting DHCPv6 information
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: adding default route via fe80::464e:6dff:fe41:436e
Jul 09 21:23:33 raspberrypi colord[355]: failed to get session [pid 259]: No data available
Jul 09 21:23:34 raspberrypi colord-sane[391]: [bjnp] create_broadcast_socket: ERROR - bind socket to local address failed - Cannot assign requested address
Jul 09 21:23:34 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Jul 09 21:23:34 raspberrypi airsaned[279]: server finished with error status -1, last error was 99: Cannot assign requested address
Jul 09 21:23:34 raspberrypi systemd[1]: airsaned.service: Main process exited, code=exited, status=255/EXCEPTION
Jul 09 21:23:34 raspberrypi systemd[1]: airsaned.service: Failed with result 'exit-code'.
Jul 09 21:23:34 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 21:23:34 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 21:23:35 raspberrypi bthelper[371]: Changing power off succeeded
Jul 09 21:23:36 raspberrypi dhcpcd[322]: wlan0: leased 192.168.178.39 for 864000 seconds
Jul 09 21:23:42 raspberrypi avahi-daemon[309]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.39.
Jul 09 21:23:42 raspberrypi dhcpcd[322]: wlan0: adding route to 192.168.178.0/24
Jul 09 21:23:42 raspberrypi avahi-daemon[309]: New relevant interface wlan0.IPv4 for mDNS.
Jul 09 21:23:42 raspberrypi avahi-daemon[309]: Registering new address record for 192.168.178.39 on wlan0.IPv4.
Jul 09 21:23:42 raspberrypi dhcpcd[322]: wlan0: adding default route via 192.168.178.1
Jul 09 21:23:48 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Jul 09 22:06:54 raspberrypi systemd-timesyncd[223]: Synchronized to time server for the first time [2a01:4f8:242:56ca::2]:123 (2.debian.pool.ntp.org).
Jul 09 22:06:55 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 22:06:55 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 22:06:55 raspberrypi dhcpcd[322]: forked to background, child pid 508
Jul 09 22:06:55 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Jul 09 22:06:55 raspberrypi systemd[1]: Reached target Network.
Jul 09 22:06:55 raspberrypi systemd[1]: Starting Permit User Sessions...
Jul 09 22:06:55 raspberrypi systemd[1]: Started VNC Server in Service Mode daemon.
Jul 09 22:06:55 raspberrypi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Jul 09 22:06:56 raspberrypi dhcpcd[508]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 22:06:56 raspberrypi dhcpcd[508]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 22:06:56 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Jul 09 22:06:56 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Jul 09 22:06:57 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Jul 09 22:06:57 raspberrypi bthelper[371]: Changing power on succeeded
Jul 09 22:06:57 raspberrypi systemd[1]: Started Permit User Sessions.
Jul 09 22:06:57 raspberrypi systemd[1]: Started Getty on tty1.
Jul 09 22:06:56 raspberrypi dhcpcd[508]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 22:06:56 raspberrypi dhcpcd[508]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 22:06:56 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Jul 09 22:06:56 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Jul 09 22:06:57 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Jul 09 22:06:57 raspberrypi bthelper[371]: Changing power on succeeded
Jul 09 22:06:57 raspberrypi systemd[1]: Started Permit User Sessions.
Jul 09 22:06:57 raspberrypi systemd[1]: Started Getty on tty1.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting WPA supplicant...
Jul 09 21:23:24 raspberrypi systemd[1]: Condition check resulted in Turn on SSH if /boot/ssh is present being skipped.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting rng-tools.service...
Jul 09 21:23:24 raspberrypi systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Found user 'avahi' (UID 108) and group 'avahi' (GID 113).
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully dropped root privileges.
Jul 09 21:23:24 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: avahi-daemon 0.7 starting up.
Jul 09 21:23:24 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.Avahi'
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully called chroot().
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Successfully dropped remaining capabilities.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: No service file found in /etc/avahi/services.
Jul 09 21:23:24 raspberrypi rng-tools[320]: Starting Hardware RNG entropy gatherer daemon: rngd.
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Network interface enumeration completed.
Jul 09 21:23:24 raspberrypi rngd[324]: rngd 2-unofficial-mt.14 starting up...
Jul 09 21:23:24 raspberrypi avahi-daemon[309]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 3208820741.
Jul 09 21:23:25 raspberrypi systemd[1]: Started triggerhappy global hotkey daemon.
Jul 09 21:23:25 raspberrypi systemd[1]: Started System Logging Service.
Jul 09 21:23:25 raspberrypi rngd[324]: entropy feed to the kernel ready
Jul 09 21:23:25 raspberrypi dbus-daemon[261]: [system] Activating systemd to hand-off: service name='org.freedesktop.ColorManager' unit='colord.service' requested by ':1.3' (uid=0 pid=259 comm="/usr/sbin/cupsd -l
Jul 09 21:23:25 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Jul 09 21:23:25 raspberrypi systemd[1]: Started Check for Raspberry Pi EEPROM updates.
Jul 09 21:23:25 raspberrypi systemd[1]: Started rng-tools.service.
Jul 09 21:23:25 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.systemd1'
Jul 09 21:23:26 raspberrypi dphys-swapfile[283]: want /var/swap=100MByte, checking existing: keeping it
Jul 09 21:23:26 raspberrypi systemd-logind[302]: New seat seat0.
Jul 09 21:23:26 raspberrypi dhcpcd[322]: dev: loaded udev
Jul 09 21:23:26 raspberrypi wpa_supplicant[314]: Successfully initialized wpa_supplicant
Jul 09 21:23:26 raspberrypi kernel: 8021q: 802.1Q VLAN Support v1.8
Jul 09 21:23:26 raspberrypi kernel: Adding 102396k swap on /var/swap.  Priority:-2 extents:2 across:307200k SSFS
Jul 09 21:23:27 raspberrypi raspi-config[271]: Checking if shift key is held down:Error opening '/dev/input/event*': No such file or directory
Jul 09 21:23:27 raspberrypi raspi-config[271]:  No. Switching to ondemand scaling governor.
Jul 09 21:23:27 raspberrypi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Jul 09 21:23:27 raspberrypi systemd[1]: Started dphys-swapfile - set up, mount/unmount, and delete a swap file.
Jul 09 21:23:27 raspberrypi systemd[1]: Started WPA supplicant.
Jul 09 21:23:27 raspberrypi systemd[1]: Started Login Service.
Jul 09 21:23:27 raspberrypi systemd[1]: Starting Manage, Install and Generate Color Profiles...
Jul 09 21:23:27 raspberrypi dhcpcd[322]: wlan0: starting wpa_supplicant
Jul 09 21:23:27 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Jul 09 21:23:27 raspberrypi dhcpcd-run-hooks[356]: wlan0: starting wpa_supplicant
Jul 09 21:23:27 raspberrypi systemd[1]: Started Make remote CUPS printers available locally.
Jul 09 21:23:28 raspberrypi kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
Jul 09 21:23:28 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.ColorManager'
Jul 09 21:23:28 raspberrypi systemd[1]: Started Manage, Install and Generate Color Profiles.
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: Core ver 2.22
Jul 09 21:23:28 raspberrypi kernel: NET: Registered protocol family 31
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI device and connection manager initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI socket layer initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: L2CAP socket layer initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: SCO socket layer initialized
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART driver ver 2.3
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART protocol H4 registered
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered
Jul 09 21:23:28 raspberrypi kernel: Bluetooth: HCI UART protocol Broadcom registered
Jul 09 21:23:28 raspberrypi btuart[258]: bcm43xx_init
Jul 09 21:23:28 raspberrypi btuart[258]: Flash firmware /lib/firmware/brcm/BCM43430A1.hcd
Jul 09 21:23:28 raspberrypi btuart[258]: Set BDADDR UART: b8:27:eb:8d:a2:90
Jul 09 21:23:28 raspberrypi btuart[258]: Set Controller UART speed to 3000000 bit/s
Jul 09 21:23:28 raspberrypi btuart[258]: Device setup complete
Jul 09 21:23:28 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
Jul 09 21:23:28 raspberrypi systemd[1]: Starting Load/Save RF Kill Switch Status...
Jul 09 21:23:29 raspberrypi systemd[1]: Started Load/Save RF Kill Switch Status.
Jul 09 21:23:29 raspberrypi systemd[1]: Created slice system-bthelper.slice.
Jul 09 21:23:29 raspberrypi dhcpcd[322]: wlan0: connected to Access Point `'
Jul 09 21:23:29 raspberrypi systemd[1]: Starting Raspberry Pi bluetooth helper...
Jul 09 21:23:29 raspberrypi bthelper[371]: Raspberry Pi BDADDR already set
Jul 09 21:23:29 raspberrypi dhcpcd[322]: wlan0: waiting for carrier
Jul 09 21:23:29 raspberrypi systemd[1]: Started Raspberry Pi bluetooth helper.
Jul 09 21:23:30 raspberrypi systemd[1]: Starting Bluetooth service...
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Bluetooth daemon 5.50
Jul 09 21:23:30 raspberrypi systemd[1]: Started Bluetooth service.
Jul 09 21:23:30 raspberrypi systemd[1]: Reached target Bluetooth.
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Starting SDP server
Jul 09 21:23:30 raspberrypi kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Jul 09 21:23:30 raspberrypi kernel: Bluetooth: BNEP filters: protocol multicast
Jul 09 21:23:30 raspberrypi kernel: Bluetooth: BNEP socket layer initialized
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Bluetooth management interface 1.18 initialized
Jul 09 21:23:30 raspberrypi dbus-daemon[261]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.9' (uid=0 pid=387 comm="/usr/
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Sap driver initialization failed.
Jul 09 21:23:30 raspberrypi bluetoothd[387]: sap-server: Operation not permitted (1)
Jul 09 21:23:30 raspberrypi bluetoothd[387]: Failed to set privacy: Rejected (0x0b)
Jul 09 21:23:30 raspberrypi systemd[1]: Starting Hostname Service...
Jul 09 21:23:30 raspberrypi dhcpcd[322]: wlan0: carrier acquired
Jul 09 21:23:30 raspberrypi kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jul 09 21:23:30 raspberrypi dhcpcd[322]: wlan0: connected to Access Point `Um die Ecke'
Jul 09 21:23:31 raspberrypi dhcpcd[322]: DUID 00:01:00:01:26:d1:11:70:b8:27:eb:72:5d:6f
Jul 09 21:23:31 raspberrypi dhcpcd[322]: wlan0: IAID eb:72:5d:6f
Jul 09 21:23:31 raspberrypi dhcpcd[322]: wlan0: adding address fe80::d584:b3db:5b2a:9246
Jul 09 21:23:31 raspberrypi avahi-daemon[309]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::d584:b3db:5b2a:9246.
Jul 09 21:23:31 raspberrypi avahi-daemon[309]: New relevant interface wlan0.IPv6 for mDNS.
Jul 09 21:23:31 raspberrypi avahi-daemon[309]: Registering new address record for fe80::d584:b3db:5b2a:9246 on wlan0.*.
Jul 09 21:23:31 raspberrypi dhcpcd[322]: wlan0: soliciting an IPv6 router
Jul 09 21:23:31 raspberrypi dbus-daemon[261]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jul 09 21:23:31 raspberrypi systemd[1]: Started Hostname Service.
Jul 09 21:23:32 raspberrypi dhcpcd[322]: wlan0: rebinding lease of 192.168.178.39
Jul 09 21:23:32 raspberrypi dhcpcd[322]: wlan0: probing address 192.168.178.39/24
Jul 09 21:23:33 raspberrypi colord[355]: failed to get session [pid 259]: No data available
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: Router Advertisement from fe80::464e:6dff:fe41:436e
Jul 09 21:23:33 raspberrypi kernel: ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: adding address 2a01:c22:b0e2:6300:2f:94cd:7719:412/64
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::d584:b3db:5b2a:9246.
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2a01:c22:b0e2:6300:2f:94cd:7719:412.
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Registering new address record for 2a01:c22:b0e2:6300:2f:94cd:7719:412 on wlan0.*.
Jul 09 21:23:33 raspberrypi avahi-daemon[309]: Withdrawing address record for fe80::d584:b3db:5b2a:9246 on wlan0.
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: adding route to 2a01:c22:b0e2:6300::/64
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: requesting DHCPv6 information
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 21:23:33 raspberrypi dhcpcd[322]: wlan0: adding default route via fe80::464e:6dff:fe41:436e
Jul 09 21:23:33 raspberrypi colord[355]: failed to get session [pid 259]: No data available
Jul 09 21:23:34 raspberrypi colord-sane[391]: [bjnp] create_broadcast_socket: ERROR - bind socket to local address failed - Cannot assign requested address
Jul 09 21:23:34 raspberrypi systemd[1]: systemd-rfkill.service: Succeeded.
Jul 09 21:23:34 raspberrypi airsaned[279]: server finished with error status -1, last error was 99: Cannot assign requested address
Jul 09 21:23:34 raspberrypi systemd[1]: airsaned.service: Main process exited, code=exited, status=255/EXCEPTION
Jul 09 21:23:34 raspberrypi systemd[1]: airsaned.service: Failed with result 'exit-code'.
Jul 09 21:23:34 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 21:23:34 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 21:23:35 raspberrypi bthelper[371]: Changing power off succeeded
Jul 09 21:23:36 raspberrypi dhcpcd[322]: wlan0: leased 192.168.178.39 for 864000 seconds
Jul 09 21:23:42 raspberrypi avahi-daemon[309]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.39.
Jul 09 21:23:42 raspberrypi dhcpcd[322]: wlan0: adding route to 192.168.178.0/24
Jul 09 21:23:42 raspberrypi avahi-daemon[309]: New relevant interface wlan0.IPv4 for mDNS.
Jul 09 21:23:42 raspberrypi avahi-daemon[309]: Registering new address record for 192.168.178.39 on wlan0.IPv4.
Jul 09 21:23:42 raspberrypi dhcpcd[322]: wlan0: adding default route via 192.168.178.1
Jul 09 21:23:48 raspberrypi systemd[1]: systemd-fsckd.service: Succeeded.
Jul 09 22:06:54 raspberrypi systemd-timesyncd[223]: Synchronized to time server for the first time [2a01:4f8:242:56ca::2]:123 (2.debian.pool.ntp.org).
Jul 09 22:06:55 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 22:06:55 raspberrypi dhcpcd[322]: Too few arguments.
Jul 09 22:06:55 raspberrypi dhcpcd[322]: forked to background, child pid 508
Jul 09 22:06:55 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Jul 09 22:06:55 raspberrypi systemd[1]: Reached target Network.
Jul 09 22:06:55 raspberrypi systemd[1]: Starting Permit User Sessions...
Jul 09 22:06:55 raspberrypi systemd[1]: Started VNC Server in Service Mode daemon.
Jul 09 22:06:55 raspberrypi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Jul 09 22:06:56 raspberrypi dhcpcd[508]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 22:06:56 raspberrypi dhcpcd[508]: wlan0: fe80::464e:6dff:fe41:436e is reachable again
Jul 09 22:06:56 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server...
Jul 09 22:06:56 raspberrypi systemd[1]: Starting /etc/rc.local Compatibility...
Jul 09 22:06:57 raspberrypi systemd[1]: Started /etc/rc.local Compatibility.
Jul 09 22:06:57 raspberrypi bthelper[371]: Changing power on succeeded
Jul 09 22:06:57 raspberrypi systemd[1]: Started Permit User Sessions.
Jul 09 22:06:57 raspberrypi systemd[1]: Started Getty on tty1.
Jul 09 22:06:57 raspberrypi systemd[1]: Reached target Login Prompts.
Jul 09 22:06:57 raspberrypi sshd[570]: Server listening on 0.0.0.0 port 22.
Jul 09 22:06:57 raspberrypi sshd[570]: Server listening on :: port 22.
Jul 09 22:06:57 raspberrypi systemd[1]: Started OpenBSD Secure Shell server.
Jul 09 22:06:57 raspberrypi systemd[1]: Reached target Multi-User System.
Jul 09 22:06:57 raspberrypi systemd[1]: Reached target Graphical Interface.
Jul 09 22:06:57 raspberrypi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Jul 09 22:06:58 raspberrypi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Jul 09 22:06:58 raspberrypi systemd[1]: Started Update UTMP about System Runlevel Changes.
Jul 09 22:06:58 raspberrypi systemd[1]: Startup finished in 27.339s (kernel) + 59.178s (userspace) = 1min 26.518s.
Jul 09 22:07:04 raspberrypi systemd[1]: systemd-hostnamed.service: Succeeded.
Jul 09 22:07:06 raspberrypi vncserver-x11[566]: ServerManager: Server started
Jul 09 22:07:06 raspberrypi colord[355]: failed to get session [pid 259]: No data available
Jul 09 22:07:07 raspberrypi vncserver-x11[566]: ConsoleDisplay: Cannot find a running X server on vt1
Jul 09 22:07:17 raspberrypi colord[355]: failed to get session [pid 259]: No data available
Jul 09 22:07:48 raspberrypi sshd[583]: ssh_dispatch_run_fatal: Connection from 192.168.178.29 port 55790: Broken pipe [preauth]
Jul 09 22:07:56 raspberrypi sshd[584]: Accepted password for pi from 192.168.178.29 port 55795 ssh2
Jul 09 22:07:56 raspberrypi sshd[584]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Jul 09 22:07:56 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Jul 09 22:07:56 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Jul 09 22:07:56 raspberrypi systemd-logind[302]: New session 1 of user pi.
Jul 09 22:07:56 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Jul 09 22:07:56 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Jul 09 22:07:56 raspberrypi systemd[589]: pam_unix(systemd-user:session): session opened for user pi by (uid=0)
Jul 09 22:07:57 raspberrypi systemd[589]: Listening on GnuPG network certificate management daemon.
Jul 09 22:07:57 raspberrypi systemd[589]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jul 09 22:07:57 raspberrypi systemd[589]: Reached target Paths.
Jul 09 22:07:57 raspberrypi systemd[589]: Listening on GnuPG cryptographic agent and passphrase cache.
Jul 09 22:07:57 raspberrypi systemd[589]: Reached target Timers.
Jul 09 22:07:57 raspberrypi systemd[589]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jul 09 22:07:57 raspberrypi systemd[589]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jul 09 22:07:57 raspberrypi systemd[589]: Starting D-Bus User Message Bus Socket.
Jul 09 22:07:57 raspberrypi systemd[589]: Listening on D-Bus User Message Bus Socket.
Jul 09 22:07:57 raspberrypi systemd[589]: Reached target Sockets.
Jul 09 22:07:57 raspberrypi systemd[589]: Reached target Basic System.
Jul 09 22:07:57 raspberrypi systemd[1]: Started User Manager for UID 1000.
Jul 09 22:07:57 raspberrypi systemd[589]: Reached target Default.
Jul 09 22:07:57 raspberrypi systemd[589]: Startup finished in 800ms.
Jul 09 22:07:57 raspberrypi systemd[1]: Started Session 1 of user pi.
Jul 09 22:08:00 raspberrypi sudo[618]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/systemctl status airsaned
Jul 09 22:08:00 raspberrypi sudo[618]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Jul 09 22:08:04 raspberrypi sudo[618]: pam_unix(sudo:session): session closed for user root
Jul 09 22:08:27 raspberrypi sudo[669]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl
Jul 09 22:08:27 raspberrypi sudo[669]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Jul 09 22:09:33 raspberrypi sudo[669]: pam_unix(sudo:session): session closed for user root
Jul 09 22:09:35 raspberrypi sudo[672]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl
Jul 09 22:09:35 raspberrypi sudo[672]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
lines 518-564/564 (END)
SimulPiscator commented 3 years ago

Thanks for the full log. It seems that avahi-daemon needs to be listed as a dependency. I added a line to the systemd unit file. Let me know whether it works for you now.

hiatsu0 commented 3 years ago

Can confirm that changing the line After=avahi-daemon.service in airsaned.service, while removing the earlier remedy ExecStartPre=/bin/sleep 15 seems to do the trick for me!

I can still see some error in create_broadcast_socket but regardless of that everything still works:

$ systemctl status airsaned.service
● airsaned.service - AirSane Imaging Service
   Loaded: loaded (/lib/systemd/system/airsaned.service; enabled; vendor preset: enabled)
   Active: active (running) since Sat 2021-07-10 17:18:36 BST; 1min 31s ago
 Main PID: 450 (airsaned)
    Tasks: 5 (limit: 2062)
   CGroup: /system.slice/airsaned.service
           └─450 /usr/local/bin/airsaned --interface=* --base-port=8090 --access-log= --hotplug=true --mdns-announce=true --local-scanners-only=true --opti

Jul 10 17:18:36 raspi3 systemd[1]: Started AirSane Imaging Service.
Jul 10 17:18:36 raspi3 airsaned[450]: [bjnp] create_broadcast_socket: ERROR - bind socket to local address failed - Cannot assign requested address
SimulPiscator commented 3 years ago

Thanks for the report. Regarding the "[bnjp] ..." error message, I think it will go away if you comment out unneeded drivers in /etc/sane.d/dll.conf.