Bug 1403186

Summary: cannot start postfix anymore with selinux
Product: [Fedora] Fedora Reporter: Frank Ansari <mail>
Component: selinux-policyAssignee: Lukas Vrabec <lvrabec>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: high    
Version: 25CC: dominick.grift, dwalsh, lvrabec, mgrepl, miguel, mike, pedemonte, plautrba, pmoore, sergio_nsk, ssekidde
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: selinux-policy-3.13.1-225.20.fc25 selinux-policy-3.13.1-225.22.fc25 selinux-policy-3.13.1-225.23.fc25 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-11-01 16:39:14 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
errors with original postfix-script
none
error messages when I remove /dev/null from line 122
none
After running .autorelabel
none
after applying policy 3.13.1-225.3 none

Description Frank Ansari 2016-12-09 11:31:29 UTC
Created attachment 1229935 [details]
errors with original postfix-script

Description of problem:
When I start postfix there is an error like this:

/usr/libexec/postfix/postfix-script: line 122: /dev/null: Permission denied

Version-Release number of selected component (if applicable):
Version     : 3.13.1
Release     : 225.1.fc25

How reproducible:
Set selinux to enforcing and try to start postfix.

Steps to Reproduce:
1.
2.
3.

Actual results:
postfix does not start.

Expected results:
postfix should start.

Additional info:
postfix:
Version     : 3.1.3
Release     : 2.fc25

audit2allow did not help this time. Probably there is something strange broken but I could not figure this out.

When I remove the /dev/null from line 122 I get other errors also related to /dev/null.

Comment 1 Frank Ansari 2016-12-09 11:32:10 UTC
Created attachment 1229936 [details]
error messages when I remove /dev/null from line 122

Comment 2 Frank Ansari 2016-12-09 11:33:58 UTC
root@bat postfix] # ls -Z /dev/null
system_u:object_r:null_device_t:s0 /dev/null

Starting postfix in permissive mode is possible of course.

Comment 3 Frank Ansari 2016-12-09 11:58:10 UTC
Created attachment 1229940 [details]
After running .autorelabel

I have put /.autorelabel and restarted the system. After the autorelabel has been done I have enabled SELinux again and restarted postfix. It again refused to start.

Comment 4 Lukas Vrabec 2016-12-09 12:02:27 UTC
Frank, 
Could you reproduce it with following build? 
http://koji.fedoraproject.org/koji/buildinfo?buildID=823721

Thanks.

Comment 5 Frank Ansari 2016-12-09 14:54:07 UTC
I have downloaded and installed these packages:

selinux-policy-3.13.1-225.3.fc25.noarch.rpm
selinux-policy-devel-3.13.1-225.3.fc25.noarch.rpm
selinux-policy-doc-3.13.1-225.3.fc25.noarch.rpm
selinux-policy-minimum-3.13.1-225.3.fc25.noarch.rpm
selinux-policy-mls-3.13.1-225.3.fc25.noarch.rpm
selinux-policy-sandbox-3.13.1-225.3.fc25.noarch.rpm
selinux-policy-targeted-3.13.1-225.3.fc25.noarch.rpm

The error is still the same.

Comment 6 Frank Ansari 2016-12-09 14:54:39 UTC
Created attachment 1230023 [details]
after applying policy 3.13.1-225.3

Comment 7 Lukas Vrabec 2016-12-09 23:49:58 UTC
This issue is fixed in 255.3 build.

Your system looks misslabeled. Please run:
# restorecon -Rv / 

Thanks.

Comment 8 Frank Ansari 2016-12-10 11:50:56 UTC
I tried this but it does not help. This is the same as the autorelabel I did before.

What did help to fix read access from /dev/null was this policies:


module my-master 1.0;

require {
	type postfix_master_t;
	type unlabeled_t;
	class file read;
}

#============= postfix_master_t ==============
allow postfix_master_t unlabeled_t:file read;


module my-pickup 1.0;

require {
	type postfix_pickup_t;
	type unlabeled_t;
	class file { read write };
	class dir search;
}

#============= postfix_pickup_t ==============
allow postfix_pickup_t unlabeled_t:dir search;

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_pickup_t unlabeled_t:file { read write };


But I guess this is not the solution of these issues. Problem will not be postfix selinux policies but something wrong with the labeling of my dev devices.

Unfortunately I have no idea how to fix this since restorecon does not help.

Comment 9 Frank Ansari 2016-12-10 13:53:49 UTC
This bug seems to be very similar to #1389863.

I have absolutely no idea what could be wrong with /dev/null.

So now I have removed /dev/null and recreated it.

All these SELinux alarms come from postfix.

I have done this:

rm /dev/null
mknod /dev/null c 1 3
chmod 666 /dev/null
chcon -u system_u /dev/null


