one x communicator speech quality issues

[Maxwell1001]

Thank you in advance...

Main CM 5.2 s8720 / G650

Problems Site G450 off main site
ISDN TRUNKS

1XC users on site have issues with calls cutting off and poor speech quality. this is for both internal and external calls. Internal being local calls on there site.

Only 1XC user have this not IP Phone users.

Happens on both 1XC 6.0 & 1XC 6.1 but seems to not be as bad on 6.0

trace below from 1XC

PROBLEMS CALL TIME
11:39
11:51
12:01
13:15

TRACE NAME endpointlog.txt




[01/10/2012 10:24:21:451] ERR: CONTACT: bDiscoverAvayaEnv = 1
[01/10/2012 10:24:21:857] ERR: MEDIA: CVideoManager::Initialize(): Video Ports invalid!
[01/10/2012 10:24:23:545] ERR: MEDIA: CVideoManager:rocessRTPPortUpdates(): Video is not enabled!
[01/10/2012 10:24:26:779] ERR: MEDIA: CVideoManager:rocessRTPPortUpdates(): Video is not enabled!
[01/10/2012 10:24:27:561] EMG: CORE: Local Logging level is set to 'error'.
[01/10/2012 10:24:27:561] ERR: UI: Error loading skin: res://skins/9630/flat.xml
[01/10/2012 10:24:27:576] EMG: CORE: Remote Logging level is set to 'emergency'.
[01/10/2012 10:24:27:904] ERR: EXTAPP: Recieved an XML message from an Unregistered client. Ignoring the message.
[01/10/2012 10:24:29:795] ERR: CONFIG: CChildView::GetUserAreaPath() : SHCreateDirectoryEx failed with rc = 183
[01/10/2012 10:24:29:795] ERR: DIAL: ApplyDialingRulesToNumber: input string is null
[01/10/2012 10:24:29:811] ERR: SIGNAL: RAS : RAS signaling channel local port number: 1024.
[01/10/2012 10:24:30:014] ERR: CONFIG: SetParameterToMasterTable: Value to set = -1 < minimum value field = 0, aborting!
[01/10/2012 10:24:31:810] ERR: MEDIA: CVideoManager:rocessRTPPortUpdates(): Video is not enabled!
[01/10/2012 10:25:16:091] ERR: SESSION: ProcessSwitchHookQuery not implemented
[01/10/2012 10:26:46:060] ERR: CORE: Receiver Socket 19652: receiver socket returned error (10054).
[01/10/2012 10:26:46:216] ERR: EXTAPP: Recieved an XML message from an Unregistered client. Ignoring the message.
[01/10/2012 10:26:46:544] ERR: CORE: Receiver Socket 19612: receiver socket returned error (10054).
[01/10/2012 10:26:46:732] ERR: CORE: Receiver Socket 19620: receiver socket returned error (10054).
[01/10/2012 10:26:47:107] ERR: CORE: Receiver Socket 19584: receiver socket returned error (10054).
[01/10/2012 10:26:47:263] ERR: CORE: Receiver Socket 19604: receiver socket returned error (10054).
[01/10/2012 10:40:25:461] ERR: SESSION: ProcessSwitchHookQuery not implemented
[01/10/2012 10:48:18:942] EMG: CORE: Local Logging level is set to 'error'.
[01/10/2012 10:48:18:942] EMG: CORE: Remote Logging level is set to 'emergency'.
[01/10/2012 10:48:20:848] EMG: CORE: Local Logging level is set to 'notice'.
[01/10/2012 10:48:20:848] EMG: CORE: Remote Logging level is set to 'emergency'.
[01/10/2012 10:48:23:364] EMG: CORE: Local Logging level is set to 'debug'.
[01/10/2012 10:48:23:364] DBH: CONFIG: [828] GetParameter(id= 266).
[01/10/2012 10:48:23:364] EMG: CORE: Remote Logging level is set to 'emergency'.
[01/10/2012 10:49:04:676] DBH: MEDIA: [4720] CAudioManager::GenerateVolumeUpdatedEvent(): Generating VolumeUpdatedEvent: <VolumeUpdatedEvent xmlns="

http://xml.avaya.com/endpointAPI">

<deviceType>playback</deviceType>

<deviceName>Plantronics C610</deviceName>

<deviceGUID>Plantronics C610</deviceGUID>

<volume>100</volume>

</VolumeUpdatedEvent>

