1

I'm using Google Kubernetes Engine (GKE) in conjunction with Stackdriver Logging.

The Stackdriver's documentation says there are some special fields used by Logging agent to set fields in the LogEntry object.

As regard to severity field, it works fine. However, time field doesn't work as intended.

The following JSON is a MySQL error log, which was modified and redirected to stdout:

(beautified and annotated for clarity)

{
  "prio": 0,
  "err_code": 11323,
  "component": "mysqlx",
  "source_line": 154,
  "source_file": "socket_acceptors_task.cc",
  "function": "show_startup_log",
  "msg": "X Plugin ready for connections. Socket: '/var/run/mysqld/mysqlx.sock' bind-address: '::' port: 33060",
  "err_symbol": "ER_XPLUGIN_LISTENER_STATUS_MSG",
  "SQL_state": "HY000",
  "subsystem": "Server",
  "label": "System",

  // Added for Stackdriver Logging
  "severity": "INFO",
  "time": "1548054692.636",

  // This is the same time written in human-readable format.
  "time.readable": "2019-01-21T07:11:32.636761Z"
}

And the following is the corresponding log recorded by Stackdriver Logging:

(beautified and annotated for clarity)

{
  "insertId": "1jibhqgfw4kum0",
  "jsonPayload": {
    // Both `severity` and `time` fields were removed.

    "msg": "X Plugin ready for connections. Socket: '/var/run/mysqld/mysqlx.sock' bind-address: '::' port: 33060",
    "label": "System",
    "prio": 0,
    "err_code": 11323,
    "time.readable": "2019-01-21T07:11:32.636761Z",
    "subsystem": "Server",
    "source_file": "socket_acceptors_task.cc",
    "err_symbol": "ER_XPLUGIN_LISTENER_STATUS_MSG",
    "function": "show_startup_log",
    "SQL_state": "HY000",
    "source_line": 154,
    "component": "mysqlx"
  },
  "resource": {
    "type": "container",
    "labels": {
      "namespace_id": "myproject",
      "instance_id": "506697609301173766",
      "zone": "asia-east1-b",
      "pod_id": "demo-demoid1234567890-sns7g",
      "project_id": "harai-development",
      "cluster_name": "myproject",
      "container_name": "mysql-errorlog-output"
    }
  },

  // `timestamp` doesn't reflect the value in the original log,
  // which is "2019-01-21T07:11:32.636761Z".
  "timestamp": "2019-01-21T07:11:44Z",

  // `severity` reflects the value in the original log
  "severity": "INFO",

  "labels": {
    "compute.googleapis.com/resource_name": "fluentd-gcp-v3.1.0-pwc9k",
    "container.googleapis.com/pod_name": "demo-demoid1234567890-sns7g",
    "container.googleapis.com/stream": "stdout",
    "container.googleapis.com/namespace_name": "myproject"
  },
  "logName": "projects/harai-development/logs/mysql-errorlog-output",
  "receiveTimestamp": "2019-01-21T07:11:49.560205566Z"
}

Although the both time and severity fields were removed, timestamp field in LogEntry doesn't reflect the time specified in the original time field.

How can I set timestamp to the time the log is created?

Akihiro HARAI
  • 175
  • 7
  • To verify that you are using structured logging (single line) as per [1](https://cloud.google.com/kubernetes-engine/docs/how-to/logging#best_practices) [2](https://cloud.google.com/logging/docs/structured-logging), you may change the severity to something other than info, like “DEBUG”, would it reflect in the logs ? – Fady Jan 24 '19 at 00:46
  • @Fady With respect to `severity`, it definitely reflects the value in the logs. – Akihiro HARAI Jan 24 '19 at 03:03
  • So I assume you have tried a different severity like “debug” and it did show, correct ? – Fady Jan 24 '19 at 03:36
  • @Fady Yes, I have output several log messages with different severities, and confirmed they were properly recognized by the agent. – Akihiro HARAI Jan 24 '19 at 05:26
  • 1
    At this point I suggest opening an [issuetracker](https://cloud.google.com/support/docs/issue-trackers) report as to be investigated by the Stackdriver team. Include simple reproduction steps (e.g how did you configure structured logging) as to help the team with their investigation. – Fady Jan 24 '19 at 05:42

1 Answers1

1

In the Fluentd configuration for GKE cluster, the time format is defined like this:

time_format %Y-%m-%dT%H:%M:%S.%NZ

Therefore, it will work as expected by setting the time field as "2019-01-21T07:11:32.636761000Z".

Ref: https://issuetracker.google.com/issues/123303610

Akihiro HARAI
  • 175
  • 7