[cisco-voip] Re: Disconnect of the POTS connection to the CCME upon
phone pick-up
Wes Sisk
wsisk at cisco.com
Thu Jan 19 09:41:51 EST 2006
Router detects power denial incoming from line. Maybe have another talk
with your CO.
//current state=connected, detected incoming event disconnect
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
//disconnect ipphone leg
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
//remote side releases power denial
Jan 15 15:58:56.786: htsp_process_event: [2/1, FXOLS_POWER_DENIAL,
E_HTSP_RELEASE_REQ]fxols_offhook_release
/Wes
Petya Kohts wrote:
> 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