2018-01-23 17:45 UTC

View Issue Details Jump to Notes ]
IDProjectCategoryView StatusLast Update
0014298CentOS-7mdadmpublic2017-12-21 13:35
Reportercandlerb 
PrioritynormalSeverityminorReproducibilityalways
StatusnewResolutionopen 
Product Version7.4.1708 
Target VersionFixed in Version 
Summary0014298: mdadm stdout/stderr discarded when run from cron
DescriptionThis is weirdest problem I have seen in a long time, but it is completely reproducible: have tested it both on real hardware and on a DigitalOcean VM of CentOS 7.

Suppose you have a script like this:

#!/bin/bash
mdadm /dev/md127 >/tmp/f1 # writes to stdout
mdadm -V 2>/dev/f2 # writes to stderr

This script works fine when run from the command line. But when run from cron, the files created are zero bytes. And yet, prefixing with "strace -f" shows it is calling write(1, ...) and write(2, ...) as expected.

The problem does not occur on CentOS 6, and although the system has SELinux enabled, there are no SELinux warnings or errors logged.
Steps To Reproduce==> /usr/local/sbin/testcron.sh <==
#!/bin/bash -ex
echo hello
strace -v -f /usr/local/sbin/testcron2.sh
echo goodbye

==> /usr/local/sbin/testcron2.sh <==
#!/bin/sh -ex
/sbin/mdadm /dev/md127

chmod +x on both. Run from the command line and all is OK:

[root@storage4 ~]# /usr/local/sbin/testcron.sh >/tmp/out 2>/tmp/err
[root@storage4 ~]# cat /tmp/out
hello
/dev/md127: 58682.29GiB raid6 23 devices, 1 spare. Use mdadm --detail for more detail.
goodbye

Now run it from cron:

==> /etc/cron.d/testcron <==
* * * * * root /usr/local/sbin/testcron.sh >/tmp/testcron.out 2>/tmp/testcron.err

Wait one minute, then:

[root@storage4 ~]# cat /tmp/testcron.out
hello
goodbye

But strace shows the write(1, ...) call was successful:

[root@storage4 ~]# grep 'write(1,' /tmp/testcron.err
[pid 4346] write(1, "/dev/md127: 58682.29GiB raid6 23"..., 87) = 87

I found one smoking gun in the strace output:

[root@storage4 ~]# grep 'fstat(1,' /tmp/testcron.err
[pid 4963] fstat(1, {st_dev=makedev(0, 14), st_ino=22, st_mode=S_IFCHR|0666, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_rdev=makedev(1, 3), st_atime=2017/12/18-16:17:23.362996849, st_mtime=2017/12/18-16:17:23.362996849, st_ctime=2017/12/18-16:17:23.362996849}) = 0

S_IFCHR is a character device and makedev(1, 3) is /dev/null. But for the life of me I cannot see anywhere that stdout is redirected to /dev/null, either in the parent shell or in the mdadm process itself.
Additional InformationYou can reproduce this more simply, without having any mdadm arrays, by using "mdadm -V" which writes a message to stderr. This is also being discarded when run from cron.

The problem also reproduces if you explicitly redirect within the shell script itself:

==> /usr/local/sbin/testcron2.sh <==
#!/bin/sh
/sbin/mdadm -V >/tmp/out 2>/tmp/err

After this has run from cron, both files are zero bytes:

[root@storage4 ~]# ls -l /tmp/out /tmp/err
-rw-r--r--. 1 root root 0 Dec 21 11:40 /tmp/err
-rw-r--r--. 1 root root 0 Dec 21 11:40 /tmp/out

And yet the strace output captured in /tmp/testcron.out shows data being written to stderr.

[pid 5854] write(2, "mdadm - v4.0 - 2017-01-09\n", 26) = 26

Another thing you can do is to turn on line buffering:

==> /usr/local/sbin/testcron2.sh <==
#!/bin/sh
stdbuf -o L -e L /sbin/mdadm --detail /dev/md127 >/tmp/out 2>/tmp/err

Again, /tmp/out and /tmp/err are zero bytes when this runs from cron. But strace shows the line-buffering is active:

[pid 6790] write(1, "/dev/md127:\n", 12) = 12
[pid 6790] write(1, " Version : 1.2\n", 25) = 25
...
[pid 6790] write(1, " Creation Time : Tue Feb 5 "..., 46) = 46
[pid 6790] write(1, " Raid Level : raid6\n", 27) = 27
[pid 6790] write(1, " Array Size : 61532835840"..., 60) = 60
... etc

