spire
spire copied to clipboard
spiffe
Log expired agent SVID warning in local time
The logger emits log timestamps in the locally configured timezone.
When the agent starts and detects an expired SVID on disk, it logs a warning that includes the expiry date of the SVID. This date is logged in UTC.
When reading the logs and trying to figure out how expired an SVID is, it's really easy to miss this TZ mismatch if the system is not on UTC. Sample below. I think we should change the line to log in the local TZ so that the logger behavior is matched.
time="2021-11-21T20:31:57+05:30" level=warning msg="Private key recovered, but SVID is expired. Generating new keypair" expiry="2021-11-21 14:28:59 +0000 UTC"
Oh boy. Yes, it would be great to be consistent. I'm wondering though which is easier, local time v.s. UTC, since a fair number of the timestamps we log (maybe all?) are inherently UTC and we'd have to audit all the call sites. I wonder if it is more natural to change the time function on the logs to use UTC (provided they have a hook for this, which IIRC, they do).
I wonder if it is more natural to change the time function on the logs to use UTC
Heh if it was me I'd say yes ... but then again my machine would already be on UTC time 😆
I think most loggers log in the local system time by default? We should probably do the "normal" thing. If it's normal to log UTC time regardless of the system configuration, I think changing the logger is the right solution.
Ha, yeah, I lean towards UTC when I'm managing multiple systems, especially if they are crossing time zones. It makes log correlation that much easier. I'll double check that this is even possible with logrus.
I'm happy to work on this if there's a need!
Looking at https://github.com/spiffe/spire/blob/main/pkg/agent/attestor/node/node.go#L118, since the log is printing NotAfter, it ends up in UTC since NotBefore/NotAfter are set to UTC here: https://github.com/golang/go/blob/master/src/crypto/x509/x509.go#L1556
I agree with @evan2645 that the more "normal" thing is logging in the local system time
Talked about this today during contributor sync, thank you for joining @mjlshen!
We all agreed that local time is the right call.
There is also a lot of worry about having to do this conversion at every call site logging a timestamp. Ideally, we'd be able to hook our logger somehow so we can look out for timestamps and convert them to local system time whenever we see them. If we can't do that, we're probably looking at a bigger change to put something between our callsites and logrus.
@azdagron shared this link which he thinks might be suitable for a hook like this: https://github.com/sirupsen/logrus/blob/85981c045988a3ebe607e2f5b8a6499d86e0ddac/hooks.go#L8
