StarlingX

AIO-DX Application apply aborted Unexpected process termination while application-apply was in progress

Bug #1838101 reported by Anujeyan Manokeran on 2019-07-26

This bug report is a duplicate of: Bug #1837750: stx-application re-apply strategy requires some changes. Edit Remove

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	StarlingX	Fix Released	Medium	Bob Church

Bug Description

Brief Description
-----------------
Application apply was failed when standby controller was locked and unlocked on AIO-DX. Failure as below in sysinv.log. Prior to this system had issues CPU https://bugs.launchpad.net/starlingx/+bug/1837426

7-26 18:46:53.194 20389 ERROR sysinv.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 21 seconds.
2019-07-26 18:47:14.210 20389 INFO sysinv.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
2019-07-26 18:47:14.216 20389 INFO sysinv.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
2019-07-26 18:47:14.222 20389 ERROR sysinv.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 23 seconds.
2019-07-26 18:47:14.222 20389 ERROR sysinv.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 23 seconds.
2019-07-26 18:47:37.240 20389 INFO sysinv.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
2019-07-26 18:47:37.246 20389 INFO sysinv.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
2019-07-26 18:47:37.252 20389 ERROR sysinv.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 25 seconds.
2019-07-26 18:47:37.252 20389 ERROR sysinv.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 25 seconds.
2019-07-26 18:47:48.391 186024 INFO sysinv.cmd.dnsmasq_lease_update [-] Called 'old' for mac '24:8a:07:58:d0:d0' with ip '192.168.204.4'
2019-07-26 18:47:52.189 186219 WARNING ceph_client [-] skip checking server certificate
2019-07-26 18:47:52.509 187128 INFO sysinv.cmd.dnsmasq_lease_update [-] Called 'old' for mac '24:8a:07:58:d0:d0' with ip '192.168.204.4'
2019-07-26 18:47:54.602 185734 WARNING ceph_client [-] skip checking server certificate
2019-07-26 18:47:55.053 186219 WARNING ceph_client [-] skip checking server certificate
2019-07-26 18:47:55.123 186219 WARNING ceph_client [-] skip checking server certificate
2019-07-26 18:47:55.128 186219 WARNING ceph_client [-] skip checking server certificate
2019-07-26 18:47:55.141 186219 WARNING oslo_config.cfg [-] Deprecated: Option "auth_uri" from group "keystone_authtoken" is deprecated for removal (The auth_uri option is deprecated in favor of www_authenticate_uri and will be removed in the S release.). Its value may be silently ignored in the future.
2019-07-26 18:47:55.146 186219 WARNING oslo_config.cfg [-] Deprecated: Option "auth_uri" from group "keystone_authtoken" is deprecated. Use option "www_authenticate_uri" from group "keystone_authtoken".
2019-07-26 18:47:55.148 186219 INFO keystonemiddleware.auth_token [-] Starting Keystone auth_token middleware
2019-07-26 18:47:55.157 186219 WARNING keystonemiddleware.auth_token [-] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.
2019-07-26 18:47:55.168 186219 INFO oslo.service.wsgi [-] sysinv_api listening on 192.168.204.2:6385
2019-07-26 18:47:55.168 186219 INFO oslo_service.service [-] Starting 1 workers
2019-07-26 18:47:55.179 186219 INFO keystonemiddleware.auth_token [-] Starting Keystone auth_token middleware
2019-07-26 18:47:55.183 186219 WARNING keystonemiddleware._common.config [-] The option "user_domain_name" in conf is not known to auth_token
2019-07-26 18:47:55.184 186219 WARNING keystonemiddleware._common.config [-] The option "auth_url" in conf is not known to auth_token
2019-07-26 18:47:55.184 186219 WARNING keystonemiddleware._common.config [-] The option "project_domain_name" in conf is not known to auth_token
2019-07-26 18:47:55.184 186219 WARNING keystonemiddleware._common.config [-] The option "username" in conf is not known to auth_token
2019-07-26 18:47:55.184 186219 WARNING keystonemiddleware._common.config [-] The option "project_name" in conf is not known to auth_token
2019-07-26 18:47:55.185 186219 WARNING keystonemiddleware._common.config [-] The option "password" in conf is not known to auth_token
2019-07-26 18:47:55.187 186219 WARNING keystonemiddleware.auth_token [-] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.

