FXO problem: each incoming ring treated as new call.

[Utair Corporation]

IP Phone rings once and call cancelled on each incoming ring.

Started several day ago. I suppose telephone provider changed something in PBX settings. Speaking with them is unproductive, hard to find real specialist.

Any suggestions to try on my side?

samara-lo7-2811#sho run | sect voice-port 0/0/1

input gain -6

cptone RU

timeouts call-disconnect 1

timeouts wait-release 1

timing hookflash-out 300

connection plar 6999

Oct  3 11:44:11.908: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]

Oct  3 11:44:11.908: fxols_ringing_not

Oct  3 11:44:11.908: htsp_timer_stop

Oct  3 11:44:11.908: htsp_timer_stop3 htsp_setup_ind

Oct  3 11:44:11.908: [0/0/1] get_local_station_id calling num= calling name= calling time=10/03 15:44  orig called=

Oct  3 11:44:11.908: TGRM: reg_invoke_tgrm_accept_call(1, TGRM_CALL_VOICE, TGRM_DIRECTION_IN, 0, 0, 1, 65535)

Oct  3 11:44:11.908: TGRM: Calling vtsp_tsp_call_setup_ind().

Oct  3 11:44:11.916: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]

Oct  3 11:44:11.916: fxols_wait_setup_ack:

Oct  3 11:44:11.916: [0/0/1] set signal state = 0xC timestamp = 0

Oct  3 11:44:11.916: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0xC timestamp=0x0fxols_check_auto_call

Oct  3 11:44:11.924: htsp_timer_stop3

Oct  3 11:44:11.924: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc

Oct  3 11:44:11.924: htsp_timer - 120000 msechtsp_setup_req

Oct  3 11:44:11.928: htsp_process_event: [50/0/25.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

Oct  3 11:44:11.928: htsp_ephone_start_caller_id_tx calling num=2670000 calling name = called num=6999 orig called num=

Oct  3 11:44:11.928: [50/0/25.1] set signal state = 0x0 timestamp = 0

Oct  3 11:44:11.928: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x0 timestamp=0x0

Oct  3 11:44:11.928: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:11.928: edsp_soutput: [50/0/25.1] DN=25 chnl=193  StationInsideRing

Oct  3 11:44:11.932: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

Oct  3 11:44:11.944: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert

Oct  3 11:44:12.168: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_DSP_SIG_1100]fxols_offhook_disc

Oct  3 11:44:12.168: htsp_timer2 - 350 msec

Oct  3 11:44:12.520: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER2]fxols_disc_confirm

Oct  3 11:44:12.520: htsp_timer_stop

Oct  3 11:44:12.520: htsp_timer_stop2

Oct  3 11:44:12.520: htsp_timer_stop3

