xpl / ololog

A better console.log for the log-driven debugging junkies
https://www.npmjs.com/package/ololog
The Unlicense
215 stars 8 forks source link

Intercepting the 'time' section of the log message? #7

Closed cryptoeraser closed 5 years ago

cryptoeraser commented 5 years ago

Hi,

Great tool. I especially love the fact that we can intercept and modify the concat and render stages.

One thing I was not able to do:

I would like to format the timestamp in the following fashion:

[2019-01-19T15:40:28.535Z] (INFO) This is just a message reporting a variable:
                              [1, 2, 3, 4, 5, 6] (info @ logging.js:60)

I know we can add a custom printer for the time, but that changes the output to:

[Sat Jan 19 2019 15:17:03 GMT+0000 (Greenwich Mean Time)]

which is not something that I would like to do? So here is what I am trying to achieve:

So it looks a bit like this: format

Obviously, I tried this:

const logging = log.configure ({
    /*  Injects a function after the "concat" step            */
    'concat+' (blocks) {
        console.log(blocks)
        return blocks;
    },
    time: {
        yes: true,
        format: 'iso'
    }
});

as an attempt to intercept the text stream and try re-format it, but I got this:

[ '\u001b[33m\u001b[22m\u001b[1mThis is just a message reporting a variable:\u001b[22m\u001b[39m',
  '\u001b[33m\u001b[22m\u001b[1m\u001b[22m\u001b[39m [1, 2, 3, 4, 5, 6]' ]

... so the timestamp was not there :)

xpl commented 5 years ago

I know we can add a custom printer for the time, but that changes the output to:

Yeah, because it is supposed that if you're overriding the print function in the time stage, then you need to take care of the date formatting for yourself. That is pretty easy, just call .toISOString () on the passed date object (if you want ISO formatting):

// NB: part of the Ololog library, no need to `npm install` separately
const { cyan, yellow } = require ('ansicolor')

const logging = log.configure ({

    time: {
        yes: true,
        print: date => cyan.dim ('[' + date.toISOString () + '] ') + yellow ('(INFO) ')
    }
})

Does that help?

cryptoeraser commented 5 years ago

Yes. That worked. Thank you very much for the help.

Any suggestions about how to insert (INFO) or (WARNING) or (ERROR) etc. between the timestamp and the message block, as in the image I have included in my message above.

xpl commented 5 years ago

Any suggestions about how to insert (INFO) or (WARNING) or (ERROR) etc. between the timestamp and the message block

What do you want to use to switch between INFO/WARNING/ERROR? I guess, .info, .warn and .error methods?

I mean, log.warn ('foo') should produce [timestamp] (WARNING) foo, right?

There might be a problem with that, as we clearly need to do that not in the render stage but somewhere earlier, before adding the timestamp. But .error, .warn and .info helpers are currently defined like that, routing the parameter to the render stage only:

    get error () { return this.configure ({ render: { consoleMethod: 'error' } }) },
    get warn ()  { return this.configure ({ render: { consoleMethod: 'warn' } }) },
    get info ()  { return this.configure ({ render: { consoleMethod: 'info' } }) },

