Hi Alexey,
the bug seems to be fixed! Are you going to commit this workaround fix or
will there be a fix on the jersey side, where the root of the problem seems
to be?
Cheers and thanks for finding a fix,
André
On Tue, Aug 20, 2013 at 2:00 AM, Oleksiy Stashok <oleksiy.stashok_at_oracle.com
> wrote:
> Hi Andre,
>
> looks like it's a bug in Jersey [2], but we can work it around by
> propagating InputStream mark/reset mechanism to servlet layer.
> Pls. try the patch [1] and let me know if it fixes the problem.
>
> Thank you.
>
> WBR,
> Alexey.
>
> [1]
> https://dl.dropboxusercontent.com/u/7319744/params/grizzly-http-servlet-2.3.4.jar
> [2] org.glassfish.jersey.message.internal.EntityInputStream.java:172
>
> /**
> * Check if the underlying entity stream is empty.
> * <p>
> * Note that the operation may need to block until a first byte (or EOF) is available in the stream.
> * </p>
> *
> * @return {_at_code true} if the entity stream is empty, {_at_code false} otherwise.
> */
> public boolean isEmpty() {
> ensureNotClosed();
>
> if (input == null) {
> return true;
> }
>
> try {
> if (input.available() > 0) {
> return false;
> } else if (input.markSupported()) {
> input.mark(1);
> int i = input.read();
> input.reset();
> return i == -1;
> } else { int b = input.read();
> if (b == -1) {
> return true;
> }
>
> PushbackInputStream pbis;
> if (input instanceof PushbackInputStream) {
> pbis = (PushbackInputStream) input;
> } else {
> pbis = new PushbackInputStream(input, 1);
> input = pbis;
> }
> pbis.unread(b);
>
> return false;
> }
> } catch (IOException ex) {
> throw new ProcessingException(ex);
> }
> }
>
>
>
>
>
> On 19.08.13 16:07, André Wallat wrote:
>
> 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
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>