Fixed in 8.0.x for 8.0.21 onwards and 7.0.x for 7.0.60 onwards. Neither trunk nor 6.0.x were affected.

I think there is something missing with this fix. I get no errors on the Tomcat side, now, but mod_jk certainly isn't happy:

[Mon Mar 09 11:38:55.820 2015] [7087:140653078521600] [error] ajp_connection_tcp_get_message::jk_ajp_common.c (1372): (worker21) wrong message format 0x6f6e from 127.0.0.1:8215
[Mon Mar 09 11:38:55.824 2015] [7087:140653078521600] [error] ajp_get_reply::jk_ajp_common.c (2289): (worker21) Tomcat is down or network problems. Part of the response has already been sent to the client
[Mon Mar 09 11:38:55.824 2015] [7087:140653078521600] [info] ajp_service::jk_ajp_common.c (2773): (worker21) sending request to tomcat failed (recoverable), because of protocol error (attempt=1)
[Mon Mar 09 11:38:56.287 2015] [7087:140653078521600] [error] ajp_connection_tcp_get_message::jk_ajp_common.c (1372): (worker21) wrong message format 0x6f6e from 127.0.0.1:8215
[Mon Mar 09 11:38:56.299 2015] [7087:140653078521600] [error] ajp_get_reply::jk_ajp_common.c (2289): (worker21) Tomcat is down or network problems. Part of the response has already been sent to the client
[Mon Mar 09 11:38:56.299 2015] [7087:140653078521600] [info] ajp_service::jk_ajp_common.c (2773): (worker21) sending request to tomcat failed (recoverable), because of protocol error (attempt=2)
[Mon Mar 09 11:38:56.299 2015] [7087:140653078521600] [error] ajp_service::jk_ajp_common.c (2794): (worker21) connecting to tomcat failed (rc=-11, errors=6, client_errors=0).
[Mon Mar 09 11:38:56.299 2015] [7087:140653078521600] [info] jk_handler::mod_jk.c (2991): Service error=-11 for worker=worker21


From my earlier instrumentation, I'm getting log messages telling me what is being send to the output() method. I'm including them in case they are helpful:

WARNING: Writing to output buffer of capacity=8192, position=0, limit=8192, remaining=8192 from source buffer of size=65536, starting at offset=0, len=8200
Mar 09, 2015 11:38:56 AM org.apache.coyote.ajp.AjpNioProcessor output
WARNING: Writing to output buffer of capacity=8192, position=0, limit=8192, remaining=8192 from source buffer of size=65536, starting at offset=0, len=8200
Mar 09, 2015 11:38:56 AM org.apache.coyote.ajp.AjpNioProcessor output
WARNING: Writing to output buffer of capacity=8192, position=0, limit=8192, remaining=8192 from source buffer of size=65536, starting at offset=0, len=8200
Mar 09, 2015 11:38:56 AM org.apache.coyote.ajp.AjpNioProcessor output
WARNING: Writing to output buffer of capacity=8192, position=0, limit=8192, remaining=8192 from source buffer of size=65536, starting at offset=0, len=7240
Mar 09, 2015 11:38:56 AM org.apache.coyote.ajp.AjpNioProcessor output
WARNING: Writing to output buffer of capacity=8192, position=0, limit=8192, remaining=8192 from source buffer of size=8, starting at offset=0, len=8
Mar 09, 2015 11:38:56 AM org.apache.coyote.ajp.AjpNioProcessor output
WARNING: Writing to output buffer of capacity=8192, position=0, limit=8192, remaining=8192 from source buffer of size=6, starting at offset=0, len=6

Thanks for the fixes, Mark.

I probably could have done these changes myself, but I wasn't sure of the implications of making changes in these areas.

This is looking much better.

I was fortunate that I could reproduce this very easily in my application and we are humming-along quite smoothly, now.

Something is still not quite right.

While no errors are being thrown, content is being garbled at regular intervals.

Using Tomcat 7.0.x at r1665573 with packetSize="65536" and no other buffer-related configuration.

I see stuff like this periodically in long responses:

onclick="window.locatioAB ^D^C ^@s://[host]:443

I'm working on getting those byte values in there (after the "window.locatio" and before the "s://") for you; they may tell us something.

Okay, here's what od has to say about those bytes:

0017740  22  20  6f  6e  63  6c  69  63  6b  3d  22  77  69  6e  64  6f
          "  sp   o   n   c   l   i   c   k   =   "   w   i   n   d   o
0017760  77  2e  6c  6f  63  61  74  69  6f  41  42  20  04  03  20  00
          w   .   l   o   c   a   t   i   o   A   B  sp eot etx  sp nul

                       Here's the weirdness ^^^^^^^^^^^^^^^^^^^^^^^^^^^

