Description
Environment details
- OS: OSX Ventura 13.4.1
- Node.js version: v14.18.0
- npm version: 7.21.1
@google-cloud/logging-winstonversion: 5.3.0
Steps to reproduce
- Create a simple logger
const logger = Winston.createLogger({
level: 'info',
transports: [
new Winston.transports.Console({
format: Winston.format.combine(
Winston.format.timestamp(),
Winston.format.simple()
)
}),
new LoggingWinston({
format: Winston.format.combine(
Winston.format.timestamp(),
Winston.format.json()
),
serviceContext: {
service: config.serviceName,
version: config.serviceVersion
},
projectId: config.googleCloudProjectId
})
]
})- Use logger in a simple express app.
const app = express()
const logger = require('./logger')
app.get('/hello', (req, res) => {
logger.info('hello called', { stuff: 'yep' })
res.status(200).json({ message: 'hello' })
})- Notice in Cloud Logging and the console that the timestamps differ.
This has a big impact when using OpenTelemetry since the link to "View Logs" relies on the log entries having a timestamp that lies within the timespan of a span during a trace. There is often a drift of a few 100ms in Cloud Logging vs the timespans in Cloud Trace.
By investigating the code I found that info.timestamp is intended to be a Date instance in LoggingCommon#log. So to remedy I had to do this:
const logger = Winston.createLogger({
level: 'info',
format: Winston.format.timestamp(),
transports: [
new Winston.transports.Console({
format: Winston.format.simple()
}),
new LoggingWinston({
format: Winston.format.combine(
// Ensure timestamp is a Date instance
Winston.format((info) => {
info.timestamp = new Date(info.timestamp)
return info
})(),
Winston.format.json()
),
serviceContext: {
service: config.serviceName,
version: config.serviceVersion
},
projectId: config.googleCloudProjectId
})
]
})The code that expects timestamp to be a Date is within LoggingCommon:
An additional issue is that the key LoggingWinston.LOGGING_SAMPLED_KEY should be expected to be a boolean, but the LoggingCommon class expects it to be a string like "1". In OpenTelemetry this is stored in the traceFlags of the span context as a number, not a string. And typically we can convert to boolean via span.spanContext().traceFlags === OpenTelemetry.TraceFlags.SAMPLED. It's really odd to have this documented as needing to be a boolean but in the code it expects a string.
As a remedy I had to set this key to String(span.spanContext().traceFlags).
