JSON parsing from a GKE container

[arthurdarcet]

When logging from a Kubernetes cluster on GKE, the logs received by fluentd are those sent by docker, and follow the format:

{
  "log":"2014/09/25 21:15:03 Got request with path wombat\\n",
  "stream":"stderr", 
  "time":"2014-09-25T21:15:03.499185026Z"
}

The JSON parsing done by this plugin would be a really simple way to output formatted logs directly from an application.
This PR makes the log sent by docker acceptable for optional JSON-decoding, by putting aside the stream key just like the time key and restoring it after deciding whether or not it should be JSON-decoded

[googlebot]

Thanks for your pull request. It looks like this may be your first contribution to a Google open source project. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please visit https://cla.developers.google.com/ to sign.

Once you've signed, please reply here (e.g. I signed it!) and we'll verify. Thanks.

---

• If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
• If your company signed a CLA, they designated a Point of Contact who decides which employees are authorized to participate. You may need to contact the Point of Contact for your company and ask to be added to the group of authorized contributors. If you don't know who your Point of Contact is, direct the project maintainer to go/cla#troubleshoot.
• In order to pass this check, please resolve this problem and have the pull request author add another comment and the bot will run again.

[googlebot]

CLAs look good, thanks!

[igorpeshansky]

@crassirostris Doesn't JSON parsing work with GKE today?
@qingling128 Does this mean our tests aren't checking for this case? I'm thinking of test_structured_payload_json_container_log...

[crassirostris]

@igorpeshansky There are two layers of JSON currently. First is the json-file wrapping of docker. That's what performed in the input plugin in K8s, then the record goes to the plugin and if the message from container was json, it gets unwrapped second time

@arthurdarcet Just set input format to json, plugin handles the rest already. See the configuration, used in GKE by default.

[arthurdarcet]

@crassirostris no, the GKE default configuration is doing the JSON decode for the docker layer of log. What we have here is an app logging JSON, so the logs look like

{"stream": "stderr", "time": "…", "log": "{\"some\": \"key\", \"httpRequest\": {}, \"message\": \"log msg\"}"}

We can of course add another filter to the fluentd config (and this is actually what we are currently doing in production), but 1. changing the config of the default fluentd DeamonSet is not obvious (you need to update the default DeamonSet to add a nodeSelector: {"invalid": "filter"} that will match nothing, so that this GKE-managed DeamonSet gets scaled down to 0, then add your own DS with the updated config) ; and 2. this project actually has code that should be doing the JSON-parsing, but is not doing it just because it is afraid of overwriting the "stream" key of the input log.

[arthurdarcet]

@igorpeshansky test_structured_payload_json_container_log should indeed be testing this if I'm reading it correctly, but i'm not really fluent in ruby so i'm not sure what is happening here.

[crassirostris]

@arthurdarcet Then it should work already, try installing the mentioned configuration in your cluster (instructions) and logging json to stdout/stderr, it should show up as jsonPayload in the UI

[arthurdarcet]

our cluster is a regular, up to date, GKE cluster. It is already using this config

[qingling128]

Mik is right. It should work for GKE already. stream is handled for GKE only, and this seems to be where it is implemented:

    # Extract entry resource and common labels that should be applied to
    # individual entries from the group resource.
    def extract_entry_labels(group_resource, record)
...
      if group_resource.type == CONTAINER_CONSTANTS[:resource_type]
        # Move the stdout/stderr annotation from the record into a label
        common_labels.merge!(
          fields_to_labels(
            record, 'stream' => "#{CONTAINER_CONSTANTS[:service]}/stream"))

[crassirostris]

@arthurdarcet

our cluster is a regular, up to date, GKE cluster. It is already using this config

OK, thanks for clarifying! Could you please describe the replication steps? A line to write by your pod, what happens, what you expect to happen

[arthurdarcet]

@crassirostris Sorry for the slow response.

I'm running this pod

