MarkDH102
Posts: 329
Joined: Fri Feb 13, 2015 3:18 pm

Why does my RealVNC start so late after boot up

Tue Mar 19, 2019 7:29 am

Here is my syslog from boot up to when RealVNC starts up.
Obviously, I can't VNC in to my Pi until the service starts...
To my untrained eye, I can't see anything untoward. Maybe the entries prior to reboot give a clue to somebody?
Stretch - completely up to date, Pi0W.


Mar 18 16:41:51 scraper vncserver-x11[342,root]: Connections: disconnected: 192.168.0.153::34520 (TCP) ([System-104] read: Connection reset by peer (104))
Mar 18 16:43:14 scraper vncserver-x11[342,root]: Connections: connected: 192.168.0.145::57573 (TCP)
Mar 18 16:43:14 scraper vncserver-x11[342,root]: Connections: authenticated: 192.168.0.145::57573 (TCP), as pi (f permissions)
Mar 18 16:43:16 scraper vncserver-x11[342,root]: SPrintConnMgr: Failed to add printer: server-error-service-unavailable
Mar 18 16:45:34 scraper systemd[1]: Starting status led startup update...
Mar 18 16:45:34 scraper systemd[1]: Removed slice system-bthelper.slice.
Mar 18 16:45:34 scraper systemd[1]: Stopping Disk Manager...
Mar 18 16:45:34 scraper systemd[1]: Stopped target Timers.
Mar 18 16:45:34 scraper systemd[1]: Stopping BluezALSA proxy...
Mar 18 16:45:34 scraper systemd[1]: Unmounting RPC Pipe File System...
Mar 18 16:45:34 scraper udisksd[797]: udisks daemon version 2.1.8 exiting
Mar 18 16:45:34 scraper systemd[1]: Stopping User Manager for UID 1000...
Mar 18 16:45:34 scraper systemd[1]: Stopped target Graphical Interface.
Mar 18 16:45:34 scraper systemd[1]: Stopped target Multi-User System.
Mar 18 16:45:34 scraper systemd[1]: Stopped Check for v3d driver.
Mar 18 16:45:48 scraper kernel: [ 0.000000] Booting Linux on physical CPU 0x0
Mar 18 16:45:48 scraper kernel: [ 0.000000] Linux version 4.14.98+ ([email protected]) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1200 Tue Feb 12 20:11:02 GMT 2019
Mar 18 16:45:48 scraper kernel: [ 0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Mar 18 16:45:48 scraper kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Mar 18 16:45:48 scraper kernel: [ 0.000000] OF: fdt: Machine model: Raspberry Pi Zero W Rev 1.1
Mar 18 16:45:48 scraper kernel: [ 0.000000] Memory policy: Data cache writeback
Mar 18 16:45:48 scraper kernel: [ 0.000000] cma: Reserved 8 MiB at 0x17400000
Mar 18 16:45:48 scraper kernel: [ 0.000000] On node 0 totalpages: 98304
Mar 18 16:45:48 scraper kernel: [ 0.000000] free_area_init_node: node 0, pgdat c09caaf0, node_mem_map d7c8a100
Mar 18 16:45:48 scraper kernel: [ 0.000000] Normal zone: 864 pages used for memmap
Mar 18 16:45:48 scraper kernel: [ 0.000000] Normal zone: 0 pages reserved
Mar 18 16:45:48 scraper kernel: [ 0.000000] Normal zone: 98304 pages, LIFO batch:31
Mar 18 16:45:48 scraper kernel: [ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Mar 18 16:45:48 scraper kernel: [ 0.000000] pcpu-alloc: [0] 0
Mar 18 16:45:48 scraper kernel: [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 97440
Mar 18 16:45:48 scraper kernel: [ 0.000000] Kernel command line: 8250.nr_uarts=0 bcm2708_fb.fbwidth=1360 bcm2708_fb.fbheight=768 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:9D:09:15 vc_mem.mem_base=0x1ec00000 vc_mem.mem_size=0x20000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=c8e3b7d3-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
Mar 18 16:45:48 scraper kernel: [ 0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.000000] Memory: 370248K/393216K available (6451K kernel code, 589K rwdata, 1992K rodata, 440K init, 673K bss, 14776K reserved, 8192K cma-reserved)
Mar 18 16:45:48 scraper kernel: [ 0.000000] Virtual kernel memory layout:
Mar 18 16:45:48 scraper kernel: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] vmalloc : 0xd8800000 - 0xff800000 ( 624 MB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] lowmem : 0xc0000000 - 0xd8000000 ( 384 MB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] modules : 0xbf000000 - 0xc0000000 ( 16 MB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] .text : 0xc0008000 - 0xc0655050 (6453 kB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] .init : 0xc08d4000 - 0xc0942000 ( 440 kB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] .data : 0xc0942000 - 0xc09d54f8 ( 590 kB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] .bss : 0xc09dadf0 - 0xc0a8338c ( 674 kB)
Mar 18 16:45:48 scraper kernel: [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Mar 18 16:45:48 scraper kernel: [ 0.000000] ftrace: allocating 24128 entries in 71 pages
Mar 18 16:45:48 scraper kernel: [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
Mar 18 16:45:48 scraper kernel: [ 0.000030] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
Mar 18 16:45:48 scraper kernel: [ 0.000073] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
Mar 18 16:45:48 scraper kernel: [ 0.000165] bcm2835: system timer (irq = 27)
Mar 18 16:45:48 scraper kernel: [ 0.000743] Console: colour dummy device 80x30
Mar 18 16:45:48 scraper kernel: [ 0.001342] console [tty1] enabled
Mar 18 16:45:48 scraper kernel: [ 0.001395] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Mar 18 16:45:48 scraper kernel: [ 0.060335] pid_max: default: 32768 minimum: 301
Mar 18 16:45:48 scraper kernel: [ 0.060854] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.060910] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.062245] Disabling memory control group subsystem
Mar 18 16:45:48 scraper kernel: [ 0.062463] CPU: Testing write buffer coherency: ok
Mar 18 16:45:48 scraper kernel: [ 0.063653] Setting up static identity map for 0x8200 - 0x8238
Mar 18 16:45:48 scraper kernel: [ 0.064948] devtmpfs: initialized
Mar 18 16:45:48 scraper kernel: [ 0.074478] random: get_random_u32 called from bucket_table_alloc+0x88/0x1c4 with crng_init=0
Mar 18 16:45:48 scraper kernel: [ 0.075400] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Mar 18 16:45:48 scraper kernel: [ 0.075835] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
Mar 18 16:45:48 scraper kernel: [ 0.075907] futex hash table entries: 256 (order: -1, 3072 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.077252] pinctrl core: initialized pinctrl subsystem
Mar 18 16:45:48 scraper kernel: [ 0.078681] NET: Registered protocol family 16
Mar 18 16:45:48 scraper kernel: [ 0.081654] DMA: preallocated 1024 KiB pool for atomic coherent allocations
Mar 18 16:45:48 scraper kernel: [ 0.088181] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Mar 18 16:45:48 scraper kernel: [ 0.088256] hw-breakpoint: maximum watchpoint size is 4 bytes.
Mar 18 16:45:48 scraper kernel: [ 0.088403] Serial: AMBA PL011 UART driver
Mar 18 16:45:48 scraper kernel: [ 0.091372] bcm2835-mbox 2000b880.mailbox: mailbox enabled
Mar 18 16:45:48 scraper kernel: [ 0.092161] uart-pl011 20201000.serial: could not find pctldev for node /soc/[email protected]/uart0_pins, deferring probe
Mar 18 16:45:48 scraper kernel: [ 0.131335] bcm2835-dma 20007000.dma: DMA legacy API manager at d880d000, dmachans=0x1
Mar 18 16:45:48 scraper kernel: [ 0.133684] SCSI subsystem initialized
Mar 18 16:45:48 scraper kernel: [ 0.133973] usbcore: registered new interface driver usbfs
Mar 18 16:45:48 scraper systemd-modules-load[60]: Inserted module 'i2c_dev'
Mar 18 16:45:48 scraper fake-hwclock[82]: Mon 18 Mar 16:45:39 UTC 2019
Mar 18 16:45:48 scraper systemd[1]: Mounted Configuration File System.
Mar 18 16:45:48 scraper systemd-fsck[91]: e2fsck 1.43.4 (31-Jan-2017)
Mar 18 16:45:48 scraper systemd[1]: Started Create Static Device Nodes in /dev.
Mar 18 16:45:48 scraper systemd[1]: Started Apply Kernel Variables.
Mar 18 16:45:48 scraper systemd[1]: Started File System Check Daemon to report status.
Mar 18 16:45:48 scraper systemd-fsck[91]: /dev/mmcblk0p2: clean, 130510/971040 files, 1159471/3877760 blocks
Mar 18 16:45:48 scraper systemd[1]: Starting udev Kernel Device Manager...
Mar 18 16:45:48 scraper systemd[1]: Started File System Check on Root Device.
Mar 18 16:45:48 scraper systemd[1]: Starting Remount Root and Kernel File Systems...
Mar 18 16:45:48 scraper systemd[1]: Started Set the console keyboard layout.
Mar 18 16:45:48 scraper systemd[1]: Started Remount Root and Kernel File Systems.
Mar 18 16:45:48 scraper systemd[1]: Starting Load/Save Random Seed...
Mar 18 16:45:48 scraper systemd[1]: Starting udev Coldplug all Devices...
Mar 18 16:45:48 scraper systemd[1]: Starting Flush Journal to Persistent Storage...
Mar 18 16:45:48 scraper systemd[1]: Reached target Local File Systems (Pre).
Mar 18 16:45:48 scraper systemd[1]: Started udev Kernel Device Manager.
Mar 18 16:45:48 scraper systemd[1]: Started Load/Save Random Seed.
Mar 18 16:45:48 scraper systemd[1]: Started Flush Journal to Persistent Storage.
Mar 18 16:45:48 scraper systemd[1]: Started udev Coldplug all Devices.
Mar 18 16:45:48 scraper systemd[1]: Starting Show Plymouth Boot Screen...
Mar 18 16:45:48 scraper systemd[1]: Received SIGRTMIN+20 from PID 128 (plymouthd).
Mar 18 16:45:48 scraper systemd[1]: Started Show Plymouth Boot Screen.
Mar 18 16:45:48 scraper systemd[1]: Reached target Paths.
Mar 18 16:45:48 scraper systemd[1]: Reached target Encrypted Volumes.
Mar 18 16:45:48 scraper systemd[1]: Started Forward Password Requests to Plymouth Directory Watch.
Mar 18 16:45:48 scraper systemd[1]: Found device /dev/serial1.
Mar 18 16:45:48 scraper systemd[1]: Found device /dev/disk/by-partuuid/c8e3b7d3-01.
Mar 18 16:45:48 scraper systemd[1]: Starting File System Check on /dev/disk/by-partuuid/c8e3b7d3-01...
Mar 18 16:45:48 scraper systemd-fsck[146]: fsck.fat 4.1 (2017-01-24)
Mar 18 16:45:48 scraper systemd-fsck[146]: /dev/mmcblk0p1: 184 files, 11266/21354 clusters
Mar 18 16:45:48 scraper systemd[1]: Started File System Check on /dev/disk/by-partuuid/c8e3b7d3-01.
Mar 18 16:45:48 scraper systemd[1]: Mounting /boot...
Mar 18 16:45:48 scraper systemd[1]: Mounted /boot.
Mar 18 16:45:48 scraper systemd[1]: Reached target Local File Systems.
Mar 18 16:45:48 scraper systemd[1]: Starting Set console font and keymap...
Mar 18 16:45:48 scraper systemd[1]: Starting Create Volatile Files and Directories...
Mar 18 16:45:48 scraper systemd[1]: Starting Preprocess NFS configuration...
Mar 18 16:45:48 scraper systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
Mar 18 16:45:48 scraper systemd[1]: Starting Raise network interfaces...
Mar 18 16:45:48 scraper systemd[1]: Started Set console font and keymap.
Mar 18 16:45:48 scraper systemd[1]: Started Preprocess NFS configuration.
Mar 18 16:45:48 scraper systemd[1]: Started Tell Plymouth To Write Out Runtime Data.
Mar 18 16:45:48 scraper systemd[1]: Started Create Volatile Files and Directories.
Mar 18 16:45:48 scraper systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Mar 18 16:45:48 scraper systemd[1]: Starting Network Time Synchronization...
Mar 18 16:45:48 scraper systemd[1]: Reached target NFS client services.
Mar 18 16:45:48 scraper systemd[1]: Reached target Remote File Systems (Pre).
Mar 18 16:45:48 scraper systemd[1]: Reached target Remote File Systems.
Mar 18 16:45:48 scraper systemd[1]: Started Update UTMP about System Boot/Shutdown.
Mar 18 16:45:48 scraper systemd[1]: Started Network Time Synchronization.
Mar 18 16:45:48 scraper systemd[1]: Reached target System Time Synchronized.
Mar 18 16:45:48 scraper systemd[1]: Reached target System Initialization.
Mar 18 16:45:48 scraper systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Mar 18 16:45:48 scraper systemd[1]: Started status monitor service.
Mar 18 16:45:48 scraper systemd[1]: apt-daily.timer: Adding 8h 55min 54.320896s random time.
Mar 18 16:45:48 scraper systemd[1]: Started Daily apt download activities.
Mar 18 16:45:48 scraper systemd[1]: apt-daily-upgrade.timer: Adding 16min 58.814190s random time.
Mar 18 16:45:48 scraper systemd[1]: Started Daily apt upgrade and clean activities.
Mar 18 16:45:48 scraper systemd[1]: Started Daily Cleanup of Temporary Directories.
Mar 18 16:45:48 scraper systemd[1]: Reached target Timers.
Mar 18 16:45:48 scraper systemd[207]: status-monitor.service: Failed at step CHROOT spawning /usr/bin/python3: No such file or directory
Mar 18 16:45:48 scraper systemd[1]: Listening on D-Bus System Message Bus Socket.
Mar 18 16:45:48 scraper systemd[1]: Listening on triggerhappy.socket.
Mar 18 16:45:48 scraper systemd[1]: Reached target Sockets.
Mar 18 16:45:48 scraper systemd[1]: Reached target Basic System.
Mar 18 16:45:48 scraper systemd[1]: Starting Login Service...
Mar 18 16:45:48 scraper systemd[1]: Started uptime record daemon.
Mar 18 16:45:48 scraper systemd[1]: Starting System Logging Service...
Mar 18 16:45:48 scraper systemd[1]: Starting Check for v3d driver...
Mar 18 16:45:48 scraper systemd[1]: Starting Configure Bluetooth Modems connected by UART...
Mar 18 16:45:48 scraper systemd[1]: Starting Disable WiFi if country not set...
Mar 18 16:45:48 scraper systemd[1]: Started Regular background program processing daemon.
Mar 18 16:45:48 scraper liblogging-stdlog: [origin software="rsyslogd" swVersion="8.24.0" x-pid="213" x-info="http://www.rsyslog.com"] start
Mar 18 16:45:48 scraper kernel: [ 0.134113] usbcore: registered new interface driver hub
Mar 18 16:45:48 scraper kernel: [ 0.134350] usbcore: registered new device driver usb
Mar 18 16:45:48 scraper kernel: [ 0.140808] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-02-12 19:42
Mar 18 16:45:48 scraper kernel: [ 0.142854] clocksource: Switched to clocksource timer
Mar 18 16:45:48 scraper kernel: [ 0.228765] VFS: Disk quotas dquot_6.6.0
Mar 18 16:45:48 scraper kernel: [ 0.228944] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.229267] FS-Cache: Loaded
Mar 18 16:45:48 scraper kernel: [ 0.229627] CacheFiles: Loaded
Mar 18 16:45:48 scraper kernel: [ 0.246928] NET: Registered protocol family 2
Mar 18 16:45:48 scraper kernel: [ 0.248184] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.248316] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.248435] TCP: Hash tables configured (established 4096 bind 4096)
Mar 18 16:45:48 scraper kernel: [ 0.248616] UDP hash table entries: 256 (order: 0, 4096 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.248676] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Mar 18 16:45:48 scraper kernel: [ 0.249048] NET: Registered protocol family 1
Mar 18 16:45:48 scraper kernel: [ 0.249814] RPC: Registered named UNIX socket transport module.
Mar 18 16:45:48 scraper kernel: [ 0.249872] RPC: Registered udp transport module.
Mar 18 16:45:48 scraper kernel: [ 0.249898] RPC: Registered tcp transport module.
Mar 18 16:45:48 scraper kernel: [ 0.249923] RPC: Registered tcp NFSv4.1 backchannel transport module.
Mar 18 16:45:48 scraper kernel: [ 0.251830] hw perfevents: no irqs for PMU, sampling events not supported
Mar 18 16:45:48 scraper kernel: [ 0.251963] hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available
Mar 18 16:45:48 scraper kernel: [ 0.255818] workingset: timestamp_bits=14 max_order=17 bucket_order=3
Mar 18 16:45:48 scraper kernel: [ 0.268166] FS-Cache: Netfs 'nfs' registered for caching
Mar 18 16:45:48 scraper kernel: [ 0.269559] NFS: Registering the id_resolver key type
Mar 18 16:45:48 scraper kernel: [ 0.269652] Key type id_resolver registered
Mar 18 16:45:48 scraper kernel: [ 0.269684] Key type id_legacy registered
Mar 18 16:45:48 scraper kernel: [ 0.269733] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
Mar 18 16:45:48 scraper kernel: [ 0.274575] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
Mar 18 16:45:48 scraper kernel: [ 0.275067] io scheduler noop registered
Mar 18 16:45:48 scraper kernel: [ 0.275118] io scheduler deadline registered (default)
Mar 18 16:45:48 scraper kernel: [ 0.275672] io scheduler cfq registered
Mar 18 16:45:48 scraper kernel: [ 0.275719] io scheduler mq-deadline registered
Mar 18 16:45:48 scraper kernel: [ 0.275749] io scheduler kyber registered
Mar 18 16:45:48 scraper kernel: [ 0.278067] BCM2708FB: allocated DMA memory 57500000
Mar 18 16:45:48 scraper kernel: [ 0.278181] BCM2708FB: allocated DMA channel 0 @ d880d000
Mar 18 16:45:48 scraper kernel: [ 0.303587] Console: switching to colour frame buffer device 170x48
Mar 18 16:45:48 scraper kernel: [ 0.325734] bcm2835-rng 20104000.rng: hwrng registered
Mar 18 16:45:48 scraper kernel: [ 0.326199] vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
Mar 18 16:45:48 scraper kernel: [ 0.327573] vc-sm: Videocore shared memory driver
Mar 18 16:45:48 scraper kernel: [ 0.328450] gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000
Mar 18 16:45:48 scraper kernel: [ 0.348474] brd: module loaded
Mar 18 16:45:48 scraper kernel: [ 0.361413] loop: module loaded
Mar 18 16:45:48 scraper kernel: [ 0.361604] Loading iSCSI transport class v2.0-870.
Mar 18 16:45:48 scraper kernel: [ 0.362684] usbcore: registered new interface driver smsc95xx
Mar 18 16:45:48 scraper kernel: [ 0.363044] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Mar 18 16:45:48 scraper kernel: [ 0.391400] dwc_otg 20980000.usb: base=0xf0980000
Mar 18 16:45:48 scraper kernel: [ 0.591967] Core Release: 2.80a
Mar 18 16:45:48 scraper kernel: [ 0.592132] Setting default values for core params
Mar 18 16:45:48 scraper kernel: [ 0.592345] Finished setting default values for core params
Mar 18 16:45:48 scraper kernel: [ 0.798952] Using Buffer DMA mode
Mar 18 16:45:48 scraper kernel: [ 0.805103] Periodic Transfer Interrupt Enhancement - disabled
Mar 18 16:45:48 scraper kernel: [ 0.811175] Multiprocessor Interrupt Enhancement - disabled
Mar 18 16:45:48 scraper kernel: [ 0.817224] OTG VER PARAM: 0, OTG VER FLAG: 0
Mar 18 16:45:48 scraper kernel: [ 0.823361] Dedicated Tx FIFOs mode
Mar 18 16:45:48 scraper kernel: [ 0.830278] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xd7514000 dma = 0x57514000 len=9024
Mar 18 16:45:48 scraper kernel: [ 0.836686] FIQ FSM acceleration enabled for :
Mar 18 16:45:48 scraper kernel: [ 0.836686] Non-periodic Split Transactions
Mar 18 16:45:48 scraper kernel: [ 0.836686] Periodic Split Transactions
Mar 18 16:45:48 scraper kernel: [ 0.836686] High-Speed Isochronous Endpoints
Mar 18 16:45:48 scraper kernel: [ 0.836686] Interrupt/Control Split Transaction hack enabled
Mar 18 16:45:48 scraper kernel: [ 0.867331] dwc_otg: Microframe scheduler enabled
Mar 18 16:45:48 scraper kernel: [ 0.867614] WARN::hcd_init_fiq:459: FIQ on core 0 at 0xc04a00d0
Mar 18 16:45:48 scraper kernel: [ 0.873896] WARN::hcd_init_fiq:460: FIQ ASM at 0xc04a03ac length 36
Mar 18 16:45:48 scraper kernel: [ 0.879976] WARN::hcd_init_fiq:486: MPHI regs_base at 0xf0006000
Mar 18 16:45:48 scraper kernel: [ 0.886195] dwc_otg 20980000.usb: DWC OTG Controller
Mar 18 16:45:48 scraper kernel: [ 0.892347] dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1
Mar 18 16:45:48 scraper kernel: [ 0.898547] dwc_otg 20980000.usb: irq 56, io mem 0x00000000
Mar 18 16:45:48 scraper kernel: [ 0.904721] Init: Port Power? op_state=1
Mar 18 16:45:48 scraper kernel: [ 0.910800] Init: Power Port (0)
Mar 18 16:45:48 scraper kernel: [ 0.917233] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Mar 18 16:45:48 scraper kernel: [ 0.923427] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Mar 18 16:45:48 scraper kernel: [ 0.929409] usb usb1: Product: DWC OTG Controller
Mar 18 16:45:48 scraper kernel: [ 0.935408] usb usb1: Manufacturer: Linux 4.14.98+ dwc_otg_hcd
Mar 18 16:45:48 scraper kernel: [ 0.941441] usb usb1: SerialNumber: 20980000.usb
Mar 18 16:45:48 scraper kernel: [ 0.948676] hub 1-0:1.0: USB hub found
Mar 18 16:45:48 scraper kernel: [ 0.955012] hub 1-0:1.0: 1 port detected
Mar 18 16:45:48 scraper kernel: [ 0.962124] dwc_otg: FIQ enabled
Mar 18 16:45:48 scraper kernel: [ 0.962138] dwc_otg: NAK holdoff enabled
Mar 18 16:45:48 scraper kernel: [ 0.962144] dwc_otg: FIQ split-transaction FSM enabled
Mar 18 16:45:48 scraper kernel: [ 0.962164] Module dwc_common_port init
Mar 18 16:45:48 scraper kernel: [ 0.962684] usbcore: registered new interface driver usb-storage
Mar 18 16:45:48 scraper kernel: [ 0.969525] mousedev: PS/2 mouse device common for all mice
Mar 18 16:45:48 scraper kernel: [ 0.975901] IR NEC protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 0.981999] IR RC5(x/sz) protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 0.988134] IR RC6 protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 0.994171] IR JVC protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 0.999963] IR Sony protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 1.005744] IR SANYO protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 1.011416] IR Sharp protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 1.017044] IR MCE Keyboard/mouse protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 1.022736] IR XMP protocol handler initialized
Mar 18 16:45:48 scraper kernel: [ 1.029823] bcm2835-wdt 20100000.watchdog: Broadcom BCM2835 watchdog timer
Mar 18 16:45:48 scraper kernel: [ 1.036342] bcm2835-cpufreq: min=700000 max=1000000
Mar 18 16:45:48 scraper kernel: [ 1.042935] sdhci: Secure Digital Host Controller Interface driver
Mar 18 16:45:48 scraper kernel: [ 1.048782] sdhci: Copyright(c) Pierre Ossman
Mar 18 16:45:48 scraper kernel: [ 1.055293] mmc-bcm2835 20300000.mmc: could not get clk, deferring probe
Mar 18 16:45:48 scraper kernel: [ 1.061978] sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe
Mar 18 16:45:48 scraper kernel: [ 1.068519] sdhci-pltfm: SDHCI platform and OF driver helper
Mar 18 16:45:48 scraper kernel: [ 1.075247] ledtrig-cpu: registered to indicate activity on CPUs
Mar 18 16:45:48 scraper kernel: [ 1.081367] hidraw: raw HID events driver (C) Jiri Kosina
Mar 18 16:45:48 scraper kernel: [ 1.087675] usbcore: registered new interface driver usbhid
Mar 18 16:45:48 scraper kernel: [ 1.093731] usbhid: USB HID core driver
Mar 18 16:45:48 scraper kernel: [ 1.100502] vchiq: vchiq_init_state: slot_zero = d7580000, is_master = 0
Mar 18 16:45:48 scraper kernel: [ 1.108623] [vc_sm_connected_init]: start
Mar 18 16:45:48 scraper kernel: [ 1.120160] [vc_sm_connected_init]: end - returning 0
Mar 18 16:45:48 scraper kernel: [ 1.127496] Initializing XFRM netlink socket
Mar 18 16:45:48 scraper kernel: [ 1.133559] NET: Registered protocol family 17
Mar 18 16:45:48 scraper kernel: [ 1.139514] Key type dns_resolver registered
Mar 18 16:45:48 scraper kernel: [ 1.147102] registered taskstats version 1
Mar 18 16:45:48 scraper kernel: [ 1.161283] uart-pl011 20201000.serial: cts_event_workaround enabled
Mar 18 16:45:48 scraper kernel: [ 1.167570] 20201000.serial: ttyAMA0 at MMIO 0x20201000 (irq = 81, base_baud = 0) is a PL011 rev2
Mar 18 16:45:48 scraper kernel: [ 1.176780] mmc-bcm2835 20300000.mmc: mmc_debug:0 mmc_debug2:0
Mar 18 16:45:48 scraper kernel: [ 1.182996] mmc-bcm2835 20300000.mmc: DMA channel allocated
Mar 18 16:45:48 scraper kernel: [ 1.245490] sdhost: log_buf @ d7513000 (57513000)
Mar 18 16:45:48 scraper kernel: [ 1.287036] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
Mar 18 16:45:48 scraper kernel: [ 1.294939] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Mar 18 16:45:48 scraper kernel: [ 1.302502] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Mar 18 16:45:48 scraper kernel: [ 1.311476] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
Mar 18 16:45:48 scraper kernel: [ 1.331766] random: fast init done
Mar 18 16:45:48 scraper kernel: [ 1.337612] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Mar 18 16:45:48 scraper kernel: [ 1.344828] of_cfs_init
Mar 18 16:45:48 scraper kernel: [ 1.350670] of_cfs_init: OK
Mar 18 16:45:48 scraper kernel: [ 1.378114] Waiting for root device PARTUUID=c8e3b7d3-02...
Mar 18 16:45:48 scraper kernel: [ 1.431358] mmc0: host does not support reading read-only switch, assuming write-enable
Mar 18 16:45:48 scraper kernel: [ 1.440543] mmc0: new high speed SDHC card at address 0007
Mar 18 16:45:48 scraper kernel: [ 1.447813] mmcblk0: mmc0:0007 SD32G 28.8 GiB
Mar 18 16:45:48 scraper kernel: [ 1.457306] mmcblk0: p1 p2
Mar 18 16:45:48 scraper kernel: [ 1.490933] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Mar 18 16:45:48 scraper kernel: [ 1.497385] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Mar 18 16:45:48 scraper kernel: [ 1.516369] devtmpfs: mounted
Mar 18 16:45:48 scraper kernel: [ 1.525228] Freeing unused kernel memory: 440K
Mar 18 16:45:48 scraper kernel: [ 1.531397] This architecture does not have kernel memory protection.
Mar 18 16:45:48 scraper kernel: [ 1.540593] mmc1: new high speed SDIO card at address 0001
Mar 18 16:45:48 scraper kernel: [ 2.320502] NET: Registered protocol family 10
Mar 18 16:45:48 scraper kernel: [ 2.328883] Segment Routing with IPv6
Mar 18 16:45:48 scraper kernel: [ 2.350645] ip_tables: (C) 2000-2006 Netfilter Core Team
Mar 18 16:45:48 scraper kernel: [ 2.402462] random: systemd: uninitialized urandom read (16 bytes read)
Mar 18 16:45:48 scraper kernel: [ 2.565222] random: systemd: uninitialized urandom read (16 bytes read)
Mar 18 16:45:48 scraper kernel: [ 2.807234] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read)
Mar 18 16:45:48 scraper kernel: [ 4.040771] i2c /dev entries driver
Mar 18 16:45:48 scraper kernel: [ 6.909267] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Mar 18 16:45:48 scraper kernel: [ 10.332477] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Mar 18 16:45:48 scraper kernel: [ 10.381234] bcm2835_alsa bcm2835_alsa: card created with 8 channels
Mar 18 16:45:48 scraper kernel: [ 11.151902] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
Mar 18 16:45:48 scraper kernel: [ 11.190488] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
Mar 18 16:45:48 scraper kernel: [ 11.190891] usbcore: registered new interface driver brcmfmac
Mar 18 16:45:48 scraper kernel: [ 11.739310] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Oct 23 2017 03:55:53 version 7.45.98.38 (r674442 CY) FWID 01-e58d219f
Mar 18 16:45:48 scraper kernel: [ 11.740598] brcmfmac: brcmf_c_preinit_dcmds: CLM version = API: 12.2 Data: 7.11.15 Compiler: 1.24.2 ClmImport: 1.24.1 Creation: 2014-05-26 10:53:55 Inc Data: 9.10.39 Inc Compiler: 1.29.4 Inc ClmImport: 1.36.3 Creation: 2017-10-23 03:47:14
Mar 18 16:45:48 scraper systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Mar 18 16:45:48 scraper cron[226]: (CRON) INFO (pidfile fd = 3)
Mar 18 16:45:49 scraper systemd[1]: Started D-Bus System Message Bus.
Mar 18 16:45:49 scraper cron[226]: (CRON) INFO (Running @reboot jobs)
Mar 18 16:45:49 scraper kernel: [ 15.460200] uart-pl011 20201000.serial: no DMA platform data
Mar 18 16:45:49 scraper dbus[237]: [system] Successfully activated service 'org.freedesktop.systemd1'
Mar 18 16:45:49 scraper systemd[1]: Starting WPA supplicant...
Mar 18 16:45:49 scraper systemd[1]: Starting dhcpcd on all interfaces...
Mar 18 16:45:49 scraper systemd[1]: Starting LSB: Autogenerate and use a swap file...
Mar 18 16:45:49 scraper systemd[1]: Starting triggerhappy global hotkey daemon...
Mar 18 16:45:50 scraper systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Mar 18 16:45:50 scraper systemd[1]: Starting status led service...
Mar 18 16:45:50 scraper dhcpcd[260]: dev: loaded udev
Mar 18 16:45:50 scraper thd[263]: Found socket passed from systemd
Mar 18 16:45:50 scraper systemd[267]: status-led.service: Failed at step CHROOT spawning /bin/bash: No such file or directory
Mar 18 16:45:50 scraper dhcpcd[260]: no valid interfaces found
Mar 18 16:45:50 scraper wpa_supplicant[259]: Successfully initialized wpa_supplicant
Mar 18 16:45:50 scraper systemd[1]: Starting Save/Restore Sound Card State...
Mar 18 16:45:50 scraper dhcpcd[260]: forked to background, child pid 269
Mar 18 16:45:50 scraper systemd[1]: Started System Logging Service.
Mar 18 16:45:50 scraper avahi-daemon[265]: Found user 'avahi' (UID 108) and group 'avahi' (GID 112).
Mar 18 16:45:50 scraper systemd[1]: Started triggerhappy global hotkey daemon.
Mar 18 16:45:50 scraper avahi-daemon[265]: Successfully dropped root privileges.
Mar 18 16:45:50 scraper avahi-daemon[265]: avahi-daemon 0.6.32 starting up.
Mar 18 16:45:50 scraper systemd[1]: status-monitor.service: Main process exited, code=exited, status=210/CHROOT
Mar 18 16:45:50 scraper systemd[1]: status-monitor.service: Unit entered failed state.
Mar 18 16:45:50 scraper systemd[1]: status-monitor.service: Failed with result 'exit-code'.
Mar 18 16:45:50 scraper avahi-daemon[265]: Successfully called chroot().
Mar 18 16:45:50 scraper systemd[1]: Started Check for v3d driver.
Mar 18 16:45:50 scraper avahi-daemon[265]: Successfully dropped remaining capabilities.
Mar 18 16:45:50 scraper systemd[1]: Started Disable WiFi if country not set.
Mar 18 16:45:50 scraper avahi-daemon[265]: No service file found in /etc/avahi/services.
Mar 18 16:45:50 scraper systemd[1]: Started dhcpcd on all interfaces.
Mar 18 16:45:50 scraper avahi-daemon[265]: Network interface enumeration completed.
Mar 18 16:45:50 scraper systemd[1]: status-led.service: Control process exited, code=exited status=210
Mar 18 16:45:50 scraper avahi-daemon[265]: Server startup complete. Host name is scraper.local. Local service cookie is 1628923548.
Mar 18 16:45:50 scraper systemd[1]: Failed to start status led service.
Mar 18 16:45:50 scraper avahi-daemon[265]: Failed to parse address 'fe80::aa0c:63ff:fe6d:3b42%wlan0', ignoring.
Mar 18 16:45:50 scraper systemd[1]: Dependency failed for status led startup update.
Mar 18 16:45:50 scraper systemd[1]: status-led-on.service: Job status-led-on.service/start failed with result 'dependency'.
Mar 18 16:45:50 scraper systemd[1]: status-led.service: Unit entered failed state.
Mar 18 16:45:50 scraper systemd[1]: status-led.service: Failed with result 'exit-code'.
Mar 18 16:45:50 scraper systemd[1]: Started Save/Restore Sound Card State.
Mar 18 16:45:51 scraper systemd[1]: status-monitor.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:51 scraper systemd[1]: status-led.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:51 scraper dphys-swapfile[261]: Starting dphys-swapfile swapfile setup ...
Mar 18 16:45:51 scraper systemd[1]: Started WPA supplicant.
Mar 18 16:45:51 scraper systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Mar 18 16:45:51 scraper systemd[1]: Started Login Service.
Mar 18 16:45:51 scraper systemd[1]: Stopped status monitor service.
Mar 18 16:45:51 scraper raspi-config[230]: Checking if shift key is held down:Error opening '/dev/input/event*': No such file or directory
Mar 18 16:45:51 scraper raspi-config[230]: No. Switching to ondemand scaling governor.
Mar 18 16:45:51 scraper systemd[1]: Started status monitor service.
Mar 18 16:45:51 scraper systemd[1]: Stopped status led service.
Mar 18 16:45:51 scraper systemd[1]: Starting status led service...
Mar 18 16:45:51 scraper systemd[290]: status-monitor.service: Failed at step CHROOT spawning /usr/bin/python3: No such file or directory
Mar 18 16:45:52 scraper systemd[296]: status-led.service: Failed at step CHROOT spawning /bin/bash: No such file or directory
Mar 18 16:45:52 scraper systemd[1]: Started Raise network interfaces.
Mar 18 16:45:52 scraper systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Mar 18 16:45:52 scraper systemd[1]: status-monitor.service: Main process exited, code=exited, status=210/CHROOT
Mar 18 16:45:52 scraper systemd[1]: status-monitor.service: Unit entered failed state.
Mar 18 16:45:52 scraper systemd[1]: status-monitor.service: Failed with result 'exit-code'.
Mar 18 16:45:52 scraper systemd[1]: status-led.service: Control process exited, code=exited status=210
Mar 18 16:45:52 scraper systemd[1]: Failed to start status led service.
Mar 18 16:45:52 scraper systemd[1]: status-led.service: Unit entered failed state.
Mar 18 16:45:52 scraper systemd[1]: status-led.service: Failed with result 'exit-code'.
Mar 18 16:45:52 scraper systemd[1]: status-monitor.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:52 scraper systemd[1]: Stopped status monitor service.
Mar 18 16:45:52 scraper systemd[1]: Started status monitor service.
Mar 18 16:45:52 scraper systemd[1]: Reached target Network.
Mar 18 16:45:52 scraper systemd[1]: Reached target Network is Online.
Mar 18 16:45:52 scraper systemd[308]: status-monitor.service: Failed at step CHROOT spawning /usr/bin/python3: No such file or directory
Mar 18 16:45:52 scraper systemd[1]: Starting Samba NMB Daemon...
Mar 18 16:45:52 scraper dphys-swapfile[261]: want /var/swap=100MByte, checking existing: keeping it
Mar 18 16:45:52 scraper systemd[1]: Started Set time with ntpdate.
Mar 18 16:45:52 scraper systemd[1]: Starting Permit User Sessions...
Mar 18 16:45:52 scraper systemd[1]: Started VNC Server in Service Mode daemon.
Mar 18 16:45:52 scraper ntpdate[313]: Exiting, name server cannot be used: Temporary failure in name resolution (-3)18 Mar 16:45:52 ntpdate[313]: name server cannot be used: Temporary failure in name resolution (-3)
Mar 18 16:45:52 scraper kernel: [ 18.760870] Adding 102396k swap on /var/swap. Priority:-2 extents:11 across:241660k SSFS
Mar 18 16:45:52 scraper systemd[1]: Starting /etc/rc.local Compatibility...
Mar 18 16:45:52 scraper dphys-swapfile[261]: done.
Mar 18 16:45:53 scraper systemd[1]: Started LSB: Autogenerate and use a swap file.
Mar 18 16:45:53 scraper systemd[1]: status-monitor.service: Main process exited, code=exited, status=210/CHROOT
Mar 18 16:45:53 scraper systemd[1]: status-monitor.service: Unit entered failed state.
Mar 18 16:45:53 scraper systemd[1]: status-monitor.service: Failed with result 'exit-code'.
Mar 18 16:45:53 scraper systemd[1]: ntpdate.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 16:45:53 scraper systemd[1]: ntpdate.service: Unit entered failed state.
Mar 18 16:45:53 scraper systemd[1]: ntpdate.service: Failed with result 'exit-code'.
Mar 18 16:45:53 scraper systemd[1]: Started Permit User Sessions.
Mar 18 16:45:53 scraper systemd[1]: Started /etc/rc.local Compatibility.
Mar 18 16:45:53 scraper systemd[1]: status-led.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:53 scraper systemd[1]: status-monitor.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:53 scraper systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Mar 18 16:45:53 scraper systemd[1]: Stopped status monitor service.
Mar 18 16:45:53 scraper systemd[1]: Started status monitor service.
Mar 18 16:45:53 scraper systemd[1]: Reached target Sound Card.
Mar 18 16:45:53 scraper systemd[1]: Stopped status led service.
Mar 18 16:45:53 scraper systemd[328]: status-monitor.service: Failed at step CHROOT spawning /usr/bin/python3: No such file or directory
Mar 18 16:45:53 scraper systemd[1]: Starting status led service...
Mar 18 16:45:53 scraper systemd[1]: Starting Terminate Plymouth Boot Screen...
Mar 18 16:45:53 scraper systemd[1]: Starting Light Display Manager...
Mar 18 16:45:53 scraper systemd[330]: status-led.service: Failed at step CHROOT spawning /bin/bash: No such file or directory
Mar 18 16:45:53 scraper systemd[1]: Starting Hold until boot process finishes up...
Mar 18 16:45:54 scraper systemd[1]: Received SIGRTMIN+21 from PID 128 (plymouthd).
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Main process exited, code=exited, status=210/CHROOT
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Unit entered failed state.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Failed with result 'exit-code'.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Control process exited, code=exited status=210
Mar 18 16:45:54 scraper systemd[1]: Failed to start status led service.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Unit entered failed state.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Failed with result 'exit-code'.
Mar 18 16:45:54 scraper systemd[1]: Started Terminate Plymouth Boot Screen.
Mar 18 16:45:54 scraper systemd[1]: Started Hold until boot process finishes up.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:54 scraper systemd[1]: Stopped status monitor service.
Mar 18 16:45:54 scraper systemd[1]: Started status monitor service.
Mar 18 16:45:54 scraper systemd[1]: Starting Load/Save RF Kill Switch Status...
Mar 18 16:45:54 scraper systemd[1]: Started Getty on tty1.
Mar 18 16:45:54 scraper systemd[342]: status-monitor.service: Failed at step CHROOT spawning /usr/bin/python3: No such file or directory
Mar 18 16:45:54 scraper systemd[1]: Reached target Login Prompts.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Main process exited, code=exited, status=210/CHROOT
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Unit entered failed state.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Failed with result 'exit-code'.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:54 scraper systemd[1]: Stopped status led service.
Mar 18 16:45:54 scraper systemd[1]: Starting status led service...
Mar 18 16:45:54 scraper systemd[346]: status-led.service: Failed at step CHROOT spawning /bin/bash: No such file or directory
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Control process exited, code=exited status=210
Mar 18 16:45:54 scraper systemd[1]: Failed to start status led service.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Unit entered failed state.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Failed with result 'exit-code'.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:54 scraper systemd[1]: Stopped status monitor service.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Start request repeated too quickly.
Mar 18 16:45:54 scraper systemd[1]: Failed to start status monitor service.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Unit entered failed state.
Mar 18 16:45:54 scraper systemd[1]: status-monitor.service: Failed with result 'exit-code'.
Mar 18 16:45:54 scraper systemd[1]: status-led.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:54 scraper systemd[1]: Stopped status led service.
Mar 18 16:45:54 scraper systemd[1]: Starting status led service...
Mar 18 16:45:54 scraper systemd[349]: status-led.service: Failed at step CHROOT spawning /bin/bash: No such file or directory
Mar 18 16:45:54 scraper kernel: [ 20.947950] Bluetooth: Core ver 2.22
Mar 18 16:45:54 scraper kernel: [ 20.948069] NET: Registered protocol family 31
Mar 18 16:45:54 scraper kernel: [ 20.948078] Bluetooth: HCI device and connection manager initialized
Mar 18 16:45:54 scraper kernel: [ 20.948104] Bluetooth: HCI socket layer initialized
Mar 18 16:45:54 scraper kernel: [ 20.948119] Bluetooth: L2CAP socket layer initialized
Mar 18 16:45:54 scraper kernel: [ 20.948159] Bluetooth: SCO socket layer initialized
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Control process exited, code=exited status=210
Mar 18 16:45:55 scraper kernel: [ 21.015172] Bluetooth: HCI UART driver ver 2.3
Mar 18 16:45:55 scraper kernel: [ 21.015190] Bluetooth: HCI UART protocol H4 registered
Mar 18 16:45:55 scraper kernel: [ 21.015195] Bluetooth: HCI UART protocol Three-wire (H5) registered
Mar 18 16:45:55 scraper systemd[1]: Failed to start status led service.
Mar 18 16:45:55 scraper kernel: [ 21.048266] Bluetooth: HCI UART protocol Broadcom registered
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Unit entered failed state.
Mar 18 16:45:55 scraper btuart[215]: bcm43xx_init
Mar 18 16:45:55 scraper btuart[215]: Flash firmware /lib/firmware/brcm/BCM43430A1.hcd
Mar 18 16:45:55 scraper btuart[215]: Set BDADDR UART: b8:27:eb:37:a3:bf
Mar 18 16:45:55 scraper btuart[215]: Set Controller UART speed to 3000000 bit/s
Mar 18 16:45:55 scraper btuart[215]: Device setup complete
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Failed with result 'exit-code'.
Mar 18 16:45:55 scraper systemd[1]: Started Configure Bluetooth Modems connected by UART.
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:55 scraper systemd[1]: Stopped status led service.
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Start request repeated too quickly.
Mar 18 16:45:55 scraper systemd[1]: Failed to start status led service.
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Unit entered failed state.
Mar 18 16:45:55 scraper systemd[1]: status-led.service: Failed with result 'exit-code'.
Mar 18 16:45:55 scraper systemd[1]: Started Load/Save RF Kill Switch Status.
Mar 18 16:45:55 scraper systemd[1]: Created slice system-bthelper.slice.
Mar 18 16:45:55 scraper systemd[1]: Starting Bluetooth service...
Mar 18 16:45:55 scraper bluetoothd[367]: Bluetooth daemon 5.43
Mar 18 16:45:56 scraper systemd-udevd[124]: Process '/sbin/crda' failed with exit code 249.
Mar 18 16:45:56 scraper systemd-udevd[124]: Process '/sbin/crda' failed with exit code 249.
Mar 18 16:45:56 scraper systemd-udevd[124]: Process '/sbin/crda' failed with exit code 249.
Mar 18 16:45:56 scraper systemd[1]: ntpdate.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:56 scraper systemd[1]: Stopped Set time with ntpdate.
Mar 18 16:45:56 scraper systemd[1]: Started Set time with ntpdate.
Mar 18 16:45:56 scraper ntpdate[375]: Exiting, name server cannot be used: Temporary failure in name resolution (-3)18 Mar 16:45:56 ntpdate[375]: name server cannot be used: Temporary failure in name resolution (-3)
Mar 18 16:45:56 scraper systemd[1]: ntpdate.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 16:45:56 scraper systemd[1]: ntpdate.service: Unit entered failed state.
Mar 18 16:45:56 scraper systemd[1]: ntpdate.service: Failed with result 'exit-code'.
Mar 18 16:45:56 scraper systemd[1]: Started Bluetooth service.
Mar 18 16:45:56 scraper systemd[1]: Reached target Bluetooth.
Mar 18 16:45:56 scraper systemd[1]: Started Raspberry Pi bluetooth helper.
Mar 18 16:45:56 scraper systemd[1]: Started BluezALSA proxy.
Mar 18 16:45:56 scraper bluetoothd[367]: Starting SDP server
Mar 18 16:45:57 scraper kernel: [ 23.032999] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Mar 18 16:45:57 scraper kernel: [ 23.033013] Bluetooth: BNEP filters: protocol multicast
Mar 18 16:45:57 scraper kernel: [ 23.033043] Bluetooth: BNEP socket layer initialized
Mar 18 16:45:57 scraper bluetoothd[367]: Bluetooth management interface 1.14 initialized
Mar 18 16:45:57 scraper dbus[237]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Mar 18 16:45:57 scraper bluetoothd[367]: Failed to obtain handles for "Service Changed" characteristic
Mar 18 16:45:57 scraper bluetoothd[367]: Sap driver initialization failed.
Mar 18 16:45:57 scraper bluetoothd[367]: sap-server: Operation not permitted (1)
Mar 18 16:45:57 scraper dhcpcd-run-hooks[386]: wlan0: starting wpa_supplicant
Mar 18 16:45:57 scraper bluetoothd[367]: Failed to set privacy: Rejected (0x0b)
Mar 18 16:45:57 scraper systemd[1]: Starting Hostname Service...
Mar 18 16:45:57 scraper bluetoothd[367]: Endpoint registered: sender=:1.6 path=/A2DP/SBC/Source/1
Mar 18 16:45:57 scraper kernel: [ 23.464709] Bluetooth: RFCOMM TTY layer initialized
Mar 18 16:45:57 scraper kernel: [ 23.464748] Bluetooth: RFCOMM socket layer initialized
Mar 18 16:45:57 scraper kernel: [ 23.464787] Bluetooth: RFCOMM ver 1.11
Mar 18 16:45:57 scraper lightdm[354]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
Mar 18 16:45:57 scraper systemd[1]: nmbd.service: Supervising process 400 which is not our child. We'll most likely not notice when it exits.
Mar 18 16:45:57 scraper systemd[1]: Started Light Display Manager.
Mar 18 16:45:57 scraper dbus[237]: [system] Successfully activated service 'org.freedesktop.hostname1'
Mar 18 16:45:57 scraper systemd[1]: Started Hostname Service.
Mar 18 16:45:58 scraper kernel: [ 24.065699] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Mar 18 16:45:58 scraper kernel: [ 24.065719] brcmfmac: power management disabled
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: waiting for carrier
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: carrier acquired
Mar 18 16:45:58 scraper dhcpcd[269]: DUID 00:01:00:01:21:26:5f:15:b8:27:eb:a8:2a:94
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: IAID eb:c8:5c:40
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: adding address fe80::1472:9626:a34b:490a
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: probing address 192.168.0.45/24
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: carrier lost
Mar 18 16:45:58 scraper dhcpcd[269]: wlan0: deleting address fe80::1472:9626:a34b:490a
Mar 18 16:45:59 scraper kernel: [ 25.301527] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Mar 18 16:45:59 scraper dhcpcd[269]: wlan0: carrier acquired
Mar 18 16:45:59 scraper dhcpcd[269]: wlan0: IAID eb:c8:5c:40
Mar 18 16:45:59 scraper dhcpcd[269]: wlan0: adding address fe80::d0e4:99c5:d63:6027
Mar 18 16:45:59 scraper dhcpcd[269]: wlan0: probing address 192.168.0.45/24
Mar 18 16:45:59 scraper systemd[1]: ntpdate.service: Service hold-off time over, scheduling restart.
Mar 18 16:45:59 scraper systemd[1]: Stopped Set time with ntpdate.
Mar 18 16:45:59 scraper systemd[1]: Started Set time with ntpdate.
Mar 18 16:45:59 scraper ntpdate[431]: Exiting, name server cannot be used: Temporary failure in name resolution (-3)18 Mar 16:45:59 ntpdate[431]: name server cannot be used: Temporary failure in name resolution (-3)
Mar 18 16:45:59 scraper systemd[1]: ntpdate.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 16:45:59 scraper systemd[1]: ntpdate.service: Unit entered failed state.
Mar 18 16:45:59 scraper systemd[1]: ntpdate.service: Failed with result 'exit-code'.
Mar 18 16:46:00 scraper dhcpcd[269]: wlan0: soliciting an IPv6 router
Mar 18 16:46:00 scraper avahi-daemon[265]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::d0e4:99c5:d63:6027.
Mar 18 16:46:00 scraper avahi-daemon[265]: New relevant interface wlan0.IPv6 for mDNS.
Mar 18 16:46:00 scraper avahi-daemon[265]: Registering new address record for fe80::d0e4:99c5:d63:6027 on wlan0.*.
Mar 18 16:46:00 scraper dhcpcd[269]: wlan0: Router Advertisement from fe80::aa0c:63ff:fe6d:3b42
Mar 18 16:46:00 scraper dhcpcd[269]: wlan0: adding default route via fe80::aa0c:63ff:fe6d:3b42
Mar 18 16:46:00 scraper dhcpcd[269]: wlan0: requesting DHCPv6 information
Mar 18 16:46:01 scraper lightdm[447]: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
Mar 18 16:46:01 scraper systemd[1]: Created slice User Slice of pi.
Mar 18 16:46:01 scraper systemd[1]: Starting User Manager for UID 1000...
Mar 18 16:46:01 scraper systemd[1]: Started Session c1 of user pi.
Mar 18 16:46:02 scraper systemd[1]: ntpdate.service: Service hold-off time over, scheduling restart.
Mar 18 16:46:02 scraper systemd[1]: Stopped Set time with ntpdate.
Mar 18 16:46:02 scraper systemd[1]: Started Set time with ntpdate.
Mar 18 16:46:03 scraper ntpdate[480]: 18 Mar 16:46:03 ntpdate[480]: no servers can be used, exiting
Mar 18 16:46:03 scraper systemd[1]: ntpdate.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 16:46:03 scraper systemd[1]: ntpdate.service: Unit entered failed state.
Mar 18 16:46:03 scraper systemd[1]: ntpdate.service: Failed with result 'exit-code'.
Mar 18 16:46:03 scraper systemd[455]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Mar 18 16:46:03 scraper systemd[455]: Reached target Timers.
Mar 18 16:46:03 scraper systemd[455]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Mar 18 16:46:03 scraper systemd[455]: Starting D-Bus User Message Bus Socket.
Mar 18 16:46:03 scraper systemd[455]: Listening on GnuPG cryptographic agent (access for web browsers).
Mar 18 16:46:03 scraper systemd[455]: Listening on GnuPG cryptographic agent and passphrase cache.
Mar 18 16:46:03 scraper systemd[455]: Reached target Paths.
Mar 18 16:46:03 scraper systemd[455]: Listening on D-Bus User Message Bus Socket.
Mar 18 16:46:03 scraper systemd[455]: Reached target Sockets.
Mar 18 16:46:03 scraper systemd[455]: Reached target Basic System.
Mar 18 16:46:03 scraper systemd[455]: Reached target Default.
Mar 18 16:46:03 scraper systemd[455]: Startup finished in 1.788s.
Mar 18 16:46:03 scraper systemd[1]: Started User Manager for UID 1000.
Mar 18 16:46:04 scraper lightdm[354]: Error opening audit socket: Protocol not supported
Mar 18 16:46:05 scraper systemd[455]: Started D-Bus User Message Bus.
Mar 18 16:46:05 scraper dhcpcd[269]: wlan0: using static address 192.168.0.45/24
Mar 18 16:46:05 scraper avahi-daemon[265]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.45.
Mar 18 16:46:05 scraper dhcpcd[269]: wlan0: adding route to 192.168.0.0/24
Mar 18 16:46:05 scraper dhcpcd[269]: wlan0: adding default route via 192.168.0.1
Mar 18 16:46:05 scraper avahi-daemon[265]: New relevant interface wlan0.IPv4 for mDNS.
Mar 18 16:46:05 scraper avahi-daemon[265]: Registering new address record for 192.168.0.45 on wlan0.IPv4.
Mar 18 16:46:06 scraper systemd[1]: ntpdate.service: Service hold-off time over, scheduling restart.
Mar 18 16:46:06 scraper systemd[1]: Stopped Set time with ntpdate.
Mar 18 16:46:06 scraper systemd[1]: Started Set time with ntpdate.
Mar 18 16:46:07 scraper systemd[1]: Started Samba NMB Daemon.
Mar 18 16:46:07 scraper systemd[1]: Starting Samba Winbind Daemon...
Mar 18 16:46:10 scraper systemd[1]: winbind.service: Supervising process 618 which is not our child. We'll most likely not notice when it exits.
Mar 18 16:46:11 scraper systemd[1]: Started Samba Winbind Daemon.
Mar 18 16:46:11 scraper systemd[1]: Starting Samba SMB Daemon...
Mar 18 16:46:12 scraper dbus-daemon[522]: Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Mar 18 16:46:12 scraper systemd[455]: Starting Virtual filesystem service...
Mar 18 16:46:12 scraper dbus-daemon[522]: Successfully activated service 'org.gtk.vfs.Daemon'
Mar 18 16:46:12 scraper systemd[455]: Started Virtual filesystem service.
Mar 18 16:46:12 scraper kernel: [ 38.708273] fuse init (API version 7.26)
Mar 18 16:46:13 scraper systemd[1]: Mounting FUSE Control File System...
Mar 18 16:46:25 scraper ntpdate[578]: 18 Mar 16:46:25 ntpdate[578]: step time server 85.199.214.101 offset 12.652532 sec
Mar 18 16:46:25 scraper systemd[455]: Time has been changed
Mar 18 16:46:25 scraper systemd[1]: Mounted FUSE Control File System.
Mar 18 16:46:25 scraper systemd[1]: Time has been changed
Mar 18 16:46:26 scraper systemd[1]: apt-daily-upgrade.timer: Adding 57min 58.243165s random time.
Mar 18 16:46:26 scraper systemd[1]: apt-daily.timer: Adding 4h 5min 11.857451s random time.
Mar 18 16:46:27 scraper systemd[1]: smbd.service: Supervising process 663 which is not our child. We'll most likely not notice when it exits.
Mar 18 16:46:28 scraper systemd[1]: Started Samba SMB Daemon.
Mar 18 16:46:28 scraper systemd[1]: Reached target Multi-User System.
Mar 18 16:46:28 scraper systemd[1]: Reached target Graphical Interface.
Mar 18 16:46:28 scraper systemd[1]: Starting Update UTMP about System Runlevel Changes...
Mar 18 16:46:28 scraper systemd[1]: Started Update UTMP about System Runlevel Changes.
Mar 18 16:46:28 scraper systemd[1]: Startup finished in 2.084s (kernel) + 39.487s (userspace) = 41.572s.
Mar 18 16:46:28 scraper dbus[237]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
Mar 18 16:46:28 scraper systemd[1]: Starting Authorization Manager...
Mar 18 16:46:28 scraper polkitd[680]: started daemon version 0.105 using authority implementation `local' version `0.105'
Mar 18 16:46:29 scraper dbus[237]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
Mar 18 16:46:29 scraper systemd[1]: Started Authorization Manager.
Mar 18 16:46:30 scraper systemd-timesyncd[187]: Synchronized to time server 217.114.59.66:123 (2.debian.pool.ntp.org).
Mar 18 16:46:31 scraper dbus-daemon[522]: Activating via systemd: service name='org.gtk.vfs.UDisks2VolumeMonitor' unit='gvfs-udisks2-volume-monitor.service'
Mar 18 16:46:31 scraper systemd[455]: Starting Virtual filesystem service - disk device monitor...
Mar 18 16:46:31 scraper dbus[237]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service'
Mar 18 16:46:31 scraper systemd[1]: Starting Disk Manager...
Mar 18 16:46:31 scraper udisksd[699]: udisks daemon version 2.1.8 starting
Mar 18 16:46:32 scraper dbus[237]: [system] Successfully activated service 'org.freedesktop.UDisks2'
Mar 18 16:46:32 scraper systemd[1]: Started Disk Manager.
Mar 18 16:46:32 scraper udisksd[699]: Acquired the name org.freedesktop.UDisks2 on the system message bus
Mar 18 16:46:33 scraper dbus-daemon[522]: Successfully activated service 'org.gtk.vfs.UDisks2VolumeMonitor'
Mar 18 16:46:33 scraper systemd[455]: Started Virtual filesystem service - disk device monitor.
Mar 18 16:46:33 scraper dbus-daemon[522]: Activating via systemd: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service'
Mar 18 16:46:33 scraper systemd[455]: Starting Virtual filesystem service - digital camera monitor...
Mar 18 16:46:33 scraper dbus-daemon[522]: Successfully activated service 'org.gtk.vfs.GPhoto2VolumeMonitor'
Mar 18 16:46:33 scraper systemd[455]: Started Virtual filesystem service - digital camera monitor.
Mar 18 16:46:33 scraper dbus-daemon[522]: Activating via systemd: service name='org.gtk.vfs.AfcVolumeMonitor' unit='gvfs-afc-volume-monitor.service'
Mar 18 16:46:33 scraper systemd[455]: Starting Virtual filesystem service - Apple File Conduit monitor...
Mar 18 16:46:33 scraper gvfs-afc-volume-monitor[726]: Volume monitor alive
Mar 18 16:46:33 scraper dbus-daemon[522]: Successfully activated service 'org.gtk.vfs.AfcVolumeMonitor'
Mar 18 16:46:33 scraper systemd[455]: Started Virtual filesystem service - Apple File Conduit monitor.
Mar 18 16:46:33 scraper dbus-daemon[522]: Activating via systemd: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service'
Mar 18 16:46:33 scraper systemd[455]: Starting Virtual filesystem service - Media Transfer Protocol monitor...
Mar 18 16:46:34 scraper dbus-daemon[522]: Successfully activated service 'org.gtk.vfs.MTPVolumeMonitor'
Mar 18 16:46:34 scraper systemd[455]: Started Virtual filesystem service - Media Transfer Protocol monitor.
Mar 18 16:46:34 scraper dbus-daemon[522]: Activating via systemd: service name='org.gtk.vfs.GoaVolumeMonitor' unit='gvfs-goa-volume-monitor.service'
Mar 18 16:46:34 scraper systemd[455]: Starting Virtual filesystem service - GNOME Online Accounts monitor...
Mar 18 16:46:34 scraper dbus-daemon[522]: Successfully activated service 'org.gtk.vfs.GoaVolumeMonitor'
Mar 18 16:46:34 scraper systemd[455]: Started Virtual filesystem service - GNOME Online Accounts monitor.
Mar 18 16:57:32 scraper kernel: [ 705.651447] random: crng init done
Mar 18 16:57:32 scraper kernel: [ 705.651475] random: 7 urandom warning(s) missed due to ratelimiting
Mar 18 16:57:32 scraper vncserver-x11[325,root]: ServerManager: Server started
Mar 18 16:57:32 scraper vncserver-x11[325,root]: ConsoleDisplay: Found running X server (pid=401, binary=/usr/lib/xorg/Xorg)
Mar 18 16:58:12 scraper vncserver-x11[325,root]: Connections: connected: 192.168.0.145::53409 (TCP)
Mar 18 16:58:12 scraper vncserver-x11[325,root]: Connections: authenticated: 192.168.0.145::53409 (TCP), as pi (f permissions)

User avatar
sconemad
Posts: 227
Joined: Thu Apr 28, 2016 1:47 pm
Location: Cambridge, UK
Contact: Website

Re: Why does my RealVNC start so late after boot up

Tue Mar 19, 2019 3:56 pm

Looks like it could be the same as this: viewtopic.php?f=28&t=230779

MarkDH102
Posts: 329
Joined: Fri Feb 13, 2015 3:18 pm

Re: Why does my RealVNC start so late after boot up

Tue Mar 19, 2019 4:33 pm

Many, many thanks for this pointer.
I now have a working system again.
I was beginning to tear my hair (what's left of it) out!

Return to “Troubleshooting”