mooncord Service crashes with Out Of Memory error

Jan 31 13:12:21 mainsailos npm[1158]: <--- Last few GCs --->
Jan 31 13:12:21 mainsailos npm[1158]: al[1158:0x7f64e70] 26110710 ms: Mark-Compact (reduce) 30.4 (32.7) -> 30.4 (32.7) MB, 10.01 / 0.02 ms  (+ 73.4 ms in 104 steps since start of marking, biggest step 9.9 ms, walltime since start of marking 99 ms) (average mu = 0.312, current mu = 0.273) finali[1158:0x7f64e70] 26110836 ms: Mark-Compact (reduce) 30.4 (32.7) -> 30.3 (32.7) MB, 5.07 / 0.00 ms  (+ 71.9 ms in 147 steps since start of marking, biggest step 1.0 ms, walltime since start of marking 90 ms) (average mu = 0.351, current mu = 0.389) finaliz
Jan 31 13:12:21 mainsailos npm[1158]: <--- JS stacktrace --->
Jan 31 13:12:21 mainsailos npm[1158]: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
Jan 31 13:12:21 mainsailos npm[1158]:  1: 0xc794bc node::Abort() [node]
Jan 31 13:12:21 mainsailos npm[1158]:  2: 0xb6e418 void node::FPrintF<>(_IO_FILE*, char const*) [node]
Jan 31 13:12:21 mainsailos npm[1158]:  3: 0xe735cc v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [node]
Jan 31 13:12:21 mainsailos npm[1158]:  4: 0xe7379c v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [node]
Jan 31 13:12:21 mainsailos npm[1158]:  5: 0x107ae1c  [node]
Jan 31 13:12:21 mainsailos npm[1158]:  6: 0x107b338 v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [node]
Jan 31 13:12:21 mainsailos npm[1158]:  7: 0x1090b20 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*) [node]
Jan 31 13:12:21 mainsailos npm[1158]:  8: 0x109116c v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
Jan 31 13:12:21 mainsailos npm[1158]:  9: 0x1091c70 v8::internal::Heap::FinalizeIncrementalMarkingIfComplete(v8::internal::GarbageCollectionReason) [node]
Jan 31 13:12:21 mainsailos npm[1158]: 10: 0x10935b4 v8::internal::IncrementalMarkingJob::Task::RunInternal() [node]
Jan 31 13:12:21 mainsailos npm[1158]: 11: 0xce6888  [node]
Jan 31 13:12:21 mainsailos npm[1158]: 12: 0xce937c node::PerIsolatePlatformData::FlushForegroundTasksInternal() [node]
Jan 31 13:12:21 mainsailos npm[1158]: 13: 0x17b03c0  [node]
Jan 31 13:12:21 mainsailos npm[1158]: 14: 0x17c3c84  [node]
Jan 31 13:12:21 mainsailos npm[1158]: 15: 0x17b117c uv_run [node]
Jan 31 13:12:21 mainsailos npm[1158]: 16: 0xba6d58 node::SpinEventLoopInternal(node::Environment*) [node]
Jan 31 13:12:21 mainsailos npm[1158]: 17: 0xcbf5a8 node::NodeMainInstance::Run() [node]
Jan 31 13:12:21 mainsailos npm[1158]: 18: 0xc386b4 node::LoadSnapshotDataAndRun(node::SnapshotData const**, node::InitializationResultImpl const*) [node]
Jan 31 13:12:21 mainsailos npm[1158]: 19: 0xc3ba2c node::Start(int, char**) [node]
Jan 31 13:12:21 mainsailos npm[1158]: 20: 0x7f8cd50e18 __libc_start_main [/lib/aarch64-linux-gnu/libc.so.6]
Jan 31 13:12:21 mainsailos npm[1158]: 21: 0xba51d0  [node]
Jan 31 13:12:21 mainsailos npm[1157]: Aborted
Jan 31 13:12:21 mainsailos systemd[1]: MoonCord.service: Main process exited, code=exited, status=134/n/a

Feb 02 '24 05:02 qwertychouskie

hey there on what hardware are you running mooncord?

Feb 03 '24 15:02 eliteSchwein

Raspberry Pi 4, I believe the 4GB version

