Thorsten Göllner
2013-Sep-26 14:03 UTC
[asterisk-users] Asterisk / SIP-Call / AGI-Script / SIGHUP after Answer
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-