[Home]

Summary:ASTERISK-19169: [patch] CallerID send before ring problem detected in chain_dahdi.c
Reporter:Oliveiros Peixoto (cvsup)Labels:patch
Date Opened:2011-04-14 22:47:43Date Closed:
Priority:MajorRegression?No
Status:Open/NewComponents:Channels/chan_dahdi
Versions:Frequency of
Occurrence
Related
Issues:
is related toASTERISK-00235 CallerID not detected.
Environment:Attachments:( 0) bug19124.diff.txt
( 1) rx.raw
( 2) rx.raw
( 3) tracks000.png
( 4) tx.raw
( 5) tx.raw
Description:hi, i am from brasil and much people know about problem of callerid here. After long time i found some issues that i would like report to you. I use Digium DTM410 with converter DTMF->FSK. Some times the callerid work and i found because.


****** ADDITIONAL INFORMATION ******

My chain_dahdi.conf with cidsignalling=dtmf enable.

callerid=asreceived
context=from-pstn
signalling=fxs_ks
;cidstart=polarity
cidsignalling=dtmf
sendcalleridafter=1
rxwink=300              ; Atlas seems to use long (250ms) winks
usecallerid=yes
hidecallerid=no
callwaiting=yes
usecallingpres=yes
callwaitingcallerid=yes
threewaycalling=yes
transfer=yes
canpark=yes
cancallforward=yes
callreturn=yes
echocancel=yes
echocancelwhenbridged=no
faxdetect=incoming
echotraining=800
rxgain=0.0
txgain=0.0
callgroup=1
pickupgroup=1
language=en


received call logs and asterisk not work.

[Apr 15 00:15:47] VERBOSE[5454] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 15 00:15:49] WARNING[5454] chan_dahdi.c: DTMFCID timed out waiting for ring. Exiting simple switch
[Apr 15 00:15:49] VERBOSE[5454] chan_dahdi.c:     -- Hungup 'DAHDI/1-1'
[Apr 15 00:15:52] VERBOSE[5455] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 15 00:15:54] WARNING[5455] chan_dahdi.c: DTMFCID timed out waiting for ring. Exiting simple switch
[Apr 15 00:15:54] VERBOSE[5455] chan_dahdi.c:     -- Hungup 'DAHDI/1-1'
[Apr 15 00:15:57] VERBOSE[5456] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 15 00:15:59] WARNING[5456] chan_dahdi.c: DTMFCID timed out waiting for ring. Exiting simple switch
[Apr 15 00:15:59] VERBOSE[5456] chan_dahdi.c:     -- Hungup 'DAHDI/1-1'






if i comment the line cidsignalling and restart asterisk the callerid works.



