E1 R2 slow dialing

[Chris Deren]

I have an E1 in Mexico configured as following:

!

controller E1 0/0/0

framing NO-CRC4

ds0-group 1 timeslots 1-15,17-31 type r2-digital r2-compelled ani

cas-custom 1

  country telmex use-defaults

  category 2

  answer-signal group-b 1

where an outbound calling seems slow, i.e. 10 seconds before proceeding with the call, debug vpm shows about 150ms delay between each digit being passed, is there a way to speed this up? I realize this E1 CAS R2 is not expected to be as fast as PRI, but this seems quite slow. Any input is appreciated. Debug output:

MX-QROP-DGW001#debug vpm signal

Voice Port Module signaling debugging is enabled

MX-QROP-DGW001#

Jul  5 19:04:43.174: htsp_timer_stop3 htsp_setup_req

Jul  5 19:04:43.174: htsp_process_event: [0/0/0:1(18), R2_Q421_IDLE, E_HTSP_SETUP_REQ]

Jul  5 19:04:43.174: r2_q421_seize(0/0/0:1(18)) E_HTSP_SETUP_REQ DNIS=0018473128277 ANI=4421534000

Jul  5 19:04:43.174: r2_q421_seize(0/0/0:1(18)) Tx SEIZUREvnm_dsp_set_sig_state:[R2 Q.421 0/0/0:1(18)] set signal state = 0x0

Jul  5 19:04:43.174: htsp_timer - 5000 msec

Jul  5 19:04:43.258: htsp_process_event: [0/0/0:1(18), R2_Q421_OG_SEIZE, E_DSP_SIG_1100]

Jul  5 19:04:43.258: r2_q421_seize_ack(0/0/0:1(18)) Rx SEIZE ACK

Jul  5 19:04:43.258: htsp_timer_stop

Jul  5 19:04:43.258: r2_reg_start_dialing(0/0/0:1(18))

Jul  5 19:04:43.258: r2_reg_process_event: [0/0/0:1(18), R2_REG_IDLE, E_R2_REG_START_DIAL(93)]

Jul  5 19:04:43.258: r2_reg_start_dial_delay(0/0/0:1(18)) dialout delay 200

Jul  5 19:04:43.258: r2_reg_timer(0/0/0:1(18)) 200 msec

Jul  5 19:04:43.458: r2_reg_process_event: [0/0/0:1(18), R2_REG_IDLE, E_R2_REG_EVENT_TIMER(86)]

Jul  5 19:04:43.458: r2_reg_start_dial(0/0/0:1(18))

Jul  5 19:04:43.458: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_IDLE R2 Got Event R2_START

Jul  5 19:04:43.458: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:43.458: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '0'

Jul  5 19:04:43.550: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:43.550: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:43.550: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:43.630: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:43.630: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:43.630: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '0'

Jul  5 19:04:43.722: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:43.722: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:43.722: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:43.802: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:43.802: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:43.802: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '1'

Jul  5 19:04:43.894: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:43.894: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:43.894: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:43.970: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:43.970: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:43.970: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '8'

Jul  5 19:04:44.062: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:44.062: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:44.062: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:44.142: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:44.142: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:44.142: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '4'

Jul  5 19:04:44.234: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:44.234: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:44.234: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:44.310: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:44.310: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:44.310: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '7'

Jul  5 19:04:44.402: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:44.402: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:44.402: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:44.494: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:44.494: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:44.494: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '3'

Jul  5 19:04:44.582: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:44.582: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:44.582: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:44.662: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:44.662: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:44.662: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '1'

Jul  5 19:04:44.750: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:44.750: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:44.750: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:44.834: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:44.834: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:44.834: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '2'

Jul  5 19:04:44.922: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:44.922: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:44.922: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:45.002: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:45.002: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:45.002: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '8'

Jul  5 19:04:45.090: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:45.090: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:45.090: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:45.170: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:45.170: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:45.170: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '2'

Jul  5 19:04:45.262: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:45.262: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:45.262: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:45.338: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:45.338: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:45.338: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '7'

Jul  5 19:04:45.430: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:45.430: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:45.430: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:45.510: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:45.510: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:45.510: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '7'

Jul  5 19:04:45.602: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:45.602: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 1

Jul  5 19:04:45.602: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:45.682: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:45.682: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Jul  5 19:04:45.682: r2_restart_timer: timer interdigit outgoing = 24000 ms

Jul  5 19:04:45.802: htsp_dialing_done(0/0/0:1(18))

Jul  5 19:04:50.611: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='3'

Jul  5 19:04:50.611: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_A R2 Got Event 3

Jul  5 19:04:50.611: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:50.763: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:50.763: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_B R2 Got Event R2_TONE_OFF

Jul  5 19:04:50.763: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '2'

Jul  5 19:04:53.251: htsp_digit_ready_up(0/0/0:1(18)): Rx digit='1'

Jul  5 19:04:53.251: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_PROCESS_B R2 Got Event 1

Jul  5 19:04:53.251: r2_reg_generate_digits(0/0/0:1(18)): Tx digit '#'

Jul  5 19:04:53.331: htsp_digit_ready(0/0/0:1(18)): Rx digit='#'

Jul  5 19:04:53.331: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_WAIT_IDLE R2 Got Event R2_TONE_OFF

Jul  5 19:04:53.331: r2_reg_event_proc(0/0/0:1(18)) ADDR_INFO_COLLECTED (DNIS=0018473128216, ANI=4421534900)

Jul  5 19:04:53.331: r2_reg_end_dial(0/0/0:1(18))

Jul  5 19:04:53.331: htsp_process_event: [0/0/0:1(18), R2_Q421_OG_SEIZE_ACK, E_DSP_DIALING_DONE]