.
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CGIPSAudioAdaptor::SetAudioDevicePreferenceOrder for playback device list.
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=0 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=2 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] GIPSVE_GetPlayoutDeviceName(0) => name=Plantronics C610 GUID=Plantronics C610
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=0 name="SoundMAX HD Audio" GUID="SoundMAX HD Audio"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=2 name="SoundMAX HD Audio" GUID="SoundMAX HD Audio"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] GIPSVE_GetPlayoutDeviceName(1) => name=SoundMAX HD Audio GUID=SoundMAX HD Audio
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=1 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] GIPSVE_GetRecordingDeviceName(0) => name=Plantronics C610 GUID=Plantronics C610
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=1 name="SoundMAX HD Audio" GUID="SoundMAX HD Audio"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] GIPSVE_GetRecordingDeviceName(1) => name=SoundMAX HD Audio GUID=SoundMAX HD Audio
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::SelectActiveDevices type=0 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::SelectActiveDevices type=1 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CAudioDeviceManager::SelectActiveDevices type=2 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CGIPSAudioAdaptor::StopPlayAllSessions()
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CGIPSAudioAdaptor::SetRingerDeviceId() Set Ringer through Playback
[01/10/2012 10:49:04:676] DBG: AUDIO: [4720] CGIPSAudioAdaptor::StartPlayAllSessions()
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] PrepareForMuteDetection(): Entering.
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] PrepareForMuteDetection(): Prepare to check playback mute state.
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] PrepareForMuteDetection(): Prepare to check microphone mute state.
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] PrepareForMuteDetection(): Secondary Ringer is not configured or used. Do not prepare to check it.
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CGIPSAudioAdaptor::SetAudioDevicePreferenceOrder Success.
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CGIPSAudioAdaptor::SetAudioDevicePreferenceOrder for microphone device list.
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=0 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=2 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] GIPSVE_GetPlayoutDeviceName(0) => name=Plantronics C610 GUID=Plantronics C610
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=0 name="SoundMAX HD Audio" GUID="SoundMAX HD Audio"
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=2 name="SoundMAX HD Audio" GUID="SoundMAX HD Audio"
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] GIPSVE_GetPlayoutDeviceName(1) => name=SoundMAX HD Audio GUID=SoundMAX HD Audio
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=1 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] GIPSVE_GetRecordingDeviceName(0) => name=Plantronics C610 GUID=Plantronics C610
[01/10/2012 10:49:04:739] DBG: AUDIO: [4720] CAudioDeviceManager::AddAvailableDevice update device type=1 name="SoundMAX HD Audio" GUID="SoundMAX HD Audio"
[01/10/2012 10:49:04:754] DBG: AUDIO: [4720] GIPSVE_GetRecordingDeviceName(1) => name=SoundMAX HD Audio GUID=SoundMAX HD Audio
[01/10/2012 10:49:04:754] DBG: AUDIO: [4720] CAudioDeviceManager::SelectActiveDevices type=0 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:754] DBG: AUDIO: [4720] CAudioDeviceManager::SelectActiveDevices type=1 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:754] DBG: AUDIO: [4720] CAudioDeviceManager::SelectActiveDevices type=2 name="Plantronics C610" GUID="Plantronics C610"
[01/10/2012 10:49:04:754] DBG: AUDIO: [4720] CGIPSAudioAdaptor::StopPlayAllSessions()
[01/10/2012 10:49:04:864] DBG: AUDIO: [4720] CGIPSAudioAdaptor::SetRingerDeviceId() Set Ringer through Playback
[01/10/2012 10:49:04:864] DBG: AUDIO: [4720] CGIPSAudioAdaptor::StartPlayAllSessions()
[01/10/2012 10:49:04:926] DBG: AUDIO: [4720] PrepareForMuteDetection(): Entering.
[01/10/2012 10:49:04:926] DBG: AUDIO: [4720] PrepareForMuteDetection(): Prepare to check playback mute state.
[01/10/2012 10:49:04:926] DBG: AUDIO: [4720] PrepareForMuteDetection(): Prepare to check microphone mute state.
[01/10/2012 10:49:04:942] DBG: AUDIO: [4720] PrepareForMuteDetection(): Secondary Ringer is not configured or used. Do not prepare to check it.
[01/10/2012 10:49:04:942] DBG: AUDIO: [4720] CGIPSAudioAdaptor::SetAudioDevicePreferenceOrder Success.
[01/10/2012 10:49:04:942] DBG: MEDIA: [4720] CAudioManager::OnSetAudioPreferenceListsRequest(): rc 1
[01/10/2012 10:49:04:942] DBH: MEDIA: [4720] CAudioManager::UpdateDeviceStructures(): Entering. TriggerEvent param = 1.
[01/10/2012 10:49:04:942] DBH: MEDIA: [4720] CAudioManager::UpdateDeviceStructures(): Audio adaptor is initialized.
[01/10/2012 10:49:04:942] DBH: MEDIA: [4720] CAudioManager::UpdateDeviceStructures(): None of active devices has been changed.
[01/10/2012 10:49:04:942] DBH: MEDIA: [4720] CAudioManager::UpdateDeviceStructures(): Entering. TriggerEvent param = 0.
[01/10/2012 10:49:04:942] DBH: MEDIA: [4720] CAudioManager::UpdateDeviceStructures(): Audio adaptor is initialized.
[01/10/2012 10:49:37:910] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 56 addr:'10.2.1.6' port:1720
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 56.
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 56.
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] TPKT: Message # 222 received (length= 52):
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 56.
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 20):

[01/10/2012 10:49:37:910] DBH: SIGNAL: [5500] 14 38 11 20 4c ae e3 1b 5b 00 3b 00 48 1b 5b 02 4b 61 3d 20

[01/10/2012 10:49:37:910] DBH: SESSION: [5500] rpm: ProcessDownlink entered: nBufferSize = 15
[01/10/2012 10:49:37:910] DBG: SESSION: [5500] ProcessRingerUpdate entered: state: 76
[01/10/2012 10:49:37:910] DBG: AUDIO: [5500] PlayAlert(type=1).
[01/10/2012 10:49:37:910] DBG: AUDIO: [5500] StopPlayBackAudio(): Stop Playback testing.
[01/10/2012 10:49:37:910] DBG: AUDIO: [5500] StopPlayBackAudio(): Test tone is not provided. Exit.
[01/10/2012 10:49:37:910] DBG: AUDIO: [5500] StopRingerAudio(): Stop Playback testing.
[01/10/2012 10:49:37:910] DBG: AUDIO: [5500] StopRingerAudio(): Test tone is not provided. Exit.
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:004] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 450 addr:'10.2.1.6' port:1720
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 450.
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 450.
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] TPKT: Message # 223 received (length= 51):
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 20 20 20 20 20 20 20 20 20 20 20 20 20