Whereas if you don't use line buffering, a single large write(1) is done. So clearly it is honouring the attributes of the stdout FD which is passed in.

I did say it was weird!! :-)
TagsNo tags attached.
abrt_hash
URL
Attached Files

-Relationships
+Relationships

-Notes

~0030808

candlerb (reporter)

It turns out this must be related to selinux, because if you do "setenforce permissive" the problem goes away.

However I do not understand how selinux is breaking stdout/stderr without:
(1) causing any syscall to return failure;
(2) causing any selinux violations in logs.

~0030810

candlerb (reporter)

Even though nothing was being written to system logs under /var/log, I discovered ausearch (*) (**)

ausearch -m avc -ts recent
...
----
time->Thu Dec 21 13:15:01 2017
type=PROCTITLE msg=audit(1513862101.413:21797): proctitle=2F7362696E2F6D6461646D002D2D64657461696C002F6465762F6D64313237
type=SYSCALL msg=audit(1513862101.413:21797): arch=c000003e syscall=59 success=yes exit=0 a0=7ffcf071ff20 a1=7ffcf071efe0 a2=164c0e0 a3=7ffcf071e820 items=0 ppid=22873 pid=22874 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=1935 comm="mdadm" exe="/usr/sbin/mdadm" subj=system_u:system_r:mdadm_t:s0-s0:c0.c1023 key=(null)
type=AVC msg=audit(1513862101.413:21797): avc: denied { write } for pid=22874 comm="mdadm" path="/tmp/out" dev="dm-0" ino=67175097 scontext=system_u:system_r:mdadm_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_tmp_t:s0 tclass=file
----
time->Thu Dec 21 13:15:01 2017
type=PROCTITLE msg=audit(1513862101.425:21798): proctitle=2F7362696E2F6D6461646D002D2D64657461696C002F6465762F6D64313237
type=SYSCALL msg=audit(1513862101.425:21798): arch=c000003e syscall=4 success=yes exit=0 a0=5627d0ec9b20 a1=7fff0d97c6d0 a2=7fff0d97c6d0 a3=100 items=0 ppid=22873 pid=22874 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=1935 comm="mdadm" exe="/usr/sbin/mdadm" subj=system_u:system_r:mdadm_t:s0-s0:c0.c1023 key=(null)
type=AVC msg=audit(1513862101.425:21798): avc: denied { getattr } for pid=22874 comm="mdadm" path="/run/systemd/initctl/fifo" dev="tmpfs" ino=13504 scontext=system_u:system_r:mdadm_t:s0-s0:c0.c1023 tcontext=system_u:object_r:initctl_t:s0 tclass=fifo_file

(and the raw logs in /var/log/audit/audit.log)

So the rejection *is* taking place. And a workaround, rather than making all of selinux permissive, is:

semanage permissive -a mdadm_t

Perhaps it's quite reasonable to block mdadm from writing to arbitrary directories when not run directly by a system administrator. The odd thing is, smartctl doesn't have this limitation.

Where this started from is that I am using the MAD Hacking SNMP scripts to monitor smartctl and mdraid status, and there are cronjobs which pull status from the tools:
https://github.com/MADhacking/snmpd-smartctl-connector
https://github.com/MADhacking/snmpd-mdraid-connector

Both have an effectively identical inner loop:

https://github.com/MADhacking/snmpd-smartctl-connector/blob/master/usr/sbin/update-smartctl-cache#L115
https://github.com/MADhacking/snmpd-mdraid-connector/blob/master/usr/sbin/update-mdraid-cache#L93

They are configured to write files under /var/cache/snmp/smartctl and /var/cache/snmp/mdadm respectively. The smartctl ones succeed, but the mdadm ones create zero byte files, when SELinux is enforcing and run from cron.

(*) Via https://github.com/moby/moby/issues/31106#issuecomment-281107795

(**) Also did "semanage dontaudit off":
https://bugzilla.redhat.com/show_bug.cgi?id=754938
https://www.ostechnix.com/linux-troubleshooting-semanage-command-not-found-in-centos-7rhel-7/
+Notes

-Issue History
Date Modified Username Field Change
2017-12-21 11:49 candlerb New Issue
2017-12-21 12:02 candlerb Note Added: 0030808
2017-12-21 13:35 candlerb Note Added: 0030810
+Issue History