multiple transports loosing SPLAT/meta

[WhiteTomX]

Please tell us about your environment:

• winston version?
  • winston@2
  • winston@3
• _node -v outputs: v8.11.3
• _Operating System? Windows
• _Language? Typescript

What is the problem?

Adding multiple transports to a logger causes the info-object to loose meta field on all but one transport.:

const Winston = require("winston");
Winston.add(new Winston.transports.Console({
    format: Winston.format.combine(Winston.format(info => {
        info.message = info.message + "Console";
        return info;
    })(), Winston.format.splat(), Winston.format.simple(), Winston.format(info => {
        // console.log(info); // meta is there!
        return info;
    })()),
    handleExceptions: true
}));
Winston.add(new Winston.transports.File({
    filename: "test.log",
    format: Winston.format.combine(Winston.format(info => {
        // console.log(info); // meta is gone :(! and so is SPLAT only a array of length 1
        return info;
    })(), Winston.format.splat(), Winston.format.simple())
}));
for (let index = 0; index < 10; index++) {
    Winston.error("test %s" + index, "blub", "metainfo");
}

Output Console:

error: test blub0Console {"meta":"metainfo"}
error: test blub1Console {"meta":"metainfo"}
error: test blub2Console {"meta":"metainfo"}
error: test blub3Console {"meta":"metainfo"}
error: test blub4Console {"meta":"metainfo"}
error: test blub5Console {"meta":"metainfo"}
error: test blub6Console {"meta":"metainfo"}
error: test blub7Console {"meta":"metainfo"}
error: test blub8Console {"meta":"metainfo"}
error: test blub9Console {"meta":"metainfo"}

Output File:

error: test blub0
error: test blub1
error: test blub2
error: test blub3
error: test blub4
error: test blub5
error: test blub6
error: test blub7
error: test blub8
error: test blub9

Sometimes one transport gets the meta and the other doesn't and for the next logentry its the other way around.

What do you expect to happen instead?

Each transport should get a clean "new" info object. At least with a full SPLAT. So {"meta":"metainfo"} is included in File too.

Other information

I tried for a moment to find the issue in debugger, but got lost in the streams. So please excuse me, if this issue belongs more to winston-transports. I try to investigate this further.

It seems the info[SPLAT] is preserved from one Transport to the other, but due to the splat() formatter th metadata is removed. Maybe its more related to the splat() altering the array than i thought...

As a workaround i will push the metadata back to SPLAT after splat():

const splatWorkaround = Winston.format.combine(
  Winston.format.splat(),
  Winston.format(info => {
    if (info.meta && info.meta instanceof Array) info[SPLAT].push(...info.meta);
    else if (info.meta) info[SPLAT].push(info.meta);
    return info;
  })()
);

To get this working i will use this workaround:

[avaly]

I was about to open a new issue regarding this exact same issue, and then I found this one. I'll post my description as well. :)

---

Please tell us about your environment:

• winston version?
  • [email protected]
• node -v outputs: v8.12.0
• Operating System? Linux
• Language? ES5

What is the problem?

The custom data added by the splat formatter as the field meta in the log message is dropped when all the following conditions are met:

• when a transport has already consumed the message (i.e. on a second transport)
• when the first log string does not contain any tokens (i.e. %s)
• when the custom format is applied on each transport

To replicate the bug, see the code:

https://gist.github.com/avaly/527eee1e061accb7e1f446ca105c3094#file-run-with-bug-js

Which outputs:

{"level":"info","message":"foo","meta":["bar","ham"]}
{"level":"info","message":"foo"}
{"level":"info","message":"with interpolated strings: bar and ham"}
{"level":"info","message":"with interpolated strings: bar and ham"}

What do you expect to happen instead?

Expected output:

{"level":"info","message":"foo","meta":["bar","ham"]}
{"level":"info","message":"foo","meta":["bar","ham"]}
{"level":"info","message":"with interpolated strings: bar and ham"}
{"level":"info","message":"with interpolated strings: bar and ham"}

Other information

If we move the custom format to the top level logger, then the bug does not present itself:

https://gist.github.com/avaly/527eee1e061accb7e1f446ca105c3094#file-run-without-bug-js

But, most of the time, different transports do require different formatting.

[Fantus]

i did some digging and i think i found the cause.

The issue is located in the winston stream module:
https://github.com/winstonjs/winston-transport/blob/master/index.js#L90

# index.js#L90
TransportStream.prototype._write = function _write(info, enc, callback) {
    ...
    // We trap(and re-throw) any errors generated by the user-provided format, but also
    // guarantee that the streams callback is invoked so that we can continue flowing.
    try {
      transformed = this.format.transform(Object.assign({}, info), this.format.options);
    } catch (err) {
      errState = err;
    }
    ...
};

They use Object.assign to create a shallow copy of the info object so the "SPLAT" array gets modified by the formatters.
To fix this we would need to do a deep clone here instead of an Object.assign

Proof:

      let clone = Object.assign({}, info);
      clone[SPLAT] = [...info[SPLAT]]
      transformed = this.format.transform(clone, this.format.options);

fixes the splat issue in your test.

[Fantus]

i think i figured out a workaround for now. You can try adding this to your scripts to make the transport use a "deepclone" instead of making shallow clone

you can try this as a workaround for now:

const deepcopy = require('deepcopy');
const TransportStream = require('winston-transport');
const { LEVEL } = require('triple-beam');

TransportStream.prototype._write = function _write(info, enc, callback) {
    if (this.silent || (info.exception === true && !this.handleExceptions)) {
        return callback(null);
    }

    // Remark: This has to be handled in the base transport now because we
    // cannot conditionally write to our pipe targets as stream. We always
    // prefer any explicit level set on the Transport itself falling back to
    // any level set on the parent.
    const level = this.level || (this.parent && this.parent.level);

    if (!level || this.levels[level] >= this.levels[info[LEVEL]]) {
        if (info && !this.format) {
            return this.log(info, callback);
        }

        let errState;
        let transformed;

        // We trap(and re-throw) any errors generated by the user-provided format, but also
        // guarantee that the streams callback is invoked so that we can continue flowing.
        try {
            transformed = this.format.transform(deepcopy(info), this.format.options);
        } catch (err) {
            errState = err;
        }

        if (errState || !transformed) {
            // eslint-disable-next-line callback-return
            callback();
            if (errState) throw errState;
            return;
        }

        return this.log(transformed, callback);
    }

    return callback(null);
};

[ochedru]

@Fantus nice workaround, thank you!

[tagyoureit]

I have a PR in for this. Waiting for review from @DABH and @indexzero. winstonjs/logform#85

[Aenima4six2]

Using this as a workaround

const deepclone = require('deepclone')

const deepCloneSplat = format((info) => {
    const cloned = deepclone(info)
    return format.splat().transform(cloned)
})

Use deepCloneSplat in place of format.Splat()

[fourpastmidnight]

I came across this, too, in #1933! The solution posed by @Aenima4six2 is what I'm using and it works like a charm! Thanks!!

In light of this, I've taken to creating my own formatter classes which ensure that if any property on info is to be "mutated", that a deepclone is taken first so that all transports get the original info object later on. This has been working well for my application.

[maverick1872]

@avaly thanks for including those gists for reproducing this issue. That has made it significantly easier to reproduce the issue described here. I've included this test in a PR of my to verify a lot of the issues we have metadata currently.

I find it most likely that this will be resolved as a part of #2072.