Entry phone audio not working on dial-in

New to Asterisk and FreePbx, but making progress. FreePBX 2.11.0.0beta2.6 and Asterisk 11.1.2 on Raspberry Pi (RaspPbx distribution).

I’ve got a fairly basic test setup working using a mix of softphones, Yealink and Grandstream hard phones, and an SPA3102, which so far works as expected (albeit with some dialling delays which I imagine are down to dialplans not being set up properly). Its all on a single local network segment.

But I’m having a problem with this door entry phone http://www.alphatech.cz/english/slim-ipdp.html (which seems to be ‘badged’ by a number of manufacturers - mine are ‘Protalk’).

Its apparently all set up OK, and registers to FreePbx. Pretty much default settings on FreePbx - started with the same settings as for the hardphone extensions.

I can dial the entry phone from another extension, and works OK - entry phone picks up, two-way audio, can control door release relays, hangs up OK.

The problem is when a button is pushed on the entry phone - configured extension rings OK. Pick up call, and there is no audio in either direction. Hang up is OK.

I’ve taken a SIP trace of traffic to the entry phone (below), but not expert enough to identify the problem. (I noticed the sending of the SnomIPPhoneImageFile information, which was rejected, and managed to disable this in the entry phone - no difference).

Can anyone shed any light on this?

=============================================================================================

[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:8] GosubIf(“SIP/719-000000c1”, “1?zap2dahdi,1()”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:1] ExecIf(“SIP/719-000000c1”, “0?Return()”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:2] Set(“SIP/719-000000c1”, “NEWDIAL=”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:3] Set(“SIP/719-000000c1”, “LOOPCNT2=1”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:4] Set(“SIP/719-000000c1”, “ITER2=1”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:5] Set(“SIP/719-000000c1”, “THISPART2=SIP/704”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:6] ExecIf(“SIP/719-000000c1”, “0?Set(THISPART2=DAHDI/704)”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:7] Set(“SIP/719-000000c1”, “NEWDIAL=SIP/704&”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:8] Set(“SIP/719-000000c1”, “ITER2=2”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:9] GotoIf(“SIP/719-000000c1”, “0?begin2”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:10] Set(“SIP/719-000000c1”, “THISDIAL=SIP/704”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:11] Return(“SIP/719-000000c1”, “”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:9] Set(“SIP/719-000000c1”, “DSTRING=SIP/704&”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:10] Set(“SIP/719-000000c1”, “ITER=2”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:11] GotoIf(“SIP/719-000000c1”, “0?begin”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:12] Set(“SIP/719-000000c1”, “DSTRING=SIP/704”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:13] Return(“SIP/719-000000c1”, “”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:27] GotoIf(“SIP/719-000000c1”, “0?nodial”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:28] GotoIf(“SIP/719-000000c1”, “0?skiptrace”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:29] GosubIf(“SIP/719-000000c1”, “1?ctset,1():ctclear,1()”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:1] Set(“SIP/719-000000c1”, “DB(CALLTRACE/704)=719”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:2] Return(“SIP/719-000000c1”, “”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:30] Set(“SIP/719-000000c1”, “D_OPTIONS=tr”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:31] ExecIf(“SIP/719-000000c1”, “0?SIPAddHeader(Alert-Info: )”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:32] ExecIf(“SIP/719-000000c1”, “0?SIPAddHeader()”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:33] ExecIf(“SIP/719-000000c1”, “0?Set(CHANNEL(musicclass)=)”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:34] GosubIf(“SIP/719-000000c1”, “0?qwait,1()”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:35] Set(“SIP/719-000000c1”, “__CWIGNORE=”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:36] Set(“SIP/719-000000c1”, “__KEEPCID=TRUE”) in new stack
[2013-03-29 22:04:45] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:37] GotoIf(“SIP/719-000000c1”, “0?usegoto,1”) in new stack
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
REGISTER sip:[FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK106323313
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected]
Call-ID: 61629487
CSeq: 23 REGISTER
Contact: sip:[email protected]:5060;line=6e3db27916951df
Authorization: Digest username=“719”, realm=“asterisk”, nonce=“0a8440ac”, uri=“sip:[FreePbx]”, response=“85d4207857847dde6d4bd48c10a95f2e”, algorithm=MD5
Max-Forwards: 70
User-Agent: VoIP Guard
Expires: 600
Content-Length: 0

<------------->
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c: — (12 headers 0 lines) —
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c: Sending to [EntryPhone]:5060 (no NAT)
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c:
<— Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK106323313;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected];tag=as2f0f5156
Call-ID: 61629487
CSeq: 23 REGISTER
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="67be26bf"
Content-Length: 0

<------------>
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘61629487’ in 32000 ms (Method: REGISTER)
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
REGISTER sip:[FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1528902680
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected]
Call-ID: 61629487
CSeq: 24 REGISTER
Contact: sip:[email protected]:5060;line=6e3db27916951df
Authorization: Digest username=“719”, realm=“asterisk”, nonce=“67be26bf”, uri=“sip:[FreePbx]”, response=“e1365d30a5c65e683c89abf4fff57bc5”, algorithm=MD5
Max-Forwards: 70
User-Agent: VoIP Guard
Expires: 600
Content-Length: 0

<------------->
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c: — (12 headers 0 lines) —
[2013-03-29 22:04:45] VERBOSE[2771] chan_sip.c: Sending to [EntryPhone]:5060 (no NAT)
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:38] GotoIf(“SIP/719-000000c1”, “0?godial”) in new stack
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:39] Set(“SIP/719-000000c1”, “CONNECTEDLINE(name,i)=X704”) in new stack
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:40] Set(“SIP/719-000000c1”, “CONNECTEDLINE(num)=704”) in new stack
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:41] Set(“SIP/719-000000c1”, “D_OPTIONS=trI”) in new stack
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Reliably Transmitting (no NAT) to [EntryPhone]:5060:
OPTIONS sip:[email protected][EntryPhone]:5060;line=6e3db27916951df SIP/2.0
Via: SIP/2.0/UDP [FreePbx]:5060;branch=z9hG4bK339d0bff
Max-Forwards: 70
From: “Unknown” sip:[email protected];tag=as3d2663a5
To: sip:[email protected]:5060;line=6e3db27916951df
Contact: sip:[email protected]:5060
Call-ID: [email protected][FreePbx]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX2.11.0beta3(11.1.2)
Date: Fri, 29 Mar 2013 22:04:48 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK1528902680;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected];tag=as2f0f5156
Call-ID: 61629487
CSeq: 24 REGISTER
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 600
Contact: sip:[email protected]:5060;line=6e3db27916951df;expires=600
Date: Fri, 29 Mar 2013 22:04:48 GMT
Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘[email protected][FreePbx]:5060’ in 6400 ms (Method: NOTIFY)
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Reliably Transmitting (no NAT) to [EntryPhone]:5060:
NOTIFY sip:[email protected][EntryPhone]:5060;line=6e3db27916951df SIP/2.0
Via: SIP/2.0/UDP [FreePbx]:5060;branch=z9hG4bK1d9ee8a7
Max-Forwards: 70
From: “Unknown” sip:[email protected];tag=as21c600f8
To: sip:[email protected]:5060;line=6e3db27916951df
Contact: sip:[email protected]:5060
Call-ID: [email protected][FreePbx]:5060
CSeq: 102 NOTIFY
User-Agent: FPBX2.11.0beta3(11.1.2)
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 89

Messages-Waiting: no
Message-Account: sip:*[email protected][FreePbx]
Voice-Message: 0/0 (0/0)


[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:42] Dial(“SIP/719-000000c1”, “SIP/704,trI”) in new stack
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] netsock2.c: == Using SIP RTP TOS bits 184
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] netsock2.c: == Using SIP RTP CoS mark 5
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘61629487’ in 32000 ms (Method: REGISTER)
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
REGISTER sip:[FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1528902680
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected]
Call-ID: 61629487
CSeq: 24 REGISTER
Contact: sip:[email protected]:5060;line=6e3db27916951df
Authorization: Digest username=“719”, realm=“asterisk”, nonce=“67be26bf”, uri=“sip:[FreePbx]”, response=“e1365d30a5c65e683c89abf4fff57bc5”, algorithm=MD5
Max-Forwards: 70
User-Agent: VoIP Guard
Expires: 600
Content-Length: 0

