puma stdout logs missing timestamps

version 12.6.201911291606-68d94f525c6.7a0d024dfca on canary:

puma_stdout.log

[25090] PumaWorkerKiller: Consuming 13792.85546875 mb with master and 16 workers.
[25090] PumaWorkerKiller: Consuming 13779.92578125 mb with master and 16 workers.
[25090] PumaWorkerKiller: Consuming 13796.58984375 mb with master and 16 workers.

puma_stderr.log

I, [2019-10-28T15:24:43.636722 #28569]  INFO -- : Attempting to send 1 request
I, [2019-10-28T15:24:43.637156 #28569]  INFO -- : Sending GET request to https://snowplow.trx.gitlab.net/i...
I, [2019-10-28T15:24:43.751922 #28569]  INFO -- : GET request to https://snowplow.trx.gitlab.net/i finished with status code 200

I would be helpful to have timestamp in the stdout logs for when we forward these to elasticsearch.

/cc @ayufan

Also change the puma_stdout.log and puma_stderr.log format to JSON. So it looks like:

puma_stdout.log

{"timestamp":"2019-12-04T11:17:04.399864Z","pid":47568,"message":"- Worker 0 (pid: 47608) booted, phase: 0"}
{"timestamp":"2019-12-04T11:17:23.661718Z","pid":47568,"message":"PumaWorkerKiller: Consuming 1589.1484375 mb with master and 2 workers."}

puma_stderr.log

{"severity":"INFO","timestamp":"2019-12-04T11:17:32.714769Z","pid":47609,"progname":null,"message":"SnowplowTracker::AsyncEmitter initialized with endpoint https://mocked-qingyudebug.snowplow.com/i"}
{"severity":"INFO","timestamp":"2019-12-04T11:17:32.716211Z","pid":47609,"progname":null,"message":"Attempting to send 1 request"}

Facts:

  • puma logs are from several sources: 1) Puma, 2) PumaWorkerKiller, 3)SnowplowTracker
  • Puma and PumaWorkerKiller use Puma::Events::PidFormatter.call to format their log
  • SnowplowTracker use Logger default formatter. SnowplowTracker write to STDERR which is overwritten by Puma #37920 (comment 254271123)

Solution summary:

Edited by 🤖 GitLab Bot 🤖