47:55.184 186219 WARNING keystonemiddleware._common.config [-] The option "username" in conf is not known to auth_token
2019-07-26 18:47:55.184 186219 WARNING keystonemiddleware._common.config [-] The option "project_name" in conf is not known to auth_token
2019-07-26 18:47:55.185 186219 WARNING keystonemiddleware._common.config [-] The option "password" in conf is not known to auth_token
2019-07-26 18:47:55.187 186219 WARNING keystonemiddleware.auth_token [-] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.
2019-07-26 18:47:55.190 186219 INFO oslo.service.wsgi [-] sysinv_api_pxe listening on 169.254.202.2:6385
2019-07-26 18:47:55.192 186219 INFO oslo_service.service [-] Starting 1 workers
2019-07-26 18:47:55.631 185734 INFO sysinv.conductor.kube_app [-] Resetting status of app stx-openstack from 'applying' to 'apply-failed'
2019-07-26 18:47:55.654 185734 WARNING urllib3.connectionpool [-] Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f190>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)': /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock
2019-07-26 18:47:55.655 185734 WARNING urllib3.connectionpool [-] Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f2d0>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)': /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock
2019-07-26 18:47:55.655 185734 WARNING urllib3.connectionpool [-] Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f410>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)': /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock
2019-07-26 18:47:55.657 185734 ERROR sysinv.common.kubernetes [-] Failed to delete custom object, Namespace kube-system: HTTPSConnectionPool(host='192.168.206.2', port=6443): Max retries exceeded with url: /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f390>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',))
2019-07-26 18:47:55.657 185734 WARNING ceph_client [-] skip checking server certificate
2019-07-26 18:47:57.478 18573
Severity
--------
Major
Steps to Reproduce
------------------
1. Lock and unlock standby controller
2. Once the controller is up application was failed

System Configuration
--------------------
AIO DX system

Expected Behavior
------------------
No failure or abort on application apply on stx-openstack
Actual Behavior
----------------
Failure or abort on application apply on stx-openstack
Reproducibility
---------------
System Configuration
--------------------
Regular system
Load
----

Last Pass
---------
Timestamp/Logs
--------------
2019-07-26T18:32:33.000
Test Activity
-------------
Regression test

Tags:

Revision history for this message

Anujeyan Manokeran (anujeyan) wrote on 2019-07-26:

collect logs Edit (41.4 MiB, application/x-tar)

Numan Waheed (nwaheed) on 2019-07-29

tags:

added: stx.retestneeded

Revision history for this message

Frank Miller (sensfan22) wrote on 2019-07-29:

Please update the bug report to indicate which load.
Also the system configuration in the report indicates "Regular system" but the title indicates "AIO-DX". Please correct the bug report template.

Ghada Khalil (gkhalil) on 2019-07-29

tags:

added: stx.containers

Maria Guadalupe Perez Ibara (maria-gp) on 2019-07-30

tags:

added: stx.regression

Revision history for this message

Ghada Khalil (gkhalil) wrote on 2019-07-31:

Marking as stx.2.0 / medium priority for now -- expected that this is an intermittent issue

Changed in starlingx:
status:	New → Triaged
importance:	Undecided → Medium
assignee:	nobody → Bob Church (rchurch)
tags:	added: stx.2.0

Revision history for this message

Bob Church (rchurch) wrote on 2019-08-02:

Download full text (29.0 KiB)

* Event Summary:
   - Unlock of standby controller
   - Application apply due to the unlock
   - ceph-mon, ceph-radosgw, dbmon start failing their audits.
     - Observing brief communication alarms on all interfaces
     - Ceph health check fails to respond with 10s timeout in this window
   - Uncontrolled swact occurs
     - Noticed some sm not scheduling on time messages, usually indicative of hitting platform resource limits
   - Monitor outage during the swact causes the mgr-restful-plugin to fail and restart
   - Total monitor outage from kill on active controller + swact + start on active controller is ~5m 37s
      2019-07-26 18:41:58.119 7fb018724700 -1 mon.controller@0(leader) e1 *** Got Signal Terminated ***
      2019-07-26 18:47:35.743 7fd370d83140 0 ceph version 13.2.2 (00071a2d9e839b95f9439daaccd4677c5d15eaa6) mimic (stable), process ceph-mon, pid 182505
   - Application is marked failed after abort

* Further actions:
   - Evaluate ceph health audit logic
     - This recent update might help: https://opendev.org/starlingx/integ/commit/12f604b4dd86663910fa152ea50265a2ae56d932
   - Evalute and optimize the monitor outage during swacts ~5m 30s minutes is excessive
     - SM dependencies on a swact: can we stop ceph-mon last on shutdown and first after startup?

2019-07-26 18:32:38.751 1799045 INFO sysinv.api.controllers.v1.host [-] controller-0 apply ihost_val {'ihost_action': 'unlock', 'task': u'Unlocking'}
2019-07-26T18:39:41.876 | 1 | node-scn | controller-0 | unknown-unknown | unlocked-unknown | customer action

