logging.md 15.6 KB
Newer Older
1 2
---
stage: Monitor
ngaskill's avatar
ngaskill committed
3
group: Respond
4
info: To determine the technical writer assigned to the Stage/Group associated with this page, see https://about.gitlab.com/handbook/engineering/ux/technical-writing/#assignments
5 6
---

7
# GitLab Developers Guide to Logging **(FREE)**
8 9 10 11 12 13 14

[GitLab Logs](../administration/logs.md) play a critical role for both
administrators and GitLab team members to diagnose problems in the field.

## Don't use `Rails.logger`

Currently `Rails.logger` calls all get saved into `production.log`, which contains
15
a mix of Rails' logs and other calls developers have inserted in the codebase.
16 17
For example:

18
```plaintext
19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37
Started GET "/gitlabhq/yaml_db/tree/master" for 168.111.56.1 at 2015-02-12 19:34:53 +0200
Processing by Projects::TreeController#show as HTML
  Parameters: {"project_id"=>"gitlabhq/yaml_db", "id"=>"master"}

  ...

  Namespaces"."created_at" DESC, "namespaces"."id" DESC LIMIT 1 [["id", 26]]
  CACHE (0.0ms) SELECT  "members".* FROM "members"  WHERE "members"."source_type" = 'Project' AND "members"."type" IN ('ProjectMember') AND "members"."source_id" = $1 AND "members"."source_type" = $2 AND "members"."user_id" = 1  ORDER BY "members"."created_at" DESC, "members"."id" DESC LIMIT 1  [["source_id", 18], ["source_type", "Project"]]
  CACHE (0.0ms) SELECT  "members".* FROM "members"  WHERE "members"."source_type" = 'Project' AND "members".
  (1.4ms) SELECT COUNT(*) FROM "merge_requests"  WHERE "merge_requests"."target_project_id" = $1 AND ("merge_requests"."state" IN ('opened','reopened')) [["target_project_id", 18]]
  Rendered layouts/nav/_project.html.haml (28.0ms)
  Rendered layouts/_collapse_button.html.haml (0.2ms)
  Rendered layouts/_flash.html.haml (0.1ms)
  Rendered layouts/_page.html.haml (32.9ms)
Completed 200 OK in 166ms (Views: 117.4ms | ActiveRecord: 27.2ms)
```

These logs suffer from a number of problems:

38
1. They often lack timestamps or other contextual information (for example, project ID or user)
39 40
1. They may span multiple lines, which make them hard to find via Elasticsearch.
1. They lack a common structure, which make them hard to parse by log
41 42
   forwarders, such as Logstash or Fluentd. This also makes them hard to
   search.
43

