Adding JSON logging to Sidekiq and Rails

Added ~168008 label

@stanhu another problem I have, and I'm not sure if this would be covered by the above links, is that backtraces are thrown out as a bunch of individual lines - but those lines lose almost all of the identifying features (because logger.info("multiple\nlines\nhere") only adds the prefix to the first line?), so you basically need to limit your search in Kibana to cover a 1s time period to catch the backtrace. Or maybe we should just say those will all be in Sentry?

I love this idea. Machine parseable logs are a must, how do we start?

@smcgivern Elastic/Logstash has some ideas how to handle multi-line errors: https://www.elastic.co/guide/en/logstash/current/multiline.html

@pcarranza I think the way to start is to see if we can get our Sidekiq logs to generate in JSON format in a separate directory or filename from the current logger.

log to 2 places then?

@pcarranza Actually, maybe we can just make a configuration option so that we don't break existing users who may rely on the current format.

Sounds like we need to get into a deprecation path.

I love the idea of being able to parse the logs and get some sense our of them.

@stanhu excellent, I think that's the place to handle it then. Just wanted to express my frustration

Added ~506179 label

I wrote up my thoughts on how we should be doing structured logging here: https://gitlab.com/gitlab-com/infrastructure/issues/1326#note_25868584

I agree that we should NOT depend on a log shipper. Having the logs on disk is immensely useful for debugging customer installations.

I've also used Filebeat extensively, and it does need to be restarted on occasion (e.g. when you change configuration).

For Rails/Sidekiq, there are a number of gems that we should evaluate:

@northrup moving your comment from the infrastructure repo to here, as per Pablo's request:

I hear what you're saying, but it also sounds like NIH to some degree. There is fluentd that solves this problem beautifully. However, I don't view this as a blocker in terms of no we're not passing JSON out today, but we ARE gathering all the logs up centrally and parsing them into a consumable format.

I think we're actually on the same page John, and I don't think it's NIH - I don't want us to invent any logging technology! :)

I think we're all in agreement that we should be logging to disk and shipping logs to an Elasticsearch cluster from disk. This leaves two decisions:

Who writes the logs to disk?

I think that the process manager / init system is responsible for persisting stdout to disk. Upstart/systemd/foreman all do this.
The alternative is the application manages it's own log files, which I'm not a fan of (due to having to deal with SIGHUPs, log rotation configuration in app config, etc etc etc)

How do we ship logs to the logging system? The main choices I can think of here are Fluentd, Filebeat and Logstash. I've used Fluentd extensively and Logstash a fair bit too.
Logstash is a memory hog and needs a JVM on your workers, I think we all agree we don't want that
Fluentd is very configurable and easy to extend. It's a Ruby project and at Gitter had quite a few issues setting it up due to Ruby versioning issues (but we were not a Ruby shop). Once it's running it's generally pretty good.
Filebeat is Go and compiles down to a single binary so is easy to deploy, but I'll defer to @stanhu's opinion on it as he's used it in anger and I haven't :)

cc @bjk-gitlab

All processes under omnibus-gitlab currently manage the log files via runit (e.g. /var/log/gitlab/gitaly/current) and logrotate. Outputting to stdout and stderr are already handled by that right now. I don't think we need to reinvent the wheel there.

I like Filebeat: it's a really lightweight agent on each of the machine, but it's only the log shipper; you still need Logstash or some aggregator. You'll also want to put some queue (e.g. Redis) in front of it to provide some resiliency. @amulvany has experience with this and can probably chime in here.

Logstash is indeed a memory hog, but it seems to be more robust than Fluentd, which is written in Ruby and doesn't have a solid multi-core/process story to support a large inflow of logs. My team had to constantly reset Fluentd whenever the CPU was pegged at 100%, got in a bad state of disconnections, or had internal buffers grow unbounded.

I think we already have a number of Logstash Grok patterns, which are already giving us structured querying for HAProxy logs, so I would vote to keep trying to make Logstash work as the aggregator.

As I read @stanhu's issue and the comments above, the main point was that we should be able to generate machine parsable logs from GitLab.

I personally love the idea of being able to structure the solution so that end users can either enable JSON logging output or disable JSON and get the current logging format.