[Apr 15 00:04:22] VERBOSE[4767] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 15 00:04:23] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:1] Wait("DAHDI/1-1", "3") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:2] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:3] Gosub("DAHDI/1-1", "app-blacklist-check,s,1") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@app-blacklist-check:2] Set("DAHDI/1-1", "CALLED_BLACKLIST=1") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@app-blacklist-check:3] Return("DAHDI/1-1", "") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:4] ExecIf("DAHDI/1-1", "1 ?Set(CALLERID(name)=13732123272)") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:5] Wait("DAHDI/1-1", "3") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:6] Set("DAHDI/1-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:7] Set("DAHDI/1-1", "CALLERPRES()=allowed_not_screened") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:8] Goto("DAHDI/1-1", "timeconditions,1,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Goto (timeconditions,1,1)
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [1@timeconditions:1] GotoIfTime("DAHDI/1-1", "14:00-18:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [1@timeconditions:2] GotoIfTime("DAHDI/1-1", "08:00-12:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [1@timeconditions:3] Goto("DAHDI/1-1", "ivr-4,s,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Goto (ivr-4,s,1)
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:1] Set("DAHDI/1-1", "MSG=custom/URAAtendimento") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:2] Set("DAHDI/1-1", "LOOPCOUNT=0") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:3] Set("DAHDI/1-1", "__DIR-CONTEXT=") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:4] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-4=") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:5] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-4") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:6] GotoIf("DAHDI/1-1", "0?begin") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:7] Answer("DAHDI/1-1", "") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:8] Wait("DAHDI/1-1", "1") in new stack
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:9] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[Apr 15 00:04:30] VERBOSE[4767] func_timeout.c:     -- Digit timeout set to 3.000
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:10] Set("DAHDI/1-1", "TIMEOUT(response)=2") in new stack
[Apr 15 00:04:30] VERBOSE[4767] func_timeout.c:     -- Response timeout set to 2.000
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:11] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:12] ExecIf("DAHDI/1-1", "1?Background(custom/URAAtendimento)") in new stack
[Apr 15 00:04:30] VERBOSE[4767] file.c:     -- <DAHDI/1-1> Playing 'custom/URAAtendimento.slin' (language 'en')
[Apr 15 00:04:30] WARNING[4767] file.c: Unexpected control subclass '2'
[Apr 15 00:04:41] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:13] WaitExten("DAHDI/1-1", ",") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Timeout on DAHDI/1-1, going to 't'
[Apr 15 00:04:43] WARNING[4767] func_db.c: DB_DELETE requires an argument, DB_DELETE(<family>/<key>)
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [t@ivr-4:1] NoOp("DAHDI/1-1", "Deleting:  ") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [t@ivr-4:2] Set("DAHDI/1-1", "__NODEST=") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [t@ivr-4:3] Goto("DAHDI/1-1", "app-blackhole,hangup,1") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Goto (app-blackhole,hangup,1)
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [hangup@app-blackhole:1] NoOp("DAHDI/1-1", "Blackhole Dest: Hangup") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [hangup@app-blackhole:2] Hangup("DAHDI/1-1", "") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:   == Spawn extension (app-blackhole, hangup, 2) exited non-zero on 'DAHDI/1-1'
[Apr 15 00:04:43] VERBOSE[4767] chan_dahdi.c:     -- Hungup 'DAHDI/1-1'



but the next calls the callerid not work more.


[Apr 15 00:04:22] VERBOSE[4767] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 15 00:04:23] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:1] Wait("DAHDI/1-1", "3") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:2] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:3] Gosub("DAHDI/1-1", "app-blacklist-check,s,1") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@app-blacklist-check:2] Set("DAHDI/1-1", "CALLED_BLACKLIST=1") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@app-blacklist-check:3] Return("DAHDI/1-1", "") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:4] ExecIf("DAHDI/1-1", "1 ?Set(CALLERID(name)=13732123272)") in new stack
[Apr 15 00:04:26] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:5] Wait("DAHDI/1-1", "3") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:6] Set("DAHDI/1-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:7] Set("DAHDI/1-1", "CALLERPRES()=allowed_not_screened") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@from-pstn:8] Goto("DAHDI/1-1", "timeconditions,1,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Goto (timeconditions,1,1)
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [1@timeconditions:1] GotoIfTime("DAHDI/1-1", "14:00-18:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [1@timeconditions:2] GotoIfTime("DAHDI/1-1", "08:00-12:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [1@timeconditions:3] Goto("DAHDI/1-1", "ivr-4,s,1") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Goto (ivr-4,s,1)
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:1] Set("DAHDI/1-1", "MSG=custom/URAAtendimento") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:2] Set("DAHDI/1-1", "LOOPCOUNT=0") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:3] Set("DAHDI/1-1", "__DIR-CONTEXT=") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:4] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-4=") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:5] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-4") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:6] GotoIf("DAHDI/1-1", "0?begin") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:7] Answer("DAHDI/1-1", "") in new stack
[Apr 15 00:04:29] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:8] Wait("DAHDI/1-1", "1") in new stack
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:9] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[Apr 15 00:04:30] VERBOSE[4767] func_timeout.c:     -- Digit timeout set to 3.000
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:10] Set("DAHDI/1-1", "TIMEOUT(response)=2") in new stack
[Apr 15 00:04:30] VERBOSE[4767] func_timeout.c:     -- Response timeout set to 2.000
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:11] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
[Apr 15 00:04:30] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:12] ExecIf("DAHDI/1-1", "1?Background(custom/URAAtendimento)") in new stack
[Apr 15 00:04:30] VERBOSE[4767] file.c:     -- <DAHDI/1-1> Playing 'custom/URAAtendimento.slin' (language 'en')
[Apr 15 00:04:30] WARNING[4767] file.c: Unexpected control subclass '2'
[Apr 15 00:04:41] VERBOSE[4767] pbx.c:     -- Executing [s@ivr-4:13] WaitExten("DAHDI/1-1", ",") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Timeout on DAHDI/1-1, going to 't'
[Apr 15 00:04:43] WARNING[4767] func_db.c: DB_DELETE requires an argument, DB_DELETE(<family>/<key>)
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [t@ivr-4:1] NoOp("DAHDI/1-1", "Deleting:  ") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [t@ivr-4:2] Set("DAHDI/1-1", "__NODEST=") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [t@ivr-4:3] Goto("DAHDI/1-1", "app-blackhole,hangup,1") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Goto (app-blackhole,hangup,1)
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [hangup@app-blackhole:1] NoOp("DAHDI/1-1", "Blackhole Dest: Hangup") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:     -- Executing [hangup@app-blackhole:2] Hangup("DAHDI/1-1", "") in new stack
[Apr 15 00:04:43] VERBOSE[4767] pbx.c:   == Spawn extension (app-blackhole, hangup, 2) exited non-zero on 'DAHDI/1-1'
[Apr 15 00:04:43] VERBOSE[4767] chan_dahdi.c:     -- Hungup 'DAHDI/1-1'


