Retransmission timeout - outbound call errors <SOLVED>

garcus · April 8, 2013, 11:42pm

Hoping to get some help from esteemed experts; I am new to IP telephony and am trying to set-up a FreePBX distro. So far, setup of a Digium card with FXO port and installation of the distro itself was cake. After establishing a trunk, and specify outbound plan (and inbound, doesn’t work either), and registering a SIP phone (Nortel 1535), I can’t dial out.

The issue is that the call rings, and can connect, but auto-disconnects. I get the following errors:

WARNING[1810] chan_sip.c: Retransmission timeout reached on transmission 304768-c01a8c0-13c4-45026-4f02-29dd718-4f02 for seqno 2 (Critical Response) – See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
WARNING[1810] chan_sip.c: Hanging up call 304768-c01a8c0-13c4-45026-4f02-29dd718-4f02 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).

I’m port forwarding 5060-5080, and given my limited experience, am at a loss. Are there any obvious solutions to the above retransmission error that I should investigate?

garcus · April 10, 2013, 4:18pm

Removed the NAT, port forwarding rules on pfsense (which the asterisk is behind), and enabled AON.

Inbound calls now work, but there is still a problem. Outbound calls still give me the retransmission timeout after 6400ms. On inbound calls, when I initiate the hangup on the SIP phone, the caller doesn’t receive the hangup, and automagically redials the SIP phone.

Does anyone think this is still a NAT problem?

bksales · April 10, 2013, 10:32pm

public sip trunks, then

on the firewall forward udp ports 5060, 10001-20000 to the internal ip address of your pbx
on the firewall turn off any sip alg or sip transformations in the firewall
either disable or set firewall udp timers to 3 minutes or more
make sure your pbx has a static ip address and in the freepbx sip settings set NAT to yes
turn on NAT on in your firewall
if you have a static public ip address use it with your sip provider instead of registration

garcus · April 11, 2013, 7:38pm

bksales -
Appreciate the help. I’ve tinkered with my pfsense Firewall/NAT some more. Here are some of my observations and comments re: your specific pointers:

I started out with simple port-forwarding rules, for UDP ports 5060, and 10000-20000 to asterisk, but with pfsense, the recommendation was to do manual outbound NAT (AON, static). This got me to receive inbound calls. But I think one-way audio only. Outbound calls still a problem with retransmission timeout at 6400ms.
I am not aware of any sip alg or sip transformations that I can turn off on pfsense. Maybe I’m ignorant here, and I will delve into this potential issue further.
UDP timers have always been disabled.
yes, and yes.
NAT is on in pfsense, with static ports.
I have a dynamic IP address (use a dynamic DNS provider), but am not using a SIP provider. Using a DAHDI trunk to digium FXO card interfaced to POTS.

