Undertow adapter error in logs

[danielsz]

Hi,

I am seeing the following error in my logs. It props up consistently, but I haven't figured out yet what causes it. It doesn't seem to be related to application code. That's what I take away from the stack trace.
The Ring adapter for the Undertow web server in my deps.edn is luminus/ring-undertow-adapter.

Feb 26 19:18:58 asher java[4144420]: 19:18:58.399 [XNIO-1 task-4] ERROR io.undertow.request - UT005071: Undertow request failed HttpServerExchange{ GET /chsk}
Feb 26 19:18:58 asher java[4144420]: java.lang.UnsupportedOperationException: Body class not supported: class clojure.lang.Keyword
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow.response$fn__25971.invokeStatic(response.clj:46)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow.response$fn__25971.invoke(response.clj:14)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow.response$fn__25944$G__25939__25951.invoke(response.clj:11)
Feb 26 19:18:58 asher java[4144420]:         at taoensso.sente.server_adapters.community.undertow$fn__30134.invokeStatic(undertow.clj:76)
Feb 26 19:18:58 asher java[4144420]:         at taoensso.sente.server_adapters.community.undertow$fn__30134.invoke(undertow.clj:73)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow.response$fn__25944$G__25939__25951.invoke(response.clj:11)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow.response$set_exchange_response.invokeStatic(response.clj:59)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow.response$set_exchange_response.invoke(response.clj:52)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow$handle_request.invokeStatic(undertow.clj:23)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow$handle_request.invoke(undertow.clj:19)
Feb 26 19:18:58 asher java[4144420]:         at ring.adapter.undertow$undertow_handler$fn$reify__26028.handleRequest(undertow.clj:41)
Feb 26 19:18:58 asher java[4144420]:         at io.undertow.server.session.SessionAttachmentHandler.handleRequest(SessionAttachmentHandler.java:68)
Feb 26 19:18:58 asher java[4144420]:         at io.undertow.server.Connectors.executeRootHandler(Connectors.java:393)
Feb 26 19:18:58 asher java[4144420]:         at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859)
Feb 26 19:18:58 asher java[4144420]:         at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
Feb 26 19:18:58 asher java[4144420]:         at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
Feb 26 19:18:58 asher java[4144420]:         at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
Feb 26 19:18:58 asher java[4144420]:         at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
Feb 26 19:18:58 asher java[4144420]:         at java.base/java.lang.Thread.run(Thread.java:829)

[ptaoussanis]

@danielsz Hi Daniel,

It'd be helpful to have some more context - incl.:

• What version of Sente are you running?
• Has this error always occurred, or is it new?
• If new, has anything relevant recently changed?
• Is the reference example project show the same issue with your chosen deps?

Feb 26 19:18:58 asher java[4144420]: java.lang.UnsupportedOperationException: Body class not supported: class clojure.lang.Keyword
Feb 26 19:18:58 asher java[4144420]: at ring.adapter.undertow.response$fn__25971.invokeStatic(response.clj:46)
Feb 26 19:18:58 asher java[4144420]: at ring.adapter.undertow.response$fn__25971.invoke(response.clj:14)

From the error, it sounds like Undertow might be encountering a keyword as a Ring response (i.e. rather than the usual Ring response map, etc.). Is it possible you have middleware or some other handler that could unexpectedly return a keyword?

[danielsz]

Thank you, Peter. I'll investigate and report back asap.

[danielsz]

Hi Peter,

I finally have more information to report. Sorry about the wait.
Firstly, answering your questions, I'm on the latest version of Sente, and I think I've seen the problem since I switched to using Undertow and the Undertow community adapter. In order to test this issue, I've forked the Undertow community adapter and added some print debugging to points of interest. Lo and behold, we've got answers. The issue seems to revolve around what is being returned when an ajax timeout occurs.

