SIP phone not ringing when dahdi dial-in from PSTN

JohnnySSH · July 6, 2012, 8:55am

Hi,

I am not quite sure what’s going on here but I have a Polycom IP601 which I have updated the firmware to version 3.1.8 in order to be able to use the ‘new’ secret format for the extension. I also have an OpenVox A400p PCI FXO/FXS card which works fine, and POTS phone which also works fine while using inbound and outbound routes.

My issue is that the Polycom simply won’t ring when a dahdi session is initiated, I can however make outbound calls over the PSTN from the IP601.

This is what I have found from the logs:

[2012-07-06 09:02:34] WARNING[16057] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)

A more complete version of the log is here:

[2012-07-06 09:01:20] ERROR[15961] res_config_ldap.c: Cannot load configuration file: res_ldap.conf
[2012-07-06 09:01:20] NOTICE[15961] res_config_ldap.c: Cannot reload LDAP RealTime driver.
[2012-07-06 09:01:20] VERBOSE[3343] config.c: == Parsing '/etc/asterisk/sip_custom_post.conf': [2012-07-06 09:01:20] VERBOSE[3343] config.c: == Found
[2012-07-06 09:01:20] VERBOSE[15961] loader.c: -- Reloading module 'codec_adpcm.so' (Adaptive Differential PCM Coder/Decoder)
[2012-07-06 09:01:20] VERBOSE[15961] loader.c: -- Reloading module 'app_playback.so' (Sound File Playback Application)
[2012-07-06 09:01:20] VERBOSE[15961] loader.c: -- Reloading module 'codec_g726.so' (ITU G.726-32kbps G726 Transcoder)
[2012-07-06 09:01:20] VERBOSE[15961] loader.c: -- Reloading module 'app_minivm.so' (Mini VoiceMail (A minimal Voicemail e-mail System))
[2012-07-06 09:01:20] WARNING[15961] app_minivm.c: Failed to load configuration file. Module activated with default settings.
[2012-07-06 09:01:20] VERBOSE[3343] netsock2.c: == Using SIP TOS bits 96
[2012-07-06 09:01:20] VERBOSE[3343] netsock2.c: == Using SIP CoS mark 4
[2012-07-06 09:01:20] VERBOSE[3343] config.c: == Parsing '/etc/asterisk/sip_notify.conf': [2012-07-06 09:01:20] VERBOSE[3343] config.c: == Found
[2012-07-06 09:01:20] VERBOSE[3343] config.c: == Parsing '/etc/asterisk/sip_notify_custom.conf': [2012-07-06 09:01:20] VERBOSE[3343] config.c: == Found
[2012-07-06 09:01:20] VERBOSE[3343] config.c: == Parsing '/etc/asterisk/sip_notify_additional.conf': [2012-07-06 09:01:20] VERBOSE[3343] config.c: == Found
[2012-07-06 09:02:29] VERBOSE[16057] sig_analog.c: -- Starting simple switch on 'DAHDI/2-1'
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:1] ExecIf("DAHDI/2-1", "1?Set(__FROM_DID=s)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:2] Gosub("DAHDI/2-1", "app-blacklist-check,s,1()") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/2-1", "0?blacklisted") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@app-blacklist-check:2] Set("DAHDI/2-1", "CALLED_BLACKLIST=1") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@app-blacklist-check:3] Return("DAHDI/2-1", "") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:3] Set("DAHDI/2-1", "CDR(did)=s") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:4] ExecIf("DAHDI/2-1", "1 ?Set(CALLERID(name)=)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:5] Set("DAHDI/2-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:6] Set("DAHDI/2-1", "CALLERPRES()=allowed_not_screened") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@from-pstn:7] Goto("DAHDI/2-1", "ext-group,600,1") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (ext-group,600,1)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:1] Macro("DAHDI/2-1", "user-callerid,") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:1] Set("DAHDI/2-1", "AMPUSER=") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("DAHDI/2-1", "0?report") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("DAHDI/2-1", "1?Set(REALCALLERIDNUM=)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:4] Set("DAHDI/2-1", "AMPUSER=") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:5] Set("DAHDI/2-1", "AMPUSERCIDNAME=") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("DAHDI/2-1", "1?report") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (macro-user-callerid,s,13)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("DAHDI/2-1", "0?continue") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:14] Set("DAHDI/2-1", "__TTL=64") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("DAHDI/2-1", "1?continue") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (macro-user-callerid,s,26)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:26] Set("DAHDI/2-1", "CALLERID(number)=") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:27] Set("DAHDI/2-1", "CALLERID(name)=") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-user-callerid:28] Set("DAHDI/2-1", "CHANNEL(language)=en") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:2] Macro("DAHDI/2-1", "blkvm-setifempty,") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("DAHDI/2-1", "1?init") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (macro-blkvm-setifempty,s,4)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("DAHDI/2-1", "__BLKVM_CHANNEL=DAHDI/2-1") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("DAHDI/2-1", "SHARED(BLKVM,DAHDI/2-1)=TRUE") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("DAHDI/2-1", "GOSUB_RETVAL=TRUE") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("DAHDI/2-1", "") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:3] GotoIf("DAHDI/2-1", "1?skipov") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (ext-group,600,6)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:6] Set("DAHDI/2-1", "RRNODEST=") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:7] Set("DAHDI/2-1", "__NODEST=600") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:8] GosubIf("DAHDI/2-1", "0?sub-rgsetcid,s,1()") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:9] Gosub("DAHDI/2-1", "sub-record-check,s,1(rg,600,dontcare)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("DAHDI/2-1", "1?check") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (sub-record-check,s,6)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:6] Set("DAHDI/2-1", "__MON_FMT=wav") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("DAHDI/2-1", "1?next") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (sub-record-check,s,10)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("DAHDI/2-1", "0?Return()") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("DAHDI/2-1", "0?rg,1") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:12] Set("DAHDI/2-1", "__REC_STATUS=INITIALIZED") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("DAHDI/2-1", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:14] Set("DAHDI/2-1", "NOW=1341561754") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:15] Set("DAHDI/2-1", "__DAY=06") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:16] Set("DAHDI/2-1", "__MONTH=07") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:17] Set("DAHDI/2-1", "__YEAR=2012") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:18] Set("DAHDI/2-1", "__TIMESTR=20120706-090234") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:19] Set("DAHDI/2-1", "__FROMEXTEN=unknown") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:20] Set("DAHDI/2-1", "__CALLFILENAME=rg-600-unknown-20120706-090234-1341561749.71") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@sub-record-check:21] Goto("DAHDI/2-1", "rg,1") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (sub-record-check,rg,1)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [rg@sub-record-check:1] GosubIf("DAHDI/2-1", "0?record,1(rg,dontcare,unknown)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [rg@sub-record-check:2] Return("DAHDI/2-1", "") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:10] Set("DAHDI/2-1", "RingGroupMethod=ringall") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [600@ext-group:11] Macro("DAHDI/2-1", "dial,20,tr,250-260") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-dial:1] GotoIf("DAHDI/2-1", "1?dial") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Goto (macro-dial,s,3)
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-dial:3] AGI("DAHDI/2-1", "dialparties.agi") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Added extension 250 to extension map
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Added extension 260 to extension map
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Extension 250 cf is disabled
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Extension 260 cf is disabled
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Extension 250 do not disturb is disabled
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Extension 260 do not disturb is disabled
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: DbDel CALLTRACE/250 - Caller ID is not defined
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: DbDel CALLTRACE/260 - Caller ID is not defined
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- dialparties.agi: Filtered ARG3: 250-260
[2012-07-06 09:02:34] VERBOSE[16057] res_agi.c: -- <DAHDI/2-1>AGI Script dialparties.agi completed, returning 0
[2012-07-06 09:02:34] VERBOSE[16057] pbx.c: -- Executing [s@macro-dial:7] Dial("DAHDI/2-1", "DAHDI/1&SIP/260,20,trM(auto-blkvm)") in new stack
[2012-07-06 09:02:34] VERBOSE[16057] app_dial.c: -- Called DAHDI/1
[2012-07-06 09:02:34] WARNING[16057] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-07-06 09:02:34] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:35] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:35] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:38] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:38] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:41] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:41] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 is ringing
[2012-07-06 09:02:42] VERBOSE[16057] app_dial.c: -- DAHDI/1-1 answered DAHDI/2-1
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-auto-blkvm:1] Set("DAHDI/1-1", "__MACRO_RESULT=") in new stack
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-auto-blkvm:2] Macro("DAHDI/1-1", "blkvm-clr,") in new stack
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("DAHDI/1-1", "SHARED(BLKVM,DAHDI/2-1)=") in new stack
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("DAHDI/1-1", "GOSUB_RETVAL=") in new stack
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("DAHDI/1-1", "") in new stack
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-auto-blkvm:3] ExecIf("DAHDI/1-1", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=1)") in new stack
[2012-07-06 09:02:42] VERBOSE[16057] pbx.c: -- Executing [s@macro-auto-blkvm:4] ExecIf("DAHDI/1-1", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)") in new stack
[2012-07-06 09:03:31] VERBOSE[16057] pbx.c: -- Executing [h@macro-dial:1] Macro("DAHDI/2-1", "hangupcall") in new stack
[2012-07-06 09:03:31] VERBOSE[16057] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("DAHDI/2-1", "1?theend") in new stack
[2012-07-06 09:03:31] VERBOSE[16057] pbx.c: -- Goto (macro-hangupcall,s,3)
[2012-07-06 09:03:31] VERBOSE[16057] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("DAHDI/2-1", "0?Set(CDR(recordingfile)=)") in new stack
[2012-07-06 09:03:31] VERBOSE[16057] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("DAHDI/2-1", "") in new stack
[2012-07-06 09:03:31] VERBOSE[16057] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'DAHDI/2-1' in macro 'hangupcall'
[2012-07-06 09:03:31] VERBOSE[16057] features.c: == Spawn extension (macro-dial, h, 1) exited non-zero on 'DAHDI/2-1'
[2012-07-06 09:03:31] VERBOSE[16057] sig_analog.c: -- Hanging up on 'DAHDI/1-1'
[2012-07-06 09:03:31] VERBOSE[16057] chan_dahdi.c: -- Hungup 'DAHDI/1-1'
[2012-07-06 09:03:31] VERBOSE[16057] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'DAHDI/2-1' in macro 'dial'
[2012-07-06 09:03:31] VERBOSE[16057] pbx.c: == Spawn extension (ext-group, 600, 11) exited non-zero on 'DAHDI/2-1'
[2012-07-06 09:03:31] VERBOSE[16057] sig_analog.c: -- Hanging up on 'DAHDI/2-1'
[2012-07-06 09:03:31] VERBOSE[16057] chan_dahdi.c: -- Hungup 'DAHDI/2-1'

Can anyone help figure out what is going on?

Thanks.

JohnnySSH · July 7, 2012, 8:19am

Googling this a bit I found probably the best posting on the very limited number of results got:

http://www.thirdlane.com/forum/unable-to-create-channel

which suggested that the phone maybe unavailable.

However, what is odd is that dialing internally works fine??

I will post the extensions config later as currently I’m not in a position to that (no access to server CLI).

Using the web-ui however, I discovered this:

260/260                    172.16.1.2                               D              A  5060     UNREACHABLE

So it is probably the reason…

What could cause this though?

Checking the handset claimed “registered” for both ‘line’ and ‘server’ registrations.

Is there some kind of setting perhaps to activate or change?

system · June 4, 2014, 7:37pm