InvalidStateError and slow page loading speed when long-poll-first is t on a deployed website (localhost is fine)

[shakatoday]

Brief

On a deployed website (localhost is fine) when long-poll-first is t

1. Browsers got InvalidStateError 2. loading speed is super slow 3. semaphore type error on Lisp side.

Sample program: CLOG tutorial 32
Operating System: FreeBSD 13.1
Browser: Safari 15.5, Microsoft Edge 103.0.1264.71 (Official build) (arm64)
CL Implementation: sbcl 2.2.0

Error messages and speed

REPL

Condition caught in handle-message - The value
                                       NIL
                                     is not of type
                                       SB-THREAD:SEMAPHORE
                                     when binding SB-THREAD:SEMAPHORE.

Safari screenshots

Microsoft Edge screenshots

[rabbibotton]

When long polling is done, websockets are still used for events. It appears that the connection is not being established or still in a state waiting to establish. I will look in to it today. Thanks!!! Let you know soon about it.

[rabbibotton]

Does this error occur on the first query for a property of the site?
How often does it occur?
Does the same error occur on other servers? With other browsers?

The main purpose of long polling is to allow for search engine indexing. If your use case is different let me know, as perhaps there may be additional ideas I can offer.

[rabbibotton]

Can you send me the log also from your REPL if that is a possibility, I just need the initialize to the failure.

[rabbibotton]

If running a new set if logs, if can use the current git head. By the way I noticed now that the ID fix I made on your last ticket was not being used for long polling. That has been fixed as well.

[rabbibotton]

I have made a change to long polling. Using :long-poll-first :extend gives the previous behavior, long polling continues to run until the on-new-window handler is completed. :long-poll-first t will the stop long polling on first query made to browser. Leaving long-polling on creates the appearance that the site is still loading and its chief goal is for search engine crawling that is better served by keeping it short and the main data upfront.

[rabbibotton]

I changed the default behavior back for the :long-poll-first parameter but now can specify how many requests made to browser before stopping to long-poll.

[shakatoday]

Updated my tests today here.

Key observations

It required more than 15 seconds to load the page when I put the website behind a nginx proxy. (I had always done this before my tests today on this issue)
However, when I directly access to the CL web server via browsers, the required time reduced to around 6 seconds.

Environments

Sample program: CLOG tutorial 32
Server-side Operating System: FreeBSD 13.1, Amazon Linux 2022 preview, Ubuntu Linux 22.04 LTS
Server-side reverse proxy: nginx
Server-side CL web server: Hunchentoot (haven't used Woo to speed up)
Server-side CL implementation: sbcl 2.2.0 on FreeBSD 13.1, sbcl 2.2.6 on Linux

Client-side browsers: Safari 15.5, Microsoft Edge 103.0.1264.71 (Official build) (arm64), FireFox 102.0.1 (64-bit), Chrome 103.0.5060.134 (Official Build) (arm64)

Server location: Oregon, USA. (hosted on AWS)
Client location: Taipei, Taiwan. (That is, there must be kind of significant latency difference compared with localhost or same country Internet routes)

Server-side Logs

CL-USER> (setf clog-connection::*verbose-output* t)
T
CL-USER> (clog:run-tutorial 32) ; I removed (open-browser) at the end of START-TUTORIAL


 ---- The tutorial src is located at: /home/ubuntu/.roswell/local-projects/rabbibotton/clog/./tutorial/32-tutorial.lisp
Database location: /home/ubuntu/.roswell/local-projects/rabbibotton/clog/tut-32.db
Hunchentoot server is started.
Listening on 0.0.0.0:8080.
HTTP listening on    : 0.0.0.0:8080
HTML root            : /home/ubuntu/.roswell/local-projects/rabbibotton/clog/static-files/
Long poll first      : yes
Boot function added  : yes
Boot html source use : compiled version, when no file
Boot js source use   : compiled version
Boot file for path / : /boot.html
NIL
New html connection id - 1933909815
Start new window handler on connection-id - 1933909815Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
Awaiting websocket connection for 1933909815
HTML connection closed - 1933909815
Reconnection id - 1933909815 to #<SERVER {100410A0E3}>
1933909815 Ping
1933909815 Ping
1933909815 Ping
1933909815 Ping
1933909815 Ping

[shakatoday]

Does this error occur on the first query for a property of the site?

Sorry I didn't test whether it is the "first query for a property" or not.

How often does it occur?

In the case of tutorial 32 given my environments it was very regular. 2~4 (usually 2) client-side errors if behind the nginx reverse proxy; Exactly 1 if not behind the nginx reverse proxy.

If you mean how often does this behavior in a whole appear: every time when using the browser to open a url routing (new ws connection I guess).

Does the same error occur on other servers? With other browsers?

Updated the info on my previous comments

The main purpose of long polling is to allow for search engine indexing. If your use case is different let me know, as perhaps there may be additional ideas I can offer.

Thanks. My use case I think I will just make a static homepage for search engines. :)

