Rails.logger messages lack timestamps and other context

We have lots of Rails.logger calls sprinkled in our application that are difficult to track because they don't have timestamps or any useful identifiers where they come from. For example, if I run a project import/export by hand, I saw:

irb(main):006:0> ProjectExportWorker.new.perform(u.id, proj.id)
Ignoring error converting IBM424_rtl into UTF8: U_FILE_ACCESS_ERROR
Ignoring error converting IBM424_rtl into UTF8: U_FILE_ACCESS_ERROR
Ignoring error converting IBM424_rtl into UTF8: U_FILE_ACCESS_ERROR
Ignoring error converting IBM424_rtl into UTF8: U_FILE_ACCESS_ERROR
Saved project export /var/opt/gitlab/gitlab-rails/shared/tmp/project_exports/root/gitlab-ce/work/../2017-07-20_23-22-810_root_gitlab-ce_export.tar.gz
Import/Export - Project gitlab-ce with ID: 1 successfully exported

These messages are useful, but they are easy to miss in production.log.

I propose we move to a JSON logging approach. We can do what we are doing with Geo: gitlab-org/gitlab-ee!2482

Thoughts, @grzesiek and @rymai?

I believe that using a custom structured logging mechanism is a great idea

I think it should be pretty simple to implement a custom mechanism, that would be simple and would work well for us, but there are also some existing projects like https://rocketjob.github.io/semantic_logger with a Rails gem. This is probably too much for us, but might be worth to look closer at it.

I propose we move to a JSON logging approach. We can do what we are doing with Geo: gitlab-org/gitlab-ee!2482

@stanhu That makes total sense. I'd say we should build upon what you've done in gitlab-ee!2482.

@grzesiek I played with Semantic Logger for a while and chose lograge instead. I think the issue I had with Semantic Logger was that it seemed harder to have both the regular production.log files (to avoid breaking users/support who are used to looking at it) and a separate JSON-based log file, but now that I look again I'm not sure if that's true. I also found Semantic Logger difficult to make logging go to entirely separate files (e.g. geo.log) for specific types of calls, so I ended up just implementing something simpler in gitlab-ee!2482.

changed milestone to %Next 2-3 months in gitlab-foss

Interesting related read: https://medium.com/@chimeracoder/dont-read-your-logs-13586c790202

mentioned in merge request gitlab-foss!13396 (merged)

@stanhu in your example, we'd end up with timestamps from somewhere, right? https://log.gitlap.com/app/kibana#/doc/logstash-*/logstash-2017.08.10/gitlab?id=AV3LyDqNVjAhR-bSv9t7&_g=()

Is it just because the logger you're using is a stdout logger, or are we adding these to our Rails logs at some point?

I agree on the rest, if we provide a nice way to write structured log messages, I have a bunch of places I can use that

@smcgivern Yes, those timestamps were added by rsyslog and Logstash (which actually adds the timestamp when the message was received, not when it was produced). Most customers don't have these tools, and often we get raw logs from customers.

Is it just because the logger you're using is a stdout logger, or are we adding these to our Rails logs at some point?

Yes, we're adding it to the Rails logs.

moved from gitlab-foss#35388 (moved)