2019-07-26T18:40:27.000 controller-1 sm: debug time[12467.330] log<15> INFO: sm_alarm[97894]: sm_alarm_thread.c(638): Raising alarm (communication-failure) for node (controller-1) domain () entity (oam).
2019-07-26T18:40:27.000 controller-1 sm: debug time[12467.335] log<16> INFO: sm_alarm[97894]: sm_alarm_thread.c(1083): Raised alarm (communication-failure) for node (controller-1) domain () entity (oam), fm_uuid=07de968b-ab45-4133-a100-03e34d12cb07.
2019-07-26T18:40:27.000 controller-1 sm: debug time[12467.335] log<17> INFO: sm_alarm[97894]: sm_alarm_thread.c(638): Raising alarm (communication-failure) for node (controller-1) domain () entity (mgmt).
2019-07-26T18:40:27.000 controller-1 sm: debug time[12467.430] log<18> INFO: sm_alarm[97894]: sm_alarm_thread.c(1083): Raised alarm (communication-failure) for node (controller-1) domain () entity (mgmt), fm_uuid=59862cfb-0054-4007-a2ae-618814a6fa27.

2019-07-26 18:40:30.108 1798378 INFO sysinv.conductor.kube_app [-] All docker images for application stx-openstack were successfully downloaded in 441 seconds
2019-07-26 18:40:30.150 1798378 INFO sysinv.conductor.kube_app [-] Starting Armada service...
2019-07-26 18:40:31.140 1798378 INFO sysinv.conductor.kube_app [-] Starting progress monitoring thread for app stx-openstack

* Event Summary:
   - Unlock of standby controller
   - Application apply due to the unlock
   - ceph-mon, ceph-radosgw, dbmon start failing their audits. 
     - Observing brief communication alarms on all interfaces
     - Ceph health check fails to respond with 10s timeout in this window
   - Uncontrolled swact occurs
     - Noticed some sm not scheduling on time messages, usually indicative of hitting platform resource limits
   - Monitor outage during the swact causes the mgr-restful-plugin to fail and restart
   - Total monitor outage from kill on active controller + swact + start on active controller is ~5m 37s
      2019-07-26 18:41:58.119 7fb018724700 -1 mon.controller@0(leader) e1 *** Got Signal Terminated ***
      2019-07-26 18:47:35.743 7fd370d83140  0 ceph version 13.2.2 (00071a2d9e839b95f9439daaccd4677c5d15eaa6) mimic (stable), process ceph-mon, pid 182505
   - Application is marked failed after abort

2019-07-26 18:32:38.751 1799045 INFO sysinv.api.controllers.v1.host [-] controller-0 apply ihost_val {'ihost_action': 'unlock', 'task': u'Unlocking'}
2019-07-26T18:39:41.876 |          1 | node-scn             | controller-0                     | unknown-unknown                  | unlocked-unknown                 | customer action

