проблема с входящими звонками

Добрый день. Имеется астериск 11.9.0. Вот часть dialplan'а:

    [ Context 'incoming' created by 'pbx_ael' ]
  '0446667590' =>   1. Gosub(num_norm,~~s~~,1)                    [pbx_ael]
                    2. Set(REC_FILE=/opt/records/internal/internal_${CALLERID(dnid)}_${CALLERID(num)}_${STRFTIME(${EPOCH},GMT+2,%Y%m%d-%H%M%S)}) [pbx_ael]
                    3. Set(CDR(userField)=<a href="http://${WEB_ADDRESS}/internal/internal_${CALLERID(dnid)}_${CALLERID(num)}_${STRFTIME(${EPOCH},GMT+2,%Y%m%d-%H%M%S)}.mp3">Record</a>) [pbx_ael]
                    4. Set(CDR(accountcode)=1012)                 [pbx_ael]
                    5. Set(monopt=nice -n 19 /usr/local/bin/lame -b 32 --silent "${REC_FILE}.wav" "${REC_FILE}.mp3" && rm -f "${REC_FILE}.wav") [pbx_ael]
                    6. Dial(SIP/501,20,Tt)                        [pbx_ael]
                    7. Hangup()                                   [pbx_ael]

при звонке на номер 0446667560 в консоле вижу :

 == Using SIP RTP CoS mark 5
    -- Executing [0446667590@incoming:1] Gosub("SIP/siplife-0000007b", "num_norm,~~s~~,1") in new stack
    -- Executing [~~s~~@num_norm:1] NoOp("SIP/siplife-0000007b", "631423259") in new stack
    -- Executing [~~s~~@num_norm:2] MSet("SIP/siplife-0000007b", "CALLERIDLEN=9") in new stack
    -- Executing [~~s~~@num_norm:3] GotoIf("SIP/siplife-0000007b", "1?4:5") in new stack
    -- Goto (num_norm,~~s~~,4)
    -- Executing [~~s~~@num_norm:4] Set("SIP/siplife-0000007b", "CALLERID(num)=0631423259") in new stack
    -- Executing [~~s~~@num_norm:5] NoOp("SIP/siplife-0000007b", "Finish if_num_norm_16") in new stack
    -- Executing [~~s~~@num_norm:6] GotoIf("SIP/siplife-0000007b", "0?7:9") in new stack
    -- Goto (num_norm,~~s~~,9)
    -- Executing [~~s~~@num_norm:9] NoOp("SIP/siplife-0000007b", "Finish if_num_norm_17") in new stack
    -- Executing [~~s~~@num_norm:10] GotoIf("SIP/siplife-0000007b", "0?11:13") in new stack
    -- Goto (num_norm,~~s~~,13)
    -- Executing [~~s~~@num_norm:13] NoOp("SIP/siplife-0000007b", "Finish if_num_norm_18") in new stack
    -- Executing [~~s~~@num_norm:14] Return("SIP/siplife-0000007b", "") in new stack
    -- Executing [0446667590@incoming:2] Set("SIP/siplife-0000007b", "REC_FILE=/opt/records/internal/internal_0446667590_0631423259_20150408-101554") in new stack
    -- Executing [0446667590@incoming:3] Set("SIP/siplife-0000007b", "CDR(userField)=<a href="http:///internal/internal_0446667590_0631423259_20150408-101554.mp3">Record</a>") in new stack
    -- Executing [0446667590@incoming:4] Set("SIP/siplife-0000007b", "CDR(accountcode)=1012") in new stack
    -- Executing [0446667590@incoming:5] Set("SIP/siplife-0000007b", "monopt=nice -n 19 /usr/local/bin/lame -b 32 --silent "/opt/records/internal/internal_0446667590_0631423259_20150408-101554.wav" "/opt/records/internal/internal_0446667590_0631423259_20150408-101554.mp3" && rm -f "/opt/records/internal/internal_0442337590_0631423259_20150408-101554.wav"") in new stack
    -- Executing [0446667590@incoming:6] Dial("SIP/siplife-0000007b", "SIP/501,20,Tt") in new stack
  == Using SIP RTP CoS mark 5
    -- Called SIP/501
    -- SIP/501-0000007c is ringing

501й начинает звонить, я слышу в ответ короткие, на другой стороне просто тишина и через 20 секунд в консоле: Nobody picked up in 20000 ms

    -- Executing [0446667590@incoming:7] Hangup("SIP/siplife-0000007b", "") in new stack
  == Spawn extension (incoming, 0446667590, 7) exited non-zero on 'SIP/siplife-0000007b'

Где свернул "не туда"? Подскажите пожалуйста.

sip debug 501 при звонке:

== Using SIP RTP CoS mark 5
Audio is at 8782
Adding codec 100004 (alaw) to SDP
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 10.12.3.12:5060:
INVITE sip:501@10.12.3.12:5060 SIP/2.0
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK42272158;rport
Max-Forwards: 70
From: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
To: <sip:501@10.12.3.12:5060>
Contact: <sip:0631423259@10.12.3.11:5060>
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 11.9.0
Date: Wed, 08 Apr 2015 13:46:32 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 250

v=0
o=root 83441831 83441831 IN IP4 10.12.3.11
s=Asterisk PBX 11.9.0
c=IN IP4 10.12.3.11
t=0 0
m=audio 8782 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
    -- Called SIP/501

<--- SIP read from UDP:10.12.3.12:5060 --->
SIP/2.0 100 Trying
To: <sip:501@10.12.3.12:5060>
From: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK42272158
Server: Linksys/SPA922-6.1.5(a)
Content-Length: 0

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

<--- SIP read from UDP:10.12.3.12:5060 --->
SIP/2.0 180 Ringing
To: <sip:501@10.12.3.12:5060>;tag=310be76fb8b78a4i0
From: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK42272158
Contact: "501" <sip:501@10.12.3.12:5060>
Server: Linksys/SPA922-6.1.5(a)
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---
list_route: hop: <sip:501@10.12.3.12:5060>
    -- SIP/501-00000092 is ringing

<--- SIP read from UDP:10.12.3.12:5060 --->
SIP/2.0 200 OK
To: <sip:501@10.12.3.12:5060>;tag=310be76fb8b78a4i0
From: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK42272158
Contact: "501" <sip:501@10.12.3.12:5060>
Server: Linksys/SPA922-6.1.5(a)
Content-Length: 204
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces
Content-Type: application/sdp

v=0
o=- 1187528 1187528 IN IP4 10.12.3.12
s=-
c=IN IP4 10.12.3.12
t=0 0
m=audio 16434 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv
<------------->
--- (12 headers 11 lines) ---
Found RTP audio format 8
Found RTP audio format 101
Found audio description format PCMA for ID 8
Found audio description format telephone-event for ID 101
Capabilities: us - (ulaw|alaw), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 10.12.3.12:16434
list_route: hop: <sip:501@10.12.3.12:5060>
set_destination: Parsing <sip:501@10.12.3.12:5060> for address/port to send to
set_destination: set destination to 10.12.3.12:5060
Transmitting (NAT) to 10.12.3.12:5060:
ACK sip:501@10.12.3.12:5060 SIP/2.0
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK41563505;rport
Max-Forwards: 70
From: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
To: <sip:501@10.12.3.12:5060>;tag=310be76fb8b78a4i0
Contact: <sip:0631423259@10.12.3.11:5060>
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 11.9.0
Content-Length: 0


---
    -- SIP/501-00000092 answered SIP/siplife-00000091
       > 0x7f6ab4093d10 -- Probation passed - setting RTP source address to 10.12.3.12:16434

<--- SIP read from UDP:10.12.3.12:5060 --->
BYE sip:0631423259@10.12.3.11:5060 SIP/2.0
Via: SIP/2.0/UDP 10.12.3.12:5060;branch=z9hG4bK-a3249497
From: <sip:501@10.12.3.12>;tag=310be76fb8b78a4i0
To: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 101 BYE
Max-Forwards: 70
User-Agent: Linksys/SPA922-6.1.5(a)
Content-Length: 0

<------------->
--- (9 headers 0 lines) ---
Sending to 10.12.3.12:5060 (NAT)
Scheduling destruction of SIP dialog '272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060' in 6400 ms (Method: BYE)

<--- Transmitting (NAT) to 10.12.3.12:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.12.3.12:5060;branch=z9hG4bK-a3249497;received=10.12.3.12;rport=5060
From: <sip:501@10.12.3.12>;tag=310be76fb8b78a4i0
To: <sip:0631423259@10.12.3.11>;tag=as3b2dbd2e
Call-ID: 272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060
CSeq: 101 BYE
Server: Asterisk PBX 11.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
  == Spawn extension (incoming, 0442337590, 6) exited non-zero on 'SIP/siplife-00000091'
[Apr  8 16:46:40] WARNING[1259]: chan_sip.c:4176 retrans_pkt: Retransmission timeout reached on transmission 36587018-DD2A11E4-9872A5FD-C31507F5@212.58.166.46 for seqno 101 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
Really destroying SIP dialog '272fcf68468e6e6b4a1280762e853ded@10.12.3.11:5060' Method: BYE
Reliably Transmitting (NAT) to 10.12.3.12:5060:
OPTIONS sip:501@10.12.3.12:5060 SIP/2.0
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK3c0e9739;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@10.12.3.11>;tag=as6b1087e6
To: <sip:501@10.12.3.12:5060>
Contact: <sip:asterisk@10.12.3.11:5060>
Call-ID: 1784bf675270c1a136a24dbf237411e5@10.12.3.11:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 11.9.0
Date: Wed, 08 Apr 2015 13:46:48 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:10.12.3.12:5060 --->
SIP/2.0 200 OK
To: <sip:501@10.12.3.12:5060>;tag=2e7fe3c7a131da0ci0
From: "asterisk" <sip:asterisk@10.12.3.11>;tag=as6b1087e6
Call-ID: 1784bf675270c1a136a24dbf237411e5@10.12.3.11:5060
CSeq: 102 OPTIONS
Via: SIP/2.0/UDP 10.12.3.11:5060;branch=z9hG4bK3c0e9739
Server: Linksys/SPA922-6.1.5(a)
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces

<------------->
--- (10 headers 0 lines) ---
Really destroying SIP dialog '1784bf675270c1a136a24dbf237411e5@10.12.3.11:5060' Method: OPTIONS