trentm / node-bunyan

a simple and fast JSON logging module for node.js services
Other
7.15k stars 514 forks source link

-c condition not working #363

Open BionanoDev opened 8 years ago

BionanoDev commented 8 years ago

Our log lines look like this:

{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}

if I run bunyan -c 'this.operation=="updateRunProgress"' IrysView.log to get the log entry with that operation it returns every log line. No filtering appears to be taking place. I've tried many variations, but nothing seems to work. What am I missing?

Khez commented 8 years ago

Hello,

I tested this on a couple of version of bunyan, including v1.7.0 and v.1.7.1 What version are you using that's giving you trouble?

Best Regards, Khez

P.S. This was the test scenario on filtering this exact line:

echo '{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}' | bunyan -c 'this.operation!="updateRunProgress"'
barkthins commented 8 years ago

I reproduce the same issue on both 1.5.x and 1.7.x. All log lines returned for my logs.

HOWEVER, if I remove all whitespace inside the single quotes the problem goes away. So I think that's that problem. Somehow whitespace seems to be affectting the result.

'this.operation!="updateRunProgress"' work correctly,

but 'this.operation != "updateRunProgress"' does not work.

@Khez in your example, I get this error if I have whitespace.

bunyan: ENOENT, open '!='
bunyan: ENOENT, open '"updateRunProgress"'
BionanoDev commented 8 years ago

Yes I was on 1.7.0

rooftopsparrow commented 8 years ago

Just to clarify from what @Khez was pointing out. When you say -c 'this.operation == "updateRunProgress"' means you only want to see all logs that have that match that operation ( notice the == ) where as -c 'this.operation != "updateRunProgress"' means you want to see every record that does not contain that operation ( notice the != ).

Also tested the filtering posted above on 1.7 and it seems to work ( at least over here :smile: )

Test:

$ bunyan --version
bunyan 1.7.1
# Should have no output ( 'this.operation != "updateRunProgress"' )
$ echo '{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}' | bunyan -c 'this.operation!="updateRunProgress"'
# Should have output ( 'this.operation == "updateRunProgress"' )
$ echo '{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}' | bunyan -c 'this.operation=="updateRunProgress"'
[2016-02-25T21:05:54.585Z]  INFO: IrysView/8424 on BNM-227: knickers update run (object=knickers.data, operation=updateRunProgress)
barkthins commented 8 years ago

@rooftopsparrow it works because there's no spaces in the javascript code. As soon as there are spaces, it doesn't work.

Khez commented 8 years ago

@barkthins thanks for showing us the error :)

You have an issue with the way shell interprets arguments, that is to say it's not really a problem just a misunderstanding on your part. Let me show you what I mean.

Start by creating a log file.

# create the log file
echo '' > /tmp/khez.log
#  add a log with the updateRunProgress operation
echo '{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}' >> /tmp/khez.log
# add a log with the updateRunProgress operation
echo '{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"khez","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}' >> /tmp/khez.log

This will have created a log file /tmp/khez.log with two operations updateRunProgress and khez

# this will show you both logs
bunyan /tmp/khez.log

# this will show you the one log
bunyan /tmp/khez.log -c 'this.operation == "updateRunProgress"'

Notice in this example that the argument to -c is wrapped in quotes. What I suspect you're doing is

bunyan /tmp/khez.log -c this.operation == "updateRunProgress"

Which indeed shows:

bunyan: ENOENT: no such file or directory, open '=='
bunyan: ENOENT: no such file or directory, open 'updateRunProgress'

What you are effectively doing in this second scenario is using this.operation as the argument to the -c option and then telling bunyan to also open == and updateRunProgress in addition to /tmp/khez.log

Just wrap your entire condition in quotes :)

@trentm I think this can safely be closed, not a bunyan issue...

barkthins commented 8 years ago

I tried wrapping them in one and two layers of quotes. In fact I followed exactly the bunyan --help directions. So it may be a shell problem, but then the directions are wrong for the most common shell out there.

I messed around with minimist to get this to work. No luck, same issue. See test code below.

I also looked help on bash, and none of that helped. So before closing this you might want to help out your poor bash users, because it's not obvious.

Example code and test runs:

#!/usr/bin/env node
var argv = require('minimist')(process.argv.slice(2));
console.log(argv);
./test.js --condition 'a b'
{ _: [ 'b' ], condition: 'a' }
./test.js --condition "a b"
{ _: [ 'b' ], condition: 'a' }
./test.js --condition `echo 'a b'`
{ _: [ 'b' ], condition: 'a' }
barkthins commented 8 years ago

