Bug 1393587 - ejabberd does not start after upgrading Fedora 24 to Fedora 25
Summary: ejabberd does not start after upgrading Fedora 24 to Fedora 25
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: ejabberd
Version: 25
Hardware: All
OS: Linux
high
urgent
Target Milestone: ---
Assignee: Randy Barlow
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-11-09 22:36 UTC by Randy Barlow
Modified: 2016-11-27 23:40 UTC (History)
6 users (show)

Fixed In Version: ejabberd-16.09-2.fc26
Clone Of:
Environment:
Last Closed: 2016-11-27 23:40:34 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Randy Barlow 2016-11-09 22:36:49 UTC
Description of problem:
Today I upgraded my ejabberd server from Fedora 24 to Fedora 25, and after the upgrade ejabberd fails to start.


Version-Release number of selected component (if applicable):
$ rpm -q ejabberd
ejabberd-16.08-2.fc25.x86_64


How reproducible:
Every time.


Steps to Reproduce:
1. Try to start ejabberd on Fedora 25.


Actual results:
It fails to start, though the systemd unit reports success.


Expected results:
It should start.


Additional info:
In journald, I see this:

Nov 09 17:31:46 flag.electronsweatshop.com systemd[1]: ejabberd.service: Failed with result 'exit-code'.
Nov 09 17:31:46 flag.electronsweatshop.com systemd[1]: Starting A distributed, fault-tolerant Jabber/XMPP server...
Nov 09 17:31:46 flag.electronsweatshop.com audit: SELINUX_ERR op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:initrc_t:s0
Nov 09 17:31:46 flag.electronsweatshop.com bash[785]: /usr/bin/bash: /usr/bin/ejabberdctl: Permission denied
Nov 09 17:31:46 flag.electronsweatshop.com audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=ejabberd comm="systemd" exe="/usr/lib/systemd/systemd" hostn
Nov 09 17:31:46 flag.electronsweatshop.com systemd[1]: ejabberd.service: Main process exited, code=exited, status=126/n/a

Comment 1 Randy Barlow 2016-11-10 02:46:13 UTC
I'm noticing that there is a difference in permissions between Fedora 24's ejabberdctl and Fedora 25's:

$ rpm -q ejabberd
ejabberd-16.01-5.fc24.x86_64
$ ls -lah /usr/bin/ejabberdctl 
-rwxr-xr-x. 1 root root 16K Apr 15  2016 /usr/bin/ejabberdctl

vs.

$ rpm -q ejabberd
ejabberd-16.08-2.fc25.x86_64
$ ls -lah /usr/bin/ejabberdctl
-r-xr-x---. 1 root root 14K Aug 18 09:17 /usr/bin/ejabberdctl

Changing the permissions back to the old format does get ejabberd's startup closer to working, but it seems to still fail on SELinux denials. Strangely enough, ejabberdctl seems to be getting installed as rabbitmq_exec_t (on Fedora 24 as well):

# ls -lahZ /usr/bin/ejabberdctl 
-rwxr-xr-x. 1 root root system_u:object_r:rabbitmq_exec_t:s0 14K Aug 18 09:17 /usr/bin/ejabberdctl

# audit2allow -a


#============= init_t ==============
allow init_t epmd_port_t:tcp_socket name_connect;

#!!!! WARNING: 'etc_t' is a base type.
allow init_t etc_t:file write;
allow init_t jabber_interserver_port_t:tcp_socket name_connect;
allow init_t rabbitmq_exec_t:file ioctl;
allow init_t rabbitmq_var_lib_t:dir { add_name read remove_name write };
allow init_t rabbitmq_var_lib_t:file { create getattr open read rename unlink write };
allow init_t rabbitmq_var_log_t:dir { read write };
allow init_t rabbitmq_var_log_t:file { append getattr open read write };


I'm not sure exactly what is happening here, but it does seem that the policy in Fedora 25 is more restrictive than it was in Fedora 24. There may also be some connection to starting ejabberd with bash in the unit file:

ExecStart=/usr/bin/bash /usr/bin/ejabberdctl…

