[Background reports] Infinite loader

[RachL]

Description

A test scenario which end up with an infinite loader for the user.

Steps to Reproduce

1. Go to https://coopcircuits.fr/admin/reports/packing/customer as hub 922 or super admin with hub 922 as filter
2. Change start date for January &st 2023 (keep end date as is)
3. Ask for xlsx file
4. See you get an email after 3 minutes with the file, while the report page still shows the loader

Severity

S3 as we get the email in the end

Your Environment

• Version used: v4.4.17
• Browser name and version: Firefox and chrome
• Operating System and version (desktop or mobile): desktop

[RachL]

@mkllnk FYI I've reproduced it. Can it be linked to the number of reports run in parallel/at the same time?

[mkllnk]

I've reproduced it.

Great, how?

Can it be linked to the number of reports run in parallel/at the same time?

Are you running multiple reports in the same tab? I would need to look into that. Hm, no, you can't be running another report because you are waiting for the first one in that tab. But maybe you are running another one in another tab. It should work though. Let me know how I can reproduce it and then I may find the culprit.

[RachL]

@mkllnk same scenario that is in the issue. Only one tab opened. However this scenario passes if I'm trying during low hours (evening for example). So maybe when you try on your timezone it will always work?

I guess maybe this one we can't fix it atm and we need to have more occurrences before we can do something.

[mkllnk]

Interesting, I just tried to load that report and I didn't even see the loading screen. The console gave me a hint though:

The connection to wss://coopcircuits.fr/cable was interrupted while the page was loading.

The site was generally very slow.

[mkllnk]

Nothing in Bugsnag. The report format doesn't matter, by the way.

[mkllnk]

I also didn't need the big date range. The default of one month still triggered the problem.

Firefox used to have a bug related to the error message here and I tried the suggested workaround by changing the Firefox option to false but it didn't help:

network.http.http2.websockets

[mkllnk]

I haven't gotten a single report rendered in the browser yet. The connection is slow but the server is not busy. It's only 5am in France now. UK staging works without any problem. AU production works without problem. There's something weird about the websocket connection.

[mkllnk]

fr_prod is the only server with increased puma workers and threads. I tried setting it back to our default but that didn't change anything.

[mkllnk]

I was wondering what's different about fr_prod. It runs Ubuntu 20 which is otherwise only used by India and New Zealand. On nz_prod I found intermittent problems as well.

When I load the page, there's one cable connection initiated straight away. Another cable connection is request is send several seconds later. If I try to render the report before the second request, nothing happens. But if I do it after the second request, the loading indicator comes up and then the report.

I still need to find out how to debug websockets properly.

[mkllnk]

Turns out that Firefox doesn't have the messages tab in my dev tools. 🤷 Chromium has it though. I got the loading message and plenty of ping messages but when the report finished, it didn't get sent to the browser even though the scoped channel was connected properly.

[mkllnk]

There's a weird thing that the browser is subscribing twice to the channels. And it's in different order.

uk-staging (success):

fr-prod (fail):

[mkllnk]

I have to stop here for now. Ideas for investigation:

• Why does fr-prod initiate the session channel straight away and the scoped channel has to wait until the page is loaded while uk-staging does it the other way round?
• Could the asset compilation make a difference?
• Are we loading some JS twice?
• Could a firewall make a difference?

[dacook]

@rioug found this:
WebSocket error occurred: Broken pipe in the logs : https://discuss.rubyonrails.org/t/getting-a-broken-pipe-error-with-websockets/80841 Points toward an issue with our redis config, also mentioned in the stackoverflow link above. I reckon we should start with that.

Also my investigations of the logs on au_staging for the bulk products screen:
StimulusReflex issues (WebSocket broken pipe)

[rioug]

This has an example of the redis config to potentially fix the issue : https://stackoverflow.com/questions/76255963/rails-actioncable-sporadically-failing-to-subscribe

[rioug]

I had a look at the solution offered in the link above, I tried increasing the number of Redis connection as explained but it broke :

New unhandled error in staging from OpenFoodNetwork Aus in gems/redis-client-0.20.0/lib/redis_client/config.rb:21 (details)
Unhandled error
ArgumentError: unknown keyword: :pool_size
Location
gems/redis-client-0.20.0/lib/redis_client/config.rb:21 - initialize

I had a look at the various gem we use, redis-client does support a connection pool via connection_pool gem , see https://github.com/redis-rb/redis-client?tab=readme-ov-file#usage. But the 'redis' gem doesn't seem to be using it. Instead they recommend the following https://github.com/redis/redis-rb?tab=readme-ov-file#connection-pooling-and-thread-safety

I tried to use the redis-client connection pool directly via redis but it broke. So I ended up trying this patch, adding a ConnectionPool::Wrapper when initialising the redis client

# @client = initialize_client(@options)
@client = ConnectionPool::Wrapper.new(size: 50, timeout: 3) { initialize_client(@options) }

https://github.com/redis/redis-rb/blob/7cc45e5e3f33ece7e235434de5fbd24c9b9d3180/lib/redis.rb#L73
It didn't break ! but I doesn't seem to fix our problem. I feel like I am chasing the wrong issue.

Further idea to try:

• look at our proxy timeout as explained here : https://stackoverflow.com/questions/76255963/rails-actioncable-sporadically-failing-to-subscribe
• monitor redis connection/status to see if the problem is actually coming from there
• review our usage of StimulusReflex/CableReady on the page, we seem to a few things on page load