2019-07-26T18:40:40.000 controller-1 sm: debug time[12479.845] log<21080> INFO: sm[97872]: sm_service_audit.c(175): Action (audit-enabled) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-mon), reason_text=, exit_code=-65534.
2019-07-26T18:40:40.000 controller-1 sm: debug time[12479.845] log<21081> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-mon) with kill signal, pid=2535225.
2019-07-26T18:40:40.000 controller-1 sm: debug time[12479.845] log<21082> INFO: sm[97872]: sm_service_audit.c(75): Max retires not met for action (audit-enabled) of service (ceph-mon), attempts=1.
2019-07-26T18:40:41.000 controller-1 sm: debug time[12481.242] log<21084> INFO: sm[97872]: sm_service_audit.c(175): Action (audit-enabled) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-radosgw), reason_text=, exit_code=-65534.
2019-07-26T18:40:41.000 controller-1 sm: debug time[12481.242] log<21085> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-radosgw) with kill signal, pid=2535637.
2019-07-26T18:40:41.000 controller-1 sm: debug time[12481.242] log<21086> INFO: sm[97872]: sm_service_audit.c(75): Max retires not met for action (audit-enabled) of service (ceph-radosgw), attempts=1.
2019-07-26T18:40:41.000 controller-1 sm: debug time[12481.243] log<21087> ERROR: sm[97872]: sm_service_audit.c(228): Failed to query service based on pid (2535637), error=NOT_FOUND.
2019-07-26T18:40:42.000 controller-0 sm: debug time[250.468] log<346> INFO: sm[96729]: sm_service_action.c(98): Plugin (/usr/lib/ocf/resource.d/heartbeat/IPaddr2) has been changed, was=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, now=0b574c85bfb7b90273064b5b1496f91ab63f752692ab2c598c2279c91b15b184c761986c0c21d0d93a72d9da7ecfd0cb0a8ba0d33ffd8782322138568932c369.
2019-07-26T18:40:42.000 controller-0 sm: debug time[250.469] log<347> INFO: sm[96729]: sm_service_action.c(98): Plugin (/usr/lib/ocf/resource.d/heartbeat/IPaddr2) has been changed, was=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, now=0b574c85bfb7b90273064b5b1496f91ab63f752692ab2c598c2279c91b15b184c761986c0c21d0d93a72d9da7ecfd0cb0a8ba0d33ffd8782322138568932c369.
2019-07-26T18:40:42.000 controller-0 sm: debug time[250.469] log<348> INFO: sm[96729]: sm_service_action.c(98): Plugin (/usr/lib/ocf/resource.d/heartbeat/IPaddr2) has been changed, was=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, now=0b574c85bfb7b90273064b5b1496f91ab63f752692ab2c598c2279c91b15b184c761986c0c21d0d93a72d9da7ecfd0cb0a8ba0d33ffd8782322138568932c369.
2019-07-26T18:40:42.000 controller-0 sm: debug time[250.470] log<349> INFO: sm[96729]: sm_service_action.c(98): Plugin (/usr/lib/ocf/resource.d/heartbeat/IPaddr2) has been changed, was=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, now=0b574c85bfb7b90273064b5b1496f91ab63f752692ab2c598c2279c91b15b184c761986c0c21d0d93a72d9da7ecfd0cb0a8ba0d33ffd8782322138568932c369.
2019-07-26T18:40:42.000 controller-0 sm: debug time[250.471] log<350> INFO: sm[96729]: sm_service_action.c(98): Plugin (/usr/lib/ocf/resource.d/heartbeat/IPaddr2) has been changed, was=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, now=0b574c85bfb7b90273064b5b1496f91ab63f752692ab2c598c2279c91b15b184c761986c0c21d0d93a72d9da7ecfd0cb0a8ba0d33ffd8782322138568932c369.
2019-07-26T18:40:42.000 controller-0 sm: debug time[250.497] log<351> INFO: sm[96729]: sm_service_action.c(98): Plugin (/usr/lib/ocf/resource.d/heartbeat/IPaddr2) has been changed, was=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, now=0b574c85bfb7b90273064b5b1496f91ab63f752692ab2c598c2279c91b15b184c761986c0c21d0d93a72d9da7ecfd0cb0a8ba0d33ffd8782322138568932c369.
2019-07-26T18:40:55.000 controller-1 sm: debug time[12494.857] log<21088> INFO: sm[97872]: sm_service_audit.c(175): Action (audit-enabled) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-mon), reason_text=, exit_code=-65534.
2019-07-26T18:40:55.000 controller-1 sm: debug time[12494.857] log<21089> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-mon) with kill signal, pid=2537397.
2019-07-26T18:40:55.000 controller-1 sm: debug time[12494.857] log<21090> INFO: sm[97872]: sm_service_audit.c(70): Max retires met for action (audit-enabled) of service (ceph-mon), attempts=2.
2019-07-26T18:40:55.000 controller-1 sm: debug time[12494.869] log<21091> INFO: sm[97872]: sm_service_disable.c(380): Started disable action (2539955) for service (ceph-mon), flag (0).
2019-07-26T18:40:55.000 controller-1 sm: debug time[12494.869] log<21092> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-mon) received event (audit-failed) was in the enabled-active state and is now in the disabling state.
2019-07-26T18:40:55.000 controller-1 sm: debug time[12494.869] log<21093> ERROR: sm[97872]: sm_service_audit.c(228): Failed to query service based on pid (2537397), error=NOT_FOUND.
2019-07-26T18:40:55.000 controller-1 sm: debug time[12495.170] log<21094> INFO: sm[97872]: sm_service_disable.c(380): Started disable action (2539982) for service (ceph-radosgw), flag (0).
2019-07-26T18:40:55.000 controller-1 sm: debug time[12495.170] log<21095> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-radosgw) received event (disable) was in the enabled-active state and is now in the disabling state.

