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 <mailto: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_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
>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>