Slow dial out through PSTN trunk

Asterisk Asterisk Support
1

Hi all, I’m posting this here as I got no answer on the trixbox forum, which leads me to belive the problem might not be in trixbox, but in my asterisk setup.

I just put up my first trixbox setup, 27 polycom phones (mixture of 601’s & 330’s). All working really good, love the trixbox software, but still tweaking setup files and trying to get my head around all the configuration files.

I have a question regarding the long delay I have when placing a call to an outside number, through my Sangoma B600 card. When I dial the number, I get a wait time around 10 to 11 seconds before I get connected and the phone starts ringing. My dial plan is quite simple:

XXXXXXXX
XXXXXXXXXX

(not really figured out how the dial plan works yet, but I figure the above should just let me dial any 6 or 8 digit numbers?)

Could someone shed some light to where I might poke around to get rid of this behaviour?

I’ve been searching other posts for this problem, and I can’t really find anything relevant. I had a look in the Polycom phones, to see if there was some sort of dialplan in them that caused the delay, but even with a cleaned dialplan setting in the phone, it’s giving me a 10 sec delay before I get connected.

I also had a look at the /var/log/asterisk/full log, to see what’s going on. But can’t make heads or tail of most of it.

I notice that at:
[Feb 24 18:25:40] VERBOSE[15368] logger.c: – DAHDI/3-1 answered SIP/210-00000058

there is a 5 or 6 sec wait, then the dial goes thru and the phone starts ringing (mobile).

If anyone could just point me in the right direction, I for one would be very gratefull, to not speak about the girls in admin who give me angry stares nowdays… :wink:

Cheers,

Peter

The full log from initiated call to ring and hang-up is here:

[Feb 24 18:25:36] VERBOSE[3127] logger.c: == Using SIP RTP TOS bits 184
[Feb 24 18:25:36] VERBOSE[3127] logger.c: == Using SIP RTP CoS mark 5
[Feb 24 18:25:36] VERBOSE[3127] logger.c: == Using SIP VRTP TOS bits 136
[Feb 24 18:25:36] VERBOSE[3127] logger.c: == Using SIP VRTP CoS mark 6
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [0124031824@from-internal:1] Macro(“SIP/210-00000058”, “user-callerid,SKIPTTL,”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/210-00000058”, “AMPUSER=210”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/210-00000058”, “0?report”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/210-00000058”, “1?Set(REALCALLERIDNUM=210)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/210-00000058”, “AMPUSER=210”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/210-00000058”, “AMPUSERCIDNAME=Peter”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/210-00000058”, “0?report”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/210-00000058”, “AMPUSERCID=210”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/210-00000058”, “CALLERID(all)=“Peter” <210>”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:9] ExecIf(“SIP/210-00000058”, “0?Set(CHANNEL(language)=)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:10] GotoIf(“SIP/210-00000058”, “1?continue”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Goto (macro-user-callerid,s,19)
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-user-callerid:19] NoOp(“SIP/210-00000058”, “Using CallerID “Peter” <210>”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [0124031824@from-internal:2] Set(“SIP/210-00000058”, “_NODEST=”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [0124031824@from-internal:3] Macro(“SIP/210-00000058”, “record-enable,210,OUT,”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/210-00000058”, “1?check”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Goto (macro-record-enable,s,4)
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/210-00000058”, “recordingcheck,20110224-182537,1298543137.126”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Feb 24 18:25:37] VERBOSE[15368] logger.c: recordingcheck,20110224-182537,1298543137.126: Outbound recording not enabled
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – AGI Script recordingcheck completed, returning 0
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“SIP/210-00000058”, “”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [0124031824@from-internal:4] Macro(“SIP/210-00000058”, “dialout-trunk,1,0124031824,”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/210-00000058”, “DIAL_TRUNK=1”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/210-00000058”, “0?sub-pincheck,s,1”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/210-00000058”, “0?disabletrunk,1”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/210-00000058”, “DIAL_NUMBER=0124031824”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/210-00000058”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/210-00000058”, “OUTBOUND_GROUP=OUT_1”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/210-00000058”, “1?nomax”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Goto (macro-dialout-trunk,s,9)
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/210-00000058”, “0?skipoutcid”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/210-00000058”, “DIAL_TRUNK_OPTIONS=”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/210-00000058”, “outbound-callerid,1”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/210-00000058”, “0?Set(CALLERPRES()=)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/210-00000058”, “0?Set(REALCALLERIDNUM=210)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/210-00000058”, “1?normcid”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Goto (macro-outbound-callerid,s,6)
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/210-00000058”, “USEROUTCID=”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/210-00000058”, “EMERGENCYCID=”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/210-00000058”, “TRUNKOUTCID=”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/210-00000058”, “1?trunkcid”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Goto (macro-outbound-callerid,s,12)
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“SIP/210-00000058”, “0?Set(CALLERID(all)=)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“SIP/210-00000058”, “0?Set(CALLERID(all)=)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/210-00000058”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:12] ExecIf(“SIP/210-00000058”, “0?AGI(fixlocalprefix)”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/210-00000058”, “OUTNUM=0124031824”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/210-00000058”, “custom=DAHDI/g0”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/210-00000058”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^))”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:16] Macro(“SIP/210-00000058”, “dialout-trunk-predial-hook,”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/210-00000058”, “”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:17] GotoIf(“SIP/210-00000058”, “0?bypass,1”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/210-00000058”, “0?customtrunk”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Executing [s@macro-dialout-trunk:19] Dial(“SIP/210-00000058”, “DAHDI/g0/0124031824,300,”) in new stack
[Feb 24 18:25:37] VERBOSE[15368] logger.c: – Called g0/0124031824
[Feb 24 18:25:37] DEBUG[3076] pbx.c: FONALITY: This thread has already held the conlock, skip locking
[Feb 24 18:25:40] VERBOSE[15368] logger.c: – DAHDI/3-1 answered SIP/210-00000058
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/210-00000058”, “hangupcall,”) in new stack
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/210-00000058”, “1?skiprg”) in new stack
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Goto (macro-hangupcall,s,4)
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“SIP/210-00000058”, “1?skipblkvm”) in new stack
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Goto (macro-hangupcall,s,7)
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“SIP/210-00000058”, “1?theend”) in new stack
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Goto (macro-hangupcall,s,9)
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“SIP/210-00000058”, “”) in new stack
[Feb 24 18:25:57] VERBOSE[15368] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/210-00000058’ in macro ‘hangupcall’
[Feb 24 18:25:57] VERBOSE[15368] logger.c: – Hungup ‘DAHDI/3-1’
[Feb 24 18:25:57] VERBOSE[15368] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘SIP/210-00000058’ in macro ‘dialout-trunk’
[Feb 24 18:25:57] VERBOSE[15368] logger.c: == Spawn extension (from-internal, 0124031824, 4) exited non-zero on ‘SIP/210-00000058’

