[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: Possible message multiplexing problem

On Tue, 24 Jun 2008 04:17:11 +0100
Love Hörnquist Åstrand <lha@kth.se> wrote:

> >
> > Is multiple packets going through the same port incorrect behavior
> > in itself?
> >
> > With extra logging I do not think I will be able to trigger the very  
> > rare
> > "Additional preauthentication required" error. But catching packets
> > going through the same port could be much easier.
> 
> Yes, there is no way to determine what request the reply should match  
> up with.

Well this seems like an OS related problem.

Below is logging of Apache starting w/ my SPNEGO module and then a second
or two of running 3 HTTP clients against it.

The format of each line is file:line:function: ident: pid: stuff. The
"OPENED" lines are immediately after connect() and "CLOSED" are
immediately after close(2). Note that the krb5_context 0x64e96bc0 is
the GSSAPI context which is inherited across Apache forking workers. Also
note that addresses are truncated to 4 bytes for brevity even though it
is a 64 bit system.

So you can clearly see different pids (3303, 3307, 3301, ...) getting
the same port (60994). Later on in the log (not shown below) the ports
do start to change but still not correctly.

The only thing I can think of is that the problem has something to do
with VMWare Server running on the machine (the Windows 2003 Server acting
as the KDC and running the HTTP clients is running within it). VMWare
installs a kernel module and creates a number of network interfaces for
the VMs. Maybe that driver is screwing up the kernel networking stack.

Or, perhaps Apache's prefork multi-process model isn't really using
fork(2) but something like clone(2) and that is having and effect
on things.

Whatever the case, it does not look like has anything to do with either
Heimdal or my code. If two different processes call connect(2) at around
the same time and get the same port number that's an OS issue.

I'm going to update VMWare server when CentOS 5.2 comes out (any day
now). I'll let you know what happens for anyone who may be curious.

Mike

context.c:245:krb5_init_context: CTXINI: 3298: 0x64e96bc0
context.c:245:krb5_init_context: CTXINI: 3298: 0x64eb04a0
context.c:272:krb5_free_context: CTXFRE: 3298: 0x64eb04a0
send_to_kdc.c:374:krb5_sendto: OPENED: 3298: context=0x64e96bc0,a=0x64eb2050,fd=19,addr=192.168.2.19,port=51062
send_to_kdc.c:391:krb5_sendto: CLOSED: 3298: context=0x64e96bc0,a=0x64eb2050,fd=19,addr=192.168.2.19,port=51062
send_to_kdc.c:374:krb5_sendto: OPENED: 3298: context=0x64e96bc0,a=0x64eb2160,fd=19,addr=192.168.2.19,port=51063
send_to_kdc.c:391:krb5_sendto: CLOSED: 3298: context=0x64e96bc0,a=0x64eb2160,fd=19,addr=192.168.2.19,port=51063
send_to_kdc.c:374:krb5_sendto: OPENED: 3298: context=0x64e96bc0,a=0x64eb3820,fd=19,addr=192.168.2.19,port=51064
send_to_kdc.c:391:krb5_sendto: CLOSED: 3298: context=0x64e96bc0,a=0x64eb3820,fd=19,addr=192.168.2.19,port=51064

<APACHE MODULE INIT COMPLETE - FORKING OF WORKERS STARTS HERE>