Oct  3 11:44:12.520: htsp_timer_stop3 htsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:12.524: htsp_process_event: [50/0/25.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release

Oct  3 11:44:12.524: [50/0/25.1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:12.524: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:12.524: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:12.524: edsp_soutput: [50/0/25.1] DN=25 chnl=193 StationRingOff

Oct  3 11:44:12.524: TGRM: reg_invoke_tgrm_call_update(50, 0, 25, 65535, 0, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:12.536: edsprm_close_cleanuphtsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:12.540: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release

Oct  3 11:44:12.540: htsp_timer_stop

Oct  3 11:44:12.540: htsp_timer_stop2

Oct  3 11:44:12.540: htsp_timer_stop3

Oct  3 11:44:12.540: [0/0/1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:12.544: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:12.544: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:12.544: htsp_timer - 2000 msec

Oct  3 11:44:12.544: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:12.544: flex_dsprm_close_cleanup

Oct  3 11:44:14.544: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout

Oct  3 11:44:14.544: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:14.544: dsp_req_sig_state: [0/0/1] packet_len=8 channel_id=129 packet_id=40

Oct  3 11:44:14.548: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]

Oct  3 11:44:15.808: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing

Oct  3 11:44:15.808: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_PENDING, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:15.808: htsp_timer - 125 msec

Oct  3 11:44:15.936: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer

Oct  3 11:44:15.936: htsp_timer - 10000 msec

Oct  3 11:44:17.940: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]

Oct  3 11:44:17.940: fxols_ringing_not

Oct  3 11:44:17.940: htsp_timer_stop

Oct  3 11:44:17.940: htsp_timer_stop3 htsp_setup_ind

Oct  3 11:44:17.940: [0/0/1] get_local_station_id calling num= calling name= calling time=10/03 15:44  orig called=

Oct  3 11:44:17.940: TGRM: reg_invoke_tgrm_accept_call(1, TGRM_CALL_VOICE, TGRM_DIRECTION_IN, 0, 0, 1, 65535)

Oct  3 11:44:17.940: TGRM: Calling vtsp_tsp_call_setup_ind().

Oct  3 11:44:17.948: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]

Oct  3 11:44:17.948: fxols_wait_setup_ack:

Oct  3 11:44:17.948: [0/0/1] set signal state = 0xC timestamp = 0

Oct  3 11:44:17.948: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0xC timestamp=0x0fxols_check_auto_call

Oct  3 11:44:17.956: htsp_timer_stop3

Oct  3 11:44:17.956: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc

Oct  3 11:44:17.956: htsp_timer - 120000 msechtsp_setup_req

Oct  3 11:44:17.960: htsp_process_event: [50/0/25.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

Oct  3 11:44:17.960: htsp_ephone_start_caller_id_tx calling num=2670000 calling name = called num=6999 orig called num=

Oct  3 11:44:17.960: [50/0/25.1] set signal state = 0x0 timestamp = 0

Oct  3 11:44:17.960: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x0 timestamp=0x0

Oct  3 11:44:17.960: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:17.960: edsp_soutput: [50/0/25.1] DN=25 chnl=193  StationInsideRing

Oct  3 11:44:17.960: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

Oct  3 11:44:17.972: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert

Oct  3 11:44:18.200: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_DSP_SIG_1100]fxols_offhook_disc

Oct  3 11:44:18.200: htsp_timer2 - 350 msec

Oct  3 11:44:18.552: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER2]fxols_disc_confirm

Oct  3 11:44:18.552: htsp_timer_stop

Oct  3 11:44:18.552: htsp_timer_stop2

Oct  3 11:44:18.552: htsp_timer_stop3

