Splunk-connect-for-kubernetes: Exception stack trace logs getting split into multiple lines (events) when seen on splunk

[pc-rshetty]

What happened:
We have been migrating application from EC2 based deployments to kubernetes based deployments.
We are seeing the logs get split when we view on splunk. Example a java exception stack trace is multiple events on splunk. This never used to happen previously when we had it hosted on ec2(not containers)
What you expected to happen:
Entire exception stack trace should be part of single log on splunk
How to reproduce it (as minimally and precisely as possible):

Anything else we need to know?:
This is on EKS with Docker.
Environment:

• Kubernetes version (use kubectl version):
  we are on k8s 1.14
• Ruby version (use ruby --version):
• OS (e.g: cat /etc/os-release):
  Amazon Linux 2
• Splunk version:
• Others:

[matthewmodestino]

Hi! The Concat filter plugin is what will handle the linebreakers to make your stacktraces pretty in Splunk.

Please review this example:

https://github.com/splunk/splunk-connect-for-kubernetes/issues/255

Please be careful with the tag matching/regex and please do not try and apply a linebreaker to all pods. Apply the rules thoughtfully as they can add processing impact to how much data you can move from a single collector.

Also I have a blog post here showing how I make sure I review my apps/pods and ensure the data is clean by setting linebreakers in fluentd, and sourcetype parsing on the splunk side:

https://mattymo.io/splunking-ghost/

[taskar82]

I dont think it is a multiline problem originally, rather a buffer or some thing that need adjustments... We have the same problem with our java stacktraces (Helm 1.4.3), one example, logged as a single line json in the container: It is 14535 chars in total logged as one single line (local tail confirms), it looks like Fluentd, or some kind of parsing is splitting the line, when its indexed it ends up as TWO events. First event 8192 characters and the next 6343.

[jonaslar]

We see the same with one long line being spilit into two events in Splunk. Splunk 7 and Splunk Connect for Kubernetes 1.4.3.

See added files.

igeflaxagentv1_longevent.log
splunk_igeflaxagentv2_events.log

[matthewmodestino]

have you tried this:

https://docs.fluentd.org/parser/json#stream_buffer_size

it mentions oj as a faster json parser too! thats interesting...

[jonaslar]

We have set CRI-O logs, not json, so not sure where to set the parameter:

Configurations for container logs

containers:
¦ # Path to root directory of container logs
¦ path: /var/log
¦ # Final volume destination of container log symlinks
¦ pathDest: /var/lib/docker/containers
¦ # Log format type, "json" or "cri"
¦ logFormatType: cri
¦ # Specify the log format for "cri" logFormatType
¦ # It can be "%Y-%m-%dT%H:%M:%S.%N%:z" for openshift and "%Y-%m-%dT%H:%M:%S.%NZ" for IBM IKS
¦ logFormat:
¦ # Specify the interval of refreshing the list of watch file.
¦ refreshInterval:

[matthewmodestino]

Ah, right, CRI-O uses the regex parse..can you please get the original lines from the crio log? (/var/log/pods)

Crio has "partial" events flag as well...similar to docker 16k limit.

see concat docs talking about handling partial flag...just want to confirm in the raw container log before searching too hard...

https://github.com/fluent-plugins-nursery/fluent-plugin-concat#usage

[jonaslar]

The file igeflaxagentv1_longevent.log contains the complete event fetched with "oc logs > igeflaxagentv1_longevent.log"

[matthewmodestino]

oc may add some magic, as it is a bin reading and parsing cri-o log for humans. please grab raw log from cri-o log. Afaik, oc doesnt show cri-o partial flag.

Beyond cri-o, i dont see other limits in fluentd that would snip it...I don't believe fluentd-hec will slice up payloads.

[matthewmodestino]

https://bugzilla.redhat.com/show_bug.cgi?id=1552304

Looks like concat was correct after all...red hat backported concat to their agg logging. Issue notes the 8k default..