2019-07-26T18:40:56.000 controller-1 sm: debug time[12496.605] log<21> INFO: sm_alarm[97894]: sm_alarm_thread.c(668): Clearing alarm (communication-failure) for node (controller-1) domain () entity (oam).
2019-07-26T18:40:56.000 controller-1 sm: debug time[12496.658] log<22> INFO: sm_alarm[97894]: sm_alarm_thread.c(1127): Cleared alarm (communication-failure) for node (controller-1) domain () entity (oam), fm_uuid=07de968b-ab45-4133-a100-03e34d12cb07.
2019-07-26T18:40:56.000 controller-1 sm: debug time[12496.659] log<23> INFO: sm_alarm[97894]: sm_alarm_thread.c(668): Clearing alarm (communication-failure) for node (controller-1) domain () entity (mgmt).
2019-07-26T18:40:57.000 controller-1 sm: debug time[12497.026] log<24> INFO: sm_alarm[97894]: sm_alarm_thread.c(1127): Cleared alarm (communication-failure) for node (controller-1) domain () entity (mgmt), fm_uuid=59862cfb-0054-4007-a2ae-618814a6fa27.
2019-07-26T18:40:57.000 controller-1 sm: debug time[12497.026] log<25> INFO: sm_alarm[97894]: sm_alarm_thread.c(668): Clearing alarm (communication-failure) for node (controller-1) domain () entity (cluster-host).
2019-07-26T18:40:57.000 controller-1 sm: debug time[12497.120] log<26> INFO: sm_alarm[97894]: sm_alarm_thread.c(1127): Cleared alarm (communication-failure) for node (controller-1) domain () entity (cluster-host), fm_uuid=3331f744-5505-4dd3-a37f-98800f8a5c12.

2019-07-26 18:40:57.154 /etc/init.d/ceph mon.controller WARN: Ceph failed to respond in 10s when running: timeout 10 ceph health detail | tail -n 50
2019-07-26 18:40:57.205 /etc/init.d/ceph mon.controller WARN: Aborting hang check

2019-07-26T18:41:04.000 controller-1 sm: debug time[12504.410] log<121> INFO: sm_service_hb[97942]: sm_timer.c(288): Not scheduling on time, elapsed=294 ms.
2019-07-26T18:41:10.000 controller-1 sm: debug time[12509.873] log<21098> INFO: sm[97872]: sm_service_disable.c(162): Action (disable) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-mon), reason_text=, exit_code=-65534.
2019-07-26T18:41:10.000 controller-1 sm: debug time[12509.873] log<21099> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-mon) with kill signal, pid=2539955.
2019-07-26T18:41:10.000 controller-1 sm: debug time[12509.873] log<21100> INFO: sm[97872]: sm_service_disable.c(69): Max retires met for action (disable) of service (ceph-mon), attempts=1.
2019-07-26T18:41:10.000 controller-1 sm: debug time[12509.874] log<21101> ERROR: sm[97872]: sm_service_disable.c(215): Failed to query service based on pid (2539955), error=NOT_FOUND.
2019-07-26T18:41:10.000 controller-1 sm: debug time[12510.096] log<21102> INFO: sm[97872]: sm_service_disable.c(380): Started disable action (2542206) for service (ceph-mon), flag (0).

2019-07-26T18:41:25.000 controller-1 sm: debug time[12525.096] log<21104> INFO: sm[97872]: sm_service_disable.c(162): Action (disable) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-mon), reason_text=, exit_code=-65534.
2019-07-26T18:41:25.000 controller-1 sm: debug time[12525.096] log<21105> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-mon) with kill signal, pid=2542206.
2019-07-26T18:41:25.000 controller-1 sm: debug time[12525.096] log<21106> INFO: sm[97872]: sm_service_disable.c(69): Max retires met for action (disable) of service (ceph-mon), attempts=1.
2019-07-26T18:41:25.000 controller-1 sm: debug time[12525.101] log<21107> ERROR: sm[97872]: sm_service_disable.c(215): Failed to query service based on pid (2542206), error=NOT_FOUND.
2019-07-26T18:41:25.000 controller-1 sm: debug time[12525.491] log<21108> INFO: sm[97872]: sm_service_disable.c(380): Started disable action (2544711) for service (ceph-mon), flag (0).

2019-07-26T18:41:31.000 controller-0 sm: debug time[299.206] log<420> INFO: sm[96729]: sm_node_api.cpp(477): Updating node (controller-0) info.
2019-07-26T18:41:31.000 controller-0 sm: debug time[299.243] log<421> INFO: sm[96729]: sm_failover.c(1133): controller-0 unlocked-enabled-degraded, controller-1 unlocked-enabled-degraded
2019-07-26T18:41:31.000 controller-1 sm: debug time[12531.039] log<21113> INFO: sm[97872]: sm_failover.c(1133): controller-1 unlocked-enabled-degraded, controller-0 unlocked-enabled-degraded