somebody can help to fix this?
Comments:By: Oliveiros Peixoto (cvsup) 2011-04-14 23:02:13

sorry the correct error log of next calls.

[Apr 15 00:05:15] VERBOSE[4774] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 15 00:05:19] NOTICE[4774] chan_dahdi.c: Got event 18 (Ring Begin)...
[Apr 15 00:05:20] NOTICE[4774] chan_dahdi.c: Got event 2 (Ring/Answered)...
[Apr 15 00:05:20] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:1] Wait("DAHDI/1-1", "3") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:2] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:3] Gosub("DAHDI/1-1", "app-blacklist-check,s,1") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@app-blacklist-check:2] Set("DAHDI/1-1", "CALLED_BLACKLIST=1") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@app-blacklist-check:3] Return("DAHDI/1-1", "") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:4] ExecIf("DAHDI/1-1", "1 ?Set(CALLERID(name)=)") in new stack
[Apr 15 00:05:23] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:5] Wait("DAHDI/1-1", "3") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:6] Set("DAHDI/1-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:7] Set("DAHDI/1-1", "CALLERPRES()=allowed_not_screened") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@from-pstn:8] Goto("DAHDI/1-1", "timeconditions,1,1") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Goto (timeconditions,1,1)
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [1@timeconditions:1] GotoIfTime("DAHDI/1-1", "14:00-18:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [1@timeconditions:2] GotoIfTime("DAHDI/1-1", "08:00-12:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [1@timeconditions:3] Goto("DAHDI/1-1", "ivr-4,s,1") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Goto (ivr-4,s,1)
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:1] Set("DAHDI/1-1", "MSG=custom/URAAtendimento") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:2] Set("DAHDI/1-1", "LOOPCOUNT=0") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:3] Set("DAHDI/1-1", "__DIR-CONTEXT=") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:4] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-4=") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:5] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-4") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:6] GotoIf("DAHDI/1-1", "0?begin") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:7] Answer("DAHDI/1-1", "") in new stack
[Apr 15 00:05:26] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:8] Wait("DAHDI/1-1", "1") in new stack
[Apr 15 00:05:27] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:9] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[Apr 15 00:05:27] VERBOSE[4774] func_timeout.c:     -- Digit timeout set to 3.000
[Apr 15 00:05:27] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:10] Set("DAHDI/1-1", "TIMEOUT(response)=2") in new stack
[Apr 15 00:05:27] VERBOSE[4774] func_timeout.c:     -- Response timeout set to 2.000
[Apr 15 00:05:27] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:11] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
[Apr 15 00:05:27] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:12] ExecIf("DAHDI/1-1", "1?Background(custom/URAAtendimento)") in new stack
[Apr 15 00:05:27] VERBOSE[4774] file.c:     -- <DAHDI/1-1> Playing 'custom/URAAtendimento.slin' (language 'en')
[Apr 15 00:05:27] WARNING[4774] file.c: Unexpected control subclass '2'
[Apr 15 00:05:39] VERBOSE[4774] pbx.c:     -- Executing [s@ivr-4:13] WaitExten("DAHDI/1-1", ",") in new stack
[Apr 15 00:05:39] VERBOSE[4774] pbx.c:   == Spawn extension (ivr-4, s, 13) exited non-zero on 'DAHDI/1-1'
[Apr 15 00:05:39] VERBOSE[4774] pbx.c:     -- Executing [h@ivr-4:1] Hangup("DAHDI/1-1", "") in new stack
[Apr 15 00:05:39] VERBOSE[4774] pbx.c:   == Spawn extension (ivr-4, h, 1) exited non-zero on 'DAHDI/1-1'
[Apr 15 00:05:39] VERBOSE[4774] chan_dahdi.c:     -- Hungup 'DAHDI/1-1'
By: Shaun Ruffell (sruffell) 2011-04-15 11:01:16

