users@grizzly.java.net

Re: BUFFER_UNDERFLOW problem with SSL

From: Amy Kang <Amy.Kang_at_Sun.COM>
Date: Wed, 05 Nov 2008 07:31:39 -0800

Please see below for more debug logging output.
This time I'v used stateful protocol chain. My parser
did get called but with garbage as if it's not unwrapped.

My parser extends com.sun.grizzly.ParserProtocolFilter
by overriding newProtocolParser() method.

-------------------------------------------------------------------
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller doSelect
FINE: OP_ACCEPT on sun.nio.ch.SelectionKeyImpl_at_a53de4
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller doSelect
FINE: OP_READ on sun.nio.ch.SelectionKeyImpl_at_e4245
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller pollContext
FINE: pollContext(..) Context : com.sun.grizzly.Context_at_95da38
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=100 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] consumed: 100 produced: 0 status: OK
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=139 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] consumed: 139 produced: 0 status: OK
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
:q
yueyang >cat g
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller doSelect
FINE: OP_ACCEPT on sun.nio.ch.SelectionKeyImpl_at_a53de4
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller doSelect
FINE: OP_READ on sun.nio.ch.SelectionKeyImpl_at_e4245
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller pollContext
FINE: pollContext(..) Context : com.sun.grizzly.Context_at_95da38
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=100 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] consumed: 100 produced: 0 status: OK
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=139 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] consumed: 139 produced: 0 status: OK
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] consumed: 0 produced: 0 status: BUFFER_UNDERFLOW
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=43 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=37 lim=20480 cap=20480] consumed: 6 produced: 0 status: OK
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=37 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:427)
com.sun.grizzly.util.SSLUtils.doHandshake(SSLUtils.java:377)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:223)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:325)
com.sun.grizzly.util.WorkerThreadImpl.run(WorkerThreadImpl.java:184)
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] consumed: 37 produced: 0 status: OK
Nov 5, 2008 7:19:03 AM com.sun.grizzly.filter.SSLReadFilter doRead
FINE: SSLReadFilter. Read: 0 Calling unwrapAll. InputBB: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480] byteBuffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384 cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480 cap=20480]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.util.SSLUtils unwrap
FINER:
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getStackTrace(Thread.java:1383)
com.sun.grizzly.util.SSLUtils.unwrap(SSLUtils.java:245)
com.sun.grizzly.util.SSLUtils.unwrapAll(SSLUtils.java:192)
com.sun.grizzly.filter.SSLReadFilter.doRead(SSLReadFilter.java:268)
com.sun.grizzly.filter.SSLReadFilter.doHandshake(SSLReadFilter.java:226)
com.sun.grizzly.filter.SSLReadFilter.execute(SSLReadFilter.java:154)
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:67)
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:56)
com.sun.grizzly.util.WorkerThreadImpl.processTask(WorkerThreadImpl.java:pectingMoreData
FINEST: expectingMoreData=true
Nov 5, 2008 7:19:03 AM com.sun.messaging.bridge.service.Custom.CustomProtocolParser releaseBuffer
FINEST: [expectingMoreData=true, hasMoreBytesToParse=false]
Nov 5, 2008 7:19:03 AM com.sun.grizzly.Controller returnContext
FINE: returnContext() Context : com.sun.grizzly.Context_at_95da38

----- Original Message -----
From: Oleksiy Stashok <Oleksiy.Stashok_at_Sun.COM>
Date: Wednesday, November 5, 2008 1:35 am
Subject: Re: BUFFER_UNDERFLOW problem with SSL
To: users_at_grizzly.dev.java.net


> Agree with John. Please set FINEST or ALL logging level.
> For me it looks like handshake phase passed fine, but then nothing
> happens... nothing comes to server.
>
> Thanks.
>
> WBR,
> Alexey.
>
> On Nov 5, 2008, at 7:37 , John ROM wrote:
>
> > Hi Amy,
> > could you set log level to ALL?
> > just to make sure, your Filter is not using
> > com.sun.grizzly.filter.ParserProtocolFilter but you have written a
>
> > custom ProtocolFilter?
> >
> > could you share your code?
> >
> > Many Greetings
> > John
> >
> > -------- Original-Nachricht --------
> >> Datum: Tue, 04 Nov 2008 17:45:55 -0800
> >> Von: Amy Kang <Amy.Kang_at_Sun.COM>
> >> An: users_at_grizzly.dev.java.net
> >> Betreff: BUFFER_UNDERFLOW problem with SSL
> >
> >> Hi,
> >>
> >> Have anyone seen similar problem using SSL ? My server uses
> >> SSLReadFilter at front of my own protocol parser and filter. However
> >> my parser and filter were not get called and the client does not get
> >> a reply after sent its first application data packet. I'm using
> >> self-signed
> >> certificate on server side and client uses a trust all default
> >> TrustManager,
> >> Grizzly 1.8.6.3
> >>
> >> Nov 4, 2008 2:57:43 AM com.sun.grizzly.Controller doSelect
> >> FINE: OP_ACCEPT on sun.nio.ch.SelectionKeyImpl_at_716cb7
> >> Nov 4, 2008 2:57:43 AM com.sun.grizzly.Controller doSelect
> >> FINE: OP_READ on sun.nio.ch.SelectionKeyImpl_at_1a61172
> >> Nov 4, 2008 2:57:43 AM com.sun.grizzly.Controller pollContext
> >> FINE: pollContext(..) Context : com.sun.grizzly.Context_at_6ed322
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384
> >> cap=16384] secured: java.nio.HeapByteBuffer[pos=100 lim=20480
> >> cap=20480]
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384
> >> cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480
> >> cap=20480]
> >> consumed: 100 produced: 0 status: OK
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384
> >> cap=16384] secured: java.nio.HeapByteBuffer[pos=139 lim=20480
> >> cap=20480]
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384
> >> cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480
> >> cap=20480]
> >> consumed: 139 produced: 0 status: OK
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> FINE: start unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384
> >> cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480
> >> cap=20480]
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> FINE: after unwrap. buffer: java.nio.HeapByteBuffer[pos=0 lim=16384
> >> cap=16384] secured: java.nio.HeapByteBuffer[pos=0 lim=20480
> >> cap=20480]
> >> consumed: 0 p roduced: 0 status: BUFFER_UNDERFLOW
> >> Nov 4, 2008 2:57:45 AM com.sun.grizzly.util.SSLUtils unwrap
> >> .....
> >>
> >> Thanks,
> >> Amy
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: users-unsubscribe_at_grizzly.dev.java.net
> >> For additional commands, e-mail: users-help_at_grizzly.dev.java.net
> >
> > --
> > "Feel free" - 10 GB Mailbox, 100 FreeSMS/Monat ...
> > Jetzt GMX TopMail testen: http://www.gmx.net/de/go/topmail
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: users-unsubscribe_at_grizzly.dev.java.net
> > For additional commands, e-mail: users-help_at_grizzly.dev.java.net
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe_at_grizzly.dev.java.net
> For additional commands, e-mail: users-help_at_grizzly.dev.java.net
>