Jetty
  1. Jetty
  2. JETTY-322

AJP13 - Invalid state on AJP CPING request

    Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Number of attachments :
      4

      Description

      I'm using Linux ubuntu with Apache 2.0.55 and mod_jk 1.2.14. (I tried it on redhat 4 also with apache 2.0.52 and mod_jk 1.2.19 it is the same).
      With the latest version of jetty (6.1.2rc5) I managed to solve most of my problems with Ajp13 (SSL and other).
      With basic configuration the HTTP and HTTPS queries are answered but some strange error appears in the mod_jk.log file.
      The mod_jk.log is full of:
      [Thu Apr 26 23:17:38 2007] [info] ajp_send_request::jk_ajp_common.c (1178): Socket 14 is not connected any more (errno=-1)
      [Thu Apr 26 23:17:38 2007] [info] ajp_send_request::jk_ajp_common.c (1202): Error sending request. Will try another pooled connection
      [Thu Apr 26 23:17:38 2007] [info] ajp_send_request::jk_ajp_common.c (1225): All endpoints are disconnected or dead
      [Thu Apr 26 23:17:38 2007] [info] ajp_service::jk_ajp_common.c (1749): Sending request to tomcat failed, recoverable operation attempt=1
      [Thu Apr 26 23:17:39 2007] [info] ajp_send_request::jk_ajp_common.c (1178): Socket 14 is not connected any more (errno=-1)
      [Thu Apr 26 23:17:39 2007] [info] ajp_send_request::jk_ajp_common.c (1202): Error sending request. Will try another pooled connection

      Suspecting connections not keep alive I changed my worker.properties with:
      worker.list=jetty
      worker.jetty.port=8011
      worker.jetty.host=localhost
      worker.jetty.type=ajp13
      worker.jetty.lbfactor=1
      worker.jetty.socket_keepalive=1
      worker.jetty.socket_timeout=60
      worker.jetty.recycle_timeout=60
      worker.jetty.connect_timeout=60000
      worker.jetty.prepost_timeout=60000

      Now I get on jetty:
      2007-04-26 23:43:18.934::WARN: handle failed
      java.lang.IllegalStateException: State==HEADER
      at org.mortbay.jetty.ajp.Ajp13Generator.flush(Ajp13Generator.java:431)
      at org.mortbay.jetty.ajp.Ajp13Generator.sendCPong(Ajp13Generator.java:765)
      at org.mortbay.jetty.ajp.Ajp13Parser.parseNext(Ajp13Parser.java:294)
      at org.mortbay.jetty.ajp.Ajp13Parser.parseAvailable(Ajp13Parser.java:142)
      at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java :378)
      at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:226)
      at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)
      2007-04-26 23:43:18.937::INFO: AJP13: CPING is sent by peer

      and on mod_jk.log:
      [Thu Apr 26 23:37:31 2007] [info] ajp_connection_tcp_get_message::jk_ajp_common.c (955): Tomcat has forced a connection close for socket 14
      [Thu Apr 26 23:37:31 2007] [info] ajp_handle_cping_cpong::jk_ajp_common.c (833): awaited reply cpong, not received
      [Thu Apr 26 23:37:31 2007] [info] ajp_send_request::jk_ajp_common.c (1248): Error connecting to the Tomcat process.
      [Thu Apr 26 23:37:31 2007] [info] ajp_service::jk_ajp_common.c (1749): Sending request to tomcat failed, recoverable operation attempt=3
      [Thu Apr 26 23:37:31 2007] [error] ajp_service::jk_ajp_common.c (1758): Error connecting to tomcat. Tomcat is probably not started or is listening on the wrong port. worker=jetty failed
      [Thu Apr 26 23:37:31 2007] [info] jk_handler::mod_jk.c (1971): Service error=0 for worker=jetty

      1. ajp_patch_20070423.patch
        1 kB
        Leopoldo Agdeppa III
      2. ajp_patch_20070430.patch
        2 kB
        Leopoldo Agdeppa III
      3. ajp_patch_20070503.patch
        9 kB
        Leopoldo Agdeppa III
      4. fred_ajp_patch_20070429.patch
        4 kB
        Frederic Simon

        Activity

        Hide
        Leopoldo Agdeppa III added a comment -

        when flushing a data the state of generator is checked if its equals to header, and throws and illegal state exception STATE==HEADER, at this point of time, when apache sents a CPING request, we need to flush CPONG data as an immediate response to the request, so I decided to ignore this state checking during flushing if its a CPING request

        Show
        Leopoldo Agdeppa III added a comment - when flushing a data the state of generator is checked if its equals to header, and throws and illegal state exception STATE==HEADER, at this point of time, when apache sents a CPING request, we need to flush CPONG data as an immediate response to the request, so I decided to ignore this state checking during flushing if its a CPING request
        Hide
        Leopoldo Agdeppa III added a comment -

        Fix Patch

        Show
        Leopoldo Agdeppa III added a comment - Fix Patch
        Leopoldo Agdeppa III made changes -
        Field Original Value New Value
        Attachment ajp_patch_20070423.patch [ 27044 ]
        Hide
        Greg Wilkins added a comment -

        thanks bong

        Show
        Greg Wilkins added a comment - thanks bong
        Greg Wilkins made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Hide
        Frederic Simon added a comment -

        So, I tried the pacth and it solve the problem but I encountered the next one (which is the original "Socket 14 is not connected any more (errno=-1)"
        I found the problem and solved it (it's in the patch joined).
        In AJP the connections are persistent, so basically, the patch is initializing the Ajp13Generator to persistent and increasing the default timeout on the Ajp13SocketConnector. There was also some changes in the rest methods needed for making it work.
        With the patch have no exception on any side (mod_jk and jetty) and the sockets stay open.

        Show
        Frederic Simon added a comment - So, I tried the pacth and it solve the problem but I encountered the next one (which is the original "Socket 14 is not connected any more (errno=-1)" I found the problem and solved it (it's in the patch joined). In AJP the connections are persistent, so basically, the patch is initializing the Ajp13Generator to persistent and increasing the default timeout on the Ajp13SocketConnector. There was also some changes in the rest methods needed for making it work. With the patch have no exception on any side (mod_jk and jetty) and the sockets stay open.
        Hide
        Frederic Simon added a comment -

        The patch is from trunk/extras/ajp and contain the other patch inside.

        Show
        Frederic Simon added a comment - The patch is from trunk/extras/ajp and contain the other patch inside.
        Frederic Simon made changes -
        Attachment fred_ajp_patch_20070429.patch [ 27059 ]
        Hide
        Leopoldo Agdeppa III added a comment -

        this might be due to setting the state=end in sendCPong() method, the sendCPong method is just putting the CPONG data to header, its not yet sent to peer,
        im sending for a new fix for this one, sorry for the oooopppss

        Show
        Leopoldo Agdeppa III added a comment - this might be due to setting the state=end in sendCPong() method, the sendCPong method is just putting the CPONG data to header, its not yet sent to peer, im sending for a new fix for this one, sorry for the oooopppss
        Hide
        Frederic Simon added a comment -

        After your patch the sendCPong was working great. It was sending it back to mod_jk.
        The problem was that there was also an _endp.close() when state=end, and this is making mod_jk crazy.
        What you answer pong and close... So, it did not work...
        My changes are just a couples of lines in initialization and reset, it looks big because I removed logs on ping-pong (filling the log very fast), and a printstatcktrace when connection is closed or timeout (which is normal in AJP).
        By the way, the AJP connection and the socket need to be closed on exception, I suppose the main handler should do that no?

        Show
        Frederic Simon added a comment - After your patch the sendCPong was working great. It was sending it back to mod_jk. The problem was that there was also an _endp.close() when state=end, and this is making mod_jk crazy. What you answer pong and close... So, it did not work... My changes are just a couples of lines in initialization and reset, it looks big because I removed logs on ping-pong (filling the log very fast), and a printstatcktrace when connection is closed or timeout (which is normal in AJP). By the way, the AJP connection and the socket need to be closed on exception, I suppose the main handler should do that no?
        Hide
        Leopoldo Agdeppa III added a comment -

        some threads might have just closed the endp before even sending the data from the buffer

        Show
        Leopoldo Agdeppa III added a comment - some threads might have just closed the endp before even sending the data from the buffer
        Hide
        Leopoldo Agdeppa III added a comment -

        the changes i made are just on the sending cpong, instead of setting the state to END in the prepare buffers, I removed it, instead the state will be marked END, in the flush() method under the module "Keep flushing while there is something to flush (except break below)" in its CASE 0 where theres a proper place to mark the state=END and where the closing of _endp is done

        Show
        Leopoldo Agdeppa III added a comment - the changes i made are just on the sending cpong, instead of setting the state to END in the prepare buffers, I removed it, instead the state will be marked END, in the flush() method under the module "Keep flushing while there is something to flush (except break below)" in its CASE 0 where theres a proper place to mark the state=END and where the closing of _endp is done
        Hide
        Leopoldo Agdeppa III added a comment -

        fix for _endp closed and not sending any CPONG reply

        Show
        Leopoldo Agdeppa III added a comment - fix for _endp closed and not sending any CPONG reply
        Leopoldo Agdeppa III made changes -
        Attachment ajp_patch_20070430.patch [ 27065 ]
        Hide
        Frederic Simon added a comment -

        OK.
        But anyway AJP is really a persistent connections protocol so setting the genrator to persistent looks mandatory to me, no?

        Show
        Frederic Simon added a comment - OK. But anyway AJP is really a persistent connections protocol so setting the genrator to persistent looks mandatory to me, no?
        Greg Wilkins made changes -
        Status Resolved [ 5 ] Reopened [ 4 ]
        Resolution Fixed [ 1 ]
        Hide
        Greg Wilkins added a comment -

        I have applied the additional patches and done a few tidy ups.
        AJP is working for me for both apache 2.2 and apache 2.0, with mod_jk and mod_proxy_jk.
        However, I don't think I observed any CPINGs at all from them. Under what circumstances
        are CPINGs generated?

        Can this patch be tested as a matter of urgency as it is the blocker on a stable 6.1.2 release.

        cheers

        Show
        Greg Wilkins added a comment - I have applied the additional patches and done a few tidy ups. AJP is working for me for both apache 2.2 and apache 2.0, with mod_jk and mod_proxy_jk. However, I don't think I observed any CPINGs at all from them. Under what circumstances are CPINGs generated? Can this patch be tested as a matter of urgency as it is the blocker on a stable 6.1.2 release. cheers
        Hide
        Frederic Simon added a comment -

        Great.
        The CPING/CPONG appears when the following params are added to mod_jk 1.2.xx:
        worker.jetty.socket_keepalive=1
        worker.jetty.socket_timeout=60
        worker.jetty.recycle_timeout=60
        worker.jetty.connect_timeout=60000
        worker.jetty.prepost_timeout=60000

        Show
        Frederic Simon added a comment - Great. The CPING/CPONG appears when the following params are added to mod_jk 1.2.xx: worker.jetty.socket_keepalive=1 worker.jetty.socket_timeout=60 worker.jetty.recycle_timeout=60 worker.jetty.connect_timeout=60000 worker.jetty.prepost_timeout=60000
        Hide
        Leopoldo Agdeppa III added a comment -

        this time its really fixed

        Show
        Leopoldo Agdeppa III added a comment - this time its really fixed
        Leopoldo Agdeppa III made changes -
        Attachment ajp_patch_20070503.patch [ 27123 ]
        Hide
        Leopoldo Agdeppa III added a comment -

        fixed

        Show
        Leopoldo Agdeppa III added a comment - fixed
        Leopoldo Agdeppa III made changes -
        Status Reopened [ 4 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]

          People

          • Assignee:
            Leopoldo Agdeppa III
            Reporter:
            Leopoldo Agdeppa III
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: