fix: respect Winston Formatters

[liboz]

Thank you for opening a Pull Request! Before submitting your PR, there are a few things you can do to make sure it goes smoothly:

• Make sure to open an issue as a bug/issue before writing your code! That way we can discuss the change, evaluate designs, and agree on the general idea
• Ensure the tests and linter pass
• Code coverage does not decrease (if any source code was changed)
• Appropriate docs were updated (if necessary)

Fixes #540, maybe (#536) 🦕

The formatted version of the message is stored in info[MESSAGE] not info.message. This PR simply changes it to look at the correct location.

[codecov]

Codecov Report

Merging #548 (339ef2a) into master (9c73f88) will increase coverage by 0.10%.
The diff coverage is 93.33%.

@@            Coverage Diff             @@
##           master     #548      +/-   ##
==========================================
+ Coverage   94.64%   94.74%   +0.10%     
==========================================
  Files           7        7              
  Lines         672      685      +13     
  Branches       49       52       +3     
==========================================
+ Hits          636      649      +13     
- Misses         35       36       +1     
+ Partials        1        0       -1     

Impacted Files	Coverage Δ
src/index.ts	98.99% <93.33%> (+0.07%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9c73f88...44826c1. Read the comment docs.

[simonz130]

@liboz, could you amend your commit to follow conventional commits? See conventionalcommits.org

[liboz]

@simonz130 Done

[laljikanjareeya]

@liboz Thanks for the PR. It seems like this PR is breaking the existing functionality please refer the below quick start example:

const loggingWinston = new LoggingWinston();
const logger = winston.createLogger({
    level: 'info',
    transports: [
        loggingWinston,
    ],
});
logger.info('shields at 99%');

Output in Google Cloud Console:

Before applying the changes:

{
    ...
    jsonPayload: {
        message: 'shields at 99%',
        ...
    }
    ...
}

After applying this changes:

{
    ...
    jsonPayload: {
        message: '{"message":"shields at 99%","level":"info"}' ,
        ...
    }
    ...
}

you can't use info[MESSAGE] always need to check if format is applied than use the same, while in normal case need to use message.

[liboz]

@laljikanjareeya You're right that in that specific example it would return in the format you specified. However, that simply replicates the behavior in the rest of the winston ecosystem. Wouldn't the correct thing to do be to update the quick start example to use one of the default formatters winston provides? For example, winston.format.simple would return info: shields at 99%.

If that's considered problematic, do you think it makes more sense to allow a formatter be passed in and have the plain message be the default formatter?

[liboz]

@laljikanjareeya I changed it so that by default it uses just plain "message". However, it also allows one to pass in their own custom formatter into the logger.

[0xSage]

Taking a look this week

[0xSage]

Hi @liboz , thanks for your contribution. We'd like to get this in for you soon.

I pulled your PR to review your changes, but the log was not formatted. Perhaps I'm not using your fix as intended.

Can you extend the test in system-test/logging-winston to demonstrate your changes, i.e. :

it('should work correctly with winston formats', async () => {
      const MESSAGE = 'A message that should be padded';
      const start = Date.now();
      const LOG_NAME = logName('logging_winston_system_tests_2');
      const logger = winston.createLogger({
        transports: [new LoggingWinston({logName: LOG_NAME})],
        format: winston.format.combine(
          winston.format.colorize(),
          winston.format.padLevels(),
         // TODO: add your format configs here or write a similar test for it
        ),
      });

      logger.error(MESSAGE);

      const [entry] = await pollLogs(
        LOG_NAME,
        start,
        1,
        WRITE_CONSISTENCY_DELAY_MS
      );
      const data = entry.data as {message: string};
      assert.strictEqual(data.message, `   ${MESSAGE}`);
    });

Note: to run system tests in this repo make sure you've set GCLOUD_PROJECT and GOOGLE_APPLICATION_CREDENTIALS

[liboz]

@nicoleczhu As I mentioned earlier, I changed it so that this now lets you pass in a custom formatter through the constructor.

If one does not do that, the default for LoggingWinston is logform.format.printf(info => `${info.message}`); to maintain compatibility as @laljikanjareeya wanted. Because of this, it will ignore a printf passed in through the format option in the createLogger function

const logger = winston.createLogger({
        transports: [new LoggingWinston({logName: LOG_NAME})],
        format: winston.format.combine(
          winston.format.colorize(),
          winston.format.padLevels(),
         // TODO: add your format configs here or write a similar test for it (printf HERE WILL BE IGNORED)
        ),
      });

The work around would be to instead do something like this and pass it in through the constructor of LoggingWinston

const logger = winston.createLogger({
        transports: [new LoggingWinston({logName: LOG_NAME, format: winston.format.printf(info => `TEST123: ${info.message}})],
        format: winston.format.combine(
          winston.format.colorize(),
          winston.format.padLevels(),
         // TODO: add your format configs here or write a similar test for it (printf HERE WILL BE IGNORED)
        ),
      });

If the compatibility that @laljikanjareeya wants is required, I don't think there is an easier way. However, I think if a doc update could happen where people are directed to use a normal formatter like format.printf(info => `${info.message}`); that would simplify a lot of things. What do you think?

[0xSage]

@liboz I see what you're saying.

Let's keep the default logform.format.printf(info => ${info.message}); behavior, so your PR is not a breaking change for all users.

Can you add a test to showcase your extension? I can't do it directly as I can't edit your remote branch. Something along the lines of should be able to override loggingWinston print format

[liboz]

@nicoleczhu Done

[0xSage]

@liboz I tried to merge but it looks like this PR is still breaking CI. See reports errors test.

Running it locally, I'm getting:

{
insertId: "..........3s1NuTHIp1WdASZcRYqxbC"
jsonPayload: {
metadata: {0}
message: "undefined"
}
resource: {
type: "global"
labels: {
project_id: "log-bench"
}
}
timestamp: "2021-02-02T23:03:31.190000057Z"
severity: "ERROR"
logName: "projects/log-bench/logs/bc230313-3f2b-4c0d-a4e2-5a91bb7fc98c_logging_winston_error_reporting_system_tests"
receiveTimestamp: "2021-02-02T23:03:31.581090452Z"
}

Something in the changes is breaking error message formatting.

Are you able to run tests locally yourself? You just need to set GCLOUD_PROJECT GOOGLE_APPLICATION_CREDENTIALS

[liboz]

@nicoleczhu Sorry for the delay. I took a look at it today. I hadn't run the error test because I didn't have the error reporting API enabled so they naturally failed. Thankfully, after enabling them I was able to confirm the issue. It seems like an important use case and I'm glad the tests caught it.

There doesn't appear to be an easy way to handle this case as error are formatted in very interesting ways... It seems that a formatter that is passed into a transport like LoggingWinston behaves very differently from a formatter passed into the createLogger function. The major issue this causes is that any message that is generated from Error will not be passed through. This line seems to be the issue as Object.assign(new Error("test123")) for example returns {}. This makes it impossible to handle error formatting with a custom formatter inside the LoggingWinston.

The only way I can think of to handle this is:

1. No longer use the fallback

if (!options.format) {
      options.format = logform.format.printf(info => `${info.message}`);
    }

and just allow for a json formatted logging to be the default, the error formatting will work. Unfortunately, in order to get the same display for errors, we would need a special catch case, which does not seem like it would be very robust.

Otherwise, it seems like there isn't a great solution regardless and I can just close this PR.

[0xSage]

Hi @liboz , there doesn't seem to be a perfect solution here. Thank you for iterating on this though - now we know! Please feel free to close this PR for now. Thank you for your work here.