<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:12.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal"><span style="font-size:11.0pt">Hello all,<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">During testing I have found behavior that I cannot explain based on our current understanding of the operation of the async and rest_client functionality. I have reproduced this behavior with a fairly simple
script configuration, the relevant piece of which is below:<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">children=8<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">loadmodule "rest_client.so"<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">modparam("rest_client", "connection_timeout", 5)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">modparam("rest_client", "connect_poll_interval", 1)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">modparam("rest_client", "curl_timeout", 5)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">route {<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> xlog("L_ALERT", "before t_newtran()\r\n");<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> t_newtran();<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> xlog("L_ALERT", "after t_newtran()\r\n");<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> async(rest_post("http://0.0.0.0", "{}", "application/json", "$var(body)", "$var(ctype)", "$var(rcode)"), test_resume);<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> xlog("L_ALERT", "after async\r\n");<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">}<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""><o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">route[test_resume] {<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> xlog("L_ALERT", "test_resume: $retcode\r\n");<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New""> t_reply("503", "Service Unavailable");<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">}<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">The expected operation is to immediately trigger t_newtran() which sends a 100 response, then timeout on the rest_post call in 5 seconds and respond with a 503. For individual calls this does occur, although
the timeout consistently takes several seconds too long, usually ~8s, as can be seen in the logs from the above code:<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 19:10:56 [337] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 19:10:56 [337] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 19:11:04 [337] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 19:11:04 [337] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">The extra time is troubling, but the bigger concern is that when I run multiple concurrent calls, I find that the 8 UDP children are still all blocking against the rest_post call. Here are the logs for that
test:<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [337] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [337] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [338] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [338] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [335] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [335] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [333] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:51 [333] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [331] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [331] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [336] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [336] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [332] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [332] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [334] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:52 [334] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [337] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [337] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [337] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [337] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [338] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [338] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [338] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [338] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [335] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [335] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [335] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [335] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [333] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [333] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [333] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [333] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [331] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [331] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [331] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [331] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [336] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [336] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [336] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [336] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [332] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [332] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [332] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:19:59 [332] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:00 [334] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:00 [334] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:00 [334] before t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:00 [334] after t_newtran()<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [337] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [337] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [338] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [338] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [335] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [335] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [333] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [333] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [331] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [331] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [336] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [336] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [332] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [332] test_resume: -2<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [334] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0 (5s)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:10.0pt;font-family:"Courier New"">Jun 24 21:20:07 [334] test_resume: -2</span><span style="font-size:11.0pt"><o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">You can clearly see that the first 8 Invites are processed immediately, but then no new messages are processed until the rest queries begin to timeout. As each query times out, freeing a child process, a new
inbound request is processed. Clearly the message processing is being blocked on the rest queries, which is not supposed to happen when using async. Am I missing something in my configuration or am I not understanding how async is supposed to work somehow?<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt;color:black">Ben Newlin </span>
<o:p></o:p></p>
</div>
</body>
</html>