[cisco-voip] RE: Disconnect of the POTS connection to the CCME upon
phone pick-up
Petya Kohts
petya at nigilist.ru
Sun Jan 15 12:07:14 EST 2006
Wes, thanks for support.
Here is the 'debug vpm signal' output when the call was lost
(after less than a second of talk), phone was picked up at 4507
(first phone in ephone-hunt group of two: 4507, 4504):
Jan 15 15:58:53.019: htsp_process_event: [2/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
Jan 15 15:58:53.023: htsp_timer - 125 msec
Jan 15 15:58:53.152: htsp_process_event: [2/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
Jan 15 15:58:53.152: htsp_timer - 10000 msec
Jan 15 15:58:54.073: htsp_process_event: [2/1, FXOLS_RINGING, E_DSP_SIG_0100]
Jan 15 15:58:54.073: fxols_ringing_not
Jan 15 15:58:54.073: htsp_timer_stop
Jan 15 15:58:54.073: htsp_timer_stop3 htsp_setup_ind
Jan 15 15:58:54.073: [2/1] get_local_station_id calling num= calling name= calling time=01/15 18:58 orig called=
Jan 15 15:58:54.085: htsp_process_event: [2/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
Jan 15 15:58:54.085: fxols_wait_setup_ack:
Jan 15 15:58:54.085: htsp_timer - 6000 msec
Jan 15 15:58:54.089: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
Jan 15 15:58:54.097: htsp_timer_stop3 htsp_setup_req
Jan 15 15:58:54.101: htsp_process_event: [50/0/7.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup
Jan 15 15:58:54.105: htsp_ephone_start_caller_id_tx calling num= calling name = called num=A3007A300 orig called num=3007
Jan 15 15:58:54.105: [50/0/7.1] set signal state = 0x0 timestamp = 0
Jan 15 15:58:54.109: efxs_onhook_setup: local target is available
htsp_alerthtsp_alert_notify
Jan 15 15:58:54.117: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert
Jan 15 15:58:56.096: htsp_process_event: [50/0/7.1, EFXS_WAIT_OFFHOOK, E_DSP_SIG_1100]efxs_waitoff_offhook
Jan 15 15:58:56.096: [50/0/7.1] set signal state = 0x4 timestamp = 0 htsp_dial
Jan 15 15:58:56.100: htsp_process_event: [50/0/7.1, EFXS_CONNECT, E_DSP_DIALING_DONE]
Jan 15 15:58:56.108: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_VOICE_CUT_THROUGH]fxols_proc_voice
Jan 15 15:58:56.112: htsp_process_event: [50/0/7.1, EFXS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]efxs_connect_cutthru
Jan 15 15:58:56.112: [50/0/7.1] set signal state = 0x7 timestamp = 0htsp_call_feature:feature 24
htsp_call_feature: caller id enable 0x3 call_connected 1
Jan 15 15:58:56.116: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_CONNECT]fxols_offhook_connect
Jan 15 15:58:56.116: [2/1] set signal state = 0xC timestamp = 0
Jan 15 15:58:56.116: htsp_timer_stop
Jan 15 15:58:56.116: htsp_process_event: [50/0/7.1, EFXS_CONNECT, E_HTSP_CALLERID_WAITING]
Jan 15 15:58:56.120: efxs_callerid_update
Jan 15 15:58:56.120: efxs_callerid_update process caller_id_string
Jan 15 15:58:56.120: efxs_callerid_update process caller_id_string OK
Jan 15 15:58:56.120: efxs_callerid_update number= [] name= []
Jan 15 15:58:56.417: htsp_process_event: [2/1, FXOLS_CONNECT, E_DSP_SIG_1100]fxols_offhook_disc
Jan 15 15:58:56.417: htsp_timer2 - 350 msec
Jan 15 15:58:56.769: htsp_process_event: [2/1, FXOLS_CONNECT, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
Jan 15 15:58:56.769: htsp_timer_stop
Jan 15 15:58:56.769: htsp_timer_stop2
Jan 15 15:58:56.769: htsp_timer_stop3
Jan 15 15:58:56.773: htsp_timer_stop3
Jan 15 15:58:56.773: htsp_timer_stop3
Jan 15 15:58:56.773: htsp_process_event: [50/0/7.1, EFXS_CONNECT, E_HTSP_RELEASE_REQ]efxs_connect_disc
Jan 15 15:58:56.777: htsp_timer_stop
Jan 15 15:58:56.777: [50/0/7.1] set signal state = 0xC timestamp = 0
Jan 15 15:58:56.786: [50/0/7.1] set signal state = 0x4 timestamp = 0
Jan 15 15:58:56.786: htsp_timer - 10 msec
Jan 15 15:58:56.786: htsp_process_event: [2/1, FXOLS_POWER_DENIAL, E_HTSP_RELEASE_REQ]fxols_offhook_release
Jan 15 15:58:56.786: htsp_timer_stop
Jan 15 15:58:56.786: htsp_timer_stop2
Jan 15 15:58:56.786: htsp_timer_stop3
Jan 15 15:58:56.790: [2/1] set signal state = 0x4 timestamp = 0
Jan 15 15:58:56.790: htsp_timer - 2000 msec
Jan 15 15:58:56.802: htsp_process_event: [50/0/7.1, EFXS_CPC, E_HTSP_EVENT_TIMER]efxs_cpc_timer
Jan 15 15:58:56.802: htsp_timer - 30000 msec
Jan 15 15:58:56.806: htsp_process_event: [50/0/7.1, EFXS_WAIT_ONHOOK, E_DSP_SIG_0100]efxs_waitonhook_onhook
Jan 15 15:58:56.806: htsp_timer_stop htsp_report_onhook_sig
Jan 15 15:58:58.793: htsp_process_event: [2/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
Jan 15 15:58:58.821: htsp_process_event: [2/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
Here is the 'debug vpm signal' output when the call was NOT lost
(talked about 10 seconds), phone was picked up at 4504
(second phone in ephone-hunt group of two: 4507, 4504):
Jan 15 16:20:51.104: htsp_process_event: [2/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
Jan 15 16:20:51.108: htsp_timer - 125 msec
Jan 15 16:20:51.232: htsp_process_event: [2/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
Jan 15 16:20:51.232: htsp_timer - 10000 msec
Jan 15 16:20:52.097: htsp_process_event: [2/1, FXOLS_RINGING, E_DSP_SIG_0100]
Jan 15 16:20:52.097: fxols_ringing_not
Jan 15 16:20:52.097: htsp_timer_stop
Jan 15 16:20:52.097: htsp_timer_stop3 htsp_setup_ind
Jan 15 16:20:52.097: [2/1] get_local_station_id calling num= calling name= calling time=01/15 19:20 orig called=
Jan 15 16:20:52.109: htsp_process_event: [2/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
Jan 15 16:20:52.109: fxols_wait_setup_ack:
Jan 15 16:20:52.109: htsp_timer - 6000 msec
Jan 15 16:20:52.113: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
Jan 15 16:20:52.121: htsp_timer_stop3 htsp_setup_req
Jan 15 16:20:52.125: htsp_process_event: [50/0/7.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup
Jan 15 16:20:52.129: htsp_ephone_start_caller_id_tx calling num= calling name = called num=A3007A300 orig called num=3007
Jan 15 16:20:52.129: [50/0/7.1] set signal state = 0x0 timestamp = 0
Jan 15 16:20:52.133: efxs_onhook_setup: local target is available
htsp_alerthtsp_alert_notify
Jan 15 16:20:52.141: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert
Jan 15 16:20:56.032: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
Jan 15 16:20:56.032: htsp_timer_stop
Jan 15 16:20:56.032: htsp_timer_stop2
Jan 15 16:20:57.114: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
Jan 15 16:20:57.114: htsp_timer_stop2
Jan 15 16:20:57.114: htsp_timer - 6000 msec
Jan 15 16:20:58.139: htsp_timer_stop3
Jan 15 16:20:58.139: htsp_process_event: [50/0/7.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release
Jan 15 16:20:58.139: [50/0/7.1] set signal state = 0x4 timestamp = 0
Jan 15 16:20:58.151: htsp_timer_stop3 htsp_setup_req
Jan 15 16:20:58.155: htsp_process_event: [50/0/4.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup
Jan 15 16:20:58.159: htsp_ephone_start_caller_id_tx calling num= calling name = called num=A3007A301 orig called num=3007
Jan 15 16:20:58.163: [50/0/4.1] set signal state = 0x0 timestamp = 0
Jan 15 16:20:58.167: efxs_onhook_setup: local target is available
htsp_alert
Jan 15 16:20:59.882: htsp_process_event: [50/0/4.1, EFXS_WAIT_OFFHOOK, E_DSP_SIG_1100]efxs_waitoff_offhook
Jan 15 16:20:59.882: [50/0/4.1] set signal state = 0x4 timestamp = 0 htsp_dial
Jan 15 16:20:59.882: htsp_process_event: [50/0/4.1, EFXS_CONNECT, E_DSP_DIALING_DONE]
Jan 15 16:20:59.894: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_VOICE_CUT_THROUGH]fxols_proc_voice
Jan 15 16:20:59.894: htsp_process_event: [50/0/4.1, EFXS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]efxs_connect_cutthru
Jan 15 16:20:59.894: [50/0/4.1] set signal state = 0x7 timestamp = 0htsp_call_feature:feature 24
htsp_call_feature: caller id enable 0x3 call_connected 1
Jan 15 16:20:59.898: htsp_process_event: [2/1, FXOLS_PROCEEDING, E_HTSP_CONNECT]fxols_offhook_connect
Jan 15 16:20:59.898: [2/1] set signal state = 0xC timestamp = 0
Jan 15 16:20:59.898: htsp_timer_stop
Jan 15 16:20:59.898: htsp_process_event: [50/0/4.1, EFXS_CONNECT, E_HTSP_CALLERID_WAITING]
Jan 15 16:20:59.902: efxs_callerid_update
Jan 15 16:20:59.902: efxs_callerid_update process caller_id_string
Jan 15 16:20:59.902: efxs_callerid_update process caller_id_string OK
Jan 15 16:20:59.902: efxs_callerid_update number= [] name= []
Jan 15 16:21:15.319: htsp_process_event: [50/0/4.1, EFXS_CONNECT, E_DSP_SIG_0100]efxs_offhook_onhook
Jan 15 16:21:15.323: htsp_timer - 10 msec
Jan 15 16:21:15.335: htsp_process_event: [50/0/4.1, EFXS_CONNECT, E_HTSP_EVENT_TIMER]efxs_connect_wait_release_req
Jan 15 16:21:15.335: htsp_timer_stop
Jan 15 16:21:15.339: htsp_timer_stop3
Jan 15 16:21:15.339: htsp_timer_stop3
Jan 15 16:21:15.339: htsp_process_event: [50/0/4.1, EFXS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]efxs_waitrls_req_rlshtsp_report_onhook_sig
Jan 15 16:21:15.367: htsp_process_event: [2/1, FXOLS_CONNECT, E_HTSP_RELEASE_REQ]fxols_offhook_release
Jan 15 16:21:15.367: htsp_timer_stop
Jan 15 16:21:15.367: htsp_timer_stop2
Jan 15 16:21:15.367: htsp_timer_stop3
Jan 15 16:21:15.367: [2/1] set signal state = 0x4 timestamp = 0
Jan 15 16:21:15.371: htsp_timer - 2000 msec
Jan 15 16:21:17.375: htsp_process_event: [2/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
Jan 15 16:21:17.379: htsp_process_event: [2/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
On Saturday, January 14, 2006, 21:19:31 you wrote:
WS> the fxo port answers and immediately goes into power denial
WS> 194618.382 (FXOLS_CONNECT, E_HTSP_EVENT_TIMER2) ->
WS> 194618.398 (FXOLS_POWER_DENIAL, E_HTSP_RELEASE_REQ) ->
WS> i'm not sure if the router initiates power denial or detects power
WS> denial incoming from the PSTN.
WS> can you grab a 'debug vpm signal' from the fxo port. good comparison:
WS> On Jan 12, 2006, at 12:41 PM, Petya Kohts wrote:
WS> Hello.
WS> I'm experiencing problems with answering incoming calls
WS> received to Cisco 1760 with VIC2-4FXO.
WS> The error script is:
WS> - someone calls to the office
WS> - user picks up the phone (IP Phone 7905G)
WS> - there's a little period of time (maybe half of a second)
WS> when user hears the calling side
WS> - IP phone goes on-hook (without user putting the receiver
WS> to the base)
WS> - calling side hears busy tone
WS> I'm not sure but this may depend of ephone-hunt groups, because
WS> if I pick-up the first phone in the hunt group then line disconnects
WS> (almost always but not always), if I pick-up the second phone
WS> in the hunt group the line stays (almost always but not always)!
WS> Here is the output of "show voice trace" when picking up the 1st
WS> phone in the hunt group:
WS> 2/1 State Transitions: timestamp (state, event) -> (state, event) ...
WS> 194615.790 (FXOLS_RINGING, E_DSP_SIG_0100) ->
WS> 194615.802 (FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK) ->
WS> 194615.806 (FXOLS_PROCEEDING, E_HTSP_PROCEEDING) ->
WS> 194615.838 (FXOLS_PROCEEDING, E_HTSP_ALERT) ->
WS> 194617.733 (FXOLS_PROCEEDING, E_HTSP_VOICE_CUT_THROUGH) ->
WS> 194617.737 (FXOLS_PROCEEDING, E_HTSP_CONNECT) ->
WS> 194618.029 (FXOLS_CONNECT, E_DSP_SIG_1100) ->
WS> 194618.382 (FXOLS_CONNECT, E_HTSP_EVENT_TIMER2) ->
WS> 194618.398 (FXOLS_POWER_DENIAL, E_HTSP_RELEASE_REQ) ->
WS> 194620.401 (FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER) ->
WS> 194620.401 (FXOLS_ONHOOK, E_DSP_SIG_0100) ->
WS> Here is the output of "show voice trace" when picking up the 2nd
WS> phone in the hunt group (talked 2 seconds):
WS> 2/1 State Transitions: timestamp (state, event) -> (state, event) ...
WS> 194799.130 (FXOLS_RINGING, E_DSP_SIG_0100) ->
WS> 194799.142 (FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK) ->
WS> 194799.146 (FXOLS_PROCEEDING, E_HTSP_PROCEEDING) ->
WS> 194799.182 (FXOLS_PROCEEDING, E_HTSP_ALERT) ->
WS> 194803.049 (FXOLS_PROCEEDING, E_DSP_SIG_0000) ->
WS> 194804.131 (FXOLS_PROCEEDING, E_DSP_SIG_0100) ->
WS> 194807.039 (FXOLS_PROCEEDING, E_HTSP_VOICE_CUT_THROUGH) ->
WS> 194807.047 (FXOLS_PROCEEDING, E_HTSP_CONNECT) ->
WS> 194811.138 (FXOLS_CONNECT, E_HTSP_RELEASE_REQ) ->
WS> 194813.137 (FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER) ->
WS> 194813.153 (FXOLS_ONHOOK, E_DSP_SIG_0100) ->
WS> Another thing I'd like to specify: I had a talk with provider
WS> day before yesterday and they admitted that they had changed
WS> the configuration and there might be something wrong with
WS> the new one. Since then they have been trying to figure out
WS> what's wrong but there are no results still.
WS> Can anyone give me some shortcut, some keywords to read about
WS> or just explain me what's happening?
WS> Regards,
WS> Petya.
WS> _______________________________________________
WS> cisco-voip mailing list
WS> cisco-voip at puck.nether.net
WS> https://puck.nether.net/mailman/listinfo/cisco-voip
More information about the cisco-voip
mailing list