Jul  5 19:04:53.331: r2_q421_dial_done(0/0/0:1(18)) E_HTSP_RELEASE_REQ

Jul  5 19:04:53.331: r2_reg_dial_done(0/0/0:1(18))

Jul  5 19:04:53.331: r2_reg_process_event: [0/0/0:1(18), R2_REG_DIALING, E_R2_REG_ADDR_COLLECTED(89)]

Jul  5 19:04:53.331: r2_reg_addr_collected(0/0/0:1(18))

Jul  5 19:04:53.331: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_IDLE R2 Got Event R2_STOP

Jul  5 19:04:53.331: r2_reg_timer(0/0/0:1(18)) 300 msec

Jul  5 19:04:53.631: r2_reg_process_event: [0/0/0:1(18), R2_REG_DIALING, E_R2_REG_EVENT_TIMER(86)]

Jul  5 19:04:53.631: r2_reg_addr_collect_to(0/0/0:1(18))htsp_alert

Jul  5 19:04:53.631: htsp_call_bridged invoked

Jul  5 19:04:53.631: r2_reg_event_proc(0/0/0:1(18)) ALERTING RECEIVED

Jul  5 19:04:53.631: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_IDLE R2 Got Event R2_ALERTING

Jul  5 19:04:53.639: htsp_process_event: [0/0/0:1(18), R2_Q421_OG_SEIZE_ACK, E_HTSP_VOICE_CUT_THROUGH]

Jul  5 19:04:55.811: htsp_timer_stop3

Jul  5 19:04:55.827: htsp_process_event: [0/0/0:1(18), R2_Q421_OG_SEIZE_ACK, E_HTSP_RELEASE_REQ]

Jul  5 19:04:55.827: r2_q421_clr_fwd(0/0/0:1(18)) E_HTSP_RELEASE_REQ

Jul  5 19:04:55.827: r2_reg_channel_disconnected(0/0/0:1(18))

Jul  5 19:04:55.827: r2_q421_clr_fwd(0/0/0:1(18)) Tx CLEAR FWDvnm_dsp_set_sig_state:[R2 Q.421 0/0/0:1(18)] set signal state = 0x8

Jul  5 19:04:55.827: htsp_timer - 1000 msec

Jul  5 19:04:55.827: r2_reg_process_event: [0/0/0:1(18), R2_REG_WAIT_FOR_CONNECT, E_R2_REG_DISCONNECT(91)]

Jul  5 19:04:55.827: r2_reg_disconnect_idle(0/0/0:1(18))

Jul  5 19:04:55.827: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_IDLE R2 Got Event R2_STOP

Jul  5 19:04:55.827: r2_reg_timer_stop(0/0/0:1(18))

Jul  5 19:04:55.919: htsp_process_event: [0/0/0:1(18), R2_Q421_OG_CLR_FWD, E_DSP_SIG_1000]

Jul  5 19:04:55.919: r2_q421_clr_fwd_idle(0/0/0:1(18)) Rx IDLE

Jul  5 19:04:55.919: htsp_timer_stop

Jul  5 19:04:55.919: r2_q421_clr_fwd_idle(0/0/0:1(18)) Tx IDLEvnm_dsp_set_sig_state:[R2 Q.421 0/0/0:1(18)] set signal state = 0x8

Jul  5 19:04:55.919: r2_reg_channel_disconnected(0/0/0:1(18))

Jul  5 19:04:55.919: r2_reg_process_event: [0/0/0:1(18), R2_REG_IDLE, E_R2_REG_DISCONNECT(91)]

Jul  5 19:04:55.919: r2_reg_disconnect_idle(0/0/0:1(18))

Jul  5 19:04:55.919: R2 Outgoing Voice(0/0): DSX (E1 0/0/0:17): STATE: R2_OUT_IDLE R2 Got Event R2_STOP

Jul  5 19:04:55.919: r2_reg_timer_stop(0/0/0:1(18))

Chris

[acampbell]

Hi Chrs,

Not an expert on E1-R2 at all.

But looking at this link:-

http://www.cisco.com/en/US/tech/tk652/tk653/technologies_tech_note09186a00800943c2.shtml

At the bottom of the page it states the following:-

There are three types of interregister signaling:

• R2-Compelled—When a tone-pair is sent from the switch (forward signal), the tones stay on until the remote end responds (sends an ACK) with a pair of tones that signals the switch to turn off the tones. The tones are compelled to stay on until they are turned off.

  
  

• R2-Non-Compelled —The tone-pairs are sent (forward signal) as pulses so they stay on for a short duration. Responses (backward signals) to the switch (Group B) are sent as pulses. There are no Group A signals in non-compelled interregister signaling.

  Note: Most installations use the non-compelled type of interregister signaling.

  
  

• R2-Semi-Compelled—Forward tone-pairs are sent as compelled. Responses (backward signals) to the switch are sent as pulses. It is the same as compelled, except that the backward signals are pulsed instead of continuous.

  
  

Note: Do not use compelled signaling on slow (satellite) links. The call setup time is too large because of distance delays.

Looking at your trace I see that the sizure to siezure ACK takes about 84mS

ACKs to the sent digits is about 88mS

That does seem slow.

May be you could test R2-Non-Compelled

Regards,
Alex.
Please rate useful posts.

[Cristobal Jimenez Priego]

hello Chris,

 I know this was a long time ago

but we just deployed an E1 CAS in Brazil, and are experiencing the same problem

where you able to solve the 10 sec delay?

thanks

[voip7372]

Did you ever figure out what was causing this delay?  I'm seeing the same thing at an office we have in Mexico.  

Overall, it seems like it's taking about 15 seconds before I hear ringback and know the call is actually ringing the far end.

Jun 25 09:20:29.437: r2_restart_timer: timer interdigit outgoing = 24000 ms