Re: [opensuse-programming] Is it a bug in the kernel or in my program?

6 Jan 2009

      Torsten,

If you don't get an answer on this very lightly used mailing list, you
might want to repost to the factory list.

The factory list tends to have a lot more suse developers
participating.  (There may be an even better list for you, but factory
is the best I know.)

Greg

On Tue, Jan 6, 2009 at 2:13 PM, Torsten Foertsch
 wrote:
...
Hi,
I am the author of the perl module IO::Handle::Record. This module
provides also file descriptor passing between processes. The current
release on CPAN has worked up to opensuse 11.0 but breaks with 11.1.
I don't want to bore you with the details of interfacing perl. So here
comes a short verbal description of what happens. One test case creates
a socketpair, forks and then passes a big block of data along with 2
file descriptors via sendmsg/recvmsg to the other process. The sending
side is in non-blocking mode and uses select() to wait for the file
descriptor to become writeable.
The receiving side first reads 2 integers to get the number of bytes and
the number of file descriptors passed and then reads the rest of the
record.
As the data block is larger than the kernel buffer the sendmsg will pass
only a part and then return EAGAIN. Here is what happens at the sending
side.
write(2, "--> sending 2 fds at blib/lib/IO"..., 60) = 60
sendmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"\0\6\335\335\0\0\0\2\5\7\2\0\1_\220\n\txyzabc123\0\0\0\0\1\0"..., 450021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS {6,
8}}, msg_flags=0}, 0) = 128000
write(2, "--> sending data chunk: controll"..., 92) = 92
munmap(0x7fbf29894000, 450560)          = 0
munmap(0x7fbf29902000, 450560)          = 0
close(8)                                = 0
close(6)                                = 0
brk(0xd15000)                           = 0xd15000
brk(0xd83000)                           = 0xd83000
sendmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 322021}], msg_controllen=0, msg_flags=0}, 0) = -1 EAGAIN (Resource temporarily
unavailabl
e)
write(2, "--> sending data chunk: controll"..., 87) = 87
brk(0xca7000)                           = 0xca7000
brk(0xd15000)                           = 0xd15000
munmap(0x7fbf2b957000, 720896)          = 0
brk(0xdc5000)                           = 0xdc5000
select(8, NULL, [5], NULL, NULL) = 1 (out [5])
fstat(5, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
brk(0xe33000)                           = 0xe33000
brk(0xea0000)                           = 0xea0000
sendmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 322021}], msg_controllen=0, msg_flags=0}, 0) = 112000
write(2, "--> sending data chunk: controll"..., 91)                            = 91
sendmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 210021}], msg_controllen=0, msg_flags=0}, 0) = 128000
write(2, "--> sending data chunk: controll"..., 91)                            = 91
sendmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 82021}], msg_controllen=0, msg_flags=0}, 0) = 82021
You see there are 5 sendmsg calls but only the first passes descriptors.
The 2nd returns then EAGAIN.
So far it is correct. The problem is the receiver. There are 11 recvmsg
calls. The first 8 of them handle the 128000 bytes chunk that was sent
by the first sendmsg, the one that sends the 2 file descriptors.
Those 8 syscalls receive 8 bytes, then 31992 bytes (8+31992==32000) and
then 6 times 16000 bytes.
But all of those calls receive file descriptors! While only the first
should.
Is that a kernel bug? Or is my program wrong?
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\0\6\335\335\0\0\0\2", 8}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, {5, 8}}, msg_flags=0}, 0) = 8
write(2, "==> expecting 1024 fds -- got 8 "..., 86) = 86
fcntl(5, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(5, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(5, 0, SEEK_CUR)                   = 0
fstat(5, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(5, F_SETFD, FD_CLOEXEC)           = 0
fstat(5, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(8, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(8, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(8, 0, SEEK_CUR)                   = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
mmap(NULL, 450560, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbf2b999000
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\5\7\2\0\1_\220\n\txyzabc123\0\0\0\0\1\0\0\0\0\1\0\0\0\0"..., 450013}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, {11,
14}}
, msg_flags=0}, 0) = 31992
write(2, "==> expecting 1024 fds -- got 31"..., 90) = 90
fcntl(11, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(11, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(11, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(11, 0, SEEK_CUR)                  = 0
fstat(11, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
fstat(11, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(14, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(14, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(14, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(14, 0, SEEK_CUR)                  = 0
fstat(14, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(14, F_SETFD, FD_CLOEXEC)          = 0
fstat(14, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 418021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS,
{
15, 16}}, msg_flags=0}, 0) = 16000
write(2, "==> expecting 1024 fds -- got 16"..., 90) = 90
fcntl(15, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(15, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(15, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(15, 0, SEEK_CUR)                  = 0
fstat(15, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(15, F_SETFD, FD_CLOEXEC)          = 0
fstat(15, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(16, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(16, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(16, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(16, 0, SEEK_CUR)                  = 0
fstat(16, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(16, F_SETFD, FD_CLOEXEC)          = 0
fstat(16, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 402021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS,
{
17, 18}}, msg_flags=0}, 0) = 16000
write(2, "==> expecting 1024 fds -- got 16"..., 90) = 90
fcntl(17, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(17, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(17, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(17, 0, SEEK_CUR)                  = 0
fstat(17, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(17, F_SETFD, FD_CLOEXEC)          = 0
fstat(17, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(18, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(18, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(18, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(18, 0, SEEK_CUR)                  = 0
fstat(18, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(18, F_SETFD, FD_CLOEXEC)          = 0
fstat(18, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 386021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS,
{
19, 20}}, msg_flags=0}, 0) = 16000
write(2, "==> expecting 1024 fds -- got 16"..., 90) = 90
fcntl(19, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(19, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(19, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(19, 0, SEEK_CUR)                  = 0
fstat(19, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(19, F_SETFD, FD_CLOEXEC)          = 0
fstat(19, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(20, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(20, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(20, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(20, 0, SEEK_CUR)                  = 0
fstat(20, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(20, F_SETFD, FD_CLOEXEC)          = 0
fstat(20, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 370021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS,
{
21, 22}}, msg_flags=0}, 0) = 16000
write(2, "==> expecting 1024 fds -- got 16"..., 90) = 90
fcntl(21, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(21, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(21, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(21, 0, SEEK_CUR)                  = 0
fstat(21, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(21, F_SETFD, FD_CLOEXEC)          = 0
fstat(21, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(22, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(22, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(22, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(22, 0, SEEK_CUR)                  = 0
fstat(22, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(22, F_SETFD, FD_CLOEXEC)          = 0
fstat(22, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 354021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS,
{
23, 24}}, msg_flags=0}, 0) = 16000
write(2, "==> expecting 1024 fds -- got 16"..., 90) = 90
fcntl(23, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(23, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(23, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(23, 0, SEEK_CUR)                  = 0
fstat(23, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(23, F_SETFD, FD_CLOEXEC)          = 0
fstat(23, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(24, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(24, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(24, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(24, 0, SEEK_CUR)                  = 0
fstat(24, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(24, F_SETFD, FD_CLOEXEC)          = 0
fstat(24, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 338021}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS,
{
25, 26}}, msg_flags=0}, 0) = 16000
write(2, "==> expecting 1024 fds -- got 16"..., 90) = 90
fcntl(25, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(25, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
ioctl(25, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(25, 0, SEEK_CUR)                  = 0
fstat(25, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(25, F_SETFD, FD_CLOEXEC)          = 0
fstat(25, {st_mode=S_IFREG|0644, st_size=1405, ...}) = 0
fcntl(26, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(26, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
ioctl(26, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff33b53fc0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(26, 0, SEEK_CUR)                  = 0
fstat(26, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
fcntl(26, F_SETFD, FD_CLOEXEC)          = 0
fstat(26, {st_mode=S_IFREG|0644, st_size=246, ...}) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 322021}], msg_controllen=0, msg_flags=0}, 0) = 112000
write(2, "==> expecting 1024 fds -- got 11"..., 93) = 93
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 210021}], msg_controllen=0, msg_flags=0}, 0) = 128000
write(2, "==> expecting 1024 fds -- got 12"..., 93) = 93
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=8*1024}) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0\0\0\0\1\0"..., 82021}], msg_controllen=0, msg_flags=0}, 0) = 82021
write(2, "==> expecting 1024 fds -- got 82"..., 92) = 92
Thanks,
Torsten
--
To unsubscribe, e-mail: opensuse-programming+unsubscribe@opensuse.org
For additional commands, e-mail: opensuse-programming+help@opensuse.org
-- 
Greg Freemyer
Litigation Triage Solutions Specialist
http://www.linkedin.com/in/gregfreemyer
First 99 Days Litigation White Paper -
http://www.norcrossgroup.com/forms/whitepapers/99%20Days%20whitepaper.pdf

The Norcross Group
The Intersection of Evidence & Technology
http://www.norcrossgroup.com
-- 
To unsubscribe, e-mail: opensuse-programming+unsubscribe@opensuse.org
For additional commands, e-mail: opensuse-programming+help@opensuse.org