So, that's a literal "AB" followed by a space, EOT, ETX, space, and NUL bytes. Then, the text continues on where it left off. The number of unexpected bytes takes up the same number of bytes in the output, so it's a straight clobbering of bytes and not something being inserted, and changing the total content length.

0020000  73  3a  2f  2f   [etc]
          s   :   /   /   [etc]

With unprintable characters replaced with "x", the content is:

window.locatioAB xx xs://[host]:443

And it should be this:

window.location="https://[host]:443

So you can see that those bytes were replaced and not inserted (or deleted). So the byte count is correct, but something else is wrong.

There are many other instances in thie page I'm looking at right now. I'll check to see if they all have the same pattern.

Yes, all occurrences of the garbled bytes are the same set of replacement bytes:

  41  42   20  04  03  02  00
   A   B   sp eot etx  sp nul

This does it on a fresh Tomcat 7.0.x trunk:

1. Modify the AJP <Connector> thusly:

    <Connector port="8009"
               redirectPort="8443"
               protocol="org.apache.coyote.ajp.AjpNioProtocol"
               URIEncoding="UTF-8"
               packetSize="65536"
               />

  (redirectPort and URIEncoding probably have nothing to do with it)

2. Set up your mod_jk worker thusly:

  worker.template.type=ajp13
  worker.template.host=localhost
  worker.template.connection_pool_timeout=60
  worker.template.socket_timeout=300
  worker.template.max_packet_size=65536

  worker.list=test-worker
  worker.test-worker.reference=worker.template
  worker.test-worker.port=8009

  (the 'template' worker is probably not necessary)

3. Run this simple JSP:

<%@page buffer="20kb" contentType="text/plain" %><%
  int iterations = 12500;
  int bytes = 0;
  for(int i=0; i<iterations; ++i) {
    out.println(String.format("%1$06x", bytes));
    bytes += 8;
  }
%>

Note the large (ish) buffer size and the long (ish) content.

Search the output for the text "AB" which is never actually intended to be in the output; you'll see scarring of the response text at regular intervals.

(In reply to Christopher Schultz from comment #7)
> Yes, all occurrences of the garbled bytes are the same set of replacement
> bytes:
> 
>   41  42   20  04  03  02  00
>    A   B   sp eot etx  sp nul

AB is the start on a tomcat-to-web-server-packet. The 0x20 and 0x04 are the length of the packet, so here it is 8196 bytes. Next is packet type 0x03 which is a body chunk packet. Next is 0x02 0x00 but I think it actually is 0x20 0x00 (see your previous post) which is the chunk size, so here it is 8KB. The rest is the raw data.

So it looks like the TC AJP connector has somehow framed the response into to small packets not respecting the configured packet size. It would be interesting though to see the data before these bytes. Namely whether the previous AJP packet had the right size, so the "AB" starts right after the previous packet and the error is on the reassembling side (mod_jk), or whether th previous packet announced more data than it actually sended and then "suddenly" a new packet started.

Regards,

Rainer

When I run that script, the first hiccup comes at byte 0x00248a (decimal 9354):

002478
002480
00AB ^D^C ^@2490
  ^ byte 0x2480 + 8 + 2)

  (Note that each line is 8 bytes long: 6 bytes of address + \r\n,
   so the "AB" starts at 0x2480 + 8 + 2)
002498
0024a0

Then it happens again at byte 0x491a (decimal 18714):

004908
004910
0049AB ^D^C ^@20
004928
004930

The distance between the first and second scars is 0x2490 (9360) bytes.

Then again at 0x6dae (decimal 28078):

006d98
006da0
006da8AB ^D^C ^@
006db8
006dc0

That's an offset to the previous scar of 0x2494 (decimal 9364).

Then again at 0x9241 (decimal 37441):

009230
009238
0AB ^D^C ^@09248
009250
009258

That's an offset of 9363.

I've taken another look at AjpNioProcessor.output, and the loop looks very straightforward. As long as writeBuffer.put() and NioSelectorPool.write work as advertized, and no IOException occurs at line 316 (selector = pool.get()), it should work.

