Catch multiline traceback from Odoo logs

yamaryldahl · June 11, 2023, 8:17pm

Hi,

A regular log line from Odoo looks like this:

2023-06-11 19:59:16,264 1 INFO db_tmp werkzeug: 192.168.32.1 - - [11/Jun/2023 19:59:16] "GET /web/assets/190-796b097/web.assets_common_minimal.min.js HTTP/1.0" 404 - 3 0.001 0.002

Which is easy to parse in Loki with the following regex:

(?P<datetime>.+ .+) (?P<userid>\d+) (?P<level>\w+) (?P<database>[a-zA-Z0-9_?]+) (?P<process>[a-zA-Z\._]+): (?P<message>.*)

Now a traceback looks like this:

2023-06-11 19:59:16,277 1 INFO db_tmp odoo.addons.base.models.ir_attachment: _read_file reading /var/lib/odoo/.local/share/Odoo/filestore/db_tmp/0e/0ee951439c6eb9f6df65166aa4dda9b8351ecd0e 
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/odoo/api.py", line 886, in get
    return field_cache[record._ids[0]]
KeyError: 191

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/odoo/fields.py", line 1082, in __get__
    value = env.cache.get(record, self)
  File "/usr/lib/python3/dist-packages/odoo/api.py", line 889, in get
    raise CacheMiss(record, field)
odoo.exceptions.CacheMiss: 'ir.attachment(191,).datas'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/odoo/api.py", line 886, in get
    return field_cache[record._ids[0]]
KeyError: 191

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/odoo/fields.py", line 1082, in __get__
    value = env.cache.get(record, self)
  File "/usr/lib/python3/dist-packages/odoo/api.py", line 889, in get
    raise CacheMiss(record, field)
odoo.exceptions.CacheMiss: 'ir.attachment(191,).raw'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/odoo/addons/base/models/ir_attachment.py", line 119, in _file_read
    with open(full_path, 'rb') as f:
FileNotFoundError: [Errno 2] No such file or directory: '/var/lib/odoo/.local/share/Odoo/filestore/db_tmp/0e/0ee951439c6eb9f6df65166aa4dda9b8351ecd0e'

Apparently this aggregation can only be done via the Promtail configuration.

Of course I read the documentation here: https://grafana.com/docs/loki/latest/clients/promtail/stages/multiline/

Then I tried this configuration which doesn’t aggregate anything:

- job_name: odoo
  pipeline_stages:
  - multiline:
      firstline: '^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{1,3}'
      max_wait_time: 3s
      max_lines: 500
  - regex: 
      expression: '^(?P<datetime>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{1,3})(?P<message>(?s:.*))$'
  - timestamp:
      source: datetime
      format: "2006-01-02 15:04:05,999999999Z"

I tried with various other values for these parameters, quite randomly, to no avail.

Based on the log sample I showed above, can anybody point me in the right direction.

Thanks a lot.

tonyswumac · June 12, 2023, 3:52pm

I haven’t done a lot of multi-line logs, so my recommendation may be a bit off here.

The multiline configuration in promtail is not for aggregation. It is for promtail to parse multiple lines of logs and consider them one single log line instead of multiple. This generally results in cleaner log in Loki, and potentially easier to parse (although I’ll admit I haven’t really looked into parsing multi-line logs).

Consider your example:

2023-06-11 19:59:16,277 1 INFO db_tmp odoo.addons.base.models.ir_attachment: _read_file reading /var/lib/odoo/.local/share/Odoo/filestore/db_tmp/0e/0ee951439c6eb9f6df65166aa4dda9b8351ecd0e 
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/odoo/api.py", line 886, in get
    return field_cache[record._ids[0]]
KeyError: 191

Without multi-line configuration, it’ll land in Loki like this ([TIMESTAMP] being the time stamp assigned to log line):

[2023-06-11 19:59:16] 2023-06-11 19:59:16,277 1 INFO db_tmp odoo.addons.base.models.ir_attachment: _read_file reading /var/lib/odoo/.local/share/Odoo/filestore/db_tmp/0e/0ee951439c6eb9f6df65166aa4dda9b8351ecd0e 
[2023-06-11 19:59:16] Traceback (most recent call last):
[2023-06-11 19:59:16]   File "/usr/lib/python3/dist-packages/odoo/api.py", line 886, in get
[2023-06-11 19:59:16]     return field_cache[record._ids[0]]
[2023-06-11 19:59:16] KeyError: 191

With multi-line configuration it’ll land as one log line like this:

[2023-06-11 19:59:16] 2023-06-11 19:59:16,277 1 INFO db_tmp odoo.addons.base.models.ir_attachment: _read_file reading /var/lib/odoo/.local/share/Odoo/filestore/db_tmp/0e/0ee951439c6eb9f6df65166aa4dda9b8351ecd0e 
  Traceback (most recent call last):
   File "/usr/lib/python3/dist-packages/odoo/api.py", line 886, in get
     return field_cache[record._ids[0]]
 KeyError: 191

You’d still need to figure out how to parse it in Loki. Hopefully that makes sense.

yamaryldahl · June 12, 2023, 4:43pm

Thank you for your answer!

I suppose “aggregate” wasn’t the appropriate term.

As you can see in my sample, there actually are multiple related tracebacks one after the other, giving a comprehensive information about the issue. What I’d like to have is indeed one log line containing the whole thing, like you showed in your last snippet. My end goal is to allow users to search for some keywords and then be able to read the whole traceback in one cell. Ideally the traceback should be formatted the same way it was in the original log.

With the configuration I showed, I don’t get the result you show in the snippet. What I get is the following (explorer view):

Which leads me to believe my config file is totally wrong…

yamaryldahl · August 8, 2023, 6:39pm

I gave it another try today as I really need this feature to work if I want to convince the department to use Grafana.

I managed to get the full stack trace in a single line with this config:

- job_name: odoo
  pipeline_stages:
  - multiline:
      firstline: '\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{1,3}'
      max_wait_time: 3s
      max_lines: 500

But when I inspect the cell I see a list of json log lines, which is unreadable. How can I clean this to only see the stacktrace without all the json log label?

tonyswumac · August 8, 2023, 6:55pm

That looks like Docker logs to me. Try using the docker stage in your pipelines (see Configuration | Grafana Loki documentation).

yamaryldahl · August 8, 2023, 7:05pm

Worked like a charm, thank you very much!