2019-07-26T18:41:40.000 controller-1 sm: debug time[12540.520] log<21117> INFO: sm[97872]: sm_service_disable.c(162): Action (disable) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-mon), reason_text=, exit_code=-65534.
2019-07-26T18:41:40.000 controller-1 sm: debug time[12540.520] log<21118> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-mon) with kill signal, pid=2544711.
2019-07-26T18:41:40.000 controller-1 sm: debug time[12540.520] log<21119> INFO: sm[97872]: sm_service_disable.c(69): Max retires met for action (disable) of service (ceph-mon), attempts=1.
2019-07-26T18:41:40.000 controller-1 sm: debug time[12540.521] log<21120> ERROR: sm[97872]: sm_service_disable.c(215): Failed to query service based on pid (2544711), error=NOT_FOUND.
2019-07-26T18:41:41.000 controller-1 sm: debug time[12540.796] log<21121> INFO: sm[97872]: sm_service_disable.c(380): Started disable action (2546616) for service (ceph-mon), flag (0).
2019-07-26T18:41:42.000 controller-1 sm: debug time[12542.329] log<21122> INFO: sm[97872]: sm_service_audit.c(428): Aborting action (audit-disabled) of service (ceph-radosgw).
2019-07-26T18:41:42.000 controller-1 sm: debug time[12542.329] log<21123> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-radosgw) with kill signal, pid=2546751.
2019-07-26T18:41:42.000 controller-1 sm: debug time[12542.329] log<21124> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-radosgw) received event (enable-throttle) was in the disabled state and is now in the enabling-throttle state.
2019-07-26T18:41:42.000 controller-1 sm: debug time[12542.330] log<21125> ERROR: sm[97872]: sm_service_audit.c(228): Failed to query service based on pid (2546751), error=NOT_FOUND.

2019-07-26T18:41:46.000 controller-1 sm: debug time[12546.368] log<14> INFO: sm_heartbeat[97899]: sm_timer.c(288): Not scheduling on time, elapsed=241 ms.
2019-07-26T18:41:46.000 controller-1 sm: debug time[12546.369] log<125> INFO: sm_service_hb[97942]: sm_timer.c(288): Not scheduling on time, elapsed=205 ms.
2019-07-26T18:41:47.000 controller-1 sm: debug time[12547.379] log<126> INFO: sm_service_hb[97942]: sm_timer.c(300): Now scheduling on time.
2019-07-26T18:41:47.000 controller-1 sm: debug time[12547.400] log<15> INFO: sm_heartbeat[97899]: sm_timer.c(300): Now scheduling on time.

2019-07-26T18:41:56.000 controller-0 sm: debug time[324.099] log<479> INFO: sm[96729]: sm_service_domain_filter.c(338): Uncontrolled swact start
2019-07-26T18:41:56.000 controller-0 sm: debug time[324.099] log<480> INFO: sm[96729]: sm_node_swact_monitor.cpp(23): Start of swact: affining tasks to idle cores...
2019-07-26T18:41:56.000 controller-0 sm: debug time[324.099] log<482> INFO: sm[96729]: sm_node_swact_monitor.cpp(29): Swact has started, host will be active
2019-07-26T18:41:56.000 controller-0 sm: debug time[324.270] log<3> INFO: sm_ta[96759]: sm_task_affining_thread.c(39): Invoking system call, affining to idle cores...

2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.796] log<21141> INFO: sm[97872]: sm_service_disable.c(162): Action (disable) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service (ceph-mon), reason_text=, exit_code=-65534.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.796] log<21142> INFO: sm[97872]: sm_service_action.c(345): Aborting service (ceph-mon) with kill signal, pid=2546616.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.796] log<21143> INFO: sm[97872]: sm_service_disable.c(69): Max retires met for action (disable) of service (ceph-mon), attempts=1.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.796] log<21144> INFO: sm[97872]: sm_service_disabling_state.c(259): Service (ceph-mon) is failed and has reached max action failures (4).
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.796] log<21145> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-mon) received event (disable-failed) was in the disabling state and is now in the disabling-failed state, condition=action-failure.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.797] log<21146> INFO: sm[97872]: sm_service_group_audit.c(434): Service group (controller-services) member (ceph-mon) has mapped status (failed), overall_status=failed.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.797] log<21147> INFO: sm[97872]: sm_service_group_audit.c(444): Service group (controller-services) member (ceph-mon) has mapped condition (action-failure), overall_condition=action-failure.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.797] log<21148> INFO: sm[97872]: sm_service_group_fsm.c(904): Service group (controller-services) was in the active state and is now in the active-failed state, condition=action-failure.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.797] log<21149> ERROR: sm[97872]: sm_service_disable.c(215): Failed to query service based on pid (2546616), error=NOT_FOUND.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.888] log<21150> INFO: sm[97872]: sm_service_disable.c(279): Action (disable) completed with result (success), state (unknown), status (unknown), and condition (unknown) for service (ceph-radosgw), reason_text=, exit_code=0.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.888] log<21151> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-radosgw) received event (disable-success) was in the disabling state and is now in the disabled state.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12555.959] log<21152> INFO: sm[97872]: sm_service_api.c(300): Recovery of service (ceph-mon) requested.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12556.143] log<21153> INFO: sm[97872]: sm_service_engine.c(347): Fail counts and status for service (ceph-mon) cleared in disabling state.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12556.144] log<21154> INFO: sm[97872]: sm_service_enable.c(459): Started enable action (2549687) for service (ceph-mon).
2019-07-26T18:41:56.000 controller-1 sm: debug time[12556.144] log<21155> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-mon) received event (enable-throttle) was in the disabling-failed state and is now in the enabling-failed state.
2019-07-26T18:41:56.000 controller-1 sm: debug time[12556.144] log<21157> INFO: sm[97872]: sm_service_fsm.c(1032): Service (ceph-radosgw) received event (enable-throttle) was in the disabled state and is now in the enabling-throttle state.

