Voicemail hangs up on caller

Asterisk Asterisk Support
1

I have a 1.8.13.0 system that was working fine and has not had any configuration changes. However, all of a sudden, voicemail doesn’t work properly. It will record some amount of time, between 5 and 570 seconds, and then drop. Here’s what I’ve done so far:

The amount of time is inconsistent, but I have verified my maxsecs is sufficiently high.
Even though the problem is on all extensions, I’ve deleted and recreated an extension.
I’ve played around with various different RTP timeout options and with the NAT options.
I completely recompiled Asterisk.

I’m about to just do a full reinstall and backup restore, but I want to make sure I’m not missing something and/or that something will be corrupted in the backup and replicate the issue when it is restored. I’m pasting logs below.

Thanks in advance for any help!

Here’s the debug log from full:

[code][2013-01-24 03:42:28] DEBUG[10106] res_rtp_asterisk.c: Got RTCP report of 64 bytes
[2013-01-24 03:42:28] DEBUG[5924] manager.c: Examining event:
Event: RTCPReceived
Privilege: reporting,all
From: callerip:19353
PT: 200(Sender Report)
ReceptionReports: 1
SenderSSRC: 0
FractionLost: 0
PacketsLost: 0
HighestSequence: 10194
SequenceNumberCycles: 0
IAJitter: 87
LastSR: 29260.0268435456
DLSR: 39.9630(sec)
RTT: 35(sec)

[2013-01-24 03:42:33] DEBUG[10106] res_rtp_asterisk.c: Got RTCP report of 64 bytes
[2013-01-24 03:42:33] DEBUG[5924] manager.c: Examining event:
Event: RTCPReceived
Privilege: reporting,all
From: callerip:19353
PT: 200(Sender Report)
ReceptionReports: 1
SenderSSRC: 0
FractionLost: 0
PacketsLost: 0
HighestSequence: 10195
SequenceNumberCycles: 0
IAJitter: 81
LastSR: 29260.0268435456
DLSR: 44.9630(sec)
RTT: 36(sec)

[2013-01-24 03:42:36] DEBUG[10106] app.c: One waitfor failed, trying another
[2013-01-24 03:42:36] DEBUG[5862] chan_sip.c: Auto destroying SIP dialog ‘56549abd36f48890724d8f846c5851f2@callerip:5060’
[2013-01-24 03:42:36] DEBUG[5862] chan_sip.c: Destroying SIP dialog 56549abd36f48890724d8f846c5851f2@callerip:5060
[2013-01-24 03:42:38] WARNING[10106] app.c: No audio available on SIP/iotrunk-00000004??
[2013-01-24 03:42:38] VERBOSE[10106] app.c: – User hung up
[2013-01-24 03:42:38] DEBUG[10106] channel.c: Set channel SIP/iotrunk-00000004 to read format alaw
[2013-01-24 03:42:38] DEBUG[10106] app.c: Locked path ‘/var/spool/asterisk/voicemail/default/720/INBOX’
[2013-01-24 03:42:38] DEBUG[10106] app_voicemail.c: /var/spool/asterisk/voicemail/default/720/INBOX map[0] = 1, count = 1
[2013-01-24 03:42:38] DEBUG[10106] app_voicemail.c: /var/spool/asterisk/voicemail/default/720/INBOX map[1] = 1, count = 2
[2013-01-24 03:42:38] DEBUG[5924] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/iotrunk-00000004
Variable: VM_MESSAGEFILE
Value: /var/spool/asterisk/voicemail/default/720/INBOX/msg0002
Uniqueid: 1359016893.4

[2013-01-24 03:42:38] DEBUG[10106] app.c: Unlocked path ‘/var/spool/asterisk/voicemail/default/720/INBOX’
[2013-01-24 03:42:38] DEBUG[5924] manager.c: Examining event:
Event: MessageWaiting
Privilege: call,all
Mailbox: 720@default
Waiting: 1
New: 3
Old: 0

