json logging improvements for puma
puma_stdout.json
Contains mostly json lines, though we do see the startup message as a non json formatted line:
=== puma startup: 2019-12-18 10:31:37 +0000 ===
puma_stderr.log
Has a mix of both json lines and non-json lines
zlib(finalizer): Zlib::GzipWriter object must be closed explicitly.
zlib(finalizer): the stream was freed prematurely.
{"severity":"INFO","timestamp":"2019-12-18T05:58:17.065Z","pid":9695,"progname":null,"message":"SnowplowTracker::AsyncEmitter initialized with endpoint https://snowplow.trx.gitlab.net/i"}
{"severity":"INFO","timestamp":"2019-12-18T05:58:17.067Z","pid":9695,"progname":null,"message":"Attempting to send 1 request"}
{"severity":"INFO","timestamp":"2019-12-18T05:58:17.067Z","pid":9695,"progname":null,"message":"Sending GET request to https://snowplow.trx.gitlab.net/i..."}
{"severity":"INFO","timestamp":"2019-12-18T05:58:17.173Z","pid":9695,"progname":null,"message":"GET request to https://snowplow.trx.gitlab.net/i finished with status code 200"}
{"severity":"INFO","timestamp":"2019-12-18T05:58:20.142Z","pid":10097,"progname":null,"message":"SnowplowTracker::AsyncEmitter initialized with endpoint https://snowplow.trx.gitlab.net/i"}
{"severity":"INFO","timestamp":"2019-12-18T05:58:20.144Z","pid":10097,"progname":null,"message":"Attempting to send 1 request"}
{"severity":"INFO","timestamp":"2019-12-18T05:58:20.144Z","pid":10097,"progname":null,"message":"Sending GET request to https://snowplow.trx.gitlab.net/i..."}
{"severity":"INFO","timestamp":"2019-12-18T05:58:20.216Z","pid":10097,"progname":null,"message":"GET request to https://snowplow.trx.gitlab.net/i finished with status code 200"}
zlib(finalizer): Zlib::GzipWriter object must be closed explicitly.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): Zlib::GzipWriter object must be closed explicitly.
zlib(finalizer): the stream was freed prematurely.
[fog][DEPRECATION] Fog::Storage::Google => #get_object_url is deprecated, use #get_object_https_url instead (["/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/fog-google-1.9.1/lib/fog/storage/google_json/requests/get_object_url.rb:8:in `get_object_url'"])
zlib(finalizer): Zlib::GzipWriter object must be closed explicitly.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): Zlib::GzipWriter object must be closed explicitly.
zlib(finalizer): the stream was freed prematurely.
{"severity":"INFO","timestamp":"2019-12-18T06:26:37.910Z","pid":19353,"progname":null,"message":"SnowplowTracker::AsyncEmitter initialized with endpoint https://snowplow.trx.gitlab.net/i"}
{"severity":"INFO","timestamp":"2019-12-18T06:26:37.912Z","pid":19353,"progname":null,"message":"Attempting to send 1 request"}
{"severity":"INFO","timestamp":"2019-12-18T06:26:37.913Z","pid":19353,"progname":null,"message":"Sending GET request to https://snowplow.trx.gitlab.net/i..."}
{"severity":"INFO","timestamp":"2019-12-18T06:26:37.998Z","pid":19353,"progname":null,"message":"GET request to https://snowplow.trx.gitlab.net/i finished with status code 200"}
{"severity":"INFO","timestamp":"2019-12-18T06:38:45.686Z","pid":24925,"progname":null,"message":"SnowplowTracker::AsyncEmitter initialized with endpoint https://snowplow.trx.gitlab.net/i"}
{"severity":"INFO","timestamp":"2019-12-18T06:38:45.688Z","pid":24925,"progname":null,"message":"Attempting to send 1 request"}
{"severity":"INFO","timestamp":"2019-12-18T06:38:45.688Z","pid":24925,"progname":null,"message":"Sending GET request to https://snowplow.trx.gitlab.net/i..."}
{"severity":"INFO","timestamp":"2019-12-18T06:38:45.794Z","pid":24925,"progname":null,"message":"GET request to https://snowplow.trx.gitlab.net/i finished with status code 200"}
{"severity":"INFO","timestamp":"2019-12-18T06:40:04.358Z","pid":28132,"progname":null,"message":"SnowplowTracker::AsyncEmitter initialized with endpoint https://snowplow.trx.gitlab.net/i"}
{"severity":"INFO","timestamp":"2019-12-18T06:40:04.363Z","pid":28132,"progname":null,"message":"Attempting to send 1 request"}
{"severity":"INFO","timestamp":"2019-12-18T06:40:04.364Z","pid":28132,"progname":null,"message":"Sending GET request to https://snowplow.trx.gitlab.net/i..."}
{"severity":"INFO","timestamp":"2019-12-18T06:40:04.451Z","pid":28132,"progname":null,"message":"GET request to https://snowplow.trx.gitlab.net/i finished with status code 200"}
zlib(finalizer): Zlib::GzipWriter object must be closed explicitly.
zlib(finalizer): the stream was freed prematurely.
=== puma startup: 2019-12-18 10:28:43 +0000 ===
=== puma startup: 2019-12-18 10:31:37 +0000 ===
It looks like we have some gem log spew that is sneaking in that we may not have control over. I don't think this is a big issue since I believe our log parser will just ignore these lines. It might be useful to wrap the startup messages in json however so they can be added to centralized logging.