It might be convenient if we could access that config parameter from other stages, but that is not currently possible (although we could rewrite the https://github.com/xpl/pipez/blob/master/pipez.js to make it possible, but that might not be easy...)

As a quick workaround, we could introduce a new pre-defined stage in the Ololog itself, that would inject the INFO/WARNING/ERROR tag (and change the .error, .info, .warn helpers to route the parameter to that new stage in addition to the render stage).

Will it solve your problem?

cryptoeraser commented 5 years ago

Hi,

Thanks for looking into this, thank you for your time. This sounds a bit too much of a work for a feature that probably will not improve the outcome other than cosmetic results. I don't want to disrupt your dev process with something that is not going to add a lot in return.

I am using the log wrapped inside a sub-module of my project. So I am encapsulating the config and the methods inside an object.

const logger = log.configure ({
    time: {
        yes: true,
        print: date => cyan.dim ('[' + date.toISOString () + '] ') + yellow ('(INFO) ')
    },
   locate: { shift: 1 }
})

const logging = {
    info: function(message) {
        \\ Customise and handle additional features etc.
        logger(yellow('INFO)' + message)
    },
   warning: function(message) {
        \\ Customise and handle additional features etc.
        logger(cyan('WARNING)' + message)
   }
}

(Excuse my pseudo-code, I do not have access to my actual code right now.) The point of wrapping this is to customise bits and pieces in order for this to fit my needs and improve readability. For example, if I am verbosing an object, I would like to have it in a different colour and on a new line (please see the example below).

Then I do this:

// After importing the logging wrapper.
log.info(`Exchange returns the following pairs:\n ${JSON.stringify(myPairsArray)}`)

So I get,

[timestamp] (INFO) Exchange returns the following pairs:
            ['BTC', 'XMR', 'XLM', 'ETH']

So, I think everything is fine so far. Unless my wrapper approach is pointless? :)

Back to the question, maybe in the future, if there is more demand for this option by others etc. You might add a way to insert context sensitive bits that can be injected at the wrapper level. For example:

const logging = {
    info: function(message, id) {
          /* Do stuff such as:
             Injecting the ID into the log message so we know about the context it is coming from:
             timestamp + ID + message
          */

    }
}

So you get:

[timestamp] | CLUSTER[01] | (INFO) Exchange returns the following pairs:
                            ['BTC', 'XMR', 'XLM', 'ETH']
[timestamp] | CLUSTER[21] | (INFO) Exchange returns the following pairs:
                            ['ADA', 'FCT', LSK', 'ZEC']

which in return might allow a custom info, warning tag etc and improve the readability.

// timestamp + ID + INFO + message
[timestamp] | CLUSTER[01] | INFO | Exchange returns the following pairs:
                                   ['BTC', 'XMR', 'XLM', 'ETH']
[timestamp] | CLUSTER[21] | INFO | Exchange returns the following pairs:
                                   ['ADA', 'FCT', LSK', 'ZEC']

At the end of the day, this is mostly cosmetic to certain level. I love your module.

For python I am using a variant of this: Logaware Docs six8/logaware

xpl commented 5 years ago

@cryptoeraser I've added a new overrideable stage called tag. Please see the updated docs:

  1. Displaying The INFO/WARN/ERROR Tags
  2. Customized Tag Printer
screen shot 2019-01-22 at 22 46 59

The example code:

const bullet = require ('string.bullet') // NB: these packages are part of Ololog, no need to install them separately
const { cyan, yellow, red, dim } = require ('ansicolor')

const log = require ('ololog').configure ({

    locate: false,
    time: true,
    tag: (lines, {
            level = '',
            levelColor = { 'info': cyan, 'warn': yellow, 'error': red.bright.inverse },
            clusterId
          }) => {

        const clusterStr = clusterId ? ('CLUSTER[' + (clusterId + '').padStart (2, '0') + ']') : ''
        const levelStr = level && (levelColor[level] || (s => s)) (level.toUpperCase ())

        return bullet (dim (clusterStr.padStart (10)) + '\t' + levelStr.padStart (6) + '\t', lines)
    }
})
log.configure ({ tag: { clusterId: 1  } })       ('foo')
log.configure ({ tag: { clusterId: 3  } }).info  ('bar')
log.configure ({ tag: { clusterId: 27 } }).error ('a multiline\nerror\nmessage')
xpl commented 5 years ago

Also notice the usage of string.bullet — a little helper (that is a part of Ololog) that helps formatting multiline messages that do not spill below the added prefix.

cryptoeraser commented 5 years ago

Yeah, I have seen your commit and I was already digging in the diffs :) Thank you very much! This is amazing!