<------------->
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: — (12 headers 0 lines) —
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Sending to [EntryPhone]:5060 (no NAT)
[2013-03-29 22:04:48] NOTICE[2771] chan_sip.c: Correct auth, but based on stale nonce received from ‘“Prod Door” sip:[email protected];tag=1874547334’
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK1528902680;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected];tag=as2f0f5156
Call-ID: 61629487
CSeq: 24 REGISTER
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“2cb6cf77”, stale=true
Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘61629487’ in 32000 ms (Method: REGISTER)
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] app_dial.c: – Called SIP/704
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] chan_sip.c:
<— Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK1524082986;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=320428240
To: sip:[email protected];tag=as040ccf54
Call-ID: 1396090569
CSeq: 21 INVITE
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:[email protected]:5060
Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] app_dial.c: – Connected line update to SIP/719-000000c1 prevented.
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
REGISTER sip:[FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1528902680
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected]
Call-ID: 61629487
CSeq: 24 REGISTER
Contact: sip:[email protected]:5060;line=6e3db27916951df
Authorization: Digest username=“719”, realm=“asterisk”, nonce=“67be26bf”, uri=“sip:[FreePbx]”, response=“e1365d30a5c65e683c89abf4fff57bc5”, algorithm=MD5
Max-Forwards: 70
User-Agent: VoIP Guard
Expires: 600
Content-Length: 0

<------------->
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: — (12 headers 0 lines) —
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Sending to [EntryPhone]:5060 (no NAT)
[2013-03-29 22:04:48] NOTICE[2771] chan_sip.c: Correct auth, but based on stale nonce received from ‘“Prod Door” sip:[email protected];tag=1874547334’
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK1528902680;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=1874547334
To: “Prod Door” sip:[email protected];tag=as2f0f5156
Call-ID: 61629487
CSeq: 24 REGISTER
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“2cb6cf77”, stale=true
Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘61629487’ in 32000 ms (Method: REGISTER)
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP [FreePbx]:5060;branch=z9hG4bK339d0bff
From: “Unknown” sip:[email protected];tag=as3d2663a5
To: sip:[email protected]:5060;line=6e3db27916951df;tag=1285556830
Call-ID: [email protected][FreePbx]:5060
CSeq: 102 OPTIONS
Allow: INVITE, ACK, BYE, CANCEL, REFER, OPTIONS, INFO, REGISTER
Accept: application/sdp
User-Agent: VoIP Guard
Content-Length: 0

<------------->
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: — (10 headers 0 lines) —
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘[email protected][FreePbx]:5060’ Method: OPTIONS
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
SIP/2.0 481 Subscription Does Not Exist
Via: SIP/2.0/UDP [FreePbx]:5060;branch=z9hG4bK1d9ee8a7
From: “Unknown” sip:[email protected];tag=as21c600f8
To: sip:[email protected]:5060;line=6e3db27916951df;tag=1684613317
Call-ID: [email protected][FreePbx]:5060
CSeq: 102 NOTIFY
User-Agent: VoIP Guard
Content-Length: 0