On a different topic I don't think that we need to solve the "how do we ship the logs" question. We have historically not done this in any release and we leave it up to the user for however they wish to take log files from their machines and aggregate them. For us at GitLab we use rsyslog to catch all the output that is being written and stream it to a central logging server, however that's not a solution that we ship with GitLab, just something we use on GitLab.com. While I like Fluentd and am a champion of that product (I think they've matured over the last few years), ultimately I think that shipping and aggregation should be left to the hands of the engineers that are tasked with it and we should stick to enabling them to have either machine parsable or human readable data.

@northrup I agree. The issue here was, in fact, about creating structured, JSON logs that can be ingested easily.

Redis is able to handle large bursts of data while the Logstash server computes, also it prevents data loss if ES goes down. Personally I would have to agree with @northrup and leave this to the engineers as I think it would be unlikely to find a one-size-fits-all solution.

Regarding JSON, I think you could write a stable grok filter for the above sidekiq event (albeit I'm not sure how much it varies) though JSON would offer more versatility as the data could then be indexed by anything. This is really handy for types of data that might need to be restored (i.e. audit trail), though I can't see it being of much benefit for application logs if the grok filter works.

Cool, sounds like we're all in agreement

It's also worth pointing out that if you're logging in JSON format, Filebeat is also capable of delivering logs directly into Elasticsearch without the need for Logstash. Obviously you lose some of the ability to transform/customise the log entries before persisting them, but it also means that you have one less moving part.

If your Elasticsearch is running in cluster, it's pretty resilient to downtime and you can do rolling upgrades on the ES infrastructure to avoid maintenance outages.

Using this configuration could help keep things simple, even if just in the beginning..

Violent agreement indeed.

So far:

We all agree that it's a decision of infrastructure to implement the log shipping however they want.
We already have a solution in place for log shipping (for better or worse), so this is not a problem that needs solving now.
What's missing is the ability of the application to log in JSON format for easy consumption, and this is what we need to focus on.

We have to deal with this in multiple places in the application, which are:

unicorn/rails - the application and the api in general
gitlab-shell - ssh access
gitaly - git access
workhorse - whatever it is that it's doing these days
sidekiq - background jobs processing
nginx ?
haproxy ?
postgresql ?
redis ?
prometheus server and all the myriad of exporters that are around ?
whatever I'm forgetting in the way ?
ssh auth in general for intrusion detection (cc/ @briann )

@stanhu given that this goes across the whole application and infrastructure, should we look for someone from product to own this effort ?

cc/ @JobV @ernstvn

@pcarranza I think there should be a directive that all the components we develop should have an option to generate a structured JSON log message, and I agree this should be pushed onto the respective teams. I would suggest that we start with Unicorn/Rails (e.g. ~Platform) and see how this works out. I think it will be an incredibly useful thing.

/cc: @DouweM, @mydigitalself

Assigning to @mydigitalself for resourcing.

assigned to @mydigitalself

If Edge is doing this (which the label implies), @regisF is the PM.

assigned to @regisF

@regisF do you have a milestone in mind for this? Sounds like many teams benefit from this, and the stability of GitLab.com will benefit also.

@regisF @mydigitalself I'm trying to make sense of the connections. To what extent does this overlap with https://gitlab.com/gitlab-org/gitlab-ce/issues/29403 ?

@ernstvn I think this is most likely a sub-task of increasing observability and #29403 may need to get converted into a Meta with additional links. I'll discuss.

@ernstvn we should unassign/reassign this issue.

@JobV Can you please re-assign?

removed assignee

@stanhu @ernstvn is the issue description up to date? It seems that this is ~Platform right?

Yes, issue description is still accurate.

mentioned in commit c330b2cd

mentioned in commit 66fe8f19

mentioned in commit 831251db

mentioned in merge request !12928 (merged)

The Geo team is in search of a good structured logging system. I evaluated a number of gems out there, and it seems there are a lot out there with different focuses. For logging Rails views, I think lograge has the right approach for summarizing a single endpoint in a line. !12928 (merged) introduces a separate log file that can easily be ingested by Logstash. Note I looked at semantic_logger and logstasher. I think logstasher may work, but lograge seems better maintained for Rails 5.

Logging Sidekiq events is a different beast. There is some discussion here, but as far as I can tell there are two main gems:

https://github.com/Springest/Sidekiq-Logging-JSON: Uses the Sidekiq logging framework. Provides basic information, not everything in the structured logs.
https://github.com/iMacTia/sidekiq-logstash: Uses a Sidekiq middleware to log the full context of the job. The output is nice, but I'm concerned about the overhead in parsing JSON data repeatedly inside a middleware: https://github.com/iMacTia/sidekiq-logstash/blob/master/lib/sidekiq/logging/shared.rb#L7

However, as far as I can tell, lograge and logstasher aren't meant to log arbitrary messages (e.g. Rails.logger.info "foobar"); they are meant to handle the Rails request logs. I think we'll want to use something like LogstashLogger instead.

@stanhu It probably won't affect your decision, but at least for GitLab internal use the plan is to move away from Logstash towards Fluentd.

@briann Oh, right. It looks like Fluentd recommends using Lograge in JSON mode: http://www.fluentd.org/datasources/rails It sounds like we can standardize on just pure JSON, since the Logstash format just adds a few fields that aren't really necessary.

https://github.com/fluent/fluent-logger-ruby and https://github.com/actindi/act-fluent-logger-rails look more interesting now as just a simple substitute for Rails.logger.

Although it always seems odd to me that Fluentd recommends using JSON mode while saying that if you are using Elasticsearch, use a plugin that generates Logstash-compatible data. Fluentd has a tendency to use a lot of CPU doing JSON parsing and unparsing, so I think we're better off just sticking with Logstash format.

@stanhu we’re actusllly talking about a hybrid where the host only runs fluent bit and dedicated aggregators run fluentd http://fluentbit.io/documentation/0.11/about/fluentd_and_fluentbit.html

@northrup Yes, I know, but if you see the instructions in http://www.fluentd.org/datasources/rails, you'll see the configuration as such:

<match rails>
  type elasticsearch
  host <YOUR_HOST>
  port <YOUR_PORT>
  logstash_format true
  # other options...
</match>

The Elasticsearch Fluentd plug-in augments whatever fields are missing (e.g. @timestamp) from the JSON data to ensure Elasticsearch is happy.

mentioned in commit 9e265080

mentioned in commit e2b1c16a

Is there this issue on any roadmap? Or is some workaround possible?

There has been some progress made: production_json.log and api_json.log. See https://docs.gitlab.com/ee/administration/logs.html.

This is an old issue but I would like to re-animate it as we are now looking at logging for the gcp migration as well as deprecating the existing logstash configuration in favor of fluentd across all environments.

Where we have JSON Logging

gitaly
production_json
api_json

Where we want JSON logging

sidekiq / sidekiq_cluster - this issue?
gitlab-shell - gitlab-shell#124 (closed)
gitlab-workhorse - gitlab-workhorse#157 (closed)

Other places?

postgres? http://paquier.xyz/postgresql-2/postgres-logs-json.markdown/
redis? - probably not
unicorn? - probably not going to be easy, https://stackoverflow.com/questions/48334894/custom-log-format-for-unicorn
pgbouncer? - probably not

We can write fluentd regex parsers but it would be much better to have a more standardized approach to logging. I would like to see at least sidekiq and the golang projects add support in the shortterm if it is doable.

@jarv @_stark is working on the postgres structured logging: see https://gitlab.com/gitlab-com/infrastructure/issues/3444

Regarding gitlab-workhorse structured logging, @pchojnacki created gitlab-workhorse!120 (closed) over a year ago. I left a question on the MR about finishing it off: gitlab-workhorse!120 (comment 60315609)

@jarv for the items which currently don't have structured logging (and some which possibly never will), there's nothing blocking us from simply shipping the logs as text (as they are right now), right? For example, there's no urgent need for Redis logs to be parsed in a structured manner is there?

@andrewn is there any way to exclude such logs? Whenever I'm using gitlab in docker with gelf log driver and graylog for central logging I get an internal log file in graylog bloated with errors about message formatting - more about the issue https://community.graylog.org/t/internal-logs-filling-after-update-to-2-3-1/2609

added production request label

added backend label

mentioned in issue gitlab-com/migration#230 (closed)

@jarv for the items which currently don't have structured logging (and some which possibly never will), there's nothing blocking us from simply shipping the logs as text (as they are right now), right? For example, there's no urgent need for Redis logs to be parsed in a structured manner is there?

Brought up in gitlab-com/migration#230 (comment 61913338) that the logging for sidekiq really needs improvement, even if we can't immediately support structured logging.

Is a new issue needed that is specific to supporting structured logging for sidekiq? gitlab-com/migration#230 (closed)

Is there any chance that https://gitlab.com/gitlab-org/gitlab-ce/issues/20060#note_35211900 can be picked up? If not we are going to need to come up with something else for sidekiq log management.

I did some investigation here for Sidekiq JSON logging, and the existing gems don't quite do what we need. I think the best approach is to create our own Sidekiq middleware and logger based on the work done on the existing gems out there.

A. https://github.com/iMacTia/sidekiq-logstash

Good: The JSON includes the JID as independent fields.
Good: It supports filtering of parameters if we so desire.
Bad: It depends on an unmaintained logstash-event gem.
Bad: It doesn't log when a job starts: https://github.com/iMacTia/sidekiq-logstash/issues/4

The JSON output looks like:

{"queue":"cronjob:update_all_mirrors","args":[],"class":"UpdateAllMirrorsWorker","retry":false,"queue_namespace":"cronjob","jid":"d67f19de0e576045638f9a19","created_at":"2018-04-01T04:44:19.964Z","enqueued_at":"2018-04-01T04:44:19.965Z","pid":2740,"duration":0.086,"message":"UpdateAllMirrorsWorker JID-d67f19de0e576045638f9a19: done: 0.086 sec","job_status":"done","completed_at":"2018-04-01T04:44:20.052Z","@timestamp":"2018-04-01T04:44:20.052Z","@version":"1"}

B. https://github.com/Springest/Sidekiq-Logging-JSON

Good: Not much code, one single file that extends Sidekiq's logger: https://github.com/Springest/Sidekiq-Logging-JSON/blob/master/lib/sidekiq/logging/json.rb.
Bad: Doesn't log the arguments of the job. Unlike sidekiq-logstash, it doesn't insert itself as a Sidekiq middleware to get this.
Bad: JSON doesn't include JID as a parsed field; the full Sidekiq context is included, but I like the idea of being able to search jid: by itself.

Sample JSON output:

{"@timestamp":"2018-04-01T04:45:31Z","@fields":{"pid":49745,"tid":"TID-ovjvlo58w","context":" PagesDomainVerificationCronWorker JID-c7ec5ca89a393b85cd34390c","program_name":null,"worker":"PagesDomainVerificationCronWorker"},"@type":"sidekiq","@status":"start","@severity":"INFO","@run_time":null,"@message":"start"}
{"@timestamp":"2018-04-01T04:45:32Z","@fields":{"pid":49745,"tid":"TID-ovjvlo58w","context":" PagesDomainVerificationCronWorker JID-c7ec5ca89a393b85cd34390c","program_name":null,"worker":"PagesDomainVerificationCronWorker"},"@type":"sidekiq","@status":"done","@severity":"INFO","@run_time":0.012,"@message":"done: 0.012 sec"}

Other issues (easily fixed)

The Sidekiq metrics exporter in https://gitlab.com/gitlab-org/gitlab-ce/blob/master/lib/gitlab/metrics/sidekiq_metrics_exporter.rb#L20 also pollutes the logs with WEBrick output. We should move this to another log file: http://ruby-doc.org/stdlib-2.1.0/libdoc/webrick/rdoc/WEBrick.html

We'll want to disable our Gitlab::SidekiqMiddleware::ArgumentsLogger when using a JSON logger since we should have this information.

mentioned in merge request !18121 (merged)

I think I got https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/18121/diffs working, but need to add tests.

mentioned in commit def15c1d

mentioned in commit c0f87a21

mentioned in merge request !18127 (merged)

assigned to @stanhu

mentioned in commit 435396ba

mentioned in commit 05e1cbc4

changed milestone to %10.7

changed the description

mentioned in commit c0be8bc7

mentioned in commit d5b3f8a2

mentioned in commit fd2997c5

mentioned in commit 442ec6b8

mentioned in commit 6415ac9e

closed via merge request !18121 (merged)

mentioned in commit b15dd5df

mentioned in issue gitlab#199449

mentioned in issue gitlab#208922 (closed)

Adding JSON logging to Sidekiq and Rails

Designs

Child items ...

Activity

Where we have JSON Logging

Where we want JSON logging

Other places?

Other issues (easily fixed)