We are seeing some wierddialing delays with our trixbox install. Anytime a call is created, internal, external, in an IVR, etc. there is about a 10-15 second delay before we get ringing. Anyone heard of anything like this? Any help is greatly appreciated!
Kory
Yep,
Have you watched the asterisk CLI as it try's to place the call? If not start there.
How many trunks do you have? Happening on all phones? Trixbox version? Why so short on details?
If you have more than one trunk my guess is the call never gets through to the first and you have to wait for it to fail over to the next. Also, chekc that someone didn't change the delay time! By default there is a 4 second delay betweent he last number pushed before asterisk tries to call. This might have been changed.
In the future make sure when submitting you provide more detail about your configuration. This helps us not have to shoot in the dark. Including log files can also help Kepp them to the key parts though!
Thanks Paris
Paris Templin
Quality Computer Consulting for the North Puget Sound, Washington
www.templincomputing.net
Sorry, haven't really posted much to the forums. Lets see to answer the questions:
We have 4 trunks, all standard phone lines form the telco.
It is doing it on all our phones.
We are running Trixbox 2.0.0.
I'll admit, I have not watched the CLI when placing a call. i did try and look at teh logs, but my Trixbox knowledge is pretty limited.
There are only a handful of us in the office, and only 2 of us thet get into the Interface, and neither of us changed the delay....i don;t even know where that setting is..lol.
This whole issue seems like it has been getting worse over the last couple months, lik ethe delay is getting longer. Our box has been very stable for over a year now, and we have not made any changes to it. The wierd thing is it doesn;t do it all the time, but it is about 95% of the time.
Not sure what else to add, I'll throw on a section of the log file from a call.
Thanks again for the assistance!
Kory
Here's the log form a call that had the delay....
Sep 11 14:46:52 DEBUG[26739] acl.c: ##### Testing 4.79.19.59 with 10.101.1.0
Sep 11 14:46:52 DEBUG[26739] chan_sip.c: Target address 4.79.19.59 is not local, substituting externip
Sep 11 14:46:52 DEBUG[26739] chan_sip.c: Allocating new SIP dialog for 6ffabe176b7ab0a515928ac641ba4ab2@4.79.19.59 - NOTIFY (No RTP)
Sep 11 14:47:00 DEBUG[26739] acl.c: ##### Testing 10.101.1.105 with 10.101.1.0
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: Allocating new SIP dialog for 5fc92631-1c65238b-e0d0b6f8@10.101.1.105 - INVITE (With RTP)
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: * SIP extension value: 3 for call 5fc92631-1c65238b-e0d0b6f8@10.101.1.105
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: Setting NAT on RTP to 0
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: Stopping retransmission on '5fc92631-1c65238b-e0d0b6f8@10.101.1.105' of Response 1: Match Found
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: Setting NAT on RTP to 0
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: Checking SIP call limits for device 105
Sep 11 14:47:00 DEBUG[26739] chan_sip.c: build_route: Contact hop:
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Macro'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Expression result is '1'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Macro'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Expression result is '0'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Not taking any branch
Sep 11 14:47:00 DEBUG[16241] pbx.c: Expression result is '0'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Not taking any branch
Sep 11 14:47:00 DEBUG[16241] pbx.c: Function result is '105'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'NoOp'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Function result is '105'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:00 DEBUG[16242] app_queue.c: Device 'SIP/105' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Sep 11 14:47:00 DEBUG[16241] pbx.c: Function result is 'Kory Lorenz'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Expression result is '0'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Not taking any branch
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Function result is '"Kory Lorenz" '
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'NoOp'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Function result is '105'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'Macro'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Function result is '0'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:00 DEBUG[16241] pbx.c: Launching 'AGI'
Sep 11 14:47:08 DEBUG[26739] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Sep 11 14:47:08 DEBUG[26739] acl.c: ##### Testing 10.101.1.116 with 10.101.1.0
Sep 11 14:47:08 DEBUG[26739] chan_sip.c: Stopping retransmission on '4d97d60b076f30f7111dc30c745862d0@10.101.1.9' of Request 102: Match Found
Sep 11 14:47:13 VERBOSE[16241] logger.c: recordingcheck|20080911-144700|1221162420.51: Outbound recording not enabled
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'NoOp'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Macro'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Expression result is '1'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'NoOp'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Function result is ''
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] db.c: Unable to find key '105/emergency_cid' in family 'DEVICE'
Sep 11 14:47:13 DEBUG[16241] func_db.c: DB: DEVICE/105/emergency_cid not found in database.
Sep 11 14:47:13 DEBUG[16241] pbx.c: Function result is ''
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Expression result is '1'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Expression result is '0'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Not taking any branch
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Expression result is '1'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Function result is '"IT21" '
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'NoOp'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Function result is '1'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Expression result is '0'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Not taking any branch
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'AGI'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Function result is 'ZAP/3'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Set'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Expression result is '0'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'GotoIf'
Sep 11 14:47:13 DEBUG[16241] pbx.c: Not taking any branch
Sep 11 14:47:13 DEBUG[16241] pbx.c: Launching 'Dial'
Sep 11 14:47:13 DEBUG[16241] chan_zap.c: Using channel 3
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-14.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable MACRO_DEPTH.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-13.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable custom.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-12.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable OUTNUM.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-11.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-10.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable DIAL_TRUNK.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-9.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable DIAL_NUMBER.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-8.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-7.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable GROUP.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-6.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable MACRO_PRIORITY.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable MACRO_CONTEXT.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable MACRO_EXTEN.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable ARG1.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-15.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-13.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-12.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-11.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-7.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable TRUNKOUTCID.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-6.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable EMERGENCYCID.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-5.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable USEROUTCID.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-4.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable DB_RESULT.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-3.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-outbound-callerid-s-1.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-5.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable ARG2.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-record-enable-s-5.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-record-enable-s-4.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-record-enable-s-1.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-4.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-9.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-8.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-7.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable AMPUSERCIDNAME.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-6.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable AMPUSER.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-5.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-4.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable REALCALLERIDNUM.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-3.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-2.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-user-callerid-s-1.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-3.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-macro-dialout-trunk-s-1.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable ARG4.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable ARG3.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable STACK-from-internal-98166744893-1.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable SIPCALLID.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable SIPUSERAGENT.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable SIPDOMAIN.
Sep 11 14:47:13 DEBUG[16241] channel.c: Not copying variable SIPURI.
Sep 11 14:47:13 DEBUG[16241] chan_zap.c: Dialing 'w8166744893'
Sep 11 14:47:13 DEBUG[16241] chan_zap.c: Deferring dialing...
Sep 11 14:47:13 DEBUG[16258] app_queue.c: Device 'Zap/3' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Sep 11 14:47:13 DEBUG[16259] app_queue.c: Device 'Zap/3' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Sep 11 14:47:14 DEBUG[16241] chan_zap.c: Exception on 22, channel 3
Sep 11 14:47:14 DEBUG[16241] chan_zap.c: Got event Hook Transition Complete(12) on channel 3 (index 0)
Sep 11 14:47:16 DEBUG[16241] chan_zap.c: Exception on 22, channel 3
Sep 11 14:47:16 DEBUG[16241] chan_zap.c: Got event Dial Complete(9) on channel 3 (index 0)
Sep 11 14:47:16 DEBUG[16241] chan_zap.c: Enabled echo cancellation on channel 3
Sep 11 14:47:16 WARNING[16241] chan_zap.c: Unable to request echo training on channel 3
Sep 11 14:47:18 DEBUG[16241] chan_zap.c: Exception on 22, channel 3
Sep 11 14:47:18 DEBUG[16241] chan_zap.c: Got event Dial Complete(9) on channel 3 (index 0)
Sep 11 14:47:18 DEBUG[16241] chan_zap.c: Echo cancellation already on
Sep 11 14:47:18 DEBUG[16241] channel.c: Set channel SIP/105-f30d to read format ulaw
Sep 11 14:47:18 DEBUG[16241] channel.c: Set channel Zap/3-1 to write format ulaw
Sep 11 14:47:18 DEBUG[16241] channel.c: Set channel Zap/3-1 to read format ulaw
Sep 11 14:47:18 DEBUG[16241] channel.c: Set channel SIP/105-f30d to write format ulaw
Sep 11 14:47:18 DEBUG[16241] chan_sip.c: sip_answer(SIP/105-f30d)
Sep 11 14:47:18 DEBUG[16266] app_queue.c: Device 'Zap/3' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Sep 11 14:47:18 DEBUG[16267] app_queue.c: Device 'SIP/105' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Sep 11 14:47:18 DEBUG[16241] rtp.c: Ooh, format changed from unknown to ulaw
Sep 11 14:47:18 DEBUG[26739] chan_sip.c: Stopping retransmission on '5fc92631-1c65238b-e0d0b6f8@10.101.1.105' of Response 2: Match Found
Sep 11 14:47:20 DEBUG[16241] rtp.c: Got RTCP report of 88 bytes
Sep 11 14:47:23 DEBUG[16241] channel.c: Didn't get a frame from channel: SIP/105-f30d
Sep 11 14:47:23 DEBUG[16241] channel.c: Bridge stops bridging channels SIP/105-f30d and Zap/3-1
Sep 11 14:47:23 DEBUG[16241] channel.c: Hanging up channel 'Zap/3-1'
Sep 11 14:47:23 DEBUG[16241] chan_zap.c: zt_hangup(Zap/3-1)
Sep 11 14:47:23 DEBUG[16241] chan_zap.c: Hangup: channel: 3 index = 0, normal = 22, callwait = -1, thirdcall = -1
Sep 11 14:47:23 DEBUG[16241] chan_zap.c: disabled echo cancellation on channel 3
Sep 11 14:47:23 DEBUG[16241] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/3-1
Sep 11 14:47:23 DEBUG[16241] chan_zap.c: Updated conferencing on 3, with 0 conference users
Sep 11 14:47:23 DEBUG[16241] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Sep 11 14:47:23 DEBUG[16241] app_macro.c: Spawn extension (macro-dialout-trunk,s,14) exited non-zero on 'SIP/105-f30d' in macro 'dialout-trunk'
Sep 11 14:47:23 DEBUG[16241] pbx.c: Spawn extension (macro-dialout-trunk,s,14) exited non-zero on 'SIP/105-f30d'
Sep 11 14:47:23 DEBUG[16275] app_queue.c: Device 'Zap/3' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
Sep 11 14:47:23 DEBUG[16241] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Sep 11 14:47:23 DEBUG[16241] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2008-09-11 14:47:00','\"IT21\" ','9133933763','98166744893','from-internal', 'SIP/105-f30d','Zap/3-1','Dial','ZAP/3/w8166744893|120|r',23,5,'ANSWERED',3,'','1221162420.51')
Sep 11 14:47:23 DEBUG[16241] channel.c: Hanging up channel 'SIP/105-f30d'
Sep 11 14:47:23 DEBUG[16241] chan_sip.c: Hangup call SIP/105-f30d, SIP callid 5fc92631-1c65238b-e0d0b6f8@10.101.1.105)
Sep 11 14:47:23 DEBUG[16241] chan_sip.c: update_call_counter(105) - decrement call limit counter
Sep 11 14:47:23 DEBUG[16276] app_queue.c: Device 'SIP/105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Sep 11 14:47:23 DEBUG[16276] app_queue.c: Device 'SIP/105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Well, our problem seems to be gone now. We had been seeing some jitter on some calls also, so we swapped out the sever hardware last night. We transfered the harddrive and our sangoma cards over to the new server, fired it up and both problems dissapeared!
Thanks for the assistance!
Kory
Copyright © 2011 Fonality
Fonality and trixbox are trademarks of Fonality. Trademark Policy. Privacy Policy.
Asterisk is a trademark of Digium, Inc. Fonality and trixbox are not affiliated with, nor endorsed by Digium, Inc.
Member Since:
2006-07-07