[asterisk-users] Asterisk / SIP-Call / AGI-Script / SIGHUP after Answer

Thu Sep 26 09:03:46 CDT 2013

Hi,

I am facing a (for me) strange problem. When placing a SIP-Call I 
normally get connected and the dialplan is executed. The Call-Flow is 
controlled by a PHP-Agi-Script. The script answers the call (via 
AGI-Command) and a simple voicefile is played. SOMETIMES(!) I get 
disconnected immediately after the Answer - without any reason. This 
happens about all fifth call.

Later on you will find my SIP-Debug-Output. I can see a "BYE"-Message. 
But why?

AGI-Debug-Messages:
(yes - I can the result is -1 > but why? Normally it is 0)

<-- snip -->
<SIP/thorsten-000001f8>AGI Rx << Answer
<SIP/thorsten-000001f8>AGI Tx >> 200 result=-1
<-- snip -->

SIP-Debug-Messages:

<-- snip -->
<--- SIP read from UDP:217.92.105.86:51861 --->
INVITE sip:3 at myhost.org SIP/2.0
Via: SIP/2.0/UDP 
192.168.1.2:51861;rport;branch=z9hG4bKPj47b1a62ac3744acd996426618d90388f
Max-Forwards: 70
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>
Contact: <sip:03794281 at 192.168.1.2:51861>
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28484 INVITE
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, 
MESSAGE, REFER
Supported: 100rel, replaces, norefersub, gruu
User-Agent: Blink 0.5.0 (Windows)
Content-Type: application/sdp
Content-Length: 386

v=0
o=- 3589198761 3589198761 IN IP4 192.168.1.2
s=Blink 0.5.0 (Windows)
c=IN IP4 192.168.1.2
t=0 0
m=audio 10054 RTP/AVP 108 99 98 9 0 8 96
c=IN IP4 192.168.1.2
a=rtcp:10055
a=rtpmap:108 opus/48000
a=rtpmap:99 speex/32000
a=rtpmap:98 speex/16000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=sendrecv
<------------->
--- (13 headers 17 lines) ---
Sending to 217.92.105.86:51861 (no NAT)
Sending to 217.92.105.86:51861 (no NAT)
Using INVITE request as basis request - a19e81e8a2d74f718e1263ab3fd3b328
Found peer 'thorsten' for 'thorsten' from 217.92.105.86:51861

<--- Reliably Transmitting (NAT) to 217.92.105.86:51861 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 
192.168.1.2:51861;branch=z9hG4bKPj47b1a62ac3744acd996426618d90388f;received=217.92.105.86;rport=51861
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>;tag=as7b1fc32b
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28484 INVITE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, 
INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="myhost", nonce="0d688867"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog 'a19e81e8a2d74f718e1263ab3fd3b328' 
in 32000 ms (Method: INVITE)

<--- SIP read from UDP:217.92.105.86:51861 --->
ACK sip:3 at myhost.org SIP/2.0
Via: SIP/2.0/UDP 
192.168.1.2:51861;rport;branch=z9hG4bKPj47b1a62ac3744acd996426618d90388f
Max-Forwards: 70
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>;tag=as7b1fc32b
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28484 ACK
User-Agent: Blink 0.5.0 (Windows)
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:217.92.105.86:51861 --->
INVITE sip:3 at myhost.org SIP/2.0
Via: SIP/2.0/UDP 
192.168.1.2:51861;rport;branch=z9hG4bKPj71edb9caa0e84a52b14777e7d949bc2a
Max-Forwards: 70
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>
Contact: <sip:03794281 at 192.168.1.2:51861>
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28485 INVITE
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, 
MESSAGE, REFER
Supported: 100rel, replaces, norefersub, gruu
User-Agent: Blink 0.5.0 (Windows)
Authorization: Digest username="thorsten", realm="myhost", 
nonce="0d688867", uri="sip:3 at myhost.org", 
response="c1a2ab209d255b4ee805edd4de48380a", algorithm=MD5
Content-Type: application/sdp
Content-Length: 386

v=0
o=- 3589198761 3589198761 IN IP4 192.168.1.2
s=Blink 0.5.0 (Windows)
c=IN IP4 192.168.1.2
t=0 0
m=audio 10054 RTP/AVP 108 99 98 9 0 8 96
c=IN IP4 192.168.1.2
a=rtcp:10055
a=rtpmap:108 opus/48000
a=rtpmap:99 speex/32000
a=rtpmap:98 speex/16000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=sendrecv
<------------->
--- (14 headers 17 lines) ---
Sending to 217.92.105.86:51861 (NAT)
Using INVITE request as basis request - a19e81e8a2d74f718e1263ab3fd3b328
Found peer 'thorsten' for 'thorsten' from 217.92.105.86:51861
   == Using SIP RTP CoS mark 5