I'm not completely clear on why that is done, but it could be related.

Comment 2 Randy Barlow 2016-11-10 03:57:40 UTC
These are the messages in audit.log:

type=SELINUX_ERR msg=audit(1478750215.370:619): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:rabbitmq_t:s0
type=AVC msg=audit(1478750215.374:620): avc:  denied  { ioctl } for  pid=2734 comm="ejabberdctl" path="/usr/bin/ejabberdctl" dev="dm-1" ino=33568917 ioctlcmd=0x5401 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:rabbitmq_exec_t:s0 tclass=file permissive=0
type=SELINUX_ERR msg=audit(1478750215.379:621): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.383:622): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.388:623): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.393:624): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.398:625): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.405:626): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.407:627): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=AVC msg=audit(1478750215.412:628): avc:  denied  { name_connect } for  pid=2741 comm="epmd" dest=4369 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:epmd_port_t:s0 tclass=tcp_socket permissive=0
type=AVC msg=audit(1478750215.414:629): avc:  denied  { name_connect } for  pid=2741 comm="epmd" dest=4369 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:epmd_port_t:s0 tclass=tcp_socket permissive=0
type=SELINUX_ERR msg=audit(1478750215.421:630): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:initrc_t:s0
type=SELINUX_ERR msg=audit(1478750215.424:631): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.430:632): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.435:633): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.438:634): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:initrc_t:s0
type=SELINUX_ERR msg=audit(1478750215.442:635): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SERVICE_START msg=audit(1478750215.450:636): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=ejabberd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
type=SELINUX_ERR msg=audit(1478750215.457:637): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=SELINUX_ERR msg=audit(1478750215.481:638): op=security_bounded_transition seresult=denied oldcontext=system_u:system_r:init_t:s0 newcontext=system_u:system_r:unconfined_service_t:s0
type=AVC msg=audit(1478750215.557:639): avc:  denied  { read } for  pid=2761 comm="async_8" name="ejabberd" dev="dm-1" ino=958170 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:rabbitmq_var_lib_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1478750215.559:640): avc:  denied  { write } for  pid=2761 comm="async_8" name="ejabberd" dev="dm-1" ino=958170 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:rabbitmq_var_lib_t:s0 tclass=dir permissive=0
type=AVC msg=audit(1478750215.606:641): avc:  denied  { name_connect } for  pid=2752 comm="beam" dest=4369 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:epmd_port_t:s0 tclass=tcp_socket permissive=0

Comment 3 Randy Barlow 2016-11-10 04:28:49 UTC
gholms pointed out that the "NoNewPrivileges=true" line in the unit file causes processes to be disallowed to transition SELinux contexts:

https://github.com/systemd/systemd/issues/3845

I dropped that line and now things work again. However, it was noted that the unit file was also launching ejabberd with /usr/bin/bash which gets a very permissive context. I attempted to drop bash and run ejabberdctl directly with the unit file and that resulted in these denials:

type=SERVICE_START msg=audit(1478751169.449:647): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=ejabberd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
type=AVC msg=audit(1478751171.862:648): avc:  denied  { write } for  pid=2989 comm="async_2" name="ejabberd.pem" dev="dm-1" ino=44546 scontext=system_u:system_r:rabbitmq_t:s0 tcontext=unconfined_u:object_r:etc_t:s0 tclass=file permissive=0
type=AVC msg=audit(1478751171.863:649): avc:  denied  { write } for  pid=2989 comm="async_2" name="ejabberd.pem" dev="dm-1" ino=44546 scontext=system_u:system_r:rabbitmq_t:s0 tcontext=unconfined_u:object_r:etc_t:s0 tclass=file permissive=0
type=AVC msg=audit(1478751171.865:650): avc:  denied  { name_bind } for  pid=2986 comm="beam" src=5349 scontext=system_u:system_r:rabbitmq_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=tcp_socket permissive=0

The ejabberd.pem file looks like this, and a restorecon does not alter it:

-rw-------. 1 ejabberd ejabberd unconfined_u:object_r:etc_t:s0 9.8K Oct 15 11:33 /etc/ejabberd/ejabberd.pem