2019-07-26 18:41:58.119 7fb018724700 -1 mon.controller@0(leader) e1 *** Got Signal Terminated ***

2019-07-26T18:42:09.083 |       1236 | service-scn          | ceph-mon                         | disabling-failed                 | disabled-failed                  | disable success 
2019-07-26 18:42:20.673 1799045 INFO keystoneauth.session [-] Failure: Unable to establish connection to http://192.168.204.2:5000/v3/auth/tokens: HTTPConnectionPool(host='192.168.204.2', port=5000): Max retries exceeded with url: /v3/auth/tokens (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fbed4149710>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)). Retrying in 0.5s.
2019-07-26 18:42:21.311 1799045 INFO keystoneauth.session [-] Failure: Unable to establish connection to http://192.168.204.2:5000/v3/auth/tokens: HTTPConnectionPool(host='192.168.204.2', port=5000): Max retries exceeded with url: /v3/auth/tokens (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fbed32b5bd0>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)). Retrying in 1.0s.
2019-07-26 18:42:22.322 1799045 INFO keystoneauth.session [-] Failure: Unable to establish connection to http://192.168.204.2:5000/v3/auth/tokens: HTTPConnectionPool(host='192.168.204.2', port=5000): Max retries exceeded with url: /v3/auth/tokens (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fbed38990d0>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)). Retrying in 2.0s.
2019-07-26 18:42:24.370 1799045 CRITICAL keystonemiddleware.auth_token [-] Unable to validate token: Unable to establish connection to http://192.168.204.2:5000/v3/auth/tokens: HTTPConnectionPool(host='192.168.204.2', port=5000): Max retries exceeded with url: /v3/auth/tokens (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fbed32aa690>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',))
2019-07-26 18:42:42.461 1798378 INFO sysinv.conductor.kube_app [-] Armada service started!
2019-07-26 18:42:42.470 1798378 INFO sysinv.conductor.kube_app [-] Armada apply command = /bin/bash -c 'set -o pipefail; armada apply --debug /manifests/stx-openstack/1.0-17-centos-stable-versioned/stx-openstack-stx-openstack.yaml --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/kube-system-ingress.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-ingress.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-nginx-ports-control.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-mariadb.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-garbd.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-memcached.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-rabbitmq.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-keystone.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-barbican.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-glance.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-cinder.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-ceph-rgw.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-libvirt.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-nova.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-nova-api-proxy.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-neutron.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-placement.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-heat.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-horizon.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-aodh.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-gnocchi.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-panko.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-ceilometer.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-keystone-api-proxy.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-openvswitch.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/helm-toolkit-helm-toolkit.yaml  --values /overrides/stx-openstack/1.0-17-centos-stable-versioned/openstack-ironic.yaml --values /manifests/stx-openstack/1.0-17-centos-stable-versioned/m-armada-manifest-meta.yaml  --values /manifests/stx-openstack/1.0-17-centos-stable-versioned/cg-openstack-mariadb-meta.yaml --tiller-host tiller-deploy.kube-system.svc.cluster.local | tee /logs/stx-openstack-apply.log'
2019-07-26 18:43:04.664 1798532 INFO oslo_service.service [-] Caught SIGTERM, stopping children
2019-07-26 18:43:13.053 1798378 INFO sysinv.conductor.kube_app [-] Exiting progress monitoring thread for app stx-openstack

