Re: Error in Form-Parameter conversion

  • From: André Wallat <andre.wallat@...>
  • To: users@...
  • Subject: Re: Error in Form-Parameter conversion
  • Date: Tue, 20 Aug 2013 10:58:11 +0200

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@...
> 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 {@code true} if the entity stream is empty, {@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@...
> >:
>
>>  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@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@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@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@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@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@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@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@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@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@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@...> 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@...> 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@...> 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@...> 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@...> 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
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>


Re: Error in Form-Parameter conversion

(continued)

Re: Error in Form-Parameter conversion

André Wallat 08/17/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/17/2013

Re: Error in Form-Parameter conversion

André Wallat 08/18/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/18/2013

Re: Error in Form-Parameter conversion

André Wallat 08/18/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/19/2013

Re: Error in Form-Parameter conversion

André Wallat 08/19/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/19/2013

Re: Error in Form-Parameter conversion

André Wallat 08/19/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/20/2013

Re: Error in Form-Parameter conversion

André Wallat 08/20/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/20/2013
Terms of Use; Privacy Policy; Copyright ©2013-2015 (revision 20150226.965aeb8)
 
 
Close
loading
Please Confirm
Close