[cisco-voip] Re: Disconnect of the POTS connection to the CCME upon
phone pick-up
Wes Sisk
wsisk at cisco.com
Fri Jan 20 17:38:55 EST 2006
looks like the voice port is in the offhook state and then it detects
another instance of ringtone inbound from the CO. I see several issues
on this where the ring voltage was very low coming into the fxo port,
presumably because of a weak driver from the CO or long copper run.
/Wes
Petya Kohts wrote:
> Wes, thanks for interpreting these codes.
> I wish I knew where to learn how to do it myself ;-)
>
> Regarding the problem:
> CO confirmed that they switched my lines somehow (some
> of engineers told me that they are multiplexed into E1 now).
>
> So they switched me once and the problem (dropped incoming
> calls on some phones in hunt-group) was gone.
>
> But another problem came up! My hunt groups stopped working.
> What I mean is that incoming call was routed to every phone
> in hunt group once and then voice-port hung in ring-det state:
>
> moscow>show voice port sum
>
> PORT CH SIG-TYPE ADMIN OPER STATUS STATUS EC
> ========= == ============ ===== ==== ======== ======== ==
> 2/0 -- fxo-ls up dorm idle on-hook y
> 2/1 -- fxo-ls up up ring-det on-hook y
> 2/2 -- fxo-ls up dorm idle on-hook y
> 2/3 -- fxo-ls up dorm idle on-hook y
>
> Instinctively, I've managed to understand that this happens
> when voice port goes into ring-det state and at the same time
> hunting process finishes the iteration through the list.
>
> So I've changed ephone-hunt timeout from 6 seconds to 7 and
> this fixed the problem.
>
> In spite of this I've forced the CO to fix everything and they did!
> So now my hunting groups work even with timeout 6.
>
>
> Still I am seeing strange lines in 'debug vpm all' output, like this:
> 122912: Jan 20 18:25:26.739: [2/1, FXOLS_OFFHOOK, E_DSP_SIG_0000] -> ERROR: INVALID INPUT
>
> Can you tell me what this means?
>
>
> Petya.
>
>
> On Thursday, January 19, 2006, 17:41:51, you wrote:
>
> WS> Router detects power denial incoming from line. Maybe have another talk
> WS> with your CO.
>
> WS> //current state=connected, detected incoming event disconnect
> WS> Jan 15 15:58:56.417: htsp_process_event: [2/1, FXOLS_CONNECT,
> WS> E_DSP_SIG_1100]fxols_offhook_disc
>
> WS> Jan 15 15:58:56.417: htsp_timer2 - 350
> WS> msec
>
> WS> Jan 15 15:58:56.769: htsp_process_event: [2/1, FXOLS_CONNECT,
> WS> E_HTSP_EVENT_TIMER2]fxols_disc_confirm
>
> WS> Jan 15 15:58:56.769:
> WS> htsp_timer_stop
>
> WS> Jan 15 15:58:56.769:
> WS> htsp_timer_stop2
>
> WS> Jan 15 15:58:56.769:
> WS> htsp_timer_stop3
>
> WS> Jan 15 15:58:56.773:
> WS> htsp_timer_stop3
>
> WS> Jan 15 15:58:56.773:
> WS> htsp_timer_stop3
>
>
> WS> //disconnect ipphone leg
> WS> Jan 15 15:58:56.773: htsp_process_event: [50/0/7.1, EFXS_CONNECT,
> WS> E_HTSP_RELEASE_REQ]efxs_connect_disc
>
> WS> Jan 15 15:58:56.777:
> WS> htsp_timer_stop
>
> WS> Jan 15 15:58:56.777: [50/0/7.1] set signal state = 0xC timestamp =
> WS> 0
>
> WS> Jan 15 15:58:56.786: [50/0/7.1] set signal state = 0x4 timestamp =
> WS> 0
>
> WS> Jan 15 15:58:56.786: htsp_timer - 10
> WS> msec
>
>
> WS> //remote side releases power denial
> WS> Jan 15 15:58:56.786: htsp_process_event: [2/1, FXOLS_POWER_DENIAL,
> WS> E_HTSP_RELEASE_REQ]fxols_offhook_release
>
> WS> /Wes
>
> WS> 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