Nightly outage of all data between 02:28 and 03:38

Emoncms
1

Hi All!

First time poster, but I have a fairly comprehensive setup based around an Emonpi monitoring Solar, battery & ASHP. Absolutely love the product and would be lost without it :slight_smile:

One thing which has me puzzled however is that there seems to be a period between 02:28 & 03:38 every night when the Pi is offline.

I have looked into the logs and it seems that there isnā€™t anything of interest in thereā€¦ An excerpt from last night just shows the following around that time:
2022-01-10 02:17:50.489|WARN|emoncms_mqtt.php|Not connected, retrying connection
2022-01-10 02:17:50.568|WARN|emoncms_mqtt.php|Connecting to MQTT server: Connection Accepted.: code: 0

Does anyone here have any ideas as to what this may be, or how I may be able to debug whatā€™s going on / been going on at all?

Many thanks!

2

Bump, although this time although the start time of the outage was consistent the end time was slightly earlier:

Screenshot_20220111-091048
Screenshot_20220111-091048864Ɨ1824 208 KB

3

Can you paste in the system information from your Admin ā†’ System Information page?
If you use the ā€œCopy as Markdownā€ button and paste it into a post, it will be nicely formatted for you.

image
image1112Ɨ218 26.9 KB

4

Sureā€¦

Server Information

Server Information

Services

  • emonhub :- Active Running

  • emoncms_mqtt :- Active Running

  • feedwriter :- Active Running - sleep 300s 75 feed points pending write

  • service-runner :- Active Running

  • emonPiLCD :- Active Running

  • redis-server :- Active Running

  • mosquitto :- Active Running

  • demandshaper :- Active Running

Emoncms

Server

  • OS :- Linux 4.19.118-v7+
  • Host :- emonpi | emonpi | (192.168.1.101)
  • Date :- 2022-01-11 11:06:31 UTC
  • Uptime :- 11:06:31 up 7:51, 0 users, load average: 0.02, 0.08, 0.08

Memory

  • RAM :- Used: 18.35%
    • Total :- 975.6 MB
    • Used :- 179.01 MB
    • Free :- 796.59 MB
  • Swap :- Used: 0.00%
    • Total :- 100 MB
    • Used :- 0 B
    • Free :- 100 MB
      Write Load Period

Disk

  • / :- Used: 49.02%
    • Total :- 3.92 GB
    • Used :- 1.92 GB
    • Free :- 1.81 GB
    • Write Load :- n/a
  • /boot :- Used: 20.24%
    • Total :- 252.05 MB
    • Used :- 51.01 MB
    • Free :- 201.04 MB
    • Write Load :- n/a
  • /var/opt/emoncms :- Used: 3.34%
    • Total :- 9.98 GB
    • Used :- 341.49 MB
    • Free :- 9.14 GB
    • Write Load :- n/a
  • /var/log :- Used: 3.06%
    • Total :- 50 MB
    • Used :- 1.53 MB
    • Free :- 48.47 MB
    • Write Load :- n/a

HTTP

  • Server :- Apache/2.4.38 (Raspbian) HTTP/1.1 CGI/1.1 80

MySQL

  • Version :- 5.5.5-10.3.22-MariaDB-0+deb10u1
  • Host :- 127.0.0.1 (127.0.0.1)
  • Date :- 2022-01-11 11:06:31 (UTC 00:00ā€Œā€‹)
  • Stats :- Uptime: 31719 Threads: 11 Questions: 27372 Slow queries: 0 Opens: 48 Flush tables: 1 Open tables: 41 Queries per second avg: 0.862

Redis

  • Version :-
    • Redis Server :- 5.0.3
    • PHP Redis :- 5.0.2
  • Host :- localhost:6379
  • Size :- 155 keys (878.83K)
  • Uptime :- 0 days

MQTT Server

  • Version :- Mosquitto 1.5.7
  • Host :- localhost:1883 (127.0.0.1)

PHP

  • Version :- 7.3.19-1~deb10u1 (Zend Version 3.3.19)
  • Modules :- apache2handlercalendar Core ctype curl date dom v20031129exif fileinfo filter ftp gd gettext hash iconv json v1.7.0libxml mbstring mosquitto v0.4.0mysqli mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: 7cc7cc96e675f6d72e5cf0f267f48e167c2abb23 $openssl pcre PDO pdo_mysql Phar posix readline redis v5.0.2Reflection session shmop SimpleXML sockets sodium SPL standard sysvmsg sysvsem sysvshm tokenizer wddx xml xmlreader xmlwriter xsl Zend OPcache zlib

Pi

  • Model :- Raspberry Pi 3 Model B Rev 1.2 - 1GB (Embest)

  • Serial num. :- 9B30EA9A

  • CPU Temperature :- 41.86Ā°C

  • GPU Temperature :- 40.8Ā°C

  • emonpiRelease :- emonSD-17Oct19

  • File-system :- read-write

Client Information

Client Information

