Re: Error in Form-Parameter conversion

  • From: Oleksiy Stashok <oleksiy.stashok@...>
  • To: users@...
  • Subject: Re: Error in Form-Parameter conversion
  • Date: Mon, 19 Aug 2013 15:14:38 -0700

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@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@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@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@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@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@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@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@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@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@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@... <mailto: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 <http://0.0.0.0:9998>]

    Hope this helps,
    André



    On Sun, Aug 18, 2013 at 5:27 PM, Oleksiy Stashok
    <oleksiy.stashok@... <mailto: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@...
        <mailto: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@...
            <mailto: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@...
                        <mailto: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

Gajanan 08/17/2013

Re: Error in Form-Parameter conversion

Oleksiy Stashok 08/17/2013

Re: Error in Form-Parameter conversion

gajanan x.kulkarni 08/17/2013

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-2017 (revision 20160708.bf2ac18)
 
 
Close
loading
Please Confirm
Close