Fixes #30278 - Fix missing newlines in logs

[adamruzicka]

Before:

$ exec bin/smart_proxy_dynflow_core
D, [2020-07-01T15:18:18.451524 #2415322] DEBUG -- : Using HTTP
I, [2020-07-01T15:18:18.455993 #2415322]  INFO -- : WEBrick 1.4.2
I, [2020-07-01T15:18:18.456018 #2415322]  INFO -- : ruby 2.6.3 (2019-04-16) [x86_64-linux]
D, [2020-07-01T15:18:18.456826 #2415322] DEBUG -- : Rack::Handler::WEBrick is mounted on /.
Could not open DB for dynflow at '', will keep data in memory. Restart will drop all dynflow data.Execution plan cleaner removing 0 execution plans.WEBrick::HTTPServer#start: pid=2415322 port=8008accept: 127.0.0.1:42150Rack::Handler::WEBrick is invoked.require_ssl_client_verification: skipping, non-HTTPS request127.0.0.1 - - [01/Jul/2020:15:18:23 CEST] "GET /task/count? HTTP/1.1" 404 528
close: 127.0.0.1:42150Executor heartbeatExecutor heartbeat^Cclose TCPSocket(::1, 8008)close TCPSocket(127.0.0.1, 8008)going to shutdown ...WEBrick::HTTPServer#start done.start terminating delayed_executor...start terminating throttle_limiter...start terminating executor...shutting down Core ...... Dynflow core terminated.start terminating executor dispatcher...start terminating client dispatcher...stop listening for new events...start terminating clock...%

After:

$ bundle exec bin/smart_proxy_dynflow_core
D, [2020-07-01T15:19:24.634248 #2415917] DEBUG -- : Using HTTP
I, [2020-07-01T15:19:24.638637 #2415917]  INFO -- : WEBrick 1.4.2
I, [2020-07-01T15:19:24.638665 #2415917]  INFO -- : ruby 2.6.3 (2019-04-16) [x86_64-linux]
D, [2020-07-01T15:19:24.639419 #2415917] DEBUG -- : Rack::Handler::WEBrick is mounted on /.
W, [2020-07-01T15:19:24.639492 #2415917]  WARN -- : Could not open DB for dynflow at '', will keep data in memory. Restart will drop all dynflow data.
I, [2020-07-01T15:19:24.684245 #2415917]  INFO -- dynflow: Execution plan cleaner removing 0 execution plans.
I, [2020-07-01T15:19:24.685436 #2415917]  INFO -- : WEBrick::HTTPServer#start: pid=2415917 port=8008
D, [2020-07-01T15:19:39.669295 #2415917] DEBUG -- dynflow: Executor heartbeat
D, [2020-07-01T15:19:54.672196 #2415917] DEBUG -- dynflow: Executor heartbeat
^CD, [2020-07-01T15:19:55.543972 #2415917] DEBUG -- : close TCPSocket(::1, 8008)
D, [2020-07-01T15:19:55.544132 #2415917] DEBUG -- : close TCPSocket(127.0.0.1, 8008)
I, [2020-07-01T15:19:55.544203 #2415917]  INFO -- : going to shutdown ...
I, [2020-07-01T15:19:55.544257 #2415917]  INFO -- : WEBrick::HTTPServer#start done.
I, [2020-07-01T15:19:55.545164 #2415917]  INFO -- dynflow: start terminating delayed_executor...
I, [2020-07-01T15:19:55.548561 #2415917]  INFO -- dynflow: start terminating throttle_limiter...
I, [2020-07-01T15:19:55.552315 #2415917]  INFO -- dynflow: start terminating executor...
I, [2020-07-01T15:19:55.552849 #2415917]  INFO -- dynflow: shutting down Core ...
I, [2020-07-01T15:19:55.565278 #2415917]  INFO -- dynflow: ... Dynflow core terminated.
I, [2020-07-01T15:19:55.566380 #2415917]  INFO -- dynflow: start terminating executor dispatcher...
I, [2020-07-01T15:19:55.573431 #2415917]  INFO -- dynflow: start terminating client dispatcher...
I, [2020-07-01T15:19:55.577786 #2415917]  INFO -- dynflow: stop listening for new events...
I, [2020-07-01T15:19:55.579523 #2415917]  INFO -- dynflow: start terminating clock...

This is just a temporary workaround until #61 gets in

[lzap]

Isn't better just to add newline in the formatter? And what the new logging stack has anything to do with this? Isn't this just a bug?

[adamruzicka]

Isn't better just to add newline in the formatter?

Now matter what I tried this yielded the best results. In some places I was getting a single newline for some messages and two for others, in another place I was getting 0 and 1.

And what the new logging stack has anything to do with this? Isn't this just a bug?

The bug doesn't seem to be present when running with the new logging stack.

[lzap]

Now matter what I tried this yielded the best results. In some places I was getting a single newline for some messages and two for others, in another place I was getting 0 and 1.

Cant you just "chomp" the input (that's fast operation) and add a newline?

[adamruzicka]

I could do that, but then we end up with log which has newlines, but is missing other things such as timestamps

D, [2020-07-01T17:27:55.326292 #2449942] DEBUG -- : Using HTTP
I, [2020-07-01T17:27:55.331704 #2449942]  INFO -- : WEBrick 1.4.2
I, [2020-07-01T17:27:55.331739 #2449942]  INFO -- : ruby 2.6.3 (2019-04-16) [x86_64-linux]
D, [2020-07-01T17:27:55.332479 #2449942] DEBUG -- : Rack::Handler::WEBrick is mounted on /.
Could not open DB for dynflow at '', will keep data in memory. Restart will drop all dynflow data.
Execution plan cleaner removing 0 execution plans.
WEBrick::HTTPServer#start: pid=2449942 port=8008
accept: 127.0.0.1:54256
Rack::Handler::WEBrick is invoked.
require_ssl_client_verification: skipping, non-HTTPS request
127.0.0.1 - - [01/Jul/2020:17:28:07 CEST] "GET /task/count? HTTP/1.1" 404 528
close: 127.0.0.1:54256
Executor heartbeat
^Cclose TCPSocket(::1, 8008)
close TCPSocket(127.0.0.1, 8008)
going to shutdown ...
WEBrick::HTTPServer#start done.
start terminating delayed_executor...
start terminating throttle_limiter...
start terminating executor...
shutting down Core ...
... Dynflow core terminated.
start terminating executor dispatcher...
start terminating client dispatcher...
stop listening for new events...
start terminating clock...

How about this 5b87612?

[lzap]

We have the same discussion in core - is it good to have multiline comments or not? We ended up with our own formatter which adds | character:

https://github.com/theforeman/foreman/blob/develop/lib/foreman/logging.rb#L244-L255

There is an ongoing discussion if we want to prepend also the prefix from our normal formatter. You can do that as well, although I do not like the idea as it can look weird in ElasticSearch, it is very convinient when you are grepping logs for example for session id.

[lzap]

Ping - do you like my proposal? :-)

[adamruzicka]

Sorry, this somehow slipped under my radar. Let's go with adding just | for now

[adamruzicka]

Are you suggesting we do it as part of this or do it in #61 ?

[lzap]

True I could do that during the refactoring. Let's merge this, it's better than it was.