1036541 - Loop server logs non-json messages to stdout

Status: VERIFIED FIXED

(Hello (Loop) :: Server, defect)

Description

[Benson Wong [:mostlygeek]]

v0.9.0 adds logging of json messages to stdout for consumption by heka. Howevever, there are non-json formatted messages also going to stdout: 

When the server starts:

Server listening on http://127.0.0.1:8000

When /__heartbeat__ is hit: 
2000 'https://api.opentok.com/session/create'

When heka sees these messages it will write an error log for it. These should be cleaned up.

Comment 1

[Alexis Metaireau (:alexis)]

I had a discussion with Tarek where he was saying this wasn't a problem and heka would just ignore the non json messages.

Tarek, can you confirm? Otherwise I can of course disable non json messages when we're on production.

Comment 2

[Rémy Hubscher (:natim)]

As we said once, I think we should write the metrics on stdout and all other messages to stderr to avoid this problem as it is easier to clean stdout than stderr and that we don't care too much adding some noise to stderr.

For me it is important to keep the server starting message in the log in production to know how often circus is restarting the server or make sure there is no error after a restart.

Comment 3

[Tarek Ziadé (:tarek)]

> Tarek, can you confirm?

Yes that was confirmed by Rob. But if it's easy to clean

> I think we should write the metrics on stdout 

It's in the stdout. (console.log)

Comment 4

[Alexis Metaireau (:alexis)]

Well, writing other messages to stderr sounds weird to me if they're not errors.

Why is it easier to clean stdout rather than stderr?

Comment 5

[Rémy Hubscher (:natim)]

Because Javascript errors are automatically logged to errors.
Maybe we should let circus define a stdheka channel on the third fd for heka.

Something like:

    node loop/index.js 1>stdout 2>stderr 3>stdheka

Comment 6

[Tarek Ziadé (:tarek)]

> Why is it easier to clean stdout rather than stderr?

stderr is used for errors. if we use it for the messages, would we re-route errors in stdout ?
can we really catch all of them ? even if improbable segfaults will be in stderr afaik 

> Maybe we should let circus define a stdheka channel on the third fd for heka.

We can't use the fd 3 like that. we'd need to log to a file to do it we would need to add a rotating file handler in the node,js app, not in circus

Comment 7

[Tarek Ziadé (:tarek)]

I know we've discussed that earlier and discard it, but re-reading all the comments, I think everyone feel nervous about denaturing how the stdout/stderr work.

What if node.js emits its own heka log and make it compatible with logrotate ?

Would that work for you ?  I found: https://github.com/bpaquet/log4node 

or do you need us to do our own rotation

Comment 8

[Benson Wong [:mostlygeek]]

I think having a logging library is a good first step. winston (https://github.com/flatiron/winston) is pretty well supported now. 

Using winston you can have it transport to console (default), to a file, to loggly, etc. 

The next step would be handling rotation of logs files. Winston has a transport for that (https://github.com/flatiron/winston/pull/205) but it might be better to figure out how to get it working with log_rotate and sending nodejs a HUP/USR1 signal to reopen the log file.

Comment 9

[Benson Wong [:mostlygeek]]

Also if we are so inclined, we could write a winston transport that logs straight to heka via https://github.com/mozilla-services/heka-node

Comment 10

[Rémy Hubscher (:natim)]

Attachment: Link to Github PR — #185

Comment 11

[Alexis Metaireau (:alexis)]

Comment on attachment 8478156 [details] [review]
Link to Github PR — #185

https://github.com/mozilla-services/loop-server/commit/83468960482f230e72f6100a555649cdf839bb03

Comment 12

[James Bonacci [:jbonacci]]

OK. Thanks. Should already be out there in Stage and Production.