Preserving Caller ID on CME through CUE Auto-Attendant

Kevin Parsons · ‎07-25-2014

I'm having problems with a CME 10.0 system / CUE 8.6.7 where the caller id from the carrier gets "lost" somehow when traversing from CME to the auto-attendant on CUE.

This system has four analog lines connecting to FXO ports all of which are configured to send the call to the AA. I have tried reconfiguring one of the FXO ports to go straight to a ephone-dn, whereupon the caller id is present and shows up on the screen. But taking the call through the CUE AA somehow kills the caller id from showing up.

Here are two "debug vpm signal" captures I took, the first with the call going through the auto-attendant, the second with the call going straight to a epone-dn.

Capture 1: (via the AA)

AGS-ChicagoWentworth#
005988: Jul 25 09:26:37.936 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=46810 systime=83603480
005989: Jul 25 09:26:37.936 CDT: htsp_process_event: [0/2/0, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
005990: Jul 25 09:26:37.936 CDT: htsp_timer - 125 msec
005991: Jul 25 09:26:38.064 CDT: htsp_process_event: [0/2/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
005992: Jul 25 09:26:38.064 CDT: htsp_timer - 10000 msec
005993: Jul 25 09:26:38.064 CDT: htsp_timer_stop3 htsp_setup_ind
005994: Jul 25 09:26:38.064 CDT: [0/2/0] get_fxo_caller_id:Caller ID receive failed. parseCallerIDString:no data.
005995: Jul 25 09:26:38.064 CDT: [0/2/0] get_local_station_id calling num= calling name= calling time=07/25 09:26 orig called=
005996: Jul 25 09:26:38.068 CDT: htsp_process_event: [0/2/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
005997: Jul 25 09:26:38.068 CDT: fxols_wait_setup_ack:
005998: Jul 25 09:26:38.068 CDT: htsp_timer - 6000 msec
005999: Jul 25 09:26:38.068 CDT: [0/2/0] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
006000: Jul 25 09:26:38.072 CDT: htsp_process_event: [0/2/0, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_prochtsp_alert_notify
006001: Jul 25 09:26:38.100 CDT: htsp_process_event: [0/2/0, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert
006002: Jul 25 09:26:38.116 CDT: htsp_call_bridged invoked
006003: Jul 25 09:26:38.116 CDT: htsp_process_event: [0/2/0, FXOLS_PROCEEDING, E_HTSP_CONNECT]fxols_offhook_connect
006004: Jul 25 09:26:38.120 CDT: [0/2/0] htsp_stop_caller_id_rx. message length 0
006005: Jul 25 09:26:38.120 CDT: [0/2/0] set signal state = 0xC timestamp = 0
006006: Jul 25 09:26:38.120 CDT: htsp_timer_stop
006007: Jul 25 09:26:38.120 CDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]fxols_connect_proc_voice
006008: Jul 25 09:26:38.320 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=47199 systime=83603519
006009: Jul 25 09:26:38.320 CDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_DSP_SIG_0100]fxols_normal_battery
006010: Jul 25 09:26:38.320 CDT: htsp_timer_stop2
006011: Jul 25 09:26:38.436 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=47313 systime=83603530
006012: Jul 25 09:26:38.436 CDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_DSP_SIG_0110]fxols_rvs_battery
006013: Jul 25 09:26:38.436 CDT: htsp_timer_stop2
006014: Jul 25 09:26:38.436 CDT: htsp_timer_stop2
006015: Jul 25 09:26:55.700 CDT: %SEC-6-IPACCESSLOGP: list 101 denied udp 0.0.0.0(68) -> 255.255.255.255(67), 6 packets
006016: Jul 25 09:27:02.184 CDT: htsp_digit_ready(0/2/0): digit = 1
006017: Jul 25 09:27:02.204 CDT: htsp_timer_stop3 htsp_setup_req
006018: Jul 25 09:27:02.208 CDT: Orig called num:4010
006019: Jul 25 09:27:02.208 CDT: htsp_process_event: [50/0/1.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup
006020: Jul 25 09:27:02.208 CDT: htsp_ephone_start_caller_id_tx calling num= calling name = called num=4010 orig called num=
006021: Jul 25 09:27:02.208 CDT: [50/0/1.1] set signal state = 0x0 timestamp = 0
006022: Jul 25 09:27:02.208 CDT: efxs_onhook_setup: local target is available
htsp_alert
006023: Jul 25 09:27:04.580 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=38136 systime=83606145
006024: Jul 25 09:27:04.580 CDT: htsp_process_event: [50/0/1.1, EFXS_WAIT_OFFHOOK, E_DSP_SIG_1100]efxs_waitoff_offhook
006025: Jul 25 09:27:04.580 CDT: [50/0/1.1] set signal state = 0x4 timestamp = 0 htsp_dial
006026: Jul 25 09:27:04.580 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_DSP_DIALING_DONE]
006027: Jul 25 09:27:04.584 CDT: htsp_call_bridged invoked
006028: Jul 25 09:27:04.584 CDT: htsp_call_bridged invoked
006029: Jul 25 09:27:04.584 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]efxs_connect_cutthru
006030: Jul 25 09:27:04.584 CDT: [50/0/1.1] set signal state = 0x7 timestamp = 0
006031: Jul 25 09:27:04.588 CDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]fxols_connect_proc_voice
006032: Jul 25 09:27:23.176 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=39136 systime=83608004
006033: Jul 25 09:27:23.176 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_DSP_SIG_0100]efxs_offhook_onhook
006034: Jul 25 09:27:23.176 CDT: htsp_timer - 10 msec
006035: Jul 25 09:27:23.188 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_HTSP_EVENT_TIMER]efxs_connect_wait_release_req
006036: Jul 25 09:27:23.188 CDT: htsp_timer_stop
006037: Jul 25 09:27:23.188 CDT: htsp_timer_stop3
006038: Jul 25 09:27:23.188 CDT: htsp_timer_stop3
006039: Jul 25 09:27:23.188 CDT: htsp_process_event: [50/0/1.1, EFXS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]efxs_waitrls_req_rlshtsp_report_onhook_sig
006040: Jul 25 09:27:23.208 CDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_RELEASE_REQ]fxols_offhook_release
006041: Jul 25 09:27:23.208 CDT: htsp_timer_stop
006042: Jul 25 09:27:23.208 CDT: htsp_timer_stop2
006043: Jul 25 09:27:23.208 CDT: htsp_timer_stop3
006044: Jul 25 09:27:23.208 CDT: [0/2/0] set signal state = 0x4 timestamp = 0
006045: Jul 25 09:27:23.208 CDT: htsp_timer - 2000 msec
006046: Jul 25 09:27:23.480 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=26822 systime=83608035
006047: Jul 25 09:27:23.480 CDT: htsp_process_event: [0/2/0, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
006048: Jul 25 09:27:25.208 CDT: htsp_process_event: [0/2/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
006049: Jul 25 09:27:25.208 CDT: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=83608208
006050: Jul 25 09:27:25.208 CDT: htsp_process_event: [0/2/0, FXOLS_ONHOOK, E_DSP_SIG_0100]term no mon
AGS-ChicagoWentworth#u all
All possible debugging has been turned off

Capture 2: (straight to a ephone-dn)

AGS-ChicagoWentworth#term mon
AGS-ChicagoWentworth#debug vpm signal
Voice Port Module signaling debugging is enabled
AGS-ChicagoWentworth#
006054: Jul 25 09:31:14.418 CDT: htsp_digit_ready(50/0/2.1): digit = 2
006055: Jul 25 09:31:18.858 CDT: htsp_digit_ready(50/0/2.1): digit = 7
006056: Jul 25 09:31:19.126 CDT: htsp_digit_ready(50/0/2.1): digit = 7
006057: Jul 25 09:31:19.510 CDT: htsp_digit_ready(50/0/2.1): digit = 3
006058: Jul 25 09:31:19.870 CDT: htsp_digit_ready(50/0/2.1): digit = 2
006059: Jul 25 09:31:20.238 CDT: htsp_digit_ready(50/0/2.1): digit = 3
006060: Jul 25 09:31:20.626 CDT: htsp_digit_ready(50/0/2.1): digit = 8
006061: Jul 25 09:31:20.942 CDT: htsp_digit_ready(50/0/2.1): digit = 5
006062: Jul 25 09:31:21.430 CDT: htsp_digit_ready(50/0/2.1): digit = 0
006063: Jul 25 09:31:21.958 CDT: htsp_digit_ready(50/0/2.1): digit = 9
006064: Jul 25 09:31:22.422 CDT: htsp_digit_ready(50/0/2.1): digit = 4
006065: Jul 25 09:31:38.730 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=19929 systime=83633560
006066: Jul 25 09:31:38.730 CDT: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
006067: Jul 25 09:31:38.730 CDT: htsp_timer - 125 msec
006068: Jul 25 09:31:38.858 CDT: htsp_process_event: [0/2/3, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
006069: Jul 25 09:31:38.858 CDT: htsp_timer - 10000 msec
006070: Jul 25 09:31:38.858 CDT: htsp_timer_stop3 htsp_setup_ind
006071: Jul 25 09:31:38.858 CDT: [0/2/3] get_fxo_caller_id:Caller ID receive failed. parseCallerIDString:no data.
006072: Jul 25 09:31:38.858 CDT: [0/2/3] get_local_station_id calling num= calling name= calling time=07/25 09:31 orig called=
006073: Jul 25 09:31:38.862 CDT: htsp_process_event: [0/2/3, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
006074: Jul 25 09:31:38.862 CDT: fxols_wait_setup_ack:
006075: Jul 25 09:31:38.862 CDT: htsp_timer - 6000 msec
006076: Jul 25 09:31:38.862 CDT: [0/2/3] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
006077: Jul 25 09:31:38.866 CDT: htsp_timer_stop3
006078: Jul 25 09:31:38.866 CDT: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_prochtsp_setup_req
006079: Jul 25 09:31:38.866 CDT: Orig called num:4010
006080: Jul 25 09:31:38.866 CDT: htsp_process_event: [50/0/1.1, EFXS_ONHOOK, E_HTSP_SETUP_REQ]efxs_onhook_setup
006081: Jul 25 09:31:38.870 CDT: htsp_ephone_start_caller_id_tx calling num= calling name = called num=4010 orig called num=
006082: Jul 25 09:31:38.870 CDT: [50/0/1.1] set signal state = 0x0 timestamp = 0
006083: Jul 25 09:31:38.870 CDT: efxs_onhook_setup: local target is available
htsp_alerthtsp_alert_notify
006084: Jul 25 09:31:38.874 CDT: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert
006085: Jul 25 09:31:39.906 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=21102 systime=83633677
006086: Jul 25 09:31:39.906 CDT: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
006087: Jul 25 09:31:39.906 CDT: htsp_timer_stop2
006088: Jul 25 09:31:39.906 CDT: htsp_timer - 6000 msec
006089: Jul 25 09:31:41.030 CDT: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_CALLERID_RX_DONE]fxols_proc_caller_id_done
006090: Jul 25 09:31:41.030 CDT: [0/2/3] htsp_stop_caller_id_rx. message length 46
006091: Jul 25 09:31:41.030 CDT: [0/2/3] get_fxo_caller_id:Caller ID received. Message type=128 length=42 checksum=8E
006092: Jul 25 09:31:41.030 CDT: [0/2/3] Caller ID String 80 27 01 08 30 37 32 35 30 39 33 31 02 0A 37 31 39 33 33 30 30 33 32 36 07 0F 50 41 52 53 4F 4E 53 20 4B 45 56 49 4E 20 20 8E
006093: Jul 25 09:31:41.030 CDT: [0/2/3] get_fxo_caller_id calling num=7193300326 calling name=PARSONS KEVIN calling time=07/25 09:31 htsp_call_service_msg
006094: Jul 25 09:31:41.034 CDT: htsp_call_service_msg number= [7193300326] name= [PARSONS KEVIN ]
006095: Jul 25 09:31:43.835 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=25030 systime=83634070
006096: Jul 25 09:31:43.835 CDT: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
006097: Jul 25 09:31:43.835 CDT: htsp_timer_stop
006098: Jul 25 09:31:43.835 CDT: htsp_timer_stop2
006099: Jul 25 09:31:43.995 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=40136 systime=83634086
006100: Jul 25 09:31:43.995 CDT: htsp_process_event: [50/0/1.1, EFXS_WAIT_OFFHOOK, E_DSP_SIG_1100]efxs_waitoff_offhook
006101: Jul 25 09:31:43.995 CDT: [50/0/1.1] set signal state = 0x4 timestamp = 0 htsp_dial
006102: Jul 25 09:31:43.995 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_DSP_DIALING_DONE]
006103: Jul 25 09:31:43.995 CDT: htsp_call_bridged invoked
006104: Jul 25 09:31:43.995 CDT: htsp_call_bridged invoked
006105: Jul 25 09:31:43.995 CDT: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_CONNECT]fxols_offhook_connect
006106: Jul 25 09:31:43.995 CDT: [0/2/3] set signal state = 0xC timestamp = 0
006107: Jul 25 09:31:43.995 CDT: htsp_timer_stop
006108: Jul 25 09:31:43.999 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]efxs_connect_cutthru
006109: Jul 25 09:31:43.999 CDT: [50/0/1.1] set signal state = 0x7 timestamp = 0
006110: Jul 25 09:31:43.999 CDT: htsp_process_event: [0/2/3, FXOLS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]fxols_connect_proc_voice
006111: Jul 25 09:31:44.095 CDT: htsp_digit_ready(50/0/2.1): digit = 2
006112: Jul 25 09:31:44.199 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=25394 systime=83634106
006113: Jul 25 09:31:44.199 CDT: htsp_process_event: [0/2/3, FXOLS_CONNECT, E_DSP_SIG_0100]fxols_normal_battery
006114: Jul 25 09:31:44.199 CDT: htsp_timer_stop2
006115: Jul 25 09:31:55.703 CDT: %SEC-6-IPACCESSLOGP: list 101 denied udp 0.0.0.0(68) -> 255.255.255.255(67), 6 packets
006116: Jul 25 09:32:12.435 CDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=41136 systime=83636930
006117: Jul 25 09:32:12.435 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_DSP_SIG_0100]efxs_offhook_onhook
006118: Jul 25 09:32:12.435 CDT: htsp_timer - 10 msec
006119: Jul 25 09:32:12.447 CDT: htsp_process_event: [50/0/1.1, EFXS_CONNECT, E_HTSP_EVENT_TIMER]efxs_connect_wait_release_req
006120: Jul 25 09:32:12.447 CDT: htsp_timer_stop
006121: Jul 25 09:32:12.447 CDT: htsp_timer_stop3
006122: Jul 25 09:32:12.447 CDT: htsp_timer_stop3
006123: Jul 25 09:32:12.447 CDT: htsp_process_event: [50/0/1.1, EFXS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]efxs_waitrls_req_rlshtsp_report_onhook_sig
006124: Jul 25 09:32:12.467 CDT: htsp_process_event: [0/2/3, FXOLS_CONNECT, E_HTSP_RELEASE_REQ]fxols_offhook_release
006125: Jul 25 09:32:12.467 CDT: htsp_timer_stop
006126: Jul 25 09:32:12.467 CDT: htsp_timer_stop2
006127: Jul 25 09:32:12.467 CDT: htsp_timer_stop3
006128: Jul 25 09:32:12.467 CDT: [0/2/3] set signal state = 0x4 timestamp = 0
006129: Jul 25 09:32:12.467 CDT: htsp_timer - 2000 msec
006130: Jul 25 09:32:14.467 CDT: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
006131: Jul 25 09:32:14.467 CDT: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=83637133
006132: Jul 25 09:32:14.467 CDT: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0100]
006133: Jul 25 09:32:16.239 CDT: htsp_digit_ready(50/0/2.1): digit = 2
006134: Jul 25 09:32:19.575 CDT: htsp_digit_ready(50/0/2.1): digit = 1term no mon
AGS-ChicagoWentworth#u all
All possible debugging has been turned off

I have other CME systems on the same versions of CME and CUE that aren't displaying this problem, so I'm trying to figure out why the caller id is lost on this one. Any help will be greatly appreciated.

Kevin