Filebeat 6.0 Multiline issue

Elastic Stack Beats
1

Hello.
I use multiline in filebeat prospectors for procesing error messages with python trace. Example:

    - paths:
      - "/var/log/heat/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: heat
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'

So, event should start with string, ended on something like
ERROR some.program_name Traceback (most recent call last):
and end with:
ERROR some.programe_name

And this work. But sometime filebeat send as one event multiple strings from log, doesn't matched this patterns:

{
  "@timestamp": "2017-11-28T14:05:28.803Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.0.0"
  },
  "offset": 1102398,
  "message": "2017-11-28 09:05:23.993 4898 INFO designate.policy [req-2d8937ed-8b1c-403c-8b38-f47e1e598d70 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 09:05:23.993 4898 INFO designate.policy [req-2d8
937ed-8b1c-403c-8b38-f47e1e598d70 - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-11-28 09:05:24.009 4898 INFO designate.policy [req-2d8937ed-8b1c-403c-8b38-f47e1e598d70 - - - - -] Policy che
ck succeeded for rule 'all_tenants' on target {}\n2017-11-28 09:05:24.010 4898 INFO designate.policy [req-2d8937ed-8b1c-403c-8b38-f47e1e598d70 - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-
11-28 09:05:24.024 4898 INFO designate.policy [req-2d8937ed-8b1c-403c-8b38-f47e1e598d70 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 09:05:24.024 4898 INFO designate.policy [req-2d8937ed-8b1c-403c-8b3
8-f47e1e598d70 - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}",
  "source": "/var/log/designate/central.log",
  "fields": {
    "environment": "pilot-iaas",
    "service": "designate",
    "domain": "openstack"
  },
  "beat": {
    "version": "6.0.0",
    "timezone": "-05:00",
    "name": "beat.hostname.com",
    "hostname": "beat.hostname.com"
  }
}

How i can solve it?

2

@Oldo You are right the log doesn't seems to match the pattern, also the "source" doesn't seem to match the configured path in filebeat, are they coming from another configured prospector?

"source": "/var/log/designate/central.log",

VS

      - "/var/log/heat/*.log"
3

Sure, this is other prospector, but with same multiline pattern. Here full config:

filebeat.prospectors:
    - paths:
      - "/var/log/syslog"
      - "/var/log/messages"
      - "/var/log/auth.log"
      - "/var/log/secure"
      fields:
        service: syslog
        domain: system_os
        environment: pilot-iaas
    - paths:
      - "/var/log/cron"
      fields:
        service: cron
        domain: system_os
        environment: pilot-iaas
    - paths:
      - "/var/log/nova/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: nova
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'
    - paths:
      - "/var/log/neutron/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: neutron
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'
    - paths:
      - "/var/log/cinder/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: cinder
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'
    - paths:
      - "/var/log/glance/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: glance
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'
    - paths:
      - "/var/log/heat/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: heat
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'
    - paths:
      - "/var/log/designate/*.log"
      exclude_lines: ['DEBUG']
      fields:
        service: designate
        domain: openstack
        environment: pilot-iaas
      multiline:
        match: after
        negate: true
        pattern: '(ERROR)\s[0-9a-z\._]+\s(Traceback\s\(most\srecent\scall\slast\)):$'
        flush_pattern: '\s(ERROR)\s[0-9a-z\._]+\s$'
#output.logstash:
#  hosts: ["kvmvmhost01cn:5044"]
output.file:
  path: "/var/log/beat"
  filename: filebeat.out
  codec.json:
    pretty: true
processors:
  - add_locale: ~
logging.level: warning
logging.to_files: true
logging.to_syslog: false
logging.files:
  path: /var/log/beat
  name: filebeat.log
  keepfiles: 7
  permissions: 0644
4

Here just two examples from one source:
Correct non-multiline event message:

"message": "2017-11-28 09:37:50.547 9902 INFO nova.scheduler.host_manager [req-ca2c374e-5ef2-4c8a-b904-548d2bb8e762 - - - - -] Successfully synced instances from host 'kvmvmhost09cn.domain.com'.",

Wrong multiline event message from same source:

  "message": "2017-11-28 09:38:56.280 9902 INFO nova.scheduler.host_manager [req-6c962801-8a76-4d2e-bfb3-db9892d347c1 - - - - -] Successfully synced instances from host 'kvmvmhost07cn.domain.com'.\n2017-11-28 09:39:01.105 9902 INFO nova.scheduler.host_manager [req-69d787c7-58b4-4a85-b837-9653eb412bfa - - - - -] Successfully synced instances from host 'kvmvmhost04cn.domain.com'.",
5

Could you provide some raw log samples for testing. I think it will be easier to debug this if we can see the logs that we are trying to parse. Please include some that have the python trace.

6

Sure.

2017-11-28 10:11:23.990 5098 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}
2017-11-28 10:11:23.990 5098 INFO designate.central.rpcapi [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:11:24.011 5098 INFO designate.central.rpcapi [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:11:24.027 5098 INFO designate.central.rpcapi [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:13:23.989 5098 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for rule 'all_tenants' on target {}
2017-11-28 10:13:23.990 5098 INFO designate.central.rpcapi [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:13:24.009 5098 INFO designate.central.rpcapi [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:13:24.026 5098 INFO designate.central.rpcapi [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:15:23.989 5098 INFO designate.policy [req-969264da-6ae6-4dc7-9e2c-2e7608661a5d - - - - -] Policy check succeeded for rule 'all_tenants' on target {}
2017-11-28 10:15:23.990 5098 INFO designate.central.rpcapi [req-969264da-6ae6-4dc7-9e2c-2e7608661a5d - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:15:24.011 5098 INFO designate.central.rpcapi [req-969264da-6ae6-4dc7-9e2c-2e7608661a5d - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:15:24.027 5098 INFO designate.central.rpcapi [req-969264da-6ae6-4dc7-9e2c-2e7608661a5d - - - - -] find_domains: Calling central's find_domains.
2017-11-28 10:17:23.990 5098 INFO designate.policy [req-56d7cc6d-6cc2-4e98-84ab-29ddd140175f - - - - -] Policy check succeeded for rule 'all_tenants' on target {}

Result in filebeat:

  "message": "2017-11-28 10:11:23.990 5098 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 10:11:23.990 5098 INFO designate.central.rpcapi [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] find_domains: Calling central's find_domains.\n2017-11-28 10:11:24.011 5098 INFO designate.central.rpcapi [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] find_domains: Calling cen
tral's find_domains.\n2017-11-28 10:11:24.027 5098 INFO designate.central.rpcapi [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] find_domains: Calling central's find_domains.\n2017-11-28 10:13:23.989 5098 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 10:13:23.990 5098 INFO designate.central.rpcapi [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] find_domains: Calling central's find_domains.\n2017-11-28 10:13:24.009 5098 INFO designate.central.rpcapi [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] find_domains: Calling central's find_domains.\n2017-11-28 10:13:24.026 5098 INFO designate.cent
ral.rpcapi [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] find_domains: Calling central's find_domains.",
  "message": "2017-11-28 10:11:23.996 4898 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 10:11:23.997 4898 INFO designate.policy [req-3a0
51688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-11-28 10:11:24.015 4898 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy che
ck succeeded for rule 'all_tenants' on target {}\n2017-11-28 10:11:24.015 4898 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-
11-28 10:11:24.030 4898 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 10:11:24.031 4898 INFO designate.policy [req-3a051688-3090-4720-bf0
3-33218eb590b9 - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-11-28 10:13:23.994 4898 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for ru
le 'all_tenants' on target {}\n2017-11-28 10:13:23.995 4898 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-11-28 10:13:24.013
4898 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for rule 'all_tenants' on target {}\n2017-11-28 10:13:24.013 4898 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - -
- - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}\n2017-11-28 10:13:24.029 4898 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for rule 'all_tenants' on
 target {}\n2017-11-28 10:13:24.030 4898 INFO designate.policy [req-f460652d-7dc7-4ed3-a684-61dff61a38bd - - - - -] Policy check succeeded for rule 'find_domains' on target {'tenant_id': None}"
7

Python trace messages:

2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info Traceback (most recent call last):
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/common/utils.py", line 356, in call
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     return func(*args, **kwargs)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/router_info.py", line 746, in process
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     self.process_external(agent)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/router_info.py", line 716, in process_external
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     self, existing_floating_ips, fip_statuses)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 382, in update_fip_statuses
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     self.context, ri.router_id, fip_statuses)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 112, in update_floatingip_statuses
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     router_id=router_id, fip_statuses=fip_statuses)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/common/rpc.py", line 129, in call
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     return self._original_context.call(ctxt, method, **kwargs)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 158, in call
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     retry=self.retry)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     timeout=timeout, retry=retry)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 431, in send
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     retry=retry)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 422, in _send
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     raise result
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info RemoteError: Remote error: DBDeadlock (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE floa
tingips SET status=%s WHERE floatingips.id = %s'] [parameters: ('DOWN', 'fac23f28-cb4f-417e-b05d-1a7e3c6c53cd')]
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info [u'Traceback (most recent call last):\n', u'  File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply\n    executor_call
back))\n', u'  File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch\n    executor_callback)\n', u'  File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 129, in _do_di
spatch\n    result = func(ctxt, **new_args)\n', u'  File "/usr/lib/python2.7/site-packages/neutron/api/rpc/handlers/l3_rpc.py", line 236, in update_floatingip_statuses\n    context, fip_id, constants.FLOATINGIP_STATUS_DOWN)\n', u'  File
"/usr/lib/python2.7/site-packages/neutron/db/l3_db.py", line 1051, in update_floatingip_status\n    fip_query.update({\'status\': status}, synchronize_session=False)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.p
y", line 3176, in update\n    update_op.exec_()\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1127, in exec_\n    self._do_exec()\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/per
sistence.py", line 1282, in _do_exec\n    mapper=self.mapper)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1046, in execute\n    bind, close_with_result=True).execute(clause, params or {})\n', u'  Fil
e "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute\n    return meth(self, multiparams, params)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_con
nection\n    return connection._execute_clauseelement(self, multiparams, params)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement\n    compiled_sql, distilled_params\n', u'
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context\n    context)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception\n    u
til.raise_from_cause(newraise, exc_info)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause\n    reraise(type(exception), exception, tb=exc_tb)\n', u'  File "/usr/lib64/python2.7/si
te-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context\n    context)\n', u'  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute\n    cursor.execute(statement, parameters)\n', u
'  File "/usr/lib64/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute\n    self.errorhandler(self, exc, value)\n', u'  File "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler\n
 raise errorclass, errorvalue\n', u"DBDeadlock: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE floatingips SET status=%s WHERE floatingips.id = %s'] [param
eters: ('DOWN', 'fac23f28-cb4f-417e-b05d-1a7e3c6c53cd')]\n"].
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info
8