[2013-01-24 03:42:38] DEBUG[5924] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/iotrunk-00000004
Variable: VMSTATUS
Value: SUCCESS
Uniqueid: 1359016893.4

[2013-01-24 03:42:38] DEBUG[10106] app_macro.c: Spawn extension (macro-vm,s-CHANUNAVAIL,2) exited non-zero on ‘SIP/iotrunk-00000004’ in macro ‘vm’
[2013-01-24 03:42:38] VERBOSE[10106] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/iotrunk-00000004’ in macro ‘vm’
[2013-01-24 03:42:38] DEBUG[5924] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/iotrunk-00000004
Variable: MACRO_DEPTH
Value: 1
Uniqueid: 1359016893.4

[2013-01-24 03:42:38] DEBUG[5924] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/iotrunk-00000004
Variable: ARG1
Value: 720
Uniqueid: 1359016893.4[/code]

Here’s the realtime server:

== Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 -- Executing [720@from-internal:1] Macro("SIP/iotrunk-00000002", "exten-vm,720,720") in new stack -- Executing [s@macro-exten-vm:1] Macro("SIP/iotrunk-00000002", "user-callerid,") in new stack -- Executing [s@macro-user-callerid:1] Set("SIP/iotrunk-00000002", "AMPUSER=5555555555") in new stack -- Executing [s@macro-user-callerid:2] GotoIf("SIP/iotrunk-00000002", "0?report") in new stack -- Executing [s@macro-user-callerid:3] ExecIf("SIP/iotrunk-00000002", "1?Set(REALCALLERIDNUM=5555555555)") in new stack -- Executing [s@macro-user-callerid:4] Set("SIP/iotrunk-00000002", "AMPUSER=") in new stack -- Executing [s@macro-user-callerid:5] Set("SIP/iotrunk-00000002", "AMPUSERCIDNAME=") in new stack -- Executing [s@macro-user-callerid:6] GotoIf("SIP/iotrunk-00000002", "1?report") in new stack -- Goto (macro-user-callerid,s,10) -- Executing [s@macro-user-callerid:10] GotoIf("SIP/iotrunk-00000002", "0?continue") in new stack -- Executing [s@macro-user-callerid:11] Set("SIP/iotrunk-00000002", "__TTL=64") in new stack -- Executing [s@macro-user-callerid:12] GotoIf("SIP/iotrunk-00000002", "1?continue") in new stack -- Goto (macro-user-callerid,s,19) -- Executing [s@macro-user-callerid:19] Set("SIP/iotrunk-00000002", "CALLERID(number)=5555555555") in new stack -- Executing [s@macro-user-callerid:20] Set("SIP/iotrunk-00000002", "CALLERID(name)=5555555555") in new stack -- Executing [s@macro-user-callerid:21] NoOp("SIP/iotrunk-00000002", "Using CallerID "5555555555" <5555555555>") in new stack -- Executing [s@macro-exten-vm:2] Set("SIP/iotrunk-00000002", "RingGroupMethod=none") in new stack -- Executing [s@macro-exten-vm:3] Set("SIP/iotrunk-00000002", "VMBOX=720") in new stack -- Executing [s@macro-exten-vm:4] Set("SIP/iotrunk-00000002", "__EXTTOCALL=720") in new stack -- Executing [s@macro-exten-vm:5] Set("SIP/iotrunk-00000002", "CFUEXT=") in new stack -- Executing [s@macro-exten-vm:6] Set("SIP/iotrunk-00000002", "CFBEXT=") in new stack -- Executing [s@macro-exten-vm:7] Set("SIP/iotrunk-00000002", "RT=15") in new stack -- Executing [s@macro-exten-vm:8] Macro("SIP/iotrunk-00000002", "record-enable,720,IN") in new stack -- Executing [s@macro-record-enable:1] GotoIf("SIP/iotrunk-00000002", "1?check") in new stack -- Goto (macro-record-enable,s,4) -- Executing [s@macro-record-enable:4] ExecIf("SIP/iotrunk-00000002", "0?MacroExit()") in new stack -- Executing [s@macro-record-enable:5] GotoIf("SIP/iotrunk-00000002", "0?Group:OUT") in new stack -- Goto (macro-record-enable,s,15) -- Executing [s@macro-record-enable:15] GotoIf("SIP/iotrunk-00000002", "1?IN") in new stack -- Goto (macro-record-enable,s,20) -- Executing [s@macro-record-enable:20] ExecIf("SIP/iotrunk-00000002", "1?MacroExit()") in new stack -- Executing [s@macro-exten-vm:9] Macro("SIP/iotrunk-00000002", "dial-one,15,tr,720") in new stack -- Executing [s@macro-dial-one:1] Set("SIP/iotrunk-00000002", "DEXTEN=720") in new stack -- Executing [s@macro-dial-one:2] Set("SIP/iotrunk-00000002", "DIALSTATUS_CW=") in new stack -- Executing [s@macro-dial-one:3] GosubIf("SIP/iotrunk-00000002", "0?screen,1") in new stack -- Executing [s@macro-dial-one:4] GosubIf("SIP/iotrunk-00000002", "0?cf,1") in new stack -- Executing [s@macro-dial-one:5] GotoIf("SIP/iotrunk-00000002", "1?skip1") in new stack -- Goto (macro-dial-one,s,8) -- Executing [s@macro-dial-one:8] GotoIf("SIP/iotrunk-00000002", "0?nodial") in new stack -- Executing [s@macro-dial-one:9] GotoIf("SIP/iotrunk-00000002", "0?continue") in new stack -- Executing [s@macro-dial-one:10] Set("SIP/iotrunk-00000002", "EXTHASCW=ENABLED") in new stack -- Executing [s@macro-dial-one:11] GotoIf("SIP/iotrunk-00000002", "0?next1:cwinusebusy") in new stack -- Goto (macro-dial-one,s,23) -- Executing [s@macro-dial-one:23] GotoIf("SIP/iotrunk-00000002", "1?next3:continue") in new stack -- Goto (macro-dial-one,s,24) -- Executing [s@macro-dial-one:24] ExecIf("SIP/iotrunk-00000002", "0?Set(DIALSTATUS_CW=BUSY)") in new stack -- Executing [s@macro-dial-one:25] GotoIf("SIP/iotrunk-00000002", "0?nodial") in new stack -- Executing [s@macro-dial-one:26] GosubIf("SIP/iotrunk-00000002", "1?dstring,1:dlocal,1") in new stack -- Executing [dstring@macro-dial-one:1] Set("SIP/iotrunk-00000002", "DSTRING=") in new stack -- Executing [dstring@macro-dial-one:2] Set("SIP/iotrunk-00000002", "DEVICES=720") in new stack -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/iotrunk-00000002", "0?Return()") in new stack -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/iotrunk-00000002", "0?Set(DEVICES=20)") in new stack -- Executing [dstring@macro-dial-one:5] Set("SIP/iotrunk-00000002", "LOOPCNT=1") in new stack -- Executing [dstring@macro-dial-one:6] Set("SIP/iotrunk-00000002", "ITER=1") in new stack -- Executing [dstring@macro-dial-one:7] Set("SIP/iotrunk-00000002", "THISDIAL=SIP/720") in new stack -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/iotrunk-00000002", "1?zap2dahdi,1") in new stack -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/iotrunk-00000002", "0?Return()") in new stack -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/iotrunk-00000002", "NEWDIAL=") in new stack -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/iotrunk-00000002", "LOOPCNT2=1") in new stack -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/iotrunk-00000002", "ITER2=1") in new stack -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/iotrunk-00000002", "THISPART2=SIP/720") in new stack -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/iotrunk-00000002", "0?Set(THISPART2=DAHDI/720)") in new stack -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/iotrunk-00000002", "NEWDIAL=SIP/720&") in new stack -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/iotrunk-00000002", "ITER2=2") in new stack -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/iotrunk-00000002", "0?begin2") in new stack -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/iotrunk-00000002", "THISDIAL=SIP/720") in new stack -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/iotrunk-00000002", "") in new stack -- Executing [dstring@macro-dial-one:9] Set("SIP/iotrunk-00000002", "DSTRING=SIP/720&") in new stack -- Executing [dstring@macro-dial-one:10] Set("SIP/iotrunk-00000002", "ITER=2") in new stack -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/iotrunk-00000002", "0?begin") in new stack -- Executing [dstring@macro-dial-one:12] Set("SIP/iotrunk-00000002", "DSTRING=SIP/720") in new stack -- Executing [dstring@macro-dial-one:13] Return("SIP/iotrunk-00000002", "") in new stack -- Executing [s@macro-dial-one:27] GotoIf("SIP/iotrunk-00000002", "0?nodial") in new stack -- Executing [s@macro-dial-one:28] GotoIf("SIP/iotrunk-00000002", "1?skiptrace") in new stack -- Goto (macro-dial-one,s,30) -- Executing [s@macro-dial-one:30] Set("SIP/iotrunk-00000002", "D_OPTIONS=tr") in new stack -- Executing [s@macro-dial-one:31] ExecIf("SIP/iotrunk-00000002", "0?SIPAddHeader(Alert-Info: )") in new stack -- Executing [s@macro-dial-one:32] ExecIf("SIP/iotrunk-00000002", "0?SIPAddHeader()") in new stack -- Executing [s@macro-dial-one:33] ExecIf("SIP/iotrunk-00000002", "0?Set(CHANNEL(musicclass)=)") in new stack -- Executing [s@macro-dial-one:34] GosubIf("SIP/iotrunk-00000002", "0?qwait,1") in new stack -- Executing [s@macro-dial-one:35] Set("SIP/iotrunk-00000002", "__CWIGNORE=") in new stack -- Executing [s@macro-dial-one:36] Set("SIP/iotrunk-00000002", "__KEEPCID=TRUE") in new stack -- Executing [s@macro-dial-one:37] Dial("SIP/iotrunk-00000002", "SIP/720,15,tr") in new stack == Everyone is busy/congested at this time (1:0/0/1) -- Executing [s@macro-dial-one:38] ExecIf("SIP/iotrunk-00000002", "0?Set(DIALSTATUS=)") in new stack -- Executing [s@macro-dial-one:39] GosubIf("SIP/iotrunk-00000002", "0?s-CHANUNAVAIL,1") in new stack -- Executing [s@macro-dial-one:40] MacroExit("SIP/iotrunk-00000002", "") in new stack -- Executing [s@macro-exten-vm:10] GotoIf("SIP/iotrunk-00000002", "0?exit") in new stack -- Executing [s@macro-exten-vm:11] Set("SIP/iotrunk-00000002", "SV_DIALSTATUS=CHANUNAVAIL") in new stack -- Executing [s@macro-exten-vm:12] GosubIf("SIP/iotrunk-00000002", "0?docfu,1") in new stack -- Executing [s@macro-exten-vm:13] GosubIf("SIP/iotrunk-00000002", "0?docfb,1") in new stack -- Executing [s@macro-exten-vm:14] Set("SIP/iotrunk-00000002", "DIALSTATUS=CHANUNAVAIL") in new stack -- Executing [s@macro-exten-vm:15] NoOp("SIP/iotrunk-00000002", "Voicemail is '720'") in new stack -- Executing [s@macro-exten-vm:16] GotoIf("SIP/iotrunk-00000002", "0?s-CHANUNAVAIL,1") in new stack -- Executing [s@macro-exten-vm:17] NoOp("SIP/iotrunk-00000002", "Sending to Voicemail box 720") in new stack -- Executing [s@macro-exten-vm:18] Macro("SIP/iotrunk-00000002", "vm,720,CHANUNAVAIL,") in new stack -- Executing [s@macro-vm:1] Macro("SIP/iotrunk-00000002", "user-callerid,SKIPTTL") in new stack -- Executing [s@macro-user-callerid:1] Set("SIP/iotrunk-00000002", "AMPUSER=5555555555") in new stack -- Executing [s@macro-user-callerid:2] GotoIf("SIP/iotrunk-00000002", "0?report") in new stack -- Executing [s@macro-user-callerid:3] ExecIf("SIP/iotrunk-00000002", "0?Set(REALCALLERIDNUM=5555555555)") in new stack -- Executing [s@macro-user-callerid:4] Set("SIP/iotrunk-00000002", "AMPUSER=") in new stack -- Executing [s@macro-user-callerid:5] Set("SIP/iotrunk-00000002", "AMPUSERCIDNAME=") in new stack -- Executing [s@macro-user-callerid:6] GotoIf("SIP/iotrunk-00000002", "1?report") in new stack -- Goto (macro-user-callerid,s,10) -- Executing [s@macro-user-callerid:10] GotoIf("SIP/iotrunk-00000002", "1?continue") in new stack -- Goto (macro-user-callerid,s,19) -- Executing [s@macro-user-callerid:19] Set("SIP/iotrunk-00000002", "CALLERID(number)=5555555555") in new stack -- Executing [s@macro-user-callerid:20] Set("SIP/iotrunk-00000002", "CALLERID(name)=5555555555") in new stack -- Executing [s@macro-user-callerid:21] NoOp("SIP/iotrunk-00000002", "Using CallerID "5555555555" <5555555555>") in new stack -- Executing [s@macro-vm:2] Set("SIP/iotrunk-00000002", "VMGAIN=""") in new stack -- Executing [s@macro-vm:3] GotoIf("SIP/iotrunk-00000002", "1?vmx,1") in new stack -- Goto (macro-vm,vmx,1) -- Executing [vmx@macro-vm:1] Set("SIP/iotrunk-00000002", "MEXTEN=720") in new stack -- Executing [vmx@macro-vm:2] Set("SIP/iotrunk-00000002", "MMODE=CHANUNAVAIL") in new stack -- Executing [vmx@macro-vm:3] Set("SIP/iotrunk-00000002", "RETVM=") in new stack -- Executing [vmx@macro-vm:4] Set("SIP/iotrunk-00000002", "MODE=unavail") in new stack -- Executing [vmx@macro-vm:5] GotoIf("SIP/iotrunk-00000002", "1?chknomsg") in new stack -- Goto (macro-vm,vmx,7) -- Executing [vmx@macro-vm:7] GotoIf("SIP/iotrunk-00000002", "0?s-CHANUNAVAIL,1") in new stack -- Executing [vmx@macro-vm:8] GotoIf("SIP/iotrunk-00000002", "1?notdirect") in new stack -- Goto (macro-vm,vmx,10) -- Executing [vmx@macro-vm:10] NoOp("SIP/iotrunk-00000002", "Checking if ext 720 is enabled: ") in new stack -- Executing [vmx@macro-vm:11] GotoIf("SIP/iotrunk-00000002", "1?s-CHANUNAVAIL,1") in new stack -- Goto (macro-vm,s-CHANUNAVAIL,1) -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/iotrunk-00000002", "get-vmcontext,720") in new stack -- Executing [s@macro-get-vmcontext:1] Set("SIP/iotrunk-00000002", "VMCONTEXT=default") in new stack -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/iotrunk-00000002", "0?200:300") in new stack -- Goto (macro-get-vmcontext,s,300) -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/iotrunk-00000002", "") in new stack -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/iotrunk-00000002", "720@default,u""") in new stack -- <SIP/iotrunk-00000002> Playing 'vm-theperson.gsm' (language 'en') -- <SIP/iotrunk-00000002> Playing 'digits/7.gsm' (language 'en') -- <SIP/iotrunk-00000002> Playing 'digits/2.gsm' (language 'en') -- <SIP/iotrunk-00000002> Playing 'digits/0.gsm' (language 'en') -- <SIP/iotrunk-00000002> Playing 'vm-isunavail.gsm' (language 'en') -- <SIP/iotrunk-00000002> Playing 'vm-intro.gsm' (language 'en') -- <SIP/iotrunk-00000002> Playing 'beep.gsm' (language 'en') -- Recording the message -- x=0, open writing: /var/spool/asterisk/voicemail/default/720/tmp/NUxTKS format: wav, 0xb6f091e8 -- User hung up == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/iotrunk-00000002' in macro 'vm' == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SIP/iotrunk-00000002' in macro 'exten-vm' == Spawn extension (from-internal, 720, 1) exited non-zero on 'SIP/iotrunk-00000002' -- Executing [h@from-internal:1] Macro("SIP/iotrunk-00000002", "hangupcall") in new stack -- Executing [s@macro-hangupcall:1] GotoIf("SIP/iotrunk-00000002", "1?skiprg") in new stack -- Goto (macro-hangupcall,s,4) -- Executing [s@macro-hangupcall:4] GotoIf("SIP/iotrunk-00000002", "1?skipblkvm") in new stack -- Goto (macro-hangupcall,s,7) -- Executing [s@macro-hangupcall:7] GotoIf("SIP/iotrunk-00000002", "1?theend") in new stack -- Goto (macro-hangupcall,s,9) -- Executing [s@macro-hangupcall:9] Hangup("SIP/iotrunk-00000002", "") in new stack == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/iotrunk-00000002' in macro 'hangupcall' == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/iotrunk-00000002'

