Enhancing Pino to Support (Message, Payload) Logging Without Breaking Pretty Logs

Collapse
X
 
  • Time
  • Show
Clear All
new posts
  • MyrinNew
    Senior Member
    • Feb 2024
    • 5168

    #1

    Enhancing Pino to Support (Message, Payload) Logging Without Breaking Pretty Logs

    Introduction

    Pino is a blazing-fast logging library for Node.js, built for structured logs and high performance. However, one common frustration developers face is that Pino does not natively support logging a message alongside an object the way console.log does.


    Note: this is my approach and a solution that works well for me. If you have any suggestions, improvements, or use a different method in your projects, I’d love to hear your thoughts!


    The Problem

    If you log with:






    logger.info('User created', { userId: 123 });







    You expect:






    INFO [12:30:45] User created { userId: 123 }







    But instead, Pino ignores the second argument:






    INFO [12:30:45] User created







    Even worse, if you're using pino-pretty, the output doesn’t format correctly when using string interpolation (%s, %j).





    Understanding Why Pino Ignores Extra Arguments

    Pino follows a strict logging format:

    1. One argument → If it's an object, it's logged as JSON.
    2. One argument → If it's a string, it’s logged as a msg field.
    3. More than one argument → Only placeholders (%s, %d, %j) are used.




    logger.info('Hello %s', 'world'); // ✅ Logs correctly
    logger.info('Hello', { world: true }); // ❌ Logs only "Hello"







    Unlike console.log, Pino does not merge a message with an object unless explicitly structured.





    Major Problem: pino-pretty Ignores Error Serializers

    Default Behavior: Errors Are Not Properly Serialized

    Pino does not properly serialize errors when logged using %j:






    logger.debug('hello %j', new Error('some crazy error'));







    🚨 Logs:






    DEBUG [12:30:45] hello
    • The error serializer is ignored.
    • The stack trace is lost.
    • Everything is stringified in one line.


    Fixed Behavior: Error Serializer Works in Dev Mode

    With our fix:






    logger.debug('hello', new Error('some crazy error'));







    🎉 Logs correctly in development environments with pino-pretty:






    DEBUG [12:30:45] hello
    {
    "error": {
    "type": "Error",
    "message": "some crazy error",
    "stack": "Error: some crazy error
    at file.js:12:34"
    }
    }
    • Preserves the error stack trace.
    • Works seamlessly in pino-pretty and JSON logs.





    The Right Fix: Supporting (message, payload) While Preserving Pino's Structure

    To fix this behavior, we need to:
    • Detect when the first argument is a string and second is an object.
    • Ensure %s, %d, and %j placeholders still work correctly.
    • Preserve Pino’s structured JSON logging.
    • Ensure compatibility with pino-pretty, transports, and serializers.


    Final Fix





    import pino, { LogFn, Logger, LoggerOptions } from 'pino';

    const isDevelopment = process.env.NEXT_PUBLIC_NODE_ENV === 'development' || process.env.NODE_ENV === 'development';

    const pinoConfig: LoggerOptions = {
    level: process.env.LOG_LEVEL || 'debug',
    // We recommend using pino-pretty in development environments only
    ...(isDevelopment
    ? {
    transport: {
    target: 'pino-pretty',
    options: { colorize: true, translateTime: 'HH:MM:ss Z', sync: true },
    },
    }
    : {}),
    hooks: { logMethod },
    timestamp: pino.stdTimeFunctions.isoTime,
    serializers: {
    err: pino.stdSerializers.err,
    error: pino.stdSerializers.err,
    },
    };

    const logger = pino(pinoConfig);

    function logMethod(this: Logger, args: ParametersLogFn>, method: LogFn) {
    // If two arguments: (message, payload) -> Format correctly
    if (args.length === 2 && typeof args[0] === 'string' && typeof args[1] === 'object' && !args[0].includes('%')) {
    const payload = { msg: args[0], ...args[1] };

    // If the object is an Error, serialize it properly
    if (args[1] instanceof Error) {
    payload.error = payload.error ?? args[1];
    }

    method.call(this, payload);
    } else {
    // any other amount of parameters, or order of parameters will be considered here
    method.apply(this, args);
    }
    }

    export default logger;










    How This Fix Works

    (Message, Payload) Now Works as Expected





    logger.info('User created', { userId: 123 });







    ➡️ Logs correctly:






    INFO [12:30:45] User created { userId: 123 }







    Before: ❌ Second argument ignored


    Now: ✅ Structured properly.



    Preserves String Interpolation

    When a string interpolation is present in the message, we fallback to the default behavior of Pino to handle string interpolations. See pino docs for more details: https://github.com/pinojs/pino/blob/...i.md#logmethod






    logger.info('User %s created with ID %d', 'John', 123);







    ➡️ Logs:






    INFO [12:30:45] User John created with ID 123










    Ensures Error Serialization Works





    logger.error('Something went wrong', new Error('Oops!'));







    ➡️ Logs:






    ERROR [12:30:45] Something went wrong { error: { msg: 'Oops!', stack: '...' } }







    Before: ❌ Pino didn't include the error in the logs

    Now: ✅ Uses Pino's error serializer.





    Why I believe This Fix is The Right Approach

    • Respects Pino’s structured logging (doesn’t mutate logs).
    • Fully supports pino-pretty formatting.
    • Doesn’t break child loggers, transports, or serializers.
    • Makes Pino more intuitive without hacks.





    Final Thoughts

    With this fix:
    • Pino behaves the way you expect.
    • Messages and objects log together properly.
    • Pino remains fast, structured, and developer-friendly.


    Happy coding!




    More...
Working...