Trace in beat message:

  "message": "2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info Traceback (most recent call last):\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-packages/neutron/commo
n/utils.py\", line 356, in call\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     return func(*args, **kwargs)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-packa
ges/neutron/agent/l3/router_info.py\", line 746, in process\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     self.process_external(agent)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/
usr/lib/python2.7/site-packages/neutron/agent/l3/router_info.py\", line 716, in process_external\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     self, existing_floating_ips, fip_statuses)\n2017-11-24 05:56:27.513 1
68308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py\", line 382, in update_fip_statuses\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     self.context, ri.rout
er_id, fip_statuses)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py\", line 112, in update_floatingip_statuses\n2017-11-24 05:56:27.513 168308 ERROR
neutron.agent.l3.router_info     router_id=router_id, fip_statuses=fip_statuses)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-packages/neutron/common/rpc.py\", line 129, in call\n201
7-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     return self._original_context.call(ctxt, method, **kwargs)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-packages/os
lo_messaging/rpc/client.py\", line 158, in call\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     retry=self.retry)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/usr/lib/python2.7/site-
packages/oslo_messaging/transport.py\", line 90, in _send\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     timeout=timeout, retry=retry)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File \"/u
sr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py\", line 431, in send\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     retry=retry)\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_i
nfo   File \"/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py\", line 422, in _send\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     raise result\n2017-11-24 05:56:27.513 168308 ERROR neutron.a
gent.l3.router_info RemoteError: Remote error: DBDeadlock (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE floatingips SET status=%s WHERE floatingips.id = %
s'] [parameters: ('DOWN', 'fac23f28-cb4f-417e-b05d-1a7e3c6c53cd')]\n2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info [u'Traceback (most recent call last):\\n', u'  File \"/usr/lib/python2.7/site-packages/oslo_messaging/r
pc/dispatcher.py\", line 142, in _dispatch_and_reply\\n    executor_callback))\\n', u'  File \"/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py\", line 186, in _dispatch\\n    executor_callback)\\n', u'  File \"/usr/lib/
python2.7/site-packages/oslo_messaging/rpc/dispatcher.py\", line 129, in _do_dispatch\\n    result = func(ctxt, **new_args)\\n', u'  File \"/usr/lib/python2.7/site-packages/neutron/api/rpc/handlers/l3_rpc.py\", line 236, in update_floati
ngip_statuses\\n    context, fip_id, constants.FLOATINGIP_STATUS_DOWN)\\n', u'  File \"/usr/lib/python2.7/site-packages/neutron/db/l3_db.py\", line 1051, in update_floatingip_status\\n    fip_query.update({\\'status\\': status}, synchron
ize_session=False)\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py\", line 3176, in update\\n    update_op.exec_()\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py\", line 1127,
in exec_\\n    self._do_exec()\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py\", line 1282, in _do_exec\\n    mapper=self.mapper)\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session
.py\", line 1046, in execute\\n    bind, close_with_result=True).execute(clause, params or {})\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py\", line 914, in execute\\n    return meth(self, multiparams, para
ms)\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py\", line 323, in _execute_on_connection\\n    return connection._execute_clauseelement(self, multiparams, params)\\n', u'  File \"/usr/lib64/python2.7/site-
packages/sqlalchemy/engine/base.py\", line 1010, in _execute_clauseelement\\n    compiled_sql, distilled_params\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py\", line 1146, in _execute_context\\n    context)
\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py\", line 1337, in _handle_dbapi_exception\\n    util.raise_from_cause(newraise, exc_info)\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/util/com
pat.py\", line 200, in raise_from_cause\\n    reraise(type(exception), exception, tb=exc_tb)\\n', u'  File \"/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py\", line 1139, in _execute_context\\n    context)\\n', u'  File \"/u
sr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py\", line 450, in do_execute\\n    cursor.execute(statement, parameters)\\n', u'  File \"/usr/lib64/python2.7/site-packages/MySQLdb/cursors.py\", line 174, in execute\\n    self
.errorhandler(self, exc, value)\\n', u'  File \"/usr/lib64/python2.7/site-packages/MySQLdb/connections.py\", line 36, in defaulterrorhandler\\n    raise errorclass, errorvalue\\n', u\"DBDeadlock: (_mysql_exceptions.OperationalError) (121
3, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE floatingips SET status=%s WHERE floatingips.id = %s'] [parameters: ('DOWN', 'fac23f28-cb4f-417e-b05d-1a7e3c6c53cd')]\\n\"].\n2017-11-24 05:56:27.513
168308 ERROR neutron.agent.l3.router_info ",
9