<------------->
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: — (8 headers 0 lines) —
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘[email protected][FreePbx]:5060’ Method: NOTIFY
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
NOTIFY sip:[email protected][FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1109136888
From: “Prod Door” sip:[email protected];tag=565414963
To: sip:[email protected]
Call-ID: 1530514004
CSeq: 20 NOTIFY
Content-Type: application/snomxml
Max-Forwards: 70
User-Agent: VoIP Guard
Content-Length: 235

<?xml version="1.0" encoding="UTF-8"?> 0 0 http://[EntryPhone]/video.jpg http://[EntryPhone]/snom01.xml <-------------> [2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: --- (10 headers 7 lines) --- [2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: <--- Transmitting (no NAT) to [EntryPhone]:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1109136888;received=[EntryPhone] From: "Prod Door" ;tag=565414963 To: ;tag=as0f069cb5 Call-ID: 1530514004 CSeq: 20 NOTIFY Server: FPBX2.11.0beta3(11.1.2) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘1530514004’ in 32000 ms (Method: NOTIFY)
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] app_dial.c: – SIP/704-000000c2 is ringing
[2013-03-29 22:04:48] VERBOSE[30354][C-0000006d] chan_sip.c:
<— Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK1524082986;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=320428240
To: sip:[email protected];tag=as040ccf54
Call-ID: 1396090569
CSeq: 21 INVITE
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:[email protected]:5060
Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
NOTIFY sip:[email protected][FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK537528715
From: “Prod Door” sip:[email protected];tag=472532245
To: sip:[email protected]
Call-ID: 392454681
CSeq: 20 NOTIFY
Content-Type: application/snomxml
Max-Forwards: 70
User-Agent: VoIP Guard
Content-Length: 235

<?xml version="1.0" encoding="UTF-8"?> 0 0 http://[EntryPhone]/video.jpg http://[EntryPhone]/snom01.xml <-------------> [2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: --- (10 headers 7 lines) --- [2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: <--- Transmitting (no NAT) to [EntryPhone]:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK537528715;received=[EntryPhone] From: "Prod Door" ;tag=472532245 To: ;tag=as4bc635b8 Call-ID: 392454681 CSeq: 20 NOTIFY Server: FPBX2.11.0beta3(11.1.2) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0

<------------>
[2013-03-29 22:04:48] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘392454681’ in 32000 ms (Method: NOTIFY)
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] app_dial.c: – Connected line update to SIP/719-000000c1 prevented.
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] app_dial.c: – SIP/704-000000c2 answered SIP/719-000000c1
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] chan_sip.c: Audio is at 7256
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] chan_sip.c: Adding codec 100003 (ulaw) to SDP
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] chan_sip.c: Adding codec 100004 (alaw) to SDP
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2013-03-29 22:04:50] VERBOSE[30354][C-0000006d] chan_sip.c:
<— Reliably Transmitting (no NAT) to [EntryPhone]:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP [EntryPhone]:5060;branch=z9hG4bK1524082986;received=[EntryPhone];rport=5060
From: “Prod Door” sip:[email protected];tag=320428240
To: sip:[email protected];tag=as040ccf54
Call-ID: 1396090569
CSeq: 21 INVITE
Server: FPBX2.11.0beta3(11.1.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:[email protected]:5060
Content-Type: application/sdp
Content-Length: 313

v=0
o=root 1165129459 1165129459 IN IP4 [FreePbx]
s=Asterisk PBX 11.1.2
c=IN IP4 [FreePbx]
t=0 0
m=audio 7256 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
m=video 0 RTP/AVP 34 102
<------------>
[2013-03-29 22:04:50] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
ACK sip:[email protected][FreePbx]:5060 SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1971181931
From: “Prod Door” sip:[email protected];tag=320428240
To: sip:[email protected];tag=as040ccf54
Call-ID: 1396090569
CSeq: 21 ACK
Contact: sip:[email protected]:5060
Max-Forwards: 70
User-Agent: VoIP Guard
Content-Length: 0

<------------->
[2013-03-29 22:04:50] VERBOSE[2771] chan_sip.c: — (10 headers 0 lines) —
[2013-03-29 22:04:50] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
NOTIFY sip:[email protected][FreePbx] SIP/2.0
Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1289796849
From: “Prod Door” sip:[email protected];tag=899238535
To: sip:[email protected]
Call-ID: 2075904362
CSeq: 20 NOTIFY
Content-Type: application/snomxml
Max-Forwards: 70
User-Agent: VoIP Guard
Content-Length: 235

<?xml version="1.0" encoding="UTF-8"?> 0 0 http://[EntryPhone]/video.jpg http://[EntryPhone]/snom01.xml <-------------> [2013-03-29 22:04:50] VERBOSE[2771] chan_sip.c: --- (10 headers 7 lines) --- [2013-03-29 22:04:50] VERBOSE[2771] chan_sip.c: <--- Transmitting (no NAT) to [EntryPhone]:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP [EntryPhone]:5060;rport;branch=z9hG4bK1289796849;received=[EntryPhone] From: "Prod Door" ;tag=899238535 To: ;tag=as1e37d484 Call-ID: 2075904362 CSeq: 20 NOTIFY Server: FPBX2.11.0beta3(11.1.2) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0

<------------>
[2013-03-29 22:04:50] VERBOSE[2771] chan_sip.c: Scheduling destruction of SIP dialog ‘2075904362’ in 32000 ms (Method: NOTIFY)
[2013-03-29 22:04:55] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
jaK
<------------->
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:1] Macro(“SIP/719-000000c1”, “hangupcall,”) in new stack
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/719-000000c1”, “1?theend”) in new stack
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] pbx.c: – Goto (macro-hangupcall,s,3)
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/719-000000c1”, “0?Set(CDR(recordingfile)=)”) in new stack
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] pbx.c: – Executing [[email protected]:4] Hangup(“SIP/719-000000c1”, “”) in new stack
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/719-000000c1’ in macro ‘hangupcall’
[2013-03-29 22:05:11] VERBOSE[30354][C-0000006d] pbx.c: == Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/719-000000c1’
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/719-000000c1’ in macro ‘dial-one’
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/719-000000c1’ in macro ‘exten-vm’
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] pbx.c: == Spawn extension (from-internal, 704, 2) exited non-zero on ‘SIP/719-000000c1’
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] chan_sip.c: Scheduling destruction of SIP dialog ‘1396090569’ in 6400 ms (Method: ACK)
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] chan_sip.c: set_destination: Parsing sip:[email protected]:5060 for address/port to send to
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] chan_sip.c: set_destination: set destination to [EntryPhone]:5060
[2013-03-29 22:05:13] VERBOSE[30354][C-0000006d] chan_sip.c: Reliably Transmitting (no NAT) to [EntryPhone]:5060:
BYE sip:[email protected][EntryPhone]:5060 SIP/2.0
Via: SIP/2.0/UDP [FreePbx]:5060;branch=z9hG4bK079c25a7;rport
Max-Forwards: 70
From: sip:[email protected];tag=as040ccf54
To: “Prod Door” sip:[email protected];tag=320428240
Call-ID: 1396090569
CSeq: 102 BYE
User-Agent: FPBX2.11.0beta3(11.1.2)
Proxy-Authorization: Digest username=“719”, realm=“asterisk”, algorithm=MD5, uri=“sip:[FreePbx]”, nonce=“56d2e246”, response="4536eb57fed0f593722ad58bfb5500ae"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


[2013-03-29 22:05:13] VERBOSE[2771] chan_sip.c:
<— SIP read from UDP:[EntryPhone]:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP [FreePbx]:5060;branch=z9hG4bK079c25a7;rport=5060
From: sip:[email protected];tag=as040ccf54
To: “Prod Door” sip:[email protected];tag=320428240
Call-ID: 1396090569
CSeq: 102 BYE
User-Agent: VoIP Guard
Content-Length: 0

<------------->
[2013-03-29 22:05:13] VERBOSE[2771] chan_sip.c: — (8 headers 0 lines) —
[2013-03-29 22:05:13] VERBOSE[2771][C-0000006d] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived
[2013-03-29 22:05:13] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘1396090569’ Method: ACK
[2013-03-29 22:05:17] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘1322599030’ Method: NOTIFY
[2013-03-29 22:05:20] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘61629487’ Method: REGISTER
[2013-03-29 22:05:20] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘1530514004’ Method: NOTIFY
[2013-03-29 22:05:20] VERBOSE[2771] chan_sip.c: Really destroying SIP dialog ‘392454681’ Method: NOTIFY

Seems to work OK on a fresh install of Asterisk 11.3 (not that the above was old - only a week or so!)