[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 395.
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] TPKT: Message # 224 received (length= 55):
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 59.
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 23):

[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] 17 38 11 20 ae e3 20 20 20 20 20 20 20 20 20 20 20 20 20 a3 e3 1b 45

[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:004] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:49:38:004] DBG: SIGNAL: [5500] DBuffer = <a= >
[01/10/2012 10:49:38:004] DBH: SESSION: [5500] SetPhoneDisplay = <a= >
[01/10/2012 10:49:38:004] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] startOfName = 79, endOfName = -1, startOfNumber = 80, endOfNumber = -1
[01/10/2012 10:49:38:020] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:49:38:020] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer: btnIndex = 7, nCallIndex = -1
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 336.
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] TPKT: Message # 225 received (length= 51):
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 1b 5b 00 3b 11 48 20 20 20 20 20 20 20

[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 281.
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] TPKT: Message # 226 received (length= 61):
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 65.
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 29):

[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] 1d 38 11 20 ae e3 20 20 20 20 20 31 38 38 32 35 32 1b 45 a9 e3 1b 54 02 00 1d 06 1b 45

[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:49:38:020] DBG: SIGNAL: [5500] DBuffer = <a= 188252 >
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] SetPhoneDisplay = <a= 188252 >
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] startOfName = -1, endOfName = 1, startOfNumber = 29, endOfNumber = 34
[01/10/2012 10:49:38:020] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:49:38:020] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] SetCallNumber: btn 7, <1>
[01/10/2012 10:49:38:020] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer: btnIndex = 7, nCallIndex = -1
[01/10/2012 10:49:38:020] DBH: SIGNAL: [5500] ProcessEscT: nameP = 2, nameL = 0, numP = 29, numL = 6
[01/10/2012 10:49:38:020] DBG: SIGNAL: [5500] ProcessEscT: name = , number = 188252
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:49:38:035] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 216.
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] TPKT: Message # 227 received (length= 51):
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 1b 5b 00 3b 02 48 20 20 20 20 20 43 41

[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 161.
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] TPKT: Message # 228 received (length= 52):
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 56.
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 20):

[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] 14 38 11 20 ab e3 4c 4c 20 46 52 4f 4d 20 1b 45 a3 80 28 0f