So these are in the same log file or different log files?

2017-11-28 10:11:23.990 5098 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}
...

and

2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info Traceback (most recent call last):
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/common/utils.py", line 356, in call
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info     return func(*args, **kwargs)
2017-11-24 05:56:27.513 168308 ERROR neutron.agent.l3.router_info   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/router_info.py", line 746, in process
...
10

This is different log files. I post my config with prospector above.

11

I see the prospector definitions, but I don't know which file name is associated with each log sample you posted.

Let's start with this log:

2017-11-28 10:11:23.990 5098 INFO designate.policy [req-3a051688-3090-4720-bf03-33218eb590b9 - - - - -] Policy check succeeded for rule 'all_tenants' on target {}

What file is this? I'm assuming /var/log/designate/central.log.

Why does the prospector have multiline settings in it? I don't see any multiline messages in the sample. Is that correct? Or does the sample just not show any?

12

Yes, in this log sample i doesn't have multiline (trace event).
Ok, i got another sample log, where correct multiline events proced as well as wrong one

13

Here is it:

2017-09-06 10:41:34.457 22898 ERROR heat.common.wsgi [-] SIGTERM received
2017-09-06 10:45:16.721 5685 WARNING oslo_config.cfg [-] Option "username" from group "keystone_authtoken" is deprecated. Use option "user-name" from group "keystone_authtoken".
2017-09-06 10:45:16.747 5685 CRITICAL heat-api [-] ConnectionRefused: Unable to establish connection to http://cloud01cn-vip:15000
2017-09-06 10:45:16.747 5685 ERROR heat-api Traceback (most recent call last):
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/bin/heat-api", line 10, in <module>
2017-09-06 10:45:16.747 5685 ERROR heat-api     sys.exit(main())
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/heat/cmd/api.py", line 51, in main
2017-09-06 10:45:16.747 5685 ERROR heat-api     app = config.load_paste_app()
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/heat/common/config.py", line 429, in load_paste_app
2017-09-06 10:45:16.747 5685 ERROR heat-api     app = wsgi.paste_deploy_app(conf_file, app_name, cfg.CONF)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/heat/common/wsgi.py", line 1102, in paste_deploy_app
2017-09-06 10:45:16.747 5685 ERROR heat-api     return deploy.loadapp("config:%s" % paste_config_file, name=app_name)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 247, in loadapp
2017-09-06 10:45:16.747 5685 ERROR heat-api     return loadobj(APP, uri, name=name, **kw)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 272, in loadobj
2017-09-06 10:45:16.747 5685 ERROR heat-api     return context.create()
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2017-09-06 10:45:16.747 5685 ERROR heat-api     return self.object_type.invoke(self)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 207, in invoke
2017-09-06 10:45:16.747 5685 ERROR heat-api     app = filter(app)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/heat/common/auth_url.py", line 76, in auth_url_filter
2017-09-06 10:45:16.747 5685 ERROR heat-api     return AuthUrlFilter(app, conf)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/heat/common/auth_url.py", line 31, in __init__
2017-09-06 10:45:16.747 5685 ERROR heat-api     self.auth_url = self._get_auth_url()
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/heat/common/auth_url.py", line 42, in _get_auth_url
2017-09-06 10:45:16.747 5685 ERROR heat-api     auth_url=cfg.CONF.clients_keystone.auth_uri)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 337, in inner
2017-09-06 10:45:16.747 5685 ERROR heat-api     return func(*args, **kwargs)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/discover.py", line 181, in __init__
2017-09-06 10:45:16.747 5685 ERROR heat-api     authenticated=authenticated)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 337, in inner
2017-09-06 10:45:16.747 5685 ERROR heat-api     return func(*args, **kwargs)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/_discover.py", line 142, in __init__
2017-09-06 10:45:16.747 5685 ERROR heat-api     authenticated=authenticated)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 337, in inner
2017-09-06 10:45:16.747 5685 ERROR heat-api     return func(*args, **kwargs)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/_discover.py", line 40, in get_version_data
2017-09-06 10:45:16.747 5685 ERROR heat-api     resp = session.get(url, headers=headers, authenticated=authenticated)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 493, in get
2017-09-06 10:45:16.747 5685 ERROR heat-api     return self.request(url, 'GET', **kwargs)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 337, in inner
2017-09-06 10:45:16.747 5685 ERROR heat-api     return func(*args, **kwargs)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 386, in request
2017-09-06 10:45:16.747 5685 ERROR heat-api     resp = send(**kwargs)
2017-09-06 10:45:16.747 5685 ERROR heat-api   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 430, in _send_request
2017-09-06 10:45:16.747 5685 ERROR heat-api     raise exceptions.ConnectionRefused(msg)
2017-09-06 10:45:16.747 5685 ERROR heat-api ConnectionRefused: Unable to establish connection to http://cloud01cn-vip:15000
2017-09-06 10:45:16.747 5685 ERROR heat-api
2017-09-06 10:49:35.720 24571 WARNING oslo_config.cfg [-] Option "username" from group "keystone_authtoken" is deprecated. Use option "user-name" from group "keystone_authtoken".
2017-09-06 10:49:35.732 24571 INFO heat.api [-] Starting Heat REST API on 0.0.0.0:8004
2017-09-06 10:49:35.732 24571 INFO heat.common.wsgi [-] Starting 16 workers
2017-09-06 10:49:35.734 24571 INFO heat.common.wsgi [-] Started child 24676
2017-09-06 10:49:35.736 24571 INFO heat.common.wsgi [-] Started child 24677
2017-09-06 10:49:35.738 24571 INFO heat.common.wsgi [-] Started child 24678
2017-09-06 10:49:35.740 24571 INFO heat.common.wsgi [-] Started child 24679
2017-09-06 10:49:35.742 24571 INFO heat.common.wsgi [-] Started child 24680

