Bug 783955 - 2.6.41.10-2.fc15.x86_64 breaks mdmonitor.service
Summary: 2.6.41.10-2.fc15.x86_64 breaks mdmonitor.service
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 15
Hardware: x86_64
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 784076 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-01-23 10:50 UTC by Harald Reindl
Modified: 2012-05-02 17:24 UTC (History)
13 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-01-24 13:20:42 UTC
Type: ---


Attachments (Terms of Use)

Description Harald Reindl 2012-01-23 10:50:05 UTC
please take a look at my mdadm-bugreport
confirmed that this does not happen with 2.6.41.9-1.fc15.x86_64

https://bugzilla.redhat.com/show_bug.cgi?id=783823

Comment 1 Alasdair Kergon 2012-01-23 11:19:50 UTC
That's 0x1261 BLKFLSBUF which ought to be one of the ones allowed through, I'd have thought.

Comment 2 Alasdair Kergon 2012-01-23 11:29:31 UTC
Is BLKROSET affected too?
(Try 'blockdev --setro')

Comment 3 Paolo Bonzini 2012-01-23 11:35:51 UTC
It seems more likely that the backport was wrong, I'll take a look.

Comment 4 Paolo Bonzini 2012-01-23 12:30:56 UTC
Actually, the warning seems a false positive to me.

The BLKFLSBUF code first tries sending down the ioctl to the driver.  This is where the warning is generated.  The driver, however, will return -ENOTTY both in .9-1 and .10-2 (tried "git grep BLKFLSBUF drivers/").

This matches what I see when I do

   blockdev --setro /dev/sda3

I see "sending ioctl 125d to a partition" twice in dmesg, but a strace shows that the ioctl is succeeding.

   ioctl(3, BLKROSET, 1)                   = 0

My patches are still the most likely culprit, but it's not immediate to see what's going wrong.

Harald, can you attach a strace?  Also, can you try disabling printk ratelimiting ("sysctl -w kernel.printk_ratelimit=0 kernel.printk_ratelimit_burst=0")?

Comment 5 Josh Boyer 2012-01-23 19:31:07 UTC
*** Bug 784076 has been marked as a duplicate of this bug. ***

Comment 6 Paolo Bonzini 2012-01-24 11:11:36 UTC
I cannot reproduce the problem with mdmonitor.service (only the dmesg warning, but that's only ugly).


$ sudo mdadm --create /dev/md0 --level=1 -n2 -x1 /dev/sda5 /dev/sda6 /dev/sda7
mdadm: Note: this array has metadata at the start and
    may not be suitable as a boot device.  If you plan to
    store '/boot' on this device please ensure that
    your boot-loader understands md/v1.x metadata, or use
    --metadata=0.90
Continue creating array? y
mdadm: Defaulting to version 1.2 metadata
mdadm: array /dev/md0 started.
yakj:~ pbonzini$ sudo chmod ugo+rw /dev/md0 /dev/sda[567]
yakj:~ pbonzini$ cat /proc/mdstat 
Personalities : [raid1] 
md0 : active raid1 sda7[2](S) sda6[1] sda5[0]
      5684212 blocks super 1.2 [2/2] [UU]
      [====>................]  resync = 21.7% (1237376/5684212) finish=3.9min speed=18521K/sec
      
unused devices: <none>

$ dmesg
...
[ 2704.167988] md: md0: resync done.
[ 2704.336251] RAID1 conf printout:
[ 2704.336260]  --- wd:2 rd:2
[ 2704.336269]  disk 0, wo:0, o:1, dev:sda5
[ 2704.336276]  disk 1, wo:0, o:1, dev:sda6
$ sudo systemctl status mdmonitor.service
mdmonitor.service - Software RAID monitoring and management
	  Loaded: loaded (/etc/systemd/system/mdmonitor.service; disabled)
	  Active: active (running) since Tue, 24 Jan 2012 11:54:31 +0100; 23s ago
	 Process: 3482 ExecStart=/sbin/mdadm --monitor --program=/bin/true --scan -f --pid-file=/var/run/mdadm/mdadm.pid (code=exited, status=0/SUCCESS)
	Main PID: 3483 (mdadm)
	  CGroup: name=systemd:/system/mdmonitor.service
		  └ 3483 /sbin/mdadm --monitor --program=/bin/true --scan -f --pid-file=/var/run/mdadm/mdadm.pid
$ sudo /sbin/mdadm --detail /dev/md0
/dev/md0:
        Version : 1.2
  Creation Time : Tue Jan 24 11:46:34 2012
     Raid Level : raid1
     Array Size : 5684212 (5.42 GiB 5.82 GB)
  Used Dev Size : 5684212 (5.42 GiB 5.82 GB)
   Raid Devices : 2
  Total Devices : 3
    Persistence : Superblock is persistent

    Update Time : Tue Jan 24 11:52:07 2012
          State : clean
 Active Devices : 2
Working Devices : 3
 Failed Devices : 0
  Spare Devices : 1

           Name : yakj.usersys.redhat.com:0  (local to host yakj.usersys.redhat.com)
           UUID : b5fa445c:bc4fe9d2:e453ed71:08587c35
         Events : 17

    Number   Major   Minor   RaidDevice State
       0       8        5        0      active sync   /dev/sda5
       1       8        6        1      active sync   /dev/sda6

       2       8        7        -      spare   /dev/sda7
$ sudo sh -x /usr/sbin/raid-check 
+ '[' -f /proc/mdstat ']'
+ '[' -f /etc/sysconfig/raid-check ']'
+ . /etc/sysconfig/raid-check
++ ENABLED=yes
++ CHECK=check
++ NICE=low
++ CHECK_DEVS=md0
++ REPAIR_DEVS=md0
++ SKIP_DEVS=
+ '[' yes '!=' yes ']'
+ case "$CHECK" in
+ ionice=
+ renice=
+ case $NICE in
+ renice='-n 5'
+ ionice='-c2 -n7'
++ cut -f 1 -d ' '
++ grep '^md.*: active' /proc/mdstat
+ active_list=md0
+ '[' -z md0 ']'
+ declare -A check
+ dev_list=
+ check_list=
+ for dev in '$active_list'
+ grep -w md0
+ echo
+ '[' -f /sys/block/md0/md/sync_action ']'
++ cat /sys/block/md0/md/array_state
+ array_state=clean
+ '[' clean '!=' clean -a clean '!=' active ']'
++ cat /sys/block/md0/md/sync_action
+ sync_action=idle
+ '[' idle '!=' idle ']'
+ ck=
+ echo md0
+ grep -w md0
+ ck=repair
+ grep -w md0
+ echo md0
+ ck=check
+ '[' -z check ']'
+ dev_list=' md0'
+ check[$dev]=check
+ '[' check = check ']'
+ check_list=' md0'
+ '[' -z ' md0' ']'
+ for dev in '$dev_list'
+ echo check
+ resync_pid=
+ wait=10
+ '[' 10 -gt 0 -a -z '' ']'
+ sleep 6
+ let wait--
++ ps -ef
++ awk -v mddev=md0 'BEGIN { pattern = "^\\[" mddev "_resync]$" } $8 ~ pattern { print $2 }'
+ resync_pid=3822
+ '[' 9 -gt 0 -a -z 3822 ']'
+ '[' -n 3822 -a -n '-n 5' ']'
+ renice -n 5 -p 3822
+ '[' -n 3822 -a -n '-c2 -n7' ']'
+ ionice -c2 -n7 -p 3822
+ '[' -z ' md0' ']'
+ checking=1
+ '[' 1 -ne 0 ']'
+ sleep 60
+ checking=0
+ for dev in '$check_list'
++ cat /sys/block/md0/md/sync_action
+ sync_action=idle
+ '[' idle '!=' idle ']'
+ '[' 0 -ne 0 ']'
+ for dev in '$check_list'
++ cat /sys/block/md0/md/mismatch_cnt
+ mismatch_cnt=0
++ cat /sys/block/md0/md/level
+ raid_lvl=raid1
+ '[' raid1 = raid1 -o raid1 = raid10 ']'
+ continue
$ dmesg
...
[ 3333.854826] md: data-check of RAID array md0
[ 3333.854830] md: minimum _guaranteed_  speed: 1000 KB/sec/disk.
[ 3333.854832] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for data-check.
[ 3333.854836] md: using 128k window, over a total of 5684212k.
[ 3639.920121] md: md0: data-check done.
$ sudo systemctl status mdmonitor.service
[sudo] password for pbonzini: 
mdmonitor.service - Software RAID monitoring and management
	  Loaded: loaded (/etc/systemd/system/mdmonitor.service; disabled)
	  Active: active (running) since Tue, 24 Jan 2012 11:54:31 +0100; 14min ago
	 Process: 3482 ExecStart=/sbin/mdadm --monitor --program=/bin/true --scan -f --pid-file=/var/run/mdadm/mdadm.pid (code=exited, status=0/SUCCESS)
	Main PID: 3483 (mdadm)
	  CGroup: name=systemd:/system/mdmonitor.service
		  └ 3483 /sbin/mdadm --monitor --program=/bin/true --scan -f --pid-file=/var/run/mdadm...

Comment 7 Paolo Bonzini 2012-01-24 11:12:49 UTC
And here is my service file:

$ cat /etc/systemd/system/mdmonitor.service 
[Unit]
Description=Software RAID monitoring and management
After=syslog.target
ConditionPathExists=/etc/mdadm.conf

[Service]
Type=forking
PIDFile=/var/run/mdadm/mdadm.pid
EnvironmentFile=-/etc/sysconfig/mdmonitor
ExecStart=/sbin/mdadm --monitor --program=/bin/true --scan -f --pid-file=/var/run/mdadm/mdadm.pid

[Install]
WantedBy=multi-user.target


1) Can you check in /var/log/messages _why_ did mdmonitor fail?