[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:49:38:035] DBG: SIGNAL: [5500] DBuffer = <a= CALL FROM 188252 >
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] SetPhoneDisplay = <a= CALL FROM 188252 >
[01/10/2012 10:49:38:035] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] startOfName = 7, endOfName = 15, startOfNumber = 29, endOfNumber = 34
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] ContainsConferenceString(CALL FROM)?
[01/10/2012 10:49:38:035] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer: btnIndex = 7, nCallIndex = -1
[01/10/2012 10:49:38:035] DBG: SESSION: [5500] ProcessLampUpdate: button Index: 7 button num: 7 ntype: 'GREEN' state: 'FLASH' module: 0
[01/10/2012 10:49:38:035] DBG: SESSION: [5500] GenerateIncomingCall: nButtonIndex = 7
[01/10/2012 10:49:38:035] DBH: SESSION: [5500] CreateCall: 6, activeCall:-1, Total Calls: 1
[01/10/2012 10:49:38:035] DBG: SESSION: [5500] CallController::CreateCall: callIndex = 6, btnIndex = 7
[01/10/2012 10:49:38:035] NOT: SESSION: INC - Incoming call from 188252 via Server
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:051] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] GetContactFromExtension(188252)
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] 5488: GenerateSessionUpdatedEvent(): no match found, use name from CM
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] SetNameNumberAvail: 7, 0
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] SetCallState: nCallIndex: 6, CallState: 1
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] NotifyCallStateChange: nCallIndex: 6, state: 1
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): bAlwaysSent 0, nConferenceID: -1 nCallIndex=6
[01/10/2012 10:49:38:051] NOT: SESSION: INC - Local Alerting for Incoming Call
[01/10/2012 10:49:38:051] DBG: SESSION: [5500] GenerateIncomingCall: callIndex: 6, nButtonIndex = 7
[01/10/2012 10:49:38:051] DBG: SESSION: [5500] ProcessTrigger entered: nButton: 7, lampType: 1, lampState: 8
[01/10/2012 10:49:38:051] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 0, nButtonIndex=7
[01/10/2012 10:49:38:051] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 105.
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] TPKT: Message # 229 received (length= 101):
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 105.
[01/10/2012 10:49:38:051] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=8, msgPtr=0x816eb0c
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] Q931: processFacilityMsg().
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] Q931: crv=0x1, crv length=2
[01/10/2012 10:49:38:066] DBH: SIGNAL: [5500] CH245Controller: processFastStart: SessionType AUDIO
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] CH245AnnexLAudio: processFastStartOLC().
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] H245: processFastStartOLC: forwardLCP; audio out.
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] H245: Forward encryption sync is not present
[01/10/2012 10:49:38:066] DBH: SIGNAL: [5500] parseEmAudioCapability: codec: 12(G.729), frameRate: 2, packetSize: 160, sampleRate: 8000
[01/10/2012 10:49:38:066] DBH: SIGNAL: [5500] CH245Controller: processFastStart: retCode: 0
[01/10/2012 10:49:38:066] DBH: SIGNAL: [5500] CH245Controller: processFastStart: SessionType AUDIO
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] CH245AnnexLAudio: processFastStartOLC().
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] H245: processFastStartOLC: reverseLCP; audio in.
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] H245: Reverse encryption sync is not present
[01/10/2012 10:49:38:066] DBH: SIGNAL: [5500] parseEmAudioCapability: codec: 12(G.729), frameRate: 2, packetSize: 160, sampleRate: 8000
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] H245: processFastStartOLC: ReverseLCP:
[01/10/2012 10:49:38:066] DBG: SIGNAL: [5500] H245: processFastStartOLC: ReverseLCP: Silence suppression is present: 0
[01/10/2012 10:49:38:066] DBG: AUDIO: [5500] StartSession()
[01/10/2012 10:49:38:066] DBG: AUDIO: [5500] StartSession(VoIP Session Id= 1, remote address= 10.2.100.1:2060).
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] CIPCall:repare. CN Payload is not specified.
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] VoIP[1][0]: Start: going to start GIPS media.
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] SetQOS DSCP[46] 802p[5]
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CWinQoSAdaptor::SetQOSDSCP srcAddr:192.168.200.25:2048 descAddr:10.2.100.1:2060 DSCP:46 Protocol:1
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CIClarityQoSClient::SetQOSDSCP(): SENDING a SetDSCP...: 100007f:8888
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CWinQoSAdaptor::SetQOSDSCP srcAddr:192.168.200.25:2049 descAddr:10.2.100.1:2061 DSCP:46 Protocol:1
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CIClarityQoSClient::SetQOSDSCP(): SENDING a SetDSCP...: 100007f:8888
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CWinQoSAdaptor::SetQOS802pTag srcAddr:192.168.200.25:2048 descAddr:10.2.100.1:2060 802p:5 Protocol:1
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CIClarityQoSClient::SetQOS802pTag(): SENDING a Set802pTAG...: 100007f:8888
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CWinQoSAdaptor::SetQOS802pTag srcAddr:192.168.200.25:2049 descAddr:10.2.100.1:2061 802p:5 Protocol:1
[01/10/2012 10:49:38:082] DBH: QOS: [5500] CIClarityQoSClient::SetQOS802pTag(): SENDING a Set802pTAG...: 100007f:8888
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] Start sending packets for channel id [0]
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] GetECStatus ecState[1] ecMode[3] aesMode[135711344] aesAttn[30393424]
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] GetNSStatus nsState[1] nsMode[4]
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] GetAGCStatus agcState[1] agcMode[2]
[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] GetSpeakerVolume speakerVolume[215]
[01/10/2012 10:49:38:082] DBH: AUDIO: [5500] Scaling the volume = 100 to channel = 0[01/10/2012 10:49:38:082] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:082] DBH: MEDIA: [5500] CAudioManager::StartSession(): Number of active sessions= 1.
[01/10/2012 10:49:38:082] DBG: QOS: [2996] ProcessStartMetricsMonitorRequest Successful Metric Subscription: ClientId: 0, Frequency (ms):5000, Query: audioQualityMetrics.
[01/10/2012 10:49:38:082] DBH: SIGNAL: [5500] CH245Controller: processFastStart: retCode: 0
[01/10/2012 10:49:38:082] DBH: SIGNAL: [5500] Q931: processFastStart() returned 0.
[01/10/2012 10:49:38:082] DBH: SIGNAL: [5500] NotifyStatus: 12 nParam=0
[01/10/2012 10:49:38:082] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:082] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:49:38:082] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:49:38:098] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:49:38:113] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 56 addr:'10.2.1.6' port:1720
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 56.
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 56.
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] TPKT: Message # 230 received (length= 52):
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 56.
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 20):

[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] 14 38 11 20 89 ae e3 1b 5b 00 3b 00 48 1b 5b 02 4b 61 3d 20

[01/10/2012 10:49:38:113] DBH: SESSION: [5500] rpm: ProcessDownlink entered: nBufferSize = 15
[01/10/2012 10:49:38:113] DBH: SESSION: [5500] currentHookState: 1, newState OnHook: 0
[01/10/2012 10:49:38:113] DBG: SESSION: [5500] ProcessTrigger: bState = 0, triggerType: 1
[01/10/2012 10:49:38:113] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 1, nButtonIndex=-1
[01/10/2012 10:49:38:113] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:113] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 345 addr:'10.2.1.6' port:1720
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5180] SendCCMSMessage: send buffer:
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 345.
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5180] 03 00 00 09 05 38 00 80 02

[01/10/2012 10:49:38:113] DBH: SIGNAL: [5180] Q931: sendCCMSMessages: Total bytes received= 684.
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5180] Q931: sendCCMSMessages: remaining bytes= 9.
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5180] TPKT: Message # 231 received (length= 5):
[01/10/2012 10:49:38:113] DBG: SIGNAL: [5180] Q931: sendInfoMsg().
[01/10/2012 10:49:38:113] DBG: SIGNAL: [5180] Q931: sending Setup, msg length=38
[01/10/2012 10:49:38:113] DBG: SIGNAL: [5180] Q931: sendTPKTPacket().
[01/10/2012 10:49:38:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 345.
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] TPKT: Message # 232 received (length= 51):
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 20 20 20 20 20 20 20 20 20 20 20 20 20

[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 290.
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] TPKT: Message # 233 received (length= 55):
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 59.
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 23):

[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] 17 38 11 20 ae e3 20 20 20 20 20 20 20 20 20 20 20 20 20 a3 e3 1b 45