I skip some lines, its same

2017-09-06 10:49:35.765 24571 INFO heat.common.wsgi [-] Started child 24691
2017-09-06 10:50:10.407 24684 INFO oslo.messaging._drivers.impl_rabbit [req-bea9e90e-8a81-4c8d-aa8b-2c344dae3c6c af28077e387b4fdcb9542912effcb53d 3d89b4fec1df4c3d8bfd472da3567b8d] Connecting to AMQP server on 127.0.0.1:5672
2017-09-06 10:50:10.419 24684 INFO oslo.messaging._drivers.impl_rabbit [req-bea9e90e-8a81-4c8d-aa8b-2c344dae3c6c af28077e387b4fdcb9542912effcb53d 3d89b4fec1df4c3d8bfd472da3567b8d] Connected to AMQP server on 127.0.0.1:5672
2017-09-06 10:50:10.458 24684 INFO oslo.messaging._drivers.impl_rabbit [req-bea9e90e-8a81-4c8d-aa8b-2c344dae3c6c af28077e387b4fdcb9542912effcb53d 3d89b4fec1df4c3d8bfd472da3567b8d] Connecting to AMQP server on 127.0.0.1:5672
2017-09-06 10:50:10.469 24684 INFO oslo.messaging._drivers.impl_rabbit [req-bea9e90e-8a81-4c8d-aa8b-2c344dae3c6c af28077e387b4fdcb9542912effcb53d 3d89b4fec1df4c3d8bfd472da3567b8d] Connected to AMQP server on 127.0.0.1:5672
14