[rabbibotton]

Logs:
1 Awaiting message is expected in most cases, but any more means delays in establishing the websocket to is still reasonable. In the log you sent, it is actually giving up, i.e. it is hot happening. That usually is a configuration issue with a proxy.

<<Thanks. My use case I think I will just make a static homepage for search engines. :)>>

You can also make your static front page and then add boot.js if need for additional functionality on it and server it also through the CLOG app. I personally think that is always the better solution as can tailor the SEO properly. This also allows me to not use long-poll at all.

Do you see any issues when not running long-poll?

[shakatoday]

Logs: 1 Awaiting message is expected in most cases, but any more means delays in establishing the websocket to is still reasonable. In the log you sent, it is actually giving up, i.e. it is hot happening. That usually is a configuration issue with a proxy.

Thank you I'm trying the reverse proxy configuration.

<<Thanks. My use case I think I will just make a static homepage for search engines. :)>>

You can also make your static front page and then add boot.js if need for additional functionality on it and server it also through the CLOG app. I personally think that is always the better solution as can tailor the SEO properly. This also allows me to not use long-poll at all.

Do you see any issues when not running long-poll?

No problem if long-poll-first set to nil, even behind nginx the page loading time was only around 1 second in the case of CLOG tutorial 32. Not quick enough for a website but I think there are many other ways to optimize it (static resources, switching to woo, CDN, server locations, etc).

Thanks. :)

For this opened issue itself......I don't know we can call it resolved or not because even without reverse proxy the page loading time with :long-poll-first set to t could probably be too long (around 6 seconds) compared with :long-poll-first set to nil (around 1 second). I think your patch is good enough (since now developers can specify how many requests made to browser before stopping long-poll.) However, I guess the manual, tutorial, API, default value, or wiki can be further tuned to help other people not encounter similar situations. Maybe the easiest way is to set a default value for the number of requests made to browsers before stopping long-poll?

Thanks again!

[rabbibotton]

BTW, do you have issues reaching clogpower.com that is running long-polling on internet (reverse proxy running on apache)?

[shakatoday]

BTW, do you have issues reaching clogpower.com that is running long-polling on internet (reverse proxy running on apache)?

Yes, I have. Unfortunately from my browsers (and network distance?) clogpower.com behaves similar to my experiments on tutorial 32. The page loading time were around 5 seconds (sometimes it's faster). I think that means if I configure nginx correctly, the page loading time can be reduced to similar range.

Browsers: Safari 15.5, Microsoft Edge 103.0.1264.71 (Official build) (arm64), FireFox 102.0.1 (64-bit), Chrome 103.0.5060.134 (Official Build) (arm64)

Feel free to tell me if there's anything I can provide.

Screenshots

Safari

FireFox

Google Chrome

Microsoft Edge

Google PageSpeed Insights

It shows Failed Document Requests.
This should be more important than what I see on my browsers?

[rabbibotton]

That helps. What I want to know is once the websocket connection is made are there still delays on that order of time.

I'll try and see if I can put together soon some logging and a sample we can figure that out with.

That will let us know if the issue is the network latency overall or latency only in establishing the websocket. Then we can figure how to work around the delays since we know the issues are all latency related.

[rabbibotton]

If you are not using long polling are you still seeing significant delays? While clearly this is all a latency issue and worse because of the initial round trips for local storage requests, I am curious if there are any issues when using the regular websocket from start.

[shakatoday]

I don't see significant delays if not using long polling. Is there anything I can further help you with?

Btw, the code I switched the auth from localStorage to server-side sessions by cookies is here. I won't do it recently but I'll figure out a way for clog websocket servers to directly access the corresponding lack sessions. It can not only remove the call to document.cookie but also save the initial round trips for auth.