Found RTP audio format 108
Found RTP audio format 99
Found RTP audio format 98
Found RTP audio format 9
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 96
Found unknown media description format opus for ID 108
Found audio description format speex for ID 99
Found audio description format speex for ID 98
Found audio description format G722 for ID 9
Found audio description format PCMU for ID 0
Found audio description format PCMA for ID 8
Found audio description format telephone-event for ID 96
Capabilities: us - (gsm|ulaw|alaw|g729|g722), peer - 
audio=(ulaw|alaw|speex16|g722|speex32)/video=(nothing)/text=(nothing), 
combined - (ulaw|alaw|g722)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 
(telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 192.168.1.2:10054
Looking for 3 in thorsten_sip_for_testing (domain myhost.org)
list_route: hop: <sip:03794281 at 192.168.1.2:51861>

<--- Transmitting (NAT) to 217.92.105.86:51861 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 
192.168.1.2:51861;branch=z9hG4bKPj71edb9caa0e84a52b14777e7d949bc2a;received=217.92.105.86;rport=51861
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28485 INVITE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, 
INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:3 at 213.203.1.2:5060>
Content-Length: 0

<------------>
     -- Executing [3 at thorsten_sip_for_testing:1] 
AGI("SIP/thorsten-000001f0", "test.php,subid=630") in new stack
     -- Launched AGI Script /var/lib/asterisk/agi-bin/test.php
Audio is at 14698
Adding codec 100012 (g722) to SDP
Adding codec 100003 (ulaw) to SDP
Adding codec 100004 (alaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<--- Reliably Transmitting (NAT) to 217.92.105.86:51861 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
192.168.1.2:51861;branch=z9hG4bKPj71edb9caa0e84a52b14777e7d949bc2a;received=217.92.105.86;rport=51861
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>;tag=as79a9c387
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28485 INVITE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, 
INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:3 at 213.203.1.2:5060>
Content-Type: application/sdp
Content-Length: 289

v=0
o=root 1063384923 1063384923 IN IP4 213.203.1.2
s=Asterisk PBX 11.5.1
c=IN IP4 213.203.1.2
t=0 0
m=audio 14698 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>

<--- SIP read from UDP:217.92.105.86:51861 --->
ACK sip:3 at 213.203.1.2:5060 SIP/2.0
Via: SIP/2.0/UDP 
192.168.1.2:51861;rport;branch=z9hG4bKPj4c08fe792cf74918ba269828783c7f9f
Max-Forwards: 70
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>;tag=as79a9c387
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28485 ACK
User-Agent: Blink 0.5.0 (Windows)
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---

<--- SIP read from UDP:217.92.105.86:51861 --->
BYE sip:3 at 213.203.1.2:5060 SIP/2.0
Via: SIP/2.0/UDP 
192.168.1.2:51861;rport;branch=z9hG4bKPj11fe405b28e64c0f8752db1df28c06e5
Max-Forwards: 70
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>;tag=as79a9c387
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28486 BYE
User-Agent: Blink 0.5.0 (Windows)
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---
Sending to 217.92.105.86:51861 (NAT)
Scheduling destruction of SIP dialog 'a19e81e8a2d74f718e1263ab3fd3b328' 
in 32000 ms (Method: BYE)

<--- Transmitting (NAT) to 217.92.105.86:51861 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
192.168.1.2:51861;branch=z9hG4bKPj11fe405b28e64c0f8752db1df28c06e5;received=217.92.105.86;rport=51861
From: "Thorsten (myhost)" 
<sip:thorsten at myhost.org>;tag=4313e82f4af9423bab056113e5e05713
To: <sip:3 at myhost.org>;tag=as79a9c387
Call-ID: a19e81e8a2d74f718e1263ab3fd3b328
CSeq: 28486 BYE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, 
INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
     -- <SIP/thorsten-000001f0>AGI Script test.php completed, returning 4
   == Spawn extension (thorsten_sip_for_testing, 3, 1) exited non-zero 
on 'SIP/thorsten-000001f0'
Really destroying SIP dialog '83adddbbb5d047adae99fd01eeb55fee' Method: BYE
Really destroying SIP dialog '7b49c8a353bc4df2abeef189489271c7' Method: BYE
<-- snip -->

Here ist my setup:

Asterisk: 11.5.1 (server direct connected / public IP is 213.203.1.2 > 
not really but you will find this IP in the logs)
Windows-Voip-Client: Blink 0.5.0
My Client ist behind NAT (public IP of my router is 217.92.105.86 > 
Client has private IP 192.168.1.2)
No encryption is used.

Any idea?

Thanks in advance
-Thorsten-