HTTP

  • Browser :- Mozilla/5.0 (Linux; Android 12; Pixel 4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.104 Mobile Safari/537.36
  • Language :- en-GB,en-US;q=0.9,en;q=0.8

Window

  • Size :- 393 x 727

Screen

  • Resolution :- 393 x 830
5

So it looks like your Pi rebooted at (11:06 - 7:51) 3:15AM?
Are you losing power to it?

Do you have SSH access? If so, can you check the contents of /var/log/syslog around the relevant time?

6

Probably not relevant for you, but I had a related problem where a subset of my data was always missing between midnight and about 1:00 am. It took a while to track down, but in my case the data was being captured from a ā€œsmartā€ hybrid inverter through mqtt. Apparently this inverter goes offline for about 15 minutes at midnight while it checks for - and installs - any firmware updates!

7

Thanks for the replies :slight_smile:

I should have ssh, Iā€™ll try at lunch and pull any relevant logs. I donā€™t think thereā€™s any reason it could lose power. The weird thing is that it is in the cupboard with our ashp controllers and it occurs nightly when the domestic hot water is heating up. Not sure if this is linked?

I did think it was more likely to be one of the peripheral devices sending days in but then as greebo noticed I saw the actual pi was logging a reboot.

8

Apologies for the massive file dump, I tried to attach but couldnā€™t attach a text file.
Looks like the pi reboots at the start time of the outage (~02:18)

I wonder why it then takes > 1 hour to start logging data again? This includes the sensors directly attached to the pi (I have 3 heat sensors attached which donā€™t log anything in the ā€˜outageā€™ period)

Can you see any clues in the log?

Jan 12 02:15:26 emonpi rngd[398]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Jan 12 02:15:26 emonpi rngd[398]: stats: FIPS 140-2(2001-10-10) Poker: 0
Jan 12 02:15:26 emonpi rngd[398]: stats: FIPS 140-2(2001-10-10) Runs: 0
Jan 12 02:15:26 emonpi rngd[398]: stats: FIPS 140-2(2001-10-10) Long run: 0
Jan 12 02:15:26 emonpi rngd[398]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Jan 12 02:15:26 emonpi rngd[398]: stats: HRNG source speed: (min=593.619; avg=908.361; max=939.590)Kibits/s
Jan 12 02:15:26 emonpi rngd[398]: stats: FIPS tests speed: (min=5.558; avg=6.866; max=7.036)Mibits/s
Jan 12 02:15:26 emonpi rngd[398]: stats: Lowest ready-buffers level: 2
Jan 12 02:15:26 emonpi rngd[398]: stats: Entropy starvations: 0
Jan 12 02:15:26 emonpi rngd[398]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Jan 12 02:17:01 emonpi CRON[16945]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 12 02:17:01 emonpi systemd[1]: Reloading Log2Ram.
Jan 12 02:17:01 emonpi log2ram[16955]: sending incremental file list
Jan 12 02:17:01 emonpi log2ram[16955]: auth.log
Jan 12 02:17:01 emonpi log2ram[16955]: daemon.log
Jan 12 02:17:01 emonpi log2ram[16955]: log2ram.log
Jan 12 02:18:32 emonpi kernel: [    0.000000] Booting Linux on physical CPU 0x0
Jan 12 02:18:32 emonpi kernel: [    0.000000] Linux version 4.19.118-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1311 SMP Mon Apr 27 14:21:24 BST 2020
Jan 12 02:18:32 emonpi kernel: [    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
Jan 12 02:18:32 emonpi kernel: [    0.000000] CPU: div instructions available: patching division code
Jan 12 02:18:32 emonpi kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Jan 12 02:18:32 emonpi kernel: [    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
Jan 12 02:18:32 emonpi kernel: [    0.000000] Memory policy: Data cache writealloc
Jan 12 02:18:32 emonpi kernel: [    0.000000] cma: Reserved 8 MiB at 0x3dc00000
Jan 12 02:18:32 emonpi kernel: [    0.000000] On node 0 totalpages: 255488
Jan 12 02:18:32 emonpi kernel: [    0.000000]   Normal zone: 2246 pages used for memmap
Jan 12 02:18:32 emonpi kernel: [    0.000000]   Normal zone: 0 pages reserved
Jan 12 02:18:32 emonpi kernel: [    0.000000]   Normal zone: 255488 pages, LIFO batch:63
Jan 12 02:18:32 emonpi kernel: [    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
Jan 12 02:18:32 emonpi kernel: [    0.000000] percpu: Embedded 16 pages/cpu s36864 r8192 d20480 u65536
Jan 12 02:18:32 emonpi kernel: [    0.000000] pcpu-alloc: s36864 r8192 d20480 u65536 alloc=16*4096
Jan 12 02:18:32 emonpi kernel: [    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
Jan 12 02:18:32 emonpi kernel: [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 253242
Jan 12 02:18:32 emonpi kernel: [    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000  console=tty1 root=PARTUUID=6c586e13-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
Jan 12 02:18:32 emonpi kernel: [    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.000000] Memory: 989796K/1021952K available (8192K kernel code, 656K rwdata, 2232K rodata, 1024K init, 831K bss, 23964K reserved, 8192K cma-reserved)
Jan 12 02:18:32 emonpi kernel: [    0.000000] Virtual kernel memory layout:
Jan 12 02:18:32 emonpi kernel: [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]     vmalloc : 0xbe800000 - 0xff800000   (1040 MB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]     lowmem  : 0x80000000 - 0xbe600000   ( 998 MB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]       .text : 0x(ptrval) - 0x(ptrval)   (9184 kB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]       .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]       .data : 0x(ptrval) - 0x(ptrval)   ( 657 kB)
Jan 12 02:18:32 emonpi kernel: [    0.000000]        .bss : 0x(ptrval) - 0x(ptrval)   ( 832 kB)
Jan 12 02:18:32 emonpi kernel: [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Jan 12 02:18:32 emonpi kernel: [    0.000000] ftrace: allocating 27093 entries in 80 pages
Jan 12 02:18:32 emonpi kernel: [    0.000000] rcu: Hierarchical RCU implementation.
Jan 12 02:18:32 emonpi kernel: [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
Jan 12 02:18:32 emonpi kernel: [    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
Jan 12 02:18:32 emonpi kernel: [    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
Jan 12 02:18:32 emonpi kernel: [    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
Jan 12 02:18:32 emonpi kernel: [    0.000023] Switching to timer-based delay loop, resolution 52ns
Jan 12 02:18:32 emonpi kernel: [    0.000273] Console: colour dummy device 80x30
Jan 12 02:18:32 emonpi kernel: [    0.000905] console [tty1] enabled
Jan 12 02:18:32 emonpi kernel: [    0.000963] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
Jan 12 02:18:32 emonpi kernel: [    0.001006] pid_max: default: 32768 minimum: 301
Jan 12 02:18:32 emonpi kernel: [    0.001372] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.001408] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.002363] CPU: Testing write buffer coherency: ok
Jan 12 02:18:32 emonpi kernel: [    0.002843] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Jan 12 02:18:32 emonpi kernel: [    0.003517] Setting up static identity map for 0x100000 - 0x10003c
Jan 12 02:18:32 emonpi kernel: [    0.003686] rcu: Hierarchical SRCU implementation.
Jan 12 02:18:32 emonpi kernel: [    0.004516] smp: Bringing up secondary CPUs ...
Jan 12 02:18:32 emonpi kernel: [    0.005422] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
Jan 12 02:18:32 emonpi kernel: [    0.006391] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
Jan 12 02:18:32 emonpi kernel: [    0.007306] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
Jan 12 02:18:32 emonpi kernel: [    0.007420] smp: Brought up 1 node, 4 CPUs
Jan 12 02:18:32 emonpi kernel: [    0.007501] SMP: Total of 4 processors activated (153.60 BogoMIPS).
Jan 12 02:18:32 emonpi kernel: [    0.007525] CPU: All CPU(s) started in HYP mode.
Jan 12 02:18:32 emonpi kernel: [    0.007546] CPU: Virtualization extensions available.
Jan 12 02:18:32 emonpi kernel: [    0.008546] devtmpfs: initialized
Jan 12 02:18:32 emonpi kernel: [    0.021815] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
Jan 12 02:18:32 emonpi kernel: [    0.022088] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
Jan 12 02:18:32 emonpi kernel: [    0.022138] futex hash table entries: 1024 (order: 4, 65536 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.022745] pinctrl core: initialized pinctrl subsystem
Jan 12 02:18:32 emonpi kernel: [    0.023623] NET: Registered protocol family 16
Jan 12 02:18:32 emonpi kernel: [    0.026772] DMA: preallocated 1024 KiB pool for atomic coherent allocations
Jan 12 02:18:32 emonpi kernel: [    0.032647] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
Jan 12 02:18:32 emonpi kernel: [    0.032683] hw-breakpoint: maximum watchpoint size is 8 bytes.
Jan 12 02:18:32 emonpi kernel: [    0.032900] Serial: AMBA PL011 UART driver
Jan 12 02:18:32 emonpi kernel: [    0.035237] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
Jan 12 02:18:32 emonpi kernel: [    0.050032] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-04-15 11:43, variant start_cd
Jan 12 02:18:32 emonpi kernel: [    0.060044] raspberrypi-firmware soc:firmware: Firmware hash is 82f9bb929ce2186eb1824178c1ae82902ad6275c
Jan 12 02:18:32 emonpi kernel: [    0.103323] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
Jan 12 02:18:32 emonpi kernel: [    0.104986] SCSI subsystem initialized
Jan 12 02:18:32 emonpi kernel: [    0.105220] usbcore: registered new interface driver usbfs
Jan 12 02:18:32 emonpi kernel: [    0.105294] usbcore: registered new interface driver hub
Jan 12 02:18:32 emonpi kernel: [    0.105413] usbcore: registered new device driver usb
Jan 12 02:18:32 emonpi kernel: [    0.107096] clocksource: Switched to clocksource arch_sys_counter
Jan 12 02:18:32 emonpi kernel: [    0.197613] VFS: Disk quotas dquot_6.6.0
Jan 12 02:18:32 emonpi kernel: [    0.197724] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.197894] FS-Cache: Loaded
Jan 12 02:18:32 emonpi kernel: [    0.198113] CacheFiles: Loaded
Jan 12 02:18:32 emonpi kernel: [    0.208126] NET: Registered protocol family 2
Jan 12 02:18:32 emonpi kernel: [    0.208990] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.209055] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.209185] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.209389] TCP: Hash tables configured (established 8192 bind 8192)
Jan 12 02:18:32 emonpi kernel: [    0.209546] UDP hash table entries: 512 (order: 2, 16384 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.209616] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.209872] NET: Registered protocol family 1
Jan 12 02:18:32 emonpi kernel: [    0.210472] RPC: Registered named UNIX socket transport module.
Jan 12 02:18:32 emonpi kernel: [    0.210499] RPC: Registered udp transport module.
Jan 12 02:18:32 emonpi kernel: [    0.210521] RPC: Registered tcp transport module.
Jan 12 02:18:32 emonpi kernel: [    0.210542] RPC: Registered tcp NFSv4.1 backchannel transport module.
Jan 12 02:18:32 emonpi kernel: [    0.212369] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
Jan 12 02:18:32 emonpi kernel: [    0.215475] Initialise system trusted keyrings
Jan 12 02:18:32 emonpi kernel: [    0.215680] workingset: timestamp_bits=14 max_order=18 bucket_order=4
Jan 12 02:18:32 emonpi kernel: [    0.225642] FS-Cache: Netfs 'nfs' registered for caching
Jan 12 02:18:32 emonpi kernel: [    0.226225] NFS: Registering the id_resolver key type
Jan 12 02:18:32 emonpi kernel: [    0.226277] Key type id_resolver registered
Jan 12 02:18:32 emonpi kernel: [    0.226300] Key type id_legacy registered
Jan 12 02:18:32 emonpi kernel: [    0.226331] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
Jan 12 02:18:32 emonpi kernel: [    0.231790] Key type asymmetric registered
Jan 12 02:18:32 emonpi kernel: [    0.231827] Asymmetric key parser 'x509' registered
Jan 12 02:18:32 emonpi kernel: [    0.231902] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
Jan 12 02:18:32 emonpi kernel: [    0.232096] io scheduler noop registered
Jan 12 02:18:32 emonpi kernel: [    0.232122] io scheduler deadline registered (default)
Jan 12 02:18:32 emonpi kernel: [    0.232338] io scheduler cfq registered
Jan 12 02:18:32 emonpi kernel: [    0.232362] io scheduler mq-deadline registered (default)
Jan 12 02:18:32 emonpi kernel: [    0.232387] io scheduler kyber registered
Jan 12 02:18:32 emonpi kernel: [    0.235482] bcm2708_fb soc:fb: FB found 1 display(s)
Jan 12 02:18:32 emonpi kernel: [    0.240860] Console: switching to colour frame buffer device 82x26
Jan 12 02:18:32 emonpi kernel: [    0.244995] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
Jan 12 02:18:32 emonpi kernel: [    0.248788] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
Jan 12 02:18:32 emonpi kernel: [    0.251636] bcm2835-rng 3f104000.rng: hwrng registered
Jan 12 02:18:32 emonpi kernel: [    0.253362] vc-mem: phys_addr:0x00000000 mem_base=0x3f000000 mem_size:0x3f600000(1014 MiB)
Jan 12 02:18:32 emonpi kernel: [    0.256690] vc-sm: Videocore shared memory driver
Jan 12 02:18:32 emonpi kernel: [    0.258508] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
Jan 12 02:18:32 emonpi kernel: [    0.272280] brd: module loaded
Jan 12 02:18:32 emonpi kernel: [    0.283870] loop: module loaded
Jan 12 02:18:32 emonpi kernel: [    0.285930] Loading iSCSI transport class v2.0-870.
Jan 12 02:18:32 emonpi kernel: [    0.288118] libphy: Fixed MDIO Bus: probed
Jan 12 02:18:32 emonpi kernel: [    0.289624] usbcore: registered new interface driver lan78xx
Jan 12 02:18:32 emonpi kernel: [    0.291111] usbcore: registered new interface driver smsc95xx
Jan 12 02:18:32 emonpi kernel: [    0.292532] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Jan 12 02:18:32 emonpi kernel: [    0.321814] dwc_otg 3f980000.usb: base=(ptrval)
Jan 12 02:18:32 emonpi kernel: [    0.523484] Core Release: 2.80a
Jan 12 02:18:32 emonpi kernel: [    0.524915] Setting default values for core params
Jan 12 02:18:32 emonpi kernel: [    0.526378] Finished setting default values for core params
Jan 12 02:18:32 emonpi kernel: [    0.728139] Using Buffer DMA mode
Jan 12 02:18:32 emonpi kernel: [    0.729541] Periodic Transfer Interrupt Enhancement - disabled
Jan 12 02:18:32 emonpi kernel: [    0.730944] Multiprocessor Interrupt Enhancement - disabled
Jan 12 02:18:32 emonpi kernel: [    0.732327] OTG VER PARAM: 0, OTG VER FLAG: 0
Jan 12 02:18:32 emonpi kernel: [    0.733693] Dedicated Tx FIFOs mode
Jan 12 02:18:32 emonpi kernel: [    0.735451] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bdd04000 dma = 0xfdd04000 len=9024
Jan 12 02:18:32 emonpi kernel: [    0.738156] FIQ FSM acceleration enabled for :
Jan 12 02:18:32 emonpi kernel: [    0.738156] Non-periodic Split Transactions
Jan 12 02:18:32 emonpi kernel: [    0.738156] Periodic Split Transactions
Jan 12 02:18:32 emonpi kernel: [    0.738156] High-Speed Isochronous Endpoints
Jan 12 02:18:32 emonpi kernel: [    0.738156] Interrupt/Control Split Transaction hack enabled
Jan 12 02:18:32 emonpi kernel: [    0.744506] dwc_otg: Microframe scheduler enabled
Jan 12 02:18:32 emonpi kernel: [    0.744563] WARN::hcd_init_fiq:457: FIQ on core 1
Jan 12 02:18:32 emonpi kernel: [    0.745871] WARN::hcd_init_fiq:458: FIQ ASM at 8068fda0 length 36
Jan 12 02:18:32 emonpi kernel: [    0.747169] WARN::hcd_init_fiq:497: MPHI regs_base at be810000
Jan 12 02:18:32 emonpi kernel: [    0.748493] dwc_otg 3f980000.usb: DWC OTG Controller
Jan 12 02:18:32 emonpi kernel: [    0.749838] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
Jan 12 02:18:32 emonpi kernel: [    0.751208] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
Jan 12 02:18:32 emonpi kernel: [    0.752574] Init: Port Power? op_state=1
Jan 12 02:18:32 emonpi kernel: [    0.753885] Init: Power Port (0)
Jan 12 02:18:32 emonpi kernel: [    0.755405] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
Jan 12 02:18:32 emonpi kernel: [    0.758056] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jan 12 02:18:32 emonpi kernel: [    0.759467] usb usb1: Product: DWC OTG Controller
Jan 12 02:18:32 emonpi kernel: [    0.760850] usb usb1: Manufacturer: Linux 4.19.118-v7+ dwc_otg_hcd
Jan 12 02:18:32 emonpi kernel: [    0.762266] usb usb1: SerialNumber: 3f980000.usb
Jan 12 02:18:32 emonpi kernel: [    0.764226] hub 1-0:1.0: USB hub found
Jan 12 02:18:32 emonpi kernel: [    0.765582] hub 1-0:1.0: 1 port detected
Jan 12 02:18:32 emonpi kernel: [    0.767461] dwc_otg: FIQ enabled
Jan 12 02:18:32 emonpi kernel: [    0.767468] dwc_otg: NAK holdoff enabled
Jan 12 02:18:32 emonpi kernel: [    0.767473] dwc_otg: FIQ split-transaction FSM enabled
Jan 12 02:18:32 emonpi kernel: [    0.767484] Module dwc_common_port init
Jan 12 02:18:32 emonpi kernel: [    0.767752] usbcore: registered new interface driver usb-storage
Jan 12 02:18:32 emonpi kernel: [    0.769264] mousedev: PS/2 mouse device common for all mice
Jan 12 02:18:32 emonpi kernel: [    0.771466] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
Jan 12 02:18:32 emonpi kernel: [    0.773101] bcm2835-cpufreq: min=600000 max=1200000
Jan 12 02:18:32 emonpi kernel: [    0.774950] sdhci: Secure Digital Host Controller Interface driver
Jan 12 02:18:32 emonpi kernel: [    0.776357] sdhci: Copyright(c) Pierre Ossman
Jan 12 02:18:32 emonpi kernel: [    0.778168] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
Jan 12 02:18:32 emonpi kernel: [    0.780049] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
Jan 12 02:18:32 emonpi kernel: [    0.781665] sdhci-pltfm: SDHCI platform and OF driver helper
Jan 12 02:18:32 emonpi kernel: [    0.784690] ledtrig-cpu: registered to indicate activity on CPUs
Jan 12 02:18:32 emonpi kernel: [    0.786378] hidraw: raw HID events driver (C) Jiri Kosina
Jan 12 02:18:32 emonpi kernel: [    0.788098] usbcore: registered new interface driver usbhid
Jan 12 02:18:32 emonpi kernel: [    0.789621] usbhid: USB HID core driver
Jan 12 02:18:32 emonpi kernel: [    0.791841] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
Jan 12 02:18:32 emonpi kernel: [    0.794760] [vc_sm_connected_init]: start
Jan 12 02:18:32 emonpi kernel: [    0.798206] vc_vchi_sm_init: failed to open VCHI service (-1)
Jan 12 02:18:32 emonpi kernel: [    0.798212] [vc_sm_connected_init]: failed to initialize shared memory service
Jan 12 02:18:32 emonpi kernel: [    0.801156] [vc_sm_connected_init]: end - returning -1
Jan 12 02:18:32 emonpi kernel: [    0.803791] Initializing XFRM netlink socket
Jan 12 02:18:32 emonpi kernel: [    0.805280] NET: Registered protocol family 17
Jan 12 02:18:32 emonpi kernel: [    0.806870] Key type dns_resolver registered
Jan 12 02:18:32 emonpi kernel: [    0.808960] Registering SWP/SWPB emulation handler
Jan 12 02:18:32 emonpi kernel: [    0.811069] registered taskstats version 1
Jan 12 02:18:32 emonpi kernel: [    0.812500] Loading compiled-in X.509 certificates
Jan 12 02:18:32 emonpi kernel: [    0.820581] uart-pl011 3f201000.serial: cts_event_workaround enabled
Jan 12 02:18:32 emonpi kernel: [    0.822119] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
Jan 12 02:18:32 emonpi kernel: [    0.826885] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
Jan 12 02:18:32 emonpi kernel: [    0.828404] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
Jan 12 02:18:32 emonpi kernel: [    0.856046] sdhost: log_buf @ (ptrval) (fdd07000)
Jan 12 02:18:32 emonpi kernel: [    0.892378] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
Jan 12 02:18:32 emonpi systemd-modules-load[111]: Inserted module 'i2c_dev'
Jan 12 02:18:32 emonpi kernel: [    0.895389] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.898360] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.902510] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
Jan 12 02:18:32 emonpi kernel: [    0.906368] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
Jan 12 02:18:32 emonpi kernel: [    0.908968] of_cfs_init
Jan 12 02:18:32 emonpi kernel: [    0.910312] of_cfs_init: OK
Jan 12 02:18:32 emonpi kernel: [    0.912050] Waiting for root device PARTUUID=6c586e13-02...
Jan 12 02:18:32 emonpi kernel: [    0.966551] mmc0: host does not support reading read-only switch, assuming write-enable
Jan 12 02:18:32 emonpi kernel: [    0.971656] mmc0: new high speed SDHC card at address 5048
Jan 12 02:18:32 emonpi kernel: [    0.974181] mmcblk0: mmc0:5048 SD16G 14.4 GiB
Jan 12 02:18:32 emonpi kernel: [    0.977937]  mmcblk0: p1 p2 p3
Jan 12 02:18:32 emonpi kernel: [    0.982996] random: fast init done
Jan 12 02:18:32 emonpi mtp-probe: checking bus 1, device 3: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
Jan 12 02:18:32 emonpi kernel: [    0.987215] Indeed it is in host mode hprt0 = 00021501
Jan 12 02:18:32 emonpi kernel: [    0.999553] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
Jan 12 02:18:32 emonpi kernel: [    1.000843] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
Jan 12 02:18:32 emonpi kernel: [    1.088430] mmc1: new high speed SDIO card at address 0001
Jan 12 02:18:32 emonpi systemd-udevd[156]: Using default interface naming scheme 'v240'.
Jan 12 02:18:32 emonpi kernel: [    1.197143] usb 1-1: new high-speed USB device number 2 using dwc_otg
Jan 12 02:18:32 emonpi kernel: [    1.198556] Indeed it is in host mode hprt0 = 00001101
Jan 12 02:18:32 emonpi kernel: [    1.437409] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
Jan 12 02:18:32 emonpi kernel: [    1.440071] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jan 12 02:18:32 emonpi mtp-probe: bus: 1, device: 3 was not an MTP device
Jan 12 02:18:32 emonpi kernel: [    1.442194] hub 1-1:1.0: USB hub found
Jan 12 02:18:32 emonpi kernel: [    1.443796] hub 1-1:1.0: 5 ports detected
Jan 12 02:18:32 emonpi kernel: [    1.478157] EXT4-fs (mmcblk0p2): recovery complete
Jan 12 02:18:32 emonpi kernel: [    1.481487] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Jan 12 02:18:32 emonpi systemd-udevd[162]: Using default interface naming scheme 'v240'.
Jan 12 02:18:32 emonpi kernel: [    1.484591] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Jan 12 02:18:32 emonpi kernel: [    1.494856] devtmpfs: mounted
Jan 12 02:18:32 emonpi fake-hwclock[110]: Wed 12 Jan 02:17:01 UTC 2022
Jan 12 02:18:32 emonpi kernel: [    1.503607] Freeing unused kernel memory: 1024K
Jan 12 02:18:32 emonpi kernel: [    1.505533] Run /sbin/init as init process
Jan 12 02:18:32 emonpi kernel: [    1.757152] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Jan 12 02:18:32 emonpi kernel: [    1.887437] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
Jan 12 02:18:32 emonpi systemd[1]: Starting Flush Journal to Persistent Storage...
Jan 12 02:18:32 emonpi kernel: [    1.890704] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Jan 12 02:18:32 emonpi kernel: [    1.895098] smsc95xx v1.0.6
Jan 12 02:18:32 emonpi kernel: [    1.990533] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:30:ea:9a
Jan 12 02:18:32 emonpi systemd-fsck[136]: e2fsck 1.44.5 (15-Dec-2018)
Jan 12 02:18:32 emonpi kernel: [    2.247180] NET: Registered protocol family 10
Jan 12 02:18:32 emonpi kernel: [    2.250295] Segment Routing with IPv6
Jan 12 02:18:32 emonpi systemd-fsck[136]: rootfs: clean, 68136/265584 files, 529052/1053440 blocks
Jan 12 02:18:32 emonpi kernel: [    3.246754] random: systemd: uninitialized urandom read (16 bytes read)
Jan 12 02:18:32 emonpi kernel: [    3.260730] random: systemd: uninitialized urandom read (16 bytes read)
Jan 12 02:18:32 emonpi kernel: [    3.267229] random: systemd: uninitialized urandom read (16 bytes read)
Jan 12 02:18:32 emonpi systemd-fsck[276]: fsck.fat 4.1 (2017-01-24)
Jan 12 02:18:32 emonpi kernel: [    3.466768] i2c /dev entries driver
Jan 12 02:18:32 emonpi kernel: [    3.779026] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Jan 12 02:18:32 emonpi kernel: [    4.480137] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
Jan 12 02:18:32 emonpi kernel: [    4.483007] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
Jan 12 02:18:32 emonpi kernel: [    4.483032] [vc_sm_connected_init]: start
Jan 12 02:18:32 emonpi kernel: [    4.484843] vc_sm_cma_vchi_init: failed to open VCHI service (-1)
Jan 12 02:18:32 emonpi kernel: [    4.484853] [vc_sm_connected_init]: failed to initialize shared memory service
Jan 12 02:18:32 emonpi kernel: [    4.513112] media: Linux media interface: v0.10
Jan 12 02:18:32 emonpi kernel: [    4.546985] videodev: Linux video capture interface: v2.00
Jan 12 02:18:32 emonpi kernel: [    4.596883] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 12 02:18:32 emonpi kernel: [    4.597343] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Jan 12 02:18:32 emonpi kernel: [    4.611876] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Jan 12 02:18:32 emonpi kernel: [    4.618109] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
Jan 12 02:18:32 emonpi kernel: [    4.634401] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Jan 12 02:18:32 emonpi kernel: [    4.636418] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Jan 12 02:18:32 emonpi kernel: [    4.642044] bcm2835_audio soc:audio: card created with 8 channels
Jan 12 02:18:32 emonpi kernel: [    4.648089] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
Jan 12 02:18:32 emonpi kernel: [    4.911268] cfg80211: Loading compiled-in X.509 certificates for regulatory database
Jan 12 02:18:32 emonpi kernel: [    4.962406] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
Jan 12 02:18:32 emonpi kernel: [    5.027728] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
Jan 12 02:18:32 emonpi kernel: [    5.035626] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
Jan 12 02:18:32 emonpi kernel: [    5.035875] usbcore: registered new interface driver brcmfmac
Jan 12 02:18:32 emonpi kernel: [    5.251140] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
Jan 12 02:18:32 emonpi kernel: [    5.251234] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
Jan 12 02:18:32 emonpi kernel: [    5.251959] 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
Jan 12 02:18:32 emonpi kernel: [   15.113261] random: crng init done
Jan 12 02:18:32 emonpi kernel: [   15.113270] random: 7 urandom warning(s) missed due to ratelimiting
Jan 12 02:18:32 emonpi kernel: [   37.431981] EXT4-fs (mmcblk0p3): mounting ext2 file system using the ext4 subsystem
Jan 12 02:18:32 emonpi kernel: [   37.451980] EXT4-fs (mmcblk0p3): mounted filesystem without journal. Opts: (null)
Jan 12 02:18:32 emonpi kernel: [   39.384140] 8021q: 802.1Q VLAN Support v1.8
Jan 12 02:18:32 emonpi systemd-fsck[276]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
Jan 12 02:18:32 emonpi systemd-fsck[276]:  Automatically removing dirty bit.
Jan 12 02:18:32 emonpi systemd-fsck[276]: Performing changes.
Jan 12 02:18:32 emonpi systemd-fsck[276]: /dev/mmcblk0p1: 241 files, 104466/516190 clusters
Jan 12 02:18:32 emonpi systemd-fsck[277]: e2fsck 1.44.5 (15-Dec-2018)
Jan 12 02:18:32 emonpi systemd-fsck[277]: /dev/mmcblk0p3 was not cleanly unmounted, check forced.
Jan 12 02:18:32 emonpi systemd-fsck[277]: Pass 1: Checking inodes, blocks, and sizes
Jan 12 02:18:32 emonpi systemd-fsck[277]: Pass 2: Checking directory structure
Jan 12 02:18:32 emonpi systemd-fsck[277]: Pass 3: Checking directory connectivity
Jan 12 02:18:32 emonpi systemd-fsck[277]: Pass 4: Checking reference counts
Jan 12 02:18:32 emonpi systemd-fsck[277]: Pass 5: Checking group summary information
Jan 12 02:18:32 emonpi systemd-fsck[277]: Free blocks count wrong (10115311, counted=10114600).
Jan 12 02:18:32 emonpi systemd-fsck[277]: Fix? yes
Jan 12 02:18:32 emonpi systemd-fsck[277]: /dev/mmcblk0p3: ***** FILE SYSTEM WAS MODIFIED *****
Jan 12 02:18:32 emonpi systemd-fsck[277]: /dev/mmcblk0p3: 69/665088 files (2.9% non-contiguous), 519640/10634240 blocks
Jan 12 02:18:32 emonpi log2ram[290]: sending incremental file list
Jan 12 02:18:32 emonpi log2ram[290]: ./
Jan 12 02:18:32 emonpi log2ram[290]: alternatives.log
Jan 12 02:18:32 emonpi log2ram[290]: auth.log
Jan 12 02:18:32 emonpi log2ram[290]: bootstrap.log
Jan 12 02:18:32 emonpi log2ram[290]: btmp
Jan 12 02:18:32 emonpi log2ram[290]: daemon.log
Jan 12 02:18:32 emonpi log2ram[290]: debug
Jan 12 02:18:32 emonpi log2ram[290]: dpkg.log
Jan 12 02:18:32 emonpi log2ram[290]: faillog
Jan 12 02:18:32 emonpi log2ram[290]: kern.log

******************** CONTENT REMOVED TO FIT IN POST***********************
Jan 12 02:18:52 emonpi systemd[553]: Reached target Shutdown.
Jan 12 02:18:52 emonpi systemd[553]: systemd-exit.service: Succeeded.
Jan 12 02:18:52 emonpi systemd[553]: Started Exit the Session.
Jan 12 02:18:52 emonpi systemd[553]: Reached target Exit the Session.
Jan 12 02:18:52 emonpi systemd[1]: [email protected]: Succeeded.
Jan 12 02:18:52 emonpi systemd[1]: Stopped User Manager for UID 1000.
Jan 12 02:18:52 emonpi systemd[1]: Stopping User Runtime Directory /run/user/1000...
Jan 12 02:18:52 emonpi systemd[1]: run-user-1000.mount: Succeeded.
Jan 12 02:18:52 emonpi systemd[1]: [email protected]: Succeeded.
Jan 12 02:18:52 emonpi systemd[1]: Stopped User Runtime Directory /run/user/1000.
Jan 12 02:18:52 emonpi systemd[1]: Removed slice User Slice of UID 1000.
Jan 12 02:19:00 emonpi systemd[1]: systemd-fsckd.service: Succeeded.
Jan 12 03:43:29 emonpi systemd-timesyncd[359]: Synchronized to time server for the first time 188.125.64.6:123 (2.debian.pool.ntp.org).
Jan 12 03:43:29 emonpi systemd[1]: Starting Clean php session files...
Jan 12 03:43:30 emonpi systemd[1]: phpsessionclean.service: Succeeded.
9

You should be able to next time, Iā€™ve nudged your privileges up a step.

1 Like
10

Can you attach the whole file now that Robert has fixed your privileges? Iā€™m interested to see the bit just before these lines :slight_smile:

The start of that log indicates you probably lost power (due to the need to check the filesystems with fsck), but these lines I quoted above near the end seem to be indicating a controlled shutdown at about 2:18am?

11

I still seem to have issues uploading file, but here is the precursor to last nightā€™s shut down (at 02:17:40):

Jan 13 00:17:01 emonpi rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="385" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Jan 13 00:17:01 emonpi systemd[1]: Reloading Log2Ram.
Jan 13 00:17:02 emonpi log2ram[29096]: sending incremental file list
Jan 13 00:17:02 emonpi log2ram[29096]: ./
Jan 13 00:17:02 emonpi log2ram[29096]: auth.log
Jan 13 00:17:02 emonpi log2ram[29096]: daemon.log
Jan 13 00:17:02 emonpi log2ram[29096]: log2ram.log
Jan 13 00:17:02 emonpi log2ram[29096]: messages
Jan 13 00:17:02 emonpi log2ram[29096]: syslog
Jan 13 00:17:02 emonpi log2ram[29096]: emoncms/wificheck.log
Jan 13 00:17:02 emonpi log2ram[29096]: logrotate/
Jan 13 00:17:02 emonpi log2ram[29096]: logrotate/logrotate.log
Jan 13 00:17:02 emonpi log2ram[29096]: logrotate/logrotate.status
Jan 13 00:17:02 emonpi log2ram[29096]: mysql/
Jan 13 00:17:02 emonpi log2ram[29096]: mysql/error.log
Jan 13 00:17:02 emonpi log2ram[29096]: sent 62,631 bytes  received 5,794 bytes  136,850.00 bytes/sec
Jan 13 00:17:02 emonpi log2ram[29096]: total size is 1,569,339  speedup is 22.94
Jan 13 00:17:02 emonpi systemd[1]: Reloaded Log2Ram.
Jan 13 00:20:01 emonpi CRON[29199]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:25:01 emonpi CRON[29353]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:30:01 emonpi CRON[29496]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:35:01 emonpi CRON[29650]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:39:01 emonpi CRON[29771]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 13 00:39:10 emonpi systemd[1]: Starting Clean php session files...
Jan 13 00:39:10 emonpi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 00:39:10 emonpi systemd[1]: Started Clean php session files.
Jan 13 00:40:01 emonpi CRON[29854]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:42:59 emonpi rngd[368]: stats: bits received from HRNG source: 680064
Jan 13 00:42:59 emonpi rngd[368]: stats: bits sent to kernel pool: 634336
Jan 13 00:42:59 emonpi rngd[368]: stats: entropy added to kernel pool: 634336
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2 successes: 34
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2 failures: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Poker: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Runs: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Long run: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: HRNG source speed: (min=478.918; avg=877.476; max=1022.632)Kibits/s
Jan 13 00:42:59 emonpi rngd[368]: stats: FIPS tests speed: (min=6.607; avg=7.413; max=14.234)Mibits/s
Jan 13 00:42:59 emonpi rngd[368]: stats: Lowest ready-buffers level: 2
Jan 13 00:42:59 emonpi rngd[368]: stats: Entropy starvations: 0
Jan 13 00:42:59 emonpi rngd[368]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Jan 13 00:45:02 emonpi CRON[30008]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:50:01 emonpi CRON[30141]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 00:55:01 emonpi CRON[30295]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:00:01 emonpi CRON[30449]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:05:01 emonpi CRON[30579]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:09:01 emonpi CRON[30712]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 13 01:09:10 emonpi systemd[1]: Starting Clean php session files...
Jan 13 01:09:10 emonpi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 01:09:10 emonpi systemd[1]: Started Clean php session files.
Jan 13 01:10:01 emonpi CRON[30794]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:15:01 emonpi CRON[30936]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:17:01 emonpi CRON[31016]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 13 01:17:01 emonpi systemd[1]: Reloading Log2Ram.
Jan 13 01:17:01 emonpi log2ram[31027]: sending incremental file list
Jan 13 01:17:01 emonpi log2ram[31027]: ./
Jan 13 01:17:01 emonpi log2ram[31027]: auth.log
Jan 13 01:17:01 emonpi log2ram[31027]: daemon.log
Jan 13 01:17:01 emonpi log2ram[31027]: log2ram.log
Jan 13 01:17:01 emonpi log2ram[31027]: syslog
Jan 13 01:17:01 emonpi log2ram[31027]: emoncms/wificheck.log
Jan 13 01:17:01 emonpi log2ram[31027]: logrotate/
Jan 13 01:17:01 emonpi log2ram[31027]: logrotate/logrotate.log
Jan 13 01:17:01 emonpi log2ram[31027]: logrotate/logrotate.status
Jan 13 01:17:01 emonpi log2ram[31027]: sent 63,873 bytes  received 4,253 bytes  136,252.00 bytes/sec
Jan 13 01:17:01 emonpi log2ram[31027]: total size is 1,626,200  speedup is 23.87
Jan 13 01:17:01 emonpi systemd[1]: Reloaded Log2Ram.
Jan 13 01:20:01 emonpi CRON[31115]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:25:01 emonpi CRON[31257]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:30:01 emonpi CRON[31412]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:35:01 emonpi CRON[31562]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:39:01 emonpi CRON[31677]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 13 01:39:04 emonpi systemd[1]: Starting Clean php session files...
Jan 13 01:39:04 emonpi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 01:39:04 emonpi systemd[1]: Started Clean php session files.
Jan 13 01:40:01 emonpi CRON[31760]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:42:59 emonpi rngd[368]: stats: bits received from HRNG source: 720064
Jan 13 01:42:59 emonpi rngd[368]: stats: bits sent to kernel pool: 664096
Jan 13 01:42:59 emonpi rngd[368]: stats: entropy added to kernel pool: 664096
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2 successes: 36
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2 failures: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Poker: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Runs: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Long run: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: HRNG source speed: (min=478.918; avg=880.648; max=1022.632)Kibits/s
Jan 13 01:42:59 emonpi rngd[368]: stats: FIPS tests speed: (min=6.607; avg=7.396; max=14.234)Mibits/s
Jan 13 01:42:59 emonpi rngd[368]: stats: Lowest ready-buffers level: 2
Jan 13 01:42:59 emonpi rngd[368]: stats: Entropy starvations: 0
Jan 13 01:42:59 emonpi rngd[368]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Jan 13 01:45:01 emonpi CRON[31913]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:50:01 emonpi CRON[32043]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 01:55:01 emonpi CRON[32198]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 02:00:01 emonpi CRON[32340]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 02:05:01 emonpi CRON[32495]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 02:09:02 emonpi CRON[32616]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 13 02:09:10 emonpi systemd[1]: Starting Clean php session files...
Jan 13 02:09:10 emonpi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 02:09:10 emonpi systemd[1]: Started Clean php session files.
Jan 13 02:10:01 emonpi CRON[32698]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 02:15:01 emonpi CRON[387]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Jan 13 02:17:01 emonpi CRON[473]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 13 02:17:01 emonpi systemd[1]: Reloading Log2Ram.
Jan 13 02:17:01 emonpi log2ram[483]: sending incremental file list
Jan 13 02:17:01 emonpi log2ram[483]: auth.log
Jan 13 02:17:01 emonpi log2ram[483]: daemon.log
Jan 13 02:17:40 emonpi systemd-modules-load[111]: Inserted module 'i2c_dev'
Jan 13 02:17:40 emonpi mtp-probe: checking bus 1, device 3: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
Jan 13 02:17:40 emonpi systemd-udevd[155]: Using default interface naming scheme 'v240'.
Jan 13 02:17:40 emonpi mtp-probe: bus: 1, device: 3 was not an MTP device
Jan 13 02:17:40 emonpi systemd-udevd[157]: Using default interface naming scheme 'v240'.
Jan 13 02:17:40 emonpi fake-hwclock[112]: Thu 13 Jan 02:17:01 UTC 2022
Jan 13 02:17:40 emonpi systemd[1]: Starting Flush Journal to Persistent Storage...
Jan 13 02:17:40 emonpi systemd-fsck[135]: e2fsck 1.44.5 (15-Dec-2018)
Jan 13 02:17:40 emonpi systemd-fsck[135]: rootfs: clean, 68136/265584 files, 529203/1053440 blocks
Jan 13 02:17:40 emonpi systemd-fsck[256]: fsck.fat 4.1 (2017-01-24)
Jan 13 02:17:40 emonpi systemd-fsck[256]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
Jan 13 02:17:40 emonpi systemd-fsck[256]:  Automatically removing dirty bit.
Jan 13 02:17:40 emonpi systemd-fsck[256]: Performing changes.
Jan 13 02:17:40 emonpi systemd-fsck[256]: /dev/mmcblk0p1: 241 files, 104466/516190 clusters
Jan 13 02:17:40 emonpi kernel: [    0.000000] Booting Linux on physical CPU 0x0
Jan 13 02:17:40 emonpi kernel: [    0.000000] Linux version 4.19.118-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1311 SMP Mon Apr 27 14:21:24 BST 2020
Jan 13 02:17:40 emonpi kernel: [    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
Jan 13 02:17:40 emonpi kernel: [    0.000000] CPU: div instructions available: patching division code
Jan 13 02:17:40 emonpi kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Jan 13 02:17:40 emonpi kernel: [    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
Jan 13 02:17:40 emonpi kernel: [    0.000000] Memory policy: Data cache writealloc
Jan 13 02:17:40 emonpi kernel: [    0.000000] cma: Reserved 8 MiB at 0x3dc00000
Jan 13 02:17:40 emonpi kernel: [    0.000000] On node 0 totalpages: 255488

Thanks!

12

I think this is the most interesting part:

Given that the below log entry seems to occur every 5 minutes, and last occurred at 2:15, the power must have dropped between 2:15 and 2:17

Going back to your previously posted log:

Iā€™m not sure what is happening between 2:19 and 3:43 - but not much!
Is it waiting for timesync before doing anything else? It does seem to ā€œcome aliveā€ once timesync has succeeded.

I think your main goal will be to avoid the power outage in the first place instead of trying to work out why it takes so long to come back. Obviously the cause of the delayed start would be good to know as well, but the root cause is (probable) loss of power around 2:17AM.

Did your Internet router or Access Point go down as well between 2:17 and 3:43? (just wondering about the delay in achieving time sync)

13

Yes I do agree about the avoidance of the outage being better than trying to fix the subsequent symptoms. I may try changing the power source to another socket to see if that makes any difference at all.

What I donā€™t understand however is if we are seeing the logs of a shutdown event at approx 02:17, and the cause of shutdown is power loss, how is the pi able to have enough juice to log a controlled shutdown? Does the pi have a mini UPS (capacitor?) built into it for events like this?

14

Weā€™re looking at two different logs from 2 days, and the one from the 12th I canā€™t see the full picture :slight_smile: Iā€™m not sure if the power loss and the controlled shutdown are related. It could be that the pi did a controlled shutdown after booting up following a power loss because the file system needed corrections when fsck ran. That can trigger an automatic ā€œcontrolledā€ shutdown - after the fact.
Just a possible scenario - the pi lost power, restarted, found (and corrected) file system errors on the rootfs, then triggered a controlled shutdown/restart. That is just a guess though because I canā€™t see the whole log from the 12th.

The log from the 13th didnā€™t show any signs of a controlled shutdown.

15

The Pi doesnā€™t have a real-time clock so you canā€™t rely on the timestamps at all until the network has come up and the time has been synced.

The ā€œReached target Shutdownā€ messages are referring to a systemd user instance (pid 553, not pid 1), so it doesnā€™t refer to the system itself shutting down. It looks like a user logout more than anything else. Odd.

It does look very much like a power outage. I would suggest you find a teenager who is going to be up at 3am anyway to log in to the thing and see what happens around that time :grinning_face_with_smiling_eyes:

What power supply are you using for the Pi? Is anything else plugged into the USB ports?