[Bug]: TypeError encountered when logging class extending superclass which contains protected property

[turchiad]

🔎 Search Terms

TypeError

The problem

Regression in winston v3.7.1 caused the code shown further within to produce a TypeError.

See below error log:

      Object.assign(msg, this.defaultMeta, msgClone);
             ^

TypeError: Cannot assign to read only property 'canBeAnything' of object 'Error: This must not be empty'
    at Function.assign (<anonymous>)
    at DerivedLogger._addDefaultMeta (<PATH>/node_modules/winston/lib/winston/logger.js:639:14)
    at DerivedLogger.<computed> [as info] (<PATH>/node_modules/winston/lib/winston/create-logger.js:80:14)
    at Object.<anonymous> (<PATH>/index.js:31:5)
    at Module._compile (node:internal/modules/cjs/loader:1099:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1153:10)
    at Module.load (node:internal/modules/cjs/loader:975:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:77:12)
    at node:internal/main/run_main_module:17:47

What version of Winston presents the issue?

v3.7.1

What version of Node are you using?

v.17.8.0

If this worked in a previous version of Winston, which was it?

v3.6.0

Minimum Working Example

const {createLogger, format, transports} = require('winston');
const {json} = format;

const log = createLogger({
	level: 'info',
	defaultMeta: {service: 'database-service'},
	transports: [
		new transports.Console({
			format: json(),
			level: 'info',
		}),
	]
});

class SuperError extends Error {
	constructor() {
		super();
		Object.defineProperty(this, 'canBeAnything', { enumerable: true, value: ''});
	}
}

class ThisError extends SuperError {
	message;

	constructor() {
		super();
		this.message = "This must not be empty";
	}
}

log.info(new ThisError());

Additional information

This was encountered initially when using winston to report an error produced by mssql. mssql has their own error classes and when winston upticked from v3.6.0 to v3.7.1 it broke our error reporting.

Original code is closed source, but I have basically boiled down the minimum required to reproduce this error above.

Worth noting, perhaps, but extend Error is extra and I don't believe it's needed. Additionally, this TypeError is not reproduced if this.message is omitted or is equal to ''.

[wbt]

@maverick1872 Can you get on this?
As it's not possible to unpublish 3.7.1 since there are dependent packages in the registry, I marked this particular version deprecated with a message to use 3.6.0 or >3.7.1, but that marks the whole package as deprecated so we should try to get this fixed ASAP (especially since npm's undeprecate syntax doesn't actually work, and neither does their support form or email address).

[wbt]

On further consideration, I thought it was better to go forward with a patch-level reversion breaking any code that relied on the new functionality released just hours earlier than to be breaking what seemed likely to be a higher volume of previously working code on a feature update.

[maverick1872]

@maverick1872 Can you get on this?
As it's not possible to unpublish 3.7.1 since there are dependent packages in the registry, I marked this particular version deprecated with a message to use 3.6.0 or >3.7.1, but that marks the whole package as deprecated so we should try to get this fixed ASAP (especially since npm's undeprecate syntax doesn't actually work, and neither does their support form or email address).

I'm at the gym right now but I can definitely look into this.

[maverick1872]

Successfully reproduced locally. Need to figure out how to get reproduced in a test environment but hoping to have a fix sorted out by Monday or so.

[maverick1872]

@wbt @turchiad So finally got around back to doing some more diagnosing on this issue. The root cause of this TypeError is due to the fact that the Object.defineProperty() call leverages (by omission) the default writable descriptor of false. This means that when we go to mutate the original msg object, it attempts to re-assign to a non-writable property; therefore resulting in the following type error.

This is something that will have to be considered to correctly apply metadata moving forward if we want to retain the mutating behavior of Winston. Working on a resolution that includes checks against the writable attribute of all properties.

[maverick1872]

Have a fix in place for the TypeError, but this has brought to my attention another "side-effect" of the default metadata logic I introduced in v3.7.0. Since I'm leveraging a stringify operation to clone the msg so metadata can be applied appropriately without getting rid of the mutations We have lossy types in the level shorthand methods but not the log methods.

I don't perceive this to be an issue (it appears to be a current behavior as well) though. Would love to publish an alpha version of the above fixes and maybe we can get some feedback on the metadata fixes prior to publishing a minor bump that will likely be consumed by default on package upgrades.

[WhiteMinds]

What is the progress of this issue? I still can't use logger.child method to override defaultMeta.

[pflannery]

I too had to revert back to 3.7.1 so that I can still provide child loggers with override properties.

Using 3.8.2 I did a test and found that if we change the child function to check for splats then we can preserve this issue fix as well as get back child override expected behaviour
(with the added benefit of asserting user mistakes for trying to overwrite their own non-writable props).

const hasSplats = !!info[Symbol.for('splat')];

// preserves non-writable props and assertions for user land
let infoClone;
if (hasSplats) {
  // splats take precedence
  infoClone = Object.assign(
    defaultRequestMetadata,
    info
  );
} else {
  // child meta takes precedence
  infoClone = Object.assign(
    info,
    defaultRequestMetadata,
  );
}

This then produces

log.info(new ThisError())
// output: {"canBeAnything":"","level":"info","message":"This must not be empty","service":"database-service"}

log.child({service: "child service", a: "child"}).info(new ThisError())
// output: {"a":"child","canBeAnything":"","level":"info","message":"This must not be empty","service":"child service"}

log.child({service: "child service", a: "child"}).info("", {service: "splat"})
// output: {"a":"child","level":"info","message":"","service":"splat"}

log.child({service: "child service", a: "child", canBeAnything: false}).info(new ThisError())
// output: Cannot assign to read only property 'canBeAnything' of object 'Error: This must not be empty'

Im not that familiar with winston code. We may also need to merge in the splats data when they are present?