I have an app that I have created admin vars for. It looks like it worked fine for a while and pulled back the appropriate variable values, however now I am seeing this in the logs. How can I go about troubleshooting?



17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app>: Initializer:applicationStarted:Initializing admin variables...
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : Initializer:applicationStarted:__VPVarAppDate is 1576541692238
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : Initializer:applicationStarted:Timestamp is 12/16/19 19:14:52
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : Initializer:applicationStarted:Appname is 0:<app>
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : AdminVarCache:init: Timestamp is different; Load parameters....
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : AdminVarCache:init: Module? false
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : AdminVarCache:init: load data from the Experience Portal platform
17/12/2019 12:44:54:513 ERROR - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : VPClientProxy:VPAppRuntimeVars.getAppRuntimeVars returns null
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : AdminVarCache:init: no data comes back from proxy.
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : app params: {}
17/12/2019 12:44:54:513 DEBUG - D8F24D8FCD5EF6D76B5A7C58C930DC48:/<app> : AdminVarCache:init: Finish loading.

I also see this repeatedly in vpAppLogClient--

2019-12-17 13:04:40,316 1040987171 [https-openssl-nio-8443-exec-40] ERROR - VPAppRuntimeVars:getAppRuntimeVarsFromVPMS(): No callable EPM to get Application Runtime Vars
2019-12-17 13:04:40,316 1040987171 [https-openssl-nio-8443-exec-40] ERROR - VPAppRuntimeVars:printRuntimeVars: response received is NULL
2019-12-17 13:04:41,825 1040988680 [https-openssl-nio-8443-exec-35] ERROR - ReportWriter.setMaxLogFiles() missing value __VPmaxbackuplogfiles on request, getting value from vpclientlog.properties

First, does the timestamp in the log (below) look right? It should be the date and time when the values were last updated on EPM. It looks like OD is not get the values from the EPM web service. Not sure what has changed. You may have to restart EPM to see if it resolves the problem.

Initializer:applicationStarted:Timestamp is 12/16/19 19:14:52

That is about right. I changed the vars yesterday, and everything was working fine. Also we see this problem across both EPMs which are in different datacenters. A restart of the EPM seems like not a very good solution...

This looks like the culprit from vpAppLogClient, I restarted Tomcat and cleared logs, and I see this--