Here’s the SIP debug:

[code]
— (10 headers 0 lines) —
Really destroying SIP dialog ‘5ac60e1f4063152045a922104892a12a@serverip:5060’ Method: OPTIONS

— (10 headers 0 lines) —
Really destroying SIP dialog ‘671c67182a21db2944b7b0c43124c409@serverip:5060’ Method: OPTIONS
Reliably Transmitting (NAT) to callerip:5060:
OPTIONS sip:callerip SIP/2.0
Via: SIP/2.0/UDP serverip:5060;branch=z9hG4bK4a6a876c;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@serverip;tag=as4622c83a
To: sip:callerip
Contact: sip:Unknown@serverip:5060
Call-ID: 7413375d1cfc04a17923af5777d0e44d@serverip:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.8.1(1.8.13.0)
Date: Thu, 24 Jan 2013 08:25:44 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<— SIP read from UDP:callerip:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP serverip:5060;branch=z9hG4bK4a6a876c;received=69.73.39.7;rport=5060
From: “Unknown” sip:Unknown@serverip;tag=as4622c83a
To: sip:callerip;tag=as36dea8c7
Call-ID: 7413375d1cfc04a17923af5777d0e44d@serverip:5060
CSeq: 102 OPTIONS
Server: FPBX-2.10.1(1.8.8.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:callerip:5060
Accept: application/sdp
Content-Length: 0

— (10 headers 0 lines) —
Really destroying SIP dialog ‘0974f50e06192bd37ade5b4139e3804a@serverip:5060’ Method: OPTIONS

<— SIP read from UDP:callerip:5060 —>
OPTIONS sip:serverip SIP/2.0
Via: SIP/2.0/UDP callerip:5060;branch=z9hG4bK7214b7ad;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@callerip;tag=as551eeb6d
To: sip:serverip
Contact: sip:Unknown@callerip:5060
Call-ID: 7b6f966056e3cc9243bf2980368271e6@callerip:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.10.1(1.8.8.0)
Date: Thu, 24 Jan 2013 08:26:04 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------->
— (13 headers 0 lines) —
Looking for s in from-sip-external (domain serverip)

<— Transmitting (NAT) to callerip:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP callerip:5060;branch=z9hG4bK7214b7ad;received=callerip;rport=5060
From: “Unknown” sip:Unknown@callerip;tag=as551eeb6d
To: sip:serverip;tag=as389fe6aa
Call-ID: 7b6f966056e3cc9243bf2980368271e6@callerip:5060
CSeq: 102 OPTIONS
Server: FPBX-2.8.1(1.8.13.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:serverip:5060
Accept: application/sdp
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘7b6f966056e3cc9243bf2980368271e6@callerip:5060’ in 32000 ms (Method: OPTIONS)

<— SIP read from UDP:callerip:5060 —>
BYE sip:720@serverip:5060 SIP/2.0
Via: SIP/2.0/UDP callerip:5060;branch=z9hG4bK644842ee;rport
Max-Forwards: 70
From: “5555555555” sip:5555555555@callerip;tag=as4291ec6c
To: sip:720@serverip;tag=as589e3c41
Call-ID: 1dd0332a6b626d5a14c444c7237780f9@callerip:5060
CSeq: 103 BYE
User-Agent: FPBX-2.10.1(1.8.8.0)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Sending to callerip:5060 (NAT)
Scheduling destruction of SIP dialog ‘1dd0332a6b626d5a14c444c7237780f9@callerip:5060’ in 6400 ms (Method: BYE)

<— Transmitting (NAT) to callerip:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP callerip:5060;branch=z9hG4bK644842ee;received=callerip;rport=5060
From: “5555555555” sip:5555555555@callerip;tag=as4291ec6c
To: sip:720@serverip;tag=as589e3c41
Call-ID: 1dd0332a6b626d5a14c444c7237780f9@callerip:5060
CSeq: 103 BYE
Server: FPBX-2.8.1(1.8.13.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
– User hung up
== Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/iotrunk-00000003’ in macro ‘vm’
== Spawn extension (macro-exten-vm, s, 18) exited non-zero on ‘SIP/iotrunk-00000003’ in macro ‘exten-vm’
== Spawn extension (from-internal, 720, 1) exited non-zero on ‘SIP/iotrunk-00000003’
– Executing [h@from-internal:1] Macro(“SIP/iotrunk-00000003”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/iotrunk-00000003”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,4)
– Executing [s@macro-hangupcall:4] GotoIf(“SIP/iotrunk-00000003”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,7)
– Executing [s@macro-hangupcall:7] GotoIf(“SIP/iotrunk-00000003”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,9)
– Executing [s@macro-hangupcall:9] Hangup(“SIP/iotrunk-00000003”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/iotrunk-00000003’ in macro ‘hangupcall’
== Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/iotrunk-00000003’
Really destroying SIP dialog ‘1dd0332a6b626d5a14c444c7237780f9@callerip:5060’ Method: BYE[/code]

2

The caller cleared! I suspect they can’t cope with silence suppression.

3

Please elaborate. Are you saying that the calling device gave up? There shouldn’t be an issue with the call being silent on the calling end, because I’ve been testing by putting blaring music on hold on and watching to see when it drops the call. I’ve listened back to the recordings and there’s definitely audio.

From the server side, I’ve tried both with and without the transmit_silence_during_record option, to no avail.

Thanks!

4

The BYE that closes the connection is inbound, and the trace clearly says that the caller hungup.

During recording, Asterisk might only be generating RTCP and no RTP.

5

Got it. So to follow up:

Why would there be such a variance instead of it always failing quickly? It’s made it to 9 minutes.
How to I make it generate RTP?
What would cause this to start happening when it wasn’t before?

Thanks!

6

Hey mattsl, did you ever get a resolution on this? We seem to be experiencing the same issue, asterisk erroneously thinks the caller has hung up after between 12 and 48 seconds. Thanks!