Pipe auth with Jabberd2 c2s *seems* to hang to the client

Hello all,

I am trying to set up jabberd2 to use pipe authentication. 
When I test
USER-EXISTS and CHECK-PASSWORD manually with the pipe auth
script
everything appears to work fine.  Trying to connect using
Psi I get the
following in the XML console...

> <?xml version="1.0"?>
> 
> <stream:stream xmlns:stream="http://etherx.jabber
.org/streams" xmlns="jabber:client"
to="jabber.kc8onw.net" >
> 
> <?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
> 
> <iq type="get" id="auth_1"
to="jabber.kc8onw.net" >
> <query xmlns="jabber:iq:auth">
> <username>jonathan</username>
> </query>
> </iq>

and then I never see anything else till the connection is
reset.  I
recompiled JabberD with debug enabled and have the portion
of the debug
log from the start of trying to connect to where it seems to
hang below.

If anyone has any clue or suggestions what to try next I'd
welcome them
because I'm completely stuck.  If more info is needed just
let me know
what and I'll grab it.

Thanks,
Jonathan

> C2S : Mon Jun 12 06:27:06 2006 [notice] [9]
[217.194.139.131, port=55416] connect
> C2S : sx (io.c:461) 9 state change from 3 to 6
> C2S : sx (io.c:462) tag 9 event 7 data 0x0
> C2S : Mon Jun 12 06:26:51 2006 c2s.c:400 close action
on fd 9
> C2S : sx (sx.c:72) freeing sx for 9
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:417 accept action
on fd 9
> C2S : sx (sx.c:55) allocated new sx for 9
> C2S : sx (server.c:236) doing server init for sx 9
> C2S : sx (server.c:251) waiting for stream header
> C2S : sx (server.c:254) tag 9 event 0 data 0x0
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:33 want read
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:381 read action on
fd 9
> C2S : sx (io.c:159) 9 ready for reading
> C2S : sx (io.c:165) tag 9 event 2 data 0x8087be0
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:43 reading from 9
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:97 read 132 bytes
> C2S : sx (io.c:181) passed 132 read bytes
> C2S : sx (chain.c:93) calling io read chain
> C2S : sx (io.c:205) decoded read data (132 bytes):
<?xml version="1.0"?>
> C2S : <stream:stream xmlns:stream="http://etherx.jabber
.org/streams" xmlns="jabber:client"
to="jabber.kc8onw.net" >
> C2S :
> C2S : sx (server.c:118) stream request: to
jabber.kc8onw.net from (null) version (null)
> C2S : sx (server.c:133) 9 state change from 0 to 1
> C2S : sx (server.c:151) stream id is
s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe
> C2S : sx (server.c:181) prepared stream response:
<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
> C2S : sx (io.c:221) tag 9 event 1 data 0x0
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:38 want write
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:395 write action
on fd 9
> C2S : sx (io.c:293) 9 ready for writing
> C2S : sx (io.c:251) encoding 177 bytes for writing:
<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
> C2S : sx (chain.c:79) calling io write chain
> C2S : sx (io.c:312) handing app 177 bytes to write
> C2S : sx (io.c:313) tag 9 event 3 data 0x8087c00
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:104 writing to 9
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:108 177 bytes
written
> C2S : sx (server.c:29) stream established
> C2S : sx (server.c:39) 9 state change from 1 to 3
> C2S : sx (server.c:40) tag 9 event 4 data 0x0
> C2S : sx (io.c:346) tag 9 event 0 data 0x0
> C2S : Mon Jun 12 06:27:06 2006 c2s.c:33 want read
> C2S : Mon Jun 12 06:27:07 2006 c2s.c:381 read action on
fd 9
> ROUT: sx (chain.c:119) calling nad read chain
> ROUT: sx (io.c:124) tag 7 event 6 data 0x8088300
> ROUT: Mon Jun 12 06:26:29 2006 router.c:378 unicast
route from jabber.kc8onw.net to c2s
> ROUT: Mon Jun 12 06:26:29 2006 router.c:412 writing
route for 'c2s' to 127.0.0.1, port 64939
> ROUT: sx (chain.c:106) calling nad write chain
> ROUT: sx (io.c:369) queueing for write: <route
xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
to='c2s' from='jabber.kc8onw.net'><iq
xmlns='jabber:client' type='get' to='c2s'
from='jabber.kc8onw.net' id='qnpw5dmy'><query
xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> S2S : sx (io.c:159) 4 ready for reading
> ROUT: sx (io.c:392) tag 8 event 1 data 0x0
> S2S : sx (io.c:165) tag 4 event 2 data 0x80812a0
> ROUT: Mon Jun 12 06:26:29 2006 router.c:508 want write
> S2S : Mon Jun 12 06:26:29 2006 router.c:44 reading from
4
> ROUT: Mon Jun 12 06:26:29 2006 router.c:860 write
action on fd 8
> S2S : Mon Jun 12 06:26:29 2006 router.c:69 read 250
bytes
> ROUT: sx (io.c:293) 8 ready for writing
> S2S : sx (io.c:181) passed 250 read bytes
> ROUT: sx (io.c:251) encoding 250 bytes for writing:
<route xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
to='c2s' from='jabber.kc8onw.net'><iq
xmlns='jabber:client' type='get' to='c2s'
from='jabber.kc8onw.net' id='qnpw5dmy'><query
xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> S2S : sx (chain.c:93) calling io read chain
> ROUT: sx (chain.c:79) calling io write chain
> S2S : sx (io.c:205) decoded read data (250 bytes):
<route xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
to='s2s' from='jabber.kc8onw.net'><iq
xmlns='jabber:client' type='get' to='s2s'
from='jabber.kc8onw.net' id='u5kwiu7r'><query
xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> ROUT: sx (io.c:312) handing app 250 bytes to write
> S2S : sx (io.c:70) completed nad: <route xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
from='jabber.kc8onw.net' to='s2s'><iq
xmlns='jabber:client' id='u5kwiu7r'
from='jabber.kc8onw.net' to='s2s'
type='get'><query xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> ROUT: sx (io.c:313) tag 8 event 3 data 0x807f920
> S2S : sx (chain.c:119) calling nad read chain
> ROUT: Mon Jun 12 06:26:29 2006 router.c:578 writing to
8
> S2S : sx (io.c:124) tag 4 event 6 data 0x808a300
> ROUT: Mon Jun 12 06:26:29 2006 router.c:582 250 bytes
written
> S2S : Mon Jun 12 06:26:29 2006 router.c:205 got a
packet
> ROUT: sx (io.c:346) tag 8 event 0 data 0x0
> S2S : Mon Jun 12 06:26:29 2006 router.c:246 dropping
unknown or invalid packet for s2s component proper
> ROUT: Mon Jun 12 06:26:29 2006 router.c:503 want read
> S2S : Mon Jun 12 06:26:29 2006 router.c:290 read action
on fd 4
> ROUT: sx (io.c:394) tag 8 event 0 data 0x0
> S2S : sx (io.c:159) 4 ready for reading
> ROUT: Mon Jun 12 06:26:29 2006 router.c:503 want read
> S2S : sx (io.c:165) tag 4 event 2 data 0x80813a0
> ROUT: Mon Jun 12 06:27:14 2006 main.c:429 running time
checks
> S2S : Mon Jun 12 06:26:29 2006 router.c:44 reading from
4
> S2S : Mon Jun 12 06:26:29 2006 router.c:69 read 79
bytes
> S2S : sx (io.c:181) passed 79 read bytes
> S2S : sx (chain.c:93) calling io read chain
> S2S : sx (io.c:205) decoded read data (79 bytes):
<presence xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
from='c2s'/>
> S2S : sx (io.c:70) completed nad: <presence
xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
from='c2s'/>
> S2S : sx (chain.c:119) calling nad read chain
> S2S : sx (io.c:124) tag 4 event 6 data 0x808a300
> S2S : Mon Jun 12 06:26:29 2006 router.c:205 got a
packet
> S2S : Mon Jun 12 06:26:29 2006 router.c:215 dropping
non-route packet
> S2S : Mon Jun 12 06:27:14 2006 main.c:567 running time
checks
> ROUT: Mon Jun 12 06:27:14 2006 main.c:434 next time
check at 1150108094
> ROUT: Mon Jun 12 06:28:14 2006 main.c:429 running time
checks
> S2S : Mon Jun 12 06:27:14 2006 main.c:572 next time
check at 1150108094
> S2S : Mon Jun 12 06:28:14 2006 main.c:567 running time
checks