2019-12-17 14:00:26,138 1086146 [VPAppRuntimeVarsMonitorThread: https://IP/axis2/services/VPAppVarsService] ERROR - VPAppRuntimeVars:EPMWebServicesClientBaseImpl:getAppVarsAxis2() Caught Exception FAILED to send request to https://IP/axis2/services/VPAppVarsService Application Name: From AE Server: SERVER with error: org.apache.axis2.rpc.receivers.RPCInOnlyMessageReceiver cannot be cast to org.apache.axis2.engine.MessageReceiver NOTE: It could be caused by this EPM is not online or some other network issues.
java.lang.ClassCastException: org.apache.axis2.rpc.receivers.RPCInOnlyMessageReceiver cannot be cast to org.apache.axis2.engine.MessageReceiver
at org.apache.axis2.deployment.DescriptionBuilder.loadMessageReceiver(DescriptionBuilder.java:192)
at org.apache.axis2.deployment.DescriptionBuilder$1.run(DescriptionBuilder.java:145)
at org.apache.axis2.deployment.DescriptionBuilder$1.run(DescriptionBuilder.java:142)
at org.apache.axis2.java.security.AccessController.doPrivileged(AccessController.java:132)
at org.apache.axis2.deployment.DescriptionBuilder.processMessageReceivers(DescriptionBuilder.java:141)
at org.apache.axis2.deployment.AxisConfigBuilder.populateConfig(AxisConfigBuilder.java:106)
at org.apache.axis2.deployment.DeploymentEngine.populateAxisConfiguration(DeploymentEngine.java:857)
at org.apache.axis2.deployment.FileSystemConfigurator.getAxisConfiguration(FileSystemConfigurator.java:116)
at org.apache.axis2.context.ConfigurationContextFactory.createConfigurationContext(ConfigurationContextFactory.java:64)
at org.apache.axis2.context.ConfigurationContextFactory.createConfigurationContextFromFileSystem(ConfigurationContextFactory.java:210)
at org.apache.axis2.client.ServiceClient.configureServiceClient(ServiceClient.java:151)
at org.apache.axis2.client.ServiceClient.<init>(ServiceClient.java:144)
at com.avaya.xml.ws.vpappvars.voiceportal.VPAppVarsServiceStub.<init>(VPAppVarsServiceStub.java:95)
at com.avaya.xml.ws.vpappvars.voiceportal.VPAppVarsServiceStub.<init>(VPAppVarsServiceStub.java:81)
at com.avaya.xml.ws.vpappvars.voiceportal.VPAppVarsServiceStub.<init>(VPAppVarsServiceStub.java:130)
at com.avaya.vp.ws.EPMWebServicesClientBaseImpl.getAppVarsAxis2(EPMWebServicesClientBaseImpl.java:580)
at com.avaya.vp.appruntimevars.AppRuntimeVarsMonitor$MonitorTask.callAppRuntimeVarsWS(AppRuntimeVarsMonitor.java:244)
at com.avaya.vp.appruntimevars.AppRuntimeVarsMonitor$MonitorTask.run(AppRuntimeVarsMonitor.java:286)
at java.lang.Thread.run(Unknown Source)
2019-12-17 14:00:26,138 1086146 [VPAppRuntimeVarsMonitorThread: https://IP/axis2/services/VPAppVarsService] ERROR - VPAppRuntimeVars:EPMWebServicesClientBaseImpl:getAppVarsAxis2() Caught Exception FAILED to send request to https://IP/axis2/services/VPAppVarsService Application Name: From AE Server: SERVER with error: org.apache.axis2.rpc.receivers.RPCInOnlyMessageReceiver cannot be cast to org.apache.axis2.engine.MessageReceiver NOTE: It could be caused by this EPM is not online or some other network issues.
java.lang.ClassCastException: org.apache.axis2.rpc.receivers.RPCInOnlyMessageReceiver cannot be cast to org.apache.axis2.engine.MessageReceiver
at org.apache.axis2.deployment.DescriptionBuilder.loadMessageReceiver(DescriptionBuilder.java:192)
at org.apache.axis2.deployment.DescriptionBuilder$1.run(DescriptionBuilder.java:145)
at org.apache.axis2.deployment.DescriptionBuilder$1.run(DescriptionBuilder.java:142)
at org.apache.axis2.java.security.AccessController.doPrivileged(AccessController.java:132)
at org.apache.axis2.deployment.DescriptionBuilder.processMessageReceivers(DescriptionBuilder.java:141)
at org.apache.axis2.deployment.AxisConfigBuilder.populateConfig(AxisConfigBuilder.java:106)
at org.apache.axis2.deployment.DeploymentEngine.populateAxisConfiguration(DeploymentEngine.java:857)
at org.apache.axis2.deployment.FileSystemConfigurator.getAxisConfiguration(FileSystemConfigurator.java:116)
at org.apache.axis2.context.ConfigurationContextFactory.createConfigurationContext(ConfigurationContextFactory.java:64)
at org.apache.axis2.context.ConfigurationContextFactory.createConfigurationContextFromFileSystem(ConfigurationContextFactory.java:210)
at org.apache.axis2.client.ServiceClient.configureServiceClient(ServiceClient.java:151)
at org.apache.axis2.client.ServiceClient.<init>(ServiceClient.java:144)
at com.avaya.xml.ws.vpappvars.voiceportal.VPAppVarsServiceStub.<init>(VPAppVarsServiceStub.java:95)
at com.avaya.xml.ws.vpappvars.voiceportal.VPAppVarsServiceStub.<init>(VPAppVarsServiceStub.java:81)
at com.avaya.xml.ws.vpappvars.voiceportal.VPAppVarsServiceStub.<init>(VPAppVarsServiceStub.java:130)
at com.avaya.vp.ws.EPMWebServicesClientBaseImpl.getAppVarsAxis2(EPMWebServicesClientBaseImpl.java:580)
at com.avaya.vp.appruntimevars.AppRuntimeVarsMonitor$MonitorTask.callAppRuntimeVarsWS(AppRuntimeVarsMonitor.java:244)
at com.avaya.vp.appruntimevars.AppRuntimeVarsMonitor$MonitorTask.run(AppRuntimeVarsMonitor.java:286)
at java.lang.Thread.run(Unknown Source)

This error has something to do with the mixed versions of the same library file in the Tomcat/lib or between the Tomcat/lib and the app/WEB-INF/lib. Make sure you don't have duplicate files (of similar names) within the Tomcat/lib and between the app/WEB-INF/lib.

There REALLY should be a better way to flag and report this condition. In this instance we did have two apps that had their own copies of Axis2 1.7.4 in their WEB-INF/lib ( vs the 1.6.2 in Tomcat/lib). Maybe some type of check should be created in the AdminVar client app startup that puts a huge ERROR flag on the fact that having these libraries can and will cripple your system.

In order to find this, I had to first track down which JAR files included the org.apache.axis2.rpc.receivers.RPCInOnlyMessageReceiver and org.apache.axis2.engine.MessageReceiver classes, then run a recursive listing looking for those JAR files, which led to the problem. Modifying the apps to have references to TOMCAT_HOME/lib/axis* files and removing the local copies fixed the issue.

Thanks for helping me track this one down, it is all working as expected for now!

There is simply no good way of tracking what developers would do to a project in an open development environment.