Perhaps related to item 3 (see here: http://forum.pfsense.org/index.php?;topic=48909.0), I’ve also set my firewall to conservative state table optimization. And I’ve reset states as well.

No luck - I am still getting retransmission timeout of ~6400ms, and inbound calls are succeeding, but with one-way audio (i can hear, but not transmit audio on inbound calls).

I’ll do some work on my own, and provides updates if I get anywhere with this, but in researching this, at least this seems to be a common problem with asterisk behind pfsense.

bksales · April 13, 2013, 4:53am

should have nothing to do with your audio problem as none of the audio streams should be traversing it. so i guess i am missing something in your set up. are all the phones on the local lan or are you using remote phones?

garcus · April 13, 2013, 7:39pm

yeah, I’m not using a public SIP trunk, its POTS. I thought this would be simple, but am not getting something.

Here is the complete asterisk log file:

[2013-04-13 12:19:58] VERBOSE[1800] netsock2.c: == Using SIP VIDEO TOS bits 136
[2013-04-13 12:19:58] VERBOSE[1800] netsock2.c: == Using SIP VIDEO CoS mark 6
[2013-04-13 12:19:58] VERBOSE[1800] netsock2.c: == Using SIP RTP TOS bits 184
[2013-04-13 12:19:58] VERBOSE[1800] netsock2.c: == Using SIP RTP CoS mark 5
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [NXXXXXXXXX@from-internal:1] Macro(“SIP/1001-0000003d”, “user-callerid,LIMIT,”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/1001-0000003d”, “AMPUSER=1001”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/1001-0000003d”, “0?report”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/1001-0000003d”, “1?Set(REALCALLERIDNUM=1001)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:4] Set(“SIP/1001-0000003d”, “AMPUSER=1001”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/1001-0000003d”, “AMPUSERCIDNAME=TestPhone”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/1001-0000003d”, “0?report”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:7] Set(“SIP/1001-0000003d”, “AMPUSERCID=1001”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:8] Set(“SIP/1001-0000003d”, “CALLERID(all)=“TestPhone” <1001>”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:9] GotoIf(“SIP/1001-0000003d”, “0?limit”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:10] ExecIf(“SIP/1001-0000003d”, “1?Set(GROUP(concurrency_limit)=1001)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:11] GosubIf(“SIP/1001-0000003d”, “7?sub-ccss,s,1(from-internal,NXXXXXXXXX)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-ccss:1] ExecIf(“SIP/1001-0000003d”, “0?Return()”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-ccss:2] Set(“SIP/1001-0000003d”, “CCSS_SETUP=TRUE”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-ccss:3] GosubIf(“SIP/1001-0000003d”, “0?monitor_config,1(from-internal,NXXXXXXXXX):monitor_default,1(from-internal,NXXXXXXXXX)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/1001-0000003d”, “0?is_exten”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [monitor_default@sub-ccss:2] StackPop(“SIP/1001-0000003d”, “”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [monitor_default@sub-ccss:3] Return(“SIP/1001-0000003d”, “FALSE”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:12] ExecIf(“SIP/1001-0000003d”, “0?Set(CHANNEL(language)=)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:13] GotoIf(“SIP/1001-0000003d”, “1?continue”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Goto (macro-user-callerid,s,26)
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:26] Set(“SIP/1001-0000003d”, “CALLERID(number)=1001”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:27] Set(“SIP/1001-0000003d”, “CALLERID(name)=TestPhone”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/1001-0000003d”, “CHANNEL(language)=en”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [NXXXXXXXXX@from-internal:2] Set(“SIP/1001-0000003d”, “MOHCLASS=default”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [NXXXXXXXXX@from-internal:3] ExecIf(“SIP/1001-0000003d”, “1?Set(TRUNKCIDOVERRIDE= NYYYYYYYYY)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [NXXXXXXXXX@from-internal:4] Set(“SIP/1001-0000003d”, “_NODEST=”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [NXXXXXXXXX@from-internal:5] Gosub(“SIP/1001-0000003d”, “sub-record-check,s,1(out,NXXXXXXXXX,)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:1] GotoIf(“SIP/1001-0000003d”, “1?check”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Goto (sub-record-check,s,6)
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:6] Set(“SIP/1001-0000003d”, “__MON_FMT=wav”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:7] GotoIf(“SIP/1001-0000003d”, “1?next”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Goto (sub-record-check,s,10)
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:10] ExecIf(“SIP/1001-0000003d”, “0?Return()”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:11] GotoIf(“SIP/1001-0000003d”, “0?out,1”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:12] Set(“SIP/1001-0000003d”, “__REC_STATUS=INITIALIZED”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:13] ExecIf(“SIP/1001-0000003d”, “0?Set(__REC_POLICY_MODE=)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/1001-0000003d”, “NOW=1365880798”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/1001-0000003d”, “__DAY=13”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/1001-0000003d”, “__MONTH=04”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/1001-0000003d”, “__YEAR=2013”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/1001-0000003d”, “__TIMESTR=20130413-121958”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/1001-0000003d”, “__FROMEXTEN=1001”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/1001-0000003d”, “__CALLFILENAME=out-NXXXXXXXXX-1001-20130413-121958-1365880798.119”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-record-check:21] Goto(“SIP/1001-0000003d”, “out,1”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Goto (sub-record-check,out,1)
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [out@sub-record-check:1] ExecIf(“SIP/1001-0000003d”, “1?Set(__REC_POLICY_MODE=dontcare)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [out@sub-record-check:2] GosubIf(“SIP/1001-0000003d”, “0?record,1(exten,NXXXXXXXXX,1001)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [out@sub-record-check:3] Return(“SIP/1001-0000003d”, “”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [NXXXXXXXXX@from-internal:6] Macro(“SIP/1001-0000003d”, “dialout-trunk,2,NXXXXXXXXX,”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/1001-0000003d”, “DIAL_TRUNK=2”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/1001-0000003d”, “0?sub-pincheck,s,1()”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/1001-0000003d”, “0?disabletrunk,1”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/1001-0000003d”, “DIAL_NUMBER=NXXXXXXXXX”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/1001-0000003d”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/1001-0000003d”, “OUTBOUND_GROUP=OUT_2”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/1001-0000003d”, “0?nomax”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:8] GotoIf(“SIP/1001-0000003d”, “0?chanfull”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/1001-0000003d”, “0?skipoutcid”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/1001-0000003d”, “DIAL_TRUNK_OPTIONS=”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/1001-0000003d”, “outbound-callerid,2”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/1001-0000003d”, “0?Set(CALLERPRES()=)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/1001-0000003d”, “0?Set(REALCALLERIDNUM=1001)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/1001-0000003d”, “1?normcid”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Goto (macro-outbound-callerid,s,6)
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/1001-0000003d”, “USEROUTCID= NYYYYYYYYY”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/1001-0000003d”, “EMERGENCYCID=”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/1001-0000003d”, “TRUNKOUTCID=”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/1001-0000003d”, “1?trunkcid”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Goto (macro-outbound-callerid,s,12)
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“SIP/1001-0000003d”, “1?Set(CALLERID(all)=)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“SIP/1001-0000003d”, “1?Set(CALLERID(all)= NYYYYYYYYY)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/1001-0000003d”, “1?Set(CALLERID(all)= NYYYYYYYYY)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/1001-0000003d”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/1001-0000003d”, “1?sub-flp-2,s,1()”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-flp-2:1] ExecIf(“SIP/1001-0000003d”, “0?Set(TARGET_FLP_2=825635)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-flp-2:2] GotoIf(“SIP/1001-0000003d”, “0?match”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@sub-flp-2:3] Return(“SIP/1001-0000003d”, “”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/1001-0000003d”, “OUTNUM=NXXXXXXXXX”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/1001-0000003d”, “custom=DAHDI/4”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/1001-0000003d”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/1001-0000003d”, “0?Set(DIAL_TRUNK_OPTIONS=M(confirm))”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:17] Macro(“SIP/1001-0000003d”, “dialout-trunk-predial-hook,”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/1001-0000003d”, “”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/1001-0000003d”, “0?bypass,1”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/1001-0000003d”, “1?Set(CONNECTEDLINE(num,i)=NXXXXXXXXX)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/1001-0000003d”, “1?Set(CONNECTEDLINE(name,i)=CID:HSUEH)”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/1001-0000003d”, “0?customtrunk”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“SIP/1001-0000003d”, “DAHDI/4/NXXXXXXXXX,300,”) in new stack
[2013-04-13 12:19:58] VERBOSE[27514] app_dial.c: – Called DAHDI/4/NXXXXXXXXX
[2013-04-13 12:20:03] VERBOSE[27514] app_dial.c: – DAHDI/4-1 answered SIP/1001-0000003d
[2013-04-13 12:20:09] WARNING[1800] chan_sip.c: Retransmission timeout reached on transmission 304768-3101000a-13c4-45026-408-6e6b5200-408 for seqno 2 (Critical Response) – See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6400ms with no response
[2013-04-13 12:20:09] WARNING[1800] chan_sip.c: Hanging up call 304768-3101000a-13c4-45026-408-6e6b5200-408 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[2013-04-13 12:20:09] VERBOSE[27514] pbx.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/1001-0000003d”, “hangupcall,”) in new stack
[2013-04-13 12:20:09] VERBOSE[27514] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/1001-0000003d”, “1?theend”) in new stack
[2013-04-13 12:20:09] VERBOSE[27514] pbx.c: – Goto (macro-hangupcall,s,3)
[2013-04-13 12:20:09] VERBOSE[27514] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“SIP/1001-0000003d”, “0?Set(CDR(recordingfile)=)”) in new stack
[2013-04-13 12:20:09] VERBOSE[27514] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“SIP/1001-0000003d”, “”) in new stack
[2013-04-13 12:20:09] VERBOSE[27514] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/1001-0000003d’ in macro ‘hangupcall’
[2013-04-13 12:20:09] VERBOSE[27514] features.c: == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on ‘SIP/1001-0000003d’
[2013-04-13 12:20:10] VERBOSE[27514] sig_analog.c: – Hanging up on ‘DAHDI/4-1’
[2013-04-13 12:20:10] VERBOSE[27514] chan_dahdi.c: – Hungup ‘DAHDI/4-1’
[2013-04-13 12:20:10] VERBOSE[27514] app_macro.c: == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on ‘SIP/1001-0000003d’ in macro ‘dialout-trunk’
[2013-04-13 12:20:10] VERBOSE[27514] pbx.c: == Spawn extension (from-internal, NXXXXXXXXX, 6) exited non-zero on ‘SIP/1001-0000003d’

And here is the packet capture between the PBX and the SIP phone:

12:19:58.722050 IP 10.0.1.49.5060 > 172.16.0.2.5060: UDP, length 952
12:19:58.722317 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 564
12:19:58.729679 IP 10.0.1.49.5060 > 172.16.0.2.5060: UDP, length 435
12:19:58.736232 IP 10.0.1.49.5060 > 172.16.0.2.5060: UDP, length 1117
12:19:58.738357 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 515
12:20:03.500306 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 821
12:20:03.509986 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.529967 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.550036 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.570037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.589962 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.599600 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 821
12:20:03.609961 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.630038 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.650035 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.669964 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.689965 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.710036 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.730037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.749965 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.769963 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.790036 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.799821 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 821
12:20:03.810037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.829966 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.849965 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.870037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.890037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.909964 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.929966 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.950036 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.970038 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:03.989965 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.009966 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.030037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.050037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.069967 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.089966 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.110040 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.130039 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.149969 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.169969 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.190042 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.200239 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 821
12:20:04.210037 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.229969 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.249967 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.270040 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.290038 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.309968 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.329966 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.350041 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.370038 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.389969 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.409967 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.430042 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.450042 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.469970 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.489967 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.510042 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.530039 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.549971 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.569968 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.590041 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.610040 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.629971 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.649968 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.670041 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.690043 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.709971 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.729970 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.750043 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.770041 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.789971 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.809972 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.830043 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.850043 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.869972 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.889970 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.910044 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.930042 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.949972 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.969971 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:04.990043 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.001061 IP 172.16.0.2.5060 > 10.0.1.49.5060: UDP, length 821
12:20:05.010044 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.029973 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.049972 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.070045 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.090044 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.109971 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.129973 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.150043 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172
12:20:05.170045 IP 172.16.0.2.17826 > 10.0.1.49.13006: UDP, length 172

Are there any clues here?

garcus · April 13, 2013, 8:10pm

the pbx (172.16.0.2) is on a different subnet than the phone (10.0.1.49), but the two are bridged by the firewall.

also, i see that there is 1:1 mapping of port 5060, but not the RTP port, which is 17826 > 13006. Btw my phone is setup for audio RTP port of 23000. I changed it to 13000, but it didn’t seem to make a difference.

garcus · April 16, 2013, 3:40am

Stupid mistake - i realized that i did not specify the subnet that the phone is on as an additional subnet in “Asterisk SIP Settings” Did that and now it works. Thanks, and sorry for burning up your time bksales.

SkykingOH · April 15, 2013, 12:15am

Important for anyone reading this. His two networks were not bridged, they were routed.

Bridging is a Layer 2 concept.