Solved: Re: Caller ID Problem - calling number not showing on phones

jamie.mai · ‎08-20-2013

Hello, does anyone have ideas? I have a CME 8.6. I can see in the debug that I am receiving the number but lower in the log it is blank yet the name is showing. This is the same thing we are seeing on the phones. Where is the calling number going? Thanks!

Aug 20 20:14:59.341: [0/3/0] htsp_dsm_feature_notify_cb returns 2 id=DSM_FEATUR

E_SM_CALLERID_RX

Aug 20 20:14:59.341: htsp_process_event: [0/3/0, FXOLS_RINGING, E_HTSP_CALLERID_

RX_DONE]

Aug 20 20:14:59.341: htsp_timer_stop

Aug 20 20:14:59.341: htsp_timer_stop3

Aug 20 20:14:59.341: //-1/313233343930/DSM:(0/3/0):-1/dsp_stream_mgr_destroy: .

Aug 20 20:14:59.341: //-1/313233343930/DSM:(0/3/0):-1/dsm_delete_all_streams: .

Aug 20 20:14:59.341: //-1/313233343930/DSM:(0/3/0):-1/dsmapi_accept_modem_passth

rough_session: : dmgr: 3222DDDC, active sessions 0, max sessions: 16 rejected s

essions till now: 0

Aug 20 20:14:59.341: [0/3/0] htsp_stop_caller_id_rx. message length 40htsp_setup

_ind

Aug 20 20:14:59.341: [0/3/0] get_fxo_caller_id:Caller ID received. Message type=

128 length=39 checksum=43

Aug 20 20:14:59.341: [0/3/0] Caller ID String 80 24 01 08 30 38 32 30 31 36 31 3

4 02 0A 35 31 32 34 37 36 30 34 38 39 07 0C 4D 4F 4E 45 59 20 42 4F 58 20 54 48

43

Aug 20 20:14:59.341: [0/3/0] get_fxo_caller_id calling num=5124761234 calling na

me=STORE NUMBER calling time=08/20 16:14

Aug 20 20:14:59.341: TGRM: reg_invoke_tgrm_accept_call(1, TGRM_CALL_VOICE, TGRM_

DIRECTION_IN, 0, 3, 0, 65535)

Aug 20 20:14:59.341: TGRM: Calling vtsp_tsp_call_setup_ind().

Aug 20 20:14:59.341: fxols_callerid_done: call being answered

Aug 20 20:14:59.345: flex_dsprm_close_cleanup

Aug 20 20:14:59.345: //-1/313233343930/DSM:(0/3/0):-1/dsmp_dsmapi_reserve_resour

ce_cb: .

Aug 20 20:14:59.345: [0/3/0] htsp_dsm_close_done

Aug 20 20:14:59.345: htsp_process_event: [0/3/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SE

TUP_ACK]

Aug 20 20:14:59.345: fxols_wait_setup_ack:

Aug 20 20:14:59.345: [0/3/0] set signal state = 0xC timestamp = 0

Aug 20 20:14:59.345: dsp_set_sig_state: [0/3/0] packet_len=12 channel_id=132 pac

ket_id=39 state=0xC timestamp=0x0fxols_check_auto_call

Aug 20 20:14:59.349: htsp_timer_stop3

Aug 20 20:14:59.349: htsp_process_event: [0/3/0, FXOLS_PROCEEDING, E_HTSP_PROCEE

DING]fxols_offhook_proc

Aug 20 20:14:59.349: htsp_timer - 120000 msechtsp_setup_req

Aug 20 20:14:59.349: htsp_process_event: [50/0/64.1, EFXS_ONHOOK, E_HTSP_SETUP_R

EQ]efxs_onhook_setup

Aug 20 20:14:59.349: htsp_ephone_start_caller_id_tx calling num= calling name =STORE NUMBER

called num=6400 orig called num=

Aug 20 20:14:59.341: //-1/313233343930/DSM:(0/3/0):-1/dsmp_dsmapi_detection_cb:

.

paolo bevilacqua · ‎08-21-2013

