Jetty

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. Text File
    ajp_patch_20070423.patch
    27/Apr/07 6:17 AM
    1 kB
    Leopoldo Agdeppa III
  2. Text File
    ajp_patch_20070430.patch
    30/Apr/07 4:02 AM
    2 kB
    Leopoldo Agdeppa III
  3. Text File
    ajp_patch_20070503.patch
    03/May/07 6:21 AM
    9 kB
    Leopoldo Agdeppa III
  4. Text File
    fred_ajp_patch_20070429.patch
    29/Apr/07 8:51 AM
    4 kB
    Frederic Simon

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
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
Permalink
Leopoldo Agdeppa III added a comment -

Fix Patch

Show
Leopoldo Agdeppa III added a comment - Fix Patch
Hide
Permalink
Greg Wilkins added a comment -

thanks bong

Show
Greg Wilkins added a comment - thanks bong
Hide
Permalink
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
Permalink
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.
Hide
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Permalink
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
Hide
Permalink
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?
Hide
Permalink
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
Permalink
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
Permalink
Leopoldo Agdeppa III added a comment -

this time its really fixed

Show
Leopoldo Agdeppa III added a comment - this time its really fixed
Hide
Permalink
Leopoldo Agdeppa III added a comment -

fixed

Show
Leopoldo Agdeppa III added a comment - fixed

People

  • Assignee:
    Leopoldo Agdeppa III
    Reporter:
    Leopoldo Agdeppa III
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: