memory hot-add: the kernel can notify udev daemon before creating the sys file state?

[DX Cui <rijcos@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 4933 bytes --]

Hi all,
I'm debugging a strange memory hotplug issue on CentOS
6.5(2.6.32-431.17.1.el6): when a chunk of memory is hot-added, it seems the
kernel *occasionally* can send a MEMORY ADD event to the udev daemon before
the kernel actually creates the sys file 'state'!
As a result, udev can't reliably make new memory online by this udev rule:
SUBSYSTEM=="memory", ACTION=="add", ATTR{state}="online"

Please see the end of the mail for the strace log of udevd when I run udevd
manually:

When udevd gets a MEMORY ADD event for /sys/devices/system/memory/memory23,
it tries to write "online" to /sys/devices/system/memory/memory23/state,
but the file hasn't been created by the kernel yet. In this case, when I
manually check the file at once with ls, it has been created, and I can
manually echo online into it to make it online correctly.

Please note: this bad behavior of the kernel is only occasional, which may
imply there is a race condition somewhere?

BTW, it looks the issue does't exist in 3.10+ kernels. Is this a known
issue already fixed in new kernels?

I'm trying to dig into the code and I hope I can get some suggestions here.
Thanks!

-- DX

The strace log is:
1427  1400822167.053704 socket(PF_NETLINK, SOCK_DGRAM|SOCK_CLOEXEC, 15) = 5
...
1427  1400822372.247210 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK,
pid=0, groups=00000001},
msg_iov(1)=[{"add@/devices/system/memory/memory23\0ACTION=add\0DEVPATH=/devices/system/memory/memory23\0SUBSYSTEM=memory\0SEQNUM=1358\0\0\0\0\0\0\0\0\0\0\0\0\\0\0\0\0\0\0\0"...,
8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET,
cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 116
1427  1400822372.247298 lseek(10, 0, SEEK_CUR) = 1332
1427  1400822372.247320 write(10,
"N\5\0\0\0\0\0\0\37\0/devices/system/memory/memory23", 41) = 41
1427  1400822372.247352 gettimeofday({1400822372, 247358}, NULL) = 0
1427  1400822372.247387 writev(2, [{"udevd[1427]: seq 1358 queued, 'add'
'memory'\n", 45}], 1) = 45
1427  1400822372.247428 sendto(3, "<30>May 23 06:19:32 udevd[1427]: seq
1358 queued, 'add' 'memory'\n", 65, MSG_NOSIGNAL, NULL, 0) = 65
1427  1400822372.247511 sendmsg(5, {msg_name(12)={sa_family=AF_NETLINK,
pid=-4139, groups=00000000},
msg_iov(2)=[{"udev-147\0\0\0\0\0\0\0\0\312\376\35\352
\0[\0\312\n\234<\0\0\0\0", 32},
{"UDEV_LOG=7\0ACTION=add\0DEVPATH=/devices/system/memory/memory23\0SUBSYSTEM=memory\0SEQNUM=1358\0",
91}], msg_controllen=0, msg_flags=0}, 0 <unfinished ...>
1456  1400822372.247568 <... ppoll resumed> ) = 1 ([{fd=11,
revents=POLLIN}])
1427  1400822372.247578 <... sendmsg resumed> ) = 123
1456  1400822372.247595 recvmsg(11,  <unfinished ...>
1427  1400822372.247602 gettimeofday( <unfinished ...>
1456  1400822372.247615 <... recvmsg resumed>
{msg_name(12)={sa_family=AF_NETLINK, pid=1427, groups=00000000},
msg_iov(1)=[{"udev-147\0\0\0\0\0\0\0\0\312\376\35\352
\0[\0\312\n\234<\0\0\0\0UDEV_LOG=7\0ACTION=add\0DEVPATH=/devices/system/memory/memory23\0SUBSYSTEM=memory\0SEQNUM=1358\0\0\0\0\0\0\0\\0\0\0\0\0"...,
8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET,
cmsg_type=SCM_CREDENTIALS{pid=1427, uid=0, gid=0}}, msg_flags=0}, 0) = 123
1427  1400822372.247658 <... gettimeofday resumed> {1400822372, 247610},
NULL) = 0
1456  1400822372.247688 gettimeofday( <unfinished ...>
1427  1400822372.247695 writev(2, [{"udevd[1427]: passed 123 bytes to
monitor 0x7f71f4c6a6c0\n", 56}], 1 <unfinished ...>
1456  1400822372.247715 <... gettimeofday resumed> {1400822372, 247706},
NULL) = 0
1427  1400822372.247722 <... writev resumed> ) = 56
1456  1400822372.247738 writev(2, [{"udevd-work[1456]: seq 1358 running\n",
35}], 1 <unfinished ...>
1427  1400822372.247750 sendto(3, "<30>May 23 06:19:32 udevd[1427]: passed
123 bytes to monitor 0x7f71f4c6a6c0\n", 76, MSG_NOSIGNAL, NULL, 0
<unfinished ...>1456  1400822372.247785 <... writev resumed> ) = 35
1427  1400822372.247792 <... sendto resumed> ) = 76
1456  1400822372.247805 sendto(3, "<30>May 23 06:19:32 udevd-work[1456]:
seq 1358 running\n", 55, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
1427  1400822372.247816 poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN},
{fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 5, -1
<unfinished ...>
1456  1400822372.247847 <... sendto resumed> ) = 55
1456  1400822372.247861 alarm(180)      = 0
1456  1400822372.247892 gettimeofday({1400822372, 247898}, NULL) = 0
1456  1400822372.247917 writev(2, [{"udevd-work[1456]: ATTR
'/sys/devices/system/memory/memory23/state' writing 'online'
/etc/udev/rules.d/100-balloons.rules:1\n", 123}], 1) = 123
1456  1400822372.247946 sendto(3, "<30>May 23 06:19:32 udevd-work[1456]:
ATTR '/sys/devices/system/memory/memory23/state' writing 'online'
/etc/udev/rules.d/100-balloons.rules:1\n", 143, MSG_NOSIGNAL, NULL, 0) = 143
1456  1400822372.247992 open("/sys/devices/system/memory/memory23/state",
O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 ENOENT (No such file or directory)

[-- Attachment #2: Type: text/html, Size: 5986 bytes --]