[mkllnk]

I've read in some threads that connecting to the same channel multiple times in one page causes issues. So one approach we could try would be to create more channels for different uses. Not as dry but maybe a bit clearer in the communication.

[dacook]

The related PR has been deployed for this, I will test shortly.

[dacook]

I've tested on au_prod and fr_prod, and unfortunately couldn't see any existing problems, or conclusive improvements for the bulk loading of records. (This might be partly because I forgot to test before deploying 🤦).
However, it's good to see the packing report screen loads much quicker now, and I've found a potential lead for improving the BUU products screen loading!

To fix:

• [BUU] Products screen: Rails is often downloading the image for each product.

[dacook]

Hokay, replicated on fr_prod (v4.4.36-modified, with latest Redis fix) this morning while I was looking for something else.
I think this is consistent with what we were seeing before, but I feel like I have a new perspective.

1. Page loads, opens up a websocket and spams the server trying to subscribe to both SessionChannel and StimulusReflex::Channel for 11 seconds until 09:37:55
   
2. After a few seconds break, a new websocket is opened. SR subscribes successfully, and requests reflex Products#fetch. A second later, the server stops sending back a ping...
   
3. After a 10 second break, a third websocket is opened. It achieves subscription, but knows nothing about what requests were sent already, so does nothing.
   

The "Broken pipe" error is occurring regularly (several times in the last hour, I can see shoppers are currently using the site). Interestingly it wasn't logged at the same time as this example. The next one was over 5 mins later.. maybe the request took that long.. (but I wasn't able to interpret the logs to prove it)
E, [2024-03-27 22:45:34 #2192118] ERROR -- : WebSocket error occurred: Broken pipe

There was a spike in CPU usage, and a minor spike in Redis usage at that time, quite likely due to the Products#fetch. As I mentioned, there are other shoppers using the system at the same time.

So, while the server was busy, it stopped sending a ping, is that normal? And after 10 seconds, the client decided to re-establish the connection. That's probably because WebSocket or ActionCable layers are not aware of the application, which was waiting for a response. In fact, I don't think even StimulusReflex has a concept of waiting for a response.
If that's the case, maybe we should reconsider what we use it for.

[mkllnk]

while the server was busy, it stopped sending a ping, is that normal?

I don't know. It's very disappointing. The server has two workers (processes) with three threads each. It should be able to serve 6 requests in parallel. We got 8 CPUs, some of which may also be busy with the database or Redis but I would have expected the server to process a simple ping within a second. Can we extend the timeout?

[mariocarabotta]

from now onwards this issue is going to be related to Background Reports only.
@dacook will create a separate issue for BUU

[mkllnk]

Summary of identified problems

Large on-screen payloads don't reach the browser

We found that generating a large report to show on the screen results in the infinite loader. The HTML can be several megabytes in size and is sent from the report job but then disappears somewhere. We don't know what the limit is and which layer drops it (cable_ready, ActionCable or Redis?). But a 4MB report is dropped. Requesting the same report in a download format sends only the link to the report to the browser and that works.

The easiest workaround would be to check for the size of the HTML and only link to the blob like with downloadable reports. Quickest solution is to just display a link like with the other reports. Next, we could render HTML with an iframe or load the content with JS as in element.innerHTML = await (await fetch(url)).json (not tested).

A busy server results in unstable web sockets

When the server is very busy, for example compiling a big report, it stops sending pings to the browser. The client has a timeout of 10 seconds after which the connection is closed and it tries to open a new one. During this time, messages are lost and don't reach the browser. ActionCable is a simple broadcasting service and discards messages when nobody is listening. The client timeout can be configured:

ActionCable.ConnectionMonitor.staleThreshold = 10;

We could also increase the number of threads handling web sockets:

config.action_cable.worker_pool_size = 4

We also need to increase the number of database connections for this one.

[dacook]

Great summary, thanks Maikel. Just one comment:

The client timeout can be configured:

True, but that may only put off the problem until later, when it might occur less predictably and be harder to track. Also worth noting that's an unsupported config, as noted on that post:

Please note that this approach is generally a really bad idea: messing with internal variables is one of the direct ways to bugs and issues.

[mkllnk]

On the problem of report size on screen:

• Previously I found that a 4MB report never reached the browser when testing in production.
• Locally, I need to go to 30MB to make it fail.
• In specs, it fails earlier but some of it may be timeouts during HTML rendering. A request spec using websockets would be good but I don't know how to do that.

So finding the limitation and solving it may be tricky. The limitation may be in the browser, or in ActionCable or in cable_ready. Instead, it would be much easier to offer a download link.

[RachL]

copying a comment from Bethan on slack:

3-4 complaints each month that reports haven't 'loaded' when they've actually been emailed - this inevitably results in lots of emails though as they try and regenerate the report multiple times (one customer yesterday had 7 'report ready' emails all in the same minute!). It might be helpful to have a 'your report is being generated and will be emailed to you shortly' message in the generated report section when the email process is initiated, to minimise users clicking 'go' lots...

[mkllnk]

Cool, I have a fix for one part of the problem. I'll create a PR next week to support displaying big reports on the screen. Then we just have the unreliable websockets connection to think about...

[amidaOFN]

Hi team, just commenting that our user reporting this is still having the same or worse issue with it - they have had to try 40 times on their last attempt to get reports