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_2a5a6254initialize 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_2a5a6254fillFully, 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_2a5a6254getBuffer. 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_58365946initialize 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_58365946readByte. 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_58365946fillFully, 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_58365946getBuffer. 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]
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
> 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]
>
> Hope this helps,
> André
>
>
>
> On Sun, Aug 18, 2013 at 5:27 PM, Oleksiy Stashok <
> 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> 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> 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> 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
>>>>
>>>>
>>>
>>>
>>
>>
>
>