Node-red restarts

General
1

This is now the second night in a row that NR restart's in the middle of the night.
In the NR log is not much to see because it's only a couple lines long.
However in the syslog of my pi there's clearly a problem.
There's a stack dump, most of the time you are in problems if you see this. :wink:
It looks like there's low memory and the node process is killed.

Anybody an idea why or maybe some hints to look better at?

Sep 14 06:25:42 RaspBroker influxd[511]: ts=2021-09-14T04:25:42.515856Z lvl=info msg="Cache snapshot (start)" log_id=0Va0Z5KW000 engine=tsm1 trace_id=0W_dhMol000 op_name=tsm1_cache_snapshot op_event=start
Sep 14 06:25:43 RaspBroker kernel: [4269984.236024] apt-show-versio invoked oom-killer: gfp_mask=0x101cca(GFP_HIGHUSER_MOVABLE|__GFP_WRITE), order=0, oom_score_adj=0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236049] CPU: 3 PID: 19840 Comm: apt-show-versio Tainted: G         C        5.4.72-v7+ #1356
Sep 14 06:25:43 RaspBroker kernel: [4269984.236055] Hardware name: BCM2835
Sep 14 06:25:43 RaspBroker kernel: [4269984.236060] Backtrace: 
Sep 14 06:25:43 RaspBroker kernel: [4269984.236086] [<8010e1c0>] (dump_backtrace) from [<8010e538>] (show_stack+0x20/0x24)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236098]  r7:ffffffff r6:00000000 r5:60000013 r4:80e996f0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236115] [<8010e518>] (show_stack) from [<8090e830>] (dump_stack+0xd4/0x118)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236132] [<8090e75c>] (dump_stack) from [<8028df9c>] (dump_header+0x64/0x1f8)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236146]  r10:00101cca r9:b314c000 r8:00000000 r7:00000558 r6:80bbbb00 r5:b40e0000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236153]  r4:b314dc70 r3:00000000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236167] [<8028df38>] (dump_header) from [<8028d334>] (oom_kill_process+0x17c/0x188)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236177]  r7:00000558 r6:80bbbb00 r5:b314dc70 r4:b40e0000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236190] [<8028d1b8>] (oom_kill_process) from [<8028dd9c>] (out_of_memory+0x244/0x344)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236201]  r7:80e04fa8 r6:80e08200 r5:b314dc70 r4:b40e0000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236216] [<8028db58>] (out_of_memory) from [<802da420>] (__alloc_pages_nodemask+0xbe8/0x121c)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236225]  r6:80e9b3c8 r5:000014dd r4:00000000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236244] [<802d9838>] (__alloc_pages_nodemask) from [<8028688c>] (pagecache_get_page+0x150/0x384)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236257]  r10:80e9ed57 r9:80e058fc r8:00000541 r7:b5b8f3b0 r6:00101cca r5:0000000e
Sep 14 06:25:43 RaspBroker kernel: [4269984.236263]  r4:00000000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236280] [<8028673c>] (pagecache_get_page) from [<8028729c>] (grab_cache_page_write_begin+0x28/0x3c)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236293]  r10:80a13a8c r9:00000000 r8:00541000 r7:b314ddc0 r6:b5b8f2a0 r5:b314dec0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236299]  r4:8324ae40
Sep 14 06:25:43 RaspBroker kernel: [4269984.236317] [<80287274>] (grab_cache_page_write_begin) from [<803e14cc>] (ext4_da_write_begin+0xc4/0x4a8)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236325]  r5:b314dec0 r4:8324ae40
Sep 14 06:25:43 RaspBroker kernel: [4269984.236343] [<803e1408>] (ext4_da_write_begin) from [<802845f0>] (generic_perform_write+0xd0/0x1f0)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236362]  r10:80a13a8c r9:00000000 r8:8324ae40 r7:803e1408 r6:b5b8f3b0 r5:b314dec0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236368]  r4:00001000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236394] [<80284520>] (generic_perform_write) from [<802896bc>] (__generic_file_write_iter+0x16c/0x1fc)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236413]  r10:b314dec0 r9:b5b8f3b0 r8:00000000 r7:b5b8f2a0 r6:8324ae40 r5:b314ded8
Sep 14 06:25:43 RaspBroker kernel: [4269984.236418]  r4:00000000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236435] [<80289550>] (__generic_file_write_iter) from [<803cacb8>] (ext4_file_write_iter+0x280/0x474)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236448]  r10:00000000 r9:b5b8f328 r8:b314dec0 r7:b5b8f2a0 r6:00002000 r5:b5b8f2a0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236454]  r4:b314ded8
Sep 14 06:25:43 RaspBroker kernel: [4269984.236467] [<803caa38>] (ext4_file_write_iter) from [<80304e58>] (__vfs_write+0x15c/0x1ec)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236481]  r10:00000004 r9:00000000 r8:00540000 r7:00000000 r6:00002000 r5:b314df60
Sep 14 06:25:43 RaspBroker kernel: [4269984.236486]  r4:8324ae40
Sep 14 06:25:43 RaspBroker kernel: [4269984.236500] [<80304cfc>] (__vfs_write) from [<80307d78>] (vfs_write+0xc0/0x1c8)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236513]  r9:00002000 r8:00000000 r7:b314df60 r6:0491c148 r5:8324ae40 r4:00002000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236526] [<80307cb8>] (vfs_write) from [<80308064>] (ksys_write+0x74/0x100)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236538]  r8:0491c148 r7:00000000 r6:00540000 r5:8324ae40 r4:8324ae40
Sep 14 06:25:43 RaspBroker kernel: [4269984.236551] [<80307ff0>] (ksys_write) from [<80308108>] (sys_write+0x18/0x1c)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236564]  r9:b314c000 r8:801011c4 r7:00000004 r6:010b1150 r5:00002000 r4:0491c148
Sep 14 06:25:43 RaspBroker kernel: [4269984.236578] [<803080f0>] (sys_write) from [<80101000>] (ret_fast_syscall+0x0/0x28)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236585] Exception stack(0xb314dfa8 to 0xb314dff0)
Sep 14 06:25:43 RaspBroker kernel: [4269984.236597] dfa0:                   0491c148 00002000 00000003 0491c148 00002000 00000000
Sep 14 06:25:43 RaspBroker kernel: [4269984.236610] dfc0: 0491c148 00002000 010b1150 00000004 041d89b8 0491c148 00421200 00000001
Sep 14 06:25:43 RaspBroker kernel: [4269984.236619] dfe0: 002d52a4 7ec4a550 00163aa0 76e12180
Sep 14 06:25:43 RaspBroker kernel: [4269984.236626] Mem-Info:
Sep 14 06:25:43 RaspBroker kernel: [4269984.236654] active_anon:104262 inactive_anon:104298 isolated_anon:0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236654]  active_file:1537 inactive_file:6244 isolated_file:32
Sep 14 06:25:43 RaspBroker kernel: [4269984.236654]  unevictable:8 dirty:590 writeback:0 unstable:0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236654]  slab_reclaimable:5293 slab_unreclaimable:5617
Sep 14 06:25:43 RaspBroker kernel: [4269984.236654]  mapped:6441 shmem:7436 pagetables:1495 bounce:0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236654]  free:5181 free_pcp:40 free_cma:44
Sep 14 06:25:43 RaspBroker kernel: [4269984.236677] Node 0 active_anon:417048kB inactive_anon:417192kB active_file:6248kB inactive_file:24976kB unevictable:32kB isolated(anon):0kB isolated(file):128kB mapped:25764kB dirty:2360kB writeback:0kB shmem:29744kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Sep 14 06:25:43 RaspBroker kernel: [4269984.236704] Normal free:20724kB min:53248kB low:57344kB high:61440kB active_anon:417432kB inactive_anon:416796kB active_file:6168kB inactive_file:25088kB unevictable:32kB writepending:2380kB present:970752kB managed:947028kB mlocked:32kB kernel_stack:1336kB pagetables:5980kB bounce:0kB free_pcp:164kB local_pcp:0kB free_cma:176kB
Sep 14 06:25:43 RaspBroker kernel: [4269984.236713] lowmem_reserve[]: 0 0
Sep 14 06:25:43 RaspBroker kernel: [4269984.236732] Normal: 1155*4kB (UMEHC) 745*8kB (UEHC) 194*16kB (UEHC) 140*32kB (UEHC) 46*64kB (UEHC) 2*128kB (H) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 21364kB
Sep 14 06:25:43 RaspBroker kernel: [4269984.236814] 18442 total pagecache pages
Sep 14 06:25:43 RaspBroker kernel: [4269984.236827] 3245 pages in swap cache
Sep 14 06:25:43 RaspBroker kernel: [4269984.236839] Swap cache stats: add 205043, delete 201798, find 3921717/3937922
Sep 14 06:25:43 RaspBroker kernel: [4269984.236848] Free swap  = 0kB
Sep 14 06:25:43 RaspBroker kernel: [4269984.236857] Total swap = 102396kB
Sep 14 06:25:43 RaspBroker kernel: [4269984.236867] 242688 pages RAM
Sep 14 06:25:43 RaspBroker kernel: [4269984.236876] 0 pages HighMem/MovableOnly
Sep 14 06:25:43 RaspBroker kernel: [4269984.236885] 5931 pages reserved
Sep 14 06:25:43 RaspBroker kernel: [4269984.236894] 16384 pages cma reserved
Sep 14 06:25:43 RaspBroker kernel: [4269984.236904] Tasks state (memory values in pages):
Sep 14 06:25:43 RaspBroker kernel: [4269984.236914] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Sep 14 06:25:43 RaspBroker kernel: [4269984.236947] [    141]     0   141     4519       68    20480      136         -1000 systemd-udevd
Sep 14 06:25:43 RaspBroker kernel: [4269984.236965] [    341]     0   341    10321     2064    73728      127             0 systemd-journal
Sep 14 06:25:43 RaspBroker kernel: [4269984.236982] [    344]   100   344     5603       25    24576      143             0 systemd-timesyn
Sep 14 06:25:43 RaspBroker kernel: [4269984.236998] [    347]     0   347     1994       18    14336       35             0 cron
Sep 14 06:25:43 RaspBroker kernel: [4269984.237014] [    348]     0   348     6378      284    18432      147             0 rsyslogd
Sep 14 06:25:43 RaspBroker kernel: [4269984.237031] [    351]     0   351      923       12    10240       40             0 alsactl
Sep 14 06:25:43 RaspBroker kernel: [4269984.237047] [    355]     0   355     3283       40    22528      137             0 systemd-logind
Sep 14 06:25:43 RaspBroker kernel: [4269984.237064] [    363] 65534   363     1080       30    14336       39             0 thd
Sep 14 06:25:43 RaspBroker kernel: [4269984.237081] [    386]   108   386     1476       41    14336       48             0 avahi-daemon
Sep 14 06:25:43 RaspBroker kernel: [4269984.237097] [    387]   104   387     1637       66    18432       53          -900 dbus-daemon
Sep 14 06:25:43 RaspBroker kernel: [4269984.237114] [    392]     0   392     7170       19    18432       16             0 rngd
Sep 14 06:25:43 RaspBroker kernel: [4269984.237131] [    398]     0   398     2685       13    20480       88             0 wpa_supplicant
Sep 14 06:25:43 RaspBroker kernel: [4269984.237147] [    416]   108   416     1443        4    12288       61             0 avahi-daemon
Sep 14 06:25:43 RaspBroker kernel: [4269984.237164] [    508]     0   508      708       10    12288       73             0 dhcpcd
Sep 14 06:25:43 RaspBroker kernel: [4269984.237180] [    511]   109   511   362048    54094   827392     4870             0 influxd
Sep 14 06:25:43 RaspBroker kernel: [4269984.237197] [    513]   111   513   245722     3762   114688     1850             0 grafana-server
Sep 14 06:25:43 RaspBroker kernel: [4269984.237214] [    514]   110   514     2342      163    18432       92             0 mosquitto
Sep 14 06:25:43 RaspBroker kernel: [4269984.237230] [    526]     0   526     1077        0    12288       25             0 agetty
Sep 14 06:25:43 RaspBroker kernel: [4269984.237247] [    535]     0   535     2681        3    20480      144         -1000 sshd
Sep 14 06:25:43 RaspBroker kernel: [4269984.237263] [    552]     0   552    48653     1361    53248      118             0 apache2
Sep 14 06:25:43 RaspBroker kernel: [4269984.237279] [    575]     0   575     6493      447    34816     3755             0 miniserv.pl
Sep 14 06:25:43 RaspBroker kernel: [4269984.237298] [  31811]  1000 31811   160242   118266  1122304     7748             0 node
Sep 14 06:25:43 RaspBroker kernel: [4269984.237315] [   8855]  1000  8855    37972     2430   131072      673             0 ffmpeg
Sep 14 06:25:43 RaspBroker kernel: [4269984.237331] [  14431]    33 14431    48659      782    45056      118             0 apache2
Sep 14 06:25:43 RaspBroker kernel: [4269984.237348] [  14432]    33 14432    48659      782    45056      118             0 apache2
Sep 14 06:25:43 RaspBroker kernel: [4269984.237364] [  14433]    33 14433    48659      782    45056      118             0 apache2
Sep 14 06:25:43 RaspBroker kernel: [4269984.237381] [  14434]    33 14434    48659      782    45056      118             0 apache2
Sep 14 06:25:43 RaspBroker kernel: [4269984.237397] [  14435]    33 14435    48659      782    45056      118             0 apache2
Sep 14 06:25:43 RaspBroker kernel: [4269984.237420] [  19830]     0 19830     2367       68    16384       12             0 cron
Sep 14 06:25:43 RaspBroker kernel: [4269984.237437] [  19832]     0 19832      485       13     8192        0             0 sh
Sep 14 06:25:43 RaspBroker kernel: [4269984.237453] [  19834]     0 19834      465       13    14336        0             0 run-parts
Sep 14 06:25:43 RaspBroker kernel: [4269984.237470] [  19839]     0 19839      485       13    10240        0             0 apt-show-versio
Sep 14 06:25:43 RaspBroker kernel: [4269984.237486] [  19840]     0 19840    29621    18126   129024        0             0 apt-show-versio
Sep 14 06:25:43 RaspBroker kernel: [4269984.237500] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=node,pid=31811,uid=1000
Sep 14 06:25:43 RaspBroker kernel: [4269984.237621] Out of memory: Killed process 31811 (node) total-vm:640968kB, anon-rss:471476kB, file-rss:1588kB, shmem-rss:0kB, UID:1000 pgtables:1096kB oom_score_adj:0
Sep 14 06:25:43 RaspBroker kernel: [4269984.384407] oom_reaper: reaped process 31811 (node), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Sep 14 06:25:43 RaspBroker systemd[1]: nodered.service: Main process exited, code=killed, status=9/KILL
Sep 14 06:25:43 RaspBroker influxd[511]: ts=2021-09-14T04:25:43.694591Z lvl=info msg="Snapshot for path written" log_id=0Va0Z5KW000 engine=tsm1 trace_id=0W_dhMol000 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/data/zigbeetempsensor/autogen/477 duration=1342.646ms
Sep 14 06:25:43 RaspBroker influxd[511]: ts=2021-09-14T04:25:43.749689Z lvl=info msg="Cache snapshot (end)" log_id=0Va0Z5KW000 engine=tsm1 trace_id=0W_dhMol000 op_name=tsm1_cache_snapshot op_event=end op_elapsed=1397.687ms
Sep 14 06:25:46 RaspBroker systemd[1]: nodered.service: Failed with result 'signal'.
Sep 14 06:25:49 RaspBroker kernel: [4269990.563924] Voltage normalised (0x00000000)
Sep 14 06:26:06 RaspBroker systemd[1]: nodered.service: Service RestartSec=20s expired, scheduling restart.
Sep 14 06:26:06 RaspBroker systemd[1]: nodered.service: Scheduled restart job, restart counter is at 2.
Sep 14 06:26:06 RaspBroker systemd[1]: Stopped Node-RED graphical event wiring tool.
Sep 14 06:26:06 RaspBroker systemd[1]: Started Node-RED graphical event wiring tool.
Sep 14 06:26:15 RaspBroker Node-RED[19916]: 14 Sep 06:26:15 - [info]
Sep 14 06:26:15 RaspBroker Node-RED[19916]: Welcome to Node-RED
Sep 14 06:26:15 RaspBroker Node-RED[19916]: ===================
Sep 14 06:26:15 RaspBroker Node-RED[19916]: 14 Sep 06:26:15 - [info] Node-RED version: v2.0.3
Sep 14 06:26:15 RaspBroker Node-RED[19916]: 14 Sep 06:26:15 - [info] Node.js  version: v12.19.0
Sep 14 06:26:15 RaspBroker Node-RED[19916]: 14 Sep 06:26:15 - [info] Linux 5.4.72-v7+ arm LE
Sep 14 06:26:17 RaspBroker Node-RED[19916]: 14 Sep 06:26:17 - [info] Loading palette nodes
Sep 14 06:26:36 RaspBroker Node-RED[19916]: 14 Sep 06:26:36 - [info] Worldmap version 2.15.5
Sep 14 06:26:37 RaspBroker Node-RED[19916]: 14 Sep 06:26:37 - [info] Dashboard version 2.30.0 started at /ui
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [info] Settings file  : /home/pi/.node-red/settings.js
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [info] HTTP Static    : /home/pi/node-red-static
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [info] Context store  : 'default' [module=memory]
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [info] User directory : /home/pi/.node-red
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [warn] Projects disabled : editorTheme.projects.enabled=false
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [info] Flows file     : /home/pi/.node-red/flows_RaspBroker.json
Sep 14 06:26:40 RaspBroker Node-RED[19916]: 14 Sep 06:26:40 - [info] Server now running at http://127.0.0.1:1880/admin/
Sep 14 06:26:43 RaspBroker Node-RED[19916]: 14 Sep 06:26:43 - [info] Starting flows
Sep 14 06:26:44 RaspBroker Node-RED[19916]: 14 Sep 06:26:44 - [info] [alexa-remote-account:34c9e5d2.8ecb8a] intialising with the PROXY method and NO saved data...
Sep 14 06:26:47 RaspBroker Node-RED[19916]: 14 Sep 06:26:47 - [info] [worldmap:Evert] started at /worldmap
Sep 14 06:26:48 RaspBroker Node-RED[19916]: 14 Sep 06:26:48 - [info] Started flows
2

You have run out of memory. What hardware are you running on?

I suggest you run top or htop whichever you prefer and watch the memory for a while. Try to see what is going on. Post a screenshot so we can have a look.

3

Hi Colin,
Thanks for the quick reply.
It was clear to me that the Pi was running out of memory, hoped that you guys could see in the log file what was causing the problem.
NR is running on a Pi3B+ together with influx, Grafana, Sqlite and Mosquitto.
It's running now for a couple of years without any problems this configuration.

Memory usage for the last 24H:

Capture
Capture293×862 34.2 KB

It's clear it's building up memory use just before the "crash" .
As mentioned before this setup is running for a couple of years now. So always remember what was changed the last time. This weekend I added some new flows.
I will disable now these new flows that I have added this Sunday and will see if the memory usage will be more stable the upcoming days.

Will let you know the outcome.

4

The advantage of using top or htop over your dashboard is that you can see if a particular process is building up memory.

5

I suspect you have an awful lot of data in those charts. You should probably try to aggregate or filter that down to about 300 points a day. (Ie one data point per pixel width in chart)

7

I think those are Grafana charts. Is that correct @edje11?

1 Like
8

How often are you writing to Influx, and how many measurements?
Are you using the SD card for the influx database?

9

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.