GoogleCloudLoggingFormatter timestamp does not work with Google Cloud Run

[rpkamp]

Monolog version 2 and 3.

In our application we have a fingers crossed handler that passes to a stream handler that writes to php://stderr using the Google Cloud Logging Formatter. This mostly works fine, except that Google Cloud Run does not use the timestamp sent from monolog as the timestamp of the message. It seems to be taking the time it received the message instead.
Most notably when we logged several messages, sleeping for 1 second between those messages, they all more or less the same timestamp in Google Cloud Logging, they certainly weren't a second apart.

Diving into it, it turns out sending messages through php://stderr is different than sending them through the logging API. Instead of timestamp the field time must be used, and the time must be in UTC.

We found that the following works for us when writing to php://stderr on Google Cloud Run (in Monolog 2):

$record['time'] = $record['datetime']->setTimezone(new DateTimeZone('UTC'))->format('Y-m-d\TH:i:s.u\Z');

With this in place the messages were logged seconds apart, even though they were still logged all at once by the fingers crossed handler.

I do wonder whether this should be changed in Monolog, because I don't know if the current implementation has a use case that I'm unaware off that uses the format that is now in the code (something else than Cloud Run and/or writing to php://stderr).

@lcobucci since you wrote the formatter in Monolog, do you have ideas on this?

[lcobucci]

I'm running this via Google Kubernetes Engine (relying on php://stderr too) and it seems to be working fine. It's interesting that Cloud Run and GKE diverge... well, maybe it's just Google being Google idk 🤷‍♂️

I don't see a reason not to support both, though... maybe $record['time'] = $record['timestamp'] = $record['datetime']->...?

[Seldaek]

Seems kinda silly to log the time twice there, but if it's gotta be done ..

Any chance that time would also work for GKE @lcobucci ?

[lcobucci]

I'll test it and come back to you 👍

[rpkamp]

@lcobucci Please also check if it works when logging in UTC time. Cloud Run doesn't like our default timezone (CEST).

(see my first post for how we're doing it now)

[lcobucci]

Hey folks, sorry about the delay.

We've tested the format by writing straight to STDERR:

{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T21:02:35.046+00:00","context":{"timeField":"time","skew":-3,"timezone":"UTC","time":"2022-09-04T21:02:35.046+00:00","now":"2022-09-04T21:02:38.047+00:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T23:02:35.047+02:00","context":{"timeField":"time","skew":-3,"timezone":"CEST","time":"2022-09-04T23:02:35.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T23:02:35.047+02:00","context":{"timeField":"time","skew":-3,"timezone":"Europe\/Amsterdam","time":"2022-09-04T23:02:35.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T21:02:38.047+00:00","context":{"timeField":"time","skew":0,"timezone":"UTC","time":"2022-09-04T21:02:38.047+00:00","now":"2022-09-04T21:02:38.047+00:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T23:02:38.047+02:00","context":{"timeField":"time","skew":0,"timezone":"CEST","time":"2022-09-04T23:02:38.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T23:02:38.047+02:00","context":{"timeField":"time","skew":0,"timezone":"Europe\/Amsterdam","time":"2022-09-04T23:02:38.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T21:02:41.047+00:00","context":{"timeField":"time","skew":3,"timezone":"UTC","time":"2022-09-04T21:02:41.047+00:00","now":"2022-09-04T21:02:38.047+00:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T23:02:41.047+02:00","context":{"timeField":"time","skew":3,"timezone":"CEST","time":"2022-09-04T23:02:41.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","time":"2022-09-04T23:02:41.047+02:00","context":{"timeField":"time","skew":3,"timezone":"Europe\/Amsterdam","time":"2022-09-04T23:02:41.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T21:02:35.047+00:00","context":{"timeField":"timestamp","skew":-3,"timezone":"UTC","time":"2022-09-04T21:02:35.047+00:00","now":"2022-09-04T21:02:38.047+00:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T23:02:35.047+02:00","context":{"timeField":"timestamp","skew":-3,"timezone":"CEST","time":"2022-09-04T23:02:35.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T23:02:35.047+02:00","context":{"timeField":"timestamp","skew":-3,"timezone":"Europe\/Amsterdam","time":"2022-09-04T23:02:35.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T21:02:38.047+00:00","context":{"timeField":"timestamp","skew":0,"timezone":"UTC","time":"2022-09-04T21:02:38.047+00:00","now":"2022-09-04T21:02:38.047+00:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T23:02:38.047+02:00","context":{"timeField":"timestamp","skew":0,"timezone":"CEST","time":"2022-09-04T23:02:38.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T23:02:38.047+02:00","context":{"timeField":"timestamp","skew":0,"timezone":"Europe\/Amsterdam","time":"2022-09-04T23:02:38.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T21:02:41.047+00:00","context":{"timeField":"timestamp","skew":3,"timezone":"UTC","time":"2022-09-04T21:02:41.047+00:00","now":"2022-09-04T21:02:38.047+00:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T23:02:41.047+02:00","context":{"timeField":"timestamp","skew":3,"timezone":"CEST","time":"2022-09-04T23:02:41.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}
{"message":"Hello there","channel":"app","severity":"INFO","timestamp":"2022-09-04T23:02:41.047+02:00","context":{"timeField":"timestamp","skew":3,"timezone":"Europe\/Amsterdam","time":"2022-09-04T23:02:41.047+02:00","now":"2022-09-04T23:02:38.047+02:00"}}

The result is that time is indeed the field that respected both skews (both future and past) and different timezones (UTC, CEST, and Europe/Amsterdam).

Looking at https://cloud.google.com/logging/docs/agent/logging/configuration#timestamp-processing the timestamp field has other expectations.

I'll send a PR to fix it, thanks @rpkamp for reporting the issue!

[lcobucci]

Alright, fixes sent... I hope that helps, sorry for the inconvenience!

[ryokomy]

Anyone who uses Laravel with Monolog v2?
I can't see any logs on Google Cloud Logging...
I can see them with Monolog v1.
I hope someone helps me and those who are in the same situation.

[lcobucci]

Anyone who uses Laravel with Monolog v2?
I can't see any logs on Google Cloud Logging...
I can see them with Monolog v1.
I hope someone helps me and those who are in the same situation.

@ryokomy that seems like a completely different thing (this formatter is only available for monolog v2 and v3).