1--- 2stage: Monitor 3group: Monitor 4info: 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[GitLab Logs](../administration/logs.md) play a critical role for both 10administrators and GitLab team members to diagnose problems in the field. 11 12## Don't use `Rails.logger` 13 14Currently `Rails.logger` calls all get saved into `production.log`, which contains 15a mix of Rails' logs and other calls developers have inserted in the codebase. 16For example: 17 18```plaintext 19Started GET "/gitlabhq/yaml_db/tree/master" for 168.111.56.1 at 2015-02-12 19:34:53 +0200 20Processing by Projects::TreeController#show as HTML 21 Parameters: {"project_id"=>"gitlabhq/yaml_db", "id"=>"master"} 22 23 ... 24 25 Namespaces"."created_at" DESC, "namespaces"."id" DESC LIMIT 1 [["id", 26]] 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"]] 27 CACHE (0.0ms) SELECT "members".* FROM "members" WHERE "members"."source_type" = 'Project' AND "members". 28 (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]] 29 Rendered layouts/nav/_project.html.haml (28.0ms) 30 Rendered layouts/_collapse_button.html.haml (0.2ms) 31 Rendered layouts/_flash.html.haml (0.1ms) 32 Rendered layouts/_page.html.haml (32.9ms) 33Completed 200 OK in 166ms (Views: 117.4ms | ActiveRecord: 27.2ms) 34``` 35 36These logs suffer from a number of problems: 37 381. They often lack timestamps or other contextual information (for example, project ID or user) 391. They may span multiple lines, which make them hard to find via Elasticsearch. 401. They lack a common structure, which make them hard to parse by log 41 forwarders, such as Logstash or Fluentd. This also makes them hard to 42 search. 43 44Note that currently on GitLab.com, any messages in `production.log` aren't 45indexed by Elasticsearch due to the sheer volume and noise. They 46do end up in Google Stackdriver, but it is still harder to search for 47logs there. See the [GitLab.com logging 48documentation](https://gitlab.com/gitlab-com/runbooks/-/tree/master/docs/logging) 49for more details. 50 51## Use structured (JSON) logging 52 53Structured logging solves these problems. Consider the example from an API request: 54 55```json 56{"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} 57``` 58 59In a single line, we've included all the information that a user needs 60to understand what happened: the timestamp, HTTP method and path, user 61ID, and so on. 62 63### How to use JSON logging 64 65Suppose you want to log the events that happen in a project 66importer. You want to log issues created, merge requests, and so on, as the 67importer progresses. Here's what to do: 68 691. 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. 711. If there isn't a good place, consider creating a new filename, but 72 check with a maintainer if it makes sense to do so. A log file should 73 make it easy for people to search pertinent logs in one place. For 74 example, `geo.log` contains all logs pertaining to GitLab Geo. 75 To create a new file: 76 1. Choose a filename (for example, `importer_json.log`). 77 1. Create a new subclass of `Gitlab::JsonLogger`: 78 79 ```ruby 80 module Gitlab 81 module Import 82 class Logger < ::Gitlab::JsonLogger 83 def self.file_name_noext 84 'importer' 85 end 86 end 87 end 88 end 89 ``` 90 91 1. In your class where you want to log, you might initialize the logger as an instance variable: 92 93 ```ruby 94 attr_accessor :logger 95 96 def initialize 97 @logger = Gitlab::Import::Logger.build 98 end 99 ``` 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 1041. Now insert log messages into your code. When adding logs, 105 make sure to include all the context as key-value pairs: 106 107 ```ruby 108 # BAD 109 logger.info("Unable to create project #{project.id}") 110 ``` 111 112 ```ruby 113 # GOOD 114 logger.info(message: "Unable to create project", project_id: project.id) 115 ``` 116 1171. Be sure to create a common base structure of your log messages. For example, 118 all messages might have `current_user_id` and `project_id` to make it easier 119 to search for activities by user for a given time. 120 121#### Implicit schema for JSON logging 122 123When using something like Elasticsearch to index structured logs, there is a 124schema for the types of each log field (even if that schema is implicit / 125inferred). It's important to be consistent with the types of your field values, 126otherwise this might break the ability to search/filter on these fields, or even 127cause whole log events to be dropped. While much of this section is phrased in 128an Elasticsearch-specific way, the concepts should translate to many systems you 129might use to index structured logs. GitLab.com uses Elasticsearch to index log 130data. 131 132Unless a field type is explicitly mapped, Elasticsearch infers the type from 133the first instance of that field value it sees. Subsequent instances of that 134field value with different types either fail to be indexed, or in some 135cases (scalar/object conflict), the whole log line is dropped. 136 137GitLab.com's logging Elasticsearch sets 138[`ignore_malformed`](https://www.elastic.co/guide/en/elasticsearch/reference/current/ignore-malformed.html), 139which allows documents to be indexed even when there are simpler sorts of 140mapping conflict (for example, number / string), although indexing on the affected fields 141breaks. 142 143Examples: 144 145```ruby 146# GOOD 147logger.info(message: "Import error", error_code: 1, error: "I/O failure") 148 149# BAD 150logger.info(message: "Import error", error: 1) 151logger.info(message: "Import error", error: "I/O failure") 152 153# WORST 154logger.info(message: "Import error", error: "I/O failure") 155logger.info(message: "Import error", error: { message: "I/O failure" }) 156``` 157 158List elements must be the same type: 159 160```ruby 161# GOOD 162logger.info(a_list: ["foo", "1", "true"]) 163 164# BAD 165logger.info(a_list: ["foo", 1, true]) 166``` 167 168Resources: 169 170- [Elasticsearch mapping - avoiding type gotchas](https://www.elastic.co/guide/en/elasticsearch/guide/current/mapping.html#_avoiding_type_gotchas) 171- [Elasticsearch mapping types]( https://www.elastic.co/guide/en/elasticsearch/reference/current/mapping-types.html) 172 173#### Logging durations 174 175Similar to timezones, choosing the right time unit to log can impose avoidable overhead. So, whenever 176challenged 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 179In order to make it easier to track timings in the logs, make sure the log key has `_s` as 180suffix and `duration` within its name (for example, `view_duration_s`). 181 182## Multi-destination Logging 183 184GitLab 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### How to use multi-destination logging 187 188Create a new logger class, inheriting from `MultiDestinationLogger` and add an 189array of loggers to a `LOGGERS` constant. The loggers should be classes that 190descend from `Gitlab::Logger`. For example, the user-defined loggers in the 191following examples could be inheriting from `Gitlab::Logger` and 192`Gitlab::JsonLogger`, respectively. 193 194You must specify one of the loggers as the `primary_logger`. The 195`primary_logger` is used when information about this multi-destination logger is 196displayed in the application (for example, using the `Gitlab::Logger.read_latest` 197method). 198 199The following example sets one of the defined `LOGGERS` as a `primary_logger`. 200 201```ruby 202module Gitlab 203 class FancyMultiLogger < Gitlab::MultiDestinationLogger 204 LOGGERS = [UnstructuredLogger, StructuredLogger].freeze 205 206 def self.loggers 207 LOGGERS 208 end 209 210 def primary_logger 211 UnstructuredLogger 212 end 213 end 214end 215``` 216 217You can now call the usual logging methods on this multi-logger. For example: 218 219```ruby 220FancyMultiLogger.info(message: "Information") 221``` 222 223This message is logged by each logger registered in `FancyMultiLogger.loggers`. 224 225### Passing a string or hash for logging 226 227When passing a string or hash to a `MultiDestinationLogger`, the log lines could be formatted differently, depending on the kinds of `LOGGERS` set. 228 229For example, let's partially define the loggers from the previous example: 230 231```ruby 232module Gitlab 233 # Similar to AppTextLogger 234 class UnstructuredLogger < Gitlab::Logger 235 ... 236 end 237 238 # Similar to AppJsonLogger 239 class StructuredLogger < Gitlab::JsonLogger 240 ... 241 end 242end 243``` 244 245Here are some examples of how messages would be handled by both the loggers. 246 2471. When passing a string 248 249```ruby 250FancyMultiLogger.info("Information") 251 252# UnstructuredLogger 253I, [2020-01-13T18:48:49.201Z #5647] INFO -- : Information 254 255# StructuredLogger 256{:severity=>"INFO", :time=>"2020-01-13T11:02:41.559Z", :correlation_id=>"b1701f7ecc4be4bcd4c2d123b214e65a", :message=>"Information"} 257``` 258 2591. When passing a hash 260 261```ruby 262FancyMultiLogger.info({:message=>"This is my message", :project_id=>123}) 263 264# UnstructuredLogger 265I, [2020-01-13T19:01:17.091Z #11056] INFO -- : {"message"=>"Message", "project_id"=>"123"} 266 267# StructuredLogger 268{:severity=>"INFO", :time=>"2020-01-13T11:06:09.851Z", :correlation_id=>"d7e0886f096db9a8526a4f89da0e45f6", :message=>"This is my message", :project_id=>123} 269``` 270 271### Logging context metadata (through Rails or Grape requests) 272 273`Gitlab::ApplicationContext` stores metadata in a request 274lifecycle, which can then be added to the web request 275or Sidekiq logs. 276 277The API, Rails and Sidekiq logs contain fields starting with `meta.` with this context information. 278 279Entry points can be seen at: 280 281- [`ApplicationController`](https://gitlab.com/gitlab-org/gitlab/-/blob/master/app/controllers/application_controller.rb) 282- [External API](https://gitlab.com/gitlab-org/gitlab/-/blob/master/lib/api/api.rb) 283- [Internal API](https://gitlab.com/gitlab-org/gitlab/-/blob/master/lib/api/internal/base.rb) 284 285#### Adding attributes 286 287When adding new attributes, make sure they're exposed within the context of the entry points above and: 288 289- Pass them within the hash to the `with_context` (or `push`) method (make sure to pass a Proc if the 290method or variable shouldn't be evaluated right away) 291- Change `Gitlab::ApplicationContext` to accept these new values 292- Make sure the new attributes are accepted at [`Labkit::Context`](https://gitlab.com/gitlab-org/labkit-ruby/blob/master/lib/labkit/context.rb) 293 294See 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 295creating visualizations in Kibana. 296 297The fields of the context are currently only logged for Sidekiq jobs triggered 298through web requests. See the 299[follow-up work](https://gitlab.com/gitlab-com/gl-infra/scalability/-/issues/68) 300for more information. 301 302### Logging context metadata (through workers) 303 304Additional 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) 305method. Using this method adds metadata that is later logged to Kibana with the done job payload. 306 307```ruby 308class MyExampleWorker 309 include ApplicationWorker 310 311 def perform(*args) 312 # Worker performs work 313 # ... 314 315 # The contents of value will appear in Kibana under `json.extra.my_example_worker.my_key` 316 log_extra_metadata_on_done(:my_key, value) 317 end 318end 319``` 320 321Please see [this example](https://gitlab.com/gitlab-org/gitlab/-/blob/16ecc33341a3f6b6bebdf78d863c5bce76b040d3/app/workers/ci/pipeline_artifacts/expire_artifacts_worker.rb#L20-21) 322which logs a count of how many artifacts are destroyed per run of the `ExpireArtifactsWorker`. 323 324## Exception Handling 325 326It often happens that you catch the exception and want to track it. 327 328It should be noted that manual logging of exceptions is not allowed, as: 329 3301. Manual logged exceptions can leak confidential data, 3311. Manual logged exception very often require to clean backtrace 332 which reduces the boilerplate, 3331. Very often manually logged exception needs to be tracked to Sentry as well, 3341. Manually logged exceptions does not use `correlation_id`, which makes hard 335 to pin them to request, user and context in which this exception was raised, 3361. Manually logged exceptions often end up across 337 multiple files, which increases burden scraping all logging files. 338 339To avoid duplicating and having consistent behavior the `Gitlab::ErrorTracking` 340provides helper methods to track exceptions: 341 3421. `Gitlab::ErrorTracking.track_and_raise_exception`: this method logs, 343 sends exception to Sentry (if configured) and re-raises the exception, 3441. `Gitlab::ErrorTracking.track_exception`: this method only logs 345 and sends exception to Sentry (if configured), 3461. `Gitlab::ErrorTracking.log_exception`: this method only logs the exception, 347 and DOES NOT send the exception to Sentry, 3481. `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 352It is advised to only use `Gitlab::ErrorTracking.track_and_raise_exception` 353and `Gitlab::ErrorTracking.track_exception` as presented on below examples. 354 355Consider adding additional extra parameters to provide more context 356for each tracked exception. 357 358### Example 359 360```ruby 361class MyService < ::BaseService 362 def execute 363 project.perform_expensive_operation 364 365 success 366 rescue => e 367 Gitlab::ErrorTracking.track_exception(e, project_id: project.id) 368 369 error('Exception occurred') 370 end 371end 372``` 373 374```ruby 375class MyService < ::BaseService 376 def execute 377 project.perform_expensive_operation 378 379 success 380 rescue => e 381 Gitlab::ErrorTracking.track_and_raise_exception(e, project_id: project.id) 382 end 383end 384``` 385 386## Additional steps with new log files 387 3881. Consider log retention settings. By default, Omnibus rotates any 389 logs in `/var/log/gitlab/gitlab-rails/*.log` every hour and [keep at 390 most 30 compressed files](https://docs.gitlab.com/omnibus/settings/logs.html#logrotate). 391 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 3941. If you add a new file, submit an issue to the [production 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 3991. 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). 401