[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:129] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:49:38:129] DBG: SIGNAL: [5500] DBuffer = <a= >
[01/10/2012 10:49:38:129] DBH: SESSION: [5500] SetPhoneDisplay = <a= >
[01/10/2012 10:49:38:129] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:129] DBH: SESSION: [5500] startOfName = 79, endOfName = -1, startOfNumber = 80, endOfNumber = -1
[01/10/2012 10:49:38:129] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:129] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:49:38:129] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:49:38:129] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer: btnIndex = 7, nCallIndex = 6
[01/10/2012 10:49:38:129] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:145] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): bAlwaysSent 0, nConferenceID: -1 nCallIndex=6
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 231.
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] TPKT: Message # 234 received (length= 51):
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 1b 5b 00 3b 11 48 20 20 20 20 20 20 20

[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 176.
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] TPKT: Message # 235 received (length= 61):
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 65.
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 29):

[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] 1d 38 11 20 ae e3 20 20 20 20 20 31 38 38 32 35 32 1b 45 a9 e3 1b 54 02 00 1d 06 1b 45

[01/10/2012 10:49:38:145] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:145] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:49:38:145] DBG: SIGNAL: [5500] DBuffer = <a= 188252 >
[01/10/2012 10:49:38:145] DBH: SESSION: [5500] SetPhoneDisplay = <a= 188252 >
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] startOfName = -1, endOfName = 1, startOfNumber = 29, endOfNumber = 34
[01/10/2012 10:49:38:160] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:49:38:160] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer: btnIndex = 7, nCallIndex = 6
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): bAlwaysSent 0, nConferenceID: -1 nCallIndex=6
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] ProcessEscT: nameP = 2, nameL = 0, numP = 29, numL = 6
[01/10/2012 10:49:38:160] DBG: SIGNAL: [5500] ProcessEscT: name = , number = 188252
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:49:38:160] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:49:38:160] DBG: SESSION: [5500] join-brdg: ProcessEscT: calling GenerateSessionUpdated Event
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:160] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): bAlwaysSent 0, nConferenceID: -1 nCallIndex=6
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 111.
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] TPKT: Message # 236 received (length= 51):
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:49:38:160] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 1b 5b 00 3b 02 48 20 20 20 20 20 43 41

[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 56.
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] TPKT: Message # 237 received (length= 52):
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 56.
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 20):

[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] 14 38 11 20 ab e3 4c 4c 20 46 52 4f 4d 20 1b 45 a3 80 2f 0f

[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:49:38:176] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:49:38:176] DBG: SIGNAL: [5500] DBuffer = <a= CALL FROM 188252 >
[01/10/2012 10:49:38:176] DBH: SESSION: [5500] SetPhoneDisplay = <a= CALL FROM 188252 >
[01/10/2012 10:49:38:176] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:49:38:176] DBH: SESSION: [5500] startOfName = 7, endOfName = 15, startOfNumber = 29, endOfNumber = 34
[01/10/2012 10:49:38:176] DBH: SESSION: [5500] ContainsConferenceString(CALL FROM)?
[01/10/2012 10:49:38:176] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:176] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer: btnIndex = 7, nCallIndex = 6
[01/10/2012 10:49:38:176] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): bAlwaysSent 0, nConferenceID: -1 nCallIndex=6
[01/10/2012 10:49:38:191] DBG: SESSION: [5500] ProcessLampUpdate: button Index: 7 button num: 7 ntype: 'GREEN' state: 'ON' module: 0
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] SetCallState: nCallIndex: 6, CallState: 3
[01/10/2012 10:49:38:191] DBG: SESSION: [5500] SetActiveCall: 6
[01/10/2012 10:49:38:191] DBG: SIGNAL: [5500] 6500: NotifyActiveCall(): SetActiveCall: 6
[01/10/2012 10:49:38:191] DBH: SIGNAL: [5500] H323Controller::ActiveCall: 6
[01/10/2012 10:49:38:191] DBH: SIGNAL: [5500] H245Controller: SetActiveCall: 6
[01/10/2012 10:49:38:191] WRN: SESSION-VIDEO: VideoCallInfo::SaveActiveCallState() Failed to preserve User Media State (1) for Held Call[-1] as Video Connection is NULL or Invalid Session Id.
[01/10/2012 10:49:38:191] DBH: SIGNAL: [5500] NotifyCallStateChange: nCallIndex: 6, state: 3
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] GenerateEstablishedEvent(nCallIndex = 6, int nConferenceId = -1, CString sRemoteUserName =
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:191] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] GetContactFromExtension(188252)
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] 5488: GenerateSessionUpdatedEvent(): no match found, use name from CM
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] SetNameNumberAvail: 7, 0
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): entered, nCallIndex= 6. conferenceId=-1
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] GenerateSessionUpdatedEvent(): bAlwaysSent 0, nConferenceID: -1 nCallIndex=6
[01/10/2012 10:49:38:191] DBG: SESSION: [5500] ProcessTrigger entered: nButton: 7, lampType: 1, lampState: 15
[01/10/2012 10:49:38:191] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 10, nButtonIndex=7
[01/10/2012 10:49:38:191] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:207] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 93 addr:'10.2.1.6' port:1720
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 93.
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 93.
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] TPKT: Message # 238 received (length= 44):
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 48.
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 12):

[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] 0c 38 11 20 a3 80 18 40 a2 80 05 40

