Bug 1956269

Summary: UC install fails on rabbitmq-server: Error when reading /var/lib/rabbitmq/.erlang.cookie: eacces
Product: Red Hat OpenStack Reporter: Pavel Sedlák <psedlak>
Component: puppet-rabbitmqAssignee: RHOS Maint <rhos-maint>
Status: CLOSED DUPLICATE QA Contact: nlevinki <nlevinki>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 13.0 (Queens)CC: jjoyce, jschluet, michele, slinaber, tvignaud
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-05-03 11:45:50 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
undercloud_install.log none

Description Pavel Sedlák 2021-05-03 11:09:48 UTC 
In OSP 13 Undercloud install fails:
> 2021-05-02 13:25:49,540 INFO: ESC[mNotice: /Stage[main]/Keystone::Db::Mysql/Openstacklib::Db::Mysql[keystone]/Openstacklib::Db::Mysql::Host_access[keystone_192.168.24.1]/Mysql_grant[keystone.24.1/keystone.*]/ensure: createdESC[0m 2021-05-02 13:25:49,574 INFO: ESC[mNotice: /Stage[main]/Keystone::Deps/Anchor[keystone::db::end]: Triggered 'refresh' from 1 eventsESC[0m
> 2021-05-02 13:25:49,575 INFO: ESC[mNotice: /Stage[main]/Keystone::Deps/Anchor[keystone::dbsync::begin]: Triggered 'refresh' from 1 eventsESC[0m
> 2021-05-02 13:25:54,186 INFO: ESC[mNotice: /Stage[main]/Keystone::Db::Sync/Exec[keystone-manage db_sync]/returns: executed successfullyESC[0m
> 2021-05-02 13:25:55,678 INFO: ESC[mNotice: /Stage[main]/Keystone::Db::Sync/Exec[keystone-manage db_sync]: Triggered 'refresh' from 3 eventsESC[0m
> 2021-05-02 13:25:55,681 INFO: ESC[mNotice: /Stage[main]/Keystone::Deps/Anchor[keystone::dbsync::end]: Triggered 'refresh' from 2 eventsESC[0m
> 2021-05-02 13:25:57,437 INFO: ESC[mNotice: /Stage[main]/Keystone/Exec[keystone-manage bootstrap]: Triggered 'refresh' from 1 eventsESC[0m
> 2021-05-02 13:25:57,440 INFO: ESC[mNotice: /Stage[main]/Keystone::Deps/Anchor[keystone::service::begin]: Triggered 'refresh' from 6 eventsESC[0m
> 2021-05-02 13:25:57,443 INFO: ESC[mNotice: /Stage[main]/Apache::Service/Service[httpd]: Dependency Service[rabbitmq-server] has failures: trueESC[0m
> 2021-05-02 13:25:57,444 INFO: ESC[1;33mWarning: /Stage[main]/Apache::Service/Service[httpd]: Skipping because of failed dependenciesESC[0m
> 2021-05-02 13:25:57,448 INFO: ESC[mNotice: /Stage[main]/Keystone::Deps/Anchor[keystone::service::end]: Dependency Service[rabbitmq-server] has failures: trueESC[0m
> 2021-05-02 13:25:57,448 INFO: ESC[1;33mWarning: /Stage[main]/Keystone::Deps/Anchor[keystone::service::end]: Skipping because of failed dependenciesESC[0m
> 2021-05-02 13:25:57,449 INFO: ESC[mNotice: /Stage[main]/Ironic::Deps/Anchor[ironic::service::end]: Dependency Service[rabbitmq-server] has failures: trueESC[0m
> 2021-05-02 13:25:57,449 INFO: ESC[1;33mWarning: /Stage[main]/Ironic::Deps/Anchor[ironic::service::end]: Skipping because of failed dependenciesESC[0m
> 2021-05-02 13:28:49,813 INFO: ESC[1;31mError: Failed to apply catalog: Execution of '/bin/openstack role list --quiet --format csv' returned 1: Unable to establish connection to http://192.168.24.1:35357/v3/roles?: HTTPConnectionPool(host=
> '192.168.24.1', port=35357): Max retries exceeded with url: /v3/roles (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x7f1ae64adc50>: Failed to establish a new connection: [Errno 111] Connecti
> on refused',)) (tried 44, for a total of 170 seconds)ESC[0m
> 2021-05-02 13:28:49,814 INFO: Changes:
> 2021-05-02 13:28:49,814 INFO:             Total: 994
> 2021-05-02 13:28:49,814 INFO: Events:
> 2021-05-02 13:28:49,815 INFO:           Failure: 1
> 2021-05-02 13:28:49,815 INFO:           Success: 994
> 2021-05-02 13:28:49,816 INFO:             Total: 995
> 2021-05-02 13:28:49,816 INFO: Resources:
> 2021-05-02 13:28:49,816 INFO:            Failed: 1
> 2021-05-02 13:28:49,817 INFO:             Total: 2691
> 2021-05-02 13:28:49,817 INFO:           Skipped: 6
> 2021-05-02 13:28:49,817 INFO:         Restarted: 96
> 2021-05-02 13:28:49,817 INFO:           Changed: 983
> 2021-05-02 13:28:49,818 INFO:       Out of sync: 984
> 2021-05-02 13:28:49,818 INFO: Time:
> 2021-05-02 13:28:49,818 INFO:    Glance image import config: 0.00
> 2021-05-02 13:28:49,818 INFO:    Neutron api config: 0.00
> 2021-05-02 13:28:49,819 INFO:        Policy rcd: 0.00
> 2021-05-02 13:28:49,819 INFO:         Resources: 0.00
> 2021-05-02 13:28:49,819 INFO:       Concat file: 0.00
> 2021-05-02 13:28:49,819 INFO:      Swift config: 0.00
> 2021-05-02 13:28:49,819 INFO:    Nova paste api ini: 0.00
> 2021-05-02 13:28:49,820 INFO:    Glance swift config: 0.01
> 2021-05-02 13:28:49,820 INFO:    Concat fragment: 0.01
> 2021-05-02 13:28:49,820 INFO:            Sysctl: 0.01
> 2021-05-02 13:28:49,820 INFO:    Neutron l3 agent config: 0.01
> 2021-05-02 13:28:49,821 INFO:    Swift object expirer config: 0.01
> 2021-05-02 13:28:49,821 INFO:    Ironic neutron agent config: 0.01
> 2021-05-02 13:28:49,821 INFO:    Neutron plugin ml2: 0.03
> 2021-05-02 13:28:49,821 INFO:    Neutron dhcp agent config: 0.03
> 2021-05-02 13:28:49,822 INFO:    Neutron agent ovs: 0.04
> 2021-05-02 13:28:49,822 INFO:             Group: 0.04
> 2021-05-02 13:28:49,822 INFO:    Sysctl runtime: 0.08
> 2021-05-02 13:28:49,822 INFO:         Vs bridge: 0.09
> 2021-05-02 13:28:49,822 INFO:              User: 0.10
> 2021-05-02 13:28:49,823 INFO:              Cron: 0.10
> 2021-05-02 13:28:49,823 INFO:    Glance cache config: 0.13
> 2021-05-02 13:28:49,823 INFO:    Swift proxy config: 0.15
> 2021-05-02 13:28:49,823 INFO:    Mistral config: 0.17
> 2021-05-02 13:28:49,824 INFO:            Anchor: 0.23
> 2021-05-02 13:28:49,824 INFO:    Glance registry config: 0.36
> 2021-05-02 13:28:49,824 INFO:    Mysql database: 0.53
> 2021-05-02 13:28:49,824 INFO:    Ring object device: 0.68
> 2021-05-02 13:28:49,824 INFO:    Ring container device: 0.72
> 2021-05-02 13:28:49,825 INFO:    Ironic inspector config: 0.77
> 2021-05-02 13:28:49,825 INFO:            Augeas: 1.13
> 2021-05-02 13:28:49,825 INFO:      Zaqar config: 1.19
> 2021-05-02 13:28:49,825 INFO:    Ring account device: 1.22
> 2021-05-02 13:28:49,826 INFO:              File: 1.62
> 2021-05-02 13:28:49,826 INFO:       Mysql grant: 1.68
> 2021-05-02 13:28:49,826 INFO:       Heat config: 1.91
> 2021-05-02 13:28:49,826 INFO:     Mysql datadir: 10.39
> 2021-05-02 13:28:49,826 INFO:    Rabbitmq plugin: 12.07
> 2021-05-02 13:28:49,827 INFO:       Nova config: 14.69
> 2021-05-02 13:28:49,827 INFO:          Last run: 1619976529
> 2021-05-02 13:28:49,827 INFO:    Keystone config: 2.02
> 2021-05-02 13:28:49,827 INFO:    Neutron config: 2.35
> 2021-05-02 13:28:49,827 INFO:    Glance api config: 2.50
> 2021-05-02 13:28:49,827 INFO:        Mysql user: 2.50
> 2021-05-02 13:28:49,827 INFO:      Nova cell v2: 2.99
> 2021-05-02 13:28:49,828 INFO:    Config retrieval: 20.78
> 2021-05-02 13:28:49,828 INFO:           Service: 21.74
> 2021-05-02 13:28:49,828 INFO:          Firewall: 30.20
> 2021-05-02 13:28:49,828 INFO:           Package: 370.61
> 2021-05-02 13:28:49,828 INFO:     Ironic config: 5.82
> 2021-05-02 13:28:49,828 INFO:              Exec: 55.81
> 2021-05-02 13:28:49,828 INFO:             Total: 567.57
> 2021-05-02 13:28:49,828 INFO: Version:
> 2021-05-02 13:28:49,828 INFO:            Config: 1619975711
> 2021-05-02 13:28:49,828 INFO:            Puppet: 4.8.2
> 2021-05-02 13:28:59,386 INFO: + rc=1
> 2021-05-02 13:28:59,386 INFO: + set -e
> 2021-05-02 13:28:59,386 INFO: + echo 'puppet apply exited with exit code 1'
> 2021-05-02 13:28:59,386 INFO: puppet apply exited with exit code 1
> 2021-05-02 13:28:59,386 INFO: + '[' 1 '!=' 2 -a 1 '!=' 0 ']'
> 2021-05-02 13:28:59,386 INFO: + exit 1
> 2021-05-02 13:28:59,400 INFO: [2021-05-02 13:28:59,389] (os-refresh-config) [ERROR] during configure phase. [Command '['dib-run-parts', '/usr/libexec/os-refresh-config/configure.d']' returned non-zero exit status 1]
> 2021-05-02 13:28:59,400 INFO: 
> 2021-05-02 13:28:59,401 INFO: [2021-05-02 13:28:59,390] (os-refresh-config) [ERROR] Aborting...
> 2021-05-02 13:28:59,414 DEBUG: An exception occurred
> Traceback (most recent call last):
>   File "/usr/lib/python2.7/site-packages/instack_undercloud/undercloud.py", line 2449, in install
>     _run_orc(instack_env)
>   File "/usr/lib/python2.7/site-packages/instack_undercloud/undercloud.py", line 1621, in _run_orc
>     _run_live_command(args, instack_env, 'os-refresh-config')
>   File "/usr/lib/python2.7/site-packages/instack_undercloud/undercloud.py", line 678, in _run_live_command
>     raise RuntimeError('%s failed. See log for details.' % name)
> RuntimeError: os-refresh-config failed. See log for details.
> 2021-05-02 13:28:59,419 ERROR: 
> #############################################################################
> Undercloud install failed.
> 
> Reason: os-refresh-config failed. See log for details.
> 
> See the previous output for details about what went wrong.  The full install
> log can be found at /home/stack/.instack/install-undercloud.log.
> 
> #############################################################################
> 
> Traceback (most recent call last):
>   File "<string>", line 1, in <module>
>   File "/usr/lib/python2.7/site-packages/instack_undercloud/undercloud.py", line 2449, in install
>     _run_orc(instack_env)
>   File "/usr/lib/python2.7/site-packages/instack_undercloud/undercloud.py", line 1621, in _run_orc
>     _run_live_command(args, instack_env, 'os-refresh-config')
>   File "/usr/lib/python2.7/site-packages/instack_undercloud/undercloud.py", line 678, in _run_live_command
>     raise RuntimeError('%s failed. See log for details.' % name)
> RuntimeError: os-refresh-config failed. See log for details.
> Command 'instack-install-undercloud' returned non-zero exit status 1

rabbimq-server failed to start:
> [root@undercloud-0 ~]# journalctl -u rabbitmq-server
> -- Logs begin at Sun 2021-05-02 13:11:25 EDT, end at Mon 2021-05-03 06:04:30 EDT. --
> May 02 13:24:02 undercloud-0.redhat.local systemd[1]: Starting RabbitMQ broker...
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: 2021-05-02 13:24:02.680439
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: args: []
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: format: "Error when reading /var/lib/rabbitmq/.erlang.cookie: eacces"
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: label: {error_logger,error_msg}
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: 2021-05-02 13:24:02.680954 crash_report        #{label=>{proc_lib,crash},report=>[[{initial_call,{auth,init,['Argument__1']}},{pid,<0.58.0>},{registered_name,[]},{error_info
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: 2021-05-02 13:24:02.681478 supervisor_report   #{label=>{supervisor,start_error},report=>[{supervisor,{local,net_sup}},{errorContext,start_error},{reason,{"Error when readin
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: 2021-05-02 13:24:02.685022 supervisor_report   #{label=>{supervisor,start_error},report=>[{supervisor,{local,kernel_sup}},{errorContext,start_error},{reason,{shutdown,{faile
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: 2021-05-02 13:24:02.687229 crash_report        #{label=>{proc_lib,crash},report=>[[{initial_call,{application_master,init,['Argument__1','Argument__2','Argument__3','Argumen
> May 02 13:24:02 undercloud-0.redhat.local rabbitmq-server[27039]: 2021-05-02 13:24:02.690051 std_info            #{label=>{application_controller,exit},report=>[{application,kernel},{exited,{{shutdown,{failed_to_start_child,net_sup,{shutdo
> May 02 13:24:03 undercloud-0.redhat.local rabbitmq-server[27039]: {"Kernel pid terminated",application_controller,"{application_start_failure,kernel,{{shutdown,{failed_to_start_child,net_sup,{shutdown,{failed_to_start_child,auth,{\"Error w
> May 02 13:24:03 undercloud-0.redhat.local rabbitmq-server[27039]: Kernel pid terminated (application_controller) ({application_start_failure,kernel,{{shutdown,{failed_to_start_child,net_sup,{shutdown,{failed_to_start_child,auth,{"Error whe
> May 02 13:24:03 undercloud-0.redhat.local rabbitmq-server[27039]: Crash dump is being written to: /var/log/rabbitmq/erl_crash.dump...done
> May 02 13:24:03 undercloud-0.redhat.local systemd[1]: rabbitmq-server.service: main process exited, code=exited, status=1/FAILURE
> May 02 13:24:03 undercloud-0.redhat.local systemd[1]: Failed to start RabbitMQ broker.
> May 02 13:24:03 undercloud-0.redhat.local systemd[1]: Unit rabbitmq-server.service entered failed state.
> May 02 13:24:03 undercloud-0.redhat.local systemd[1]: rabbitmq-server.service failed.

seems that /var/lib/rabbitmq/.erlang.cookie file is owned by root user not rabbitmq:
> [root@undercloud-0 ~]# ll /var/lib/rabbitmq/ -a
> total 8
> drwxr-x---.  3 rabbitmq rabbitmq   42 May  2 13:24 .
> drwxr-xr-x. 61 root     root     4096 May  2 13:23 ..
> -r--------.  1 root     root       20 May  2 00:00 .erlang.cookie
> drwxr-xr-x.  2 rabbitmq rabbitmq   37 May  2 13:24 mnesia

versions involved:
> [root@undercloud-0 ~]# rpm -qa|grep -i tripleo
> openstack-tripleo-puppet-elements-8.1.1-2.el7ost.noarch
> openstack-tripleo-common-8.7.1-29.el7ost.noarch
> openstack-tripleo-image-elements-8.0.3-3.el7ost.noarch
> python-tripleoclient-9.3.1-10.el7ost.noarch
> puppet-tripleo-8.5.1-24.el7ost.noarch
> ansible-tripleo-ipsec-8.1.1-0.20190513184007.7eb892c.el7ost.noarch
> openstack-tripleo-heat-templates-8.4.1-84.el7ost.noarch
> openstack-tripleo-ui-8.3.2-3.el7ost.noarch
> openstack-tripleo-validations-8.5.0-8.el7ost.noarch
> openstack-tripleo-common-containers-8.7.1-29.el7ost.noarch
> [root@undercloud-0 ~]# rpm -qa|grep -i rabbit
> puppet-rabbitmq-9.0.1-0.20190729134437.7613f08.el7ost.noarch
> rabbitmq-server-3.7.28-1.el7ost.x86_64


After manually `chown rabbitmq:rabbitmq /var/lib/rabbitmq/.erlang.cookie`
seems that `systemctl start rabbitmq-server` works normally.
As also `openstack undercloud install` passed then, and keystone is working.
Comment 2 Pavel Sedlák 2021-05-03 11:21:04 UTC 
Created attachment 1778913 [details]
undercloud_install.log
Comment 3 Michele Baldessari 2021-05-03 11:45:50 UTC 

*** This bug has been marked as a duplicate of bug 1956235 ***