Remove translate under voice-port.

Instead, you can use a voice translation-profile and rule to prefix 9 if you like.

View solution in original post

paolo bevilacqua · ‎08-20-2013

Update IOS and check again.

Also check the complete log, if there is too long a gap betwwen rings the router may thing it's two separate calls form that the lost CLID.

Ayodeji Okanlawon · ‎08-20-2013

Looks like your telco is sending the caller id..You can try and adjust the caller id ring setting on your voice port

caller-id alerting ring 2

You can refer ot this thread to get a better understanding of the problem and possible solutions

https://learningnetwork.cisco.com/thread/5363#20433

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

jamie.mai · ‎08-21-2013

Thanks for the suggestion but that did not work. I also tried battery-reversal.

I am on c2900-universalk9-mz.SPA.151-4.M2.bin is there a problem with this firmware?

paolo bevilacqua · ‎08-21-2013

Can you please post the complete trace starting when something appears in debug, ending when the calls is answered.

jamie.mai · ‎08-21-2013

Okay sure, also included pic of what they see on the phone:

Aug 21 18:09:58.744: htsp_process_event: [0/3/0, FXOLS_ONHOOK, E_DSP_SIG_0000]fx

ols_onhook_ringing

Aug 21 18:09:58.744: TGRM: reg_invoke_tgrm_call_update(0, 3, 0, 65535, 1, TGRM_C

ALL_PENDING, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Aug 21 18:09:58.744: htsp_timer - 125 msec

Aug 21 18:09:58.872: htsp_process_event: [0/3/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVE

NT_TIMER]fxols_wait_ring_min_timer

Aug 21 18:09:58.872: htsp_timer - 10000 msec

Aug 21 18:09:58.872: htsp_timer3 - 5600 msec

Aug 21 18:09:58.872: [0/3/0] htsp_start_caller_id_rx:BELLCORE

Aug 21 18:09:58.872: //-1/313233343930/DSM:(0/3/0):-1/dsp_stream_mgr_create: .

Aug 21 18:09:58.872: //-1/313233343930/DSM:(0/3/0):-1/set_echo_canceller_data: e

cho_cancel: 0

Aug 21 18:09:58.872: //-1/313233343930/DSM:(0/3/0):-1/set_echo_canceller_data: e

cho_flags: 38, echo_len: 1024

Aug 21 18:09:58.872: htsp_start_caller_id_rx create dsp_stream_manager

Aug 21 18:09:58.872: //-1/313233343930/DSM:(0/3/0):-1/dsp_stream_mgr_set_dsp_all

ocated: .

Aug 21 18:09:58.872: //-1/313233343930/DSM:(0/3/0):-1/dsp_stream_mgr_implement_f

eature:

Aug 21 18:09:58.872: dsp_stream_mgr_implement_feature: feature id = 7

Aug 21 18:09:58.872: //-1/313233343930/DSM:(0/3/0):-1/dsmp_dsmapi_reserve_resour

ce_cb: .

Aug 21 18:09:58.872: [0/3/0] htsp_dsm_create_success returns 1

Aug 21 18:09:58.872: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Co

dec

Aug 21 18:10:00.848: htsp_process_event: [0/3/0, FXOLS_RINGING, E_DSP_SIG_0100]

Aug 21 18:10:00.848: fxols_ringing_not

Aug 21 18:10:00.848: htsp_timer_stop

Aug 21 18:10:00.848: htsp_timer - 10000 msec

Aug 21 18:10:01.920: //-1/313233343930/DSM:(0/3/0):-1/dsmp_dsmapi_detection_cb:

.

Aug 21 18:10:01.920: [0/3/0] htsp_dsm_feature_notify_cb returns 2 id=DSM_FEATUR

E_SM_CALLERID_RX

Aug 21 18:10:01.920: htsp_process_event: [0/3/0, FXOLS_RINGING, E_HTSP_CALLERID_

RX_DONE]

Aug 21 18:10:01.920: htsp_timer_stop

Aug 21 18:10:01.920: htsp_timer_stop3

Aug 21 18:10:01.920: //-1/313233343930/DSM:(0/3/0):-1/dsp_stream_mgr_destroy: .

Aug 21 18:10:01.920: //-1/313233343930/DSM:(0/3/0):-1/dsm_delete_all_streams: .

Aug 21 18:10:01.920: //-1/313233343930/DSM:(0/3/0):-1/dsmapi_accept_modem_passth

rough_session: : dmgr: 3222DDDC, active sessions 0, max sessions: 16 rejected s

essions till now: 0

Aug 21 18:10:01.920: [0/3/0] htsp_stop_caller_id_rx. message length 40htsp_setup

_ind

Aug 21 18:10:01.920: [0/3/0] get_fxo_caller_id:Caller ID received. Message type=

128 length=39 checksum=2C

Aug 21 18:10:01.920: [0/3/0] Caller ID String 80 24 01 08 30 38 32 31 31 34 30 3

9 02 0A 33 31 36 35 35 39 35 36 31 38 07 0C 57 49 52 45 4C 45 53 53 20 43 41 4C

2C

Aug 21 18:10:01.920: [0/3/0] get_fxo_caller_id calling num=3165591234 calling na

me=WIRELESS CAL calling time=08/21 14:09

Aug 21 18:10:01.920: TGRM: reg_invoke_tgrm_accept_call(1, TGRM_CALL_VOICE, TGRM_

DIRECTION_IN, 0, 3, 0, 65535)

Aug 21 18:10:01.920: TGRM: Calling vtsp_tsp_call_setup_ind().

Aug 21 18:10:01.920: fxols_callerid_done: call being answered

Aug 21 18:10:01.924: flex_dsprm_close_cleanup

Aug 21 18:10:01.924: //-1/313233343930/DSM:(0/3/0):-1/dsmp_dsmapi_reserve_resour

ce_cb: .

Aug 21 18:10:01.924: [0/3/0] htsp_dsm_close_done

Aug 21 18:10:01.924: htsp_process_event: [0/3/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SE

TUP_ACK]

Aug 21 18:10:01.924: fxols_wait_setup_ack:

Aug 21 18:10:01.924: [0/3/0] set signal state = 0xC timestamp = 0

Aug 21 18:10:01.924: dsp_set_sig_state: [0/3/0] packet_len=12 channel_id=132 pac

ket_id=39 state=0xC timestamp=0x0fxols_check_auto_call

Aug 21 18:10:01.924: htsp_timer_stop3

Aug 21 18:10:01.928: htsp_process_event: [0/3/0, FXOLS_PROCEEDING, E_HTSP_PROCEE

DING]fxols_offhook_proc

Aug 21 18:10:01.928: htsp_timer - 120000 msechtsp_setup_req

Aug 21 18:10:01.928: htsp_process_event: [50/0/64.1, EFXS_ONHOOK, E_HTSP_SETUP_R

EQ]efxs_onhook_setup

Aug 21 18:10:01.928: htsp_ephone_start_caller_id_tx calling num= calling name =W

IRELESS CAL called num=6400 orig called num=

Aug 21 18:10:01.928: [50/0/64.1] set signal state = 0x0 timestamp = 0

Aug 21 18:10:01.928: edsp_set_sig_state: [50/0/64.1] packet_len=12 channel_id=50

5 packet_id=39 state=0x0 timestamp=0x0

Aug 21 18:10:01.928: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:01.928: edsp_soutput: [50/0/64.1] DN=64 chnl=505 StationInsideRing

Aug 21 18:10:01.932: efxs_onhook_setup: local target is available

htsp_alerthtsp_alert_notify

Aug 21 18:10:01.936: htsp_process_event: [0/3/0, FXOLS_PROCEEDING, E_HTSP_ALERT]

fxols_offhook_alert

Aug 21 18:10:01.936: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Co

dec

Aug 21 18:10:02.248: htsp_process_event: [0/3/0, FXOLS_PROCEEDING, E_DSP_SIG_011

0]fxols_rvs_battery

Aug 21 18:10:02.248: htsp_timer_stop2

Aug 21 18:10:04.664: htsp_process_event: [50/0/64.1, EFXS_WAIT_OFFHOOK, E_DSP_SI

G_1100]efxs_waitoff_offhook

Aug 21 18:10:04.664: [50/0/64.1] set signal state = 0x4 timestamp = 0

Aug 21 18:10:04.664: edsp_set_sig_state: [50/0/64.1] packet_len=12 channel_id=50

5 packet_id=39 state=0x4 timestamp=0x0

Aug 21 18:10:04.664: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.664: edsp_soutput: [50/0/64.1] DN=64 chnl=505 StationRingOff hts

p_dial

Aug 21 18:10:04.664: htsp_process_event: [50/0/64.1, EFXS_CONNECT, E_DSP_DIALING

_DONE]

Aug 21 18:10:04.668: htsp_call_bridged invoked

Aug 21 18:10:04.668: flex_modem_relay_supported:Modem Relay supported. flex_type

=1

Aug 21 18:10:04.668: htsp_call_bridged invoked

Aug 21 18:10:04.668: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Co

dec

Aug 21 18:10:04.668: flex_dsprm_forking_mixing_support: htsp_connect: no_offhook

0 call_connected 0

Aug 21 18:10:04.672: htsp_process_event: [0/3/0, FXOLS_PROCEED_RVS_BT, E_HTSP_CO

NNECT]fxols_offhook_connect

Aug 21 18:10:04.672: htsp_timer_stop

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_OPEN_VOICE_

CHANNEL

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_ENC_CONFIG

2

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_SET_VOICE_P

LAYOUT_DELAY

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_ECHO_CANCEL

LER_CONTROL

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_VOICE_MODE

codec=1 vad=0 size=160 edsp_state=0

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_ECHO_CANCEL

LER_CONTROL

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_SET_GAINS

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: htsp_process_event: [50/0/64.1, EFXS_CONNECT, E_HTSP_VOICE_

CUT_THROUGH]efxs_connect_cutthru

Aug 21 18:10:04.672: [50/0/64.1] set signal state = 0x7 timestamp = 0

Aug 21 18:10:04.672: edsp_set_sig_state: [50/0/64.1] packet_len=12 channel_id=50

5 packet_id=39 state=0x7 timestamp=0x0

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:04.672: edsp_soutput: [50/0/64.1] DN=64 chnl=505 EFXS_OPEN_VOICE_PA

TH count=1

Aug 21 18:10:04.672: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Co

dec

Aug 21 18:10:04.676: htsp_process_event: [0/3/0, FXOLS_CONNECT, E_HTSP_VOICE_CUT

_THROUGH]fxols_connect_proc_voice

Aug 21 18:10:23.768: htsp_process_event: [0/3/0, FXOLS_CONNECT, E_DSP_SIG_1100]f

xols_offhook_disc

Aug 21 18:10:23.768: htsp_timer2 - 350 msec

Aug 21 18:10:23.820: htsp_process_event: [50/0/64.1, EFXS_CONNECT, E_DSP_SIG_010

0]efxs_offhook_onhook

Aug 21 18:10:23.820: htsp_timer - 10 msec

Aug 21 18:10:23.832: htsp_process_event: [50/0/64.1, EFXS_CONNECT, E_HTSP_EVENT_

TIMER]efxs_connect_wait_release_req

Aug 21 18:10:23.832: htsp_timer_stop

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GEN_PACKET_

CONTROL

Aug 21 18:10:23.832: htsp_timer_stop3

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_TX_STAT

Aug 21 18:10:23.832: edsp_fake_tx_stat: [50/0/64.1] DN=64 chnl=505 by proc_id 6

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_RX_STAT

Aug 21 18:10:23.832: edsp_fake_rx_stat: [50/0/64.1] DN=64 chnl=505 by proc_id 6

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_LEVELS

Aug 21 18:10:23.832: edsp_fake_levels: [50/0/64.1] DN=64 chnl=505 by proc_id 6

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_TX_STAT

Aug 21 18:10:23.832: edsp_fake_tx_stat: [50/0/64.1] DN=64 chnl=505 by proc_id 8

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_RX_STAT

Aug 21 18:10:23.832: edsp_fake_rx_stat: [50/0/64.1] DN=64 chnl=505 by proc_id 8

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_VOICE_P

LAYOUT_DELAY

Aug 21 18:10:23.832: edsp_fake_voice_playout_delay: [50/0/64.1] DN=64 chnl=505 b

y proc_id 8

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_VOICE_P

LAYOUT_ERROR

Aug 21 18:10:23.832: edsp_fake_voice_playout_error: [50/0/64.1] DN=64 chnl=505 b

y proc_id 8

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_GET_LEVELS

Aug 21 18:10:23.832: edsp_fake_levels: [50/0/64.1] DN=64 chnl=505 by proc_id 8

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.832: edsp_soutput: [50/0/64.1] DN=64 chnl=505 GET_ERROR_STAT

Aug 21 18:10:23.832: edsp_fake_error_stat: [50/0/64.1] DN=64 chnl=505 by proc_id

8htsp_release_req: cause 16, no_onhook 0

Aug 21 18:10:23.836: htsp_process_event: [50/0/64.1, EFXS_WAIT_RELEASE_REQ, E_HT

SP_RELEASE_REQ]efxs_waitrls_req_rlshtsp_report_onhook_sig

Aug 21 18:10:23.836: TGRM: reg_invoke_tgrm_call_update(50, 0, 64, 65535, 0, TGRM

_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Aug 21 18:10:23.836: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.836: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_IDLE_MODE

Aug 21 18:10:23.836: edsp_soutput: [50/0/64.1] DN=64 chnl=505

Aug 21 18:10:23.836: edsp_soutput: [50/0/64.1] DN=64 chnl=505 MSG_RX_CLOSE_VOICE

_CHANNEL

Aug 21 18:10:23.836: edsprm_close_cleanuphtsp_release_req: cause 16, no_onhook 0

Aug 21 18:10:23.844: htsp_process_event: [0/3/0, FXOLS_CONNECT, E_HTSP_RELEASE_R

EQ]fxols_offhook_release

Aug 21 18:10:23.844: htsp_timer_stop

Aug 21 18:10:23.844: htsp_timer_stop2

Aug 21 18:10:23.844: htsp_timer_stop3

Aug 21 18:10:23.844: [0/3/0] set signal state = 0x4 timestamp = 0

Aug 21 18:10:23.844: dsp_set_sig_state: [0/3/0] packet_len=12 channel_id=132 pac

ket_id=39 state=0x4 timestamp=0x0

Aug 21 18:10:23.844: TGRM: reg_invoke_tgrm_call_update(0, 3, 0, 65535, 1, TGRM_C

ALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_IN)

Aug 21 18:10:23.844: htsp_timer - 2000 msec

Aug 21 18:10:23.844: TGRM: reg_invoke_tgrm_channel_service_update(0, 3, 0, 65535

, 1)

Aug 21 18:10:23.844: TGRM: reg_invoke_tgrm_call_update(0, 3, 0, 65535, 1, TGRM_C

ALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Aug 21 18:10:23.844: flex_dsprm_close_cleanup

Aug 21 18:10:24.588: htsp_process_event: [0/3/0, FXOLS_GUARD_OUT, E_DSP_SIG_0110

]

Aug 21 18:10:25.844: htsp_process_event: [0/3/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_T

IMER]fxols_guard_out_timeout

Aug 21 18:10:25.844: TGRM: reg_invoke_tgrm_call_update(0, 3, 0, 65535, 1, TGRM_C

ALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)

Aug 21 18:10:25.844: dsp_req_sig_state: [0/3/0] packet_len=8 channel_id=132 pack

et_id=40

Aug 21 18:10:25.844: htsp_process_event: [0/3/0, FXOLS_ONHOOK, E_DSP_SIG_0100]