Apr 02 23:04:50 asher java[2164444]: 23:04:50.718 [XNIO-1 task-6] DEBUG sapiens.adapter - (if ajax-resp-timeout-ms
Apr 02 23:04:50 asher java[2164444]:   (deref resp-promise_ ajax-resp-timeout-ms ajax-resp-timeout-val)
Apr 02 23:04:50 asher java[2164444]:   (deref resp-promise_))
Apr 02 23:04:50 asher java[2164444]: => "[:chsk/timeout]"
Apr 02 23:04:54 asher java[2164444]: 23:04:54.641 [XNIO-1 task-4] DEBUG sapiens.adapter - (if ajax-resp-timeout-ms
Apr 02 23:04:54 asher java[2164444]:   (deref resp-promise_ ajax-resp-timeout-ms ajax-resp-timeout-val)
Apr 02 23:04:54 asher java[2164444]:   (deref resp-promise_))
Apr 02 23:04:54 asher java[2164444]: => :undertow/ajax-resp-timeout
Apr 02 23:04:54 asher java[2164444]: 23:04:54.643 [XNIO-1 task-4] ERROR io.undertow.request - UT005071: Undertow request failed HttpServerExchange{ GET /chsk}
Apr 02 23:04:54 asher java[2164444]: java.lang.UnsupportedOperationException: Body class not supported: class clojure.lang.Keyword

Is this starting to make sense? Please feel free to instruct me further.

[ptaoussanis]

Hi Daniel, thanks for the extra info (and debugging!).

Could it be that the Undertow adapter expects this value to be a standard Ring response (e.g. map)?

I'm not sure why the default is a keyword, but it could be the intention was for that to be replaced (either in config, or by middleware, etc.)?

If so, that's definitely unclear - sorry about that! If you can confirm that this is the source of your error, I'll dig into this a bit more next time I'm on batched Sente work. Will need to check the Undertow source/docs. If this does indeed need to be a proper Ring response, we can warn about that at the time the adapter is built.

[danielsz]

A fix is coming.

Yes, since we're not the author, second guessing is the best we can do. After carefully reading the source code of both the Undertow community adapter for Sente and the Ring adapter for which it was written, my interpretation is that we're dealing with an abstraction leak. You see, a Clojure promise was chosen to back up Sente's ajax channel, the code path taken when (:websocket? ring-req) is false.
If the exchange completes within the timeout, the promise will have a message to deliver, but if it doesn't, it would block forever when dereferenced, unless called with the 2-arity version of deref.

The variant taking a timeout can be used for blocking references (futures and promises), and will return
timeout-val if the timeout (in milliseconds) is reached before a value is available.

A 2-arity version of deref is therefore used, but the only return value that makes sense in the case of a timeout is one that would result in terminating the exchange. And for that to happen the return value needs to be a nil. Giving the user a choice doesn't make sense in this scenario.

This is the best of my understanding at this point. I could be wrong in so many ways (as always). However, I have uploaded a patched version on my production server in order to test my assumptions. If the logs remain clean over time, I would be able to submit a PR with increased confidence. Please let me know if that's all right with you. Thank you!

[danielsz]

The fix has run on my production servers for a couple of days. No more errors.

When a timeout occurs on ajax-read!, this is the debug output.

2024-04-08_13:04:25.04541 [XNIO-1 task-11] DEBUG a.helpers.sente-undertow-adapter - (if ajax-resp-timeout-ms
2024-04-08_13:04:25.04544   (deref resp-promise_ ajax-resp-timeout-ms nil)
2024-04-08_13:04:25.04544   (deref resp-promise_))
2024-04-08_13:04:25.04544 => nil

Returning nil terminates the exchange, and that's that. Would you be interested in a PR? Please let me know. Thank you!

[ptaoussanis]

@danielsz Hi Daniel, thanks for the investigation on this - and for reporting back your findings. PR very welcome, thanks! 🙏

[ptaoussanis]

Merging #445 in a moment, closing 👍 Thanks again for the report and fix!