Uncertain if Bug or Covid-19

Hi guys,

Been using the repetier-server for roughly 3 months. Occasionally, every 2 to 3 weeks or so, it decides to ruin my day and halt ongoing prints. This time, I managed to catch some logs and also did some digging in the forum - and I think it is beyond my skill level to handle (silly lil cosplayer - I know more about Anime than about Raspberroes).

I'm running Repetier-Server 1.3.0 on a Raspberry pi 3B (1GB mem), connect to the pi original power supply (which is connected to a UPS batter).

I have two printers attached to the pi - Pulse X (by mattercontrol, just a dumb lil' varient of MK2 printers with a Rambo board. HA! Cosplaygirl nailed it! I hope <span>:open_mouth:</span> ) and Prusa mk3s.

I noticed that everytime it failed - it always happened when Prusa was already in mid-print, and I started a new print with the Pulse. It once happened when I just connected to USB of the Pulse (after calibrating it), but mostly it happens when I just upload an STL file and start a Pulse print.

I don't recall it halting when handling Prusa prints. However, for Prusa, I print directly from the Prusa Slicer (not uploading any STL - but had configured the slicer to communicate directly). By the way, I wish I could do the same with Pulse - but. yeah. that. Nope.

LOGS! I got logs!! and I went through the effort of trying to make sense of them. I noticed these threads (but I'm not sure I can find a solution through them to be honest): 
https://forum.repetier.com/discussion/7041/printer-suddenly-stops-mid-print ;
https://forum.repetier.com/discussion/5865/out-of-memory-crash-repetier-server-on-raspberry-pi

There was another post I looked through (about mid-print stopping) from 2022 I think.

All I can say is - that from my understanding - repetier-server crashes, and maybe even experiences a "memory leak" (I was actually taking this from the 2nd link about - they seem to have the same error I get in the logs).

To make my post decent and clean, I'll share the logs in the first comment.

And if I made a mistake in the forum (and posted it wrongfully in "general") I apologize.

Comments

  • edited July 2022
    TIME OF CRASH: 16:56~ (23rd of July)

    This crash happened EXACTLY after uploading a file to Pulse X and asking to print it. So at 16:55 the fun actaully starts I think.

    repetier-server log file

    2022-07-23 14:41:17: Time analysing /var/lib/Repetier-Server/printer/Prusa/jobs/00000056_Body22_0.2mm_PC_MK3S_4h2m.g:3740108 us
    2022-07-23 14:41:38: start printjob Body22_0.2mm_PC_MK3S_4h2m on printer Prusa
    2022-07-23 14:41:39: Updating info for /var/lib/Repetier-Server/printer/Prusa/jobs/00000056_Body22_0.2mm_PC_MK3S_4h2m.g printer Prusa
    2022-07-23 14:41:43: Time analysing /var/lib/Repetier-Server/printer/Prusa/jobs/00000056_Body22_0.2mm_PC_MK3S_4h2m.g:3703235 us
    2022-07-23 16:55:19: Job created: /var/lib/Repetier-Server/printer/PulseXED124/models/00000069_redBinoV2.u
    2022-07-23 16:55:19: move /var/lib/Repetier-Server/tmp/upload25.bin to /var/lib/Repetier-Server/printer/PulseXED124/models/00000069_redBinoV2.u
    2022-07-23 16:55:19: finish job creation /var/lib/Repetier-Server/printer/PulseXED124/models/00000069_redBinoV2.u
    2022-07-23 16:55:19: Uploaded redBinoV2 size:9959589
    2022-07-23 16:55:19: Updating info for /var/lib/Repetier-Server/printer/PulseXED124/models/00000069_redBinoV2.g printer PulseXED124
    2022-07-23 16:55:23: Time analysing /var/lib/Repetier-Server/printer/PulseXED124/models/00000069_redBinoV2.g:4080964 us
    2022-07-23 16:55:32: Job created: /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.u
    2022-07-23 16:55:32: finish job creation /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.u
    2022-07-23 16:55:32: start printjob redBinoV2 on printer PulseXE-D124
    2022-07-23 16:55:32: Updating info for /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.g printer PulseXED124
    2022-07-23 16:55:44: Time analysing /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.g:11580734 us
    2022-07-23 16:56:10: Closing websocket for missing ping
    2022-07-23 16:56:37: Start logging...
    2022-07-23 16:56:37: Imported external command Shutdown Server
    2022-07-23 16:56:37: Imported external command Reboot Server
    2022-07-23 16:56:37: Imported allowed execute command shutdown
    2022-07-23 16:56:37: Imported allowed execute command reboot
    2022-07-23 16:56:37: Webdirectory: /usr/local/Repetier-Server/www/
    2022-07-23 16:56:37: Storage directory: /var/lib/Repetier-Server/
    2022-07-23 16:56:37: Configuration file: /usr/local/Repetier-Server/etc/RepetierServer.xml
    2022-07-23 16:56:37: Directory for temporary files: /tmp/
    2022-07-23 16:56:37: Reading firmware data ...
    2022-07-23 16:56:38: Starting Network ...
    2022-07-23 16:56:38: Active features:0
    2022-07-23 16:56:38: Reading printer configurations ...
    2022-07-23 16:56:38: Reading printer config /var/lib/Repetier-Server/configs/PulseXED124.xml
    2022-07-23 16:56:38: Starting printjob manager thread for PulseXED124
    2022-07-23 16:56:38: Reading printer config /var/lib/Repetier-Server/configs/Prusa.xml
    2022-07-23 16:56:38: Set webcam url:http://127.0.0.1:8080/?action=stream
    2022-07-23 16:56:38: Starting printjob manager thread for Prusa
    2022-07-23 16:56:38: Starting printer threads ...
    2022-07-23 16:56:38: Starting printer thread for PulseXE-D124
    2022-07-23 16:56:38: Starting printer thread for Prusa
    2022-07-23 16:56:38: Starting work dispatcher subsystem ...
    2022-07-23 16:56:38: Starting user database ...
    2022-07-23 16:56:38: Importing projects ...
    2022-07-23 16:56:38: Importing wifi connections from /var/lib/Repetier-Server/database/repetier-network.xml
    2022-07-23 16:56:38: Importing wifi connections from /var/lib/Repetier-Server/database/repetier-network-stored.xml
    2022-07-23 16:56:38: Initializing LUA ...
    2022-07-23 16:56:38: Starting wifi watcher ...
    2022-07-23 16:56:38: Register LUA cloud services
    2022-07-23 16:56:38: add G-Code-Renderer
    2022-07-23 16:56:38: LUA initalization finished.
    2022-07-23 16:56:38: Work dispatcher thread started.
    2022-07-23 16:56:38: Internal work dispatcher thread started.
    2022-07-23 16:56:38: Setting up MQTT Client ...
    2022-07-23 16:56:38: Starting web server ...
    2022-07-23 16:56:38: Webserver started.
    2022-07-23 16:56:39: Connection started: Prusa
    2022-07-23 16:56:39: Internal reset printer Prusa
    2022-07-23 16:56:39: Reset printer Prusa
    2022-07-23 16:56:39: Connection started: PulseXE-D124
    2022-07-23 16:56:39: Internal reset printer PulseXE-D124
    2022-07-23 16:56:39: Reset printer PulseXE-D124
    2022-07-23 16:56:39: Websocket opened
    2022-07-23 16:56:41: New SSID AnimeGirlsHouse
    2022-07-23 16:57:43: Websocket opened
    2022-07-23 16:58:48: start printjob redBinoV2 on printer PulseXE-D124
    2022-07-23 16:58:49: Updating info for /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.g printer PulseXED124
    2022-07-23 16:58:53: Time analysing /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.g:4206450 us
    2022-07-23 16:59:28: Websocket opened


    Syslog Log
    Jul 23 16:50:27 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:50:58 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20225' (uid=0 pid=2629 comm="timedatectl ")
    Jul 23 16:50:58 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:50:59 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:50:59 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:51:29 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:52:00 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20227' (uid=0 pid=2721 comm="timedatectl ")
    Jul 23 16:52:00 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:52:00 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:52:00 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:52:30 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:53:01 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20229' (uid=0 pid=2810 comm="timedatectl ")
    Jul 23 16:53:01 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:53:01 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:53:01 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:53:31 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:54:03 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20231' (uid=0 pid=2901 comm="timedatectl ")
    Jul 23 16:54:03 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:54:03 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:54:03 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:54:33 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:55:04 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20233' (uid=0 pid=2993 comm="timedatectl ")
    Jul 23 16:55:04 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:55:04 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:55:04 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:55:34 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:56:07 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20235' (uid=0 pid=3089 comm="timedatectl ")
    Jul 23 16:56:07 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:56:07 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:56:07 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:56:33 RepetierServer kernel: [618941.851937] Websocket invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
    Jul 23 16:56:33 RepetierServer kernel: [618941.851957] CPU: 1 PID: 17088 Comm: Websocket Tainted: G         C        5.10.63-v7+ #1496
    Jul 23 16:56:33 RepetierServer kernel: [618941.851961] Hardware name: BCM2835
    Jul 23 16:56:33 RepetierServer kernel: [618941.851965] Backtrace:
    Jul 23 16:56:33 RepetierServer kernel: [618941.851987] [<809f0cb0>] (dump_backtrace) from [<809f1040>] (show_stack+0x20/0x24)
    Jul 23 16:56:33 RepetierServer kernel: [618941.851997]  r7:ffffffff r6:00000000 r5:60000113 r4:80fe5e54
    Jul 23 16:56:33 RepetierServer kernel: [618941.852007] [<809f1020>] (show_stack) from [<809f5250>] (dump_stack+0xcc/0xf8)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852016] [<809f5184>] (dump_stack) from [<809f3540>] (dump_header+0x64/0x208)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852024]  r10:80f05184 r9:00100cca r8:00000000 r7:80d148c4 r6:9f846a00 r5:842ddd00
    Jul 23 16:56:33 RepetierServer kernel: [618941.852029]  r4:82bfbe48 r3:48d1b936
    Jul 23 16:56:33 RepetierServer kernel: [618941.852040] [<809f34dc>] (dump_header) from [<802b3b50>] (oom_kill_process+0x1b4/0x1c0)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852047]  r7:80d148c4 r6:82bfbe48 r5:842de280 r4:842ddd00
    Jul 23 16:56:33 RepetierServer kernel: [618941.852056] [<802b399c>] (oom_kill_process) from [<802b46c8>] (out_of_memory+0x2b8/0x390)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852063]  r7:80f08400 r6:80f05008 r5:842ddd00 r4:82bfbe48
    Jul 23 16:56:33 RepetierServer kernel: [618941.852072] [<802b4410>] (out_of_memory) from [<80304114>] (__alloc_pages_nodemask+0x7ec/0x1184)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852079]  r7:8102d208 r6:00001400 r5:000012b9 r4:00000000
    Jul 23 16:56:33 RepetierServer kernel: [618941.852089] [<80303928>] (__alloc_pages_nodemask) from [<802ebec4>] (handle_mm_fault+0x5e4/0xe30)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852098]  r10:82bfbfb0 r9:4c0f0000 r8:00000040 r7:00000000 r6:4c0f0000 r5:80f05008
    Jul 23 16:56:33 RepetierServer kernel: [618941.852102]  r4:00000255
    Jul 23 16:56:33 RepetierServer kernel: [618941.852114] [<802eb8e0>] (handle_mm_fault) from [<80a006b0>] (do_page_fault+0x144/0x314)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852123]  r10:00000255 r9:00000800 r8:9427b044 r7:9427b000 r6:00000817 r5:4c0f0000
    Jul 23 16:56:33 RepetierServer kernel: [618941.852128]  r4:82bfbfb0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852138] [<80a0056c>] (do_page_fault) from [<80114010>] (do_DataAbort+0x4c/0xcc)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852146]  r10:74726174 r9:73657220 r8:82bfbfb0 r7:4c0f0000 r6:80a0056c r5:00000817
    Jul 23 16:56:33 RepetierServer kernel: [618941.852150]  r4:80f0ac38
    Jul 23 16:56:33 RepetierServer kernel: [618941.852159] [<80113fc4>] (do_DataAbort) from [<80100da4>] (__dabt_usr+0x44/0x60)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852164] Exception stack(0x82bfbfb0 to 0x82bfbff8)
    Jul 23 16:56:33 RepetierServer kernel: [618941.852170] bfa0:                                     4c0f0000 500f1170 009065a0 00000000
    Jul 23 16:56:33 RepetierServer kernel: [618941.852178] bfc0: 65207469 6772656d 79636e65 6f747320 726f2070 73657220 74726174 65687420
    Jul 23 16:56:33 RepetierServer kernel: [618941.852185] bfe0: 040012d0 753e7d88 008525c7 00878846 20000030 ffffffff
    Jul 23 16:56:33 RepetierServer kernel: [618941.852192]  r8:10c5387d r7:10c5383d r6:ffffffff r5:20000030 r4:00878846
    Jul 23 16:56:33 RepetierServer kernel: [618941.852196] Mem-Info:
    Jul 23 16:56:33 RepetierServer kernel: [618941.852211] active_anon:171 inactive_anon:206263 isolated_anon:0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852211]  active_file:135 inactive_file:168 isolated_file:0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852211]  unevictable:4 dirty:0 writeback:0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852211]  slab_reclaimable:2942 slab_unreclaimable:4289
    Jul 23 16:56:33 RepetierServer kernel: [618941.852211]  mapped:2180 shmem:14710 pagetables:1760 bounce:0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852211]  free:4621 free_pcp:0 free_cma:57
    Jul 23 16:56:33 RepetierServer kernel: [618941.852223] Node 0 active_anon:684kB inactive_anon:825052kB active_file:540kB inactive_file:672kB unevictable:16kB isolated(anon):0kB isolated(file):0kB mapped:8720kB dirty:0kB writeback:0kB shmem:58840kB writeback_tmp:0kB kernel_stack:1752kB all_unreclaimable? no
    Jul 23 16:56:33 RepetierServer kernel: [618941.852238] DMA free:18484kB min:20480kB low:24576kB high:28672kB reserved_highatomic:0KB active_anon:684kB inactive_anon:824680kB active_file:480kB inactive_file:144kB unevictable:16kB writepending:0kB present:917504kB managed:892584kB mlocked:16kB pagetables:7040kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:228kB
    Jul 23 16:56:33 RepetierServer kernel: [618941.852245] lowmem_reserve[]: 0 0 0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852271] DMA: 932*4kB (UMEC) 524*8kB (UMEC) 250*16kB (UMEC) 96*32kB (UME) 30*64kB (UME) 7*128kB (UM) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 17808kB
    Jul 23 16:56:33 RepetierServer kernel: [618941.852371] 15025 total pagecache pages
    Jul 23 16:56:33 RepetierServer kernel: [618941.852378] 0 pages in swap cache
    Jul 23 16:56:33 RepetierServer kernel: [618941.852384] Swap cache stats: add 0, delete 0, find 0/0
    Jul 23 16:56:33 RepetierServer kernel: [618941.852390] Free swap  = 0kB
    Jul 23 16:56:33 RepetierServer kernel: [618941.852396] Total swap = 0kB
    Jul 23 16:56:33 RepetierServer kernel: [618941.852402] 229376 pages RAM
    Jul 23 16:56:33 RepetierServer kernel: [618941.852408] 0 pages HighMem/MovableOnly
    Jul 23 16:56:33 RepetierServer kernel: [618941.852413] 6230 pages reserved
    Jul 23 16:56:33 RepetierServer kernel: [618941.852419] 16384 pages cma reserved
    Jul 23 16:56:33 RepetierServer kernel: [618941.852425] Tasks state (memory values in pages):
    Jul 23 16:56:33 RepetierServer kernel: [618941.852431] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
    Jul 23 16:56:33 RepetierServer kernel: [618941.852453] [    115]     0   115     8746      814    61440        0             0 systemd-journal
    Jul 23 16:56:33 RepetierServer kernel: [618941.852463] [    151]     0   151     4530      217    20480        0         -1000 systemd-udevd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852476] [    354]   100   354     5595      164    26624        0             0 systemd-timesyn
    Jul 23 16:56:33 RepetierServer kernel: [618941.852485] [    390]     0   390     3252      166    20480        0             0 systemd-logind
    Jul 23 16:56:33 RepetierServer kernel: [618941.852495] [    392]     0   392      923       51    10240        0             0 alsactl
    Jul 23 16:56:33 RepetierServer kernel: [618941.852505] [    393]     0   393     2741      160    20480        0             0 wpa_supplicant
    Jul 23 16:56:33 RepetierServer kernel: [618941.852515] [    394]   104   394     1665      141    14336        0          -900 dbus-daemon
    Jul 23 16:56:33 RepetierServer kernel: [618941.852524] [    400]     0   400     1987       47    16384        0             0 cron
    Jul 23 16:56:33 RepetierServer kernel: [618941.852534] [    402]     0   402     6378      284    20480        0             0 rsyslogd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852543] [    405]     0   405     2677      103    20480        0             0 wpa_supplicant
    Jul 23 16:56:33 RepetierServer kernel: [618941.852553] [    409]   108   409     1475       98    16384        0             0 avahi-daemon
    Jul 23 16:56:33 RepetierServer kernel: [618941.852563] [    423] 65534   423     1080       44    14336        0             0 thd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852572] [    448]     0   448     7170       35    18432        0             0 rngd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852582] [    452]   108   452     1442       63    14336        0             0 avahi-daemon
    Jul 23 16:56:33 RepetierServer kernel: [618941.852591] [    506]     0   506      535       32     8192        0             0 hciattach
    Jul 23 16:56:33 RepetierServer kernel: [618941.852601] [    523]     0   523     2384       71    16384        0             0 bluetoothd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852611] [    574]     0   574      726      105    10240        0             0 dhcpcd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852621] [    581]     0   581      766       43    12288        0             0 bash
    Jul 23 16:56:33 RepetierServer kernel: [618941.852631] [    611]     0   611     2673      146    20480        0         -1000 sshd
    Jul 23 16:56:33 RepetierServer kernel: [618941.852640] [    661]     0   661    12549      292    32768        0             0 nginx
    Jul 23 16:56:33 RepetierServer kernel: [618941.852649] [    662]    33   662    12618      365    32768        0             0 nginx
    Jul 23 16:56:33 RepetierServer kernel: [618941.852659] [    663]    33   663    12611      359    32768        0             0 nginx
    Jul 23 16:56:33 RepetierServer kernel: [618941.852668] [    664]    33   664    12593      336    32768        0             0 nginx
    Jul 23 16:56:33 RepetierServer kernel: [618941.852677] [    665]    33   665    12611      359    32768        0             0 nginx
    Jul 23 16:56:33 RepetierServer kernel: [618941.852688] [    677]  1000   677      968       33    12288        0             0 xinit
    Jul 23 16:56:33 RepetierServer kernel: [618941.852698] [    678]  1000   678    48424     3559   139264        0             0 Xorg
    Jul 23 16:56:33 RepetierServer kernel: [618941.852707] [    791]  1000   791    15935      630    45056        0             0 openbox
    Jul 23 16:56:33 RepetierServer kernel: [618941.852717] [    801]  1000   801   144800     5497   395264        0             0 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852726] [    906]  1000   906     3768       52    14336        0             0 crashpad_handle
    Jul 23 16:56:33 RepetierServer kernel: [618941.852736] [    908]  1000   908     1455       29    12288        0             0 crashpad_handle
    Jul 23 16:56:33 RepetierServer kernel: [618941.852746] [    912]  1000   912    54834     1382   163840        0             0 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852756] [    913]  1000   913    54834     1382   167936        0             0 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852766] [    947]  1000   947    54834     1391   106496        0             0 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852775] [    977]  1000   977    72514     1901   210944        0           200 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852785] [    992]  1000   992    75128     4819   219136        0           200 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852794] [    994]  1000   994    59256     1923   118784        0           200 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852804] [   1001]  1000  1001    67744     1563   190464        0           200 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852814] [   1052]  1000  1052   110071    11438   514048        0           300 chromium-browse
    Jul 23 16:56:33 RepetierServer kernel: [618941.852824] [   1471]     0  1471      476       19    12288        0             0 tail
    Jul 23 16:56:33 RepetierServer kernel: [618941.852833] [   1472]     0  1472      766       45    10240        0             0 bash
    Jul 23 16:56:33 RepetierServer kernel: [618941.852843] [  26585]   109 26585   182207   161631   696320        0             0 RepetierServer
    Jul 23 16:56:33 RepetierServer kernel: [618941.852857] [   3097]     0  3097     3178      133    22528        0             0 systemd-timedat
    Jul 23 16:56:33 RepetierServer kernel: [618941.852865] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=RepetierServer,pid=26585,uid=109
    Jul 23 16:56:33 RepetierServer kernel: [618941.852971] Out of memory: Killed process 26585 (RepetierServer) total-vm:728828kB, anon-rss:646524kB, file-rss:0kB, shmem-rss:0kB, UID:109 pgtables:680kB oom_score_adj:0
    Jul 23 16:56:33 RepetierServer kernel: [618941.988180] oom_reaper: reaped process 26585 (RepetierServer), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Main process exited, code=killed, status=9/KILL
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Failed with result 'signal'.
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Service has no hold-off time (RestartSec=0), scheduling restart.
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Scheduled restart job, restart counter is at 2.
    Jul 23 16:56:34 RepetierServer systemd[1]: Stopped Repetier-Server 3D Printer Server.
    Jul 23 16:56:34 RepetierServer systemd[1]: Starting Repetier-Server 3D Printer Server...
    Jul 23 16:56:37 RepetierServer systemd[1]: Started Repetier-Server 3D Printer Server.
    Jul 23 16:56:37 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:56:40 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20237' (uid=0 pid=3581 comm="timedatectl list-timezones ")
    Jul 23 16:56:40 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:56:40 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:56:40 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 17:00:59 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 17:01:00 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20254' (uid=0 pid=4269 comm="timedatectl ")
    Jul 23 17:01:00 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 17:01:01 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 17:01:01 RepetierServer systemd[1]: Started Time & Date Service.


    Daemon Log File 

    Jul 23 16:55:34 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:56:07 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20235' (uid=0 pid=3089 comm="timedatectl ")
    Jul 23 16:56:07 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:56:07 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:56:07 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Main process exited, code=killed, status=9/KILL
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Failed with result 'signal'.
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Service has no hold-off time (RestartSec=0), scheduling restart.
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Scheduled restart job, restart counter is at 2.
    Jul 23 16:56:34 RepetierServer systemd[1]: Stopped Repetier-Server 3D Printer Server.
    Jul 23 16:56:34 RepetierServer systemd[1]: Starting Repetier-Server 3D Printer Server...
    Jul 23 16:56:37 RepetierServer systemd[1]: Started Repetier-Server 3D Printer Server.
    Jul 23 16:56:37 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    Jul 23 16:56:40 RepetierServer dbus-daemon[394]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20237' (uid=0 pid=3581 comm="timedatectl list-timezones ")
    Jul 23 16:56:40 RepetierServer systemd[1]: Starting Time & Date Service...
    Jul 23 16:56:40 RepetierServer dbus-daemon[394]: [system] Successfully activated service 'org.freedesktop.timedate1'
    Jul 23 16:56:40 RepetierServer systemd[1]: Started Time & Date Service.
    Jul 23 17:00:59 RepetierServer systemd[1]: systemd-timedated.service: Succeeded.
    
  • Ok, first thank you for timestamp and good logs. Really helpful here. First in server log 

    2022-07-23 16:55:32: Updating info for /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.g printer PulseXED124
    2022-07-23 16:55:44: Time analysing /var/lib/Repetier-Server/printer/PulseXED124/jobs/00000002_redBinoV2.g:11580734 us
    2022-07-23 16:56:10: Closing websocket for missing ping
    2022-07-23 16:56:37: Start logging...
    2022-07-23 16:56:37: Imported external command Shutdown Server
    
    you see that the server restarted as it stopped shortly after analysing the g-code (not stl file I hope).

    Looking into syslog
    Jul 23 16:56:33 RepetierServer kernel: [618941.852865] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=RepetierServer,pid=26585,uid=109
    Jul 23 16:56:33 RepetierServer kernel: [618941.852971] Out of memory: Killed process 26585 (RepetierServer) total-vm:728828kB, anon-rss:646524kB, file-rss:0kB, shmem-rss:0kB, UID:109 pgtables:680kB oom_score_adj:0
    Jul 23 16:56:33 RepetierServer kernel: [618941.988180] oom_reaper: reaped process 26585 (RepetierServer), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
    Jul 23 16:56:34 RepetierServer systemd[1]: RepetierServer.service: Main process exited, code=killed, status=9/KILL
    J
    oom-kill is a linux process that kills an application if linux is running out of memory. It choosed server as it was the biggest consumer at that moment. Actually the size was more that it normally should have.

    If you login over ssh on your pi you can run
    htop

    top see memory usage. For 1GB it should show 2-3% normally if you have not a lot of files and printers connected.
    This is most likely independent of prusa printing. Actually it is not clear what it is. If you say it happens frequently when you upload a file to that printer, please watch memory usage while you upload a test file. If that in deed happens then, please send me a sample g-code so I can analyse why that happens.

    You might also try updating to 1.4.1 using autoupdater. It will update all gcodes so it will be busy a while after update. But there we have at least fixed all known bugs so far.

  • Alright. First of all, thank you so much for digging into this, I really appreciate your efforts.

    1) I have uploaded two htop screenshots taken at few seconds difference - to try and capture some of the dynamics. I noticed most things do stay the same over 1-2 minutes of looking at it (not sure that was enough time though. Not sure if I should also calibrate htop somehow to show different outcome. Thats how I use htop when me and my roommate are struggling with openwrt - figured thats enough data).

    2) Both printers are actually currently printing (after the earlier failure, I didn't even restart the raspberry, just carried on normally and started new prints). So what we see now is just the same session from when I took the logs, and currently both printers are running for 2-3 hours already (which is the normal day-to-day activity here).

    3) You are correct. I sometimes remember how newbish I sound (or "read") when saying I "uploaded STL file" instead of "G-Code file". Always clicking on either "EXPORT G-CODE" or "UPLOAD G-CODE" should have registered somewhere :) So yeah, of course G-CODE. 

    4) Your comment about the G-CODE line (restarting after analyzing it). I think there is a pattern, but I am not completely sure about it - that the crashing happen when a file is uploaded to Pulse. I know of at least once that it happened exactly the same. Other times I either don't remember the exact scenario (or I had it reported to me by my roomie). 

    Lets assume it happens when a file is uploaded - Although I think I see a pattern (and I will follow on and provide samples as asked) of it happening this way - I dont think it ever happened with Prusa. Remember that on Prusa I push a print job with the Slicer - click and go. No manually web browsing and uploading a MatterControl sliced and exported G-CODE.

    So I think that at the moment, I may suggest isolating the situation to uploading via a web browser. Not sure if it is also related to the type of printer - I would assume it isn't as I didn't see any faulty USB/Serial/Printer messages in between the crash and uploading (as you pointed out).

    5) Regarding monitoring. I know my way around raspberries but only enough to be helpful when guided. Is there anyway I could 24/7 monitor specific values (such as memory consumption, processes, etc) and keep that in a log file? I'd prefer setting a continuous logging feature that upon crashing - I'd be able to freeze and extract. If you can suggest a strategy for that, I'd love to implement it and keep as much data as possible.

    6) Finally - updating. My favorite part of any modern technology. Will do! So once the current prints are done, I'll go ahead and update. Should it happen again, I hope you could suggest how best to monitor which values for the next crash. 

    Just in case, I will also attach the specific G-CODE that was uplaoded (though I'm pretty sure every crash had different G-CODE to it. I rarely reuse G-CODES. Hi, I hardly keep STLs!).


    HTOP1: https://i.postimg.cc/fW85gjvJ/repHTOP1.png

    HTOP2: https://i.postimg.cc/52dzP6DX/repHTOP2.png
  • Ok, screenshots look good. The memory runaway did not happen so far:-) 

    For logging memory I don't know a good tool, but you could log every minute the server memory usage. Then you also see if it goes high immediately or slowly. So login as pi

    nano /home/pi/logServerMemory

    Write following content:
    #!/bin/bash
    date >> /home/pi/memory.log
    ps aux | grep RepetierS >> /home/pi/memory.log

    Save and then make it executable:

    chmod 755 /home/pi/logServerMemory

    Now add it to cron so it gets executed every minute:

    crontab -e

    Select nano as editor. Add this line and save:
    * * * * * /home/pi/logServerMemory

    This will create a log /home/pi/memory.log

    NOTE: It will grow for ever, so from time to time just delete it if nothing happened or at some time disk is full.

    To see last 200 lines run
    tail -200 /home/pi/memory.log

    The 4th column is memory usage, so will be around 1.9 in your case. When it is above 5 I'd assume the problem kicked in and you need to check when it started increasing and remember what you did t that point.
  • Wonderful! will do so right away! couldn't update so far as I was into plenty of continuous printing, but hopefully in the morning I will be able to update to 1.4.1 as suggested. Regarding memory, I'm executing this right away and will report if anything happens.

    Hope this help anyone in the future, and thanks @Repetier for the assistance with this!

    I'll report back in a few days just in case ;)
  • edited July 2022
    Howdy, touching base with an update @Repetier

    1) I crontab'ed the script as you suggested (and also added a 1MB limit on it for archiving in a secondary file so I could always delete it and still have the monitor running with latest events).

    2) I have attached some values here from the monitor, perhaps it would make more sense to you - but I constantly see the 1.7 (lower than 1.9 even) as the usage up to a point where it a "bit" higher - 2.3+/-. All the same doesn't seem to be an issue here.

    3) Yesterday around 13:00 (25th July) I also updated to 1.4.1. Attached are some of the monitor logs before and after the update. I attached some data from the logs (I think the change in memory, again, minor as it is, was a result of the update. I manually reboot the pi post the update).


    If there will be any more issues with failures (I'll try to recreate the situation where I upload a G-CODE to the Pulse while Prusa is effortlessly about the finish a 7 hours complex print  :p and try to see if anything still happens).

    Thanks again for the efforts, and may this be fruitful for anyone stumbling something familiar in the future so we dont end like *THIS* guy!  o:)

    xkcd Wisdom of the Ancients
    #### INIT LOG ###Sun 24 Jul 23:24:32 IDT 2022 ::
    avahi      409  0.1  0.0   5900   392 ?        Ss   Jul16  22:52 avahi-daemon: running [RepetierServer.local]
    repetie+  3468  3.5  1.7  36964 15968 ?        S<sl Jul23  65:27 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        8293  0.0  0.0   7348   500 pts/0    S+   23:24   0:00 grep RepetierS
    #### END LOG ####Sun 24 Jul 23:30:01 IDT 2022 ::
    avahi      409  0.1  0.0   5900   392 ?        Ss   Jul16  22:53 avahi-daemon: running [RepetierServer.local]
    repetie+  3468  3.5  1.7  36964 15892 ?        S<sl Jul23  65:44 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        8901  0.0  0.0   7348   500 ?        S    23:30   0:00 grep RepetierS
    #### END LOG ####
    
    [..INIFITE BEARIMIES LATER..]
    
    Mon 25 Jul 03:27:01 IDT 2022 ::
    avahi      409  0.1  0.0   5900   392 ?        Ss   Jul16  23:18 avahi-daemon: running [RepetierServer.local]
    pi         800  0.0  0.0   7348   488 ?        S    03:27   0:00 grep RepetierS
    repetie+  3468  3.7  1.8  40052 16096 ?        S<sl Jul23  77:31 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    #### END LOG ####Mon 25 Jul 03:28:01 IDT 2022 ::
    avahi      409  0.1  0.0   5900   392 ?        Ss   Jul16  23:18 avahi-daemon: running [RepetierServer.local]
    pi         904  0.0  0.0   7348   512 ?        S    03:28   0:00 grep RepetierS
    repetie+  3468  3.7  1.8  40052 16084 ?        S<sl Jul23  77:33 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    #### END LOG ####
    [..EXTRA INIFITE BEARIMIES LATER..]
    #### END LOG ####Mon 25 Jul 13:13:01 IDT 2022 ::
    avahi      415  0.1  0.2   5768  2552 ?        Ss   13:02   0:01 avahi-daemon: running [RepetierServer.local]
    repetie+   660  4.1  1.5  39288 14252 ?        S<sl 13:02   0:27 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        2746  0.0  0.0   7348   552 ?        S    13:13   0:00 grep RepetierS
    #### END LOG ####Mon 25 Jul 13:14:01 IDT 2022 ::
    avahi      415  0.1  0.2   5768  2552 ?        Ss   13:02   0:01 avahi-daemon: running [RepetierServer.local]
    repetie+   660  4.3  1.8  41380 16260 ?        S<sl 13:02   0:30 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        2848  0.0  0.0   7348   552 ?        S    13:14   0:00 grep RepetierS
    #### END LOG ####Mon 25 Jul 13:15:01 IDT 2022 ::
    avahi      415  0.1  0.2   5768  2552 ?        Ss   13:02   0:01 avahi-daemon: running [RepetierServer.local]
    repetie+   660  4.2  1.9  42176 17088 ?        S<sl 13:02   0:32 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        2955  0.0  0.0   7348   548 ?        S    13:15   0:00 grep RepetierS
    #### END LOG ####Mon 25 Jul 13:16:01 IDT 2022 ::
    avahi      415  0.1  0.2   5768  2552 ?        Ss   13:02   0:01 avahi-daemon: running [RepetierServer.local]
    repetie+   660  4.2  1.8  40232 16128 ?        S<sl 13:02   0:35 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        3059  0.0  0.0   7348   528 ?        S    13:16   0:00 grep RepetierS
    #### END LOG ####Mon 25 Jul 13:17:01 IDT 2022 ::
    avahi      415  0.1  0.2   5768  2552 ?        Ss   13:02   0:01 avahi-daemon: running [RepetierServer.local]
    repetie+   660  4.6  1.9  41920 17752 ?        S<sl 13:02   0:41 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        3180  0.0  0.0   7348   580 ?        S    13:17   0:00 grep RepetierS
    #### END LOG ####Mon 25 Jul 13:18:01 IDT 2022 ::
    avahi      415  0.1  0.2   5768  2552 ?        Ss   13:02   0:01 avahi-daemon: running [RepetierServer.local]
    repetie+   660  7.5  2.6  47860 23660 ?        S<sl 13:02   1:11 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi        3291  0.0  0.0   7348   544 ?        S    13:18   0:00 grep RepetierS
    #### END LOG ####
    [..AND NOW:]
    #### END LOG ####Tue 26 Jul 14:25:01 IDT 2022 ::
    avahi      415  0.1  0.2   5900  2552 ?        Ss   Jul25   2:30 avahi-daemon: running [RepetierServer.local]
    repetie+   660  3.2  2.3  44672 20852 ?        S<sl Jul25  49:16 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi       28075  0.0  0.0   7348   544 ?        S    14:25   0:00 grep RepetierS
    #### END LOG ####Tue 26 Jul 14:26:01 IDT 2022 ::
    avahi      415  0.1  0.2   5900  2552 ?        Ss   Jul25   2:30 avahi-daemon: running [RepetierServer.local]
    repetie+   660  3.2  2.3  44672 20840 ?        S<sl Jul25  49:18 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi       28176  0.0  0.0   7348   564 ?        S    14:26   0:00 grep RepetierS
    #### END LOG ####Tue 26 Jul 14:27:01 IDT 2022 ::
    avahi      415  0.1  0.2   5900  2552 ?        Ss   Jul25   2:30 avahi-daemon: running [RepetierServer.local]
    repetie+   660  3.2  2.3  44672 20828 ?        S<sl Jul25  49:19 /usr/local/Repetier-Server/bin/RepetierServer -c /usr/local/Repetier-Server/etc/RepetierServer.xml --daemon
    pi       28232  0.0  0.0   7348   524 ?        S    14:27   0:00 grep RepetierS
    #### END LOG ####

  • Memory usage looks good so far. It varies always a bit depending on what server is just doing. Juts when it starts going craze exceeding 10% it would be unusual and probably the issue you have.

    If you have access to it before it crashes due to memory usage also try to provide
    ps aux 
    output. One case where this can in deed happen is if you have a websocket open and a request requires strating an external app that never returns. That blocks the socket and we add data in cache to deliver after request is finished. I'm already thinking about a strategy to at least stop adding data to such processes but since they are busy it is quite difficult.
Sign In or Register to comment.