UC560 Caller ID "reset" problem

[Michael Murray]

Gang,

I have a strange issue that I need help with. I have a UC560 installed with (5) Centrex lines from the carrier. When an outside call comes in the following happens:

1. The phone (7962) rings with the caller ID displayed.

2. After approx 3 seconds of ringing the phone stops ringing and the display goes blank as if the call was dropped. However, on the calling party phone the call continues to ring.

3. After another 5 seconds the 7962 phone in the office starts ringing again and you can answer the call as you normally would. The caller ID is gone though and the display just shows "Unknown Caller".

My guess is that the caller ID information being sent from the carrier is somehow changed after the first few seconds of the ringing. This is causing the UC560 to reinitialize the call setup I think.

I was able to workaround this issue by setting "caller-id alerting ring 2" but this delays the call from coming in and customers are complaining it takes too long for someone to answer.

My next step is to call the carrier and see if this is something they have configured on their end.

Has anyone seen this before?

Thanks,

-mike

[paolo bevilacqua]

Possibly a long pause between rings makes the system believe the call hasended before answering. Then when rings resume again, it is treated as a new call, but caller-id information is lost. To confirm that you can take "debug vppm signal" with :term mon". In that case do not enable other debugs, and do not use attachments to post.

Indipendetnly from the above, you can configure 'immediate' in plar command to have phones ring immediately without waiting for caller-id. However with that setting if the call is answered before caller0id is displayed, then caller-id will not show.

Aslo recommended, update UC500 software and check again.

[yahsiel2004]

Like Paolo mentioned try the following under the fxo ports:

connectin plar opx "extension number"

[Michael Murray]

Paolo,

Thanks for the input. There is no long pause between rings from the calling party end. If I connect an analog phone to the POTS line the call rings as expected. The pause between rings is only from the UC560 to the IP phone. It looks like typical caller ID information is sent around 1.5 to 2 rings:

"Before Cisco IOS Release 12.4(11)XW, Foreign Exchange Office (FXO) Caller ID in North America was delivered between the first and second ring cycles based on the GR-30-CORE standard. FXO software was configured to wait for Caller ID delivery before initiating the call setup for the next leg. As a result, the destination endpoint did not start ringing until after 1.5 to 2 ring cycles on the FXO port."

I think the UC560 may be answering before all of the caller ID information is passed. Does anyone know if "line reversal" caller ID delivery would cause something like this? Or if the the UC560 treats Single Data Message Format (SDMF) or Multiple Data Message Format (MDMF) differently?

I am going to try the immediate plar config and see if that makes a difference as well as capture some vppm signal debug. I have to wait until the office closes today first though. I'll report back later.

Thanks,

-mike

[Michael Murray]

Paolo,

Here is the output of my capture tonight.

First, I removed the caller-id 2 ring setting:

voice-port 0/1/0

no caller-id alerting ring 2

voice-port 0/1/1

no caller-id alerting ring 2

voice-port 0/1/2

no caller-id alerting ring 2

voice-port 0/1/3

no caller-id alerting ring 2

voice-port 0/2/0

no caller-id alerting ring 2

Then I made a test call into the POTS line and the timeline below is what happened. Times are approximate as it was difficult to see the exact time in the log when the ringing started/stopped.

23:11:28 Called phone (ext 60) ringing

23:11:34 Called phone stops ringing, calling phone still hears ringing

23:11:46 Called phone starts ringing again, calling phone still hears ringing

031990: Dec 27 23:11:26.111: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing

031991: Dec 27 23:11:26.111: htsp_timer - 125 msec

