logging depth for javascript objects

406 views
Skip to first unread message

Sharath Gururaj

unread,
Aug 15, 2013, 5:57:47 PM8/15/13
to bunyan-...@googlegroups.com
Is there any way to control how deep a javascript is logged?
for example, 
{a: {b:{c:{d:{e:"hi"}}}}}

should be logged completey instead of 
{a: b:[Object]}

Trent Mick

unread,
Aug 16, 2013, 2:35:55 PM8/16/13
to Sharath Gururaj, bunyan-...@googlegroups.com
Hi Sharath,

I believe bunyan is working properly here... in logging the full object depth:

```
> var bunyan = require('./lib/bunyan')
undefined
> var log = bunyan.createLogger({name: 'foo'})
undefined
> log.info('hi')
{"name":"foo","hostname":"grape.local","pid":1798,"level":30,"msg":"hi","time":"2013-08-16T18:27:46.349Z","v":0}
undefined
> obj = {a: {b:{c:{d:{e:"hi"}}}}}
{ a: { b: { c: [Object] } } }
> log.info(obj, 'hi again')
{"name":"foo","hostname":"grape.local","pid":1798,"level":30,"a":{"b":{"c":{"d":{"e":"hi"}}}},"msg":"hi again","time":"2013-08-16T18:28:08.428Z","v":0}
undefined
>
```

Or did you mean if you attempt to log the 'obj' this way?

```
> log.info('using obj this way', obj)
{"name":"foo","hostname":"grape.local","pid":1798,"level":30,"msg":"using obj this way { a: { b: { c: [Object] } } }","time":"2013-08-16T18:29:08.731Z","v":0}
```

In that case, the Bunyan "log.info()" (and log.warn, etc.) are using Node's `util.format`, the same as console.log:

```
> console.log('this is obj:', obj)
this is obj: { a: { b: { c: [Object] } } }
undefined
>
undefined
> var util= require('util')
undefined
> util.format('this is obj:', obj)
'this is obj: { a: { b: { c: [Object] } } }'
```

`util.format` uses `util.inspect(obj)`:

```
> util.inspect(obj)
'{ a: { b: { c: [Object] } } }'
```

Your options here:

1. use util.inspect manually and its 'depth' option:

```
> util.inspect(obj, {depth: null})
'{ a: { b: { c: { d: { e: \'hi\' } } } } }'
> log.info('this is obj', util.inspect(obj, {depth:null}))
{"name":"foo","hostname":"grape.local","pid":1798,"level":30,"msg":"this is obj { a: { b: { c: { d: { e: 'hi' } } } } }","time":"2013-08-16T18:33:36.312Z","v":0}
```

2. use the '%j' formatting option for util.format. Note that that doesn't handle things like methods, complex objects, but typically you aren't logging those anyway:

```
> log.info('this is obj: %j', obj)
{"name":"foo","hostname":"grape.local","pid":1798,"level":30,"msg":"this is obj: {\"a\":{\"b\":{\"c\":{\"d\":{\"e\":\"hi\"}}}}}","time":"2013-08-16T18:34:48.054Z","v":0}
```

3. Log the object as the first argument to `log.info`:

```
> log.info({obj: obj}, 'this is my obj')
{"name":"foo","hostname":"grape.local","pid":1798,"level":30,"obj":{"a":{"b":{"c":{"d":{"e":"hi"}}}}},"msg":"this is my obj","time":"2013-08-16T18:35:43.638Z","v":0}
```

I typically do #3 in my code.

Cheers,
Trent


--
Trent Mick

Sharath Gururaj

unread,
Aug 19, 2013, 11:32:20 PM8/19/13
to Trent Mick, bunyan-...@googlegroups.com
Thanks for the awesome reply trent, I was indeed using obj as the second parameter (as per the suggestion on the api guide)
and hence the truncation
I switched to method 3 and it works now. 
Just wondering why bunyan chooses to use util.format when the object is not the first to be logged?

Trent Mick

unread,
Aug 20, 2013, 12:32:21 AM8/20/13
to Sharath Gururaj, bunyan-...@googlegroups.com
> Just wondering why bunyan chooses to use util.format when the object is not the first to be logged?

I started with wanting printf style convenience:

log.info("a:%d b:%s", a, b)

using util.format was an obvious handler for that. Then special handling was added to allow adding
extra fields. That special arg has to be first, because else it is ambiguous which args belong to
printf-%-codes in the string.

Trent

--
Trent Mick
Reply all
Reply to author
Forward
0 new messages