Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Compute nodes always showing MessagingTimeOut errors

Hello,

I have an OpenStack test cluster with 10 compute nodes and 1 controller node. Everything is fine I can launch instance, migrate, attach volumes, snapshot instances all is fine. But in all my compute nodes I can see MessagingTimeout errors regularly. It clearly reflect in my rabitmq logs also. I can also see DB exceeded retry limit error in nova-conductor.log. But after couple of seconds everything will be back and fine. And all the services are seems to be running fine I can launch instances. Iam really curious to know why this happens. Any help is really appreciated.

/var/log/nova/nova-compute.log

 2017-11-14 08:53:09.812 42708 WARNING nova.scheduler.client.report [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] No authentication information found for placement API. Placement is optional in Newton, but required in Ocata. Please enable the placement service before upgrading.
2017-11-14 08:53:09.813 42708 WARNING nova.scheduler.client.report [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Unable to refresh my resource provider record
2017-11-14 08:53:09.814 42708 INFO nova.compute.resource_tracker [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Compute_service record updated for server-1:server-1
2017-11-14 08:53:18.786 42708 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 35.71 sec
2017-11-14 08:53:27.172 42708 INFO nova.compute.resource_tracker [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Auditing locally available compute resources for node server-1
2017-11-14 08:54:18.798 42708 WARNING nova.servicegroup.drivers.db [-] Lost connection to nova-conductor for reporting service status.
2017-11-14 08:54:18.800 42708 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 50.01 sec
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Error updating resources for node server-1.
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager Traceback (most recent call last):
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 6442, in update_available_resource_for_node
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     rt.update_available_resource(context)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/compute/resource_tracker.py", line 511, in update_available_resource
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     resources = self.driver.get_available_resource(self.nodename)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 5385, in get_available_resource
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     disk_over_committed = self._get_disk_over_committed_size_total()
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 6955, in _get_disk_over_committed_size_total
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     ctx, filters, use_slave=True)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 177, in wrapper
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     args, kwargs)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 236, in object_class_action_versions
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     args=args, kwargs=kwargs)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     retry=self.retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 97, in _send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     timeout=timeout, retry=retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     retry=retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     result = self._waiter.wait(msg_id, timeout)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     message = self.waiters.get(msg_id, timeout=timeout)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     'to message ID %s' % msg_id)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager MessagingTimeout: Timed out waiting for a reply to message ID c88f27cc448946d2b44f0d86e340d264
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager
2017-11-14 08:54:42.692 42708 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : c88f27cc448946d2b44f0d86e340d264
2017-11-14 08:54:42.694 42708 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : 32111e339c754ca49168143e48315240
2017-11-14 08:55:18.808 42708 ERROR oslo.messaging._drivers.impl_rabbit [-] [56e6680f-7271-4173-a63d-835ac1ad5554] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 37740
2017-11-14 08:55:21.079 42708 INFO oslo.messaging._drivers.impl_rabbit [-] [56e6680f-7271-4173-a63d-835ac1ad5554] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 38502.
2017-11-14 08:56:10.431 42708 ERROR oslo.messaging._drivers.impl_rabbit [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] [e2c8c98f-f6a5-4205-bd40-e74f341a053e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 59516
2017-11-14 08:56:15.183 42708 INFO oslo.messaging._drivers.impl_rabbit [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] [e2c8c98f-f6a5-4205-bd40-e74f341a053e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 38506.

/var/log/nova/nova-conductor.log

    2017-11-14 08:53:06.765 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 96.83 sec
    2017-11-14 08:53:47.772 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 133.39 sec
    2017-11-14 08:54:01.777 5041 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 151.77 sec
    2017-11-14 08:54:01.780 5064 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 151.86 sec
    2017-11-14 08:54:18.825 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 117.98 sec
    2017-11-14 08:54:43.251 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.48 sec
    2017-11-14 08:54:50.804 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 95.99 sec
    2017-11-14 08:54:52.779 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 95.37 sec
    2017-11-14 08:55:00.477 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.54 sec
    2017-11-14 08:55:00.785 5035 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.87 sec
    2017-11-14 08:55:05.733 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 36.91 sec
    2017-11-14 08:55:17.718 5049 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 205.95 sec
    2017-11-14 08:55:16.186 5046 ERROR oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 50726
    2017-11-14 08:55:21.789 5070 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.02 sec
    2017-11-14 08:55:23.619 5046 INFO oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39830.
    2017-11-14 08:55:27.893 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 34.64 sec
    2017-11-14 08:55:28.458 5070 ERROR oslo.messaging._drivers.impl_rabbit [req-5b6db315-80e7-407a-8133-569aa84ae596 - - - - -] [a35e377f-a845-4e14-b180-efbf7ca8f57e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 50520
    2017-11-14 08:55:34.358 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 33.55 sec
    2017-11-14 08:55:35.334 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 32.55 sec
    2017-11-14 08:55:35.343 5054 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:35.345 5074 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:35.346 5039 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:31.893 5056 ERROR oslo.messaging._drivers.impl_rabbit [req-655a8997-62ab-48c4-a2b5-aaec3e348429 - - - - -] [437dcd32-d543-4d59-9a54-8a4b78726791] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56288
    2017-11-14 08:55:37.841 5041 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 85.47 sec
    2017-11-14 08:55:37.843 5064 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 85.47 sec
    2017-11-14 08:55:36.543 5077 ERROR oslo.messaging._drivers.impl_rabbit [req-d9229816-d734-47c9-b3ca-388ab66cd74c - - - - -] [999eeb6b-c28c-4cbf-bee8-1ca203101873] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56310
    2017-11-14 08:55:39.237 5070 INFO oslo.messaging._drivers.impl_rabbit [req-5b6db315-80e7-407a-8133-569aa84ae596 - - - - -] [a35e377f-a845-4e14-b180-efbf7ca8f57e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39836.
    2017-11-14 08:55:39.276 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 28.80 sec
    2017-11-14 08:55:39.323 5077 ERROR oslo.messaging._drivers.impl_rabbit [req-7e828ed0-b384-4ed6-9b13-b5caccb11dad - - - - -] [af728466-2a99-4d7a-8d8a-b486dd2775fa] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44186
    2017-11-14 08:55:41.200 5056 INFO oslo.messaging._drivers.impl_rabbit [req-655a8997-62ab-48c4-a2b5-aaec3e348429 - - - - -] [437dcd32-d543-4d59-9a54-8a4b78726791] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39838.
    2017-11-14 08:55:44.040 5046 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 254.14 sec
    2017-11-14 08:55:46.493 5036 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.56 sec
    2017-11-14 08:55:46.504 5060 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.57 sec
    2017-11-14 08:55:46.515 5071 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.51 sec
    2017-11-14 08:55:46.524 5051 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.52 sec
    2017-11-14 08:55:49.319 5077 INFO oslo.messaging._drivers.impl_rabbit [req-d9229816-d734-47c9-b3ca-388ab66cd74c - - - - -] [999eeb6b-c28c-4cbf-bee8-1ca203101873] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39840.
    2017-11-14 08:55:46.884 5066 ERROR oslo.messaging._drivers.impl_rabbit [req-ecc3fc93-b0e9-42f9-9e89-2c75c06691fc - - - - -] [91fd3e8d-2239-4dd8-a815-f240b209814f] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 51690
    2017-11-14 08:55:51.223 5055 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 261.29 sec
    2017-11-14 08:55:58.617 5066 INFO oslo.messaging._drivers.impl_rabbit [req-ecc3fc93-b0e9-42f9-9e89-2c75c06691fc - - - - -] [91fd3e8d-2239-4dd8-a815-f240b209814f] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39850.
    2017-11-14 08:56:10.056 5071 ERROR oslo.messaging._drivers.impl_rabbit [req-f07192c9-1e21-441b-90a9-3b51ea806915 - - - - -] [3b6c34ed-1d54-4ca3-8dc2-de7ae72adf0a] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44180
2017-11-14 08:56:10.423 5064 ERROR oslo.messaging._drivers.impl_rabbit [req-24e3bcac-2409-4363-b16f-71e27fa0ad49 - - - - -] [b181caa4-477e-4ccd-86d7-347b0df87e8e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56296
2017-11-14 08:56:14.197 5071 INFO oslo.messaging._drivers.impl_rabbit [req-f07192c9-1e21-441b-90a9-3b51ea806915 - - - - -] [3b6c34ed-1d54-4ca3-8dc2-de7ae72adf0a] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39862.
2017-11-14 08:56:15.659 5051 ERROR oslo.messaging._drivers.impl_rabbit [req-95a04262-fd7d-477f-813c-e24d97970ce7 - - - - -] [c80e2327-4879-4151-b2cf-3069743f2e8c] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44206
2017-11-14 08:56:20.086 5077 INFO oslo.messaging._drivers.impl_rabbit [req-7e828ed0-b384-4ed6-9b13-b5caccb11dad - - - - -] [af728466-2a99-4d7a-8d8a-b486dd2775fa] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39842.
2017-11-14 08:56:23.614 5051 INFO oslo.messaging._drivers.impl_rabbit [req-95a04262-fd7d-477f-813c-e24d97970ce7 - - - - -] [c80e2327-4879-4151-b2cf-3069743f2e8c] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39866.
2017-11-14 08:56:23.872 5046 ERROR oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 39830
2017-11-14 08:56:25.063 5046 INFO oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39868.
2017-11-14 08:56:30.556 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 46.20 sec
2017-11-14 08:56:36.396 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 47.12 sec
2017-11-14 08:56:42.275 5036 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.78 sec
2017-11-14 08:56:45.202 5035 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 94.42 sec
2017-11-14 08:56:49.184 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 93.45 sec
2017-11-14 08:56:53.917 5064 INFO oslo.messaging._drivers.impl_rabbit [req-24e3bcac-2409-4363-b16f-71e27fa0ad49 - - - - -] [b181caa4-477e-4ccd-86d7-347b0df87e8e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39864.
2017-11-14 08:56:55.333 5042 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 325.43 sec
2017-11-14 08:57:06.667 5040 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 327.73 sec
2017-11-14 08:57:17.980 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 100.08 sec
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api [-] DB exceeded retry limit.
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api Traceback (most recent call last):
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 139, in wrapper
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return f(*args, **kwargs)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 240, in wrapped
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return f(context, *args, **kwargs)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.gen.next()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 875, in _transaction_scope
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     yield resource
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.gen.next()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 522, in _session
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._end_session_transaction(self.session)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 543, in _end_session_transaction
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     session.commit()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 813, in commit
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.transaction.commit()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 392, in commit
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._prepare_impl()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 372, in _prepare_impl
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.session.flush()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2027, in flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._flush(objects)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2145, in _flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     transaction.rollback(_capture_exception=True)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     compat.reraise(exc_type, exc_value, exc_tb)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2109, in _flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     flush_context.execute()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     rec.execute(self)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     uow
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 170, in save_obj
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     mapper, table, update)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 706, in _emit_update_statements
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     execute(statement, multiparams)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return meth(self, multiparams, params)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return connection._execute_clauseelement(self, multiparams, params)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     compiled_sql, distilled_params
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     context)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     util.raise_from_cause(newraise, exc_info)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     reraise(type(exception), exception, tb=exc_tb)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     context)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     cursor.execute(statement, parameters)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     result = self._query(query)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     conn.query(q)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1002, in _read_query_result
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     result.read()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     first_packet = self.connection._read_packet()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     packet.check_error()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     err.raise_mysql_exception(self._data)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     _check_mysql_exception(errinfo)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     raise InternalError(errno, errorvalue)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api DBDeadlock: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'UPDATE services SET updated_at=%(updated_at)s, report_count=%(report_count)s WHERE services.id = %(services_id)s'] [parameters: {'services_id': 9, 'updated_at': datetime.datetime(2017, 11, 14, 8, 56, 1, 790229), 'report_count': 2341088}]
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api [-] DB exceeded retry limit.
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api Traceback (most recent call last):
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 139, in wrapper
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api     return f(*args, **kwargs)

Compute nodes always showing MessagingTimeOut errors

Hello,

I have an OpenStack test cluster with 10 compute nodes and 1 controller node. Everything is fine I can launch instance, migrate, attach volumes, snapshot instances all is fine. But in all my compute nodes I can see MessagingTimeout errors regularly. It clearly reflect in my rabitmq logs also. I can also see DB exceeded retry limit error in nova-conductor.log. But after couple of seconds everything will be back and fine. And all the services are seems to be running fine I can launch instances. Iam really curious to know why this happens. Any help is really appreciated.

/var/log/nova/nova-compute.log

 2017-11-14 08:53:09.812 42708 WARNING nova.scheduler.client.report [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] No authentication information found for placement API. Placement is optional in Newton, but required in Ocata. Please enable the placement service before upgrading.
2017-11-14 08:53:09.813 42708 WARNING nova.scheduler.client.report [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Unable to refresh my resource provider record
2017-11-14 08:53:09.814 42708 INFO nova.compute.resource_tracker [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Compute_service record updated for server-1:server-1
2017-11-14 08:53:18.786 42708 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 35.71 sec
2017-11-14 08:53:27.172 42708 INFO nova.compute.resource_tracker [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Auditing locally available compute resources for node server-1
2017-11-14 08:54:18.798 42708 WARNING nova.servicegroup.drivers.db [-] Lost connection to nova-conductor for reporting service status.
2017-11-14 08:54:18.800 42708 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 50.01 sec
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Error updating resources for node server-1.
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager Traceback (most recent call last):
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 6442, in update_available_resource_for_node
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     rt.update_available_resource(context)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/compute/resource_tracker.py", line 511, in update_available_resource
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     resources = self.driver.get_available_resource(self.nodename)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 5385, in get_available_resource
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     disk_over_committed = self._get_disk_over_committed_size_total()
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 6955, in _get_disk_over_committed_size_total
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     ctx, filters, use_slave=True)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 177, in wrapper
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     args, kwargs)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 236, in object_class_action_versions
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     args=args, kwargs=kwargs)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     retry=self.retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 97, in _send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     timeout=timeout, retry=retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     retry=retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     result = self._waiter.wait(msg_id, timeout)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     message = self.waiters.get(msg_id, timeout=timeout)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     'to message ID %s' % msg_id)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager MessagingTimeout: Timed out waiting for a reply to message ID c88f27cc448946d2b44f0d86e340d264
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager
2017-11-14 08:54:42.692 42708 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : c88f27cc448946d2b44f0d86e340d264
2017-11-14 08:54:42.694 42708 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : 32111e339c754ca49168143e48315240
2017-11-14 08:55:18.808 42708 ERROR oslo.messaging._drivers.impl_rabbit [-] [56e6680f-7271-4173-a63d-835ac1ad5554] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 37740
2017-11-14 08:55:21.079 42708 INFO oslo.messaging._drivers.impl_rabbit [-] [56e6680f-7271-4173-a63d-835ac1ad5554] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 38502.
2017-11-14 08:56:10.431 42708 ERROR oslo.messaging._drivers.impl_rabbit [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] [e2c8c98f-f6a5-4205-bd40-e74f341a053e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 59516
2017-11-14 08:56:15.183 42708 INFO oslo.messaging._drivers.impl_rabbit [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] [e2c8c98f-f6a5-4205-bd40-e74f341a053e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 38506.

/var/log/nova/nova-conductor.log

    2017-11-14 08:53:06.765 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 96.83 sec
    2017-11-14 08:53:47.772 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 133.39 sec
    2017-11-14 08:54:01.777 5041 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 151.77 sec
    2017-11-14 08:54:01.780 5064 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 151.86 sec
    2017-11-14 08:54:18.825 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 117.98 sec
    2017-11-14 08:54:43.251 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.48 sec
    2017-11-14 08:54:50.804 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 95.99 sec
    2017-11-14 08:54:52.779 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 95.37 sec
    2017-11-14 08:55:00.477 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.54 sec
    2017-11-14 08:55:00.785 5035 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.87 sec
    2017-11-14 08:55:05.733 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 36.91 sec
    2017-11-14 08:55:17.718 5049 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 205.95 sec
    2017-11-14 08:55:16.186 5046 ERROR oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 50726
    2017-11-14 08:55:21.789 5070 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.02 sec
    2017-11-14 08:55:23.619 5046 INFO oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39830.
    2017-11-14 08:55:27.893 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 34.64 sec
    2017-11-14 08:55:28.458 5070 ERROR oslo.messaging._drivers.impl_rabbit [req-5b6db315-80e7-407a-8133-569aa84ae596 - - - - -] [a35e377f-a845-4e14-b180-efbf7ca8f57e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 50520
    2017-11-14 08:55:34.358 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 33.55 sec
    2017-11-14 08:55:35.334 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 32.55 sec
    2017-11-14 08:55:35.343 5054 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:35.345 5074 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:35.346 5039 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:31.893 5056 ERROR oslo.messaging._drivers.impl_rabbit [req-655a8997-62ab-48c4-a2b5-aaec3e348429 - - - - -] [437dcd32-d543-4d59-9a54-8a4b78726791] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56288
    2017-11-14 08:55:37.841 5041 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 85.47 sec
    2017-11-14 08:55:37.843 5064 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 85.47 sec
    2017-11-14 08:55:36.543 5077 ERROR oslo.messaging._drivers.impl_rabbit [req-d9229816-d734-47c9-b3ca-388ab66cd74c - - - - -] [999eeb6b-c28c-4cbf-bee8-1ca203101873] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56310
    2017-11-14 08:55:39.237 5070 INFO oslo.messaging._drivers.impl_rabbit [req-5b6db315-80e7-407a-8133-569aa84ae596 - - - - -] [a35e377f-a845-4e14-b180-efbf7ca8f57e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39836.
    2017-11-14 08:55:39.276 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 28.80 sec
    2017-11-14 08:55:39.323 5077 ERROR oslo.messaging._drivers.impl_rabbit [req-7e828ed0-b384-4ed6-9b13-b5caccb11dad - - - - -] [af728466-2a99-4d7a-8d8a-b486dd2775fa] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44186
    2017-11-14 08:55:41.200 5056 INFO oslo.messaging._drivers.impl_rabbit [req-655a8997-62ab-48c4-a2b5-aaec3e348429 - - - - -] [437dcd32-d543-4d59-9a54-8a4b78726791] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39838.
    2017-11-14 08:55:44.040 5046 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 254.14 sec
    2017-11-14 08:55:46.493 5036 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.56 sec
    2017-11-14 08:55:46.504 5060 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.57 sec
    2017-11-14 08:55:46.515 5071 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.51 sec
    2017-11-14 08:55:46.524 5051 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.52 sec
    2017-11-14 08:55:49.319 5077 INFO oslo.messaging._drivers.impl_rabbit [req-d9229816-d734-47c9-b3ca-388ab66cd74c - - - - -] [999eeb6b-c28c-4cbf-bee8-1ca203101873] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39840.
    2017-11-14 08:55:46.884 5066 ERROR oslo.messaging._drivers.impl_rabbit [req-ecc3fc93-b0e9-42f9-9e89-2c75c06691fc - - - - -] [91fd3e8d-2239-4dd8-a815-f240b209814f] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 51690
    2017-11-14 08:55:51.223 5055 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 261.29 sec
    2017-11-14 08:55:58.617 5066 INFO oslo.messaging._drivers.impl_rabbit [req-ecc3fc93-b0e9-42f9-9e89-2c75c06691fc - - - - -] [91fd3e8d-2239-4dd8-a815-f240b209814f] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39850.
    2017-11-14 08:56:10.056 5071 ERROR oslo.messaging._drivers.impl_rabbit [req-f07192c9-1e21-441b-90a9-3b51ea806915 - - - - -] [3b6c34ed-1d54-4ca3-8dc2-de7ae72adf0a] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44180
2017-11-14 08:56:10.423 5064 ERROR oslo.messaging._drivers.impl_rabbit [req-24e3bcac-2409-4363-b16f-71e27fa0ad49 - - - - -] [b181caa4-477e-4ccd-86d7-347b0df87e8e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56296
2017-11-14 08:56:14.197 5071 INFO oslo.messaging._drivers.impl_rabbit [req-f07192c9-1e21-441b-90a9-3b51ea806915 - - - - -] [3b6c34ed-1d54-4ca3-8dc2-de7ae72adf0a] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39862.
2017-11-14 08:56:15.659 5051 ERROR oslo.messaging._drivers.impl_rabbit [req-95a04262-fd7d-477f-813c-e24d97970ce7 - - - - -] [c80e2327-4879-4151-b2cf-3069743f2e8c] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44206
2017-11-14 08:56:20.086 5077 INFO oslo.messaging._drivers.impl_rabbit [req-7e828ed0-b384-4ed6-9b13-b5caccb11dad - - - - -] [af728466-2a99-4d7a-8d8a-b486dd2775fa] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39842.
2017-11-14 08:56:23.614 5051 INFO oslo.messaging._drivers.impl_rabbit [req-95a04262-fd7d-477f-813c-e24d97970ce7 - - - - -] [c80e2327-4879-4151-b2cf-3069743f2e8c] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39866.
2017-11-14 08:56:23.872 5046 ERROR oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 39830
2017-11-14 08:56:25.063 5046 INFO oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39868.
2017-11-14 08:56:30.556 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 46.20 sec
2017-11-14 08:56:36.396 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 47.12 sec
2017-11-14 08:56:42.275 5036 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.78 sec
2017-11-14 08:56:45.202 5035 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 94.42 sec
2017-11-14 08:56:49.184 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 93.45 sec
2017-11-14 08:56:53.917 5064 INFO oslo.messaging._drivers.impl_rabbit [req-24e3bcac-2409-4363-b16f-71e27fa0ad49 - - - - -] [b181caa4-477e-4ccd-86d7-347b0df87e8e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39864.
2017-11-14 08:56:55.333 5042 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 325.43 sec
2017-11-14 08:57:06.667 5040 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 327.73 sec
2017-11-14 08:57:17.980 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 100.08 sec
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api [-] DB exceeded retry limit.
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api Traceback (most recent call last):
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 139, in wrapper
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return f(*args, **kwargs)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 240, in wrapped
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return f(context, *args, **kwargs)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.gen.next()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 875, in _transaction_scope
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     yield resource
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.gen.next()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 522, in _session
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._end_session_transaction(self.session)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 543, in _end_session_transaction
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     session.commit()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 813, in commit
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.transaction.commit()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 392, in commit
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._prepare_impl()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 372, in _prepare_impl
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.session.flush()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2027, in flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._flush(objects)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2145, in _flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     transaction.rollback(_capture_exception=True)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     compat.reraise(exc_type, exc_value, exc_tb)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2109, in _flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     flush_context.execute()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     rec.execute(self)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     uow
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 170, in save_obj
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     mapper, table, update)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 706, in _emit_update_statements
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     execute(statement, multiparams)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return meth(self, multiparams, params)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return connection._execute_clauseelement(self, multiparams, params)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     compiled_sql, distilled_params
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     context)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     util.raise_from_cause(newraise, exc_info)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     reraise(type(exception), exception, tb=exc_tb)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     context)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     cursor.execute(statement, parameters)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     result = self._query(query)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     conn.query(q)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1002, in _read_query_result
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     result.read()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     first_packet = self.connection._read_packet()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     packet.check_error()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     err.raise_mysql_exception(self._data)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     _check_mysql_exception(errinfo)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     raise InternalError(errno, errorvalue)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api DBDeadlock: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'UPDATE services SET updated_at=%(updated_at)s, report_count=%(report_count)s WHERE services.id = %(services_id)s'] [parameters: {'services_id': 9, 'updated_at': datetime.datetime(2017, 11, 14, 8, 56, 1, 790229), 'report_count': 2341088}]
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api [-] DB exceeded retry limit.
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api Traceback (most recent call last):
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 139, in wrapper
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api     return f(*args, **kwargs)

Compute nodes always showing MessagingTimeOut errors

Hello,

I have an OpenStack test cluster with 10 compute nodes and 1 controller node. Everything is fine I can launch instance, migrate, attach volumes, snapshot instances all is fine. But in all my compute nodes I can see MessagingTimeout MessagingTimeout errors regularly. It clearly reflect in my rabitmq logs also. I can also see DB exceeded retry limit error in nova-conductor.log. But after couple of seconds everything will be back and fine. And all the services are seems to be running fine I can launch instances. Iam really curious to know why this happens. Any help is really appreciated.

/var/log/nova/nova-compute.log

 2017-11-14 08:53:09.812 42708 WARNING nova.scheduler.client.report [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] No authentication information found for placement API. Placement is optional in Newton, but required in Ocata. Please enable the placement service before upgrading.
2017-11-14 08:53:09.813 42708 WARNING nova.scheduler.client.report [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Unable to refresh my resource provider record
2017-11-14 08:53:09.814 42708 INFO nova.compute.resource_tracker [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Compute_service record updated for server-1:server-1
2017-11-14 08:53:18.786 42708 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 35.71 sec
2017-11-14 08:53:27.172 42708 INFO nova.compute.resource_tracker [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Auditing locally available compute resources for node server-1
2017-11-14 08:54:18.798 42708 WARNING nova.servicegroup.drivers.db [-] Lost connection to nova-conductor for reporting service status.
2017-11-14 08:54:18.800 42708 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 50.01 sec
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] Error updating resources for node server-1.
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager Traceback (most recent call last):
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 6442, in update_available_resource_for_node
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     rt.update_available_resource(context)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/compute/resource_tracker.py", line 511, in update_available_resource
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     resources = self.driver.get_available_resource(self.nodename)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 5385, in get_available_resource
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     disk_over_committed = self._get_disk_over_committed_size_total()
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 6955, in _get_disk_over_committed_size_total
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     ctx, filters, use_slave=True)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 177, in wrapper
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     args, kwargs)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 236, in object_class_action_versions
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     args=args, kwargs=kwargs)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     retry=self.retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 97, in _send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     timeout=timeout, retry=retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     retry=retry)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     result = self._waiter.wait(msg_id, timeout)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     message = self.waiters.get(msg_id, timeout=timeout)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager     'to message ID %s' % msg_id)
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager MessagingTimeout: Timed out waiting for a reply to message ID c88f27cc448946d2b44f0d86e340d264
2017-11-14 08:54:35.190 42708 ERROR nova.compute.manager
2017-11-14 08:54:42.692 42708 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : c88f27cc448946d2b44f0d86e340d264
2017-11-14 08:54:42.694 42708 INFO oslo_messaging._drivers.amqpdriver [-] No calling threads waiting for msg_id : 32111e339c754ca49168143e48315240
2017-11-14 08:55:18.808 42708 ERROR oslo.messaging._drivers.impl_rabbit [-] [56e6680f-7271-4173-a63d-835ac1ad5554] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 37740
2017-11-14 08:55:21.079 42708 INFO oslo.messaging._drivers.impl_rabbit [-] [56e6680f-7271-4173-a63d-835ac1ad5554] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 38502.
2017-11-14 08:56:10.431 42708 ERROR oslo.messaging._drivers.impl_rabbit [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] [e2c8c98f-f6a5-4205-bd40-e74f341a053e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 59516
2017-11-14 08:56:15.183 42708 INFO oslo.messaging._drivers.impl_rabbit [req-724b0dad-4823-421a-a158-721375f881ea - - - - -] [e2c8c98f-f6a5-4205-bd40-e74f341a053e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 38506.

/var/log/nova/nova-conductor.log

    2017-11-14 08:53:06.765 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 96.83 sec
    2017-11-14 08:53:47.772 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 133.39 sec
    2017-11-14 08:54:01.777 5041 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 151.77 sec
    2017-11-14 08:54:01.780 5064 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 151.86 sec
    2017-11-14 08:54:18.825 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 117.98 sec
    2017-11-14 08:54:43.251 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.48 sec
    2017-11-14 08:54:50.804 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 95.99 sec
    2017-11-14 08:54:52.779 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 95.37 sec
    2017-11-14 08:55:00.477 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.54 sec
    2017-11-14 08:55:00.785 5035 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.87 sec
    2017-11-14 08:55:05.733 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 36.91 sec
    2017-11-14 08:55:17.718 5049 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 205.95 sec
    2017-11-14 08:55:16.186 5046 ERROR oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 50726
    2017-11-14 08:55:21.789 5070 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 210.02 sec
    2017-11-14 08:55:23.619 5046 INFO oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39830.
    2017-11-14 08:55:27.893 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 34.64 sec
    2017-11-14 08:55:28.458 5070 ERROR oslo.messaging._drivers.impl_rabbit [req-5b6db315-80e7-407a-8133-569aa84ae596 - - - - -] [a35e377f-a845-4e14-b180-efbf7ca8f57e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 50520
    2017-11-14 08:55:34.358 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 33.55 sec
    2017-11-14 08:55:35.334 5050 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 32.55 sec
    2017-11-14 08:55:35.343 5054 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:35.345 5074 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:35.346 5039 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 191.59 sec
    2017-11-14 08:55:31.893 5056 ERROR oslo.messaging._drivers.impl_rabbit [req-655a8997-62ab-48c4-a2b5-aaec3e348429 - - - - -] [437dcd32-d543-4d59-9a54-8a4b78726791] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56288
    2017-11-14 08:55:37.841 5041 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 85.47 sec
    2017-11-14 08:55:37.843 5064 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 85.47 sec
    2017-11-14 08:55:36.543 5077 ERROR oslo.messaging._drivers.impl_rabbit [req-d9229816-d734-47c9-b3ca-388ab66cd74c - - - - -] [999eeb6b-c28c-4cbf-bee8-1ca203101873] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56310
    2017-11-14 08:55:39.237 5070 INFO oslo.messaging._drivers.impl_rabbit [req-5b6db315-80e7-407a-8133-569aa84ae596 - - - - -] [a35e377f-a845-4e14-b180-efbf7ca8f57e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39836.
    2017-11-14 08:55:39.276 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 28.80 sec
    2017-11-14 08:55:39.323 5077 ERROR oslo.messaging._drivers.impl_rabbit [req-7e828ed0-b384-4ed6-9b13-b5caccb11dad - - - - -] [af728466-2a99-4d7a-8d8a-b486dd2775fa] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44186
    2017-11-14 08:55:41.200 5056 INFO oslo.messaging._drivers.impl_rabbit [req-655a8997-62ab-48c4-a2b5-aaec3e348429 - - - - -] [437dcd32-d543-4d59-9a54-8a4b78726791] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39838.
    2017-11-14 08:55:44.040 5046 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 254.14 sec
    2017-11-14 08:55:46.493 5036 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.56 sec
    2017-11-14 08:55:46.504 5060 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.57 sec
    2017-11-14 08:55:46.515 5071 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.51 sec
    2017-11-14 08:55:46.524 5051 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 256.52 sec
    2017-11-14 08:55:49.319 5077 INFO oslo.messaging._drivers.impl_rabbit [req-d9229816-d734-47c9-b3ca-388ab66cd74c - - - - -] [999eeb6b-c28c-4cbf-bee8-1ca203101873] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39840.
    2017-11-14 08:55:46.884 5066 ERROR oslo.messaging._drivers.impl_rabbit [req-ecc3fc93-b0e9-42f9-9e89-2c75c06691fc - - - - -] [91fd3e8d-2239-4dd8-a815-f240b209814f] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 51690
    2017-11-14 08:55:51.223 5055 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 261.29 sec
    2017-11-14 08:55:58.617 5066 INFO oslo.messaging._drivers.impl_rabbit [req-ecc3fc93-b0e9-42f9-9e89-2c75c06691fc - - - - -] [91fd3e8d-2239-4dd8-a815-f240b209814f] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39850.
    2017-11-14 08:56:10.056 5071 ERROR oslo.messaging._drivers.impl_rabbit [req-f07192c9-1e21-441b-90a9-3b51ea806915 - - - - -] [3b6c34ed-1d54-4ca3-8dc2-de7ae72adf0a] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44180
2017-11-14 08:56:10.423 5064 ERROR oslo.messaging._drivers.impl_rabbit [req-24e3bcac-2409-4363-b16f-71e27fa0ad49 - - - - -] [b181caa4-477e-4ccd-86d7-347b0df87e8e] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 56296
2017-11-14 08:56:14.197 5071 INFO oslo.messaging._drivers.impl_rabbit [req-f07192c9-1e21-441b-90a9-3b51ea806915 - - - - -] [3b6c34ed-1d54-4ca3-8dc2-de7ae72adf0a] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39862.
2017-11-14 08:56:15.659 5051 ERROR oslo.messaging._drivers.impl_rabbit [req-95a04262-fd7d-477f-813c-e24d97970ce7 - - - - -] [c80e2327-4879-4151-b2cf-3069743f2e8c] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 44206
2017-11-14 08:56:20.086 5077 INFO oslo.messaging._drivers.impl_rabbit [req-7e828ed0-b384-4ed6-9b13-b5caccb11dad - - - - -] [af728466-2a99-4d7a-8d8a-b486dd2775fa] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39842.
2017-11-14 08:56:23.614 5051 INFO oslo.messaging._drivers.impl_rabbit [req-95a04262-fd7d-477f-813c-e24d97970ce7 - - - - -] [c80e2327-4879-4151-b2cf-3069743f2e8c] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39866.
2017-11-14 08:56:23.872 5046 ERROR oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] AMQP server on controller:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: 39830
2017-11-14 08:56:25.063 5046 INFO oslo.messaging._drivers.impl_rabbit [req-cdd02445-b8d7-45ac-841e-41c1681782b9 - - - - -] [1adbbda0-6d6c-445b-844f-62802557b2c7] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39868.
2017-11-14 08:56:30.556 5038 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 46.20 sec
2017-11-14 08:56:36.396 5066 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 47.12 sec
2017-11-14 08:56:42.275 5036 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.78 sec
2017-11-14 08:56:45.202 5035 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 94.42 sec
2017-11-14 08:56:49.184 5062 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 93.45 sec
2017-11-14 08:56:53.917 5064 INFO oslo.messaging._drivers.impl_rabbit [req-24e3bcac-2409-4363-b16f-71e27fa0ad49 - - - - -] [b181caa4-477e-4ccd-86d7-347b0df87e8e] Reconnected to AMQP server on controller:5672 via [amqp] clientwith port 39864.
2017-11-14 08:56:55.333 5042 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 325.43 sec
2017-11-14 08:57:06.667 5040 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 327.73 sec
2017-11-14 08:57:17.980 5056 WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 100.08 sec
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api [-] DB exceeded retry limit.
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api Traceback (most recent call last):
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 139, in wrapper
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return f(*args, **kwargs)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 240, in wrapped
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return f(context, *args, **kwargs)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.gen.next()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 875, in _transaction_scope
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     yield resource
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.gen.next()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 522, in _session
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._end_session_transaction(self.session)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 543, in _end_session_transaction
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     session.commit()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 813, in commit
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.transaction.commit()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 392, in commit
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._prepare_impl()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 372, in _prepare_impl
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self.session.flush()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2027, in flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._flush(objects)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2145, in _flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     transaction.rollback(_capture_exception=True)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     compat.reraise(exc_type, exc_value, exc_tb)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2109, in _flush
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     flush_context.execute()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     rec.execute(self)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     uow
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 170, in save_obj
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     mapper, table, update)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 706, in _emit_update_statements
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     execute(statement, multiparams)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return meth(self, multiparams, params)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     return connection._execute_clauseelement(self, multiparams, params)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     compiled_sql, distilled_params
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     context)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     util.raise_from_cause(newraise, exc_info)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     reraise(type(exception), exception, tb=exc_tb)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     context)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     cursor.execute(statement, parameters)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     result = self._query(query)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     conn.query(q)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1002, in _read_query_result
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     result.read()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     first_packet = self.connection._read_packet()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     packet.check_error()
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     err.raise_mysql_exception(self._data)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     _check_mysql_exception(errinfo)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api     raise InternalError(errno, errorvalue)
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api DBDeadlock: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'UPDATE services SET updated_at=%(updated_at)s, report_count=%(report_count)s WHERE services.id = %(services_id)s'] [parameters: {'services_id': 9, 'updated_at': datetime.datetime(2017, 11, 14, 8, 56, 1, 790229), 'report_count': 2341088}]
2017-11-14 08:56:52.788 5037 ERROR oslo_db.api
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api [-] DB exceeded retry limit.
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api Traceback (most recent call last):
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api   File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 139, in wrapper
2017-11-14 08:56:52.788 5043 ERROR oslo_db.api     return f(*args, **kwargs)