Oct  3 11:44:18.552: htsp_timer_stop3 htsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:18.556: htsp_process_event: [50/0/25.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release

Oct  3 11:44:18.556: [50/0/25.1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:18.556: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:18.556: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:18.556: edsp_soutput: [50/0/25.1] DN=25 chnl=193 StationRingOff

Oct  3 11:44:18.556: TGRM: reg_invoke_tgrm_call_update(50, 0, 25, 65535, 0, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:18.564: edsprm_close_cleanuphtsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:18.572: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release

Oct  3 11:44:18.572: htsp_timer_stop

Oct  3 11:44:18.572: htsp_timer_stop2

Oct  3 11:44:18.572: htsp_timer_stop3

Oct  3 11:44:18.572: [0/0/1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:18.572: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:18.572: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:18.572: htsp_timer - 2000 msec

Oct  3 11:44:18.572: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:18.576: flex_dsprm_close_cleanup

Oct  3 11:44:20.572: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout

Oct  3 11:44:20.572: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:20.572: dsp_req_sig_state: [0/0/1] packet_len=8 channel_id=129 packet_id=40

Oct  3 11:44:20.572: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]

Oct  3 11:44:21.252: htsp_process_event: [50/0/16.1, EFXS_ONHOOK, E_DSP_SIG_1100]efxs_onhook_offhook htsp_setup_ind

Oct  3 11:44:21.252: [50/0/16.1] get_local_station_id calling num=9964495 calling name=Ten I.L calling time=10/03 15:44  orig called=

Oct  3 11:44:21.252: TGRM: reg_invoke_tgrm_accept_call(0, TGRM_CALL_VOICE, TGRM_DIRECTION_IN, 50, 0, 16, 65535)

Oct  3 11:44:21.252: TGRM: Calling vtsp_tsp_call_setup_ind().

Oct  3 11:44:21.256: TGRM: reg_invoke_tgrm_call_update(50, 0, 16, 65535, 0, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:21.264: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.264: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_OPEN_VOICE_CHANNEL

Oct  3 11:44:21.264: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.264: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_ENC_CONFIG 2

Oct  3 11:44:21.264: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_SET_VOICE_PLAYOUT_DELAY

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_ECHO_CANCELLER_CONTROL

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_VOICE_MODE codec=1 vad=0 size=160 edsp_state=0

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_ECHO_CANCELLER_CONTROL

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_SET_GAINS

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_DTMF_MODE

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.268: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_CP_TONE_ON 4 dir 1

Oct  3 11:44:21.268: htsp_process_event: [50/0/16.1, EFXS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]efxs_check_auto_call

Oct  3 11:44:21.604: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.604: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_CP_TONE_OFF

Oct  3 11:44:21.604: htsp_digit_ready(50/0/16.1): digit = 6

Oct  3 11:44:21.604: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:21.604: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_DTMF_MODE

Oct  3 11:44:21.792: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing

Oct  3 11:44:21.792: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_PENDING, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:21.792: htsp_timer - 125 msec

Oct  3 11:44:21.804: htsp_digit_ready(50/0/16.1): digit = 0

Oct  3 11:44:21.920: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer

Oct  3 11:44:21.920: htsp_timer - 10000 msec

Oct  3 11:44:22.004: htsp_digit_ready(50/0/16.1): digit = 2

Oct  3 11:44:22.204: htsp_digit_ready(50/0/16.1): digit = 0

Oct  3 11:44:22.220: htsp_timer_stop3

Oct  3 11:44:22.220: htsp_process_event: [50/0/16.1, EFXS_OFFHOOK, E_HTSP_PROCEEDING]efxs_offhook_proceeding

Oct  3 11:44:22.220: [50/0/16.1] set signal state = 0x8 timestamp = 0

Oct  3 11:44:22.220: edsp_set_sig_state: [50/0/16.1] packet_len=12 channel_id=121 packet_id=39 state=0x8 timestamp=0x0

Oct  3 11:44:22.220: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:22.220: edsp_soutput: [50/0/16.1] DN=16 chnl=121 EFXS_PROCEEDINGhtsp_setup_req

Oct  3 11:44:22.224: htsp_process_event: [50/0/11.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

Oct  3 11:44:22.224: htsp_ephone_start_caller_id_tx calling num=9964495 calling name =Ten I.L called num=6020 orig called num=

Oct  3 11:44:22.224: [50/0/11.1] set signal state = 0x0 timestamp = 0

Oct  3 11:44:22.228: edsp_set_sig_state: [50/0/11.1] packet_len=12 channel_id=81 packet_id=39 state=0x0 timestamp=0x0

Oct  3 11:44:22.228: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:22.228: edsp_soutput: [50/0/11.1] DN=11 chnl=81  StationInsideRing

Oct  3 11:44:22.228: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notifyhtsp_call_feature:feature 25

htsp_call_feature: caller id enable 0x3 call_connected 0

Oct  3 11:44:22.244: htsp_process_event: [50/0/16.1, EFXS_OFFHOOK, E_HTSP_CALLERID_WAITING]

Oct  3 11:44:22.244: efxs_callerid_update

Oct  3 11:44:22.244: efxs_callerid_update process caller_id_string

Oct  3 11:44:22.244: efxs_callerid_update process caller_id_string OK

Oct  3 11:44:22.244: efxs_callerid_update number= [6020] name= [Ryabchikova L.N.]

Oct  3 11:44:22.244: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:22.244: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_CP_TONE_ON 1 dir 1

Oct  3 11:44:23.964: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]

Oct  3 11:44:23.964: fxols_ringing_not

Oct  3 11:44:23.964: htsp_timer_stop

Oct  3 11:44:23.964: htsp_timer_stop3 htsp_setup_ind

Oct  3 11:44:23.964: [0/0/1] get_local_station_id calling num= calling name= calling time=10/03 15:44  orig called=

Oct  3 11:44:23.968: TGRM: reg_invoke_tgrm_accept_call(1, TGRM_CALL_VOICE, TGRM_DIRECTION_IN, 0, 0, 1, 65535)

Oct  3 11:44:23.968: TGRM: Calling vtsp_tsp_call_setup_ind().

Oct  3 11:44:23.972: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]

Oct  3 11:44:23.972: fxols_wait_setup_ack:

Oct  3 11:44:23.972: [0/0/1] set signal state = 0xC timestamp = 0

Oct  3 11:44:23.972: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0xC timestamp=0x0fxols_check_auto_call

Oct  3 11:44:23.980: htsp_timer_stop3

Oct  3 11:44:23.980: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc

Oct  3 11:44:23.980: htsp_timer - 120000 msechtsp_setup_req

Oct  3 11:44:23.984: htsp_process_event: [50/0/25.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

Oct  3 11:44:23.984: htsp_ephone_start_caller_id_tx calling num=2670000 calling name = called num=6999 orig called num=

Oct  3 11:44:23.984: [50/0/25.1] set signal state = 0x0 timestamp = 0

Oct  3 11:44:23.984: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x0 timestamp=0x0

Oct  3 11:44:23.984: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:23.984: edsp_soutput: [50/0/25.1] DN=25 chnl=193  StationInsideRing

Oct  3 11:44:23.988: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

Oct  3 11:44:24.000: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert

Oct  3 11:44:24.224: htsp_process_event: [50/0/11.1, EFXS_WAIT_OFFHOOK, E_DSP_SIG_1100]efxs_waitoff_offhook

Oct  3 11:44:24.224: [50/0/11.1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:24.224: edsp_set_sig_state: [50/0/11.1] packet_len=12 channel_id=81 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:24.224: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.224: edsp_soutput: [50/0/11.1] DN=11 chnl=81 StationRingOff htsp_dial

Oct  3 11:44:24.224: htsp_process_event: [50/0/11.1, EFXS_CONNECT, E_DSP_DIALING_DONE]

Oct  3 11:44:24.224: htsp_call_bridged invoked

Oct  3 11:44:24.228: htsp_call_bridged invoked

Oct  3 11:44:24.228: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.228: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_CP_TONE_OFF

Oct  3 11:44:24.232: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_DSP_SIG_1100]fxols_offhook_disc

Oct  3 11:44:24.232: htsp_timer2 - 350 msec

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_OPEN_VOICE_CHANNEL

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_ENC_CONFIG 2

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_SET_VOICE_PLAYOUT_DELAY

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_ECHO_CANCELLER_CONTROL

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.232: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_VOICE_MODE codec=1 vad=0 size=160 edsp_state=0

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_ECHO_CANCELLER_CONTROL

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81 MSG_RX_SET_GAINS

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_IDLE_MODE

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_ENC_CONFIG 2

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_SET_VOICE_PLAYOUT_DELAY

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_ECHO_CANCELLER_CONTROL

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.236: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_VOICE_MODE codec=1 vad=0 size=160 edsp_state=2

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_ECHO_CANCELLER_CONTROL

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121 MSG_RX_SET_GAINS

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.240: htsp_process_event: [50/0/11.1, EFXS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]efxs_connect_cutthru

Oct  3 11:44:24.240: [50/0/11.1] set signal state = 0x7 timestamp = 0

Oct  3 11:44:24.240: edsp_set_sig_state: [50/0/11.1] packet_len=12 channel_id=81 packet_id=39 state=0x7 timestamp=0x0

Oct  3 11:44:24.240: edsp_soutput: [50/0/11.1] DN=11 chnl=81

Oct  3 11:44:24.240: edsp_soutput: [50/0/11.1] DN=11 chnl=81 EFXS_OPEN_VOICE_PATH count=1

Oct  3 11:44:24.240: htsp_process_event: [50/0/16.1, EFXS_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]efxs_offhook_cutthru

Oct  3 11:44:24.240: [50/0/16.1] set signal state = 0x7 timestamp = 0

Oct  3 11:44:24.240: edsp_set_sig_state: [50/0/16.1] packet_len=12 channel_id=121 packet_id=39 state=0x7 timestamp=0x0

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.240: edsp_soutput: [50/0/16.1] DN=16 chnl=121 EFXS_OPEN_VOICE_PATH count=1htsp_connect: no_offhook 0 call_connected 0

Oct  3 11:44:24.256: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.256: edsp_soutput: [50/0/16.1] DN=16 chnl=121htsp_call_feature:feature 25

htsp_call_feature: caller id enable 0x3 call_connected 1

Oct  3 11:44:24.256: htsp_process_event: [50/0/16.1, EFXS_OFFHOOK, E_HTSP_CONNECT]efxs_offhook_connect

Oct  3 11:44:24.256: [50/0/16.1] set signal state = 0x6 timestamp = 0

Oct  3 11:44:24.256: edsp_set_sig_state: [50/0/16.1] packet_len=12 channel_id=121 packet_id=39 state=0x6 timestamp=0x0

Oct  3 11:44:24.256: edsp_soutput: [50/0/16.1] DN=16 chnl=121

Oct  3 11:44:24.256: edsp_soutput: [50/0/16.1] DN=16 chnl=121 EFXS_RVS_BATTERY

Oct  3 11:44:24.260: htsp_process_event: [50/0/16.1, EFXS_CONNECT, E_HTSP_CALLERID_WAITING]

Oct  3 11:44:24.260: efxs_callerid_update

Oct  3 11:44:24.260: efxs_callerid_update process caller_id_string

Oct  3 11:44:24.260: efxs_callerid_update process caller_id_string OK

Oct  3 11:44:24.260: efxs_callerid_update number= [6020] name= [Ryabchikova L.N.]

Oct  3 11:44:24.584: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER2]fxols_disc_confirm

Oct  3 11:44:24.584: htsp_timer_stop

Oct  3 11:44:24.584: htsp_timer_stop2

Oct  3 11:44:24.584: htsp_timer_stop3

Oct  3 11:44:24.584: htsp_timer_stop3 htsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:24.588: htsp_process_event: [50/0/25.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release

Oct  3 11:44:24.588: [50/0/25.1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:24.588: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:24.588: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:24.588: edsp_soutput: [50/0/25.1] DN=25 chnl=193 StationRingOff

Oct  3 11:44:24.588: TGRM: reg_invoke_tgrm_call_update(50, 0, 25, 65535, 0, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:24.600: edsprm_close_cleanuphtsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:24.604: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release

Oct  3 11:44:24.604: htsp_timer_stop

Oct  3 11:44:24.604: htsp_timer_stop2

Oct  3 11:44:24.604: htsp_timer_stop3

Oct  3 11:44:24.604: [0/0/1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:24.604: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:24.604: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:24.604: htsp_timer - 2000 msec

Oct  3 11:44:24.604: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:24.608: flex_dsprm_close_cleanup

Oct  3 11:44:26.604: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout

Oct  3 11:44:26.604: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:26.604: dsp_req_sig_state: [0/0/1] packet_len=8 channel_id=129 packet_id=40

Oct  3 11:44:26.604: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]

Oct  3 11:44:27.820: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing

Oct  3 11:44:27.820: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_PENDING, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:27.820: htsp_timer - 125 msec

Oct  3 11:44:27.948: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer

Oct  3 11:44:27.948: htsp_timer - 10000 msec

Oct  3 11:44:29.996: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]

Oct  3 11:44:29.996: fxols_ringing_not

Oct  3 11:44:29.996: htsp_timer_stop

Oct  3 11:44:29.996: htsp_timer_stop3 htsp_setup_ind

Oct  3 11:44:29.996: [0/0/1] get_local_station_id calling num= calling name= calling time=10/03 15:44  orig called=

Oct  3 11:44:29.996: TGRM: reg_invoke_tgrm_accept_call(1, TGRM_CALL_VOICE, TGRM_DIRECTION_IN, 0, 0, 1, 65535)

Oct  3 11:44:29.996: TGRM: Calling vtsp_tsp_call_setup_ind().

Oct  3 11:44:30.000: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]

Oct  3 11:44:30.000: fxols_wait_setup_ack:

Oct  3 11:44:30.000: [0/0/1] set signal state = 0xC timestamp = 0

Oct  3 11:44:30.000: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0xC timestamp=0x0fxols_check_auto_call

Oct  3 11:44:30.008: htsp_timer_stop3

Oct  3 11:44:30.008: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc

Oct  3 11:44:30.008: htsp_timer - 120000 msechtsp_setup_req

Oct  3 11:44:30.012: htsp_process_event: [50/0/25.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

Oct  3 11:44:30.012: htsp_ephone_start_caller_id_tx calling num=2670000 calling name = called num=6999 orig called num=

Oct  3 11:44:30.012: [50/0/25.1] set signal state = 0x0 timestamp = 0

Oct  3 11:44:30.012: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x0 timestamp=0x0

Oct  3 11:44:30.012: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:30.012: edsp_soutput: [50/0/25.1] DN=25 chnl=193  StationInsideRing

Oct  3 11:44:30.016: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

Oct  3 11:44:30.028: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert

Oct  3 11:44:30.256: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_DSP_SIG_1100]fxols_offhook_disc

Oct  3 11:44:30.256: htsp_timer2 - 350 msec

Oct  3 11:44:30.608: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER2]fxols_disc_confirm

Oct  3 11:44:30.608: htsp_timer_stop

Oct  3 11:44:30.608: htsp_timer_stop2

Oct  3 11:44:30.608: htsp_timer_stop3

Oct  3 11:44:30.612: htsp_timer_stop3 htsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:30.612: htsp_process_event: [50/0/25.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release

Oct  3 11:44:30.612: [50/0/25.1] set signal state = 0x4 timestamp = 0

Oct  3 11:44:30.612: edsp_set_sig_state: [50/0/25.1] packet_len=12 channel_id=193 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:30.612: edsp_soutput: [50/0/25.1] DN=25 chnl=193

Oct  3 11:44:30.612: edsp_soutput: [50/0/25.1] DN=25 chnl=193 StationRingOff

Oct  3 11:44:30.612: TGRM: reg_invoke_tgrm_call_update(50, 0, 25, 65535, 0, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:30.624: edsprm_close_cleanuphtsp_release_req: cause 16, no_onhook 0

Oct  3 11:44:30.632: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release

Oct  3 11:44:30.632: htsp_timer_stop

Oct  3 11:44:30.632: htsp_timer_stop2

Oct  3 11:44:30.632: htsp_timer_stop3

Oct  3 11:44:30.632: [0/0/1] set signal state = 0x4 timestamp = 0un a

Oct  3 11:44:30.632: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0x4 timestamp=0x0

Oct  3 11:44:30.632: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Oct  3 11:44:30.632: htsp_timer - 2000 msec

Oct  3 11:44:30.632: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Oct  3 11:44:30.636: flex_dsprm_close_cleanupll

[paolo bevilacqua]

Try reloading router and increase a litle the timeouts configured.

[Utair Corporation]

Which timeouts exactly?

[Utair Corporation]

increased call-disconnect and wait-release, shut down and unshut voice port.

didn't help

will try reloading at night

[keitbr]

It sounds like a polarity reversal on the FXO lines.  It is easy enough to test, simply flip the tip/ring lines and see if the problem resolves.

[Utair Corporation]

Is there a software command for that? This is a remote site, i don't have physical access.

[paolo bevilacqua]

There is no command and there is no polarity on loopstart FXO.

You should apply the steps I've indicated to you above.

[Utair Corporation]

Reverting polarity did not help.

[Utair Corporation]

Problem was bad connectivity on operator side. They have fixed contacts and it started to work as usual.