Just in case: Trace can be in any log file in the directories, where multiline set for prospector.
I'll try to pass it as one event cause trace can be realy huge and its headache - try to discover such errors in Kibana as half hundred messages.

15

I started debugging in the playground. How does this look: https://play.golang.org/p/soms67UFbr

filebeat.prospectors:
- paths: [input.txt]
  multiline:
    match: after
    negate: true
    pattern: '^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}.[0-9]{3} [0-9]+ \w+ [^\s]+ [^\s]'

output.console.enabled: true
16

To me all log messages seem to be of the form: <timestamp> <pid> <level> <component> [<context>] <message>. Whatever context is. Not how the multiline contents does not have the [<context>] part.

The error leading to the stack trace has level CRITICAL, but the stack-trace itself uses 'ERROR'. This looks like 2 logs being printed. Are multiple services writing to the same log file? If so there might be the risk of multiline logs and other services logs interleaving?

For now I'm assuming you want the CRITICAL + the stack-trace as one event (Sorry, I didn't read all posts). The critical 'character' is the [ : character: https://play.golang.org/p/qFjqKbJVVJ

Run the test script and check the outputs first line. All lines starting with true will be added to the multiline event.

My pattern: ^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3} \d+ \w+ [^\s]+ \[

When doing multiline, don't look at contents, but structure of logs and differences in structure. The flush_pattern is helpful on edge cases, but I don't think flush_pattern is required here.

To make the pattern somewhat more maintainable one can configure the pattern like this:

...
  multiline.pattern: '^${patterns.timestamp} ${patterns.pid} ${patterns.level} ${patterns.component} \['
...

patterns:
  timestamp: '(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3})'
  pid: '(\d+)'
  level: '(ERROR|CRITICAL|INFO|DEBUG|WARNING|TRACE)' # or use '\w+' if unsure about all levels
  component: '([^\s]+)'
2 Likes
17

Great, this should work! Thank you!

18

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