Hi Andre,
I think we're very close to resolve the issue, can you pls. enable
FINEST logging on org.glassfish.grizzly.http.io.InputBuffer.
Looks like if the payload comes in separate chunk somebody calls readByte().
Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
INFO: InputBuffer org.glassfish.grizzly.http.io.InputBuffer_at_58365946
readByte. Ready content: ByteBufferWrapper (1478438888)
[visible=[java.nio.HeapByteBufferR[pos=0 lim=0 cap=0]]]
So I wonder where it called from.
Thank you.
WBR,
Alexey.
On 19.08.13 14:56, André Wallat wrote:
> Hi Alexey,
>
> yeah, I know how this game is played :)
> Here comes the interesting part of the log. The first part shows a
> successful login and the last part hopefully gives the detail where
> it's going wrong:
>
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_2a5a6254 initialize with
> ready content: HeapBuffer (334335621) [pos=0 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_2a5a6254 fillFully, len:
> 33. Ready content: HeapBuffer (334335621) [pos=0 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_2a5a6254 getBuffer.
> Ready content: HeapBuffer (334335621) [pos=0 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.util.Parameters processParameters
> INFO: process parameters. Buffer: HeapBuffer (125283488) [pos=0
> lim=33 cap=33] start=0 len=33 firstbyte=j
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.util.Parameters processParameters
> INFO: Adding param. name=j_username value=admin
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.util.Parameters processParameters
> INFO: Adding param. name=j_password value=admin
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_2a5a6254 skip 33 bytes.
> Ready content: HeapBuffer (334335621) [pos=0 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_58365946 initialize with
> ready content: ByteBufferWrapper (1478438888)
> [visible=[java.nio.HeapByteBufferR[pos=0 lim=0 cap=0]]]
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_58365946 readByte. Ready
> content: ByteBufferWrapper (1478438888)
> [visible=[java.nio.HeapByteBufferR[pos=0 lim=0 cap=0]]]
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_58365946 fillFully, len:
> 33. Ready content: HeapBuffer (234235343) [pos=1 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_58365946 getBuffer.
> Ready content: HeapBuffer (234235343) [pos=1 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.util.Parameters processParameters
> INFO: process parameters. Buffer: HeapBuffer (888646187) [pos=1
> lim=33 cap=33] start=1 len=32 firstbyte=_
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.util.Parameters processParameters
> INFO: Adding param. name=_username value=admin
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.util.Parameters processParameters
> INFO: Adding param. name=j_password value=admin
> Aug 19, 2013 11:42:37 PM org.glassfish.grizzly.http.io.InputBuffer log
> INFO: InputBuffer
> org.glassfish.grizzly.http.io.InputBuffer_at_58365946 skip 32 bytes.
> Ready content: HeapBuffer (234235343) [pos=1 lim=33 cap=33]
> Aug 19, 2013 11:42:37 PM
> org.glassfish.grizzly.http.server.NetworkListener shutdownNow
> INFO: Stopped listener bound to [0.0.0.0:9998 <http://0.0.0.0:9998>]
>
>
> In the whole log the ByteBufferWrapper is only used when the error
> occurs, so maybe something is going wrong in there!?
>
> Cheers,
> André
>
>
>
>
> On Mon, Aug 19, 2013 at 9:06 PM, Oleksiy Stashok
> <oleksiy.stashok_at_oracle.com <mailto:oleksiy.stashok_at_oracle.com>> wrote:
>
> Hi Andre,
>
> it looks like 1 byte has been read off the payload before it got
> parsed as parameters.
> I prepared a new patch here [1] with more logging. It will help to
> track if somebody read 1 byte before parsing parameters.
>
> You can use the patch as it is - it will notify us about all the
> buffer reads, or you can set
> org.glassfish.grizzly.http.io.InputBuffer logging level to
> Level.FINEST to see the reads stacktraces as well.
>
> Thank you for help.
>
>
> WBR,
> Alexey.
>
> [1]
> https://dl.dropboxusercontent.com/u/7319744/params/grizzly-http-2.3.4.jar
>
> On 18.08.13 09:29, André Wallat wrote:
>> Hi Alexey,
>>
>> here's a part from the log. I wrote a simple test to send
>> POST-requests all the time and stop if the server responds with a
>> 403-error.
>>
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: process parameters. Buffer: HeapBuffer (418015750) [pos=0
>> lim=33 cap=33] start=0 len=33 firstbyte=j
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: Adding param. name=j_username value=admin
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: Adding param. name=j_password value=admin
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: process parameters. Buffer: HeapBuffer (1654094979) [pos=0
>> lim=33 cap=33] start=0 len=33 firstbyte=j
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: Adding param. name=j_username value=admin
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: Adding param. name=j_password value=admin
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: process parameters. Buffer: HeapBuffer (1271617369) [pos=1
>> lim=33 cap=33] start=1 len=32 firstbyte=_
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: Adding param. name=_username value=admin
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.util.Parameters processParameters
>> INFO: Adding param. name=j_password value=admin
>> Aug 18, 2013 6:21:15 PM
>> org.glassfish.grizzly.http.server.NetworkListener shutdownNow
>> INFO: Stopped listener bound to [0.0.0.0:9998 <http://0.0.0.0:9998>]
>>
>> Hope this helps,
>> André
>>
>>
>>
>> On Sun, Aug 18, 2013 at 5:27 PM, Oleksiy Stashok
>> <oleksiy.stashok_at_oracle.com <mailto:oleksiy.stashok_at_oracle.com>>
>> wrote:
>>
>> Hi Andre,
>>
>> unfortunately the log you sent looks fine.
>> Here I prepared the same patch for Grizzly 2.3.4 [1], there
>> is no need to change the logging level, because the logs I'm
>> interested in should be logged using Level.INFO.
>>
>> Thanks a lot.
>>
>> WBR,
>> Alexey.
>>
>> [1]
>> https://dl.dropboxusercontent.com/u/7319744/params/grizzly-http-2.3.4.jar
>>
>>
>>
>> On 18.08.13 06:36, André Wallat wrote:
>>> Hi Alexey,
>>>
>>> I tried the patched library but wasn't able to reproduce it
>>> unfortunately. With version 2.3.4 and logging level set to
>>> FINE I could get the error (see attached file). The finer I
>>> set the logging level the less the error occurs. But maybe
>>> the exception shown in the attached log file already helps
>>> to figure out the problem!?
>>>
>>> I will try some more tests ...
>>>
>>> Cheers,
>>> André
>>>
>>>
>>>
>>> On Sat, Aug 17, 2013 at 10:36 PM, Oleksiy Stashok
>>> <oleksiy.stashok_at_oracle.com
>>> <mailto:oleksiy.stashok_at_oracle.com>> wrote:
>>>
>>> Hi Andre,
>>>
>>> I tried the same request, but still can't reproduce the
>>> issue.
>>> Can you pls. try this patch [1], which extends Grizzly
>>> parameters parsing logging. Once the issue is reproduced
>>> - pls. send us the server logging.
>>>
>>> Thank you.
>>>
>>> WBR,
>>> Alexey.
>>>
>>> [1]
>>> https://dl.dropboxusercontent.com/u/7319744/params/grizzly-http-2.3.5.jar
>>>
>>>
>>>
>>> On 17.08.13 04:48, André Wallat wrote:
>>>> Hi everyone,
>>>>
>>>> I was able to take a snapshot showing the data that
>>>> lead to the error.
>>>>
>>>> * at packet no. 40 you can see a successful login
>>>> with the response in no. 43
>>>> * at packet no. 204 you can see another login (with
>>>> same form parameters) with a denied error sent in
>>>> no. 206
>>>>
>>>> I hope you can find out what's going wrong now :)
>>>> I was using an iPod touch and even on a Safari desktop
>>>> browser the problem occurred, however not that often!
>>>>
>>>> Cheers,
>>>> André
>>>>
>>>>
>>>> On Sat, Aug 17, 2013 at 4:52 AM, gajanan x.kulkarni
>>>> <gajanan.x.kulkarni_at_oracle.com
>>>> <mailto:gajanan.x.kulkarni_at_oracle.com>> wrote:
>>>>
>>>> ok lets wait on wireshark data from the André
>>>>
>>>> Thanks
>>>> Gajanan.
>>>>
>>>> On 8/17/2013 6:42 AM, Oleksiy Stashok wrote:
>>>>
>>>> I tried sending a request byte-by-byte, but
>>>> still can't reproduce the problem :(
>>>>
>>>>
>>>>
>>>> On 16.08.13 17:18, Gajanan wrote:
>>>>
>>>> Reason could be that request is coming in
>>>> smaller chunks and grizzly misses a char
>>>> while joining the chunks seen similare
>>>> issue on sailfin in the fast. To reproduce
>>>> u need simple code which writes request in
>>>> small chunks.
>>>>
>>>> Sent from my Xperia™ smartphone
>>>>
>>>> André Wallat <andre.wallat_at_gmail.com
>>>> <mailto:andre.wallat_at_gmail.com>> wrote:
>>>>
>>>> Hello,
>>>>
>>>> I came across a strange error when I access
>>>> my server from the iPad browser Safari.
>>>> Most of the times the first character of
>>>> the first form parameter is removed, so
>>>> instead of "username" the parameter
>>>> "sername" is received in my
>>>> ContainerRequestFilter. All the other
>>>> parameters are fine. Other browsers like
>>>> Chrome, Firefox and even Android worked okay.
>>>>
>>>> Any ideas? Maybe someone can open up an
>>>> issue for this?
>>>>
>>>> Here a bit more detailed scenario:
>>>> I send a post request with jQuery (v1.10.2)
>>>> to my server after I access my website the
>>>> first time. I think here it even works to
>>>> transmit/convert the form parameter
>>>> correctly, but when I submit the data a
>>>> second time, then the first form parameter
>>>> is losing its first character. My website
>>>> is a single-page-app created with AngularJS.
>>>> With firefox light I could check the
>>>> POST-request and the submitted parameters
>>>> were correct. So it has to be an error in
>>>> grizzly!?
>>>>
>>>> My workaround so far is to add a
>>>> dummy-Parameter as the first parameter, so
>>>> that the other parameters stay okay.
>>>>
>>>> Client: Safari iOS iPad 6.1.3
>>>> Server: Grizzly 2.3.5
>>>>
>>>> Cheers,
>>>> André
>>>>
>>>>
>>>>
>>>> --
>>>> "I say the glass is always full- half with air,
>>>> half with water!" - Modi
>>>>
>>>>
>>>
>>>
>>
>>
>
>