2

The Answer log entry you quote can only happen after Asterisk finishes dialling. Any delays after that are due to the network. The rest of the delay may well be because of not having the right dialplan in the SIP phone. I haven’t looked carefully enough to see whether that might be the case. Note that mobile call do take a long time to set up, as the mobile is not constantly listening, as that would waste battery power.

The fact you are getting answer before the real answer means that either answer supervision isn’t offered by your supplier, or you haven’t configured it properly.

3

One thing you may want to look at is your dial plan on the phones. we had the same issue and we fixed it by creating a dialplan on our phones (not the same phones but the dialplan should work anyway)

we switched to using : (on the phone!! not the PBX)
L:10,S:0,(9[2-9]xxxxxx|9,1[2-9]xx[2-9]xxxxxx|*xx|9,[69]11|[1-8]xx)

which essentially pushes the phone to dial when it has enough numbers to do so.
we actually got this from a website, wish I could remember to give credit but I can’t.

hope that helps.

4

Hi, thank you both very much for your suggestions. I really appreciate it. Today I re-installed trixbox, went through all config files both for trixbox, asterisk and sangoma… but can’t really find anything that sticks out as being the culprit.

I think your suggestions regarding the dial plan on the phone might actually be spot on… however, I don’t completely understand why the phones themselves need a dialplan, when it’s set in the server… I went into one of the phones via the webui (a polycom 601) and replaced the existing dialplan (refurbished phone, so probably the past users settings). I entered the same simple dialplan I have in the server, i.e,

xxxxxxx
xxxxxxxxxx

(with my limited understanding this will allow any number 7 or 10 digits to be passed to the zap trunk… not too concerned about setting any rules at the moment, just need it to work for now while I still try to figure out the best plans for our office.)

In any case, it didn’t change anything, still got the same delay… oh I should mention the delay is about 8 sec for landline numbers and 10 sec for mobile numbers, which kinda makes sense as mobile number do take longer even from a pstn line, just as david55 mentioned.

Am I screwing things up with my extremely simple dialplan you think?
Unfortunately your example dialplan does not work for this country’s dial settings…

Would you mind explaining, just briefly, what the L:10,S:0 mean?

Thanks again,

Peter.

5

The phones need a dialplan to know when the number is complete and it is safe to send the INVITE request.

6

so it’s like a 2 part process? First the phones dial the server, then the server dials the trunk?
What I don’t understand with that, is that asterisk log file starts right when I press the dial switch on the phone…

Peter.