Skip to content

Commit d438f1b

Browse files
hughescrhughescr
committed
Fix string argument handling and achieve 100% mutation coverage
- Fix logger to properly handle multiple string arguments (join with spaces instead of treating as character arrays) - Add processLogArgs function to concatenate consecutive leading strings - Wrap logger methods (info, warn, error, debug) to process arguments before passing to Winston - Remove unnecessary optimizations that caused equivalent mutants: - Early return for argCount < 2 - Conditional metadata assignment for remainingCount > 0 - Always construct and pass metadata, letting Winston's formatter handle empty objects - Add comprehensive tests for multi-argument logging scenarios - Add performance test file to measure optimization impact - Achieve 100% mutation test coverage (66/66 mutants killed)
1 parent 830a77a commit d438f1b

File tree

3 files changed

+262
-2
lines changed

3 files changed

+262
-2
lines changed

‎perf-test.mjs‎

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
import _ from 'lodash';
2+
import { performance } from 'perf_hooks';
3+
4+
const iterations = 100000;
5+
6+
const withEarlyReturn = (args) => {
7+
const argCount = args.length;
8+
if(argCount < 2) {
9+
return { message: args[0] };
10+
}
11+
const stringArgs = [];
12+
for(const arg of args) {
13+
if(!_.isString(arg)) { break; }
14+
stringArgs.push(arg);
15+
}
16+
const hasStrings = stringArgs.length > 0;
17+
const message = hasStrings ? stringArgs.join(' ') : args[0];
18+
const remainingArgs = args.slice(hasStrings ? stringArgs.length : 1);
19+
const remainingCount = remainingArgs.length;
20+
const result = { message };
21+
if(remainingCount > 0) {
22+
const metadataObjects = _.map(remainingArgs, (arg, idx) =>
23+
(_.isObject(arg) ? arg : { [idx]: arg })
24+
);
25+
result.metadata = _.assign({}, ...metadataObjects);
26+
}
27+
return result;
28+
};
29+
30+
const withoutEarlyReturn = (args) => {
31+
const stringArgs = [];
32+
for(const arg of args) {
33+
if(!_.isString(arg)) { break; }
34+
stringArgs.push(arg);
35+
}
36+
const hasStrings = stringArgs.length > 0;
37+
const message = hasStrings ? stringArgs.join(' ') : args[0];
38+
const remainingArgs = args.slice(hasStrings ? stringArgs.length : 1);
39+
const remainingCount = remainingArgs.length;
40+
const result = { message };
41+
if(remainingCount > 0) {
42+
const metadataObjects = _.map(remainingArgs, (arg, idx) =>
43+
(_.isObject(arg) ? arg : { [idx]: arg })
44+
);
45+
result.metadata = _.assign({}, ...metadataObjects);
46+
}
47+
return result;
48+
};
49+
50+
// Single arg case (most common for single-arg calls)
51+
const start1 = performance.now();
52+
for(let i = 0; i < iterations; i++) {
53+
withEarlyReturn(['single']);
54+
}
55+
const time1 = performance.now() - start1;
56+
57+
const start2 = performance.now();
58+
for(let i = 0; i < iterations; i++) {
59+
withoutEarlyReturn(['single']);
60+
}
61+
const time2 = performance.now() - start2;
62+
63+
console.log('=== Single Argument (common case) ===');
64+
console.log(`With early return: ${time1.toFixed(2)}ms`);
65+
console.log(`Without early return: ${time2.toFixed(2)}ms`);
66+
console.log(`Difference: ${(time1 - time2).toFixed(2)}ms (${((time1 / time2 - 1) * 100).toFixed(1)}%)`);
67+
68+
// Two args case (to see if early return helps)
69+
const start3 = performance.now();
70+
for(let i = 0; i < iterations; i++) {
71+
withEarlyReturn(['first', 'second']);
72+
}
73+
const time3 = performance.now() - start3;
74+
75+
const start4 = performance.now();
76+
for(let i = 0; i < iterations; i++) {
77+
withoutEarlyReturn(['first', 'second']);
78+
}
79+
const time4 = performance.now() - start4;
80+
81+
console.log('\n=== Two Arguments ===');
82+
console.log(`With early return: ${time3.toFixed(2)}ms`);
83+
console.log(`Without early return: ${time4.toFixed(2)}ms`);
84+
console.log(`Difference: ${(time3 - time4).toFixed(2)}ms (${((time3 / time4 - 1) * 100).toFixed(1)}%)`);