context.c:245:krb5_init_context: CTXINI: 3303: 0x64f3d000
send_to_kdc.c:374:krb5_sendto: OPENED: 3303: context=0x64f3d000,a=0x64f3e690,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3303: context=0x64f3d000,a=0x64f3e690,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:374:krb5_sendto: OPENED: 3303: context=0x64f3d000,a=0x64f3e4d0,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3303: context=0x64f3d000,a=0x64f3e4d0,fd=22,addr=192.168.2.19,port=60994
context.c:245:krb5_init_context: CTXINI: 3303: 0x64f3d8b0
context.c:272:krb5_free_context: CTXFRE: 3303: 0x64f3d8b0
send_to_kdc.c:374:krb5_sendto: OPENED: 3303: context=0x64e96bc0,a=0x64f3e7c0,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3303: context=0x64e96bc0,a=0x64f3e7c0,fd=22,addr=192.168.2.19,port=60994
context.c:272:krb5_free_context: CTXFRE: 3303: 0x64f3d000
context.c:245:krb5_init_context: CTXINI: 3307: 0x64f3cf80
context.c:272:krb5_free_context: CTXFRE: 3307: 0x64f3cf80
context.c:245:krb5_init_context: CTXINI: 3301: 0x64f3c510
context.c:272:krb5_free_context: CTXFRE: 3301: 0x64f3c510
send_to_kdc.c:374:krb5_sendto: OPENED: 3301: context=0x64e96bc0,a=0x64f42020,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3301: context=0x64e96bc0,a=0x64f42020,fd=22,addr=192.168.2.19,port=60994
context.c:245:krb5_init_context: CTXINI: 3302: 0x64f34310
context.c:272:krb5_free_context: CTXFRE: 3302: 0x64f34310
send_to_kdc.c:374:krb5_sendto: OPENED: 3302: context=0x64e96bc0,a=0x64f34660,fd=22,addr=192.168.2.19,port=45718
context.c:245:krb5_init_context: CTXINI: 3303: 0x64f45700
send_to_kdc.c:374:krb5_sendto: OPENED: 3303: context=0x64f45700,a=0x64f46d70,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3303: context=0x64f45700,a=0x64f46d70,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:374:krb5_sendto: OPENED: 3303: context=0x64f45700,a=0x64f46a90,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3303: context=0x64f45700,a=0x64f46a90,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3302: context=0x64e96bc0,a=0x64f34660,fd=22,addr=192.168.2.19,port=45718
send_to_kdc.c:374:krb5_sendto: OPENED: 3302: context=0x64e96bc0,a=0x64f34af0,fd=22,addr=192.168.2.19,port=45719
context.c:245:krb5_init_context: CTXINI: 3307: 0x64f43860
context.c:272:krb5_free_context: CTXFRE: 3307: 0x64f43860
send_to_kdc.c:391:krb5_sendto: CLOSED: 3302: context=0x64e96bc0,a=0x64f34af0,fd=22,addr=192.168.2.19,port=45719
send_to_kdc.c:374:krb5_sendto: OPENED: 3302: context=0x64e96bc0,a=0x64f35730,fd=22,addr=192.168.2.19,port=45720
context.c:245:krb5_init_context: CTXINI: 3305: 0x64f3c720
context.c:272:krb5_free_context: CTXFRE: 3305: 0x64f3c720
send_to_kdc.c:391:krb5_sendto: CLOSED: 3302: context=0x64e96bc0,a=0x64f35730,fd=22,addr=192.168.2.19,port=45720
context.c:245:krb5_init_context: CTXINI: 3308: 0x64f41720
send_to_kdc.c:374:krb5_sendto: OPENED: 3308: context=0x64f41720,a=0x64f42d90,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3308: context=0x64f41720,a=0x64f42d90,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:374:krb5_sendto: OPENED: 3308: context=0x64f41720,a=0x64f42bd0,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3308: context=0x64f41720,a=0x64f42bd0,fd=22,addr=192.168.2.19,port=60994
context.c:245:krb5_init_context: CTXINI: 3308: 0x64f41fb0
context.c:272:krb5_free_context: CTXFRE: 3308: 0x64f41fb0
send_to_kdc.c:374:krb5_sendto: OPENED: 3308: context=0x64e96bc0,a=0x64f42e80,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3308: context=0x64e96bc0,a=0x64f42e80,fd=22,addr=192.168.2.19,port=60994
context.c:272:krb5_free_context: CTXFRE: 3308: 0x64f41720
context.c:245:krb5_init_context: CTXINI: 3305: 0x64f337c0
context.c:272:krb5_free_context: CTXFRE: 3305: 0x64f337c0
send_to_kdc.c:374:krb5_sendto: OPENED: 3305: context=0x64e96bc0,a=0x64f33dd0,fd=22,addr=192.168.2.19,port=60994
send_to_kdc.c:391:krb5_sendto: CLOSED: 3305: context=0x64e96bc0,a=0x64f33dd0,fd=22,addr=192.168.2.19,port=60994
context.c:245:krb5_init_context: CTXINI: 3307: 0x64f5fbc0
context.c:272:krb5_free_context: CTXFRE: 3307: 0x64f5fbc0
send_to_kdc.c:374:krb5_sendto: OPENED: 3307: context=0x64e96bc0,a=0x64f44170,fd=22,addr=192.168.2.19,port=60994

-- 
Michael B Allen
PHP Active Directory SPNEGO SSO
http://www.ioplex.com/