New throwing behavior of ajax-read

[danielsz]

Sente will throw an error when an ajax timeout occurs. This behavior was introduced recently, with 9da662c.

This is a reasonable decision, however I would like to make a couple of comments and raise a couple of questions.

1. Most of the ajax timeouts I am seeing result from stale connections due to prolonged inactivity, for example, myself coming back to the browser after my laptop resumed from sleep. This cause for the error I consider benign.
2. Logs on a busy production server will show many of those uncaught errors over time.
3. We should probably explain that this is going to happen in the README, and show how to catch the error and where. Examples should be given.
4. The ex-data for now contains only the value of :timeout-msecs. It should be enhanced with data from the request such as its origin. Presumably available from the function argument sch but I am currently blanking as to what and how much information can be recalled from that.

Another perspective on this is the following:

• Do not throw the error by default, but as an opt-in setting in Sente's constructor.
• Motivation is quality of life for the developer.
• The assumption here is that most readout errors are harmless and more importantly, unrecoverable.
• Throwing the error is probably reserved for debugging.

That's it from me as for this issue. I'll be happy to hear what you all think.

[ptaoussanis]

@danielsz Hi Daniel, thanks for the considered feedback! 🙏

Sente will throw an error when an ajax timeout occurs

Just to clarify- this isn't Sente behaviour, but behaviour of some of the community adapters.

Unfortunately there's a recurring challenge that tends to occur with community adapters. An adapter will get submitted and included, but then the underlying server changes at some point - or there's some other motivation to make a change.

Then the original author/s are no longer available, and it falls on the community or me to try and maintain adapters for servers that we might not use or be familiar with.

An alternative would be to remove these 3rd-party adapters, to encourage potential authors to setup and maintain their own repo if there's interest. But in practice that of course also involves tradeoffs, and would probably mean reduced adapter availability.

This is something I'll reconsider for a future v2 though.

Anyway, on the present issue:

• It's super helpful and very much appreciated to get detailed experience reports like this from folks actually using a particular server + adapter - thank you for that!

• Apologies if the current behaviour isn't ideal!

• I'm very, very open to PRs or ideas for how these adapters can be improved. Unfortunately it looks like it hasn't been very clear how best to handle this particular topic (Ajax timeouts for the Jetty and Undertow adapters).

On your specific thoughts:

Most of the ajax timeouts I am seeing result from stale connections due to prolonged inactivity, for example, myself coming back to the browser after my laptop resumed from sleep. This cause for the error I consider benign.

That does sounds like something that probably shouldn't be throwing an exception 👍

I'm not sure off-hand how http-kit handles these cases, that could informative (or conversely could show that http-kit's doing something worse ^^).

We should probably explain that this is going to happen in the README, and show how to catch the error and where. Examples should be given.

This sounds good to me if no better alternative behaviour exists that'd altogether avoid the need for catching and concern about this.

I've been juggling a lot lately, and the added lack of familiarity with the involved servers means that I haven't had an opportunity to properly dig into understanding this topic myself yet.

My hope has been that someone more familiar with the relevant servers could propose either:

• An improvement to the server adapter/s, or
• A clear description of some improvement needed from Sente or its interfaces to enable an improvement to the server adapter/s

Do not throw the error by default, but as an opt-in setting in Sente's constructor.

Just to add context, the reason for the present behaviour (to explicitly throw) - was a recent discussion where it was suggested that the prior behaviour (to not explicitly throw) was effectively anyway leading to exceptions, just non-specific ones that were difficult to identify.

So the hope was that 9da662c would be at least no worse, but hopefully clearer.

But again, I'm not in a good position to advise on this without much time spent digging. I'm definitely keen on concrete counter suggestions!

What'd be a good alternative to throwing, that wouldn't end up just percolating to a non-specific exception?

[danielsz]

Thank you, Peter. If proceeding step by step sounds like a good strategy, I would like to start with the question as to what is Sente's expected/desired behavior in the case discussed above, ie. when the user reopens his laptop, which I suppose boils down to loses network connectivity and regains it.

[ptaoussanis]

You're welcome Daniel, thanks for looking into this 👍

what is Sente's expected/desired behavior in the case discussed above, ie. when the user reopens his laptop, which I suppose boils down to loses network connectivity and regains it

That's a good question to start 👍 Unless I'm missing something obvious (very possible), I can't think of any specific reason why one would ever need or want to specifically handle connection-level timeouts on the server-side.

Sente's request API offers:

1. Client->server request (with/out ack)
2. Server->user broadcast

For (1) the client just needs to know if the request was successful or not.

For (2) we don't need any particular confirmations. And if we did, this'd currently need to be handled manually by sending an ack event from the user's client/s after they've received the broadcast.

Where exactly are these timeout exceptions being thrown? Presumably during (1) in Ajax mode, when something with the connection went bad?

If so, that seems to me like a failure that can just be logged at a trace level and otherwise silently ignored.

Unless I'm missing something, this would be neither an exceptional nor actionable occurrence.

From the client's perspective, the relevant Ajax request would just timeout - triggering the usual client-side failed-request flow. And if the client's connection has gone bad, the client will attempt to reconnect.

What do you think?

[danielsz]