2019-07-26 18:45:36,530 126812 WARNING mgr-restful-plugin REST API ping failed: reason=HTTPSConnectionPool(host='controller-1', port=5001): Read timed out. (read timeout=15)
2019-07-26 18:45:36,530 126812 INFO mgr-restful-plugin REST API ping failure count=0
2019-07-26 18:45:37,830 128056 WARNING mgr-restful-plugin REST API ping failed: reason=HTTPSConnectionPool(host='controller-1', port=5001): Read timed out. (read timeout=15)
2019-07-26 18:45:37,846 128056 INFO mgr-restful-plugin REST API ping failure count=0
2019-07-26 18:45:37,846 128056 INFO mgr-restful-plugin Run command: /usr/bin/ceph fsid
2019-07-26 18:45:47,877 126516 INFO mgr-restful-plugin Restful plugin does not respond but failure count is within acceptable limits:  ceph_mgr=0 < 3, ping=0 < 5. Report status OK
2019-07-26 18:45:47,878 126516 WARNING mgr-restful-plugin Failed to send response back. request=status, response=OK, reason=[Errno 32] Broken pipe
2019-07-26 18:45:47,878 126812 INFO mgr-restful-plugin Run command: /usr/bin/ceph fsid
2019-07-26 18:45:53,422 128037 INFO mgr-restful-plugin Restful plugin does not respond but failure count is within acceptable limits:  ceph_mgr=0 < 3, ping=1 < 5. Report status OK
2019-07-26 18:46:02,899 126516 INFO mgr-restful-plugin Restful plugin does not respond but failure count is within acceptable limits:  ceph_mgr=0 < 3, ping=1 < 5. Report status OK
2019-07-26 18:46:02,900 126516 WARNING mgr-restful-plugin Failed to send response back. request=status, response=OK, reason=[Errno 32] Broken pipe
2019-07-26 18:46:02,900 126516 INFO mgr-restful-plugin Stop monitor with SIGTERM to process group 126812
2019-07-26 18:46:07,901 126516 INFO mgr-restful-plugin Stop monitor with SIGKILL to process group 126812
2019-07-26 18:46:07,903 126516 INFO mgr-restful-plugin Monitor stopped: pid=126812
2019-07-26 18:46:07,903 126516 INFO mgr-restful-plugin Remove service pid file: path=/var/run/ceph/mgr-restful-plugin.pid
2019-07-26 18:46:07,904 126516 INFO mgr-restful-plugin Close service socket and remove file: path=/var/run/ceph/mgr/mgr-restful-plugin.socket
2019-07-26 18:46:07,904 126516 INFO mgr-restful-plugin Release service lock: path=/var/run/ceph/mgr/mgr-restful-plugin.lock
2019-07-26 18:46:08,024 128056 WARNING mgr-restful-plugin Command timeout: command=['/usr/bin/timeout', '30', '/usr/bin/ceph', 'fsid'], timeout=30

2019-07-26T18:47:03.000 controller-1 sm: debug time[12863.282] log<21671> INFO: sm[97872]: sm_service_table.c(67): Cleared previous failure condition for service (mgr-restful-plugin) in enabled-activetate.
2019-07-26T18:47:03.000 controller-1 sm: debug time[12863.282] log<21672> INFO: sm[97872]: sm_service_enabled_active_state.c(292): Service (mgr-restful-plugin) audit success as recovered.

2019-07-26 18:47:35.743 7fd370d83140  0 ceph version 13.2.2 (00071a2d9e839b95f9439daaccd4677c5d15eaa6) mimic (stable), process ceph-mon, pid 182505

2019-07-26 18:47:55.631 185734 INFO sysinv.conductor.kube_app [-] Resetting status of app stx-openstack from 'applying' to 'apply-failed'
2019-07-26 18:47:55.654 185734 WARNING urllib3.connectionpool [-] Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f190>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)': /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock
2019-07-26 18:47:55.655 185734 WARNING urllib3.connectionpool [-] Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f2d0>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)': /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock
2019-07-26 18:47:55.655 185734 WARNING urllib3.connectionpool [-] Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f410>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',)': /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock
2019-07-26 18:47:55.657 185734 ERROR sysinv.common.kubernetes [-] Failed to delete custom object, Namespace kube-system: HTTPSConnectionPool(host='192.168.206.2', port=6443): Max retries exceeded with url: /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb81bc5f390>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',))

Revision history for this message

Ghada Khalil (gkhalil) wrote on 2019-08-23:

As per agreement with the community, moving all unresolved medium priority bugs from stx.2.0 to stx.3.0

tags:

added: stx.3.0
removed: stx.2.0

Revision history for this message

Bob Church (rchurch) wrote on 2019-09-11:

Marking this as a duplicate of bug #1837750. This apply restructuring will avoid the failure scenario by conditionally applying the application after the unlock of the controller is complete.

Additionally, there have been performance improvements for the AIO-DX which will improve sm responsiveness.

No additional change are required to address this.

Revision history for this message

Ghada Khalil (gkhalil) wrote on 2019-10-09:

Duplicate bug was fixed by:
https://review.opendev.org/677845
https://review.opendev.org/677847
Merged on 2019-08-22

Marked as Fix Released