[cisco-voip] Re[2]: Disconnect of the POTS connection to the CCME
upon phone pick-up
Petya Kohts
petya at nigilist.ru
Fri Jan 20 10:36:45 EST 2006
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