We use WSO2 APIM as an API Gateway. We have been using 2.6 but are now upgrading to 4.2 (we initially got this error on 4.1 but then tried 4.2 and got the same!). We are doing a new, fresh install on a new server and migrating over the applications, rather than trying to do an in-place upgrade. We use ansible to manage our servers, so the installation and deployment is fully scripted - the only manual steps are
We developed the ansible using local VMs. We host on CentOS 7. Three different developers (including myself) have run the ansible against totally empty VMs, to run it up from scratch, multiple times without a problem. It works there.
However, when we run it against a new, blank VM in our hosting environment, it appears to install fine but when we try to actually call an API, it doesn't work. We have gone through the whole process from scratch twice. It is exactly the same ansible code being used to do the installation locally and on the server.
The log file (wso2carbon.log) from startup shows no errors until the very end when it shows
TID: [-1234] [] [2023-03-14 17:40:17,928] INFO {org.wso2.carbon.ui.internal.CarbonUIServiceComponent} - API Publisher Default Context : https://api.example.com:443/publisher
TID: [-1234] [internal/data/v1] [2023-03-14 17:40:19,039] INFO {org.wso2.carbon.identity.oauth.config.OAuthServerConfiguration} - An instance of org.wso2.carbon.identity.oauth2.token.OauthTokenIssuerImpl is created for Identity OAuth token generation.
TID: [-1234] [] [2023-03-14 17:41:21,642] WARN {org.apache.synapse.transport.http.access.AccessConfiguration} - Error loading properties from file: access-log.properties
TID: [-1234] [] [2023-03-14 17:41:21,649] WARN {org.apache.synapse.commons.util.MiscellaneousUtil} - Error loading properties from a file at from the System defined location: access-log.properties
TID: [-1234] [] [2023-03-14 17:41:21,653] WARN {org.apache.synapse.commons.util.MiscellaneousUtil} - Error loading properties from a file at from the System defined location: access-log.properties
However, this warning is also seen in our local environments, and my understanding is that the logging is deliberately disabled.
The first token request generates the following error in the log on the servers (no such error locally - note that even on the server it does successfully generate a token despite the error in the logs)
TID: [-1234] [] [2023-03-14 17:41:21,762] ERROR {org.apache.axis2.transport.base.threads.NativeWorkerPool} - Uncaught exception java.lang.ExceptionInInitializerError
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel_aroundBody24(LogsHandler.java:310)
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel(LogsHandler.java:309)
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow_aroundBody2(LogsHandler.java:94)
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow(LogsHandler.java:84)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.invokeHandlers(Axis2SynapseEnvironment.java:1173)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.injectMessage(Axis2SynapseEnvironment.java:282)
at org.apache.synapse.core.axis2.SynapseMessageReceiver.receive(SynapseMessageReceiver.java:101)
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180)
at org.apache.synapse.transport.passthru.ServerWorker.processNonEntityEnclosingRESTHandler(ServerWorker.java:376)
at org.apache.synapse.transport.passthru.ServerWorker.processEntityEnclosingRequest(ServerWorker.java:435)
at org.apache.synapse.transport.passthru.ServerWorker.run(ServerWorker.java:183)
at org.apache.axis2.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:172)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.NullPointerException
at org.wso2.carbon.apimgt.gateway.APILoggerManager.<init>(APILoggerManager.java:84)
at org.wso2.carbon.apimgt.gateway.APILoggerManager.<clinit>(APILoggerManager.java:50)
... 15 more
After that, subsequent attempts to get a token or call an API produce
TID: [-1234] [] [2023-03-14 17:31:27,755] INFO {org.apache.synapse.transport.passthru.SourceHandler} - Writer null when calling informWriterError
TID: [-1234] [] [2023-03-14 17:31:27,755] WARN {org.apache.synapse.transport.passthru.SourceHandler} - STATE_DESCRIPTION = Socket Timeout occurred after accepting the request headers and the request body, INTERNAL_STATE = REQUEST_DONE, DIRECTION = REQUEST, CAUSE_OF_ERROR = Connection between the client and the EI timeouts, HTTP_URL = /customers/carcreleaseqa/v1/customers/v1?includeInactive=false, HTTP_METHOD = GET, SOCKET_TIMEOUT = 180000, CLIENT_ADDRESS = /10.0.100.221:37934, CONNECTION http-incoming-4 Correlation ID : 52e8c053-0fe5-4bc8-8995-62aef6d48d0b
TID: [-1234] [] [2023-03-14 17:32:56,714] ERROR {org.apache.axis2.transport.base.threads.NativeWorkerPool} - Uncaught exception java.lang.NoClassDefFoundError: Could not initialize class org.wso2.carbon.apimgt.gateway.APILoggerManager
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel_aroundBody24(LogsHandler.java:310)
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel(LogsHandler.java:309)
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow_aroundBody2(LogsHandler.java:94)
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow(LogsHandler.java:84)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.invokeHandlers(Axis2SynapseEnvironment.java:1173)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.injectMessage(Axis2SynapseEnvironment.java:282)
at org.apache.synapse.core.axis2.SynapseMessageReceiver.receive(SynapseMessageReceiver.java:101)
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180)
at org.apache.synapse.transport.passthru.ServerWorker.processNonEntityEnclosingRESTHandler(ServerWorker.java:376)
at org.apache.synapse.transport.passthru.ServerWorker.run(ServerWorker.java:190)
at org.apache.axis2.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:172)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
And, as said, the API does not get a response. Note that if we build up our own curl command (using the URL from /publisher for this API) and call the back-end from the server where WSO2 is running, it works fine. So the access to the back-end is there.
I think the second exception is a consequence of the first. I also think that the underlying problem might be something else - but since the logging isn't working, we aren't seeing the actual error. But I am totally stuck as to how to proceed.
The local VMs (which work) and the servers (which don't) are both essentially empty CentOS 7 minimal installations. We use VirtualBox locally and VMWare in hosting. They have some SSH keys and similar but nothing else installed differently. I have to accept there must be a difference, but I don't know where to start looking.
I looked at the wso2-apigw-errors.log file too. Directly after (during) start-up it shows
2023-03-14T17:58:51,333 [-] [Framework Event Dispatcher: Equinox Container: 5cfc3b31-5816-48bd-8f40-ad3b4eb18c5b] WARN ApplicationManagementServiceComponent Templates directory not found at /opt/wso2am/wso2am-4.1.0/repository/resources/identity/authntemplates
2023-03-14T17:59:38,172 [-] [Framework Event Dispatcher: Equinox Container: 5cfc3b31-5816-48bd-8f40-ad3b4eb18c5b] WARN SSLUtilBase The trusted certificate with alias [geotrustglobalca] and DN [CN=GeoTrust Global CA, O=GeoTrust Inc., C=US] is not valid due to [NotAfter: Sat May 21 07:00:00 EEST 2022]. Certificates signed by this trusted certificate WILL be accepted
The equivalent file on the local server contains no WARN lines at all! It then shows an exception with the same caused by as the first exception above (and a similar one to the second exception too)
2023-03-14T18:00:34,972 [-] [PassThroughMessageProcessor-1] ERROR NativeWorkerPool Uncaught exception
java.lang.ExceptionInInitializerError: null
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel_aroundBody24(LogsHandler.java:310) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel(LogsHandler.java:309) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow_aroundBody2(LogsHandler.java:94) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow(LogsHandler.java:84) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.invokeHandlers(Axis2SynapseEnvironment.java:1173) ~[synapse-core_2.1.7.wso2v271.jar:2.1.7-wso2v271]
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.injectMessage(Axis2SynapseEnvironment.java:282) ~[synapse-core_2.1.7.wso2v271.jar:2.1.7-wso2v271]
at org.apache.synapse.core.axis2.SynapseMessageReceiver.receive(SynapseMessageReceiver.java:101) ~[synapse-core_2.1.7.wso2v271.jar:2.1.7-wso2v271]
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180) ~[axis2_1.6.1.wso2v80.jar:?]
at org.apache.synapse.transport.passthru.ServerWorker.processNonEntityEnclosingRESTHandler(ServerWorker.java:376) ~[synapse-nhttp-transport_2.1.7.wso2v271.jar:?]
at org.apache.synapse.transport.passthru.ServerWorker.processEntityEnclosingRequest(ServerWorker.java:435) ~[synapse-nhttp-transport_2.1.7.wso2v271.jar:?]
at org.apache.synapse.transport.passthru.ServerWorker.run(ServerWorker.java:183) ~[synapse-nhttp-transport_2.1.7.wso2v271.jar:?]
at org.apache.axis2.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:172) ~[axis2_1.6.1.wso2v80.jar:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.NullPointerException
at org.wso2.carbon.apimgt.gateway.APILoggerManager.<init>(APILoggerManager.java:84) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.APILoggerManager.<clinit>(APILoggerManager.java:50) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
... 15 more
2023-03-14T18:00:44,165 [-] [PassThroughMessageProcessor-2] ERROR NativeWorkerPool Uncaught exception
java.lang.NoClassDefFoundError: Could not initialize class org.wso2.carbon.apimgt.gateway.APILoggerManager
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel_aroundBody24(LogsHandler.java:310) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.getAPILogLevel(LogsHandler.java:309) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow_aroundBody2(LogsHandler.java:94) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.wso2.carbon.apimgt.gateway.handlers.LogsHandler.handleRequestInFlow(LogsHandler.java:84) ~[org.wso2.carbon.apimgt.gateway_9.20.74.jar:?]
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.invokeHandlers(Axis2SynapseEnvironment.java:1173) ~[synapse-core_2.1.7.wso2v271.jar:2.1.7-wso2v271]
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.injectMessage(Axis2SynapseEnvironment.java:282) ~[synapse-core_2.1.7.wso2v271.jar:2.1.7-wso2v271]
at org.apache.synapse.core.axis2.SynapseMessageReceiver.receive(SynapseMessageReceiver.java:101) ~[synapse-core_2.1.7.wso2v271.jar:2.1.7-wso2v271]
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180) ~[axis2_1.6.1.wso2v80.jar:?]
at org.apache.synapse.transport.passthru.ServerWorker.processNonEntityEnclosingRESTHandler(ServerWorker.java:376) ~[synapse-nhttp-transport_2.1.7.wso2v271.jar:?]
at org.apache.synapse.transport.passthru.ServerWorker.run(ServerWorker.java:190) ~[synapse-nhttp-transport_2.1.7.wso2v271.jar:?]
at org.apache.axis2.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:172) ~[axis2_1.6.1.wso2v80.jar:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
When we make the API request it then shows
2023-03-14T18:03:35,129 [-] [HTTPS-Listener I/O dispatcher-3] WARN SourceHandler STATE_DESCRIPTION = Socket Timeout occurred after accepting the request headers and the request body, INTERNAL_STATE = REQUEST_DONE, DIRECTION = REQUEST, CAUSE_OF_ERROR = Connection between the client and the EI timeouts, HTTP_URL = /internal/data/v1/notify, HTTP_METHOD = POST, SOCKET_TIMEOUT = 180000, CLIENT_ADDRESS = /10.0.100.221:38210, CONNECTION http-incoming-1 Correlation ID : 63a80a51-ebac-4989-b866-67888eb6526e
2023-03-14T18:03:44,330 [-] [HTTPS-Listener I/O dispatcher-4] WARN SourceHandler STATE_DESCRIPTION = Socket Timeout occurred after accepting the request headers and the request body, INTERNAL_STATE = REQUEST_DONE, DIRECTION = REQUEST, CAUSE_OF_ERROR = Connection between the client and the EI timeouts, HTTP_URL = /my/endpoint/1234, HTTP_METHOD = GET, SOCKET_TIMEOUT = 180000, CLIENT_ADDRESS = /10.0.100.221:38212, CONNECTION http-incoming-2 Correlation ID : a81d76aa-4305-4484-be8b-cf7198b0c365
Followed by another NoClassDefFoundError for APILoggerManager
Looking at the code, the first excpetion comes back to
public APILoggerManager() {
this.eventHubConfigurationDto = ServiceReferenceHolder.getInstance().getApiManagerConfigurationService()
.getAPIManagerConfiguration().getEventHubConfigurationDto();
}
And looking at the ServiceReferenceHolder class, I see that getApiManagerConfigurationService() returns a member variable which is not initialised in the constructor (nothing is there!) so something needs to have called setApiManagerConfigurationService first and clearly hasn't - but why?
Can anyone give me some pointers as to what is wrong here or how I could troubleshoot it? I'm really stuck for ideas at this point.
We have (we think) found the underlying problem. It was not a difference in the hosting environment but in the configuration. Namely that the WSO2 admin user (in the environment we were using to test on the real servers) included a # in the password and we therefore fell foul of https://github.com/wso2/product-apim/issues/12186
If we change the password to something with any # characters it seems to work. We will continue to test.