[01/10/2012 10:49:38:207] DBG: SIGNAL: [5500] ProcessServiceLinkUp entered
[01/10/2012 10:49:38:207] DBG: SESSION: [5500] ProcessTrigger: bState = 1, triggerType: 200
[01/10/2012 10:49:38:207] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 200, nButtonIndex=-1
[01/10/2012 10:49:38:207] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:49:38:207] DBH: SIGNAL: [5500] Unknown transparent downlink-0x80-5. Skipping
[01/10/2012 10:49:38:207] DBH: SESSION: [5500] rpm: ProcessDownlink entered: nBufferSize = 0
[01/10/2012 10:49:38:207] DBG: SESSION: [5500] ProcessRingerUpdate entered: state: 64
[01/10/2012 10:49:38:223] DBG: AUDIO: [5500] StopPlay() tone ID= 2
[01/10/2012 10:49:38:223] DBG: AUDIO: [5500] StopPlay for tone ID= 2 succeeded
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 45.
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] TPKT: Message # 239 received (length= 41):
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 45.
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 9):

[01/10/2012 10:49:38:223] DBH: SIGNAL: [5500] 09 38 11 20 40 a3 80 2f 0f

[01/10/2012 10:49:38:223] DBH: SESSION: [5500] rpm: ProcessDownlink entered: nBufferSize = 4
[01/10/2012 10:49:38:223] DBG: SESSION: [5500] ProcessRingerUpdate entered: state: 64
[01/10/2012 10:49:38:223] DBG: SESSION: [5500] ProcessLampUpdate: button Index: 7 button num: 7 ntype: 'GREEN' state: 'ON' module: 0
[01/10/2012 10:49:38:223] DBH: SESSION: [5500] UpdateLampState: no lamp state change for button 7, lampType: 1, lampState: 15
[01/10/2012 10:49:38:223] DBH: SESSION: [5500] SetCallState: nCallIndex: 6, CallState: 3
[01/10/2012 10:49:38:223] DBH: SESSION: [5500] setCallState: no state change. 3
[01/10/2012 10:49:38:223] DBG: SESSION: [5500] ProcessTrigger entered: nButton: 7, lampType: 1, lampState: 15
[01/10/2012 10:49:38:238] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 10, nButtonIndex=7
[01/10/2012 10:49:38:238] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:49:38:238] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:49:38:238] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:49:43:020] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:49:43:020] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:49:43:020] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:49:48:051] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:49:48:051] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:49:48:051] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:49:53:082] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:49:53:082] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:49:53:082] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:49:58:098] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:49:58:113] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:49:58:113] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:03:129] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:03:129] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:03:129] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:08:160] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:08:160] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:08:160] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:13:191] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:13:191] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:13:191] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:18:222] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:18:222] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:18:222] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:23:254] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:23:254] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:23:254] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:28:285] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:28:285] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:28:285] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:33:316] DBG: QOS: [2996] QoSmanager:SendMetricSubscriptionEvents. Requesting Media Metrics for current session.
[01/10/2012 10:50:33:316] DBG: MEDIA: [2996] CAudioManager::GetCurrentSessionAudioMetrics(): Retrieving audio metrics from Adaptor.
[01/10/2012 10:50:33:316] DBG: AUDIO: [2996] GetCurrentSessionAudioMetrics().
[01/10/2012 10:50:33:879] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 62 addr:'10.2.1.6' port:1720
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 62.
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 62.
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] TPKT: Message # 240 received (length= 58):
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 62.
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 26):

[01/10/2012 10:50:33:879] DBH: SIGNAL: [5500] 1a 38 11 20 84 ad e3 1b 5b 00 3b 00 48 1b 5b 02 4b 1b 45 a6 80 20 0f 80 20 0e

[01/10/2012 10:50:33:879] DBH: SESSION: [5500] rpm: ProcessDownlink entered: nBufferSize = 21
[01/10/2012 10:50:33:879] DBH: SESSION: [5500] currentHookState: 2, newState OnHook: 1
[01/10/2012 10:50:33:879] DBG: SESSION: [5500] ProcessTrigger: bState = 1, triggerType: 1
[01/10/2012 10:50:33:894] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:50:33:894] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:50:33:894] DBG: SIGNAL: [5500] DBuffer = < >
[01/10/2012 10:50:33:894] DBH: SESSION: [5500] SetPhoneDisplay = < >
[01/10/2012 10:50:33:894] DBH: SIGNAL: [5500] MapCallAppToBtnIndex( ) => buttonIndex: -1 num=-1, module: -1
[01/10/2012 10:50:33:894] WRN: SESSION: ERROR: ProcessLoadPrimaryDisplayBuffer: call-app letter ' '[0x20] does not map to button
[01/10/2012 10:50:33:894] DBG: SESSION: [5500] ProcessLampUpdate: button Index: 7 button num: 7 ntype: 'GREEN' state: 'OFF' module: 0
[01/10/2012 10:50:33:894] DBH: SESSION: [5500] SetCallState: nCallIndex: 6, CallState: 6
[01/10/2012 10:50:33:894] DBH: SESSION: [5500] SetCallState: reset activeCall(6). callstate: 6
[01/10/2012 10:50:33:894] DBG: SESSION: [5500] SetActiveCall: -1
[01/10/2012 10:50:33:894] DBG: SIGNAL: [5500] 6500: NotifyActiveCall(): SetActiveCall: -1
[01/10/2012 10:50:33:894] DBH: SIGNAL: [5500] H323Controller::ActiveCall: -1
[01/10/2012 10:50:33:894] DBH: SIGNAL: [5500] H245Controller: SetActiveCall: -1
[01/10/2012 10:50:33:894] DBH: SIGNAL: [5500] NotifyCallStateChange: nCallIndex: 6, state: 6
[01/10/2012 10:50:33:894] NOT: SESSION: CAL - 6 Call Ended
[01/10/2012 10:50:33:894] DBH: SESSION: [5500] GenerateSessionEndedEvent: nCallIndex: 6 state: 3
[01/10/2012 10:50:33:910] DBG: SESSION: [5500] ProcessTrigger entered: nButton: 7, lampType: 1, lampState: 0
[01/10/2012 10:50:33:910] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 8, nButtonIndex=7
[01/10/2012 10:50:33:910] DBH: SESSION: [5212] 7535: EndHistoryRecord: nSessionID = 6
[01/10/2012 10:50:33:910] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:50:33:910] DBH: SESSION: [5500] ProcessLampUpdate: calling RemoveCall(6)
[01/10/2012 10:50:33:910] DBG: SESSION: [5500] CH323CallMgr::RemoveCall: nCallIndex = 6
[01/10/2012 10:50:33:910] DBG: SESSION: [5500] RemoveCall: calling SaveCallForBtn(7, -1)
[01/10/2012 10:50:33:910] DBH: SESSION: [5500] SetCallName: btn 7, <>
[01/10/2012 10:50:33:910] NOT: SESSION: TEL - [7] Remote Caller ID changing from [] to []
[01/10/2012 10:50:33:910] DBH: SESSION: [5500] SetCallNumber: btn 7, <>
[01/10/2012 10:50:33:910] DBH: SIGNAL: [5500] H245Controller: RemoveCall: 6
[01/10/2012 10:50:33:910] DBG: SESSION: [5500] ProcessLampUpdate: button Index: 7 button num: 7 ntype: 'RED' state: 'OFF' module: 0
[01/10/2012 10:50:33:910] DBH: SESSION: [5500] ProcessRed_LampUpdate entered
[01/10/2012 10:50:33:910] DBG: SESSION: [5500] ProcessTrigger entered: nButton: 7, lampType: 0, lampState: 0
[01/10/2012 10:50:33:925] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 4, nButtonIndex=7
[01/10/2012 10:50:33:925] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:50:33:925] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 71 addr:'10.2.1.6' port:1720
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5180] SendCCMSMessage: send buffer:
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 71.
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5180] 03 00 00 09 05 38 00 80 01

