On 13.11.2009 15:06, ndunn1979 wrote: > > > Rainer Jung-3 wrote: >> >> >> As said: "JkLogLevel trace" will log the full packets. >> >> > > I reran it with trace log level and I can see the break now between the > packets.
Good. > One example that works (notice "inde" at the end of the first packet and "x" > at the beginning of the next one: Hmmm, that one I'm not sure, because after the "inde" there are only null bytes. Since the beginning of the packet is not shown, I'm not sure, but likely the "inde" was just the end of the body data of the AJP packet. > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 1fe0 69 6E 26 70 72 6F 70 65 72 74 79 3D 63 61 74 65 - in&property=cate > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 1ff0 67 6F 72 69 65 73 26 69 6E 64 65 00 00 00 00 00 - gories&inde..... The bytes after "inde" are all "00", could simply be the end of gthe packet body. > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_ajp_common.c (1263): > exit > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_ajp_common.c (1702): > enter > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [debug] mod_jk.c (506): written > 8184 out of 8184 > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_ajp_common.c (1871): > exit > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_ajp_common.c (1131): > enter > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_connect.c (807): enter > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_connect.c (836): exit > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_connect.c (807): enter > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [trace] jk_connect.c (836): exit > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > received from ajp13 pos=0 len=8188 max=65536 > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 0000 03 1F F8 78 3D 27 20 2B 20 74 68 69 73 2E 6E 61 - ...x='.+.this.na 03 is the packet type (response body), 1FF8 is the size of the following body part (bytes count in hex). > [Fri Nov 13 08:32:07.937 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 0010 6D 65 20 2B 20 27 26 76 61 6C 75 65 3D 27 20 2B - me.+.'&value='.+ > > This one did not work (notice the end of the packet contains "pr" -- meaning > property and refers to "club" while the next packet starts with "action" and > refers to "wagon"): > > [Fri Nov 13 08:32:07.953 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 1fe0 6D 2E 6A 73 70 3F 61 63 74 69 6F 6E 3D 32 26 6E - m.jsp?action=2&n > [Fri Nov 13 08:32:07.953 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 1ff0 61 6D 65 3D 63 6C 75 62 26 70 72 00 00 00 00 00 - ame=club&pr..... Again I guess it's the end of the packet. Size will have likely been 8184, which in hex is 1FF8. Adding 3 Bytes AJP header (03 1F F8), total size is 1FFB. First Byte in the line above is at position 1FF1, so 1FFB is exactly the "72". > [Fri Nov 13 08:32:07.953 2009] [1916:2244] [trace] jk_ajp_common.c (1263): > exit > [Fri Nov 13 08:32:07.953 2009] [1916:2244] [trace] jk_ajp_common.c (1702): > enter > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [debug] mod_jk.c (506): written > 8184 out of 8184 > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [trace] jk_ajp_common.c (1871): > exit > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [trace] jk_ajp_common.c (1131): > enter > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [trace] jk_connect.c (807): enter > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [trace] jk_connect.c (836): exit > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [trace] jk_connect.c (807): enter > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [trace] jk_connect.c (836): exit > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > received from ajp13 pos=0 len=8188 max=65536 > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 0000 03 1F F8 61 63 74 69 6F 6E 3D 31 26 6E 61 6D 65 - ...action=1&name > [Fri Nov 13 08:32:08.218 2009] [1916:2244] [debug] jk_ajp_common.c (1259): > 0010 3D 77 61 67 6F 6E 26 70 72 6F 70 65 72 74 79 3D - =wagon&property= Right, that looks wierd. I assume you didn't leave any line in theis block out from the mail. > The REALLY odd thing is that this line in the log (the beginning of the > redundant packet appears exactly the same way twice in the mod_jk log: > > jk_ajp_common.c (1259): 0000 03 1F F8 61 63 74 69 6F 6E 3D 31 26 6E 61 6D > 65 - ...action=1&name > > So a perfectly identical packet is being sent more than once. Unfortunately you did not show the full line, so we have no timestamp and no thread and pid info :( > I don't know the absolute byte offset in the binary data. I use firebug, but > I don't know which feature will give you the byte offset (not sure if it's > necessary in light of this new information). > > Is there a specific logger property I can use to look into the Tomcat side > to see what's going on? I'm not getting any errors but it seems like it's > more likely Tomcat that's resending the redundant packets (based on what > little I understand about the interface between the two programs). The best way here would be a packet sniffer. mod_jk shows you already, which data you are looking for in the packets, and they go over the wire excatly in the same format, that is being dumped in the jk log. No binary encoding or similar involved. So reading the data in the packet sniffer is not more difficult than in the jk log. Regards, Rainer --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
