Move connection and API request log level to DEBUG

[FZambia]

Currently default log level is INFO. This means that every connect/disconnect and HTTP API request logged by default. I think this makes default logging too chatty. When lots of publish requests received logs look useless and a lot of work actually spent of this logging (noticed on flame graph, will try to reproduce and post picture here).

So proposal here is move those log lines to DEBUG level and write INFO level logs with aggregated information over minute - i.e how many connects/disconnects, how many requests of each type. This is maybe must be done together with #72 to show really useful information.

Any suggestions and objections are welcome.

[banks]

I can go either way on this.

On one hand I expect anyone who uses this in production to have turned logs down to ERROR so we are not "production ready" by default there.

On other hand it's nice for new users just playing to start up in foreground with default config and get feedback about what's going on for each request.

In either case turning log level up or down is not so horrible.

That said your suggestion of minutely summaries sounds cool but it's a bunch of work and some overhead and I'm not sure how useful it would be in production in practice given that user should already have metrics setup telling them that graphically in better resolution etc.

I think I sway towards leave it like it is and just document somewhere that we expect production deployments to tune it down...

[FZambia]

Also thought about the same things...There are some caveats with other INFO messages, like logging when SIGHUP received for example - it would be nice to see such messages in production when error level set. This whole levelled logging concept looks broken a bit:(

[banks]

In that case maybe make spammy stuff DEBUG.

Could even make that be the default if we like it being loud for first run users with default conf with recommendation in docks to turn it down

On 28 Jul 2016, at 15:40, Alexandr Emelin notifications@github.com wrote:

Also thought about the same things...There are some caveats with other INFO messages, like logging when SIGHUP received for example - it would be nice to see such messages when error level set. This whole levelled logging concept looks broken a bit:(

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

[FZambia]

I was wrong about such a big performance impact.. Because I used logging into terminal STDOUT when measuring first time. Just tried logging into file and running wrk (on my old macbook air 2011): 17.5k requests/sec (info) vs 19.5 requests/sec (error level). So just too chatty problem should be considered here.

Btw for someone interested in measuring on its own computer:

centrifugo --insecure_api --log_level=error --log_file=/tmp/centrifugo.log

wrk:

wrk -t10 -c10 -d10s -s post.lua --latency http://localhost:8000/api/

post.lua:

wrk.method = "POST"
wrk.body   = '{"method": "publish", "params": {"channel": "channel1", "data": "hello"}}'
wrk.headers["Content-Type"] = "application/json"

[FZambia]

Another solution - leave API requests and connections as INFO but make logs like reloading configuration on SIGHUP as critical so it will be visible even on error level. If anyone has problems with this I can add new log level (something like system) for important messages from Centrifugo.

[banks]

Calling stuff that is not an "error" condition "error" or even "warning" seems kinda hacky to me...

DEBUG for verbose per-request logging seems more sane...

[FZambia]

@banks just made pull request with this