[01/10/2012 10:50:33:925] DBH: SIGNAL: [5180] Q931: sendCCMSMessages: Total bytes received= 693.
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5180] Q931: sendCCMSMessages: remaining bytes= 9.
[01/10/2012 10:50:33:925] DBH: SIGNAL: [5180] TPKT: Message # 241 received (length= 5):
[01/10/2012 10:50:33:925] DBG: SIGNAL: [5180] Q931: sendInfoMsg().
[01/10/2012 10:50:33:941] DBG: SIGNAL: [5180] Q931: sending Setup, msg length=38
[01/10/2012 10:50:33:941] DBG: SIGNAL: [5180] Q931: sendTPKTPacket().
[01/10/2012 10:50:33:941] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 71.
[01/10/2012 10:50:33:941] DBH: SIGNAL: [5500] TPKT: Message # 242 received (length= 67):
[01/10/2012 10:50:33:941] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 71.
[01/10/2012 10:50:33:941] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=8, msgPtr=0x816eb0c
[01/10/2012 10:50:33:941] DBG: SIGNAL: [5500] Q931: processFacilityMsg().
[01/10/2012 10:50:33:941] DBG: SIGNAL: [5500] Q931: crv=0x1, crv length=2
[01/10/2012 10:50:33:941] DBH: SIGNAL: [5500] CH245Controller: processFastStart: SessionType AUDIO
[01/10/2012 10:50:33:957] DBG: SIGNAL: [5500] CH245AnnexLAudio: processFastStartOLC().
[01/10/2012 10:50:33:957] DBG: SIGNAL: [5500] H245: processFastStartOLC: forwardLCP; audio out.
[01/10/2012 10:50:33:957] DBH: SIGNAL: [5500] CH245Controller: processFastStart: retCode: 4
[01/10/2012 10:50:33:957] DBH: SIGNAL: [5500] CH245Controller: processFastStart: SessionType AUDIO
[01/10/2012 10:50:33:957] DBG: SIGNAL: [5500] CH245AnnexLAudio: processFastStartOLC().
[01/10/2012 10:50:33:957] DBG: SIGNAL: [5500] H245: processFastStartOLC: reverseLCP; audio in.
[01/10/2012 10:50:33:957] DBH: SIGNAL: [5500] H245AnnexLAudio::StopMedia entered
[01/10/2012 10:50:33:957] DBG: AUDIO: [5500] EndSession(call id= 1, retain reservation= 1).
[01/10/2012 10:50:33:957] DBG: AUDIO: [5500] CGIPSAudioAdaptor::SetVoiceQuality(0).
[01/10/2012 10:50:33:957] DBG: AUDIO: [5500] VoIP[1]: End(bRetainReservation= 1).
[01/10/2012 10:50:33:957] DBG: AUDIO: [5500] ResetQOS
[01/10/2012 10:50:33:957] DBH: QOS: [5500] CWinQoSAdaptor::ResetQOS srcAddr:192.168.200.25:2048 descAddr:10.2.100.1:2060
[01/10/2012 10:50:33:957] DBH: QOS: [5500] CIClarityQoSClient::ResetQOS(): SENDING a ResetQOS...: 100007F:8888
[01/10/2012 10:50:33:957] DBH: QOS: [5500] CWinQoSAdaptor::ResetQOS srcAddr:192.168.200.25:2049 descAddr:10.2.100.1:2061
[01/10/2012 10:50:33:957] DBH: QOS: [5500] CIClarityQoSClient::ResetQOS(): SENDING a ResetQOS...: 100007F:8888
[01/10/2012 10:50:34:097] DBG: AUDIO: [5500] VoIP[1]: End(retaining reservation per request (hold)).
[01/10/2012 10:50:34:097] DBH: MEDIA: [5500] CAudioManager::EndSession(): Call Preserved: 0[01/10/2012 10:50:34:097] DBH: MEDIA: [5500] CAudioManager::EndSession(): Number of active sessions= 1.
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] CH245Controller: processFastStart: retCode: 4
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: processFastStart() returned 4.
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] NotifyStatus: 13 nParam=0
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:50:34:097] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 61 addr:'10.2.1.6' port:1720
[01/10/2012 10:50:34:097] DBG: QOS: [2996] ProcessEndMetricsMonitorRequest Successful Metric Subscription: ClientId: 0, Frequency (ms):5000, Query: audioQualityMetrics.
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 61.
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 61.
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] TPKT: Message # 243 received (length= 57):
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 61.
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:50:34:097] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 25):

