log.io-file-input stops transmitting to log.io with DailyRollingFileAppender

[hivka]

Hi I have noticed that the log.io server stops receiving messages from the io-file-input when the log file is rotated. What I mean is that when an hour has passed the current logfile.log is renamed to logfile.log.[date with time]log and a new logfile.log is created.

So for example: log4j.appender.Appender2=org.apache.log4j.DailyRollingFileAppender log4j.appender.Appender2.File=app.log log4j.appender.Appender2.DatePattern='.'yyyy-MM-dd-HH

My sources in file.json are linked to specific files ex: "inputs": [ { "source": "example", "stream": "example_stream", "config": { "path": "/logs/logfile.log" } },

I have changed the debug = "true" on the server so that I could observe all of the messages send and it seems that after a while only messages from sources that have constant name (with no log rotator) are left.

This is just my observation, maybe you could take a look if I got the problem right. Furthermore is there any way to see the logs from io-file-input?

[msmathers]

This is a known limitation of node.js' fs.watch() mechanism and we have a planned feature issue for this: #211

In the meantime, your options are:

• Turn off file rotation
• Use a directory path instead of a file path in your input config, and restart the log.io-file-input process when a new file appears. It will recognize the new file on restart.

[msmathers]

See https://github.com/NarrativeScience/log.io/releases/tag/v0.4.14

[hivka]

Hi Unfortunately with the logrotator this fix is not working. My version is log.io-file-input@0.4.14. The exact same situation is present as in previous version. I do not know what the problem is, maybe some connection is broken to the watched file with the rotator.

Through it is a really nice touch to log the watched files in the log :)

I am still linking the streams to specific files: "inputs": [ { "source": "example", "stream": "example_stream", "config": { "path": "/logs/logfile.log" } },

Using a wildcard in the streams: "path": "/logs/logfile.log*" does not do the trick eater, because I think there a re too mamy files and eventually I have an error in the logs: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory

When assigning a different wildcard: "path": "/logs/logfile.lo?" The file is not displayed in the list of watched files. So a bummer also.

If you would have some insights how to fix this problem I am all ears :) Because maybe there is a quick fix for that that I have not even thought about.

[msmathers]

How many files are in your /logs/ directory?

[msmathers]

Additionally, could you post a list of the filenames in that directory if it's not too long / private?

[hivka]

Yes, hi :) Of course I can anonymise my list (listOfLogFiles.txt) Oh and original names of the application logs are not fancy, to get the idea something like: app.log, api.log, connector.log, middleware.log. The logs are originally placed under something like: "/logs/web-app/app/" (I added so that you know the lengths of the file names and that the folder name is with a special character "-").

Currently I have about 300 files from one application (I am also using logbrowser so it is nice to have logs from some period of time.

So when configuring: "path": "/logs/appNameOne.*" There ale more than 300 files to be watched.

When I use (which I have not tested because it seems a bit much): "path": "/logs/*" There will be over 1000 files.

I have also tried the approach: "path": "/logs/*.log" Then the harvester did log to be logged my 4 application logs correctly: [all][test] Watching: /logs/appNameOne.log [all][test] Watching: /logs/appNameTwo.log [all][test] Watching: /logs/appNameThree.log [all][test] Watching: /logs/appNameFour.log

The logs did wrote for a few seconds, but unfortunately this yielded the error below. I believe due to mamy logs for one stream. So i was not able to check the log rolling mechanism for this approach.

And maybe an info: I have used the former application (which was 6 years old) and it did work there. I have rewritten the dockerfile and configurations for the new app just this week. And of course I have anonymised the logs.

Sorry that the messages keep longer and longer, I want to keep the answers as much precise as possible and this requires a lot of text :)

Error:

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

<--- Last few GCs --->

[7:0x45a33e0] 115111 ms: Mark-sweep 1398.6 (1425.7) -> 1398.2 (1425.2) MB, 1435.4 / 5.6 ms (+ 0.0 ms in 9 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 1446 ms) (average mu = 0.147, current mu = 0.043) allocation fa[7:0x45a33e0] 115948 ms: Mark-sweep 1399.0 (1425.2) -> 1398.5 (1425.7) MB, 827.0 / 7.5 ms (average mu = 0.097, current mu = 0.012) allocation failure scavenge might not succeed