_______________________________________________
jabberd mailing list
jabberdjabberstudio.org
http:
//mail.jabber.org/mailman/listinfo/jabberd

try Exodus?

We also use pipe authreg .. Exodus works fine

2006/6/12, Jonathan Stewart <jonathankc8onw.net>:
> Hello all,
>
> I am trying to set up jabberd2 to use pipe
authentication.  When I test
> USER-EXISTS and CHECK-PASSWORD manually with the pipe
auth script
> everything appears to work fine.  Trying to connect
using Psi I get the
> following in the XML console...
>
> > <?xml version="1.0"?>
> >
> > <stream:stream xmlns:stream="http://etherx.jabber
.org/streams" xmlns="jabber:client"
to="jabber.kc8onw.net" >
> >
> > <?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
> >
> > <iq type="get"
id="auth_1" to="jabber.kc8onw.net"
>
> > <query xmlns="jabber:iq:auth">
> > <username>jonathan</username>
> > </query>
> > </iq>
>
> and then I never see anything else till the connection
is reset.  I
> recompiled JabberD with debug enabled and have the
portion of the debug
> log from the start of trying to connect to where it
seems to hang below.
>
> If anyone has any clue or suggestions what to try next
I'd welcome them
> because I'm completely stuck.  If more info is needed
just let me know
> what and I'll grab it.
>
> Thanks,
> Jonathan
>
> > C2S : Mon Jun 12 06:27:06 2006 [notice] [9]
[217.194.139.131, port=55416] connect
> > C2S : sx (io.c:461) 9 state change from 3 to 6
> > C2S : sx (io.c:462) tag 9 event 7 data 0x0
> > C2S : Mon Jun 12 06:26:51 2006 c2s.c:400 close
action on fd 9
> > C2S : sx (sx.c:72) freeing sx for 9
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:417 accept
action on fd 9
> > C2S : sx (sx.c:55) allocated new sx for 9
> > C2S : sx (server.c:236) doing server init for sx 9
> > C2S : sx (server.c:251) waiting for stream header
> > C2S : sx (server.c:254) tag 9 event 0 data 0x0
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:33 want read
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:381 read
action on fd 9
> > C2S : sx (io.c:159) 9 ready for reading
> > C2S : sx (io.c:165) tag 9 event 2 data 0x8087be0
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:43 reading
from 9
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:97 read 132
bytes
> > C2S : sx (io.c:181) passed 132 read bytes
> > C2S : sx (chain.c:93) calling io read chain
> > C2S : sx (io.c:205) decoded read data (132 bytes):
<?xml version="1.0"?>
> > C2S : <stream:stream xmlns:stream="http://etherx.jabber
.org/streams" xmlns="jabber:client"
to="jabber.kc8onw.net" >
> > C2S :
> > C2S : sx (server.c:118) stream request: to
jabber.kc8onw.net from (null) version (null)
> > C2S : sx (server.c:133) 9 state change from 0 to 1
> > C2S : sx (server.c:151) stream id is
s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe
> > C2S : sx (server.c:181) prepared stream response:
<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
> > C2S : sx (io.c:221) tag 9 event 1 data 0x0
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:38 want write
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:395 write
action on fd 9
> > C2S : sx (io.c:293) 9 ready for writing
> > C2S : sx (io.c:251) encoding 177 bytes for
writing: <?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
> > C2S : sx (chain.c:79) calling io write chain
> > C2S : sx (io.c:312) handing app 177 bytes to write
> > C2S : sx (io.c:313) tag 9 event 3 data 0x8087c00
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:104 writing
to 9
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:108 177 bytes
written
> > C2S : sx (server.c:29) stream established
> > C2S : sx (server.c:39) 9 state change from 1 to 3
> > C2S : sx (server.c:40) tag 9 event 4 data 0x0
> > C2S : sx (io.c:346) tag 9 event 0 data 0x0
> > C2S : Mon Jun 12 06:27:06 2006 c2s.c:33 want read
> > C2S : Mon Jun 12 06:27:07 2006 c2s.c:381 read
action on fd 9
> > ROUT: sx (chain.c:119) calling nad read chain
> > ROUT: sx (io.c:124) tag 7 event 6 data 0x8088300
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:378
unicast route from jabber.kc8onw.net to c2s
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:412
writing route for 'c2s' to 127.0.0.1, port 64939
> > ROUT: sx (chain.c:106) calling nad write chain
> > ROUT: sx (io.c:369) queueing for write: <route
xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
to='c2s' from='jabber.kc8onw.net'><iq
xmlns='jabber:client' type='get' to='c2s'
from='jabber.kc8onw.net' id='qnpw5dmy'><query
xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> > S2S : sx (io.c:159) 4 ready for reading
> > ROUT: sx (io.c:392) tag 8 event 1 data 0x0
> > S2S : sx (io.c:165) tag 4 event 2 data 0x80812a0
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:508 want
write
> > S2S : Mon Jun 12 06:26:29 2006 router.c:44 reading
from 4
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:860 write
action on fd 8
> > S2S : Mon Jun 12 06:26:29 2006 router.c:69 read
250 bytes
> > ROUT: sx (io.c:293) 8 ready for writing
> > S2S : sx (io.c:181) passed 250 read bytes
> > ROUT: sx (io.c:251) encoding 250 bytes for
writing: <route xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
to='c2s' from='jabber.kc8onw.net'><iq
xmlns='jabber:client' type='get' to='c2s'
from='jabber.kc8onw.net' id='qnpw5dmy'><query
xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> > S2S : sx (chain.c:93) calling io read chain
> > ROUT: sx (chain.c:79) calling io write chain
> > S2S : sx (io.c:205) decoded read data (250 bytes):
<route xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
to='s2s' from='jabber.kc8onw.net'><iq
xmlns='jabber:client' type='get' to='s2s'
from='jabber.kc8onw.net' id='u5kwiu7r'><query
xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> > ROUT: sx (io.c:312) handing app 250 bytes to write
> > S2S : sx (io.c:70) completed nad: <route
xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
from='jabber.kc8onw.net' to='s2s'><iq
xmlns='jabber:client' id='u5kwiu7r'
from='jabber.kc8onw.net' to='s2s'
type='get'><query xmlns='http://jabber.o
rg/protocol/disco#info'/></iq></route>
> > ROUT: sx (io.c:313) tag 8 event 3 data 0x807f920
> > S2S : sx (chain.c:119) calling nad read chain
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:578
writing to 8
> > S2S : sx (io.c:124) tag 4 event 6 data 0x808a300
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:582 250
bytes written
> > S2S : Mon Jun 12 06:26:29 2006 router.c:205 got a
packet
> > ROUT: sx (io.c:346) tag 8 event 0 data 0x0
> > S2S : Mon Jun 12 06:26:29 2006 router.c:246
dropping unknown or invalid packet for s2s component proper
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:503 want
read
> > S2S : Mon Jun 12 06:26:29 2006 router.c:290 read
action on fd 4
> > ROUT: sx (io.c:394) tag 8 event 0 data 0x0
> > S2S : sx (io.c:159) 4 ready for reading
> > ROUT: Mon Jun 12 06:26:29 2006 router.c:503 want
read
> > S2S : sx (io.c:165) tag 4 event 2 data 0x80813a0
> > ROUT: Mon Jun 12 06:27:14 2006 main.c:429 running
time checks
> > S2S : Mon Jun 12 06:26:29 2006 router.c:44 reading
from 4
> > S2S : Mon Jun 12 06:26:29 2006 router.c:69 read 79
bytes
> > S2S : sx (io.c:181) passed 79 read bytes
> > S2S : sx (chain.c:93) calling io read chain
> > S2S : sx (io.c:205) decoded read data (79 bytes):
<presence xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
from='c2s'/>
> > S2S : sx (io.c:70) completed nad: <presence
xmlns='http
://jabberd.jabberstudio.org/ns/component/1.0'
from='c2s'/>
> > S2S : sx (chain.c:119) calling nad read chain
> > S2S : sx (io.c:124) tag 4 event 6 data 0x808a300
> > S2S : Mon Jun 12 06:26:29 2006 router.c:205 got a
packet
> > S2S : Mon Jun 12 06:26:29 2006 router.c:215
dropping non-route packet
> > S2S : Mon Jun 12 06:27:14 2006 main.c:567 running
time checks
> > ROUT: Mon Jun 12 06:27:14 2006 main.c:434 next
time check at 1150108094
> > ROUT: Mon Jun 12 06:28:14 2006 main.c:429 running
time checks
> > S2S : Mon Jun 12 06:27:14 2006 main.c:572 next
time check at 1150108094
> > S2S : Mon Jun 12 06:28:14 2006 main.c:567 running
time checks
>
> _______________________________________________
> jabberd mailing list
> jabberdjabberstudio.org
> http:
//mail.jabber.org/mailman/listinfo/jabberd
>
_______________________________________________
jabberd mailing list
jabberdjabberstudio.org
http:
//mail.jabber.org/mailman/listinfo/jabberd