Feb 03 '24 20:02 qwertychouskie

Are you on bullseye?

Feb 05 '24 13:02 eliteSchwein

Yes, bullseye.

Feb 07 '24 06:02 qwertychouskie

I have this same issue.

Feb 21 05:19:53 bane npm[3418]: <--- Last few GCs --->
Feb 21 05:19:53 bane npm[3418]: ce start of marking 26 ms) (average mu = 0.732, current mu = 0.253) allocati[3418:0x6518f40] 116360549 ms: Mark-Compact (reduce) 31.2 (33.6) -> 31.2 (33.6) MB, 25.25 / 0.00 ms  (+ 0.0 ms in 0 steps since start of marking, biggest step 0.0 ms, wallt>
Feb 21 05:19:53 bane npm[3418]: <--- JS stacktrace --->
Feb 21 05:19:53 bane npm[3418]: FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
Feb 21 05:19:53 bane npm[3418]: ----- Native stack trace -----
Feb 21 05:19:53 bane npm[3418]:  1: 0xca5580 node::Abort() [node]
Feb 21 05:19:53 bane npm[3418]:  2: 0xb781f9  [node]
Feb 21 05:19:53 bane npm[3418]:  3: 0xeca4d0 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [node]
Feb 21 05:19:53 bane npm[3418]:  4: 0xeca7b7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [node]
Feb 21 05:19:53 bane npm[3418]:  5: 0x10cb95a v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [node]
Feb 21 05:19:53 bane npm[3418]:  6: 0x10a7d56 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [node]
Feb 21 05:19:53 bane npm[3418]:  7: 0x10994cc v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawArray(int, v8::internal::AllocationType) [node]
Feb 21 05:19:53 bane npm[3418]:  8: 0x10998b3 v8::internal::FactoryBase<v8::internal::Factory>::NewWeakFixedArrayWithMap(v8::internal::Map, int, v8::internal::AllocationType) [node]
Feb 21 05:19:53 bane npm[3418]:  9: 0x10bf749 v8::internal::Factory::NewTransitionArray(int, int) [node]
Feb 21 05:19:53 bane npm[3418]: 10: 0x13f933a v8::internal::TransitionsAccessor::Insert(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Map>, v8::internal::SimpleTransitionFlag) [node]
Feb 21 05:19:53 bane npm[3418]: 11: 0x138b520 v8::internal::Map::ConnectTransition(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::SimpleTransitionFlag) [node]
Feb 21 05:19:53 bane npm[3418]: 12: 0x138d442 v8::internal::Map::CopyReplaceDescriptors(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::DescriptorArray>, v8::internal::TransitionFlag, v8::internal::MaybeHandle<v8::internal::Name>
Feb 21 05:19:53 bane npm[3418]: 13: 0x138dc26 v8::internal::Map::CopyAddDescriptor(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Descriptor*, v8::internal::TransitionFlag) [node]
Feb 21 05:19:53 bane npm[3418]: 14: 0x138ddd4 v8::internal::Map::CopyWithField(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::FieldType>, v8::internal::PropertyAttributes, v8::internal:>
Feb 21 05:19:53 bane npm[3418]: 15: 0x138fada v8::internal::Map::TransitionToDataProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::i>
Feb 21 05:19:53 bane npm[3418]: 16: 0x137f04a v8::internal::LookupIterator::PrepareTransitionToDataProperty(v8::internal::Handle<v8::internal::JSReceiver>, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::StoreOrigin) [node]
Feb 21 05:19:53 bane npm[3418]: 17: 0x139aa98 v8::internal::Object::TransitionAndWriteDataProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::Maybe<v8::internal::ShouldThrow>, v8::internal::StoreOrigin) [node]
Feb 21 05:19:53 bane npm[3418]: 18: 0x150ffa5 v8::internal::Runtime_DefineKeyedOwnPropertyInLiteral(int, unsigned long*, v8::internal::Isolate*) [node]
Feb 21 05:19:53 bane npm[3418]: 19: 0x193cef6  [node]
Feb 21 05:19:56 bane npm[3417]: Aborted (core dumped)
Feb 21 05:19:56 bane systemd[1]: MoonCord.service: Main process exited, code=exited, status=134/n/a

System:

Ubuntu 22.04 LTS 
Intel(R) Core(TM) i5-4260U CPU @ 1.40GHz
8GB of memory

Feb 21 '24 16:02 samwiseg0

For what it's worth, updating to the latest https://github.com/eliteSchwein/mooncord/blob/master/scripts/MoonCord.service masks the issue by making the service auto-restart, but it'd still be better for it to not crash in the first place.

Feb 21 '24 21:02 qwertychouskie

Mine is auto restarting. Still getting notified randomly when it restarts that my printer is ready.

Feb 21 '24 21:02 samwiseg0

what is your output from node --version ?

Feb 22 '24 18:02 eliteSchwein

node --version ?

~$ node --version
v20.11.1

Edit: I do not think this is happening on another box that is running .0 vs the one that is running .1

 $  node --version
v20.11.0

Feb 22 '24 18:02 samwiseg0

hmm this is odd. i will look into that and will maybe change the the gc settings.

Feb 23 '24 09:02 eliteSchwein

Very. I have tested this on my printers pi running ~~buster~~ bullseye as well as the ubuntu machine mentioned. So this issue is across arm and intel architectures.

Let me know if there is any testing you would like me to perform. It crashes about once a day.

Feb 23 '24 14:02 samwiseg0

hmm buster isnt supported anymore. anyways, i will test it on my cm4 with dev mode (that actuelly eats even more ram)

Feb 24 '24 15:02 eliteSchwein

hmm buster isnt supported anymore. anyways, i will test it on my cm4 with dev mode (that actuelly eats even more ram)

sorry I meant bullseye. it was a fresh install of mainsail os 64 bit

Feb 24 '24 15:02 samwiseg0

In dev mode i have around 20mb ram usage without printing. I will test little more.

Feb 25 '24 14:02 eliteSchwein

In dev mode i have around 20mb ram usage without printing. I will test little more.

Is there something I can do on my side to gather more data for you?

Feb 25 '24 14:02 samwiseg0

uhm sure.

its not a elegant test method but it works

sudo systemctl stop MoonCord
sudo apt install screen
screen -S mooncordTest
cd ~/home/mooncord
/usr/bin/npm run debugstart /home/pi/printer_data/config/

with ctrl + a + d you detach the screen session with screen -rx mooncordTest you can attach the screen session

Feb 25 '24 20:02 eliteSchwein

Got it setup and piping it to a log file just so I don't lose any data when it crashes. I will post back once it crashes. Should take about a day or so.

Feb 25 '24 22:02 samwiseg0

Preliminary results I think show a slow leak. This is only after a few hours.

> [email protected] debugstart
> node --max-old-space-size=32 --trace_gc --expose-gc --trace-deprecation --trace-warnings --trace-uncaught --track-heap-objects dist/index.js /opt/moon_frost/

[131168:0x673e2d0]        6 ms: Mark-Compact 1.1 (2.2) -> 1.1 (3.2) MB, 1.50 / 0.00 ms  (average mu = 1.000, current mu = 1.000) heap profiler; GC in old space requested
[131168:0x673e2d0]      303 ms: Scavenge 6.2 (7.7) -> 5.8 (7.7) MB, 9.76 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[131168:0x673e2d0]      415 ms: Scavenge 6.5 (7.9) -> 6.4 (10.9) MB, 15.18 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[131168:0x673e2d0]      784 ms: Scavenge 8.5 (11.1) -> 8.1 (11.4) MB, 50.73 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[131168:0x673e2d0]     1027 ms: Scavenge 8.6 (11.4) -> 8.6 (16.4) MB, 92.00 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[131168:0x673e2d0]     1664 ms: Scavenge 12.8 (17.4) -> 10.5 (18.4) MB, 56.11 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[131168:0x673e2d0]     2249 ms: Scavenge 14.0 (18.6) -> 12.3 (19.9) MB, 31.49 / 0.00 ms  (average mu = 1.000, current mu = 1.000) allocation failure;
[131168:0x673e2d0]     2275 ms: Mark-Compact 12.3 (19.9) -> 10.1 (28.5) MB, 5.02 / 0.03 ms  (+ 0.0 ms in 1 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 26 ms) (average mu = 0.998, current mu = 0.998) finalize incremental marking via stack guard; GC in old space requested
[131168:0x673e2d0]     3690 ms: Scavenge 19.2 (28.7) -> 13.1 (28.7) MB, 37.80 / 0.00 ms  (average mu = 0.998, current mu = 0.998) allocation failure;
[131168:0x673e2d0]     4281 ms: Scavenge 21.3 (30.5) -> 18.5 (32.5) MB, 92.01 / 0.00 ms  (average mu = 0.998, current mu = 0.998) allocation failure;
...
[131168:0x673e2d0]  9800483 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 1.74 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9808749 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 0.95 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9816994 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 1.23 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9825290 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 0.82 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9834015 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 0.84 / 0.00 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9842326 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 0.86 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9850596 ms: Scavenge 22.9 (24.1) -> 22.1 (24.1) MB, 0.94 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9858369 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 2.04 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9866635 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 1.41 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9874905 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 0.85 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9883175 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 0.87 / 0.00 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9891446 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 0.33 / 0.00 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9899720 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 1.11 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9908083 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 0.43 / 0.00 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9916257 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 1.78 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9924525 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 0.73 / 0.00 ms  (average mu = 0.999, current mu = 1.000) task;
[131168:0x673e2d0]  9932796 ms: Scavenge 23.0 (24.1) -> 22.2 (24.1) MB, 0.88 / 0.01 ms  (average mu = 0.999, current mu = 1.000) task;

Feb 26 '24 00:02 samwiseg0

hmm. thats actuelly a good point. well i guess now that i didnt fix the memory leaks. i will take a look and try to fix it.

Feb 26 '24 08:02 eliteSchwein

Screenshot_20240226_091229

i added the inspect mode to debug start, this gives even more details via inspector mode from chrome (they use both the same engine)

Feb 26 '24 08:02 eliteSchwein

Screenshot_20240226_091557 on the first looks, it looks like that discordjs has a memory leak. i will wait a little bit longer

Feb 26 '24 08:02 eliteSchwein

interesting. its also "old space". the profiler triggers garbage collect before making a snapshot. so its just garbage somewhere?

Feb 26 '24 08:02 eliteSchwein

it seems like that the latest patches fixed it? testing it with a profile currently for some hours and hopefully i can backtrace the source of the memory leak.

Feb 27 '24 22:02 eliteSchwein

@eliteSchwein Which patches?

Here are the results from the test. The service did crash eventually. debug.log.zip

li[131168:0x673e2d0] 110701117 ms: Mark-Compact (reduce) 30.9 (33.3) -> 30.8 (33.3) MB, 5.80 / 0.01 ms  (+ 0.3 ms in 1 steps since start of marking, biggest step 0.3 ms, walltime since start of marking 55 ms) (average mu = 0.267, current mu = 0.913) finaliz[131168:0x673e2d0] 110701194 ms: Mark-Compact (reduce) 31.0 (33.3) -> 30.8 (33.3) MB, 15.60 / 0.57 ms  (+ 5.4 ms in 2 steps since start of marking, biggest step 5.4 ms, walltime since start of marking 65 ms) (average mu = 0.313, current mu = 0.763) finali

<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
----- Native stack trace -----

 1: 0xca5430 node::Abort() [node]
 2: 0xb7807d  [node]
 3: 0xeca0b0 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [node]
 4: 0xeca397 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, v8::OOMDetails const&) [node]
 5: 0x10dc0e5  [node]
 6: 0x10dc674 v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [node]
 7: 0x10f3564 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*) [node]
 8: 0x10f3d7c v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
 9: 0x10f5eda v8::internal::Heap::HandleGCRequest() [node]
10: 0x1061547 v8::internal::StackGuard::HandleInterrupts() [node]
11: 0x1502bfa v8::internal::Runtime_StackGuard(int, unsigned long*, v8::internal::Isolate*) [node]
12: 0x193cef6  [node]
Aborted (core dumped)

Are there some patches you would like me to test with before I restart the service?

Feb 27 '24 23:02 samwiseg0

the latest on the main branch

Mar 18 '24 08:03 eliteSchwein

mooncord mooncord copied to clipboard

Service crashes with Out Of Memory error

mooncord
mooncord copied to clipboard