Logging in GKE is not using the ContainerEngineHandler

[arthurdarcet]

The KUBERNETES_SERVICE environment variable is not set in a pod running on GKE, so ContainerEngineHandler never actually gets selected as the default handler here

This means all the logs go directly to the "Global" section of the Logging tab in the GCloud console, instead of being parsed by the fluentd pod running on the host, and being routed to the right "GKE > cluster > container name" section. And of course no pod/host/… metadata is added to the log.

I think the checked variable should read KUBERNETES_SERVICE_HOST but i did not open a pull request because ContainerEngineHandler does not work either: When I manually add a ContainerEngineHandler handler to the logging configuration, the logging interface at console.cloud.google.com does not actually parse the JSON that is written to stderr, so the severity for instance is not set correctly (the JSON produced by ContainerEngineHandler is directly displayed as the textPayload).

And finally (not really related to this but I'm not sure where this should go): the fluentd-gcp pod that is running by default on GKE clusters is configured with this fluentd configuration:

<filter …>
  …
  format /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<log>.*)/
</filter>

which is a very weird regex:

• it parses only one char for the severity
• the time is parsed as YYYY followed by a space, followed by anything but a space: this does not correspond to any datetime format i can think of
• the source attribute is followed by a ], but no matching [ is in the regex

The severity issue makes it impossible to actually use this filter since stackdriver does not accept logs with a severity outside the usual INFO|WARN|ERROR|…

--

All-in-all, this makes it really hard to log data from a python pod: logging with the CloudLogging handler goes to "Global" by default (and is missing many kubernetes-related meta), logging to stderr a JSON-formatted object is not parsed by the console.cloud UI, and the regex in the fluentd setup cannot pick up any valid input

OS: Kubernetes 1.6.6, running on GKE with cos
Python version: 3.6 or pypy 5.8
google-cloud-python version: 1.1.0

[duggelz]

Thanks for the bug report!

The regex matches Google's internal log format, which is indeed next to useless for customers. If you're curious, matching log lines look something like this:

I0719 15:48:54.944977 140280647644928 scriptname.py:144] Some message here

The format dates back to 1999, so it doesn't necessarily match anything else in the universe :)

[lukesneeringer]

@duggelz Is this a bug we can fix? Something that is stuck as-is? I would appreciate guidance on what to do with this ticket. :-)

[duggelz]

This is something we can fix.

[duggelz]

CC @igorpeshansky Can you comment on the environment variable and fluentd sidecar configuration? Is the plan to migrate to direct RPC calls for logging instead of fluentd, or is that just for App Engine?

[igorpeshansky]

As I understand it, GKE will keep using the fluentd containers to log the pods' stdout/stderr. @crassirostris should be able to help you debug why the output isn't parsed correctly.

[arthurdarcet]

the JSON parsing part was a bug in the k8s config in 1.6, this has been fixed in 1.7, cf GoogleCloudPlatform/fluent-plugin-google-cloud#143 (i updated the issue to reflect this)

I can create a pull request switch the environment variable to KUBERNETES_SERVICE_HOST ; but this will detect if we are running in Kubernetes cluster, not if we are running in a GKE cluster, so fixing this env variable will probably break the installation for people running in a k8s cluster on EC2/… without the fluentd DeamonSet (it will switch them away from the RPC client to this basic JSON over stderr, which won't log anything in stackdriver without the DeamonSet).

I have no idea how a GKE cluster could be detected though

[crassirostris]

@arthurdarcet Let's sort it out first. What setup do you have (simple pod definition would help), what exactly do you expect and what exactly do you see?

I see a lot of confusion here. Sidecar? Default fluentd configuration? Python library? Optional glog format parsing? Those are orthogonal things and it's hard to understand what's the problem is

[crassirostris]

@duggelz

The regex matches Google's internal log format, which is indeed next to useless for customers

It's not internal and it's used in opensource projects, including Kubernetes

[arthurdarcet]

@crassirostris the issue here is only with this Python library: it decides whether or not the ContainerEngineHandler should be used based on the KUBERNETES_SERVICE environment variable. This variable does not exist in a k8s cluster, instead KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT are defined.

I did not mention any sidecar, and mention the fluentd DeamonSet only because this ContainerEngineHandler works by logging JSON to stderr and expecting a fluentd DeamonSet to pick it up.

[crassirostris]

@arthurdarcet OK, thanks, now I understand the problem. I checked the code and KUBERNETES_SERVICE variable (without a suffix) is not present in any Kuberentes release dating back to to moment when this logic was added to this python library

@duggelz @waprin Indeed seems like a bug, should be KUBERNETES_SERVICE_HOST and/or KUBERNETES_SERVICE_PORT

@duggelz

Is the plan to migrate to direct RPC calls for logging instead of fluentd, or is that just for App Engine?

What happens inside containers in of no concern for Kubernetes, you can as well do that. However, GKE will always support sending stdout/stderr output to Stackdriver, because it's impossible to make everyone use the same approach and in Cloud Native world writing logs to stdio is more or less standard