root@PiHole:~# dmesg
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.19.97+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1294 Thu Jan 30 13:10:54 GMT 2020
[ 0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi Model B Rev 2
[ 0.000000] Memory policy: Data cache writeback
[ 0.000000] cma: Reserved 8 MiB at 0x1e400000
[ 0.000000] On node 0 totalpages: 126976
[ 0.000000] Normal zone: 1116 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 126976 pages, LIFO batch:31
[ 0.000000] random: get_random_bytes called from start_kernel+0x8c/0x494 with crng_init=0
[ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[ 0.000000] pcpu-alloc: [0] 0
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 125860
[ 0.000000] Kernel command line: coherent_pool=1M bcm2708_fb.fbwidth=16 bcm2708_fb.fbheight=16 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:7E:C9:8C vc_mem.mem_base=0x1fa00000 vc_mem.mem_size=0x20000000 dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=cb7b86f7-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.000000] Memory: 482876K/507904K available (7144K kernel code, 656K rwdata, 2128K rodata, 472K init, 797K bss, 16836K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xdf800000 - 0xff800000 ( 512 MB)
lowmem : 0xc0000000 - 0xdf000000 ( 496 MB)
modules : 0xbf000000 - 0xc0000000 ( 16 MB)
.text : 0x(ptrval) - 0x(ptrval) (7146 kB)
.init : 0x(ptrval) - 0x(ptrval) ( 472 kB)
.data : 0x(ptrval) - 0x(ptrval) ( 657 kB)
.bss : 0x(ptrval) - 0x(ptrval) ( 798 kB)
[ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[ 0.000000] ftrace: allocating 25657 entries in 76 pages
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000030] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
[ 0.000093] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
[ 0.000221] bcm2835: system timer (irq = 27)
[ 0.000638] Console: colour dummy device 80x30
[ 0.001280] console [tty1] enabled
[ 0.001364] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
[ 0.060396] pid_max: default: 32768 minimum: 301
[ 0.060979] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[ 0.061041] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[ 0.062500] CPU: Testing write buffer coherency: ok
[ 0.063862] Setting up static identity map for 0x8200 - 0x8238
[ 0.065337] devtmpfs: initialized
[ 0.076477] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[ 0.076965] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.077042] futex hash table entries: 256 (order: -1, 3072 bytes)
[ 0.078428] pinctrl core: initialized pinctrl subsystem
[ 0.080059] NET: Registered protocol family 16
[ 0.083366] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.090816] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[ 0.090892] hw-breakpoint: maximum watchpoint size is 4 bytes.
[ 0.091063] Serial: AMBA PL011 UART driver
[ 0.094370] bcm2835-mbox 2000b880.mailbox: mailbox enabled
[ 0.110709] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-02-12 12:38, variant start_cd
[ 0.120738] raspberrypi-firmware soc:firmware: Firmware hash is 53a54c770c493957d99bf49762dfabc4eee00e45
[ 0.172925] bcm2835-dma 20007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[ 0.175593] SCSI subsystem initialized
[ 0.175922] usbcore: registered new interface driver usbfs
[ 0.176069] usbcore: registered new interface driver hub
[ 0.176355] usbcore: registered new device driver usb
[ 0.178694] clocksource: Switched to clocksource timer
[ 0.289019] VFS: Disk quotas dquot_6.6.0
[ 0.289205] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.289571] FS-Cache: Loaded
[ 0.289960] CacheFiles: Loaded
[ 0.309548] NET: Registered protocol family 2
[ 0.310927] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes)
[ 0.311049] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.311166] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)[ 0.311287] TCP: Hash tables configured (established 4096 bind 4096)
[ 0.311484] UDP hash table entries: 256 (order: 0, 4096 bytes)
[ 0.311554] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[ 0.311998] NET: Registered protocol family 1
[ 0.313136] RPC: Registered named UNIX socket transport module.
[ 0.313200] RPC: Registered udp transport module.
[ 0.313231] RPC: Registered tcp transport module.
[ 0.313257] RPC: Registered tcp NFSv4.1 backchannel transport module.[ 0.315381] hw perfevents: no irqs for PMU, sampling events not supported
[ 0.315508] hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available
[ 0.320125] Initialise system trusted keyrings
[ 0.320590] workingset: timestamp_bits=14 max_order=17 bucket_order=3[ 0.337061] FS-Cache: Netfs 'nfs' registered for caching
[ 0.338527] NFS: Registering the id_resolver key type
[ 0.338624] Key type id_resolver registered
[ 0.338658] Key type id_legacy registered
[ 0.338819] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[ 0.344565] Key type asymmetric registered
[ 0.344637] Asymmetric key parser 'x509' registered
[ 0.344770] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[ 0.345279] io scheduler noop registered
[ 0.345336] io scheduler deadline registered (default)
[ 0.346007] io scheduler cfq registered
[ 0.346058] io scheduler mq-deadline registered (default)
[ 0.346091] io scheduler kyber registered
[ 0.349020] bcm2708_fb soc:fb: FB found 1 display(s)
[ 0.352050] Console: switching to colour frame buffer device 2x2
[ 0.353103] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 16x16
[ 0.357282] bcm2835-rng 20104000.rng: hwrng registered
[ 0.358137] vc-mem: phys_addr:0x00000000 mem_base=0x1fa00000 mem_size:0x20000000(512 MiB)
[ 0.360006] vc-sm: Videocore shared memory driver
[ 0.361073] gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000
[ 0.382288] brd: module loaded
[ 0.396368] loop: module loaded
[ 0.397524] Loading iSCSI transport class v2.0-870.
[ 0.399039] usbcore: registered new interface driver smsc95xx
[ 0.399524] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.427999] dwc_otg 20980000.usb: base=(ptrval)
[ 0.628862] Core Release: 2.80a
[ 0.629163] Setting default values for core params
[ 0.629557] Finished setting default values for core params
[ 0.830349] Using Buffer DMA mode
[ 0.830639] Periodic Transfer Interrupt Enhancement - disabled
[ 0.831069] Multiprocessor Interrupt Enhancement - disabled
[ 0.831472] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.831878] Dedicated Tx FIFOs mode
[ 0.832968] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = de514000 dma = 0x5e514000 len=9024
[ 0.833714] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 0.835249] dwc_otg: Microframe scheduler enabled
[ 0.835458] WARN::hcd_init_fiq:457: FIQ on core 0
[ 0.835833] WARN::hcd_init_fiq:458: FIQ ASM at c0526db4 length 36
[ 0.836287] WARN::hcd_init_fiq:497: MPHI regs_base at df810000
[ 0.836746] dwc_otg 20980000.usb: DWC OTG Controller
[ 0.837178] dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1
[ 0.837777] dwc_otg 20980000.usb: irq 56, io mem 0x00000000
[ 0.838228] Init: Port Power? op_state=1
[ 0.838525] Init: Power Port (0)
[ 0.839256] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[ 0.839887] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.840418] usb usb1: Product: DWC OTG Controller
[ 0.840767] usb usb1: Manufacturer: Linux 4.19.97+ dwc_otg_hcd
[ 0.841200] usb usb1: SerialNumber: 20980000.usb
[ 0.842721] hub 1-0:1.0: USB hub found
[ 0.843146] hub 1-0:1.0: 1 port detected
[ 0.844583] dwc_otg: FIQ enabled
[ 0.844596] dwc_otg: NAK holdoff enabled
[ 0.844602] dwc_otg: FIQ split-transaction FSM enabled
[ 0.844622] Module dwc_common_port init
[ 0.845184] usbcore: registered new interface driver usb-storage
[ 0.846155] mousedev: PS/2 mouse device common for all mice
[ 0.848003] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[ 0.849029] bcm2835-cpufreq: min=300000 max=700000
[ 0.850703] sdhci: Secure Digital Host Controller Interface driver
[ 0.851194] sdhci: Copyright(c) Pierre Ossman
[ 0.852212] sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe
[ 0.853006] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.854093] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.854709] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.855371] usbcore: registered new interface driver usbhid
[ 0.855796] usbhid: USB HID core driver
[ 0.857200] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[ 0.859854] [vc_sm_connected_init]: start
[ 0.863589] vc_vchi_sm_init: failed to open VCHI service (-1)
[ 0.863605] [vc_sm_connected_init]: failed to initialize shared memory service
[ 0.864594] [vc_sm_connected_init]: end - returning -1
[ 0.866881] Initializing XFRM netlink socket
[ 0.867327] NET: Registered protocol family 17
[ 0.867843] Key type dns_resolver registered
[ 0.870168] registered taskstats version 1
[ 0.870538] Loading compiled-in X.509 certificates
[ 0.883518] sdhost: log_buf @ (ptrval) (5e513000)
[ 0.919832] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 0.922041] of_cfs_init
[ 0.922415] of_cfs_init: OK
[ 0.923712] Waiting for root device PARTUUID=cb7b86f7-02...
[ 0.938026] random: fast init done
[ 0.972577] mmc0: host does not support reading read-only switch, assuming write-enable
[ 0.975748] mmc0: new high speed SDHC card at address 59b4
[ 0.977795] mmcblk0: mmc0:59b4 USD 7.51 GiB
[ 0.980760] mmcblk0: p1 p2
[ 1.025234] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 1.025958] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 1.037417] devtmpfs: mounted
[ 1.042619] Freeing unused kernel memory: 472K
[ 1.043000] This architecture does not have kernel memory protection.[ 1.043467] Run /sbin/init as init process
[ 1.059293] Indeed it is in host mode hprt0 = 00021501
[ 1.228824] usb 1-1: new high-speed USB device number 2 using dwc_otg[ 1.229884] Indeed it is in host mode hprt0 = 00001101
[ 1.439342] usb 1-1: New USB device found, idVendor=0424, idProduct=9512, bcdDevice= 2.00
[ 1.440028] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.442255] hub 1-1:1.0: USB hub found
[ 1.442818] hub 1-1:1.0: 3 ports detected
[ 1.758863] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 1.889339] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[ 1.890019] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.893952] smsc95xx v1.0.6
[ 1.958827] systemd[1]: System time before build time, advancing clock.
[ 1.989903] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-20980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:7e:c9:8c
[ 2.142275] NET: Registered protocol family 10
[ 2.145071] Segment Routing with IPv6
[ 2.217891] 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 -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[ 2.221146] systemd[1]: Detected architecture arm.
[ 2.233623] systemd[1]: Set hostname to <PiHole>.
[ 4.632312] random: systemd: uninitialized urandom read (16 bytes read)
[ 4.843136] random: systemd: uninitialized urandom read (16 bytes read)
[ 4.851878] systemd[1]: Created slice system-getty.slice.
[ 4.854171] random: systemd: uninitialized urandom read (16 bytes read)
[ 4.855634] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ 4.859988] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 4.862643] systemd[1]: Reached target Remote File Systems.
[ 4.866957] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 4.869784] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 4.873495] systemd[1]: Listening on udev Control Socket.
[ 7.262991] systemd[1]: Started File System Check Daemon to report status.
[ 7.470694] systemd[1]: Started Apply Kernel Variables.
[ 7.739993] systemd[1]: Started Journal Service.
[ 8.884093] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 10.256808] Adding 1605628k swap on /var/swap. Priority:-2 extents:9 across:1884156k SSFS
[ 11.078681] systemd-journald[77]: Received request to flush runtime journal from PID 1
[ 11.854677] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 11.857591] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[ 11.857628] [vc_sm_connected_init]: start
[ 11.888995] vc_sm_cma_vchi_init: failed to open VCHI service (-1)
[ 11.889012] [vc_sm_connected_init]: failed to initialize shared memory service
[ 17.717797] random: crng init done
[ 17.717822] random: 7 urandom warning(s) missed due to ratelimiting
[ 22.584181] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 24.101946] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
root@PiHole:~#
It's not a huge home network. 16 devices making requests, according to the dashboard. Peak queries is less than 1000 over the last 24 hours. Dashboard shows total queries as 51,631.
Top device is my android phone with 10348 requests. I don't know if that is unusually high. That figure is higher than Total requests so I'm assuming they are over different time periods.
BTW I noticed that pihole-FTL.log is 0 bytes and has been empty every time I checked in the last 24 hours.
Okay, it fails precisely every half an hour at :03 and :33, hence I guess this is a cron job, or a systemd timer. Please paste:
journalctl -u cron | tail -50
systemctl | grep 'timer'
And some of your journalctl -u pihole-FTL are missing line are truncated and line breaks are not where they should be. I see:
Mar 16 17:33:05 PiHole systemd[1]: Stopping LSB: pihole-FTL daemon...
Mar 16 17:33:09 PiHole dnsmasq[475]: log failed: Bad file descriptor
Mar 16 17:33:09 PiHole dnsmasq[475]: DHCPACK(eth0) 192.168.1.100 38:f9:d
Mar 16 17:33:09 PiHole dnsmasq[475]: failed to write /etc/pihole/dhcp.le
Mar 16 17:33:13 PiHole pihole-FTL[10106]: .....
Mar 16 17:33:14 PiHole pihole-FTL[10106]: Not stopped; may still be shut
Mar 16 17:33:14 PiHole systemd[1]: pihole-FTL.service: Control process e
Mar 16 17:33:14 PiHole systemd[1]: pihole-FTL.service: Failed with resul
Mar 16 17:33:14 PiHole systemd[1]: Stopped LSB: pihole-FTL daemon.
Mar 16 17:33:14 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
The full lines could be interesting, although they should not be relevant:
- Something makes systemd stopping/restarting the service every half an hour in a regular way. At least without any previous error message during the last 29 minutes, the first entry is systemd stopping it, sending a SIGTERM, which can be seen in first post dnsmasq log file.
- dnsmasq/pihole-FTL then are stopping a bit unclean, I found where the one log entry is coming from, right before the process is killed: pi-hole/pihole-FTL.service at 9e490775ff3b20f378acc9db7cec2ae6023fff7f · pi-hole/pi-hole · GitHub
- It is starting right afterwards. Since it's a sysvinit service, there is no autorestart(?), hence this again (also when checking the service file+log outputs) looks like a very regular
systemctl restart pihole-FTLorservice pihole-FTL restart
.
1 Like
Sorry - I was copy pasting from JuiceSSH on my phone which clearly truncates. This should be better.
root@PiHole:~# journalctl -u pihole-FTL
-- Logs begin at Sun 2020-03-15 16:06:21 GMT, end at Wed 2020-03-18 16:49:30 GMT. --
Mar 15 16:06:39 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
Mar 15 16:06:40 PiHole pihole-FTL[339]: Not running
Mar 15 16:06:43 PiHole su[437]: (to pihole) root on none
Mar 15 16:06:43 PiHole su[437]: pam_unix(su:session): session opened for user pihole by (uid=0)
Mar 15 16:06:55 PiHole pihole-FTL[339]: FTL started!
Mar 15 16:06:55 PiHole su[437]: pam_unix(su:session): session closed for user pihole
Mar 15 16:06:56 PiHole systemd[1]: Started LSB: pihole-FTL daemon.
Mar 16 17:33:05 PiHole systemd[1]: Stopping LSB: pihole-FTL daemon...
Mar 16 17:33:09 PiHole dnsmasq[475]: log failed: Bad file descriptor
Mar 16 17:33:09 PiHole dnsmasq[475]: DHCPACK(eth0) 192.168.1.100 38:f9:d3:04:4a:b4 Duncans-iMac
Mar 16 17:33:09 PiHole dnsmasq[475]: failed to write /etc/pihole/dhcp.leases: Bad file descriptor (retry in 60s)
Mar 16 17:33:13 PiHole pihole-FTL[10106]: .....
Mar 16 17:33:14 PiHole pihole-FTL[10106]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Mar 16 17:33:14 PiHole systemd[1]: pihole-FTL.service: Control process exited, code=exited, status=1/FAILURE
Mar 16 17:33:14 PiHole systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Mar 16 17:33:14 PiHole systemd[1]: Stopped LSB: pihole-FTL daemon.
Mar 16 17:33:14 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
Mar 16 17:33:14 PiHole pihole-FTL[10158]: /etc/init.d/pihole-FTL: line 66: kill: (475) - No such process
Mar 16 17:33:15 PiHole pihole-FTL[10158]: Stopped
Mar 16 17:33:16 PiHole su[10210]: (to pihole) root on none
Mar 16 17:33:16 PiHole su[10210]: pam_unix(su:session): session opened for user pihole by (uid=0)
Mar 16 17:33:26 PiHole pihole-FTL[10158]: FTL started!
Mar 16 17:33:26 PiHole su[10210]: pam_unix(su:session): session closed for user pihole
Mar 16 17:33:27 PiHole systemd[1]: Started LSB: pihole-FTL daemon.
Mar 16 18:03:54 PiHole systemd[1]: Stopping LSB: pihole-FTL daemon...
Mar 16 18:03:57 PiHole pihole-FTL[10429]: .
Mar 16 18:03:57 PiHole pihole-FTL[10429]: Stopped
Mar 16 18:03:57 PiHole systemd[1]: pihole-FTL.service: Succeeded.
Mar 16 18:03:57 PiHole systemd[1]: Stopped LSB: pihole-FTL daemon.
Mar 16 18:03:57 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
Mar 16 18:03:57 PiHole pihole-FTL[10465]: Not running
Mar 16 18:03:58 PiHole su[10510]: (to pihole) root on none
Mar 16 18:03:59 PiHole su[10510]: pam_unix(su:session): session opened for user pihole by (uid=0)
Mar 16 18:04:09 PiHole pihole-FTL[10465]: FTL started!
Mar 16 18:04:09 PiHole su[10510]: pam_unix(su:session): session closed for user pihole
Mar 16 18:04:09 PiHole systemd[1]: Started LSB: pihole-FTL daemon.
root@PiHole:~# journalctl -u cron | tail -50
Mar 18 15:09:01 PiHole CRON[11015]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Mar 18 15:09:01 PiHole CRON[11011]: pam_unix(cron:session): session closed for user root
Mar 18 15:10:01 PiHole CRON[11064]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:10:01 PiHole CRON[11068]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 15:10:01 PiHole CRON[11064]: pam_unix(cron:session): session closed for user root
Mar 18 15:17:01 PiHole CRON[11090]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:17:01 PiHole CRON[11095]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Mar 18 15:17:02 PiHole CRON[11090]: pam_unix(cron:session): session closed for user root
Mar 18 15:20:01 PiHole CRON[11138]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:20:01 PiHole CRON[11142]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 15:20:02 PiHole CRON[11138]: pam_unix(cron:session): session closed for user root
Mar 18 15:30:01 PiHole CRON[11162]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:30:01 PiHole CRON[11166]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 15:30:02 PiHole CRON[11162]: pam_unix(cron:session): session closed for user root
Mar 18 15:39:01 PiHole CRON[11186]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:39:01 PiHole CRON[11191]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Mar 18 15:39:01 PiHole CRON[11186]: pam_unix(cron:session): session closed for user root
Mar 18 15:40:01 PiHole CRON[11241]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:40:01 PiHole CRON[11245]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 15:40:02 PiHole CRON[11241]: pam_unix(cron:session): session closed for user root
Mar 18 15:50:01 PiHole CRON[11269]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 15:50:02 PiHole CRON[11273]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 15:50:02 PiHole CRON[11269]: pam_unix(cron:session): session closed for user root
Mar 18 16:00:02 PiHole CRON[11298]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:00:02 PiHole CRON[11302]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 16:00:03 PiHole CRON[11298]: pam_unix(cron:session): session closed for user root
Mar 18 16:09:02 PiHole CRON[11322]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:09:02 PiHole CRON[11326]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Mar 18 16:09:02 PiHole CRON[11322]: pam_unix(cron:session): session closed for user root
Mar 18 16:10:01 PiHole CRON[11374]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:10:01 PiHole CRON[11378]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 16:10:02 PiHole CRON[11374]: pam_unix(cron:session): session closed for user root
Mar 18 16:17:01 PiHole CRON[11396]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:17:01 PiHole CRON[11401]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Mar 18 16:17:03 PiHole CRON[11396]: pam_unix(cron:session): session closed for user root
Mar 18 16:20:01 PiHole CRON[11443]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:20:01 PiHole CRON[11447]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 16:20:02 PiHole CRON[11443]: pam_unix(cron:session): session closed for user root
Mar 18 16:30:01 PiHole CRON[11475]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:30:01 PiHole CRON[11479]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 16:30:02 PiHole CRON[11475]: pam_unix(cron:session): session closed for user root
Mar 18 16:39:01 PiHole CRON[11500]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:39:01 PiHole CRON[11505]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Mar 18 16:39:01 PiHole CRON[11500]: pam_unix(cron:session): session closed for user root
Mar 18 16:40:02 PiHole CRON[11556]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:40:02 PiHole CRON[11560]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 16:40:02 PiHole CRON[11556]: pam_unix(cron:session): session closed for user root
Mar 18 16:50:01 PiHole CRON[11590]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 18 16:50:01 PiHole CRON[11594]: (root) CMD ( PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Mar 18 16:50:01 PiHole CRON[11590]: pam_unix(cron:session): session closed for user root
root@PiHole:~# systemctl | grep 'timer'
timers.target loaded active active Timers
man-db.timer loaded active waiting Daily man-db regeneration
phpsessionclean.timer loaded active waiting Clean PHP session files every 30 mins
systemd-tmpfiles-clean.timer loaded active waiting Daily Cleanup of Temporary Directories
Clean PHP session files every 30 minutes matches the timeline.
Here's the cron jobs:
root@PiHole:~# crontab -l
# m h dom mon dow command
0 7 * * * pihole -up
SHELL=/bin/bash
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
45 2 * * * /usr/bin/curl -sSl https://raw.githubusercontent.com/mmotti/pihole-regex/master/install.py | /usr/bin/python3
Last three lines are to pull in a regex list at 2:45am each morning as detailed on GitHub - mmotti/pihole-regex: Custom regex filter list for use with Pi-hole.
Edit: Stripped out the crontab instructions
Don't do this. This will cause you issues. May not be related to this but please remove that from your configuration.
2 Likes
Removed from crontab. You are right - I should be aware when I am updating pihole.
@dunxd what is the output of
curl -sSl https://raw.githubusercontent.com/mmotti/pihole-regex/master/install.py | sudo python3
or
/usr/bin/curl -sSl https://raw.githubusercontent.com/mmotti/pihole-regex/master/install.py | /usr/bin/python3 (run as root)
from the command line?
Does all run through smoothly? And how long does it take to complete?
This should only interact with FTL once a day and it will send a pihole restartdns reload when it's done. No services or anything are installed - It's a one time job.
I would understand if this was only crashing just after the job was run, but I'm not sure as to why it would cause issues throughout the day.
Would definitely be interested to know the outcome of the commands being run outside of Cron, though. Might raise some questions.
2 Likes
root@PiHole:~# time curl -sSl https://raw.githubusercontent.com/mmotti/pihole-regex/master/install.py | sudo python3
[i] Root user detected
[i] Pi-hole path exists
[i] Legacy regex.list detected
[i] Fetching: https://raw.githubusercontent.com/mmotti/pihole-regex/master/regex.list
[i] 16 regexps collected from https://raw.githubusercontent.com/mmotti/pihole-regex/master/regex.list
[i] Collecting existing entries from regex.list
[i] 16 existing regexps identified
[i] Existing mmotti-regex install identified
[i] Removing previously installed regexps
[i] Syncing with https://raw.githubusercontent.com/mmotti/pihole-regex/master/regex.list
[i] Outputting 16 regexps to /etc/pihole/regex.list
[i] Restarting Pi-hole
[i] Done - Please see your installed regexps below
^(.+[_.-])?ad[sxv]?[0-9]*[_.-]
^(.+[_.-])?adse?rv(er?|ice)?s?[0-9]*[_.-]
^(.+[_.-])?telemetry[_.-]
^(www[0-9]*\.)?xn--
^adim(age|g)s?[0-9]*[_.-]
^adtrack(er|ing)?[0-9]*[_.-]
^advert(s|is(ing|ements?))?[0-9]*[_.-]
^aff(iliat(es?|ion))?[_.-]
^analytics?[_.-]
^banners?[_.-]
^beacons?[0-9]*[_.-]
^count(ers?)?[0-9]*[_.-]
^mads\.
^pixels?[-.]
^stat(s|istics)?[0-9]*[_.-]
^track(ing)?[0-9]*[_.-]
real 0m5.296s
user 0m3.679s
sys 0m0.424s
root@PiHole:~#
This only runs at 2:45am daily. Judging from the freqency of commits (Commit Activity · mmotti/pihole-regex · GitHub) updating once a week is probably enough.
But does it seem at all likely this is related to the issue I am having?
Thanks for confirming, mate.
From this I would determine that the script is unlikely to be causing you issues. The reason why it would have been mentioned really is to rule any third party changes out 
2 Likes
Delved a little further into /etc/cron files:
/etc/cron.d/php
# Look for and purge old sessions every 30 minutes
09,39 * * * * root [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi
Could be this?
/etc/cron.d/pihole - I'm sure you are familiar with this:
# Pi-hole: Update the ad sources once a week on Sunday at a random time in the
# early morning. Download any updates from the adlists
# Squash output to log, then splat the log to stdout on error to allow for
# standard crontab job error handling.
39 4 * * 7 root PATH="$PATH:/usr/local/bin/" pihole updateGravity >/var/log/pihole_updateGravity.log || cat /var/log/pihole_updateGravity.log
# Pi-hole: Flush the log daily at 00:00
# The flush script will use logrotate if available
# parameter "once": logrotate only once (default is twice)
# parameter "quiet": don't print messages
00 00 * * * root PATH="$PATH:/usr/local/bin/" pihole flush once quiet
@reboot root /usr/sbin/logrotate /etc/pihole/logrotate
# Pi-hole: Grab local version and branch every 10 minutes
*/10 * * * * root PATH="$PATH:/usr/local/bin/" pihole updatechecker local
# Pi-hole: Grab remote version every 24 hours
47 12 * * * root PATH="$PATH:/usr/local/bin/" pihole updatechecker remote
@reboot root PATH="$PATH:/usr/local/bin/" pihole updatechecker remote reboot
/etc/cron.hourly/dietpi
#!/bin/bash
{
#////////////////////////////////////
# DietPi Cron.Hourly script
#
#////////////////////////////////////
#
# Info:
# - Location /etc/cron.hourly/dietpi
#
#////////////////////////////////////
if [[ -f '/DietPi/dietpi/.installed' ]]; then
LOGGING_MODE=$(grep -m1 '^[[:blank:]]*INDEX_LOGGING_CURRENT=' /DietPi/dietpi/.installed | sed 's/^[^=]*=//')
fi
LOGGING_MODE=${LOGGING_MODE:-0}
#----------------------------------------------------------------
# Main Loop
#----------------------------------------------------------------
# Time sync update, if mode 3 (hourly) is detected
if grep -qi '^[[:blank:]]*CONFIG_NTP_MODE=3' /DietPi/dietpi.txt; then
/DietPi/dietpi/func/run_ntpd 1 &> /dev/null &
fi
#----------------------------------------------------------------
# Logging
# - Clear all log files.
if (( $LOGGING_MODE == -1 )); then
/DietPi/dietpi/func/dietpi-logclear 1 &> /dev/null
# - Update current log files data to /$HOME/logfile_storage/*. Then clear.
elif (( $LOGGING_MODE == -2 )); then
/DietPi/dietpi/func/dietpi-logclear 0 &> /dev/null
fi
#----------------------------------------------------------------
exit
#----------------------------------------------------------------
}
/etc/cron.hourly/fake-hwclock
#!/bin/sh
#
# Simple cron script - save the current clock periodically in case of
# a power failure or other crash
if (command -v fake-hwclock >/dev/null 2>&1) ; then
fake-hwclock save
fi
I'm not going to list contents of everything in the other folders, but I will list the filenames - let me know if any are worth looking at more closely. None are customised by me.
root@PiHole:/etc# ls cron.d
php pihole
root@PiHole:/etc# ls cron.daily
apt-compat bsdmainutils dietpi dpkg lighttpd man-db passwd
root@PiHole:/etc# ls cron.hourly
dietpi fake-hwclock
root@PiHole:/etc# ls cron.minutely/
readme.txt
root@PiHole:/etc# ls cron.monthly
root@PiHole:/etc# cat crontab
# Please use dietpi-cron to change cron start times
SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
# m h dom mon dow user command
#*/0 * * * * root cd / && run-parts --report /etc/cron.minutely
17 * * * * root cd / && run-parts --report /etc/cron.hourly
25 1 * * * root test -x /usr/sbin/anacron || { cd / && run-parts --report /etc/cron.daily; }
47 1 * * 7 root test -x /usr/sbin/anacron || { cd / && run-parts --report /etc/cron.weekly; }
52 1 1 * * root test -x /usr/sbin/anacron || { cd / && run-parts --report /etc/cron.monthly; }
Dietpi-cron config:
│ cron.minutely : Disabled │
│ cron.hourly : Every Hour at 17 Minutes │
│ cron.daily : Every Day at 1 Hours and 25 Minutes │
│ cron.weekly : Every Sunday at 1 Hours and 47 Minutes │
│ cron.monthly : On Day 1 of the month at 1 Hours and 52 Minutes
So the cron job restarts Pi-hole expectedly, although probably pihole restartdns reload only. Same for pihole -up (and I agree this should not be done unattended) and both only run daily, hence those two cannot be the reason.
The logs are not 100% failsafe comparable since journalctl -u pihole-FTL is from Mar 16 while journalctl -u cron is from today, however, I guess you didn't change cron execution times meanwhile.
- PHP sessionclean from cron is inactive, because the systemd timer is active instead.
pihole updatechecker localis definitely not the culprit, I checked the code, no change this breaks something.- Also both of them run in no time, rarely possible that this causes a regular pihole-FTL restart 3 minutes later.
- Hourly cron is, yeah only hourly, and also time does not match...
Lets check the systemd timers:
journalctl -u phpsessionclean | tail -20
journalctl -u systemd-tmpfiles-clean | tail -20 # although should be daily only
journalctl -u man-db | tail -20 # although should be daily only
Is there a chance that RAM gets filled, free -m and finally, could you send a DietPi bugreport: dietpi-bugreport 1
1 Like
root@PiHole:~# free -m
total used free shared buff/cache available
Mem: 480 201 33 20 245 208
Swap: 1567 6 1561
I've been ssh'd in and running htop a lot, and I noticed when the CPU was at 100% memory was never much higher than normal (below 50%). Of course I may not have noticed any spikes that occurred immediately before high CPU.
root@PiHole:~# dietpi-bugreport 1
[ INFO ] DietPi-Bugreport | Packing upload archive, please wait...
[ OK ] DietPi-Bugreport | Connection test: ssh.dietpi.com
[ OK ] DietPi-Bugreport | Bug report sent, reference code: db81edf8-d74a-43e4-b7b0-1a2f12e29968
1 Like
Can you also try pihole -d again, there was an issue with the TLS cert that has been fixed.
1 Like
Working now!
[✓] Your debug token is: https://tricorder.pi-hole.net/9q0t49soi7
Could you run dietpi-bugreport 1 again please, I needed to make a little cleanup and made an accident 
.