And applied all these policies:

module my-master 1.0;

require {
	type postfix_master_t;
	type unlabeled_t;
	class file read;
}

#============= postfix_master_t ==============
allow postfix_master_t unlabeled_t:file read;


module my-grep 1.0;

require {
	type unlabeled_t;
	type postfix_master_t;
	class file { getattr ioctl };
}

#============= postfix_master_t ==============

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_master_t unlabeled_t:file { getattr ioctl };

module my-pickup 1.0;

require {
	type postfix_pickup_t;
	type unlabeled_t;
	class file { ioctl read write };
	class dir search;
}

#============= postfix_pickup_t ==============

#!!!! This avc is allowed in the current policy
allow postfix_pickup_t unlabeled_t:dir search;

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_pickup_t unlabeled_t:file ioctl;

#!!!! This avc is allowed in the current policy
allow postfix_pickup_t unlabeled_t:file { read write };

module my-qmgr 1.0;

require {
	type unlabeled_t;
	type postfix_qmgr_t;
	class file { ioctl read write };
	class dir search;
}

#============= postfix_qmgr_t ==============

#!!!! This avc is allowed in the current policy
allow postfix_qmgr_t unlabeled_t:dir search;

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_qmgr_t unlabeled_t:file ioctl;

#!!!! This avc is allowed in the current policy
allow postfix_qmgr_t unlabeled_t:file { read write };

module my-smtp 1.0;

require {
	type unlabeled_t;
	type postfix_smtp_t;
	class file { ioctl read write };
	class dir search;
}

#============= postfix_smtp_t ==============

#!!!! This avc is allowed in the current policy
allow postfix_smtp_t unlabeled_t:dir search;

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_smtp_t unlabeled_t:file ioctl;

#!!!! This avc is allowed in the current policy
allow postfix_smtp_t unlabeled_t:file { read write };

module my-cleanup 1.0;

require {
	type postfix_cleanup_t;
	type unlabeled_t;
	class dir search;
	class file { read write };
}

#============= postfix_cleanup_t ==============
allow postfix_cleanup_t unlabeled_t:dir search;

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_cleanup_t unlabeled_t:file { read write };

Comment 10 Frank Ansari 2016-12-10 19:13:40 UTC
I also had to add this now:

module my-bounce 1.0;

require {
	type postfix_bounce_t;
	type unlabeled_t;
	class file { read write };
	class dir search;
}

#============= postfix_bounce_t ==============
allow postfix_bounce_t unlabeled_t:dir search;

#!!!! The file '/dev/null' is mislabeled on your system.  
#!!!! Fix with $ restorecon -R -v /dev/null
allow postfix_bounce_t unlabeled_t:file { read write };

Comment 11 Frank Ansari 2016-12-17 16:52:37 UTC
This cannot be a problem of "/dev/null". I can remove /dev/null and it is recreated automatically after reboot.

Since postfix does not write any debug messages I have no idea where to start.

Now it is like this: whenever SELinux is in enforcing mode postfix refuses to send mails out but simply puts them into the queue without any log entry why this happens. I find the mails by running "postqueue -p".

When I then set SELinux to permissive mode and restart postfix the queue clears automatically and the mail is sent out. In this case the logfiles are written again.

How can this be debugged and fixed?

Comment 12 Frank Ansari 2016-12-17 19:34:43 UTC
I found something which might be a clue. When I start postfix in permissive mode so that the service really comes up and then start my PC from a USB key and mount the root volume I find a file "/dev/null" with size 0. This is the only file in /dev.

This looks strange because /dev is expected to be empty when it is not populated by a running system.

When I remove this file and restart my PC I find the file again after booting from USB key.

So my next step was to disable the postfix service and removing the /dev/null file again as described above. When I then boot the PC again and check again with USB boot in /dev I find it empty as it should be.

This /dev/null file is only created in permssive mode now because I have removed all this policies given above so that the postfix service is no longer able to start in enforcing mode.

So postfix seems to make some strange things on my system with /dev/null but until now I have no idea what it could be.

Comment 13 Frank Ansari 2016-12-17 19:42:48 UTC
I forgot to say that this /dev/null file I found is a normal file (no character device).

Also I have reinstalled postfix and tried to start the service with the configuration which comes with the package.

The first error messages look like this:

Dec 17 20:25:26 bat.localdomain systemd[1]: Starting Postfix Mail Transport Agent...
Dec 17 20:25:26 bat.localdomain audit[4550]: AVC avc:  denied  { search } for  pid=4550 comm="postfix" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:object_r:u
Dec 17 20:25:26 bat.localdomain audit[4550]: AVC avc:  denied  { search } for  pid=4550 comm="postfix-script" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:obj
Dec 17 20:25:26 bat.localdomain audit[4555]: AVC avc:  denied  { search } for  pid=4555 comm="postfix-script" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:obj
Dec 17 20:25:26 bat.localdomain audit[4555]: AVC avc:  denied  { search } for  pid=4555 comm="postfix-script" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:obj
Dec 17 20:25:26 bat.localdomain postfix[4550]: /usr/libexec/postfix/postfix-script: line 122: /dev/null: Permission denied
Dec 17 20:25:26 bat.localdomain audit[4556]: AVC avc:  denied  { search } for  pid=4556 comm="postlog" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:object_r:u
Dec 17 20:25:26 bat.localdomain audit[4556]: AVC avc:  denied  { search } for  pid=4556 comm="postlog" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:object_r:u
Dec 17 20:25:26 bat.localdomain audit[4556]: AVC avc:  denied  { search } for  pid=4556 comm="postlog" name="dev" dev="dm-1" ino=605628 scontext=system_u:system_r:postfix_master_t:s0 tcontext=system_u:object_r:u
Dec 17 20:25:27 bat.localdomain systemd[1]: postfix.service: Control process exited, code=exited status=1
Dec 17 20:25:27 bat.localdomain systemd[1]: Failed to start Postfix Mail Transport Agent.
Dec 17 20:25:27 bat.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=postfix comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr
Dec 17 20:25:27 bat.localdomain systemd[1]: postfix.service: Unit entered failed state.
Dec 17 20:25:27 bat.localdomain systemd[1]: postfix.service: Failed with result 'exit-code'.
Dec 17 20:25:30 bat.localdomain dbus-daemon[1773]: [system] Activating service name='org.fedoraproject.Setroubleshootd' requested by ':1.78' (uid=0 pid=1752 comm="/usr/sbin/sedispatch " label="system_u:system_r:
Dec 17 20:25:31 bat.localdomain dbus-daemon[1773]: [system] Successfully activated service 'org.fedoraproject.Setroubleshootd'

Comment 14 Frank Ansari 2016-12-24 12:15:51 UTC
I can reproduce this behaviour now. The issue started when I wanted to migrate my system to a new HDD with tarballs.

In order to reproduce do this:

1. Install a fresh Fedora 25. Create two extra volumes: testroot and backup.
2. Ensure that SELinux is in enforcing mode and start postfix. This will work.
3. Boot your system from USB stick and mount your partitions.
4. Create a tarball with "tar cvf" of the root volume and place it on the backup volume.
5. Unpack the tarball with "tar xvf" in the testroot volume.
6. Run "touch .autorelabel" in the testroot volume.
7. Reonfigure your system to use the testroot volume as root volume.
8. Reboot your system. This will run the relabeling. After this the system will reboot again.
9. After the reboot ensure that SELinux is in enforcing mode and try to start postfix. This will fail. Also a "restorecon -r -v /" does not help.

Now the next scenario:

10. Boot again from USB stick.
11. Wipe the testroot volume by creating a new file system.
12. Create a tarball with "tar --selinux -cvf" of the root volume and place it on the backup volume. 
13. Now unpack the tarball with "tar --selinux -xvf" in the testroot volume.
14. Run "touch .autorelabel" in the testroot volume.
15. Reboot your system. This will run the relabeling. After this the system will reboot again.
16. After the reboot ensure that SELinux is in enforcing mode and try to start postfix. This will work.

This means the only thing I did wrong is not using the --selinux option in tar for packing and unpacking the tarball for the root volume.

But now my question is: why is this? I was under the impression that relabeling either with autorelabel or restorecon should fix labeling. What is wrong with this?

Comment 15 Frank Ansari 2017-01-11 09:35:31 UTC
Please note #1411942 regarding this issue. 

I have PrivateDevices=true in /usr/lib/systemd/system/postfix.service.

Comment 16 Mike Goodwin 2017-06-29 14:54:54 UTC
I can confirm this behavior. I didn't bother to use --selinux on untarring when migrating to btrfs because I figured i'd just autorelabel, and I have also come across this issue

Comment 17 Mike Goodwin 2017-06-29 16:43:32 UTC

As noted here (dropping this comment for posterity): https://bugzilla.redhat.com/show_bug.cgi?id=1412696


What's really happening with --selinux untarring is that the /* folders are labeled properly.

The problem is that by the time relabling takes place, many folders underneath / are mounted and thus the underlying folder structure is unaffected by `restorecon` or autorelabling. 


In the above ticket the fix was to bind mount / with:

   sudo mount -o x-mount.mkdir --bind / /tmp/foo

and then fix the contexts based on what they are after mounting:

   sudo chcon --reference=/dev /tmp/foo/dev

For me since there were so many incorrectly labeled:
 
   cd /tmp/foo
   ls -lZd * | awk '{ print $NF }' | while read -r dir; do chcon --reference=/${dir} /tmp/foo/${dir}; done

Comment 18 Fedora Update System 2017-08-14 15:21:52 UTC
selinux-policy-3.13.1-225.20.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-837f04c39a

Comment 19 Fedora Update System 2017-08-15 03:51:03 UTC
selinux-policy-3.13.1-225.20.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-2017-837f04c39a

Comment 20 Fedora Update System 2017-08-27 06:22:01 UTC
selinux-policy-3.13.1-225.20.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Comment 21 Sergey Markelov 2017-08-30 07:36:56 UTC
The problem still persists.

$ journalctl -xe 
...

-- Subject: Unit postfix.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit postfix.service has begun starting up.
Aug 30 14:33:36 tux.softage.local audit[3073]: AVC avc:  denied  { search } for  pid=3073 comm="postfix" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabeled_t:s
Aug 30 14:33:36 tux.softage.local audit[3073]: AVC avc:  denied  { search } for  pid=3073 comm="postfix-script" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabe
Aug 30 14:33:36 tux.softage.local audit[3079]: AVC avc:  denied  { search } for  pid=3079 comm="postfix-script" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabe
Aug 30 14:33:36 tux.softage.local audit[3079]: AVC avc:  denied  { search } for  pid=3079 comm="postfix-script" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabe
Aug 30 14:33:36 tux.softage.local postfix[3073]: /usr/libexec/postfix/postfix-script: line 122: /dev/null: Permission denied
Aug 30 14:33:36 tux.softage.local audit[3080]: AVC avc:  denied  { search } for  pid=3080 comm="postlog" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabeled_t:s
Aug 30 14:33:36 tux.softage.local audit[3080]: AVC avc:  denied  { search } for  pid=3080 comm="postlog" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabeled_t:s
Aug 30 14:33:36 tux.softage.local audit[3080]: AVC avc:  denied  { search } for  pid=3080 comm="postlog" name="dev" dev="sdb1" ino=1835009 scontext=system_u:system_r:postfix_master_t:s0 tcontext=unconfined_u:object_r:unlabeled_t:s
Aug 30 14:33:37 tux.softage.local systemd[1]: postfix.service: Control process exited, code=exited status=1
Aug 30 14:33:37 tux.softage.local systemd[1]: Failed to start Postfix Mail Transport Agent.
-- Subject: Unit postfix.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit postfix.service has failed.
--
-- The result is failed.
...

Comment 22 Fedora Update System 2017-09-01 09:34:43 UTC
selinux-policy-3.13.1-225.22.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-5d4f3635ee

Comment 23 Fedora Update System 2017-09-03 06:24:51 UTC
selinux-policy-3.13.1-225.22.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-2017-5d4f3635ee

Comment 24 Fedora Update System 2017-09-07 23:20:09 UTC
selinux-policy-3.13.1-225.22.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Comment 25 Fedora Update System 2017-10-10 12:00:29 UTC
selinux-policy-3.13.1-225.23.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-4d00e4db6a

Comment 26 Fedora Update System 2017-10-11 04:22:06 UTC
selinux-policy-3.13.1-225.23.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-2017-4d00e4db6a

Comment 27 Fedora Update System 2017-11-01 16:39:14 UTC
selinux-policy-3.13.1-225.23.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Comment 28 Miguel Perez Colino 2018-03-27 09:06:18 UTC
Same error when running F27 in Raspberry Pi
selinux-policy-3.13.1-283.28.fc27.noarch

[root@raspberry:~]# systemctl status postfix
● postfix.service - Postfix Mail Transport Agent
   Loaded: loaded (/usr/lib/systemd/system/postfix.service; disabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Tue 2018-03-27 11:00:22 CEST; 3min 36s ago

mar 27 11:00:20 raspberry systemd[1]: Starting Postfix Mail Transport Agent...
mar 27 11:00:21 raspberry postfix[10933]: /usr/libexec/postfix/postfix-script: line 122: /dev/null: Permission denied
mar 27 11:00:22 raspberry systemd[1]: postfix.service: Control process exited, code=exited status=1
mar 27 11:00:22 raspberry systemd[1]: Failed to start Postfix Mail Transport Agent.
mar 27 11:00:22 raspberry systemd[1]: postfix.service: Unit entered failed state.
mar 27 11:00:22 raspberry systemd[1]: postfix.service: Failed with result 'exit-code'.

Comment 29 Miguel Perez Colino 2018-03-27 10:59:14 UTC
Error comes from PrivateDevices in systemd unit.
Bur already opened here:
https://bugzilla.redhat.com/show_bug.cgi?id=1412696