So ... I attached a part of the log file to this email. Logging level set
to FINEST for the InputBuffer.
Am 20.08.2013 00:15 schrieb "Oleksiy Stashok" <oleksiy.stashok_at_oracle.com>:
> 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_58365946readByte. 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_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_2a5a6254skip 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_58365946skip 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
>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>
>