<--- JS stacktrace --->

==== JS stack trace =========================================

0: ExitFrame [pc: 0x1c3639b5be1d]
1: StubFrame [pc: 0x1c3639b5d1df]

Security context: 0x0cd14411e6c1 2: normalizeString(aka normalizeString) [0xe0ef2582ac9] [path.js:~52] [pc=0x1c3639f40e7e](this=0x3dd128c826f1 ,path=0x1693cfac8591 <String[40]: /logs/appNameOne.log.2020-04-23-21/>,allowAboveRoot=0x3dd128c829a1 ,separator=0x1049dd2325c9 <String[1]: />,isPathSeparator=0x0e0ef2582b09 <JSFunction ...

1: 0x8fb090 node::Abort() [node] 2: 0x8fb0dc [node] 3: 0xb031ce v8::Utils::ReportOOMFailure(v8::internal::Isolate, char const, bool) [node] 4: 0xb03404 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate, char const, bool) [node] 5: 0xef7462 [node] 6: 0xef7568 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [node] 7: 0xf03642 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node] 8: 0xf03f74 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node] 9: 0xf06be1 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [node] 10: 0xed0064 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [node] 11: 0x11701ee v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object*, v8::internal::Isolate) [node] 12: 0x1c3639b5be1d Aborted (core dumped) Connected to server: logio-server:8777

And I have another error: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory

<--- Last few GCs --->

[7:0x31183e0] 108294 ms: Scavenge 1398.1 (1424.7) -> 1397.7 (1425.7) MB, 19.3 / 0.0 ms (average mu = 0.155, current mu = 0.050) allocation failure [7:0x31183e0] 109167 ms: Mark-sweep 1398.4 (1425.7) -> 1398.0 (1425.2) MB, 858.2 / 6.0 ms (average mu = 0.130, current mu = 0.055) allocation failure scavenge might not succeed

<--- JS stacktrace --->

==== JS stack trace =========================================

0: ExitFrame [pc: 0x1b9a26cdbe1d]

Security context: 0x3be71d81e6c1 1: then [0x3be71d811251](this=0x17b9bd88d391 ,0x2b61bacd5301 <JSFunction (sfi = 0x1a8b4b14f11)>,0x2b61bacc4921 <JSFunction (sfi = 0x1a8b4b14ea9)>) 2: all [0x3be71d811059](this=0x3be71d810ed1 <JSFunction Promise (sfi = 0x1a8b4b14a09)>,0x1580a907ffd1 <JSArray[1067]>) 3: _read [0x180adc6f4bd1] [/usr/lib/node_modules/log...

1: 0x8fb090 node::Abort() [node] 2: 0x8fb0dc [node] 3: 0xb031ce v8::Utils::ReportOOMFailure(v8::internal::Isolate, char const, bool) [node] 4: 0xb03404 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate, char const, bool) [node] 5: 0xef7462 [node] 6: 0xef7568 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [node] 7: 0xf03642 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node] 8: 0xf03f74 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node] 9: 0xf06be1 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [node] 10: 0xed0064 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [node] 11: 0x11701ee v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object*, v8::internal::Isolate) [node] 12: 0x1b9a26cdbe1d Aborted (core dumped)

[msmathers]

Alright, so I just published a new version (v0.4.15) that I'm hoping solves your original issue.

I was able to simulate log rotation by moving a file that was being watched and then creating a new file of the same name. I confirmed that doing this caused the file input to not send messages when the new file was updated. v0.4.15 fixes that behavior.

Additionally, I assume you don't actually need to be watching all of the log files in that directory since no new log lines are being written to archived files, only appNameOne.log, appNameTwo.log, etc... So hopefully the memory overflow won't be an issue once you restore your file input configuration to only look at the specific files being actively written to.

[hivka]

Hi It seems to working alright :) (With the reference to specific files, no wildcards needed). Good work and thank you!

[hivka]

Hello. It seems to stop working after the weekend. No errors shows in the harvester, but also no messages are visible to be received in server. Furthermore: the logs from hour appender are not send, but the day appender logs are send (the day appender obsolete logs are also gzipped on the sever).

[msmathers]

A couple questions:

• How much time elapsed between when you started the harvester process and when logs were no longer being sent to the server?
• Do you have any evidence that the harvester "survived" a log rotation event?