(In reply to Rainer Jung from comment #9)
> (In reply to Christopher Schultz from comment #7)
> > Yes, all occurrences of the garbled bytes are the same set of replacement
> > bytes:
> > 
> >   41  42   20  04  03  02  00
> >    A   B   sp eot etx  sp nul
> 
> AB is the start on a tomcat-to-web-server-packet.

This is starting to make a lot of sense, now.

> The 0x20 and 0x04 are the
> length of the packet, so here it is 8196 bytes. Next is packet type 0x03
> which is a body chunk packet. Next is 0x02 0x00 but I think it actually is
> 0x20 0x00 (see your previous post) which is the chunk size, so here it is
> 8KB. The rest is the raw data.

Yes, the "02" was a typo: it should of course be "20" for a space.

So it looks like maybe the underlying AJP protocol component has the problem: it appears to be clobbering response message bytes with its own packet-headers... packet headers that don't need to be added to the response bytes because there is still plenty of space left in the current AJP packet.

> So it looks like the TC AJP connector has somehow framed the response into
> to small packets not respecting the configured packet size.

That would be okay, as long as the AJP headers weren't clobbering content. :)

Introducing superfluous packets would be okay, even if it were a little inefficient.

> It would be
> interesting though to see the data before these bytes. Namely whether the
> previous AJP packet had the right size, so the "AB" starts right after the
> previous packet and the error is on the reassembling side (mod_jk), or
> whether th previous packet announced more data than it actually sended and
> then "suddenly" a new packet started.

I can enable trace logging at the web server level. Let me get this working on an isolated instance where nobody else will fill-up my logs with extraneous logging.

Running the example JSP I posted on my Mac gives me no output at all: the server returns "Content-Length: 0" (probably httpd adding that, since there is no Content-Length header sent by the JSP or Tomcat).

Requesting the JSP resource via the BIO HTTP connector yields the expected output.

Here's the [debug] output from mod_jk when I get zero bytes back:

[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1179): Attempting to map URI '/examples/test.jsp' from 2 maps
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] find_match::jk_uri_worker_map.c (978): Attempting to map context URI '/examples/*=broken' source 'JkMount'
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] find_match::jk_uri_worker_map.c (991): Found a wildchar match '/examples/*=broken'
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] jk_handler::mod_jk.c (2823): Into handler jakarta-servlet worker=broken r->proxyreq=0
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] wc_get_worker_for_name::jk_worker.c (119): found a worker broken
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] wc_maintain::jk_worker.c (348): Maintaining worker myworker
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] wc_maintain::jk_worker.c (348): Maintaining worker lb
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] maintain_workers::jk_lb_worker.c (760): decay with 2^2
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] wc_maintain::jk_worker.c (348): Maintaining worker test-worker
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] wc_maintain::jk_worker.c (348): Maintaining worker broken
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] wc_get_name_for_type::jk_worker.c (303): Found worker type 'ajp13'
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] init_ws_service::mod_jk.c (1196): Service protocol=HTTP/1.1 method=GET ssl=false host=(null) addr=::1 name=localhost port=80 auth=(null) user=(null) laddr=::1 raddr=::1 uaddr=::1 uri=/examples/test.jsp
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] ajp_get_endpoint::jk_ajp_common.c (3351): (broken) acquired connection pool slot=0 after 0 retries
[Tue Mar 10 12:46:06.517 2015] [1213:140735223407360] [debug] ajp_marshal_into_msgb::jk_ajp_common.c (684): (broken) ajp marshaling done
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_service::jk_ajp_common.c (2586): processing broken with 2 retries
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_send_request::jk_ajp_common.c (1722): (broken) no usable connection found, will create a new one.
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] jk_open_socket::jk_connect.c (675): socket TCP_NODELAY set to On
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] jk_open_socket::jk_connect.c (799): trying to connect socket 23 to ::1:8009
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] jk_open_socket::jk_connect.c (825): socket 23 [::1c1e:1f49:0:0:53443 -> ::e6f0:1e50:40d2:f2:8009] connected
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): sending to ajp13 pos=4 len=185 max=8192
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0000    12 34 00 B5 02 02 00 08 48 54 54 50 2F 31 2E 31  - .4......HTTP/1.1
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0010    00 00 12 2F 65 78 61 6D 70 6C 65 73 2F 74 65 73  - .../examples/tes
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0020    74 2E 6A 73 70 00 00 03 3A 3A 31 00 FF FF 00 09  - t.jsp...::1.....
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0030    6C 6F 63 61 6C 68 6F 73 74 00 00 50 00 00 04 A0  - localhost..P....
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0040    0E 00 0B 63 75 72 6C 2F 37 2E 33 37 2E 31 00 A0  - ...curl/7.37.1..
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0050    0B 00 09 6C 6F 63 61 6C 68 6F 73 74 00 A0 01 00  - ...localhost....
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0060    03 2A 2F 2A 00 A0 08 00 01 30 00 0A 00 0F 41 4A  - .*/*.....0....AJ
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0070    50 5F 52 45 4D 4F 54 45 5F 50 4F 52 54 00 00 05  - P_REMOTE_PORT...
[Tue Mar 10 12:46:06.518 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0080    35 33 34 34 32 00 0A 00 0E 41 4A 50 5F 4C 4F 43  - 53442....AJP_LOC
[Tue Mar 10 12:46:06.519 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 0090    41 4C 5F 41 44 44 52 00 00 03 3A 3A 31 00 0A 00  - AL_ADDR...::1...
[Tue Mar 10 12:46:06.519 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 00a0    10 4A 4B 5F 4C 42 5F 41 43 54 49 56 41 54 49 4F  - .JK_LB_ACTIVATIO
[Tue Mar 10 12:46:06.519 2015] [1213:140735223407360] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c (1267): 00b0    4E 00 00 03 41 43 54 00 FF 00 00 00 00 00 00 00  - N...ACT.........
[Tue Mar 10 12:46:06.519 2015] [1213:140735223407360] [debug] ajp_send_request::jk_ajp_common.c (1782): (broken) request body to send 0 - request body to resend 0
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): received from ajp13 pos=0 len=61 max=8192
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0000    04 00 C8 00 02 4F 4B 00 00 02 00 07 52 75 6E 6E  - .....OK.....Runn
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0010    69 6E 67 00 00 04 74 72 75 65 00 A0 01 00 1D 74  - ing...true.....t
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0020    65 78 74 2F 70 6C 61 69 6E 3B 63 68 61 72 73 65  - ext/plain;charse
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0030    74 3D 49 53 4F 2D 38 38 35 39 2D 31 00 00 00 00  - t=ISO-8859-1....
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_unmarshal_response::jk_ajp_common.c (739): (broken) status = 200
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_unmarshal_response::jk_ajp_common.c (746): Number of headers is = 2
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_unmarshal_response::jk_ajp_common.c (802): (broken) Header[0] [Running] = [true]
[Tue Mar 10 12:46:06.529 2015] [1213:140735223407360] [debug] ajp_unmarshal_response::jk_ajp_common.c (802): (broken) Header[1] [Content-Type] = [text/plain;charset=ISO-8859-1]
[Tue Mar 10 12:46:06.530 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): received from ajp13 pos=0 len=2 max=8192
[Tue Mar 10 12:46:06.530 2015] [1213:140735223407360] [debug] ajp_connection_tcp_get_message::jk_ajp_common.c (1462): 0000    05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  - ................
[Tue Mar 10 12:46:06.530 2015] [1213:140735223407360] [warn] ajp_process_callback::jk_ajp_common.c (2121): (broken) AJP13 protocol: Reuse is set to false
[Tue Mar 10 12:46:06.530 2015] [1213:140735223407360] [debug] ajp_reset_endpoint::jk_ajp_common.c (851): (broken) resetting endpoint with socket 23 (socket shutdown)
[Tue Mar 10 12:46:06.530 2015] [1213:140735223407360] [debug] ajp_abort_endpoint::jk_ajp_common.c (821): (broken) aborting endpoint with socket 23
[Tue Mar 10 12:46:06.531 2015] [1213:140735223407360] [debug] jk_shutdown_socket::jk_connect.c (932): About to shutdown socket 23 [::1c1e:1f49:0:0:53443 -> ::e6f0:1e50:40d2:f2:8009]
[Tue Mar 10 12:46:06.534 2015] [1213:140735223407360] [debug] jk_is_input_event::jk_connect.c (1406): error event during poll on socket 23 [errno=22] (event=16)
[Tue Mar 10 12:46:06.534 2015] [1213:140735223407360] [debug] jk_shutdown_socket::jk_connect.c (1016): Shutdown socket 23 [::1c1e:1f49:0:0:53443 -> ::e6f0:1e50:40d2:f2:8009] and read 0 lingering bytes in 0 sec.
[Tue Mar 10 12:46:06.534 2015] [1213:140735223407360] [debug] ajp_done::jk_ajp_common.c (3282): recycling connection pool for worker broken and socket -1
[Tue Mar 10 12:46:06.534 2015] [1213:140735223407360] [debug] jk_handler::mod_jk.c (2975): Service finished with status=200 for worker=broken

Using the repro case I can see:

Tomcat doesn't send 64KB packets (or close to it) but instead it sends AJP packets announcing themselves via the packet header as having 8200 bytes including the header "AB" and packet size as integer (41 42 20 04), so 
8196 bytes excluding the header.

But then after 8188 bytes of content instead of 8196 bytes it stopps with the real package contents and the last 8 bytes of the packet are the same bytes as the first 8 bytes of that AJP message. So here's some kind of cyclic buffer overflow.

Then the next AJP package starts having the same defect etc.

Sounds like I need to look at this some more. I'll take a look later.

(In reply to Mark Thomas from comment #14)
> Sounds like I need to look at this some more. I'll take a look later.

Try now.

Now it does fill the 8196 bytes completely and the packets fit neatly one after the other. So the result unmarshalled by mod_jk is fine.

Let's see what Chris gets, but looks good to me. Thanks.

Rainer

Looks good in my test case. I'm re-enabling the configuration (by removing the socket.appWriteBufSize setting) in my development environment to see it under real use.

I assuming that this is fixed now.

I haven't gotten any complaints, and haven't noticed anything since I applied this most recent patch.