Multiline Matching based on Same Timestamp

csobchuk · July 13, 2017, 4:13pm

Is there a means to consolidate log lines that have the same timestamp (in ms resolution) as a single line.
This occurs rather frequently with Openstack logs in oslofmt where an Error will come in first and then its traceback with each line of the traceback its own similar format until the last entry which terminates with a space after the module name. Capturing on the space after the module is not a consistent trigger and many times we will get undesired captures for the same log entry.
All of the lines have the same timestamp and I would like to place them in to the same logical entry so that if a search for a module's Error would provide all of the traceback information. This would be useful instead of having possibly two searches - one for the error and then one for the timestamp. We are presently using a time window around the searches which does provide a similar result, however, I am not sure how it will scale to a larger log set and if we will run in to similar multline issues for the same reason that multiline was pushed into filebeat from logstash (interleaved log lines). Yes, we could further filter using beats hostname, etc. but this incurs a separate step(s) for the searching as well.
I was searching for a method to capture the timestamp and then match that same timestamp in the multiline match - akin to a back-tracing memory capture. Does something like that exist so that we could match the previous timestamp as the logs are coming in to filebeat?

Example log data where the first line I want captured as a separate entry and then all the lines following until the last ERROR line to be grouped.:

2017-07-11 19:58:59.574 27578 INFO nova.osapi_compute.wsgi.server [-] 192.168.34.6 "OPTIONS / HTTP/1.0" status: 200 len: 505 time: 0.0012770
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions [req-20b287f2-07ed-482d-87c2-7a21e687ecac c4faaba556134b74930dcb16e8c2ea39 9b452af30e15452692686d0b85a832b6 - - -] Unexpected exception in API method
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 478, in wrapped
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     return f(*args, **kwargs)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 73, in wrapper
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     return func(*args, **kwargs)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/api/openstack/compute/remote_consoles.py", line 116, in get_rdp_console
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     console_type)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/compute/api.py", line 170, in wrapped
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     return func(self, context, target, *args, **kwargs)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/compute/api.py", line 150, in wrapped
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     return function(self, context, instance, *args, **kwargs)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/compute/api.py", line 2975, in get_rdp_console
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     instance=instance, console_type=console_type)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/nova/compute/rpcapi.py", line 588, in get_rdp_console
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     instance=instance, console_type=console_type)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 158, in call
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     retry=self.retry)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     timeout=timeout, retry=retry)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 470, in send
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     retry=retry)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 459, in _send
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     result = self._waiter.wait(msg_id, timeout)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 342, in wait
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     message = self.waiters.get(msg_id, timeout=timeout)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions   File "/openstack/venvs/nova-13.3.14/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 244, in get
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions     'to message ID %s' % msg_id)
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions MessagingTimeout: Timed out waiting for a reply to message ID 15051d0ef3334957945cd911b5ac0acf
2017-07-11 19:59:02.613 27578 ERROR nova.api.openstack.extensions

My existing pattern is:

  multiline:
    match: before
    negate: true
    pattern: '^[0-9]{4}-[0-1][0-9]-[0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9].[0-9]{3} [0-9]+ ERROR [A-z_.]+[[:space:]]$'

I was thinking about simplifying it to simply consolidate anything that has "ERROR" with the following multiline capture:

          multiline:
            match: after
            negate: false
            pattern: '^[0-9]{4}-[0-1][0-9]-[0-3][0-9] [0-2][0-9]:[0-5][0-9]:[0-5][0-9].[0-9]{3} [0-9]+ ERROR$'

But, I suspect that multiple sequential faults that are not related would also be captured - which I don't want to do either.

csobchuk · July 13, 2017, 8:13pm

Answering my own post. I think that I will try the following pattern and see if I run in to any issues on consecutive errors. It will also capture those that don't start with the 4 digit year (well four digits anyway).
multiline.pattern: '^[0-9]{4}.?ERROR .|^[^0-9]{4}'
multiline.negate: true
multiline.match: before

If someone does figure out a way to ensure that it is only the same timestamp lines that get consolidated I would like to hear about it as I believe that would be preferable in the long term.

steffens · July 14, 2017, 2:49pm

Sounds like you want to correlate messages based on timestamp. Correlation based on actual content is not supported by multiline.

Multiline is more about matching the 'shape' of a multiline message.

Do you have some more sample how traces look like?

Please properly format logs and config files using the </> button. Makes it more readable and preserves whitespace.

steffens · July 14, 2017, 2:52pm

I have update your original post. Is this really just one error? From formatting it looks like 2 errors, but with same timestamp.

csobchuk · July 26, 2017, 4:54pm

I missed this update for some reason it didn't notify me. It is really just one error - with several identifications for the same root cause. The very first line is just the INFO level report, the second line is the ERROR and then the traceback with all the files included.

steffens · July 27, 2017, 3:05pm

what's the actual event format. You always have the [...] on the actual log message. If so, you could match on this one. e.g.: first match time and pid, then log level followed by full class name, followed by [: multiline.pattern: '^[0-9-: ]+ (INFO|ERROR) [a-zA-Z0-9]+ \['

This will separate the INFO from the error + will separate subsequent errors (if they all start with '[' character).

You can not filter out events with multiline yet. After multiline the include/exclude_lines settings will be applied.

csobchuk · July 27, 2017, 3:58pm

Thanks Steffen. I'll give that a try. I hadn't thought about separating based on the LOGLEVEL, I would just have to add add all in to the alternation. I'll let you know how it goes.

system · August 24, 2017, 3:58pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.