This document was generated from CDN thread
Created by: David Roberts on 01-06-2009 11:56:30 PM
Hi,
Our product utilizes JTAPI for 3rd party call control. Part of how it works is to open a provider and initialize a phone, do something (take offhook, answer, call, etc) and then release the phone. We may immediately reinitialize the phone once again and repeat.
What we see, specifically with CM 6.x is that the CTI manager is rejecting control of the device after this happens for a while. When we open a new provider, it starts working again fine (or use another CTI manager).
My question is whether we're hitting some sort of throttling limit or can you see a reason why our approach would cause this problem?
Thanks
Subject: RE: JTAPI device initialization throttling?
Replied by: David Staudt on 02-06-2009 05:04:03 PM
What is the nature of the error? There should not be an throttling in this area.
Ideally can you provide/attach:
- JTAPI logs (detailed/all types)
- Scenario details: timestamp of the failure, DNs/device-names involved, observed vs expected behaviour
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 04-06-2009 09:26:04 PM
After a period of time of using jtapi for third party call control, some devices get into a state where we are unable to add an address observer to them.
They stay in this state until we bounce our server, which suggests it is the client side which is the problem.
We receive a PlatformException with message ¿address is restricted¿, but we don¿t see related activity on the CTI Manager side, in the trace.
CTI control is configured as allowed in the CUCM configuration for these phones, and we are using a CTI super provider account for control.
What seems to be happening is that we get the exception when attempting to add the address observer, we then go to cleanup, and in attempting to delete the terminal, jtapi encounters another exception, which is apparently does not propagate to us.
We see this behavior on CUCM 6.X and 7.X in addition to the reported 5.1.3.
Here are the logs:
Our application logs:
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_LOGIN Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_LOGIN Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_LOGIN, Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_LOGIN, Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_PASSWORD Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_PASSWORD Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_PASSWORD, Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_PASSWORD, Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] single connection not allowed
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] single connection not allowed
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Phone timeout to wait for 10000
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Phone timeout to wait for 10000
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Address Observer
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Address Observer
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] removing address observer
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] removing address observer
2009-06-03 00:26:33,304|ERROR|Default WorkerThread 72[PrimitiveBasedLeg] Runtime exception in PrimitiveLeg: com.cisco.jtapi.PlatformExceptionImpl: Address is restricted
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Disconnect complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Disconnect complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] call deletion complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] call deletion complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[JTapiCallObserver] Checking if PhoneLine Offhook
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[JTapiCallObserver] Checking if PhoneLine Offhook
Logs from JTAPI (CiscoJtapi04.log):
535384: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) JVM Field Order is onetwothree
535385: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) EventThread wakeups are disabled
535386: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) EventThread queue statistics are disabled
535387: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) EventThread queue size threshold is 25
535388: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) Provider retry interval is set to 30 seconds
535389: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) Client desired server heartbeat time is set to 30 seconds
535390: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) CTI request timeout is is set to 30 seconds
535391: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) Provider open request timeout is set to 200 seconds
535392: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNKP143-) Provider priority is set to 2
535393: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-) Provider.info(CCMEncryption: Constructor)
535394: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-) Provider.info(Exiting CCMEncryption())
535395: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-) Provider.info(Entering CCMEncryption::encryptPassword.)
535396: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-) Provider.info(Exiting CCMEncryption::encryptPassword.success)
535397: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-) application did not set appinfo, creating default
535398: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNK
roviderImpl(): calling jtapiProperties.getSecurityPropertyForInstance()
535399: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNKP143-clarustestuser) TraceModule: JTAPI version Cisco Jtapi version 3.0(0.166) Release
535400: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNKP143-clarustestuser) Route Select Timeout is 5000 msecs
535401: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNKP143-clarustestuser) Jtapi post condition timeout is set to 15 seconds
535402: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-clarustestuser) Opening server "10.1.1.33" login "clarustestuser"
535403: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNKP143-clarustestuser) ProviderID = P143-clarustestuser
535404: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: addObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@18339e8)
535405: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@18339e8)
535406: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNKP1-clarustestuser)[Default WorkerThread 72][SEP003094C30E6D]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$2@4ed1ff)
535407: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.DefaultFeaturePhone$1@822091)
535408: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNKP1-clarustestuser)[Default WorkerThread 72](P1-clarustestuser) Request: deleteTerminal SEP003094C30E6D
535409: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[(P1-clarustestuser)]PrivilegeViolationExceptionImpl caught: application cannot remove this Terminal
535410: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNKP1-clarustestuser)[Default WorkerThread 72][SEP003094C30E6D]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@1282878)
535411: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@1282878)
535412: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNKP1-clarustestuser)[Default WorkerThread 72][SEP003094C30E6D]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@1282878)
535413: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNKP1-clarustestuser)[Default WorkerThread 72](P1-clarustestuser) Request: removeObserver
535414: Jun 03 00:26:37.804 PDT %JTAPI-CTIIMPL-7-UNKP143-clarustestuser) tTrying to create normal socket connection to 10.1.1.33
Subject: RE: JTAPI device initialization throttling?
Replied by: David Staudt on 05-06-2009 09:31:47 PM
Hi David,
Possibly the forum software is corrupting the text display, but can you confirm the JTAPI logs are set for detailed/all-types level via jtprefs?...It looks like the full level of logging is not enabled.
From what I can see, it looks like the Provider is opened and then immediately observes are added/removed, for the same device in the same millisecond..? Then a deleteTerminal is called for a Terminal that hadn't been Created (resulting in the 'restricted' exception)..? All happening before the ProviderOpenComplete (indeed before the Provider connection is even setup..?)
Can you detail what the app is attempting to do during this time?
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 05-06-2009 10:22:03 PM
David,
I am going to verify all JTAPI client-side trace is enabled. As per your other questions, our app
1. Opens a JTAPI provider and will keep it open for some period of time. If one is not open when we need to add a terminal, we will open one.
2. After a while we find, for specific phones, that addTerminal does not work.
3. As part of our cleanup, when we find this type of error, we run a cleanup routine which tries to delete the terminal, thus the exception (which we expect to see).
4. Other devices may still be added to without having any problem. The only way to recover the unresponsive device control is to restart our server or point to a new CTI Manager, both which open new jtapi provider connections.
For this reason, we suspect it may be a client problem.
In terms of the same millisec, we believe this is just a logging timestamp condition and the add/remove have some real space in between (> 1 millisec).
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 05-06-2009 10:44:35 PM
David,
Here is what our client-side jtapi logging is set for:
#This config file controls Cisco JTAPI Client Side Debugging and Tracing
#
#Changes to this file doesn't require restarting the CSIPC Service
#The next Atomic Test will pick up the chanages here.
#
jtapiConfig.DebugJtapi=true
jtapiConfig.DebugJtapiImpl=true
jtapiConfig.DebugCti=true
jtapiConfig.DebugCtiImpl=true
jtapiConfig.DebugProtocol=false
jtapiConfig.DebugMisc=false
jtapiConfig.TraceWarning=false
jtapiConfig.TraceInfo=true
jtapiConfig.TraceDebug=true
#
#File size in Bytes
#5048576 ~ 5MB
#1048576 ~ 1MB
jtapiConfig.LogFileSize=1048576
#
#Set the directory root where JTAPI traces are written
#Use double quotes e.g. "c:\\Temp\\"
#If the trace files (CiscoJtapi??.log) don't show up in this directory then check \Windows\System32\
#Some kind of Cisco Jtapi logging bug ?
jtapiConfig.TracePath="."
#
#Set the directory where JTAPI trace files should be written
#Make sure that directory is write-enabled for the CSIPC Application
jtapiConfig.TraceDir="."
jtapiConfig.UseTraceFiles=true
jtapiConfig.UseSyslog=false
jtapiConfig.UseJavaConsole=false
Subject: RE: JTAPI device initialization throttling?
Replied by: David Staudt on 06-06-2009 07:55:16 PM
Attached is a sample jtapi.ini generated from the CM7 jtprefs, with full logging enabled, for comparison.
(.txt extension added)
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 07-06-2009 05:12:16 PM
Here is the section of jtapi logs after enabling more debug levels
<strong style="mso-bidi-font-weight: normal;">JTAPI Logs snippet:
<strong style="mso-bidi-font-weight: normal;">CiscoJTAPI06.log
33107: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 8](P1-clarustest) Request: createTerminal SEP0016C791D194
33108: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 34](P1-clarustest) Request: createTerminal SEP0019E75AAB13
33109: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 99](P1-clarustest) Request: createTerminal SEP0016C791D130
33110: Jun 06 19:53:21.015 PDT %JTAPI-PROTOCOL-7-UNKP1-172.17.13.46) [Default WorkerThread 8] sending: com.cisco.cti.protocol.ProviderDeviceAcquireRequest {
sequenceNumber = 510
deviceName = SEP0016C791D194
}
33111: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: addObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@16bbe7)
33112: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 99](P1-clarustest) Request: createTerminal SEP0016C791D130
33113: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@16bbe7)
33114: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 34][SEP0019E75AAB13]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$2@8a4605)
33115: Jun 06 19:53:21.015 PDT %JTAPI-MISC-7-UNKP12-) started preloading classes
33116: Jun 06 19:53:21.015 PDT %JTAPI-MISC-7-UNKP12-) finished preloading classes
33117: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) JVM Field Order is onetwothree
33118: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) EventThread wakeups are disabled
33119: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) EventThread queue statistics are disabled
33120: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) EventThread queue size threshold is 25
33121: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) Provider retry interval is set to 30 seconds
33122: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) Client desired server heartbeat time is set to 30 seconds
33123: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) CTI request timeout is is set to 30 seconds
33124: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) Provider open request timeout is set to 200 seconds
33125: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNKP12-) Provider priority is set to 2
33126: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-) Provider.info(CCMEncryption: Constructor)
33127: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-) Provider.info(Exiting CCMEncryption())
33128: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-) Provider.info(Entering CCMEncryption::encryptPassword.)
33129: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.DefaultFeaturePhone$1@563a11)
33130: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 34](P1-clarustest) Request: deleteTerminal SEP0019E75AAB13
33131: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-) Provider.info(Exiting CCMEncryption::encryptPassword.success)
33132: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-) application did not set appinfo, creating default
33133: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNKroviderImpl(): calling jtapiProperties.getSecurityPropertyForInstance()
33134: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNKP12-clarustest) TraceModule: JTAPI version Cisco Jtapi version 6.0(0.9901)-139 Release
33135: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[(P1-clarustest)]PrivilegeViolationExceptionImpl caught: application cannot remove this Terminal
33136: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNKP12-clarustest) Route Select Timeout is 5000 msecs
33137: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNKP12-clarustest) Jtapi post condition timeout is set to 15 seconds
33138: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 34][SEP0019E75AAB13]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@fe3349)
33139: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-clarustest) Opening server "172.17.13.46" login "clarustest"
33140: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNKP12-clarustest) ProviderID = P12-clarustest
33141: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@fe3349)
33142: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 34][SEP0019E75AAB13]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@fe3349)
33143: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNKP1-clarustest)[Default WorkerThread 34](P1-clarustest) Request: removeObserver
Created by: David Roberts on 01-06-2009 11:56:30 PM
Hi,
Our product utilizes JTAPI for 3rd party call control. Part of how it works is to open a provider and initialize a phone, do something (take offhook, answer, call, etc) and then release the phone. We may immediately reinitialize the phone once again and repeat.
What we see, specifically with CM 6.x is that the CTI manager is rejecting control of the device after this happens for a while. When we open a new provider, it starts working again fine (or use another CTI manager).
My question is whether we're hitting some sort of throttling limit or can you see a reason why our approach would cause this problem?
Thanks
Subject: RE: JTAPI device initialization throttling?
Replied by: David Staudt on 02-06-2009 05:04:03 PM
What is the nature of the error? There should not be an throttling in this area.
Ideally can you provide/attach:
- JTAPI logs (detailed/all types)
- Scenario details: timestamp of the failure, DNs/device-names involved, observed vs expected behaviour
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 04-06-2009 09:26:04 PM
After a period of time of using jtapi for third party call control, some devices get into a state where we are unable to add an address observer to them.
They stay in this state until we bounce our server, which suggests it is the client side which is the problem.
We receive a PlatformException with message ¿address is restricted¿, but we don¿t see related activity on the CTI Manager side, in the trace.
CTI control is configured as allowed in the CUCM configuration for these phones, and we are using a CTI super provider account for control.
What seems to be happening is that we get the exception when attempting to add the address observer, we then go to cleanup, and in attempting to delete the terminal, jtapi encounters another exception, which is apparently does not propagate to us.
We see this behavior on CUCM 6.X and 7.X in addition to the reported 5.1.3.
Here are the logs:
Our application logs:
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_LOGIN Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_LOGIN Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_LOGIN, Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_LOGIN, Value: clarustestuser
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_PASSWORD Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Get Paramter: JTAPI_PROVIDER_PASSWORD Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_PASSWORD, Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Set Param: JTAPI_PROVIDER_PASSWORD, Value: clarus
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] single connection not allowed
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] single connection not allowed
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Phone timeout to wait for 10000
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72 Phone timeout to wait for 10000
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Address Observer
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Address Observer
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] removing address observer
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] removing address observer
2009-06-03 00:26:33,304|ERROR|Default WorkerThread 72[PrimitiveBasedLeg] Runtime exception in PrimitiveLeg: com.cisco.jtapi.PlatformExceptionImpl: Address is restricted
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Disconnect complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] Disconnect complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] call deletion complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[AbstractJTapiPhoneDevice] call deletion complete: 3741/SEP003094C30E6D
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[JTapiCallObserver] Checking if PhoneLine Offhook
2009-06-03 00:26:33,304|DEBUG|Default WorkerThread 72[JTapiCallObserver] Checking if PhoneLine Offhook
Logs from JTAPI (CiscoJtapi04.log):
535384: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) JVM Field Order is onetwothree535385: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) EventThread wakeups are disabled535386: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) EventThread queue statistics are disabled535387: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) EventThread queue size threshold is 25535388: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) Provider retry interval is set to 30 seconds535389: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) Client desired server heartbeat time is set to 30 seconds535390: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) CTI request timeout is is set to 30 seconds535391: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) Provider open request timeout is set to 200 seconds535392: Jun 03 00:26:33.304 PDT %JTAPI-CTI-7-UNK
P143-) Provider priority is set to 2535393: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-) Provider.info(CCMEncryption: Constructor)535394: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-) Provider.info(Exiting CCMEncryption())535395: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-) Provider.info(Entering CCMEncryption::encryptPassword.)535396: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-) Provider.info(Exiting CCMEncryption::encryptPassword.success)535397: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-) application did not set appinfo, creating default535398: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNK
roviderImpl(): calling jtapiProperties.getSecurityPropertyForInstance()535399: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNK
P143-clarustestuser) TraceModule: JTAPI version Cisco Jtapi version 3.0(0.166) Release535400: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNK
P143-clarustestuser) Route Select Timeout is 5000 msecs535401: Jun 03 00:26:33.304 PDT %JTAPI-JTAPIIMPL-7-UNK
P143-clarustestuser) Jtapi post condition timeout is set to 15 seconds535402: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-clarustestuser) Opening server "10.1.1.33" login "clarustestuser"535403: Jun 03 00:26:33.304 PDT %JTAPI-CTIIMPL-7-UNK
P143-clarustestuser) ProviderID = P143-clarustestuser535404: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: addObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@18339e8)
535405: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@18339e8)
535406: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK
P1-clarustestuser)[Default WorkerThread 72][SEP003094C30E6D]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$2@4ed1ff)535407: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.DefaultFeaturePhone$1@822091)
535408: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK
P1-clarustestuser)[Default WorkerThread 72](P1-clarustestuser) Request: deleteTerminal SEP003094C30E6D535409: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[(P1-clarustestuser)]PrivilegeViolationExceptionImpl caught: application cannot remove this Terminal
535410: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK
P1-clarustestuser)[Default WorkerThread 72][SEP003094C30E6D]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@1282878)535411: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK:[3741:Internal_PT]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@1282878)
535412: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK
P1-clarustestuser)[Default WorkerThread 72][SEP003094C30E6D]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@1282878)535413: Jun 03 00:26:33.304 PDT %JTAPI-JTAPI-7-UNK
P1-clarustestuser)[Default WorkerThread 72](P1-clarustestuser) Request: removeObserver535414: Jun 03 00:26:37.804 PDT %JTAPI-CTIIMPL-7-UNK
P143-clarustestuser) tTrying to create normal socket connection to 10.1.1.33Subject: RE: JTAPI device initialization throttling?
Replied by: David Staudt on 05-06-2009 09:31:47 PM
Hi David,
Possibly the forum software is corrupting the text display, but can you confirm the JTAPI logs are set for detailed/all-types level via jtprefs?...It looks like the full level of logging is not enabled.
From what I can see, it looks like the Provider is opened and then immediately observes are added/removed, for the same device in the same millisecond..? Then a deleteTerminal is called for a Terminal that hadn't been Created (resulting in the 'restricted' exception)..? All happening before the ProviderOpenComplete (indeed before the Provider connection is even setup..?)
Can you detail what the app is attempting to do during this time?
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 05-06-2009 10:22:03 PM
David,
I am going to verify all JTAPI client-side trace is enabled. As per your other questions, our app
1. Opens a JTAPI provider and will keep it open for some period of time. If one is not open when we need to add a terminal, we will open one.
2. After a while we find, for specific phones, that addTerminal does not work.
3. As part of our cleanup, when we find this type of error, we run a cleanup routine which tries to delete the terminal, thus the exception (which we expect to see).
4. Other devices may still be added to without having any problem. The only way to recover the unresponsive device control is to restart our server or point to a new CTI Manager, both which open new jtapi provider connections.
For this reason, we suspect it may be a client problem.
In terms of the same millisec, we believe this is just a logging timestamp condition and the add/remove have some real space in between (> 1 millisec).
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 05-06-2009 10:44:35 PM
David,
Here is what our client-side jtapi logging is set for:
#This config file controls Cisco JTAPI Client Side Debugging and Tracing
#
#Changes to this file doesn't require restarting the CSIPC Service
#The next Atomic Test will pick up the chanages here.
#
jtapiConfig.DebugJtapi=true
jtapiConfig.DebugJtapiImpl=true
jtapiConfig.DebugCti=true
jtapiConfig.DebugCtiImpl=true
jtapiConfig.DebugProtocol=false
jtapiConfig.DebugMisc=false
jtapiConfig.TraceWarning=false
jtapiConfig.TraceInfo=true
jtapiConfig.TraceDebug=true
#
#File size in Bytes
#5048576 ~ 5MB
#1048576 ~ 1MB
jtapiConfig.LogFileSize=1048576
#
#Set the directory root where JTAPI traces are written
#Use double quotes e.g. "c:\\Temp\\"
#If the trace files (CiscoJtapi??.log) don't show up in this directory then check \Windows\System32\
#Some kind of Cisco Jtapi logging bug ?
jtapiConfig.TracePath="."
#
#Set the directory where JTAPI trace files should be written
#Make sure that directory is write-enabled for the CSIPC Application
jtapiConfig.TraceDir="."
jtapiConfig.UseTraceFiles=true
jtapiConfig.UseSyslog=false
jtapiConfig.UseJavaConsole=false
Subject: RE: JTAPI device initialization throttling?
Replied by: David Staudt on 06-06-2009 07:55:16 PM
Attached is a sample jtapi.ini generated from the CM7 jtprefs, with full logging enabled, for comparison.
(.txt extension added)
Subject: RE: JTAPI device initialization throttling?
Replied by: David Roberts on 07-06-2009 05:12:16 PM
Here is the section of jtapi logs after enabling more debug levels
<strong style="mso-bidi-font-weight: normal;">JTAPI Logs snippet:
<strong style="mso-bidi-font-weight: normal;">CiscoJTAPI06.log
33107: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 8](P1-clarustest) Request: createTerminal SEP0016C791D19433108: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 34](P1-clarustest) Request: createTerminal SEP0019E75AAB1333109: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 99](P1-clarustest) Request: createTerminal SEP0016C791D13033110: Jun 06 19:53:21.015 PDT %JTAPI-PROTOCOL-7-UNK
P1-172.17.13.46) [Default WorkerThread 8] sending: com.cisco.cti.protocol.ProviderDeviceAcquireRequest {sequenceNumber = 510
deviceName = SEP0016C791D194
}
33111: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: addObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@16bbe7)
33112: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 99](P1-clarustest) Request: createTerminal SEP0016C791D13033113: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$1@16bbe7)
33114: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 34][SEP0019E75AAB13]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.PhoneDeviceInServiceObserver$2@8a4605)33115: Jun 06 19:53:21.015 PDT %JTAPI-MISC-7-UNK
P12-) started preloading classes33116: Jun 06 19:53:21.015 PDT %JTAPI-MISC-7-UNK
P12-) finished preloading classes33117: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) JVM Field Order is onetwothree33118: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) EventThread wakeups are disabled33119: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) EventThread queue statistics are disabled33120: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) EventThread queue size threshold is 2533121: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) Provider retry interval is set to 30 seconds33122: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) Client desired server heartbeat time is set to 30 seconds33123: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) CTI request timeout is is set to 30 seconds33124: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) Provider open request timeout is set to 200 seconds33125: Jun 06 19:53:21.015 PDT %JTAPI-CTI-7-UNK
P12-) Provider priority is set to 233126: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-) Provider.info(CCMEncryption: Constructor)33127: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-) Provider.info(Exiting CCMEncryption())33128: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-) Provider.info(Entering CCMEncryption::encryptPassword.)33129: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.DefaultFeaturePhone$1@563a11)
33130: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 34](P1-clarustest) Request: deleteTerminal SEP0019E75AAB1333131: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-) Provider.info(Exiting CCMEncryption::encryptPassword.success)33132: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-) application did not set appinfo, creating default33133: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNK
roviderImpl(): calling jtapiProperties.getSecurityPropertyForInstance()33134: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNK
P12-clarustest) TraceModule: JTAPI version Cisco Jtapi version 6.0(0.9901)-139 Release33135: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[(P1-clarustest)]PrivilegeViolationExceptionImpl caught: application cannot remove this Terminal
33136: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNK
P12-clarustest) Route Select Timeout is 5000 msecs33137: Jun 06 19:53:21.015 PDT %JTAPI-JTAPIIMPL-7-UNK
P12-clarustest) Jtapi post condition timeout is set to 15 seconds33138: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 34][SEP0019E75AAB13]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@fe3349)33139: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-clarustest) Opening server "172.17.13.46" login "clarustest"33140: Jun 06 19:53:21.015 PDT %JTAPI-CTIIMPL-7-UNK
P12-clarustest) ProviderID = P12-clarustest33141: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK:[357261:ClarusLAXInternalPT]Request: removeCallObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@fe3349)
33142: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 34][SEP0019E75AAB13]Request: removeObserver(com.clarussystems.telesvc.ttl.service.telephony.jtapi.cisco.CiscoJTapiCallObserver@fe3349)33143: Jun 06 19:53:21.015 PDT %JTAPI-JTAPI-7-UNK
P1-clarustest)[Default WorkerThread 34](P1-clarustest) Request: removeObserver