[01/10/2012 10:50:34:113] DBH: SIGNAL: [5500] 19 38 11 20 a2 80 06 ad e3 1b 5b 00 3b 00 48 1b 5b 02 4b 1b 45 a3 80 2f 0e

[01/10/2012 10:50:34:113] DBH: SIGNAL: [5500] Unknown transparent downlink-0x80-6. Skipping
[01/10/2012 10:50:34:113] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:50:34:113] DBG: SESSION: [5500] ProcessLampUpdate: button Index: 7 button num: 7 ntype: 'RED' state: 'ON' module: 0
[01/10/2012 10:50:34:113] DBH: SESSION: [5500] ProcessRed_LampUpdate entered
[01/10/2012 10:50:34:113] DBG: SESSION: [5500] ProcessLampUpdate: found activeLine: 7
[01/10/2012 10:50:34:113] DBG: SESSION: [5500] ProcessTrigger entered: nButton: 7, lampType: 0, lampState: 15
[01/10/2012 10:50:34:113] DBG: SESSION: [5500] PendingTaskMgr::HandleTrigger entered: 2, nButtonIndex=7
[01/10/2012 10:50:34:113] DBH: SESSION: [5500] HandleTrigger returned
[01/10/2012 10:50:34:113] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:50:34:113] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:50:37:082] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 56 addr:'10.2.1.6' port:1720
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 56.
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 56.
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] TPKT: Message # 244 received (length= 52):
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 56.
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 20):

[01/10/2012 10:50:37:082] DBH: SIGNAL: [5500] 14 38 11 20 4c ae e3 1b 5b 00 3b 00 48 1b 5b 02 4b 61 3d 20

[01/10/2012 10:50:37:082] DBH: SESSION: [5500] rpm: ProcessDownlink entered: nBufferSize = 15
[01/10/2012 10:50:37:082] DBG: SESSION: [5500] ProcessRingerUpdate entered: state: 76
[01/10/2012 10:50:37:082] DBG: AUDIO: [5500] PlayAlert(type=1).
[01/10/2012 10:50:37:082] DBG: AUDIO: [5500] StopPlayBackAudio(): Stop Playback testing.
[01/10/2012 10:50:37:082] DBG: AUDIO: [5500] StopPlayBackAudio(): Test tone is not provided. Exit.
[01/10/2012 10:50:37:097] DBG: AUDIO: [5500] StopRingerAudio(): Stop Playback testing.
[01/10/2012 10:50:37:097] DBG: AUDIO: [5500] StopRingerAudio(): Test tone is not provided. Exit.
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:50:37:129] DBG: SIGNAL: [5500] Q931: OnSocketDataReceived(). entered dataLength: 450 addr:'10.2.1.6' port:1720
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Total bytes received= 450.
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 450.
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] TPKT: Message # 245 received (length= 51):
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 55.
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 19):

[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] 13 38 11 20 ae e3 20 20 20 20 20 20 20 20 20 20 20 20 20

[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] CCMSReceived: returned successful
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): TPKT reset
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Remaining bytes= 395.
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] TPKT: Message # 246 received (length= 55):
[01/10/2012 10:50:37:129] DBH: SIGNAL: [5500] Q931: processTPKTMessages(): Msg Length bytes= 59.
[01/10/2012 10:50:37:144] DBH: SIGNAL: [5500] RAS : H225Q931IncomingMsg: resultFlags=0x2, indication=9, msgPtr=0x816eb0c
[01/10/2012 10:50:37:144] DBH: SIGNAL: [5500] Q931: processInfoMsg().
[01/10/2012 10:50:37:144] DBH: SIGNAL: [5500] Q931: CCMS Message received from server (length= 23):

[01/10/2012 10:50:37:144] DBH: SIGNAL: [5500] 17 38 11 20 ae e3 20 20 20 20 20 20 20 20 20 20 20 20 20 a3 e3 1b 45

[01/10/2012 10:50:37:144] DBH: SIGNAL: [5500] EscE found
[01/10/2012 10:50:37:144] DBH: SESSION: [5500] ProcessLoadPrimaryDisplayBuffer entered
[01/10/2012 10:50:37:144] DBG: SIGNAL: [5500] DBuffer = <a= >
[01/10/2012 10:50:37:144] DBH: SESSION: [5500] SetPhoneDisplay = <a= >
[01/10/2012 10:50:37:144] DBH: SIGNAL: [5500] MapCallAppToBtnIndex(a) => buttonIndex: 7 num=7, module: 0
[01/10/2012 10:50:37:144] DBH: SESSION: [5500] startOfName = 79, endOfName = -1, startOfNumber = 80, endOfNumber = -1
[01/10/2012 10:50:37:144] DBG: AUDIO: [5500] CGIPSAudioAd