| 2023-11-23 12:32:52 |
Matt Crees |
description |
The format1 regex for extracting info out of the logs does not match on some logs:
https://github.com/openstack/kolla-ansible/blob/d6844dc8958792d900663c1c51d18cd9d7b50390/ansible/roles/common/templates/conf/input/00-global.conf.j2#L19
This part of the regex assumes the request id will follow a string:
\[(\S+ req-)?((?<request_id>\S+)
This is not always the case. Has been seen in logs from Nova Compute, Cinder Backup and Cinder Volume, Neutron SRIOV NIC Agent.
Nova Compute examples, where there is no string before the request id:
fluentd.log:2023-10-06 11:14:51 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:14:51.668 7 INFO nova.compute.manager [req-f98b182f-953c-49cd-997d-79d088ae50fa - - - - -] [instance: 102722db-af5c-4843-81c9-522ab1d69021] Destroying instance with name label 'instance-000166b5' which is marked as DELETED but still present on host."
fluentd.log:2023-10-06 11:14:52 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:14:51.679 7 INFO nova.compute.manager [req-f98b182f-953c-49cd-997d-79d088ae50fa - - - - -] [instance: 102722db-af5c-4843-81c9-522ab1d69021] Terminating instance"
fluentd.log:2023-10-06 11:14:52 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:14:52.159 7 INFO nova.compute.manager [req-f98b182f-953c-49cd-997d-79d088ae50fa - - - - -] [instance: 102722db-af5c-4843-81c9-522ab1d69021] Took 0.35 seconds to destroy the instance on the hypervisor."
fluentd.log:2023-10-06 11:15:50 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:15:50.271 7 INFO nova.virt.libvirt.imagecache [req-6e500ad0-235c-42e7-9513-b1f15bca4435 - - - - -] image 91488d77-0973-49a4-bbda-aa91bdb93dfd at (/var/lib/nova/instances/_base/7e8dd7529ee4e10b530402d752fa5a0d1ad3b608): checking"
fluentd.log:2023-10-06 11:22:55 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:15:50.558 7 INFO nova.virt.libvirt.imagecache [req-6e500ad0-235c-42e7-9513-b1f15bca4435 - - - - -] Active base files: /var/lib/nova/instances/_base/7e8dd7529ee4e10b530402d752fa5a0d1ad3b608 /var/lib/nova/instances/_base/120109aad501dc6ec50027b0ada5653e57b62a24 /var/lib/nova/instances/_base/7a7b05e0cb6f21d0c75278523f86f03f3a3ee7a6 /var/lib/nova/instances/_base/e6a2ba01b54d423d33ae1762712edcb23dc1eb0b"
fluentd.log:2023-10-06 10:47:04 +0000 [warn]: #0 pattern not matched: "2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task [req-167fe5f0-4bb1-47e4-bf87-554b0f57edbf - - - - -] Error during ComputeManager._heal_instance_info_cache: oslo_messaging.exceptions.MessagingTimeout: Timed out waiting for a reply to message ID 097f3d339a0c4eacab70b872a9cafac3\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task Traceback (most recent call last):\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task File \"/var/lib/kolla/venv/lib/python3.9/site-packages/oslo_messaging/_drivers/amqpdriver.py\", line 441, in get\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task return self._queues[msg_id].get(block=True, timeout=timeout)\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task File \"/var/lib/kolla/venv/lib/python3.9/site-packages/eventlet/queue.py\", line 322, in get\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task return waiter.wait()\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task File \"/var/lib/kolla/venv/lib/python3.9/site-packages/eventlet/queue.py\", line 141, in wait\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task return get_hub().switch()\n2023-10-06 10:47:01.464 7 ERROR oslo_service.periodic_task File \"/var/lib/kolla/venv/lib/python3.9/site-packages/eventlet/hubs/hub.py\", "
Nova Compute examples where there is no request id:
2023-11-14 20:46:33 +0000 [warn]: #0 pattern not matched: "2023-11-14 20:46:33.922 7 ERROR nova.compute.manager [instance: 341b46
c8-1584-42b7-a866-2b1fe1fde093] Traceback (most recent call last):"
2023-11-14 20:46:33 +0000 [warn]: #0 pattern not matched: "2023-11-14 20:46:33.922 7 ERROR nova.compute.manager [instance: 341b46c8-1584-42b7-a866-2b1fe1fde093] self._call_wait_func(context, wait_func, volume_api, vol['id'])"
2023-11-14 20:46:33 +0000 [warn]: #0 pattern not matched: "2023-11-14 20:46:33.922 7 ERROR nova.compute.manager [instance: 341b46c8-1584-42b7-a866-2b1fe1fde093] File \"/var/lib/kolla/venv/lib64/python3.9/site-packages/nova/virt/block_device.py\", line 790, in _call_wait_func"
Cinder examples where there is no string before the request id:
fluentd.log:2023-10-06 10:43:03 +0000 [warn]: #0 pattern not matched: "2023-10-06 10:43:03.024 37 ERROR oslo_db.sqlalchemy.engines [req-19b536b0-1dbb-4039-bef0-1af6c1c3b27c - - - - -] Database connection was found disconnected; reconnecting: oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')\n[SQL: SELECT 1]\n(Background on this error at: https://sqlalche.me/e/14/e3q8)\n2023-10-06 10:43:03.024 37 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):\n2023-10-06 10:43:03.024 37 ERROR oslo_db.sqlalchemy.engines File
2023-10-06 11:38:21 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:38:20.997 7 INFO oslo_service.service [req-4633ae12-4cc3-4cdf-819e-dbc34ced7e72 - - - - -] Caught SIGTERM, stopping children"
2023-10-06 11:38:21 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:38:21.000 7 INFO oslo_service.service [req-4633ae12-4cc3-4cdf-819e-dbc34ced7e72 - - - - -] Waiting on 1 children to exit"
2023-10-06 11:38:21 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:38:21.549 37 WARNING amqp [req-4633ae12-4cc3-4cdf-819e-dbc34ced7e72 - - - - -] Received method (60, 30) during closing channel 1. This method will be ignored"
2023-10-06 11:38:25 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:38:21.565 7 INFO oslo_service.service [req-4633ae12-4cc3-4cdf-819e-dbc34ced7e72 - - - - -] Child 37 exited with status 0"
2023-10-06 11:14:46 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:14:39.662 27 WARNING oslo.service.loopingcall [req-0bf16555-f41e-49a4-86b4-2816c238386f - - - - -] Function 'cinder.service.Service.periodic_tasks' run outlasted interval by 1600.76 sec"
2023-10-06 11:23:00 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:23:00.136 37 ERROR oslo.messaging._drivers.impl_rabbit [req-a0d7648e-0b89-4fa0-a5d1-f220d2e81640 - - - - -] Failed to publish message to topic 'cinder-scheduler_fanout': : amqp.exceptions.MessageNacked"
2023-10-06 11:23:00 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:23:00.156 37 ERROR oslo.messaging._drivers.impl_rabbit [req-a0d7648e-0b89-4fa0-a5d1-f220d2e81640 - - - - -] Unable to connect to AMQP server on <ip redacted>:5671 after inf tries: : amqp.exceptions.MessageNacked"
Neutron example where there is no string before request id:
fluentd.log:2023-10-06 11:15:00 +0000 [warn]: #0 pattern not matched: "2023-10-06 11:14:49.322 7 INFO neutron.agent.securitygroups_rpc [req-d761716b-ecb7-462f-95af-a46dcf83f79e d9cc86324d95425fb880bca7953d3b82 8a0a3f9c035f4ecfa8a3eb3287251fc0 - - -] Security group member updated ['e7cdfeca-ec75-4fd3-a642-825ec528b3c2']"
This is a follow-up to this bug: https://bugs.launchpad.net/kolla-ansible/+bug/1872220 |
The format1 regex for extracting info out of the logs does not match on some logs:
https://github.com/openstack/kolla-ansible/blob/d6844dc8958792d900663c1c51d18cd9d7b50390/ansible/roles/common/templates/conf/input/00-global.conf.j2#L19
This part of the regex assumes the request id will follow a string:
\[(\S+ req-)?((?<request_id>\S+)
This is not always the case. Has been seen in logs from Nova Compute.
There is no request id:
2023-11-14 20:46:33 +0000 [warn]: #0 pattern not matched: "2023-11-14 20:46:33.922 7 ERROR nova.compute.manager [instance: 341b46
c8-1584-42b7-a866-2b1fe1fde093] Traceback (most recent call last):"
2023-11-14 20:46:33 +0000 [warn]: #0 pattern not matched: "2023-11-14 20:46:33.922 7 ERROR nova.compute.manager [instance: 341b46c8-1584-42b7-a866-2b1fe1fde093] self._call_wait_func(context, wait_func, volume_api, vol['id'])"
2023-11-14 20:46:33 +0000 [warn]: #0 pattern not matched: "2023-11-14 20:46:33.922 7 ERROR nova.compute.manager [instance: 341b46c8-1584-42b7-a866-2b1fe1fde093] File \"/var/lib/kolla/venv/lib64/python3.9/site-packages/nova/virt/block_device.py\", line 790, in _call_wait_func"
This is a follow-up to this bug: https://bugs.launchpad.net/kolla-ansible/+bug/1872220 |
|