[Please don't top post and trim your replies, thanks
http://en.wi
kipedia.org/wiki/Top-posting ]

Yingbo Qiu wrote:
> 2006/6/12, Jonathan Stewart <jonathankc8onw.net>:
>> Hello all,
>>
>> I am trying to set up jabberd2 to use pipe
authentication.  When I test
>> USER-EXISTS and CHECK-PASSWORD manually with the
pipe auth script
>> everything appears to work fine.  Trying to connect
using Psi I get the
>> following in the XML console...
>>
>> > <?xml version="1.0"?>
>> >
>> > <stream:stream xmlns:stream="http://etherx.jabber
.org/streams"
>> xmlns="jabber:client"
to="jabber.kc8onw.net" >
>> >
>> > <?xml version='1.0'?><stream:stream
>> xmlns:stream='http://etherx.jabber
.org/streams' xmlns='jabber:client'
>> from='jabber.kc8onw.net'
id='s1scvs9pwh0e1u3dd7y1902nhrun6roeex66kwhe'>
>> >
>> > <iq type="get"
id="auth_1" to="jabber.kc8onw.net"
>
>> > <query
xmlns="jabber:iq:auth">
>> > <username>jonathan</username>
>> > </query>
>> > </iq>
>>
>> and then I never see anything else till the
connection is reset.
>
> try Exodus?
> 
> We also use pipe authreg .. Exodus works fine

I didn't think it was a client issue because the last
traffic shown in
the XML log was from the client to the server and the client
is waiting
on a response from the server which never shows up.  But I
tried
connecting using mcabber which worked fine.  Then I realized
that I had
changed Psi to use 5222 so I could try and trace traffic
with ethereal.
 I changed Psi to use 5223 and now it connects fine :P

[some time later]

In writing this email I came across this in my C2S.xml

    <!-- Require STARTTLS. If this is enabled, clients
must do STARTTLS
         before they can authenticate. Until the stream is
encrypted,
         all packets will be dropped. -->

    <require-starttls/>

I would guess the server was waiting for a STARTTLS which it
never got
because Psi does not support STARTTLS :P

This initially came up because of an issue someone asked
about in the
jadmin thread titled "[jadmin] Anyone running FreeBSD
have jabberd2
working with PAM auth?" which can be found here
http://mail.jabber.org/pipermail/jadmin/2006-June/0
24027.html and more
detail will be in that thread.

Thanks,
Jonathan




_______________________________________________
jabberd mailing list
jabberdjabberstudio.org
http:
//mail.jabber.org/mailman/listinfo/jabberd