2) Does mdmonitor fail with the non-test kernel?

Comment 8 Harald Reindl 2012-01-24 11:18:06 UTC
1) 
systemd does not make much outputs except "entered failed state"

2) 
AFAIK yes, i noticed this last thursday on my workstation and the testing-kernel was on koji after that

Comment 9 Paolo Bonzini 2012-01-24 11:29:07 UTC
1) Nothing in /var/log/messages, such as

Jan 24 11:52:11 yakj mdadm[3395]: mdadm: No mail address or alert command - not monitoring.
Jan 24 11:52:11 yakj systemd[1]: mdmonitor.service: control process exited, code=exited status=1
Jan 24 11:52:11 yakj systemd[1]: Unit mdmonitor.service entered failed state.

?

2) So the mdmonitor failure is not a regression, right?

Comment 10 Harald Reindl 2012-01-24 11:39:22 UTC
seems to belong to the mdadm-bugreport, so one part of it is a kernel-regression and the other one a bug in mdadm itself - sorry for the confusion

Comment 11 Paolo Bonzini 2012-01-24 13:20:42 UTC
The kernel problem is not a bug, it's just ugly to have a warning in dmesg but that's what the warning was for---to make sure that problematic cases would be noticed.

For the mdadm, please reproduce on F16 since you're using non-standard init scripts.

Comment 12 Harald Reindl 2012-01-24 14:57:26 UTC
in my opinion "The kernel problem is not a bug, it's just ugly to have a warning in dmesg" is wrong, there should be no warnings in the state software is shipped with the distribution for normal behavior!

Comment 13 Paolo Bonzini 2012-01-24 15:16:21 UTC
We added a warning because we're not changing behavior yet; the warning must be there so that we know exactly how the behavior will change, and so that we know that changes will not be harmful.

Comment 14 Knut J BJuland 2012-02-05 12:14:32 UTC
mdadm: sending ioctl 1261 to a partition! Also present in Fedora 16 please reopen.

Comment 15 Jes Sorensen 2012-02-05 12:51:57 UTC
(In reply to comment #14)
> mdadm: sending ioctl 1261 to a partition! Also present in Fedora 16 please
> reopen.

It's information, not a bug, so no need to reopen.

Comment 16 Bill McGonigle 2012-05-02 00:09:02 UTC
Right - it's information for developers, but not a warning for the sysadmin.  The trouble here is that it's being sent with kern.warn severity, which causes vt console spew for the default printk level.  This breaks many apps on the vt (watch, top, etc.) which are commonly run by sysadmins.

(disable these on console with, e.g.: echo '4 4 1 4' > /proc/sys/kernel/printk or set the kernel.printk sysctl) 

I'd think 5, 6, or 7 would be more appropriate severities as far as RFC 5424 goes, but it's also worth asking why this is the only part of Fedora that's behaving this way (at least in common usage).  Is this important enough to force everybody who runs mdmonitor to adjust kernel.printk if they use virtual terminals? (not to mention the time they'll need to figure out that's what they need to do).

Comment 17 Paolo Bonzini 2012-05-02 17:24:30 UTC
The warnings will go away soon...


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