[asterisk-dev] Dialplan AGI with SIP channels blocking if AGI already running - parallellism not possible?
Johan Sandgren
jsa at svep.se
Wed Apr 3 07:01:01 CDT 2013
Hi everyone,
I'm using Asterisk V10.0.0 and encountered a problem related to SIP MESSAGE that I need to solve some way.
Short:
- Asterisk is receiving SIP MESSAGE from outside and I've designed a dialplan script that starts a java program using AGI. The Java program usually runs for 10 minutes before it is done.
- While this AGI-java is running, all other SIP MESSAGEs received will NOT trigger the dialplan to execute at the same context. I see the SIP MESSAGE is received by Asterisk in the console with full debugging and SIP debugging on. But nothing more happens.
Is this a bug? Or if by design limited somehow? Am I doing something wrong? Any advice where I should modify to enable incoming SIP MESSAGEs not to be blocking eachother if the previous dialplan script still is executing?
I'm supplying some logs for info.
/Johan
==============================================================================================================================
Asterisk log 1 - incoming SIP MESSAGE is starting the AGI-java program normally
==============================================================================================================================
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 0 [ 37]: MESSAGE sip:1000 at a.b.c.d SIP/2.0
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP a.b.c.d:5060;rport;branch=z9hG4bKPj1842455ed6c746bfa3aae03421f81f76
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 3 [ 65]: From: <sip:ip1 at a.b.c.d>;tag=90062e149611472d942ef62b603f6f42
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 4 [ 27]: To: <sip:1000 at a.b.c.d>
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 5 [ 41]: Call-ID: 52b5c40df0f0472e81d0a506ce526847
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 6 [ 18]: CSeq: 5504 MESSAGE
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 7 [ 29]: Accept: text/plain
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 8 [ 39]: Contact: <sip:ip1 at a.b.c.d:5060;ob>
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 9 [ 49]: User-Agent: PJSUA v2.0.1 win32-6.1/i386/msvc-15.0
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 10 [156]: Authorization: Digest username="ip1", realm="stt", nonce="25e37bcb", uri="sip:1000 at a.b.c.d", response="48e17fd572f122c732b968067ecd171d", algorithm=MD5
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 11 [ 35]: Content-Type: text/plain
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 12 [ 18]: Content-Length: 82
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 13 [ 0]:
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8622 parse_request: Body 0 [ 82]: First message, it will get delivered to the dialplan and start the AGI:java-prog!!
--- (13 headers 1 lines) ---
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:8147 find_call: = Looking for Call ID: 52b5c40df0f0472e81d0a506ce526847 (Checking From) --From tag 90062e149611472d942ef62b603f6f42 --To-tag
[Apr 3 12:14:55] DEBUG[18406]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'a.b.c.d' into...
[Apr 3 12:14:55] DEBUG[18406]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'a.b.c.d' and port ''.
[Apr 3 12:14:55] DEBUG[18406]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'a.b.c.d' into...
[Apr 3 12:14:55] DEBUG[18406]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'a.b.c.d' and port ''.
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:25408 handle_incoming: **** Received MESSAGE (11) - Command in SIP MESSAGE Receiving message!
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:16306 receive_message: SIP Text message content-type received: 'text/plain'
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:16316 receive_message: SIP Text message accepted by content-type. [Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:16348 receive_message: SIP MESSAGE debug 2
Found peer 'ip1' for 'ip1' from a.b.c.d:5060
Looking for 1000 in sipmessage (domain a.b.c.d)
[Apr 3 12:14:55] DEBUG[18406]: chan_sip.c:3363 __sip_xmit: Trying to put 'SIP/2.0 202' onto UDP socket destined for a.b.c.d:5060
Scheduling destruction of SIP dialog '52b5c40df0f0472e81d0a506ce526847' in 6400 ms (Method: MESSAGE)
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'Answer'
-- Executing [1000 at sipmessage:1] Answer("Message/ast_msg_queue", "") in new stack
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'NoOp'
-- Executing [1000 at sipmessage:2] NoOp("Message/ast_msg_queue", ""SIP-receiving"") in new stack
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'sip:1000 at a.b.c.d'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'NoOp'
-- Executing [1000 at sipmessage:3] NoOp("Message/ast_msg_queue", "To sip:1000 at a.b.c.d") in new stack
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'sip:ip1 at a.b.c.d'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'NoOp'
-- Executing [1000 at sipmessage:4] NoOp("Message/ast_msg_queue", "From sip:ip1 at a.b.c.d") in new stack
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'First message, it will get delivered to the dialplan and start the AGI:java-prog!!'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'NoOp'
-- Executing [1000 at sipmessage:5] NoOp("Message/ast_msg_queue", "Body First message, it will get delivered to the dialplan and start the AGI:java-prog!!") in new stack
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:3253 ast_str_retrieve_variable: Result of 'CHANNEL' is 'Message/ast_msg_queue'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'NoOp'
-- Executing [1000 at sipmessage:6] NoOp("Message/ast_msg_queue", ""Kanalnamn = " Message/ast_msg_queue") in new stack
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'sip:1000 at a.b.c.d'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'sip:ip1 at a.b.c.d'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'First message, it will get delivered to the dialplan and start the AGI:java-prog!!'
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4072 pbx_substitute_variables_helper_full: Function result is 'PG1ycT48cmVmPjEyMzQ1PC9yZWY+PHZlcj4wMS4wMDwvdmVyPjxtdHk+TUU8L210eT48Y2lkPjIwNzwvY2lkPjxkdHk+MjwvZHR5PjwvbXJxPgo='
[Apr 3 12:14:55] DEBUG[18395]: pbx.c:4244 pbx_extension_helper: Launching 'AGI'
-- Executing [1000 at sipmessage:7] AGI("Message/ast_msg_queue", "agi://localhost/sipmessagechecker.agi?to=sip:1000@a.b.c.d&from=sip:ip1@a.b.c.d&body=PG1ycT48cmVmPjEyMzQ1PC9yZWY+PHZlcj4wMS4wMDwvdmVyPjxtdHk+TUU8L210eT48Y2lkPjIwNzwvY2lkPjxkdHk+MjwvZHR5PjwvbXJxPgo=") in new stack
AGI Tx >> agi_network: yes
AGI Tx >> agi_network_script: sipmessagechecker.agi?to=sip:1000 at a.b.c.d&from=sip:ip1 at a.b.c.d&body=PG1ycT48cmVmPjEyMzQ1PC9yZWY+PHZlcj4wMS4wMDwvdmVyPjxtdHk+TUU8L210eT48Y2lkPjIwNzwvY2lkPjxkdHk+MjwvZHR5PjwvbXJxPgo=
[Apr 3 12:14:55] DEBUG[18395]: res_agi.c:1520 launch_netscript: Wow, connected!
==============================================================================================================================
Asterisk log 2 - incoming SIP MESSAGE is not starting dialplan
==============================================================================================================================
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 0 [ 32]: MESSAGE sip:a.b.c.d SIP/2.0
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP a.b.c.d:5060;rport;branch=z9hG4bKPj2eb132059304469b8f23a1dd0ab2083a
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 2 [ 16]: Max-Forwards: 70
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 3 [ 65]: From: <sip:ip1 at a.b.c.d>;tag=351ed60a73a049f6858f3d1795cc2ca0
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 4 [ 22]: To: <sip:a.b.c.d>
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 5 [ 41]: Call-ID: 657cba31858e4616af28255da5f1f8b1
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 6 [ 19]: CSeq: 12380 MESSAGE
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 7 [ 29]: Accept: text/plain
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 8 [ 39]: Contact: <sip:ip1 at a.b.c.d:5060;ob>
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 9 [ 49]: User-Agent: PJSUA v2.0.1 win32-6.1/i386/msvc-15.0
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 10 [151]: Authorization: Digest username="ip1", realm="stt", nonce="2ef9e3c9", uri="sip:a.b.c.d", response="37481b6d5ea8dfd9cd0d27eaddaf0351", algorithm=MD5
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 11 [ 35]: Content-Type: text/plain
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 12 [ 18]: Content-Length: 82
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8585 parse_request: Header 13 [ 0]:
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8622 parse_request: Body 0 [ 82]: First message, it will get delivered to the dialplan and start the AGI:java-prog!!
--- (13 headers 1 lines) ---
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:8147 find_call: = Looking for Call ID: 657cba31858e4616af28255da5f1f8b1 (Checking From) --From tag 351ed60a73a049f6858f3d1795cc2ca0 --To-tag
[Apr 3 12:15:34] DEBUG[18406]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'a.b.c.d' into...
[Apr 3 12:15:34] DEBUG[18406]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'a.b.c.d' and port ''.
[Apr 3 12:15:34] DEBUG[18406]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'a.b.c.d' into...
[Apr 3 12:15:34] DEBUG[18406]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'a.b.c.d' and port ''.
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:25408 handle_incoming: **** Received MESSAGE (11) - Command in SIP MESSAGE
Receiving message!
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:16306 receive_message: SIP Text message content-type received: 'text/plain'
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:16316 receive_message: SIP Text message accepted by content-type.
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:16348 receive_message: SIP MESSAGE debug 2
Found peer 'ip1' for 'ip1' from a.b.c.d:5060
Looking for s in sipmessage (domain a.b.c.d)
[Apr 3 12:15:34] DEBUG[18406]: chan_sip.c:3363 __sip_xmit: Trying to put 'SIP/2.0 202' onto UDP socket destined for a.b.c.d:5060
Scheduling destruction of SIP dialog '657cba31858e4616af28255da5f1f8b1' in 6400 ms (Method: MESSAGE)
[Apr 3 12:15:40] DEBUG[18406]: chan_sip.c:3903 __sip_autodestruct: Auto destroying SIP dialog '657cba31858e4616af28255da5f1f8b1'
[Apr 3 12:15:40] DEBUG[18406]: chan_sip.c:6058 sip_destroy: Destroying SIP dialog 657cba31858e4616af28255da5f1f8b1
Really destroying SIP dialog '657cba31858e4616af28255da5f1f8b1' Method: MESSAGE
===================================================
Johan Sandgren
Software Engineer
Svep Design Center AB
S:t Lars väg 42A
222 70 Lund, Sweden
Phone +46 46 192 722
E-mail jsa at svep.se
Website www.svep.se
More information about the asterisk-dev
mailing list