Dear List,
I am facing a strange httpclient 3.1 behaviour under stressing conditions while
encoding a post: the set of parameters is "nullified", whereas the number of
parameters is correct.
I have turned on the httpclient wire traces to get more clues, and added in my
own code a dump of the PostMethod object before and after the
httpclient.execute call: I see the actual parameters correctly set in the
PostMethod object, but actually the httpclient encoding "nullified" parameters.
Here is the code excerpt:
synchronized(this) {
// Check parameters before call
log.debug("About to call httpclient.executeMethod on object: " +
postMethodM + " containing parameters: " );
for(int i=0; i < postMethodM.getParameters().length; i++)
log.debug("\t" + i + "/ " + postMethodM.getParameters()[i].getName() +
"=" + postMethodM.getParameters()[i].getValue() );
// actually call
statusCodeM = httpclient.executeMethod(postMethodM);
// check parameters after call
log.debug("Called httpclient.executeMethod on object: " + postMethodM + "
with status: " + statusCodeM + " containing parameters: " );
for(int i=0; i < postMethodM.getParameters().length; i++)
log.debug("\t" + i + "/ " + postMethodM.getParameters()[i].getName() +
"=" + postMethodM.getParameters()[i].getValue() );
}
And here are the related traces:
Dec 10 JST 2008 09:05:48 AM.647063| 16301 | EventSender | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 About to
call httpclient.executeMethod on object: [EMAIL PROTECTED] containing
parameters:
Dec 10 JST 2008 09:05:48 AM.647205| 16301 | EventSender | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 0/
eventname=undefined
Dec 10 JST 2008 09:05:48 AM.647340| 16301 | EventSender | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 1/
session.id=http://130.211.1.96/ccxmlsession_96_830_110700
Dec 10 JST 2008 09:05:48 AM.647757| 16301 | iThreadedHttpConnectionManager| 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797
HttpConnectionManager.getConnection: config =
HostConfiguration[host=http://localhost, proxyHost=http://127.0.0.1:3128],
timeout = 10000
Dec 10 JST 2008 09:05:48 AM.647946| 16301 | nnectionManager$ConnectionPool| 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Getting
free connection, hostConfig=HostConfiguration[host=http://localhost,
proxyHost=http://127.0.0.1:3128]
Dec 10 JST 2008 09:05:48 AM.648178| 16301 | HttpConnection | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Connection
is stale, closing...
Dec 10 JST 2008 09:05:48 AM.648484| 16301 | HttpConnection | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Open
connection to 127.0.0.1:3128
Dec 10 JST 2008 09:05:48 AM.649115| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >> "POST
http://localhost/PreFetchServlet?src=/rVoiceMail_041/vxmlFiles/VoiceMail_0000.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0001.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0002.vxml.jsp&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0003.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0004.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0005.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0006.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0007.vxml.jsp&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0008.vxml.jsp&src=/rVoiceMail_041/vxmlFiles/VoiceMail_C005.jsf&src=/rVoiceMail_041/vxmlFiles/VoiceMail_C008.jsp&src=/rVoiceMail_041/grammarFiles/VoiceMail_C000.grxml&src=/rVoiceMail_041/grammarFiles/VoiceMail_C002.grxml&src=/rVoiceMail_041/ECMAScripts/VoiceMail_0000.es&src=/rVoiceMail_041/ECMAScripts/VoiceMail_C000.es&src=/rVoiceMail_041/promptFiles/VoiceMail_C000.jsf&src=/rVoiceMail_041/promptFiles/VoiceMail_C001.jsf&src=/rVoiceMail_041/promptFiles/VoiceMail_C002.jsf&src=/rVoiceMail_041/promptFiles/VoiceMail_0000.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_0001.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C009.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C010.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C011.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C012.ulaw.jsp&src=/rVoiceMail_041/promptFiles/00430058.ulaw&src=/rVoiceMail_041/promptFiles/00420001.ulaw&src=/rVoiceMail_041/promptFiles/00440000.ulaw&src=/rVoiceMail_041/promptFiles/10430058.ulaw&src=/rVoiceMail_041/promptFiles/10420005.ulaw&chk
HTTP/1.1[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.649328| 16301 | HttpMethodBase | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Adding Host
request header
Dec 10 JST 2008 09:05:48 AM.649588| 16301 | HttpMethodBase | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Default
charset used: ISO-8859-1
Dec 10 JST 2008 09:05:48 AM.649825| 16301 | HttpMethodBase | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Default
charset used: ISO-8859-1
Dec 10 JST 2008 09:05:48 AM.650013| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >>
"User-Agent: OCMP-BRE-CCXML[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.650194| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >> "Host:
localhost[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.650373| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >>
"Proxy-Connection: Keep-Alive[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.650555| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >>
"Content-Length: 19[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.650738| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >>
"Content-Type: application/x-www-form-urlencoded[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.650925| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >>
"[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.651111| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 >>
"null=null&null=null"
Dec 10 JST 2008 09:05:48 AM.651701| 16301 | EntityEnclosingMethod | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Request
body sent
Dec 10 JST 2008 09:05:48 AM.679966| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"HTTP/1.0 200 OK[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.680165| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"HTTP/1.0 200 OK[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.680370| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 << "Server:
Apache-Coyote/1.1[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.680559| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"Content-Type: application/x-www-form-urlencoded[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.680747| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"Content-Length: 0[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.680947| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 << "Date:
Wed, 10 Dec 2008 00:05:48 GMT[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.681143| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"X-Cache: MISS from ocmpsquid[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.681331| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"X-Cache-Lookup: MISS from ocmpsquid:3128[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.681518| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 << "Via:
1.0 ocmpsquid:3128 (squid/2.6.STABLE17)[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.681704| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"Proxy-Connection: keep-alive[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.682050| 16301 | Wire | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 <<
"[\r][\n]"
Dec 10 JST 2008 09:05:48 AM.682229| 16301 | EventSender | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 Called
httpclient.executeMethod on object: [EMAIL PROTECTED] with status: 200
containing parameters:
Dec 10 JST 2008 09:05:48 AM.682373| 16301 | EventSender | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 0/
eventname=undefined
Dec 10 JST 2008 09:05:48 AM.682517| 16301 | EventSender | 0|
DEBUG | http://130.211.1.96/ccxmlsession_96_830_110700/event_288797 1/
session.id=http://130.211.1.96/ccxmlsession_96_830_110700
The wireshark capture is consistent as well:
POST
http://localhost/PreFetchServlet?src=/rVoiceMail_041/vxmlFiles/VoiceMail_0000.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0001.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0002.vxml.jsp&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0003.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0004.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0005.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0006.vxml&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0007.vxml.jsp&src=/rVoiceMail_041/vxmlFiles/VoiceMail_0008.vxml.jsp&src=/rVoiceMail_041/vxmlFiles/VoiceMail_C005.jsf&src=/rVoiceMail_041/vxmlFiles/VoiceMail_C008.jsp&src=/rVoiceMail_041/grammarFiles/VoiceMail_C000.grxml&src=/rVoiceMail_041/grammarFiles/VoiceMail_C002.grxml&src=/rVoiceMail_041/ECMAScripts/VoiceMail_0000.es&src=/rVoiceMail_041/ECMAScripts/VoiceMail_C000.es&src=/rVoiceMail_041/promptFiles/VoiceMail_C000.jsf&src=/rVoiceMail_041/promptFiles/VoiceMail_C001.jsf&src=/rVoiceMail_041/promptFiles/VoiceMail_C002.jsf&src=/rVoiceMail_041/promptFiles/VoiceMail_0000.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_0001.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C009.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C010.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C011.ulaw.jsp&src=/rVoiceMail_041/promptFiles/VoiceMail_C012.ulaw.jsp&src=/rVoiceMail_041/promptFiles/00430058.ulaw&src=/rVoiceMail_041/promptFiles/00420001.ulaw&src=/rVoiceMail_041/promptFiles/00440000.ulaw&src=/rVoiceMail_041/promptFiles/10430058.ulaw&src=/rVoiceMail_041/promptFiles/10420005.ulaw&chk
HTTP/1.1
User-Agent: OCMP-BRE-CCXML
Host: localhost
Proxy-Connection: Keep-Alive
Content-Length: 19
Content-Type: application/x-www-form-urlencoded
null=null&null=null
One more strange point: the problem requires intensive traffic to happen, but
once the it has happened, all http post suffer the same problem, encoding null
parameters ...
Would this problem ring any bell? Should I turn other traces on to get more
clues?
Any feedback would be greatly appreciated.
Thanks a lot for your help.
Dominique Domet de Mont