44 45
Note that currently on GitLab.com, any messages in `production.log` aren't
indexed by Elasticsearch due to the sheer volume and noise. They
46 47
do end up in Google Stackdriver, but it is still harder to search for
logs there. See the [GitLab.com logging
48
documentation](https://gitlab.com/gitlab-com/runbooks/-/tree/master/docs/logging)
49 50 51 52 53 54 55 56 57 58 59 60
for more details.

## Use structured (JSON) logging

Structured logging solves these problems. Consider the example from an API request:

```json
{"time":"2018-10-29T12:49:42.123Z","severity":"INFO","duration":709.08,"db":14.59,"view":694.49,"status":200,"method":"GET","path":"/api/v4/projects","params":[{"key":"action","value":"git-upload-pack"},{"key":"changes","value":"_any"},{"key":"key_id","value":"secret"},{"key":"secret_token","value":"[FILTERED]"}],"host":"localhost","ip":"::1","ua":"Ruby","route":"/api/:version/projects","user_id":1,"username":"root","queue_duration":100.31,"gitaly_calls":30}
```

In a single line, we've included all the information that a user needs
to understand what happened: the timestamp, HTTP method and path, user
61
ID, and so on.
62 63 64 65

### How to use JSON logging

Suppose you want to log the events that happen in a project
66
importer. You want to log issues created, merge requests, and so on, as the
67 68 69
importer progresses. Here's what to do:

1. Look at [the list of GitLab Logs](../administration/logs.md) to see
70
   if your log message might belong with one of the existing log files.
71
1. If there isn't a good place, consider creating a new filename, but
72 73 74 75
   check with a maintainer if it makes sense to do so. A log file should
   make it easy for people to search pertinent logs in one place. For
   example, `geo.log` contains all logs pertaining to GitLab Geo.
   To create a new file:
76
   1. Choose a filename (for example, `importer_json.log`).
77 78 79 80 81 82 83 84
   1. Create a new subclass of `Gitlab::JsonLogger`:

      ```ruby
      module Gitlab
        module Import
          class Logger < ::Gitlab::JsonLogger
            def self.file_name_noext
              'importer'
85
            end
86 87 88 89
          end
         end
      end
      ```
90

91
   1. In your class where you want to log, you might initialize the logger as an instance variable:
92

93 94
      ```ruby
      attr_accessor :logger
95

96 97 98 99
      def initialize
        @logger = Gitlab::Import::Logger.build
      end
      ```
100

101
      Note that it's useful to memoize this because creating a new logger
102
      each time you log opens a file, adding unnecessary overhead.
103 104 105 106

1. Now insert log messages into your code. When adding logs,
   make sure to include all the context as key-value pairs:

107 108 109 110
   ```ruby
   # BAD
   logger.info("Unable to create project #{project.id}")
   ```
111

112 113 114 115
   ```ruby
   # GOOD
   logger.info(message: "Unable to create project", project_id: project.id)
   ```
116 117 118 119 120

1. Be sure to create a common base structure of your log messages. For example,
   all messages might have `current_user_id` and `project_id` to make it easier
   to search for activities by user for a given time.

121 122 123 124 125 126 127 128 129 130 131
#### Implicit schema for JSON logging

When using something like Elasticsearch to index structured logs, there is a
schema for the types of each log field (even if that schema is implicit /
inferred). It's important to be consistent with the types of your field values,
otherwise this might break the ability to search/filter on these fields, or even
cause whole log events to be dropped. While much of this section is phrased in
an Elasticsearch-specific way, the concepts should translate to many systems you
might use to index structured logs. GitLab.com uses Elasticsearch to index log
data.

132
Unless a field type is explicitly mapped, Elasticsearch infers the type from
133
the first instance of that field value it sees. Subsequent instances of that
134 135
field value with different types either fail to be indexed, or in some
cases (scalar/object conflict), the whole log line is dropped.
136 137 138 139 140

GitLab.com's logging Elasticsearch sets
[`ignore_malformed`](https://www.elastic.co/guide/en/elasticsearch/reference/current/ignore-malformed.html),
which allows documents to be indexed even when there are simpler sorts of
mapping conflict (for example, number / string), although indexing on the affected fields
141
breaks.
142 143

Examples:
144

145 146 147
```ruby
# GOOD
logger.info(message: "Import error", error_code: 1, error: "I/O failure")
148

149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171
# BAD
logger.info(message: "Import error", error: 1)
logger.info(message: "Import error", error: "I/O failure")

# WORST
logger.info(message: "Import error", error: "I/O failure")
logger.info(message: "Import error", error: { message: "I/O failure" })
```

List elements must be the same type:

```ruby
# GOOD
logger.info(a_list: ["foo", "1", "true"])

# BAD
logger.info(a_list: ["foo", 1, true])
```

Resources:

- [Elasticsearch mapping - avoiding type gotchas](https://www.elastic.co/guide/en/elasticsearch/guide/current/mapping.html#_avoiding_type_gotchas)
- [Elasticsearch mapping types]( https://www.elastic.co/guide/en/elasticsearch/reference/current/mapping-types.html)
172

173 174 175
#### Logging durations

Similar to timezones, choosing the right time unit to log can impose avoidable overhead. So, whenever
176
challenged to choose between seconds, milliseconds or any other unit, lean towards _seconds_ as float
177
(with microseconds precision, that is, `Gitlab::InstrumentationHelper::DURATION_PRECISION`).
178 179

In order to make it easier to track timings in the logs, make sure the log key has `_s` as
180
suffix and `duration` within its name (for example, `view_duration_s`).
181

182 183
## Multi-destination Logging

184
GitLab is transitioning from unstructured/plaintext logs to structured/JSON logs. During this transition period some logs are recorded in multiple formats through multi-destination logging.
185 186 187

### How to use multi-destination logging

188 189 190 191 192
Create a new logger class, inheriting from `MultiDestinationLogger` and add an
array of loggers to a `LOGGERS` constant. The loggers should be classes that
descend from `Gitlab::Logger`. For example, the user-defined loggers in the
following examples could be inheriting from `Gitlab::Logger` and
`Gitlab::JsonLogger`, respectively.
193

194 195 196 197
You must specify one of the loggers as the `primary_logger`. The
`primary_logger` is used when information about this multi-destination logger is
displayed in the application (for example, using the `Gitlab::Logger.read_latest`
method).
198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216

The following example sets one of the defined `LOGGERS` as a `primary_logger`.

```ruby
module Gitlab
  class FancyMultiLogger < Gitlab::MultiDestinationLogger
    LOGGERS = [UnstructuredLogger, StructuredLogger].freeze

    def self.loggers
      LOGGERS
    end

    def primary_logger
      UnstructuredLogger
    end
  end
end
```

217
You can now call the usual logging methods on this multi-logger. For example:
218 219 220 221 222

```ruby
FancyMultiLogger.info(message: "Information")
```

223
This message is logged by each logger registered in `FancyMultiLogger.loggers`.
224 225 226 227 228

### Passing a string or hash for logging

When passing a string or hash to a `MultiDestinationLogger`, the log lines could be formatted differently, depending on the kinds of `LOGGERS` set.

229
For example, let's partially define the loggers from the previous example:
230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252

```ruby
module Gitlab
  # Similar to AppTextLogger
  class UnstructuredLogger < Gitlab::Logger
    ...
  end

  # Similar to AppJsonLogger
  class StructuredLogger < Gitlab::JsonLogger
    ...
  end
end
```

Here are some examples of how messages would be handled by both the loggers.

1. When passing a string

```ruby
FancyMultiLogger.info("Information")

# UnstructuredLogger
253
I, [2020-01-13T18:48:49.201Z #5647]  INFO -- : Information
254 255 256 257 258 259 260 261 262 263 264

# StructuredLogger
{:severity=>"INFO", :time=>"2020-01-13T11:02:41.559Z", :correlation_id=>"b1701f7ecc4be4bcd4c2d123b214e65a", :message=>"Information"}
```

1. When passing a hash

```ruby
FancyMultiLogger.info({:message=>"This is my message", :project_id=>123})

# UnstructuredLogger
265
I, [2020-01-13T19:01:17.091Z #11056]  INFO -- : {"message"=>"Message", "project_id"=>"123"}
266 267 268 269 270

# StructuredLogger
{:severity=>"INFO", :time=>"2020-01-13T11:06:09.851Z", :correlation_id=>"d7e0886f096db9a8526a4f89da0e45f6", :message=>"This is my message", :project_id=>123}
```

271 272 273 274 275 276
### Logging context metadata (through Rails or Grape requests)

`Gitlab::ApplicationContext` stores metadata in a request
lifecycle, which can then be added to the web request
or Sidekiq logs.

277 278
The API, Rails and Sidekiq logs contain fields starting with `meta.` with this context information.

279 280
Entry points can be seen at:

281 282 283
- [`ApplicationController`](https://gitlab.com/gitlab-org/gitlab/-/blob/master/app/controllers/application_controller.rb)
- [External API](https://gitlab.com/gitlab-org/gitlab/-/blob/master/lib/api/api.rb)
- [Internal API](https://gitlab.com/gitlab-org/gitlab/-/blob/master/lib/api/internal/base.rb)
284 285 286 287 288 289 290 291 292 293

#### Adding attributes

When adding new attributes, make sure they're exposed within the context of the entry points above and:

- Pass them within the hash to the `with_context` (or `push`) method (make sure to pass a Proc if the
method or variable shouldn't be evaluated right away)
- Change `Gitlab::ApplicationContext` to accept these new values
- Make sure the new attributes are accepted at [`Labkit::Context`](https://gitlab.com/gitlab-org/labkit-ruby/blob/master/lib/labkit/context.rb)

294
See our <i class="fa fa-youtube-play youtube" aria-hidden="true"></i> [HOWTO: Use Sidekiq metadata logs](https://www.youtube.com/watch?v=_wDllvO_IY0) for further knowledge on
295 296 297 298
creating visualizations in Kibana.

The fields of the context are currently only logged for Sidekiq jobs triggered
through web requests. See the
Marcel Amirault's avatar
Marcel Amirault committed
299
[follow-up work](https://gitlab.com/gitlab-com/gl-infra/scalability/-/issues/68)
300 301
for more information.

302 303 304 305 306 307 308 309 310 311 312 313
### Logging context metadata (through workers)

Additional metadata can be attached to a worker through the use of the [`ApplicationWorker#log_extra_metadata_on_done`](https://gitlab.com/gitlab-org/gitlab/-/blob/16ecc33341a3f6b6bebdf78d863c5bce76b040d3/app/workers/concerns/application_worker.rb#L31-34)
method. Using this method adds metadata that is later logged to Kibana with the done job payload.

```ruby
class MyExampleWorker
  include ApplicationWorker

  def perform(*args)
    # Worker performs work
    # ...
314

315 316 317 318 319 320 321 322 323
    # The contents of value will appear in Kibana under `json.extra.my_example_worker.my_key`
    log_extra_metadata_on_done(:my_key, value)
  end
end
```

Please see [this example](https://gitlab.com/gitlab-org/gitlab/-/blob/16ecc33341a3f6b6bebdf78d863c5bce76b040d3/app/workers/ci/pipeline_artifacts/expire_artifacts_worker.rb#L20-21)
which logs a count of how many artifacts are destroyed per run of the `ExpireArtifactsWorker`.

324 325 326 327 328 329 330 331 332 333 334 335
## Exception Handling

It often happens that you catch the exception and want to track it.

It should be noted that manual logging of exceptions is not allowed, as:

1. Manual logged exceptions can leak confidential data,
1. Manual logged exception very often require to clean backtrace
   which reduces the boilerplate,
1. Very often manually logged exception needs to be tracked to Sentry as well,
1. Manually logged exceptions does not use `correlation_id`, which makes hard
   to pin them to request, user and context in which this exception was raised,
336
1. Manually logged exceptions often end up across
337 338
   multiple files, which increases burden scraping all logging files.

339
To avoid duplicating and having consistent behavior the `Gitlab::ErrorTracking`
340 341
provides helper methods to track exceptions:

342
1. `Gitlab::ErrorTracking.track_and_raise_exception`: this method logs,
343
   sends exception to Sentry (if configured) and re-raises the exception,
344
1. `Gitlab::ErrorTracking.track_exception`: this method only logs
345
   and sends exception to Sentry (if configured),
346
1. `Gitlab::ErrorTracking.log_exception`: this method only logs the exception,
347
   and DOES NOT send the exception to Sentry,
348
1. `Gitlab::ErrorTracking.track_and_raise_for_dev_exception`: this method logs,
349
   sends exception to Sentry (if configured) and re-raises the exception
350
  for development and test environments.
351

352 353
It is advised to only use `Gitlab::ErrorTracking.track_and_raise_exception`
and `Gitlab::ErrorTracking.track_exception` as presented on below examples.
354 355 356 357 358 359 360 361 362 363 364 365 366

Consider adding additional extra parameters to provide more context
for each tracked exception.

### Example

```ruby
class MyService < ::BaseService
  def execute
    project.perform_expensive_operation

    success
  rescue => e
367
    Gitlab::ErrorTracking.track_exception(e, project_id: project.id)
368 369 370 371 372 373 374 375 376 377 378 379 380

    error('Exception occurred')
  end
end
```

```ruby
class MyService < ::BaseService
  def execute
    project.perform_expensive_operation

    success
  rescue => e
381
    Gitlab::ErrorTracking.track_and_raise_exception(e, project_id: project.id)
382 383 384 385
  end
end
```

386 387
## Additional steps with new log files

388
1. Consider log retention settings. By default, Omnibus rotates any
389 390 391
   logs in `/var/log/gitlab/gitlab-rails/*.log` every hour and [keep at
   most 30 compressed files](https://docs.gitlab.com/omnibus/settings/logs.html#logrotate).
   On GitLab.com, that setting is only 6 compressed files. These settings should suffice
392
   for most users, but you may need to tweak them in [Omnibus GitLab](https://gitlab.com/gitlab-org/omnibus-gitlab).
393 394

1. If you add a new file, submit an issue to the [production
Marcel Amirault's avatar
Marcel Amirault committed
395
   tracker](https://gitlab.com/gitlab-com/gl-infra/production/-/issues) or
396
   a merge request to the [`gitlab_fluentd`](https://gitlab.com/gitlab-cookbooks/gitlab_fluentd)
397
   project. See [this example](https://gitlab.com/gitlab-cookbooks/gitlab_fluentd/-/merge_requests/51/diffs).
398 399

1. Be sure to update the [GitLab CE/EE documentation](../administration/logs.md) and the [GitLab.com
400
   runbooks](https://gitlab.com/gitlab-com/runbooks/blob/master/docs/logging/README.md).