Concat supports partial, will likely need to update the cri-o regex parser to properly extract partial flag then use concat to stitch. This could technically be done on the Splunk side with props/transforms voodoo, specifically sourcetype clone and resubmit to agg queue, or Data Stream Processor if avail.

[jonaslar]

I did not have access to the host, but ran "oc debug host/\

This gave me access to the logs, and here I do see two events in the logfile:

igeflaxagentv1_longevent_ocdebug.log

[matthewmodestino]

bingo! note the "P" for "Partial"

I believe someone had an issue here where they updated the regex to capture the partial flag then used the concat example to stitch them.

[jonaslar]

Yes, I see the P and the F. So then Fluentd does not stitch them togheter before sending to Splunk?

[matthewmodestino]

Right. I'm trying to find where I saw this, I believe it was a previous issue here.... but it boils down to this, if I am remembering precisely:

https://github.com/splunk/splunk-connect-for-kubernetes/blob/fbcd160064f655f10372b22bfedf8ac3ae83464f/helm-chart/splunk-connect-for-kubernetes/charts/splunk-kubernetes-logging/templates/configMap.yaml#L89-L100

 {{- if eq .Values.containers.logFormatType "cri" }}
        @type regexp
        expression /^(?<time>.+) (?<stream>stdout|stderr) [^ ]* (?<log>.*)$/
        time_format  {{ .Values.containers.logFormat | default "%Y-%m-%dT%H:%M:%S.%N%:z" }}
      {{- else if eq .Values.containers.logFormatType "json" }}
        @type json
        time_format %Y-%m-%dT%H:%M:%S.%NZ
      {{- end }}
        time_key time
        time_type string
        localtime false
      </parse>

I recall a customer updating the regex to extract the flag, then implemented something like this, by updating our charts:

<source>
  @type tail
  path /var/log/containers/*.log
  <parse>
    @type regexp
    expression /^(?<timestamp>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z) (?<output>\w+) (?<partial_flag>[FP]) (?<message>.+)$/
  </parse>
  tag k8s
  @label @CONCAT
</source>

<label @CONCAT>
  <filter k8s>
    @type concat
    key message
    partial_key partial_flag
    partial_value P
  </filter>
  <match k8s>
    @type relabel
    @label @OUTPUT
  </match>
</label>

<label @OUTPUT>
  <match>
    @type stdout
  </match>
</label>

However, I have seen chat in the usergroups slack channel about performance when time is extracted at various places....one customer was saying they got big throughput gains based on what was doing the timestamp parsing in fluentd.

[matthewmodestino]

@rockb1017 have you seen that thread where the user was talking about the differences in performance when doing timestamp parsing?

[taskar82]

thanks @matthewmodestino. I think we have found our issue now. Also picked up the chat in Slack regarding the timestamp parsing:

time_format was slightly different than SCK though, we were using time_format %Y-%m-%dT%H:%M:%S.%NZ
so we switched to keeping time and removing time_format
added a filter using the filter_with_time method with essentially

time = Fluent::EventTime.from_time(Time.iso8601(record['time']))
record.delete('time')

it reduced CPU utilization quite a bit and improved our throughput

[matthewmodestino]

Awesome let us know which configs you end up rocking.

timstamp may or may not apply to you

Matt

[taskar82]

We needed to add a separator aswell, default is "newline". So to stich them togheter nicely we choose this config:
(have not done anything with time_format - so far)

<filter tail.containers.var.log.containers.igeflax*.log>
        @type concat
        key log
        partial_key logtag
        partial_value P
        separator ""
</filter>

and for the regex expression:

 <parse>
        @type regexp
        expressionexpression /^(?<time>.+) (?<stream>stdout|stderr) (?<logtag>[FP]) (?<log>.*)$/
        time_format  %Y-%m-%dT%H:%M:%S.%N%:z
        time_key time
        time_type string
        localtime false
        refresh_interval 60
 </parse>