cvsup: I'm not sure from looking at this output whether you feel that this is definitely in the drivers or not?

Callerid handling is primarily done by chan_dahdi, therefore, unless you tell me otherwise, I'll move this issue to Asterisk/chan_dahdi.
By: Oliveiros Peixoto (cvsup) 2011-04-17 18:17:39

searching in google i found this.
chan_dahdi it appears that the polarity reversal sometimes causes the card to report a 'phantom' ring, which stops the read of the CallerID ( ZAP-171 ). Patch to chan_zap found her http://forums.digium.com/viewtopic.php?p=27484. Somebody can help to apply this patch in chan_dahdi?


By: Alec Davis (alecdavis) 2011-04-18 00:09:27

bug19124.diff.txt compiles but untested.

Disclaimer:
This patch violates coding practice.
.....


By: Oliveiros Peixoto (cvsup) 2011-04-18 07:04:23

This patch work what asterisk version?
By: Oliveiros Peixoto (cvsup) 2011-04-18 14:51:16

After apply this patch callerid not work.

[Apr 18 16:49:27] VERBOSE[24839] chan_dahdi.c:     -- Starting simple switch on 'DAHDI/1-1'
[Apr 18 16:49:31] NOTICE[24839] chan_dahdi.c: Got event 18 (Ring Begin)...
[Apr 18 16:49:32] NOTICE[24839] chan_dahdi.c: Got event 2 (Ring/Answered)...
[Apr 18 16:49:35] WARNING[24839] chan_dahdi.c: CallerID returned with error on channel 'DAHDI/1-1'
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:1] Set("DAHDI/1-1", "__FROM_DID=s") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:2] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:3] Gosub("DAHDI/1-1", "app-blacklist-check,s,1") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@app-blacklist-check:2] Set("DAHDI/1-1", "CALLED_BLACKLIST=1") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@app-blacklist-check:3] Return("DAHDI/1-1", "") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:4] ExecIf("DAHDI/1-1", "1 ?Set(CALLERID(name)=)") in new stack
[Apr 18 16:49:35] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:5] Wait("DAHDI/1-1", "3") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:6] Set("DAHDI/1-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:7] Set("DAHDI/1-1", "CALLERPRES()=allowed_not_screened") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@from-pstn:8] Goto("DAHDI/1-1", "timeconditions,1,1") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Goto (timeconditions,1,1)
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [1@timeconditions:1] GotoIfTime("DAHDI/1-1", "14:00-18:00,mon-fri,1-31,jan-dec?ivr-3,s,1") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Goto (ivr-3,s,1)
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:1] Set("DAHDI/1-1", "MSG=custom/URA-IVR") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:2] Set("DAHDI/1-1", "LOOPCOUNT=0") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:3] Set("DAHDI/1-1", "__DIR-CONTEXT=") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:4] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-3=") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:5] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-3") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:6] GotoIf("DAHDI/1-1", "0?begin") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:7] Answer("DAHDI/1-1", "") in new stack
[Apr 18 16:49:38] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:8] Wait("DAHDI/1-1", "1") in new stack
[Apr 18 16:49:39] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:9] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[Apr 18 16:49:39] VERBOSE[24839] func_timeout.c:     -- Digit timeout set to 3.000
[Apr 18 16:49:39] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:10] Set("DAHDI/1-1", "TIMEOUT(response)=10") in new stack
[Apr 18 16:49:39] VERBOSE[24839] func_timeout.c:     -- Response timeout set to 10.000
[Apr 18 16:49:39] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:11] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
[Apr 18 16:49:39] VERBOSE[24839] pbx.c:     -- Executing [s@ivr-3:12] ExecIf("DAHDI/1-1", "1?Background(custom/URA-IVR)") in new stack
[Apr 18 16:49:39] VERBOSE[24839] file.c:     -- <DAHDI/1-1> Playing 'custom/URA-IVR.slin' (language 'en')
[Apr 18 16:49:44] VERBOSE[24839] pbx.c:     -- Executing [h@ivr-3:1] Hangup("DAHDI/1-1", "") in new stack
[Apr 18 16:49:44] VERBOSE[24839] pbx.c:   == Spawn extension (ivr-3, h, 1) exited non-zero on 'DAHDI/1-1'
By: Shaun Ruffell (sruffell) 2012-01-05 13:51:34.766-0600

