Getting Data In

Forwarder tells me there's an "ERROR JsonLineBreaker ... had parsing error:Unexpected character: '5'" - but the error originates in the forwarder's own log?

BongoTheWhippet
Path Finder

Hello good people of the Splunk Community. This one's got me foxed.

I noticed this morning that the splunkd logs on my Raspberry Pi-hosted Universal Forwarder are rotating really quickly (check out the timestamps below - it is literally creating a log entry as fast as the CPU will spin) and I've got no idea why.

Oddly, the error appears to originate in Splunk's own log at:

/opt/splunkforwarder/var/log/splunk/splunkd.log

At first I thought the error must have been introduced from a parsed log, but then I realised two odd things - firstly, the splunkd errors I'm seeing reference the log itself as the source of the problem and secondly it appears to take issue with the number '5' (in it's own log)?

Removing the logs and restarting the forwarder doesn't help, rebooting the RPi doesn't help. As soon as the splunkd service starts, it immediately spams the splunkd.log with this. Anyone any ideas what I'm missing?

Here's what it looks like:

05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.117 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.118 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.118 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"
05-04-2020 15:48:24.118 +0100 ERROR JsonLineBreaker - JSON StreamId:14919777892573414995 had parsing error:Unexpected character: '5' - data_source="/opt/splunkforwarder/var/log/splunk/splunkd.log", data_host="rpi3", data_sourcetype="json"

 ... and lots more ...
... and more ...
... more ..
0 Karma

BongoTheWhippet
Path Finder

Okay so proposed answer here is re-install the UF.

There's one other user I've seen with this problem @anayar : https://answers.splunk.com/answers/741298/error-jsonlinebreaker.html and no solution available from user community or Splunk. If people aren't checking their UF logs, maybe they wouldn't even spot this. But my splunkd.log files are being logrotated out every 30 seconds so clearly this isn't a sustainable solution to keep it running as it is.

The mystery is how the UF got into this state as there's very little configuration or customisation on mine at all.

Cheers

0 Karma

PavelP
Motivator

Hello @BongoTheWhippet ,

please post your results after the reinstall so everybody can benefit from your experience.

0 Karma

BongoTheWhippet
Path Finder

Hi @PavelP,

It's done and the problems gone away now.

All the best

** CORRECTION **

It's back, and the bug is repeatable. I've posted details and a bug report here https://answers.splunk.com/answers/822443/raspberry-pi-universal-forwarder-bug-report-for-sp.html

0 Karma

PavelP
Motivator

Hello @BongoTheWhippet

please check this answer by @somesoni2 : https://answers.splunk.com/answers/741298/error-jsonlinebreaker.html

This particular error occured because the splunkd sourcetype was changed (INDEXED_EXTRACTIONS = JSON). Do the same check on your UF:

/opt/splunkforwarder/bin/splunk btool props list splunkd --debug | grep -v system/default

If this answer solve your issue, please up vote somesoni2 answer: https://answers.splunk.com/answers/741298/error-jsonlinebreaker.html#comment-741309

0 Karma

BongoTheWhippet
Path Finder

Hi PavelP,

Thanks - I tried that too already. Nothing unexpected in there, right?

/opt/splunkforwarder/etc/apps/search/default/props.conf [splunkd]
/opt/splunkforwarder/etc/apps/search/default/props.conf EXTRACT-fields = (?i)^(?:[^ ]* ){2}(?:[+\-]\d+ )?(?P<log_level>[^ ]*)\s+(?P<component>[^ ]+) - (?P<event_message>.+)
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        TRUNCATE = 0
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        TRUNCATE = 0
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        TRUNCATE = 0
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
/opt/splunkforwarder/etc/system/local/props.conf        TIME_PREFIX = "Time":
/opt/splunkforwarder/etc/system/local/props.conf        TRUNCATE = 0
/opt/splunkforwarder/etc/system/local/props.conf        INDEXED_EXTRACTIONS = json
/opt/splunkforwarder/etc/system/local/props.conf        KV_MODE = none
/opt/splunkforwarder/etc/system/local/props.conf        NO_BINARY_CHECK = true
/opt/splunkforwarder/etc/system/local/props.conf        SEDCMD-strip_prefix = s/^[^{]+//g
0 Karma

BongoTheWhippet
Path Finder

I've just noticed another error that gets generated, but only once:

05-04-2020 21:18:23.101 +0100 ERROR JsonLineBreaker - JSON StreamId:17548257037373434191 had parsing error:Unexpected character while looking for value: 'h' - data_source="/var/log/eve.json", data_host="dd-wrt", data_sourcetype="json"

Is the letter 'h' really so unexpected in a lint-validated json file?!

0 Karma

PavelP
Motivator

Hello @BongoTheWhippet

all lines with "local" indicate the default configuration is being overwritten, it is not common.

INDEXED_EXTRACTIONS = json is definetely wrong here, because splunkd logs are not json files. And, as you can see, there are repeating patterns, for example SEDCMD-strip_prefix = s/^[^{]+//g is repeating nine times.

0 Karma

BongoTheWhippet
Path Finder

Hi @PavelP

all lines with "local" indicate the default configuration is being overwritten, it is not common.

On a default configuration, there is no props.conf at all, so there's nothing unusual there I think.

INDEXED_EXTRACTIONS = json is definetely wrong here,

The stanza is not incorrect as it still parses the user-supplied JSON files perfectly (when it's not writing to the splunkd.log every millisecond or so!)

because splunkd logs are not json files.

Correct, they are not. But I did not tell my splunk binary to do that, none of my config files tell it to do that and I suspect the same applies to @anayar : https://answers.splunk.com/answers/741298/error-jsonlinebreaker.html. Besides, the strangest thing isn't that Splunk thinks the splunkd.log is a JSON file, even stranger is that Splunk reports that it's own application log is the source of an error, in the application log!

This is a software bug in Splunk I think, but I doubt the Splunk devs will be interested until more users experience this weird behaviour.

I'm gonna leave this running for another 24 hours, just in case someone here wants to try to triage it, but then I'll reinstall - any program pushing out multiple log lines per millisecond is not good for the CPU or the MicroSD card's flash wear.

All the best

0 Karma
Get Updates on the Splunk Community!

Index This | I am a number, but when you add ‘G’ to me, I go away. What number am I?

March 2024 Edition Hayyy Splunk Education Enthusiasts and the Eternally Curious!  We’re back with another ...

What’s New in Splunk App for PCI Compliance 5.3.1?

The Splunk App for PCI Compliance allows customers to extend the power of their existing Splunk solution with ...

Extending Observability Content to Splunk Cloud

Register to join us !   In this Extending Observability Content to Splunk Cloud Tech Talk, you'll see how to ...