Respecting winston formatting

[krzysiekfonal]

This logger ignores format settings.

const logger = winston.createLogger({
    level: LOG_LEVEL,
    format: winston.format.combine(
        winston.format.timestamp({format: 'YYYY-MM-DD HH:mm:ss,SSS'}),
        winston.format.printf(info => `${info.timestamp} |${info.level.toUpperCase()}| my-service -> ${info.message}`)),
    transports: [
        new LoggingWinston(), 
        new winston.transports.Console()
    ]
});

In the above example, console logs presents proper format defined in 'format' field, but google-cloud/logging-winston doesn't.

[synsteve]

Hi, I'll add a +1 vote for a fix for this, it would really help my projects out.

[ymotongpoo]

Note: In order for Google Cloud Logging API to understand the log level correctly, we need to have something that changes log structure format inside this library, like this:

const GoogleCloudLoggingFormatter = winston.format((info, opts={}) => {
    info['severity'] = info['level'].toUpperCase();
    return info;
});

const logger = winston.createLogger({
    level: 'info',
    format: winston.format.combine(
        winston.format.timestamp(),
        GoogleCloudLoggingFormatter(), // This must be before winston.fomrat.json()
        winston.format.json(),
    ),
    transports: [
        new winston.transports.Console({ level: 'info' })
    ]
});

[keenan-devrel]

Still under investigation. Yoshi may take another look.

[ymotongpoo]

I took a glance of this code base and it seems this library is not passing format options to transports.
https://github.com/googleapis/nodejs-logging-winston/blob/master/src/index.ts#L175-L179

On the other hand, winston.transports.Console is passing whole options that includes format option to the super class's constructor.
https://github.com/winstonjs/winston/blob/master/lib/winston/transports/console.js#L27

The tricky part is that this libraries Options interface is not compatible with wiston's LoggerOption interface. The former is inheriting Cloud Logging's LoggingOptions.

• this lib's Options interface: https://github.com/googleapis/nodejs-logging-winston/blob/master/src/index.ts#L41-L88
• winston's LoggerOption interface: https://github.com/winstonjs/winston/blob/master/index.d.ts#L77-L87

I guess the todos are:

• LoggingCommon (in src/common.ts) should accept format option
• that format option should be used to modify data variable in LoggingCommon#log

[ymotongpoo]

I made another investigation, and this requires a kind of interface change around how we treat messages passed to Cloud Logging library.

In LoggingCommon class, we use @google-cloud/logging/build/src/entry.LoggingEntry that is set to handle JSON structured logs; i.e. all logs are sent as JsonPayload in Cloud Logging.

[ymotongpoo]

As of now, the implementation expects the logs to be structured logs and not considering them to be in other format. We decided to add the logic to send them as textPayload when the users specifies custom formats.

[ymotongpoo]

I did further investigations on setting logs in textPayload field of Google Cloud's LogEntry data schema.

TL;DR: we need fundamental change if we want to route custom format logs to textPayload instead of jsonPayload.

Background
This library is totally depending upon @google-cloud/logging's Entry class to express and fulfill log information. The log writing process is delegated to @google-cloud/logging (Cloud Logging client), which is totally isolated from winston and this plugin. In the Cloud Logging client, if the passed objects to write methods in either of log.ts or log-sync.ts are instances of Entry class, the methods calls toJSON or toStructuredJSON methods of the objects, and embed it to jsonPayload.

• https://github.com/googleapis/nodejs-logging/blob/97bc9c992d25198c4380fb6088ebe5a547101c96/src/log.ts#L953
• https://github.com/googleapis/nodejs-logging/blob/97bc9c992d25198c4380fb6088ebe5a547101c96/src/log-sync.ts#L415

If we would like to embed the custom format log to textPayload field, we need to add the option to switch between Entry class and primitive string.

Compromised work around is to fill custom format log into the message field of jsonPayload, which still requires fundamental change and leads to double the size of messages.

[simonz130]

Yeah, I think that putting formatted log entry into message field of jsonPayload would be a decent compromise.
We want to use jsonPayload by default when we send logs to Cloud Logging. This allows us to provide more value to users in Logs Explorer. So the compromise you suggest makes sense to me.

[losalex]

This problem was attempted to be fixed before in #548 and based on comments seems winston library does not have a unified way to return formatted message. The code sample const { level, message, ...meta } = info; described here does not always returns message consistently and varies if format object was provide to winston.createLogger() constructor or not. It appears that info parameter could also have an info[Symbol.for('message')] in addition to info.message field and those values are not the same:

1. In case when no formatting is provided in winston.createLogger() constructor, the correct message indeed parsed correctly by const { level, message, ...meta } = info. However, info[MESSAGE] also contains a JSON string which is combination of level and message, for example {"level":"error","message":"This is message"}. Worth mentioning that for error() calls the info[MESSAGE] contains partial data without error message at all, e.g. {"level":"error"}
2. When formatting is provided in winston.createLogger() constructor, for logging calls the correct message will be in info[MESSAGE] field, while info.message contains non-formatted version of the message.
3. For some cases when only formatting functions like winston.format.padLevels() are used, the info[MESSAGE] can be undefined.

Given a fact that we don't have a way to see if formatting was provided for winston.createLogger() constructor or not, we cannot provide a deterministic approach to fetch correct message (e.g. we cannot count on info[MESSAGE] nor on info.message fields to determine where is a "right" message is).

Opened issue #125 on logfrom.

[losalex]

Closing this issue since the fix for #125 will resolve this issue without any change in this library

[lgtm2]

@losalex I just came across this issue. Perhaps this should be in your documentation? It may have led me to try using Bunyan. Also, is there any workaround you can think of here? If Winston never addresses your bug, this will be an issue for users for a while.

[losalex]

@lgtm2 , thanks for reaching out!
Unfortunately I do not have a good workaround except of perhaps using custom formatting objects in winston.createLogger() constructor which I must admit never tested before. You can see this sample mentioned before in this issue on how custom formatter can be created and used to manipulate/transform the input accordingly.
I will look into adding a comment to README about it.