Why do Splunk forwarder stop sending specific logs after a random amount of time?

[jstmatt]

Hi Splunkers!

We have an issue where, when upgrading to a newer version of the Splunk Universal forwarder (we are currently on 6.2.4, old but working fine), we are finding that the newer forwarders will stop sending the logs of our specified files after a random amount of time.  (This is in a Kubernetes environment, and have verified there are no memory/cpu/disk issues, and that it is working fine sending the splunkd.log and metrics.log files without issue).  We have tried rolling back to 6.2.4, from 8.2.7, and things work fine.  We are now trying to roll forward to 7.3.9 from 6.2.4 (versus the jump from 6.2.4 to 8.2.7).

With the above stated, it seems very strange to me that, even with low-output logs (maybe 1x transaction every 15-20 minutes), it just "works".... for maybe a few hours, or even up to 1 day.  However, the logs appear to stop being recorded in the Splunk forwarder.  The only "error" we have noticed is the following entries after enabling debug mode.

Thanks for any assistance!

08-04-2022 19:01:45.983 +0000 DEBUG FilesystemFilter [104 tailreader0] - Testing path=/data/logs/gos-transactions.log(real=/data/logs/gos-transactions.log) with global blacklisted paths
08-04-2022 19:01:45.983 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - updateReliabilityScore: fs=0x10304, worked=Y, score=1->2
08-04-2022 19:01:45.983 +0000 DEBUG FileClassifierManager [104 tailreader0] - Finding type for file: /data/logs/gos-transactions.log
08-04-2022 19:01:45.983 +0000 DEBUG FileClassifierManager [104 tailreader0] - filename="/data/logs/gos-transactions.log" invalidCharCount="0" TotalCharCount="0" PercentInvalid="0.000000"
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - Storing pending metadata for file=/data/logs/gos-transactions.log, sourcetype=log4j, charset=UTF-8
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - setting trailing nulls to false via 'true' or 'false' from conf'
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - Loading state from fishbucket.
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - Attempting to load indexed extractions config from conf=source::/data/logs/gos-transactions.log|host::cbs-global-outbound-services-systest-v1-0-0-deployment-7b9r9xc7|log4j|53 ...
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - /data/logs/gos-transactions.log is a small file (size=0b).
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - initcrc has changed to: 0x720891e9581b5428.
08-04-2022 19:01:45.983 +0000 INFO FileTracker [104 tailreader0] - Locked key=0x720891e9581b5428 to state=0x7f14a1493000
08-04-2022 19:01:45.983 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x720891e9581b5428
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - Normal record was not found for initCrc=0x720891e9581b5428.
08-04-2022 19:01:45.983 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x720891e9581b5428
08-04-2022 19:01:45.983 +0000 DEBUG WatchedFile [104 tailreader0] - Creating new pipeline input channel with channel id: 54.
08-04-2022 19:01:45.984 +0000 DEBUG WatchedFile [104 tailreader0] - Attempting to load indexed extractions config from conf=source::/data/logs/gos-transactions.log|host::cbs-global-outbound-services-systest-v1-0-0-deployment-7b9r9xc7|log4j|54 ...
08-04-2022 19:01:45.984 +0000 DEBUG WatchedFile [104 tailreader0] - seeking /data/logs/gos-transactions.log to off=0
08-04-2022 19:01:45.984 +0000 DEBUG WatchedFile [104 tailreader0] - Reached EOF: /data/logs/gos-transactions.log (read 0 bytes)
08-04-2022 19:01:45.984 +0000 INFO FileTracker [104 tailreader0] - Unlocked key=0x720891e9581b5428 locked to state=0x7f14a1493000
08-04-2022 19:01:45.984 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/data/logs/gos-transactions.log"
08-04-2022 19:01:45.985 +0000 DEBUG FilesystemFilter [104 tailreader0] - Testing path=/data/logs/gos-error.log(real=/data/logs/gos-error.log) with global blacklisted paths
08-04-2022 19:01:45.985 +0000 DEBUG FileClassifierManager [104 tailreader0] - Finding type for file: /data/logs/gos-error.log
08-04-2022 19:01:45.985 +0000 DEBUG FileClassifierManager [104 tailreader0] - filename="/data/logs/gos-error.log" invalidCharCount="0" TotalCharCount="0" PercentInvalid="0.000000"
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - Storing pending metadata for file=/data/logs/gos-error.log, sourcetype=log4j, charset=UTF-8
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - setting trailing nulls to false via 'true' or 'false' from conf'
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - Loading state from fishbucket.
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - Attempting to load indexed extractions config from conf=source::/data/logs/gos-error.log|host::cbs-global-outbound-services-systest-v1-0-0-deployment-7b9r9xc7|log4j|55 ...
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - /data/logs/gos-error.log is a small file (size=0b).
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - initcrc has changed to: 0x117409bca1aa15ee.
08-04-2022 19:01:45.985 +0000 INFO FileTracker [104 tailreader0] - Locked key=0x117409bca1aa15ee to state=0x7f14a1493400
08-04-2022 19:01:45.985 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x117409bca1aa15ee
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - Normal record was not found for initCrc=0x117409bca1aa15ee.
08-04-2022 19:01:45.985 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x117409bca1aa15ee
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - Creating new pipeline input channel with channel id: 56.
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - Attempting to load indexed extractions config from conf=source::/data/logs/gos-error.log|host::cbs-global-outbound-services-systest-v1-0-0-deployment-7b9r9xc7|log4j|56 ...
08-04-2022 19:01:45.985 +0000 DEBUG WatchedFile [104 tailreader0] - seeking /data/logs/gos-error.log to off=0
08-04-2022 19:01:45.986 +0000 DEBUG WatchedFile [104 tailreader0] - Reached EOF: /data/logs/gos-error.log (read 0 bytes)
08-04-2022 19:01:45.986 +0000 INFO FileTracker [104 tailreader0] - Unlocked key=0x117409bca1aa15ee locked to state=0x7f14a1493400
08-04-2022 19:01:45.986 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/data/logs/gos-error.log"
08-04-2022 19:01:45.988 +0000 DEBUG FilesystemFilter [104 tailreader0] - Testing path=/data/logs/gos-reqresp.log(real=/data/logs/gos-reqresp.log) with global blacklisted paths
08-04-2022 19:01:45.988 +0000 DEBUG FileClassifierManager [104 tailreader0] - Finding type for file: /data/logs/gos-reqresp.log
08-04-2022 19:01:45.988 +0000 DEBUG FileClassifierManager [104 tailreader0] - filename="/data/logs/gos-reqresp.log" invalidCharCount="0" TotalCharCount="0" PercentInvalid="0.000000"
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Storing pending metadata for file=/data/logs/gos-reqresp.log, sourcetype=log4j, charset=UTF-8
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - setting trailing nulls to false via 'true' or 'false' from conf'
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Loading state from fishbucket.
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Attempting to load indexed extractions config from conf=source::/data/logs/gos-reqresp.log|host::cbs-global-outbound-services-systest-v1-0-0-deployment-7b9r9xc7|log4j|57 ...
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - /data/logs/gos-reqresp.log is a small file (size=0b).
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - initcrc has changed to: 0x5f2cc808b9ff9884.
08-04-2022 19:01:45.988 +0000 INFO FileTracker [104 tailreader0] - Locked key=0x5f2cc808b9ff9884 to state=0x7f14a1493800
08-04-2022 19:01:45.988 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x5f2cc808b9ff9884
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Normal record was not found for initCrc=0x5f2cc808b9ff9884.
08-04-2022 19:01:45.988 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x5f2cc808b9ff9884
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Creating new pipeline input channel with channel id: 58.
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Attempting to load indexed extractions config from conf=source::/data/logs/gos-reqresp.log|host::cbs-global-outbound-services-systest-v1-0-0-deployment-7b9r9xc7|log4j|58 ...
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - seeking /data/logs/gos-reqresp.log to off=0
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Reached EOF: /data/logs/gos-reqresp.log (read 0 bytes)
08-04-2022 19:01:45.988 +0000 INFO FileTracker [104 tailreader0] - Unlocked key=0x5f2cc808b9ff9884 locked to state=0x7f14a1493800
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Loading state from fishbucket.
08-04-2022 19:01:45.988 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/data/logs/gos-reqresp.log"
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - /opt/splunk/etc/splunk.version is a small file (size=70b).
08-04-2022 19:01:45.988 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x88bb06af0f1e7032
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Record found, will advance file by offset=70 initcrc=0x88bb06af0f1e7032.
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - Preserving seekptr and initcrc.
08-04-2022 19:01:45.988 +0000 DEBUG WatchedFile [104 tailreader0] - seeking /opt/splunk/etc/splunk.version to off=70
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Reached EOF: fname=/opt/splunk/etc/splunk.version initcrclen=1048576 fishstate=key=0x88bb06af0f1e7032 sptr=70 scrc=0x4ec910cde69cfaaa fnamecrc=0x88bb06af0f1e7032 modtime=1659639678
08-04-2022 19:01:45.989 +0000 INFO FileTracker [104 tailreader0] - Unlocked key=0x88bb06af0f1e7032 locked to state=0x7f14a140d400
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Loading state from fishbucket.
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - /opt/splunk/var/log/splunk/first_install.log is a small file (size=70b).
08-04-2022 19:01:45.989 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x2deca923e7cb5a06
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Record found, will advance file by offset=70 initcrc=0x2deca923e7cb5a06.
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Preserving seekptr and initcrc.
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - seeking /opt/splunk/var/log/splunk/first_install.log to off=70
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Reached EOF: fname=/opt/splunk/var/log/splunk/first_install.log initcrclen=1048576 fishstate=key=0x2deca923e7cb5a06 sptr=70 scrc=0x4ec910cde69cfaaa fnamecrc=0x2deca923e7cb5a06 modtime=1659639679
08-04-2022 19:01:45.989 +0000 INFO FileTracker [104 tailreader0] - Unlocked key=0x2deca923e7cb5a06 locked to state=0x7f14a140ec00
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Loading state from fishbucket.
08-04-2022 19:01:45.989 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/opt/splunk/var/log/splunk/first_install.log"
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - /opt/splunk/var/log/splunk/splunkd-utility.log is a small file (size=560b).
08-04-2022 19:01:45.989 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x33674102d8ed48d7
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Record found, will advance file by offset=560 initcrc=0x33674102d8ed48d7.
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Preserving seekptr and initcrc.
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - seeking /opt/splunk/var/log/splunk/splunkd-utility.log to off=560
08-04-2022 19:01:45.989 +0000 DEBUG WatchedFile [104 tailreader0] - Reached EOF: fname=/opt/splunk/var/log/splunk/splunkd-utility.log initcrclen=1048576 fishstate=key=0x33674102d8ed48d7 sptr=560 scrc=0x484f37b61ca44a94 fnamecrc=0x33674102d8ed48d7 modtime=1659639693
08-04-2022 19:01:45.989 +0000 INFO FileTracker [104 tailreader0] - Unlocked key=0x33674102d8ed48d7 locked to state=0x7f14a140f000
08-04-2022 19:01:45.989 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/opt/splunk/var/log/splunk/splunkd-utility.log"
08-04-2022 19:01:45.989 +0000 INFO FileTracker [104 tailreader0] - Retrieving record for key=0x3a51dcd384f999d2
08-04-2022 19:01:45.990 +0000 DEBUG WatchedFile [104 tailreader0] - Preserving seekptr and initcrc.
08-04-2022 19:01:46.082 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/opt/splunk/var/log/splunk"
08-04-2022 19:01:46.082 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/opt/splunk/var/log/watchdog"
08-04-2022 19:01:46.286 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/opt/splunk/var/run/splunk/search_telemetry"
08-04-2022 19:01:46.286 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/opt/splunk/var/spool/splunk"
08-04-2022 19:01:46.286 +0000 DEBUG FilesystemChangeWatcher [100 MainTailingThread] - inotify doing infrequent backup polling for healthy path="/data/logs"