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.

[joozik]

I have the same issue with long polling. With this property set to t average page load time is ~4.5 sec, with long polling set to nil it is down to ~250ms. I was trying the tutorials 30 and 31 when deployed to the server with reverse proxy and ssl enabled. Page load time is the same for all routes ("/", "/about" etc.). Locally (without ssl) there is no issue.

[rabbibotton]

I have made further changes to improve caching that should improve this when used as well. Also the builder supports direct addition of ParaScript and JavaScript client side events.

[joozik]

I just checked on my private server but the situation did not improved for :long-poll-first t setting - still really fast loading without long polling enabled but now it takes more than 8 seconds when I enable long polling... and it it consistent for all pages each time. I tried with home, about etc. multiple times and always the same results.

The software version that I run this tutorial on was rabbibotton-clog-20240717144536 from ultralisp and quite old sbcl version available currently on this server which is SBCL 2.1.11.debian. Again additional setup is reverse proxy with ssl through nginx.

In browser console I still get this error Uncaught DOMException: Failed to execute 'send' on 'WebSocket': Still in CONNECTING state. but now it is appearing twice so I guess that is why loading page time is 2x longer now.

[rabbibotton]

Distance physically between server and client?

…

On Thu, Jul 18, 2024, 12:43 AM Józef Piątkiewicz ***@***.***> wrote: I just checked on my private server but the situation did not improved for :long-poll-first t setting - still really fast loading without long polling enabled but now it takes more than 8 seconds when I enable long polling... and it it consistent for all pages each time. I tried with home, about etc. multiple times and always the same results. The software version that I run this tutorial on was rabbibotton-clog-20240717144536 from ultralisp and quite old sbcl version available currently on this server which is SBCL 2.1.11.debian. Again additional setup is reverse proxy with ssl through nginx. In browser console I still get this error Uncaught DOMException: Failed to execute 'send' on 'WebSocket': Still in CONNECTING state. but now it is appearing twice so I guess that is why loading page time is 2x longer now. — Reply to this email directly, view it on GitHub <#186 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACYUEFJFXCZ45X2DWSOCL5TZM3QQVAVCNFSM54Q6BJHKU5DIOJSWCZC7NNSXTN2JONZXKZKDN5WW2ZLOOQ5TEMRTGQZTOMRXGU4A> . You are receiving this because you commented.Message ID: ***@***.***>

[joozik]

between me and datacenter something like 400km so I guess around ~200 miles? But when changing long-poll-first to nil with everything else exactly the same the loading time is few hundred of miliseconds (right now usually 200ms) so it can not be distance fault cause it would affect this site when run with long-poll-first nil as well in some significant way.

[joozik]

on server there are still those multiple logs about awaiting connection
... Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 HTML connection closed - 4be35fd322715ce8b26708f8f024a9b5 Reconnection id - 4be35fd322715ce8b26708f8f024a9b5 to #<SERVER {100926E163}> New html connection id - 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 HTML connection closed - 0a63b195b42f83080b67f18ac7e2b3c8 Reconnection id - 0a63b195b42f83080b67f18ac7e2b3c8 to #<SERVER {1009335473}> ...

[rabbibotton]

Agreed, I wanted to rule that out. Sounds like a regression in long polling. I return to the US Monday if have time on rode will work on, if not next week, but will get it solved.

It is probably not related to this ticket which has to do with excessive latency issues overall.

Hopefully we succeed on reducing both by next week.

[rabbibotton]

Very helpful thanks!

…

On Thu, Jul 18, 2024, 1:07 AM Józef Piątkiewicz ***@***.***> wrote: on server there are still those multiple logs about awaiting connection ... Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 Awaiting websocket connection for 4be35fd322715ce8b26708f8f024a9b5 HTML connection closed - 4be35fd322715ce8b26708f8f024a9b5 Reconnection id - 4be35fd322715ce8b26708f8f024a9b5 to #<SERVER {100926E163}> New html connection id - 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 Awaiting websocket connection for 0a63b195b42f83080b67f18ac7e2b3c8 HTML connection closed - 0a63b195b42f83080b67f18ac7e2b3c8 Reconnection id - 0a63b195b42f83080b67f18ac7e2b3c8 to #<SERVER {1009335473}> ... — Reply to this email directly, view it on GitHub <#186 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACYUEFPMUEZDN7H4JPX2OU3ZM3TKRAVCNFSM54Q6BJHKU5DIOJSWCZC7NNSXTN2JONZXKZKDN5WW2ZLOOQ5TEMRTGQ2DENJRGM2Q> . You are receiving this because you commented.Message ID: ***@***.***>

[joozik]

happy to help with testing anytime :)