OK, so I have something new to report in my investigation of these ajax timeouts being thrown. Or rather, something new to describe, namely the pattern of these timeout errors in the production logs. I would like to reiterate that Sente is working flawlessly, even with a community adapter. OK, with that out of the way, here it goes:
A request comes in, immediately triggers an ajax timeout, and then the same timeout repeats every 20 seconds. And this lasts for a couple of hours. That's all I got.
To me it sounds that the client never sees or experiences the homepage at all. Is this a broken bot? An older device? What comes to mind?

[ptaoussanis]

@danielsz Thanks for the extra info Daniel! Nothing obvious comes to mind right away, but I'll take a close look to this when I'm next on batched Sente work 👍

In the meantime, in case it's easy - it might be helpful if you could try collect other info about these requests (e.g. HTTP User Agent header, etc.).

[danielsz]

Excellent suggestion.

User Agent: Mozilla/5.0 (Linux; Android 6.0.1; Nexus 5X Build/MMB29P) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/134.0.6998.165 Mobile Safari/537.36 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)

Mozilla/5.0 (Linux; Android 7.0; SM-G930V Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.125 Mobile Safari/537.36 (compatible; Google-Read-Aloud; +https://support.google.com/webmasters/answer/1061943)

Both IPs' ASN is Google's.

Bots, crawlers and fetchers.

[ptaoussanis]

@danielsz Hi Daniel, I hope you're well!

I'm busy switching focus to Sente, and hope to cut a new release of Sente in the next week or so. Just checking if there's any update/recommendation on this issue from your end?

Thanks! 🙏

[danielsz]

Okay, quick recap. When bots scrape a Sente-enabled website, an error will be thrown. The properties of this error is that it is not actionable. The app code cannot try/catch it. The reason for the error is because bots scrape the Internet. All this to say that I don't want to see the error in my logs. I like clean log files with errors that are relevant to the app. So I am running an adapter that is identical to the one that ships with Sente, except for line 62:

(if (= resp ::timeout)
  (throw (ex-info "Ajax read timeout" {:timeout-msecs ajax-resp-timeout-ms})))
  resp)

I have the throw replaced with a log/debug.
My recommendation? Give the user the option to decide what to do with timeout errors. I think I know how to do this. Shall I prepare a PR?

[ptaoussanis]

Hey Daniel, thanks for the recap! 👍

The properties of this error is that it is not actionable.
My recommendation? Give the user the option to decide what to do with timeout errors.

Do you believe it'd ever be actionable, besides just deciding whether to log or not? It seems not, right?

If that's the case then I'd suggest that instead of making this configurable in some sort of explicit way - we instead just add a debug-level log here that can be suppressed through normal log filtering.

What do you think?

If you agree and felt like doing this, I'd be happy to see a PR that adds debug-level logging to the two relevant appenders. Or you can leave it to me, since I'll anyway need to change all log calls shortly to move them to a facade to drop the dependency on Timbre and add support for structured logging tools.

Thanks again for your assistance and patience on this!

[danielsz]

Yes, I think it makes sense to just debug log it. This error is not actionable.

My initial plan was to have this:

(defn get-sch-adapter
  "Returns a Sente `ServerChan` adapter for `ring-undertow-adapter` [1].

  Options:
     `:ajax-resp-timeout-ms` - Max msecs to wait for Ajax responses (default 60 secs),
                               exception thrown on timeout.

  [1] Ref. <https://github.com/luminus-framework/ring-undertow-adapter>."
  ([] (get-sch-adapter nil))
  ([{:as   opts
     :keys [ajax-resp-timeout-ms timeout-throw-fn]
     :or   {ajax-resp-timeout-ms (* 60 1000)
            timeout-throw-fn #(throw (ex-info "Ajax read timeout" {:timeout-msecs (* 60 1000)}))}}]

   (UndertowServerChanAdapter.
     (assoc opts
       :ajax-resp-timeout-ms ajax-resp-timeout-ms :timeout-throw-fn timeout-throw-fn) )))

And then later, this:

(ajax-read! [sch]
    (let [{:keys [ajax-resp-timeout-ms timeout-throw-fn]} adapter-opts
          resp
          (if ajax-resp-timeout-ms
            (deref resp-promise_ ajax-resp-timeout-ms ::timeout)
            (deref resp-promise_))]

      (if (= resp ::timeout)
        (timeout-throw-fn)
        resp)))

But it's kind of silly because there is not much to do or to report in the first place.
I think your plan is better. Just debug log it and integrate it with whatever you have in store with the façade for structured logging.

[danielsz]

For the sake of completeness, I will say that when bots scrape a website with Sente and cause the timeout, the output of debug log is the following:

Ajax read timeout #promise[<pending>] #atom[true] #function[taoensso.sente/make-channel-socket-server!/ring-handler--27338/on-close--27369]

Generated by the code below:

(ajax-read! [sch]
    (let [{:keys [ajax-resp-timeout-ms]} adapter-opts
          resp
          (if ajax-resp-timeout-ms
            (deref resp-promise_ ajax-resp-timeout-ms ::timeout)
            (deref resp-promise_))]

      (if (= resp ::timeout)
        (log/debug "Ajax read timeout" resp-promise_ open?_ on-close)
        resp)))

[ptaoussanis]

Great, thanks Daniel! I'll then take care of updating the 2x adapters for the next release 👍👍 Will keep this issue open till then.