Just looking at this again since cvSup mentioned in IRC that with 1.8.7 he is still having this problem. He mentioned that he is going to take some recordings and attach them to the issue.  I moved it from then DAHLIN to then ASTERISK project.
By: Shaun Ruffell (sruffell) 2012-01-05 14:09:06.860-0600

I uploaded tracks000.png which shows tx.raw and rx.raw.  I don't see any evidence of DTMF CID before the first ring in those files.
By: Oliveiros Peixoto (cvsup) 2012-01-05 14:09:08.184-0600

new dahdi_monitor files.
By: Shaun Ruffell (sruffell) 2012-01-05 16:31:48.377-0600

Ok...in my court currently. I'll just try to basically confirm with the latest release of DAHDI that the drivers / hardware are presenting all the necessary information to Asterisk.
By: Shaun Ruffell (sruffell) 2012-01-06 02:54:01.600-0600

Seems to work for me with Asterisk-1.8.7.2 and DAHDI 2.6.0 and the following /etc/asterisk/chan_dahdi.conf

{noformat}
[trunkgroups]

[channels]
usecallerid=yes
cidsignalling=dtmf
cidstart=dtmf
hidecallerid=no
callwaiting=yes
usecallingpres=yes
callwaitingcallerid=yes
threewaycalling=yes
transfer=yes
canpark=yes
cancallforward=yes
callreturn=yes
echocancel=yes
echocancelwhenbridged=yes
rxgain=0.0
txgain=0.0
group=1
callgroup=1
pickupgroup=1
immediate=no

group = 0
callprogress=yes
progzone=us

signalling=fxs_ks
callerid=asreceived
context=from-pstn
channel => 25

signalling=fxs_ks
callerid=asreceived
context=from-pstn
channel => 26

signalling=fxs_ks
callerid=asreceived
context=from-pstn
channel => 27

signalling=fxs_ks
callerid=asreceived
context=from-pstn
channel => 28

context=default
{noformat}


Then using {{./fxstest /dev/dahdi/1 dtmfcid}} to generate the spill (fxstest is in dahdi-tools) I was able to get the following output on the asterisk CLI when debug was set to 1:

{noformat}
[Jan  6 02:30:06] DEBUG[24064]: sig_analog.c:3600 analog_handle_init_event: channel (25) - signali
[Jan  6 02:30:06] DEBUG[24064]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jan  6 02:30:06] DEBUG[24064]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1752 __analog_ss_thread: __analog_ss_thread 25
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2373 __analog_ss_thread: Receiving DTMF cid on channel DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x41 'A' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x41 'A' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x41 'A' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x41 'A' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit 'A'
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '5'
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '5'
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x35 '5' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '5'
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: channel.c:3938 __ast_read: Ignoring answer on an inbound call!
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '1'
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '2'
[Jan  6 02:30:06] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:06] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x31 '1' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '1'
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x32 '2' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit '2'
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: Begin DTMF digit: 0x43 'C' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: Begin DTMF digit: 0x43 'C' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:1585 analog_handle_dtmf: End DTMF digit: 0x43 'C' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: chan_dahdi.c:2026 my_handle_dtmf: End DTMF digit: 0x43 'C' on DAHDI/25-1
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:2407 __analog_ss_thread: CID got digit 'C'
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:3488 analog_exception: analog_exception 25
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:3582 analog_exception: Exception on 9, channel 25
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:2641 __analog_handle_event: __analog_handle_event 25
[Jan  6 02:30:07] DEBUG[26911]: sig_analog.c:2668 __analog_handle_event: Got event ANALOG_EVENT_RINGBEGIN(12) on channel 25 (index 0)
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:3488 analog_exception: analog_exception 25
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:3582 analog_exception: Exception on 9, channel 25
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:2641 __analog_handle_event: __analog_handle_event 25
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:2668 __analog_handle_event: Got event ANALOG_EVENT_RINGOFFHOOK(2) on channel 25 (index 0)
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:3022 __analog_handle_event: Ring detected
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:2422 __analog_ss_thread: CID got string 'A5551212C'
[Jan  6 02:30:09] DEBUG[26911]: sig_analog.c:2424 __analog_ss_thread: CID is '5551212', flags 0
[Jan  6 02:30:09] DEBUG[26911]: pbx.c:4100 pbx_extension_helper: Launching 'WaitForRing'
[Jan  6 02:30:13] DEBUG[26911]: sig_analog.c:3488 analog_exception: analog_exception 25
[Jan  6 02:30:13] DEBUG[26911]: sig_analog.c:3582 analog_exception: Exception on 9, channel 25
Jan  6 02:30:13] DEBUG[26911]: sig_analog.c:2641 __analog_handle_event: __analog_handle_event 25
[Jan  6 02:30:13] DEBUG[26911]: sig_analog.c:2668 __analog_handle_event: Got event ANALOG_EVENT_RINGBEGIN(12) on channel 25 (index 0)
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:3488 analog_exception: analog_exception 25
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:3582 analog_exception: Exception on 9, channel 25
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:2641 __analog_handle_event: __analog_handle_event 25
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:2668 __analog_handle_event: Got event ANALOG_EVENT_RINGOFFHOOK(2) on channel 25 (index 0)
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:3022 __analog_handle_event: Ring detected
[Jan  6 02:30:15] DEBUG[26911]: pbx.c:4100 pbx_extension_helper: Launching 'Answer'
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:1482 analog_answer: analog_answer 25
[Jan  6 02:30:15] DEBUG[26911]: sig_analog.c:1513 analog_answer: Took DAHDI/25-1 off hook
{noformat}

Asterisk properly detected the CID spill and answered the channel.
By: Oliveiros Peixoto (cvsup) 2012-01-06 13:34:39.434-0600

I can confirm that callerid works on my server.

I use Elastix 2.3 beta1 with packages.


dahdi-2.4.1.2-5
asterisk-1.8.7.0-0

but one bug exist, if i set these two options in chan_dahdi.conf, the callerid not work.

busydetect=yes
busycount=3


Thanks Shaun for nice job!
By: Shaun Ruffell (sruffell) 2012-01-06 15:14:53.453-0600

Still looking at this....on my system in the lab busydetect and busycount didn't seem to matter...it worked regardless.  On Oliveiros' system it seemed to only work after the driver was first loaded...then no more ability to record the DTMF digits. Also..there seems to be some sort of polarity reversal or pulse at the beginning of the DTMF even though a polarity reversal isn't supposed to (afaik) be part of the sequence in Brazil.  So I'm still a bit at a loss about what the problem is.
By: Shaun Ruffell (sruffell) 2012-01-10 10:25:23.297-0600

Oliveiros, just one quick question. Are you using the opermode for brazil on your card?  What is the output of {{# cat /sys/module/wctdm24xxp/parameters/opermode}} when the driver is loaded on your system?
By: Oliveiros Peixoto (cvsup) 2012-01-10 11:31:27.106-0600

[root@asterisk ~]# cat /sys/module/wctdm24xxp/parameters/opermode
FCC
[root@asterisk ~]#