Add implicit dump until level

[rahulreddy]

Typical configuration for logging is

{
   "logLevel": "info",
   "dumpLevel": "error"
}

This would make INFO level log print twice.

Proposed solution:

When dumping logs print until (logLevel - 1) level i.e. in this example, all log entries with levels ERROR, TRACE, DEBUG will be printed when dumping the logs and not INFO.

[ghost]

I understand the point, that is to avoid logging twice one single entry.
The only thing then is the confusion it bears the risk to create. What I mean there is that if our tools show the "debug"/"trace" entries after the info entries, when the logs should be inversed, it can lead to a confusion when attempting to infer what happened from the logs.

Now, we are using the hrtime/date to order the logs in ELK, but is that enough ? I'm thinking that this counter-intuitive way to log might confuse a lot of people that are going to investigate on our behalf (DOGS, TS)

[rahulreddy]

Yes, this is something that has been bugging me as well (hence the issue to pick each of our brain) and it's a proposal, so we can discuss the options we have.

The current implementation we have is causing confusion for DOGS/TS as well. For example, when there is an error in S3, it prints two log entries

{"name":"S3","clientIP":"redacted","clientPort":37224,"httpMethod":"GET","httpURL":"/foo_object","time":1477540451068,"req_id":"22220a8facd6cadb3ba6","level":"info","message":"received request","hostname":"redacted","pid":165}
{"name":"S3","clientIP":"redacted","clientPort":37224,"httpMethod":"GET","httpURL":"/foo_object","time":1477540451068,"req_id":"22220a8facd6cadb3ba6","level":"info","message":"received request","hostname":"redacted","pid":165}

This spawned a whole confusion as to how S3 was getting the same request twice, while in reality the log lines were being printed twice.

From what I can see we could

1. dumping logs print until (logLevel - 1) level
2. only exclude floor level log entries from being dumped
3. may be write a log entry before (dumping) and after (dumping) indicating logs are being dumped

{"name":"S3","message":"received request","clientIP":"redacted","clientPort":37224,"httpMethod":"GET","httpURL":"/foo_object","time":1477540451068,"req_id":"22220a8facd6cadb3ba6","level":"info","hostname":"redacted","pid":165}
{"name":"S3","message":"dump logs start","clientIP":"redacted","clientPort":37224,"httpMethod":"GET","httpURL":"/foo_object","time":1477540451068,"req_id":"22220a8facd6cadb3ba6","level":"info","hostname":"redacted","pid":165}
{"name":"S3","message":"received request","clientIP":"redacted","clientPort":37224,"httpMethod":"GET","httpURL":"/foo_object","time":1477540451068,"req_id":"22220a8facd6cadb3ba6","level":"info","hostname":"redacted","pid":165}
...
...
{"name":"S3","message":"dump logs end","clientIP":"redacted","clientPort":37224,"httpMethod":"GET","httpURL":"/foo_object","time":1477540451068,"req_id":"22220a8facd6cadb3ba6","level":"info","hostname":"redacted","pid":165}

[ghost]

Mhhhh...
At least I'm all up for your third point. At least this will provide:
In ELK: one log entry specifying that dump Threshold was reached, and that the full history of the request is being dumped; while all entries will be ordered by timestamp (computed when actually creating the entry)
In logfile: One "going to dump" message that will actually be seen before the dumping of past entries.

Well, this makes sense to me at least, unless someone has a better suggestion.

Anyways, this behavior must be properly documented in the RequesTLogger class documentation when implementing it.