Am 20.02.2013 um 10:51 schrieb Axel Rau:
>>
>> Like... no ancillary data is being *passed to sendmsg*?
> Yes. My debug print at the beginning of sendmsg always shows 0.
>> Or no data is being received from recvmsg? Does tracing the relevant
>> processes with something like strace or dtruss confirm this? What process
>> is being debugged here; master, worker, or both?
> Both, because the unpack error pointed at a platform/compatibility issue in
> sendmsg.c, which is used by all parts.
> I will try to get a trace with dtruss.
truss trace of the handling of the http accept attached.
>>
>> The debug messages which you've added seem like they might be missing some
>> data, since they just truncate after 'return from sendmsg with', rather than
>> printing a string (even an empty one) after.
> Yes, the code was not finished. should display sendmsg_result, which was
> always 1. See attached diff.
>>
>>> Without ancillary data, no fd can be shipped.
>>> The only place where ancillary data could be provided seems to be
>>> twext.internet.sendfdport._SubprocessSocket.doWrite.
>>> I would be happy for any hint where to dig...
>>
>> Well, hrm. This code works fine on other platforms, so, one thing to check
>> would be to see if previous versions of the FreeBSD kernel have the same
>> issue. What exact versions of everything are you testing?
> 8.2 and 9.1. Both show same bug.
Both platforms are 64-bit.
Axel
sendmsg.c with debug code:
UID PID PPID CPU PRI NI VSZ RSS MWCHAN STAT TT TIME COMMAND
0 30587 1 0 52 0 206832 51316 usem S ?? 0:00.15 python2.7
/usr/local/bin/twistd --reactor=kqueue caldav -f
/usr/local/etc/caldavd/caldavd.plist -o Twisted/reactor=kqueue
52 30590 30587 0 52 0 190188 49816 kqread S ?? 0:00.65
/usr/local/bin/python2.7 /usr/local/bin/twistd -u _dcs -g _dcs --reactor=kqueue
-n caldav -f /usr/local/etc/caldavd/caldavd.plist -o ProcessType=Slave -o
BindAddresses=vm-fbsd.in.chaos1.de -o PIDFile=caldav-instance-0.pid -o
ErrorLogFile=None -o ErrorLogEnabled=False -o LogID=0 -o
MultiProcess/ProcessCount=2 -o ControlPort=0 -o MetaFD=24
52 30591 30587 0 52 0 190188 49816 kqread S ?? 0:00.65
/usr/local/bin/python2.7 /usr/local/bin/twistd -u _dcs -g _dcs --reactor=kqueue
-n caldav -f /usr/local/etc/caldavd/caldavd.plist -o ProcessType=Slave -o
BindAddresses=vm-fbsd.in.chaos1.de -o PIDFile=caldav-instance-1.pid -o
ErrorLogFile=None -o ErrorLogEnabled=False -o LogID=1 -o
MultiProcess/ProcessCount=2 -o ControlPort=0 -o MetaFD=26
52 30592 30587 0 43 0 190188 48656 kqread S ?? 0:00.58
/usr/local/bin/python2.7 /usr/local/bin/twistd -u _dcs -g _dcs --reactor=kqueue
-n caldav_notifier -f /usr/local/etc/caldavd/caldavd.plist
52 30593 30587 0 52 0 207216 50492 usem S ?? 0:00.65
/usr/local/bin/python2.7 /usr/local/bin/twistd -u _dcs -g _dcs --reactor=kqueue
-n caldav_groupcacher -f /usr/local/etc/caldavd/caldavd.plist -o
PIDFile=groupcacher.pid
30587: _umtx_op(0x80d85c044,0x13,0x0,0x0,0x0,0x0) = 1 (0x1)
30587: accept(21,{ AF_INET 192.168.220.121:64759 },0x7fffffffa36c) = 42 (0x2a)
30587: fcntl(42,F_GETFD,) = 0 (0x0)
30587: fcntl(42,F_SETFD,FD_CLOEXEC) = 0 (0x0)
30587: fcntl(42,F_GETFL,) = 6 (0x6)
30587: fcntl(42,F_SETFL,O_NONBLOCK|0x2) = 0 (0x0)
30587: kevent(3,{0x2a,EVFILT_READ,EV_ADD,0,0x0,0x0},1,0x0,0,{0.000000000 }) = 0
(0x0)
30587: kevent(3,{0x2a,EVFILT_READ,EV_DELETE,0,0x0,0x0},1,0x0,0,{0.000000000 })
= 0 (0x0)
30587: kevent(3,{0x19,EVFILT_WRITE,EV_ADD,0,0x0,0x0},1,0x0,0,{0.000000000 }) =
0 (0x0)
30587: gettimeofday({1361360493.531944 },0x0) = 0 (0x0)
30587: gettimeofday({1361360493.532020 },0x0) = 0 (0x0)
30587: kevent(3,{},0,{0x19,EVFILT_WRITE,0x0,0,0x800,0x0},26,{17.584695816 }) =
1 (0x1)
30587: SIGNAL 11 (SIGSEGV)
30587: process exit, rval = 0
sendmsg.c without debug code:
30813: _umtx_op(0x80d85c044,0x13,0x0,0x0,0x0,0x0) = 1 (0x1)
30813: accept(20,{ AF_INET 192.168.220.121:49816 },0x7fffffffa36c) = 41 (0x29)
30813: fcntl(41,F_GETFD,) = 0 (0x0)
30813: fcntl(41,F_SETFD,FD_CLOEXEC) = 0 (0x0)
30813: fcntl(41,F_GETFL,) = 6 (0x6)
30813: fcntl(41,F_SETFL,O_NONBLOCK|0x2) = 0 (0x0)
30813: kevent(3,{0x29,EVFILT_READ,EV_ADD,0,0x0,0x0},1,0x0,0,{0.000000000 }) = 0
(0x0)
30813: kevent(3,{0x29,EVFILT_READ,EV_DELETE,0,0x0,0x0},1,0x0,0,{0.000000000 })
= 0 (0x0)
30813: kevent(3,{0x18,EVFILT_WRITE,EV_ADD,0,0x0,0x0},1,0x0,0,{0.000000000 }) =
0 (0x0)
30813: gettimeofday({1361361535.995158 },0x0) = 0 (0x0)
30813: gettimeofday({1361361535.995204 },0x0) = 0 (0x0)
30813: kevent(3,{},0,{0x18,EVFILT_WRITE,0x0,0,0x800,0x0},26,{8.281605005 }) = 1
(0x1)
30813:
sendmsg(0x18,0x7fffffffa8e0,0x0,0x80cdd3000,0xfffffffff990800c,0x7fffffffa5f0)
= 3 (0x3)
30813: kevent(3,{0x18,EVFILT_WRITE,EV_DELETE,0,0x0,0x0},1,0x0,0,{0.000000000 })
= 0 (0x0)
30813: gettimeofday({1361361535.995489 },0x0) = 0 (0x0)
30813: gettimeofday({1361361535.995533 },0x0) = 0 (0x0)
30813: kevent(3,{},0,{0x1d,EVFILT_READ,0x0,0,0x583,0x0},26,{8.281275987 }) = 1
(0x1)
30813: read(29," [-] An exception was raised from application code while
processing a reactor selectable\n\tTraceback (most recent call last):\n\t
"...,8192) = 1411 (0x583)
30813: gettimeofday({1361361535.996574 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] [-] An exception was
raised from application code while processing a reactor selectable\n",129) =
129 (0x81)
30813: gettimeofday({1361361535.996857 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \tTraceback (most
recent call last):\n",76) = 76 (0x4c)
30813: gettimeofday({1361361535.997256 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/twisted/python/log.py", line 84, in
callWit"...,139) = 139 (0x8b)
30813: gettimeofday({1361361535.997553 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t return
callWithContext({"system": lp}, func, *args, **kw)\n",103) = 103 (0x67)
30813: gettimeofday({1361361535.997922 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/twisted/python/log.py", line 69, in
callWit"...,140) = 140 (0x8c)
30813: gettimeofday({1361361535.998238 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t return
context.call({ILogContext: newCtx}, func, *args, **kw)\n",107) = 107 (0x6b)
30813: gettimeofday({1361361535.998472 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/twisted/python/context.py", line 118,
in ca"...,145) = 145 (0x91)
30813: gettimeofday({1361361535.998868 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t return
self.currentContext().callWithContext(ctx, func, *args, **kw)\n",114) = 114
(0x72)
30813: gettimeofday({1361361535.999232 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/twisted/python/context.py", line 81, in
cal"...,144) = 144 (0x90)
30813: gettimeofday({1361361535.999506 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t return
func(*args,**kw)\n",69) = 69 (0x45)
30813: gettimeofday({1361361535.999856 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:55+0100 [-] [caldav-0] \t--- <exception caught
here> ---\n",73) = 73 (0x49)
30813: gettimeofday({1361361536.000212 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/twisted/internet/kqreactor.py", line
279, i"...,148) = 148 (0x94)
30813: gettimeofday({1361361536.000560 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t why =
selectable.doRead()\n",71) = 71 (0x47)
30813: gettimeofday({1361361536.000878 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/Calendar_and_Contacts_Server-4.2-py2.7-free"...,208)
= 208 (0xd0)
30813: gettimeofday({1361361536.001173 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t fd, description =
recvfd(self.fd)\n",79) = 79 (0x4f)
30813: gettimeofday({1361361536.001593 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t File
"/usr/local/lib/python2.7/site-packages/Calendar_and_Contacts_Server-4.2-py2.7-free"...,201)
= 201 (0xc9)
30813: gettimeofday({1361361536.001917 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t [unpackedFD] =
unpack("i", packedFD)\n",82) = 82 (0x52)
30813: gettimeofday({1361361536.002190 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \tstruct.error: unpack
requires a string argument of length 4\n",101) = 101 (0x65)
30813: gettimeofday({1361361536.002514 },0x0) = 0 (0x0)
30813: write(6,"2013-02-20 12:58:56+0100 [-] [caldav-0] \t\n",42) = 42 (0x2a)
30813: gettimeofday({1361361536.002814 },0x0) = 0 (0x0)
30813: gettimeofday({1361361536.002855 },0x0) = 0 (0x0)
30813: kevent(3,{},0,{},26,{8.273953914 }) = 0 (0x0)
30813: gettimeofday({1361361544.286639 },0x0) = 0 (0x0)
30813: __sysctl(0x7fffffff9fa0,0x4,0x7fffffff9fd0,0x7fffffff9fb8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffffaac0,0x4,0x7fffffffaaf0,0x7fffffffaad8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffff9fa0,0x4,0x7fffffff9fd0,0x7fffffff9fb8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffffaac0,0x4,0x7fffffffaaf0,0x7fffffffaad8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffff9fa0,0x4,0x7fffffff9fd0,0x7fffffff9fb8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffffaac0,0x4,0x7fffffffaaf0,0x7fffffffaad8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffff9fa0,0x4,0x7fffffff9fd0,0x7fffffff9fb8,0x0,0x0) = 0
(0x0)
30813: __sysctl(0x7fffffffaac0,0x4,0x7fffffffaaf0,0x7fffffffaad8,0x0,0x0) = 0
(0x0)
30813: gettimeofday({1361361544.287307 },0x0) = 0 (0x0)
30813: gettimeofday({1361361544.287384 },0x0) = 0 (0x0)
PGP-Key:29E99DD6 ☀ +49 151 2300 9283 ☀ computing @ chaos claudius
_______________________________________________
calendarserver-dev mailing list
calendarserver-dev@lists.macosforge.org
https://lists.macosforge.org/mailman/listinfo/calendarserver-dev