‎src/index.ts‎

Lines changed: 44 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,7 @@ function LUXON_FORMAT_NOW(): string {
3333

3434
const noprefix = 'noprefix';
3535

36-
const logger: ExtendedLogger = winston.createLogger({
36+
const baseLogger: ExtendedLogger = winston.createLogger({
3737
levels: {
3838
error: 0,
3939
warn: 1,
@@ -71,6 +71,49 @@ const logger: ExtendedLogger = winston.createLogger({
7171
],
7272
}) as unknown as ExtendedLogger;
7373

74+
// Wrap logger methods to handle multiple string arguments like console.log
75+
interface LoggerWithMethods {
76+
info(...args: unknown[]): winston.Logger
77+
warn(...args: unknown[]): winston.Logger
78+
error(...args: unknown[]): winston.Logger
79+
debug(...args: unknown[]): winston.Logger
80+
}
81+
82+
function processLogArgs(args: unknown[]): { message: unknown, metadata?: Record<string, unknown> } {
83+
// Collect consecutive leading strings
84+
const stringArgs: string[] = [];
85+
for(const arg of args) {
86+
if(!_.isString(arg)) {
87+
break;
88+
}
89+
stringArgs.push(arg);
90+
}
91+
92+
// Build message: join strings if we have any, otherwise use first arg
93+
const hasStrings = stringArgs.length > 0;
94+
const message = hasStrings ? stringArgs.join(' ') : args[0];
95+
96+
// Get remaining args (everything after strings, or everything after first arg)
97+
const remainingArgs = args.slice(hasStrings ? stringArgs.length : 1);
98+
99+
// Convert all remaining args to metadata objects, then merge
100+
const metadataObjects = _.map(remainingArgs, (arg: unknown, idx: number): Record<string, unknown> =>
101+
(_.isObject(arg) ? arg as Record<string, unknown> : { [idx]: arg })
102+
);
103+
const metadata = _.assign({}, ...metadataObjects) as Record<string, unknown>;
104+
105+
return { message, metadata };
106+
}
107+
108+
const logger: ExtendedLogger = _.create(baseLogger) as ExtendedLogger;
109+
_.forEach(['info', 'warn', 'error', 'debug'], (method) => {
110+
const originalMethod = baseLogger[method as keyof LoggerWithMethods].bind(baseLogger);
111+
logger[method as keyof LoggerWithMethods] = function(...args: unknown[]): winston.Logger {
112+
const { message, metadata } = processLogArgs(args);
113+
return originalMethod(message as string, metadata);
114+
};
115+
});
116+
74117
morgan.token('timestamp', LUXON_FORMAT_NOW);
75118
morgan.token('route', (req: http.IncomingMessage) => _.get(req as ExpressRequest, 'route.path', '***'));
76119
morgan.token('user', (req: http.IncomingMessage) => _.get(req as ExpressRequest, 'user._id')); // defaults to '-' even if you specify ''

‎test/module.test.ts‎

Lines changed: 134 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -90,12 +90,145 @@ describe('Logging', () => {
9090
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] hi \{"some":"object"\}\n$/));
9191
});
9292

93+
it('logging should handle multiple string arguments', () => {
94+
expect.assertions(1);
95+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
96+
methodLogger.info('hello', 'world');
97+
98+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] hello world\n$/));
99+
});
100+
101+
it('logging should handle multiple strings followed by object', () => {
102+
expect.assertions(1);
103+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
104+
methodLogger.info('hello', 'world', { obj: 1 });
105+
106+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] hello world \{"obj":1\}\n$/));
107+
});
108+
109+
it('logging should handle object followed by object', () => {
110+
expect.assertions(1);
111+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
112+
methodLogger.info({ obj: 1 }, { other: 2 });
113+
114+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] \{"obj":1\} \{"other":2\}\n$/));
115+
});
116+
117+
it('logging should handle three strings', () => {
118+
expect.assertions(1);
119+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
120+
methodLogger.info('hello', 'world', 'test');
121+
122+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] hello world test\n$/));
123+
});
124+
125+
it('logging should handle multiple non-object args after strings', () => {
126+
expect.assertions(1);
127+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
128+
methodLogger.info('hello', 123, 456);
129+
130+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] hello \{"0":123,"1":456\}\n$/));
131+
});
132+
133+
it('logging should handle string with multiple objects', () => {
134+
expect.assertions(1);
135+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
136+
methodLogger.info('hello', { a: 1 }, { b: 2 });
137+
138+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] hello \{"a":1,"b":2\}\n$/));
139+
});
140+
141+
it('logging should handle two objects without strings', () => {
142+
expect.assertions(1);
143+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
144+
methodLogger.info({ a: 1 }, { b: 2 });
145+
146+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] \{"a":1\} \{"b":2\}\n$/));
147+
});
148+
149+
it('logging should handle single non-object primitive', () => {
150+
expect.assertions(1);
151+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
152+
methodLogger.info(123);
153+
154+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] 123\n$/));
155+
});
156+
157+
it('logging should handle number followed by object', () => {
158+
expect.assertions(1);
159+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
160+
methodLogger.info(123, { meta: 'data' });
161+
162+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\] 123 \{"meta":"data"\}\n$/));
163+
});
164+
93165
it('logging should allow empty message', () => {
94166
expect.assertions(1);
95167
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
96168
methodLogger.info();
97169

98-
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\[INFO\]\n$/));
170+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/^\[.*\] \[INFO\]\n$/));
171+
});
172+
173+
it('logging with zero args should not have metadata', () => {
174+
expect.assertions(1);
175+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
176+
methodLogger.info();
177+
178+
expect(spyOnStream).toHaveBeenCalledWith(expect.not.stringMatching(/\{.*\}/));
179+
});
180+
181+
it('logging with one arg should not have metadata', () => {
182+
expect.assertions(1);
183+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
184+
methodLogger.info('single');
185+
186+
expect(spyOnStream).toHaveBeenCalledWith(expect.not.stringMatching(/single[^\n\r{\u2028\u2029]*\{.*\}/));
187+
});
188+
189+
it('logging with two strings should not include metadata braces', () => {
190+
expect.assertions(2);
191+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
192+
methodLogger.info('first', 'second');
193+
194+
const output = spyOnStream.mock.calls[spyOnStream.mock.calls.length - 1][0];
195+
expect(output).toMatch(/\[INFO\] first second\n$/);
196+
// Critical: no braces should appear (would fail if empty metadata {} is added)
197+
expect(output).not.toContain('{');
198+
});
199+
200+
it('logging with string and number should include metadata', () => {
201+
expect.assertions(1);
202+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
203+
methodLogger.info('msg', 123);
204+
205+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\{"0":123\}/));
206+
});
207+
208+
it('logging with 0 args should produce exactly undefined message with no metadata', () => {
209+
expect.assertions(1);
210+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
211+
methodLogger.info();
212+
213+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/^\[.*\] \[INFO\]\n$/));
214+
});
215+
216+
it('logging with 2+ args where first is not string should have metadata', () => {
217+
expect.assertions(1);
218+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
219+
methodLogger.info(null, { meta: 'data' });
220+
221+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\{"meta":"data"\}/));
222+
});
223+
224+
it('logging with single object should use that object directly as metadata', () => {
225+
expect.assertions(1);
226+
const spyOnStream = spyOn(consoleStreams._stdout, 'write').mockImplementation(_.constant(true));
227+
const metaObj = { direct: 'reference' };
228+
methodLogger.info('message', metaObj);
229+
230+
// Verify the exact object content appears in output
231+
expect(spyOnStream).toHaveBeenCalledWith(expect.stringMatching(/\{"direct":"reference"\}/));
99232
});
100233

101234
it('logging should message with just object', () => {

0 commit comments

Comments
 (0)