Why are there 405's on prod?
Opened this issue · 0 comments
Only on the production server do I occasionally see the following log:
HTTP 405 Method Not Allowed
2023-01-24 10:36:43.814 [qtp544239216-766] WARN o.a.cxf.jaxrs.impl.WebApplicationExceptionMapper - javax.ws.rs.ClientErrorException: HTTP 405 Method Not Allowed efileproxyserver-efspjava-1 | at org.apache.cxf.jaxrs.utils.SpecExceptions.toHttpException(SpecExceptions.java:117) efileproxyserver-efspjava-1 | at org.apache.cxf.jaxrs.utils.ExceptionUtils.toHttpException(ExceptionUtils.java:168) efileproxyserver-efspjava-1 | at org.apache.cxf.jaxrs.utils.JAXRSUtils.findTargetMethod(JAXRSUtils.java:633) efileproxyserver-efspjava-1 | at org.apache.cxf.jaxrs.interceptor.JAXRSInInterceptor.processRequest(JAXRSInInterceptor.java:182) efileproxyserver-efspjava-1 | at org.apache.cxf.jaxrs.interceptor.JAXRSInInterceptor.handleMessage(JAXRSInInterceptor.java:79) efileproxyserver-efspjava-1 | at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) efileproxyserver-efspjava-1 | at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) efileproxyserver-efspjava-1 | at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) efileproxyserver-efspjava-1 | at org.apache.cxf.transport.http_jetty.JettyHTTPDestination.doService(JettyHTTPDestination.java:247) efileproxyserver-efspjava-1 | at org.apache.cxf.transport.http_jetty.JettyHTTPHandler.handle(JettyHTTPHandler.java:79) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:190) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.Server.handle(Server.java:516) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) efileproxyserver-efspjava-1 | at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
Unfortunately, this doesn't give any information: what IP address? what endpoint? is it just spam? I have no idea.
I spent a ridiculously long time trying to figure out how to actually log this with CXF/Jetty/JAX-RS, and came up with only one solution: adding the following to logback.xml.
<logger name="org.eclipse.jetty" level="DEBUG"/>(source is from the [jetty documentation](https://www.eclipse.org/jetty/documentation/jetty-11/operations-guide/index.html#og-server-logging, and figuring out to get that in jetty).
This adds a lot of extra debug logs, so we'll need to find a quiet day when we can swap the server to log debug jetty things, and only keep it up enough to see one of these 405s.
An option that didn't work was adding a LogEventSender: for some reason, the log happens after the request is filled, which means that the 405 happens before we can log it, and the 405 event we get to log doesn't contain any useful information about the request (Address / path is null, so is the HttpMethod).