0 Replies Latest reply on Nov 4, 2019 11:49 PM by gilbertfernandes-stime

Filtering some exceptions sent to console or having those sent to separate file

gilbertfernandes-stime Nov 4, 2019 11:49 PM

I am using Keycloak and it uses JBoss Wildfly.

I have code in KC that does some backend calls, and I recently modified the calls (REST Easy calls) to add timeouts.

Everything works fine, but I am having trouble filtering some exceptions.

When a timeout happens, the library REST Easy generates two exceptions in that order :

java.net.SocketTimeoutException: Read timed out
javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request

I am using in my code a try/catch to any exception occuring on the call is catched :

try {

response = call to REST easy client with .target...headers...get()

LOGGER.infov("[email={0}] - findUserByEmail. Target [{1}] returned http status {2} ...", email, getUserByMailFullUrl, response.getStatus());

return toFindUserByEmail(email, response);

} catch (final Exception e) {

LOGGER.warnv(e, "[email={0}] - findUserByEmail : exception occurred on calling target [{1}]", email, getUserByMailFullUrl);

if (e.getCause() instanceof UnknownHostException || e.getCause() instanceof ConnectException || e.getCause() instanceof SocketException) {

LOGGER.warnv("[email={0}] - findUserByEmail : target [{1}] not reachable", email, this.rcLookupServiceConfig.getUrl());

return new FindUserByEmail(email, Response.Status.SERVICE_UNAVAILABLE.getStatusCode(), ErrorType.SERVER_NOT_REACHEABLE);

} else if(e.getCause() instanceof java.net.SocketTimeoutException) {

LOGGER.warnv("Timeout : [{0}] did not answer within {1} ms !",

getUserByMailFullUrl, this.rcLookupServiceConfig.getTimeout());

return new FindUserByEmail(email, Response.Status.GATEWAY_TIMEOUT.getStatusCode(), ErrorType.SERVER_NOT_REACHEABLE);

} else {

return new FindUserByEmail(email, -1, ErrorType.UNKNOWN_SERVER_ERROR);

}

As you can see, I catch UnknownHostException, ConnectException, SocketException for a specific log and one for the timeout which properly works.

But I keep seeing two exceptions in my Wildfly console each time a timeout happens. So I tried to put a try/catch on the whole method to discover that those two exceptions do happen in the library itself.

The timeout is thrown, REST Easy then throws its own exception and rethrows the first exception SocketTimeoutException that I catch.

So I have been trying for a few days to either suppress (I don't really like the idea of suppressing exceptions) then to move them to a specific file but nothing seems to work.

As a developer, my knowledge of JBoss log configuration is limited, and I am thus asking for help (spending time learning JBoss and its configuration details probably won't be allowed, they want me to code

First attempt : filtering out the exceptions

My first try was this :

</logger>

</logger>

Using the use-parent-handlers to false. I tried OFF and FATAL but the exceptions still get injected into the console.

Second attempt : moving exceptions to a separate file

I then created a new logger :

<periodic-rotating-file-handler name="RCUTIMEOUTS" autoflush="true">

<named-formatter name="PATTERN"/>

</formatter>

</periodic-rotating-file-handler>

And ask JBoss to send those two exceptions to the separate file (which I prefer to avoid suppressing exceptions) :

</handlers>

</logger>

</handlers>

</logger>

After relaunching the server, the new file appears. I then use my JMeter script + very low timeout value to generate a timeout.

I see the two exceptions appear in the server.log file and my new log file remains empty.

I don't know how to make this work properly.

What I know is those two exceptions do happen in the library I am using which then does a rethrow of the first exception.

My try/catch does properly catch and identify the SocketTimeoutException

I want those two specific exceptions to be gone from the main server.log and moved to the new log.

I have been using such blocks to increase the level of logging of some Java classes :

</logger>

And when I change the level name I see that it works fine when I move it to DEBUG level, all my LOGGER.debug do appear in console.

So setting the category to the Java class name does work to set the logger debug level.

Been searching through Google and tried various attempts but nothing seems to work.

I am using WildFly Core 3.0.8.Final as Wildfly version.

The exceptions that do occur are reproduced below when a timeout does happen :

2019-11-04 11:03:29,638 WARN [keycloak.provider.rcu.backends.BackendsProxy] [email=XXXXX@yopmail.com] - login : exception occurred on calling target [http://XXXXX]: javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request

at org.jboss.resteasy.client.jaxrs.engines.ApacheHttpClient4Engine.invoke(ApacheHttpClient4Engine.java:317)

at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:442)

at org.jboss.resteasy.client.jaxrs.internal.ClientInvocationBuilder.post(ClientInvocationBuilder.java:199)

at fr.stime.itmc.keycloak.provider.rcu.backends.BackendsProxy.login(BackendsProxy.java:266)

at fr.stime.itmc.keycloak.provider.rcu.userstorage.RcuProxyUserStorageProvider.isValid(RcuProxyUserStorageProvider.java:307)

at org.keycloak.credential.UserCredentialStoreManager.isValid(UserCredentialStoreManager.java:114)

at org.keycloak.authentication.authenticators.browser.AbstractUsernameFormAuthenticator.validatePassword(AbstractUsernameFormAuthenticator.java:198)

at org.keycloak.authentication.authenticators.browser.AbstractUsernameFormAuthenticator.validateUserAndPassword(AbstractUsernameFormAuthenticator.java:171)

at org.keycloak.authentication.authenticators.browser.UsernamePasswordForm.validateForm(UsernamePasswordForm.java:56)

at org.keycloak.authentication.authenticators.browser.UsernamePasswordForm.action(UsernamePasswordForm.java:49)

at org.keycloak.authentication.DefaultAuthenticationFlow.processAction(DefaultAuthenticationFlow.java:92)

at org.keycloak.authentication.DefaultAuthenticationFlow.processAction(DefaultAuthenticationFlow.java:76)

at org.keycloak.authentication.AuthenticationProcessor.authenticationAction(AuthenticationProcessor.java:816)

at org.keycloak.services.resources.LoginActionsService.processFlow(LoginActionsService.java:284)

at org.keycloak.services.resources.LoginActionsService.processAuthentication(LoginActionsService.java:255)

at org.keycloak.services.resources.LoginActionsService.authenticate(LoginActionsService.java:251)

at org.keycloak.services.resources.LoginActionsService.authenticateForm(LoginActionsService.java:311)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)

at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)

at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)

at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138)

at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101)

at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406)

at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213)

at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228)

at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)

at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)

at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)

at org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:90)

at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)

at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)

at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)

at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)

at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)

at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)

at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)

at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)

at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)

at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)

at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)

at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)

at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)

at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)

at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)

at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)

at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)

at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)

at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)

at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)

at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)

at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)

at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)

at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)

at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)

at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)

at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)

at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)

at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)

at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)

at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)

at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)

at io.undertow.server.Connectors.executeRootHandler(Connectors.java:326)

at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

at java.lang.Thread.run(Thread.java:748)

Caused by: java.net.SocketTimeoutException: Read timed out

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

at java.net.SocketInputStream.read(SocketInputStream.java:171)

at java.net.SocketInputStream.read(SocketInputStream.java:141)

at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)

at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)

at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)

at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)

at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)

at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261)

at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:165)

at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272)

at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124)

at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271)

at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184)

at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88)

at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)

at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)

at org.jboss.resteasy.client.jaxrs.engines.ApacheHttpClient4Engine.invoke(ApacheHttpClient4Engine.java:313)

... 74 more