doc/admin/logging.html.textile.liquid

   1 ---
   2 layout: default
   3 navsection: admin
   4 title: Logging
   5 ...
   6
   7 {% comment %}
   8 Copyright (C) The Arvados Authors. All rights reserved.
   9
  10 SPDX-License-Identifier: CC-BY-SA-3.0
  11 {% endcomment %}
  12
  13 Most Arvados services write JSON-format structured logs to stderr, which can be parsed by any operational tools that support JSON.
  14
  15 h2. Request ids
  16
  17 Using a distributed system with several services working together sometimes makes it difficult to find the root cause of errors, as one single client request usually means several different requests to more than one service.
  18
  19 To deal with this difficulty, Arvados creates a request ID that gets carried over different services as the requests take place. This ID has a specific format and it's comprised of the prefix "@req-@" followed by 20 random alphanumeric characters:
  20
  21 <pre>req-frdyrcgdh4rau1ajiq5q</pre>
  22
  23 This ID gets propagated via an HTTP @X-Request-Id@ header, and gets logged on every service.
  24
  25 h3. API Server error reporting and logging
  26
  27 In addition to providing the request ID on every HTTP response, the API Server adds it to every error message so that all clients show enough information to the user to be able to track a particular issue. As an example, let's suppose that we get the following error when trying to create a collection using the CLI tools:
  28
  29 <pre>
  30 $ arv collection create --collection '{}'
  31 Error: #<RuntimeError: Whoops, something bad happened> (req-ku5ct9ehw0y71f1c5p79)
  32 </pre>
  33
  34 The API Server logs every request in JSON format on the @production.log@ (usually under @/var/www/arvados-api/current/log/@ when installing from packages) file, so we can retrieve more information about this by using @grep@ and @jq@ tools:
  35
  36 <pre>
  37 # grep req-ku5ct9ehw0y71f1c5p79 /var/www/arvados-api/current/log/production.log | jq .
  38 {
  39   "method": "POST",
  40   "path": "/arvados/v1/collections",
  41   "format": "json",
  42   "controller": "Arvados::V1::CollectionsController",
  43   "action": "create",
  44   "status": 422,
  45   "duration": 1.52,
  46   "view": 0.25,
  47   "db": 0,
  48   "request_id": "req-ku5ct9ehw0y71f1c5p79",
  49   "client_ipaddr": "127.0.0.1",
  50   "client_auth": "zzzzz-gj3su-jllemyj9v3s5emu",
  51   "exception": "#<RuntimeError: Whoops, something bad happened>",
  52   "exception_backtrace": "/var/www/arvados-api/current/app/controllers/arvados/v1/collections_controller.rb:43:in `create'\n/var/lib/gems/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'\n ...[snipped]",
  53   "params": {
  54     "collection": "{}",
  55     "_profile": "true",
  56     "cluster_id": "",
  57     "collection_given": "true",
  58     "ensure_unique_name": "false",
  59     "help": "false"
  60   },
  61   "@timestamp": "2019-07-15T16:40:41.726634182Z",
  62   "@version": "1",
  63   "message": "[422] POST /arvados/v1/collections (Arvados::V1::CollectionsController#create)"
  64 }
  65 </pre>
  66
  67 When logging a request that produced an error, the API Server adds @exception@ and @exception_backtrace@ keys to the JSON log. The latter includes the complete error stack trace as a string, and can be displayed in a more readable form like so:
  68
  69 <pre>
  70 # grep req-ku5ct9ehw0y71f1c5p79 /var/www/arvados-api/current/log/production.log | jq -r .exception_backtrace
  71 /var/www/arvados-api/current/app/controllers/arvados/v1/collections_controller.rb:43:in `create'
  72 /var/lib/gems/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
  73 /var/lib/gems/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:188:in `process_action'
  74 /var/lib/gems/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rendering.rb:30:in `process_action'
  75 /var/lib/gems/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
  76 /var/lib/gems/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'
  77 ...
  78 </pre>