googleapis / googleapis/google-cloud-go
logging: provided timestamps are ignored in GKE when using RedirectAsJSON(os.Stdout)
- Dominant language
- Go
- Stars
- 4.5k
- Forks
- 1.6k
- Avg merge
- 1d 13h
- Merged PRs (30d)
- 109
Description
**Client**
Logging
**Environment**
Package version: v1.5.0
GKE: 1.22
Docker: scratch base image and the go binary is built inside golang:1.19.3-alpine3.16
**Go Environment**
Go 1.19
**Problem**
We are trying-out redirecting of logs to `stdout` and `stderr`, because on usage spikes we are losing some logs, and see logging API timeouts every 10 minutes. The the logs are also piling up in the memory because of that.
This is working fine in GKE, no more missing logs, but the logs' timestamps are incorrect. They use the time when they where written into `stdout`/`stderr` instead of the provided timestamp on the logging entry. The problem looks to be in the timestamps' serialization from proto to JSON. Here is a (stripped down) JSON of the log that ends-up in the Cloud Logging console:
```
{
"jsonPayload": {
"timestamp": "seconds:1668087286 nanos:217760439",
"message": "...message..."
},
"timestamp": "2022-11-10T13:34:51.285077504Z",
"receiveTimestamp": "2022-11-10T13:34:56.073708256Z"
}
```
This `"seconds:1668087286 nanos:217760439"` timestamp format (in `jsonPayload`) is not compatible with GKE's logs collector, which needs one of these formats (https://cloud.google.com/logging/docs/agent/logging/configuration#timestamp-processing). Otherwise the timestamp from `jsonPayload` is not used as the timestamp of the log itself:
```
{
"timestamp": {
"seconds": CURRENT_SECONDS,
"nanos": CURRENT_NANOS
}
}
```
or
```
{
"timestampSeconds": CURRENT_SECONDS,
"timestampNanos": CURRENT_NANOS
}
```
or
```
{
"time": CURRENT_TIME_RFC3339
}
```
The first format looks similar, but has to be a JSON object instead of just a string. Can you change the timestamp serialization into one of the GKE compatible formats please? Or extend the GKE logs collector's supported formats? Thank you.
Why is this small difference in timestamps a problem? Because of correlating the logs into parent-child relationship. The parent log has the earliest timestamp from the logs with the same trace (https://cloud.google.com/logging/docs/view/correlate-logs). When correlating request logs with logs happening during a request, the request log is always logged as the very last log, so it has the request's duration/latency. Thus we set its timestamp as the time of the start of the request, which is in the past. This is then ignored by GKE's logging collector, thus the request log ends-up with the newest timestamp and the parent-child relationship is reversed. In the end the Cloud Logging console shows the logs, happening during a request, as the parent logs, and they have one child log, the request log.
**Expected behavior**
GKE should use the timestamps set on the logging entry, also when using `RedirectAsJSON`.
**Actual behavior**
GKE ignores logging entry's timestamps and always sets its timestamps based on when the log entry was written to `stdout`/`stderr` when using `RedirectAsJSON`.
Contributor guide
Assessment
This issue has not been assessed yet.