apiVersion: v1
kind: Pod
metadata:
  name: arthur
spec:
  restartPolicy: Never
  containers:
    - name: arthur
      image: busybox:latest
      args:
        - echo
        - '{"message": "nested message"}'

on a Kubernetes cluster with the default fluent-gcp DeamonSet (with gcr.io/google-containers/fluentd-gcp:2.0.8, which contains fluent-plugin-google-cloud:0.6.4)

This logs as a textPayload in the Logging interface on console.cloud.google.com

{
 insertId:  "1ubcy54g7etgq3o"   
 labels: {…}   
 logName:  "projects/…/logs/…"   
 receiveTimestamp:  "2017-08-07T08:34:54.196482164Z"   
 resource: {…}   
 severity:  "INFO"   
 textPayload:  "{"message": "nested message"}
"   
 timestamp:  "2017-08-07T08:34:40Z"   
}

I would expect the payload to be JSON decoded, and in the jsonPayload field (and then, in the web UI, only the message field would be displayed, not the raw JSON)

[crassirostris]

@arthurdarcet Could you please specify what OS you're using and take a look at the JSON structure in any file under the following path on any node: /var/log/pods/*/*.log?

[crassirostris]

I'm interested in the set of fields in the said file. There's a check in the current stackdriver fluentd plugin that won't allow JSON parsing to happen unless the message in the log or message field and there are no other fields in the record (stream and timestamp are eraser earlier).

[arthurdarcet]

this is a default GKE cluster, so the OS is Container OS (cos-stable-59-9460-60-0)

The corresponding log file for my pod contains:

# cat arthur_default_arthur-4d97801386b78233ee3e9337f44d2421cd85223f346f81727e7a5c6d4d995524.log 
{"log":"{\"message\": \"nested message\"}\n","stream":"stdout","time":"2017-08-07T08:47:03.987011598Z"}

[crassirostris]

@arthurdarcet What do you mean by the default GKE cluster and the default fluentd-gcp DaemonSet? Kubernetes 1.7.3, where fluentd image version was updated to 2.0.8 hasn't been released in GKE yet :)

Just checked and when you perform said command on the default GKE cluster (Kubernetes 1.7.2 and fluentd 2.0.7) with Stackdriver Logging enabled, message is ingested as json:

{
 insertId:  "1dy8dbrg84m8eq8"   
 jsonPayload: {
  message:  "nested message"    
 }
 labels: {…}   
 logName:  "projects/.../logs/arthur"   
 receiveTimestamp:  "2017-08-07T09:18:24.586790232Z"   
 resource: {…}   
 severity:  "INFO"   
 timestamp:  "2017-08-07T09:18:11Z"   
}

Moreover, it also works with 2.0.8

[arthurdarcet]

ok, thank you for looking into this. To be perfectly exact:

• Our cluster is running Kuberenetes 1.6.6 (both master and nodes)
• The default DeamonSet is fluent-gcp:2.0.5 with fluent-plugin-google-cloud 0.6.3

with this, my pod logs as a textPayload. I have changed the DeamonSet to bump it to 2.0.8, with the results.

Are there other components here that could change this?

[crassirostris]

@arthurdarcet There was a problem in the past, caused by the same peculiarity mentioned in #143 (comment), when adding a field to the fluentd record in the config resulted in broken JSON parsing. More details in kubernetes/kubernetes#48139. But I think it was fixed in 1.6.6

Note, that you cannot simply change the fluentd DaemonSet in GKE cluster, it will be reverted back in a minute, it's described more in the K8s docs

If you have your custom configuration, maybe you have some record transforms there?

[arthurdarcet]

perfect, thank you, this was what I was missing. The tag filter was not yet added in 1.6.6 so that's what was breaking the JSON parsing.

For the DeamonSet, I managed to kill the default one by adding a nodeSelector to its spec, and duplicated it to add your commit manually until we upgrade the cluster.

Thanks again!