031992: Dec 27 23:11:26.239: htsp_process_event: [0/1/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer

031993: Dec 27 23:11:26.239: htsp_timer - 10000 msec

031994: Dec 27 23:11:26.239: htsp_timer3 - 5600 msec

031995: Dec 27 23:11:26.239: [0/1/0] htsp_start_caller_id_rx:BELLCORE

031996: Dec 27 23:11:26.239: htsp_start_caller_id_rx create dsp_stream_manager

031997: Dec 27 23:11:26.239: [0/1/0] htsp_dsm_create_success  returns 1

031998: Dec 27 23:11:28.187: htsp_process_event: [0/1/0, FXOLS_RINGING, E_DSP_SIG_0100]

031999: Dec 27 23:11:28.187: fxols_ringing_not

032000: Dec 27 23:11:28.187: htsp_timer_stop

032001: Dec 27 23:11:28.187: htsp_timer - 10000 msec

032002: Dec 27 23:11:29.499: [0/1/0] htsp_dsm_feature_notify_cb  returns 2 id=DSM_FEATURE_SM_CALLERID_RX

032003: Dec 27 23:11:29.499: htsp_process_event: [0/1/0, FXOLS_RINGING, E_HTSP_CALLERID_RX_DONE]

032004: Dec 27 23:11:29.499: htsp_timer_stop

032005: Dec 27 23:11:29.499: htsp_timer_stop3

032006: Dec 27 23:11:29.499: [0/1/0] htsp_stop_caller_id_rx. message length 176htsp_setup_ind

032007: Dec 27 23:11:29.499: [0/1/0] get_fxo_caller_id:Caller ID received. Message type=128 length=42 checksum=4A

032008: Dec 27 23:11:29.499: [0/1/0] Caller ID String 80 27 01 08 31 32 32 37 31 38 31 31 02 0A 37 38 31 35 33 30 38 31 39 32 07 0F 57 49 52 45 4C 45 53 53 20 43 41 4C 4C 45 52 4A

032009: Dec 27 23:11:29.499: [0/1/0] get_fxo_caller_id calling num=781XXXXXXX calling name=WIRELESS CALLER calling time=12/27 18:11 

032010: Dec 27 23:11:29.499: fxols_callerid_done: call being answered

032011: Dec 27 23:11:29.503: [0/1/0] htsp_dsm_close_done

032012: Dec 27 23:11:29.503: htsp_process_event: [0/1/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]

032013: Dec 27 23:11:29.503: fxols_wait_setup_ack:

032014: Dec 27 23:11:29.503: htsp_timer - 6000 msec

032015: Dec 27 23:11:29.507: htsp_timer_stop3

032016: Dec 27 23:11:29.507: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_prochtsp_setup_req

032017: Dec 27 23:11:29.507: htsp_process_event: [50/0/571.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

032018: Dec 27 23:11:29.507: htsp_ephone_start_caller_id_tx calling num=781XXXXXXX calling name =WIRELESS CALLER called num=60 orig called num=

032019: Dec 27 23:11:29.507: [50/0/571.1] set signal state = 0x0 timestamp = 0

032020: Dec 27 23:11:29.511: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

032021: Dec 27 23:11:29.519: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert

032022: Dec 27 23:11:29.587: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_DSP_SIG_0110]fxols_rvs_battery

032023: Dec 27 23:11:29.587: htsp_timer_stop2

032024: Dec 27 23:11:29.587: htsp_timer_stop2

032025: Dec 27 23:11:32.107: htsp_process_event: [0/1/0, FXOLS_PROCEED_RVS_BT, E_DSP_SIG_0000]

032026: Dec 27 23:11:34.227: htsp_process_event: [0/1/0, FXOLS_PROCEED_RVS_BT, E_DSP_SIG_0100]fxols_disc_confirm

032027: Dec 27 23:11:34.227: htsp_timer_stop

032028: Dec 27 23:11:34.227: htsp_timer_stop2

032029: Dec 27 23:11:34.227: htsp_timer_stop3

032030: Dec 27 23:11:34.227: htsp_timer_stop3

032031: Dec 27 23:11:34.231: htsp_process_event: [50/0/571.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release

032032: Dec 27 23:11:34.231: [50/0/571.1] set signal state = 0x4 timestamp = 0

032033: Dec 27 23:11:34.231: htsp_process_event: [0/1/0, FXOLS_PROCEED_RVS_BT, E_HTSP_RELEASE_REQ]fxols_offhook_release

032034: Dec 27 23:11:34.231: htsp_timer_stop

032035: Dec 27 23:11:34.231: htsp_timer_stop2

032036: Dec 27 23:11:34.231: htsp_timer_stop3

032037: Dec 27 23:11:34.231: [0/1/0] set signal state = 0x4 timestamp = 0

032038: Dec 27 23:11:34.231: htsp_timer - 2000 msec

032043: Dec 27 23:11:36.231: htsp_process_event: [0/1/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout

032044: Dec 27 23:11:36.231: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_DSP_SIG_0100]

032045: Dec 27 23:11:38.107: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing

032046: Dec 27 23:11:38.107: htsp_timer - 125 msec

032047: Dec 27 23:11:38.235: htsp_process_event: [0/1/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer

032048: Dec 27 23:11:38.235: htsp_timer - 10000 msec

032049: Dec 27 23:11:38.235: htsp_timer3 - 5600 msec

032050: Dec 27 23:11:38.235: [0/1/0] htsp_start_caller_id_rx:BELLCORE

032051: Dec 27 23:11:38.235: htsp_start_caller_id_rx create dsp_stream_manager

032052: Dec 27 23:11:38.235: [0/1/0] htsp_dsm_create_success  returns 1

032053: Dec 27 23:11:40.227: htsp_process_event: [0/1/0, FXOLS_RINGING, E_DSP_SIG_0100]

032054: Dec 27 23:11:40.227: fxols_ringing_not

032055: Dec 27 23:11:40.227: htsp_timer_stop

032056: Dec 27 23:11:40.227: htsp_timer - 10000 msec

032057: Dec 27 23:11:43.836: htsp_process_event: [0/1/0, FXOLS_RINGING, E_HTSP_EVENT_TIMER3]fxols_snoop_clid_stop

032058: Dec 27 23:11:43.836: htsp_timer_stop3

032059: Dec 27 23:11:44.108: htsp_process_event: [0/1/0, FXOLS_RINGING, E_DSP_SIG_0000]

032060: Dec 27 23:11:46.228: htsp_process_event: [0/1/0, FXOLS_RINGING, E_DSP_SIG_0100]

032061: Dec 27 23:11:46.228: fxols_ringing_not

032062: Dec 27 23:11:46.228: htsp_timer_stop

032063: Dec 27 23:11:46.228: htsp_timer_stop3

032064: Dec 27 23:11:46.228: [0/1/0] htsp_stop_caller_id_rx. message length 0htsp_setup_ind

032065: Dec 27 23:11:46.228: [0/1/0] get_fxo_caller_id:Caller ID receive failed.  parseCallerIDString:no data.

032066: Dec 27 23:11:46.228: [0/1/0] get_local_station_id calling num= calling name= calling time=12/27 18:11  orig called=

032067: Dec 27 23:11:46.228: [0/1/0] htsp_dsm_close_done

032068: Dec 27 23:11:46.228: htsp_process_event: [0/1/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]

032069: Dec 27 23:11:46.228: fxols_wait_setup_ack:

032070: Dec 27 23:11:46.228: htsp_timer - 6000 msec

032071: Dec 27 23:11:46.232: htsp_timer_stop3

032072: Dec 27 23:11:46.232: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_prochtsp_setup_req

032073: Dec 27 23:11:46.236: htsp_process_event: [50/0/571.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup

032074: Dec 27 23:11:46.236: htsp_ephone_start_caller_id_tx calling num= calling name = called num=60 orig called num=

032075: Dec 27 23:11:46.236: [50/0/571.1] set signal state = 0x0 timestamp = 0

032076: Dec 27 23:11:46.236: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

032077: Dec 27 23:11:46.248: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert

032079: Dec 27 23:11:50.108: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring

032080: Dec 27 23:11:50.108: htsp_timer_stop

032081: Dec 27 23:11:50.108: htsp_timer_stop2

032082: Dec 27 23:11:52.228: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear

032083: Dec 27 23:11:52.228: htsp_timer_stop2

032084: Dec 27 23:11:52.228: htsp_timer - 6000 msec

032085: Dec 27 23:11:58.228: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER]fxols_disc_confirm

032086: Dec 27 23:11:58.228: htsp_timer_stop

032087: Dec 27 23:11:58.228: htsp_timer_stop2

032088: Dec 27 23:11:58.228: htsp_timer_stop3

032089: Dec 27 23:11:58.228: htsp_timer_stop3

032090: Dec 27 23:11:58.228: htsp_process_event: [50/0/571.1, EFXS_WAIT_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_waitoff_release

032091: Dec 27 23:11:58.228: [50/0/571.1] set signal state = 0x4 timestamp = 0

032092: Dec 27 23:11:58.232: htsp_process_event: [0/1/0, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release

032093: Dec 27 23:11:58.232: htsp_timer_stop

032094: Dec 27 23:11:58.232: htsp_timer_stop2

032095: Dec 27 23:11:58.232: htsp_timer_stop3

032096: Dec 27 23:11:58.232: [0/1/0] set signal state = 0x4 timestamp = 0

032097: Dec 27 23:11:58.232: htsp_timer - 2000 msec

032102: Dec 27 23:12:00.232: htsp_process_event: [0/1/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout

032103: Dec 27 23:12:00.232: htsp_process_event: [0/1/0, FXOLS_ONHOOK, E_DSP_SIG_0100]

[paolo bevilacqua · Accepted solution]

can you try under voice port

no battery-reversal

[Michael Murray]

Paolo,

no battery-reversal did the trick! Now I can call the main number and there is no interruption in the ringing of the IP phone. Thanks very much.

-mike

[paolo bevilacqua]

Thank you for the nice rating and good luck!