I think there's an issue either with node, minimist, and your command line parser, or all three.

Escaping spaces works just great in C.

#include <stdio.h>

main(int argc, char *argv[])
{
    int i;
    printf("\n");
    for (i = 0; i < argc; i++) {
        printf("(%d): %s\n",i,argv[i]);
    }
    printf("\n");
}

And output that shows it works just fine:

gcc test.c
./a.out --condition  'a b'

(0): ./a.out
(1): --condition
(2): a b
BionanoDev commented 8 years ago

I'm not seeing a solution here that works for me. This feature is still not operational from my perspective. I am running this on my local development windows machine.

When I include spaces I get an error. When I do not include spaces I get everything.

bunyan IrysView.log -c 'operation == "constructor"' -- throws error bunyan IrysView.log -c "operation == constructor" -- throws error bunyan IrysView.log - c 'operation==constructor' -- returns everything bunayn IrysView.log -c 'operation=="constructor"' -- returns everything bunyan IrysView.log -c operation=="constructor" -- returns everything

What am I missing here?

rooftopsparrow commented 8 years ago

@BionanoDev Ah, I think this whole thread assumed you were in a unix environment not a windows environment. Perhaps you can give us a little more insight into the OS and shell you are using?

BionanoDev commented 8 years ago

I running command line on windows 7 pro.

rooftopsparrow commented 8 years ago

What happens when you do this:

bunyan -c 'this.operation == "constructor"' IrysView.log

e.g. swap the flag and the log file

BionanoDev commented 8 years ago

that returns everything

rooftopsparrow commented 8 years ago

If you can, please run this test so we can establish a baseline example.

In a file called test.log, just have one line:

{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}

What is the output of this command?

bunyan -c 'this.operation!="updateRunProgress"' test.log

vs this command?

bunyan -c 'this.operation=="updateRunProgress"' test.log

Thanks :)

BionanoDev commented 8 years ago

both commands return the single line from the test log.

rooftopsparrow commented 8 years ago

Very cool. :+1: Thanks for doing that.

Unfortunately, I do not have a windows box to help any further :disappointed: Looks like we have a real problem if someone with a windows box can also verify.

rooftopsparrow commented 8 years ago

OH! Can we try one more @BionanoDev ?

with the same log file, can you try swapping the quotes?

bunyan -c "this.operation!='updateRunProgress'" test.log

vs

bunyan -c "this.operation=='updateRunProgress'" test.log
BionanoDev commented 8 years ago

and bingo was his name.. worked. flipping the quotes was the key.

rooftopsparrow commented 8 years ago

Alright! :smile: So it turns out Windows treats single quotes differently than double quotes in a very different way than unix does ( news to me ). I found that in this SU post

Khez commented 8 years ago

@rooftopsparrow Thanks for the assist :+1:

@barkthins I tested your scenario as well... with minimist 1.2.0

# run long
./test.js and it keeps --condition 'going and going and going'
{ _: [ 'and', 'it', 'keeps' ],
  condition: 'going and going and going' }

# run short
./test.js and it keeps -c 'going and going and going'
{ _: [ 'and', 'it', 'keeps' ], c: 'going and going and going' }

So please provide us with some extra details, like node version :? Ohh and can you run $SHELL --version ?

barkthins commented 8 years ago

Okay, I found my problem. It was indeed a shell problem. I used $* instead of $@ when patching Ubuntu's stupidity of leaving ax25-node in the product which breaks all scripts that think "node" is nodejs. I'm old and even I don't remember what ax25 is for. The patch also took care of the ridicules 1Mbyte stack size default for node.

So it was all my fault. However I think the help page for bunyan should be updated to deal with shell nuances for bash and windows to avoid questions in the future. Also I recommend putting this into stack overflow, I'll be happy to vote it up.

Incorrect patch

cat `which node`
#!/bin/bash
/usr/bin/nodejs --stack-size=4096 "$*"

Correct patch

cat `which node`
#!/bin/bash
/usr/bin/nodejs --stack-size=4096 "$@"

test.js with correct patch:

./test.js --condition='this.operation != updateRunProgress'
{ _: [], condition: 'this.operation != updateRunProgress' }

and finally bunyan is happy:

echo '{"name":"IrysView","hostname":"BNM-227","pid":8424,"level":30,"object":"knickers.data","operation":"updateRunProgress","msg":"knickers update run","time":"2016-02-25T21:05:54.585Z","v":0}' | bunyan -c "this.operation != 'updateRunProgress'"
<empty>

reference: http://www.tldp.org/LDP/abs/html/internalvariables.html#APPREF