That last denial is about a failure to open port 5349, which is used by ejabberd's built-in STUN server.

Comment 4 Randy Barlow 2016-11-10 04:48:46 UTC
Here is the plan:

0) File an issue against selinux-policy requesting to allow ejabberd to open tcp 5349.
1) Contact upstream to ask why ejabberd is trying to write the pem file. Hopefully we can fix that.
2) Set the basic Unix permissions to allow the ejabberd user to exec ejabberdctl.
3) Drop the NoNewPrivileges=true from the unit file.
4) Release a new ejabberd with the fixes from #2 and #3.
5) Once we get movement on both 0 and 1, we can drop bash from the unit file and drop to a confined policy, and release yet another ejabberd.

Comment 5 Randy Barlow 2016-11-10 04:56:13 UTC
I've filed an issue against selinux-policy to ask for ejabberd to be allowed to use tcp 5349: https://bugzilla.redhat.com/show_bug.cgi?id=1393643

Comment 6 Randy Barlow 2016-11-10 05:21:41 UTC
I've filed https://github.com/processone/ejabberd/issues/1375 about the certfile being opened in write mode.

Comment 7 Randy Barlow 2016-11-10 05:35:11 UTC
I've filed https://bugzilla.redhat.com/show_bug.cgi?id=1393649 to track dropping /usr/bin/bash from the unit file.

Comment 8 Randy Barlow 2016-11-10 06:17:26 UTC
I've filed https://github.com/processone/ejabberd/issues/1376 with upstream about the NoNewPrivileges=true line in their example unit file.

Comment 9 Randy Barlow 2016-11-10 06:57:09 UTC
It's been a long night of debugging. I've gotten this fixed in Rawhide, but not in Fedora 25. It seems that Fedora 25 is FTBFS still. Since Fedora 25 is broken currently, I am leaning towards going ahead and merging the Rawhide branch over to F25 to fix this issue at the same time as fixing the FTBFS that was also already fixed in Fedora 25. Since no users could possibly have been using an ejabberd that is this broken, I don't think we have to worry about backwards incompatibility with upgrading from 16.08 to 16.09.

Additionally, I happen to know that 16.08 had an upstream issue that prevented ejabberdctl from being able to register users. I had been thinking of backporting the patch that fixes that issue, but it may be easier to simply upgrade to 16.09 where it is fixed upstream.

Comment 10 Jeremy Cline 2016-11-10 14:32:06 UTC
+1 on bumping the version since it's been clearly broken and unused.

Comment 11 Fedora Update System 2016-11-10 18:44:02 UTC
ejabberd-16.09-2.fc25 erlang-esip-1.0.8-1.fc25 erlang-fast_tls-1.0.7-1.fc25 erlang-fast_yaml-1.0.6-1.fc25 erlang-fast_xml-1.1.15-1.fc25 erlang-iconv-1.0.2-1.fc25 erlang-stringprep-1.0.6-1.fc25 erlang-stun-1.0.7-1.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2016-b5f8025233

Comment 12 Fedora Update System 2016-11-11 16:56:40 UTC
ejabberd-16.09-2.fc25, erlang-esip-1.0.8-1.fc25, erlang-fast_tls-1.0.7-1.fc25, erlang-fast_xml-1.1.15-1.fc25, erlang-fast_yaml-1.0.6-1.fc25, erlang-iconv-1.0.2-1.fc25, erlang-stringprep-1.0.6-1.fc25, erlang-stun-1.0.7-1.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-b5f8025233

Comment 13 Fedora Update System 2016-11-26 22:52:32 UTC
ejabberd-16.09-2.fc25, erlang-esip-1.0.8-1.fc25, erlang-fast_tls-1.0.7-1.fc25, erlang-fast_xml-1.1.15-1.fc25, erlang-fast_yaml-1.0.6-1.fc25, erlang-iconv-1.0.2-1.fc25, erlang-stringprep-1.0.6-1.fc25, erlang-stun-1.0.7-1.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.