Bug: Web interface looses token if under load

[phil-flip]

Not sure on how reproducible it is, but I noticed that: If there is a large load (Automated Picture adding), my login token gets invalidated, even if it is still present. This happened every time I torture the API and the Raspberry Pi is under load. Funnily enough, the API token for my automation ever expires and doesn't face these issues. So my guess is that there is something wrong with the Frontend and caching pages?

My Browser

[phil-flip]

I know this sounds silly, but eventually it is a little annoying that there is always the need to log in every 2 days or so, even if the tokens are valid for 12 months.

[sgsunder]

Do you get any server-side log messages/errors when this happens?

I never encountered this before when doing high-load tasks, but I also run on more substantial hardware (x86 server with 16GB RAM) than a Raspberry Pi. Wondering if there's an out-of-memory error or something that's causing server threads to terminate.

[phil-flip]

ill share the log when it happens again, because its completely random.

[phil-flip]

Ok, so it seems like that the frontend just drops the token, when it can't reach the backend. Or a logout function gets triggered... While it does happen more, if under load, it does also just happen randomly, when not accessed for longer than 3 or so hours. Every time with long load times up to 6 minutes. Switching browsers also doesn't seem to effect it. I am also now, very confident, that there is something wrong with the frontend. Since for example the App I use to connect to the API works fine, every time is start it, regardless if it's under load or not (sure, it might be a little slower, because hard drives.) After it loaded successfully, it also works fine in other browser, every time.

The frontend docker log has the following log entries that are relevant:

2022-08-22T00:15:00.952797145Z 172.20.0.2 -> GET /api/info HTTP/1.0 [499] - referer: http://raspiserver/ -
2022-08-22T00:15:00.953019215Z 2022/08/22 00:15:00 [error] 11#11: *7604 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.20.0.2, server: , request: "GET /api/info HTTP/1.0", upstream: "http://172.20.0.5:6666/info", host: "client", referrer: "http://raspiserver/"
2022-08-22T00:15:00.953514816Z 172.20.0.2 -> GET /api/info HTTP/1.0 [504] - referer: http://raspiserver/ -
2022-08-22T00:15:23.440207944Z 172.20.0.2 -> GET /api/user/phil?bump-login=true HTTP/1.0 [499] - referer: http://raspiserver/ -
2022-08-22T00:15:23.454586043Z 172.20.0.2 -> GET / HTTP/1.0 [304] - referer: - -
2022-08-22T00:15:23.466085960Z 172.20.0.2 -> DELETE /api/user-token/phil/707ef221-0380-49fd-a954-d9e3a72494c3 HTTP/1.0 [499] - referer: http://raspiserver/ -
2022-08-22T00:15:26.648914578Z 172.20.0.2 -> POST /api/uploads/ HTTP/1.0 [499] - referer: - -
2022-08-22T00:15:28.295125062Z 172.20.0.2 -> POST /api/uploads/ HTTP/1.0 [499] - referer: - -
2022-08-22T00:16:23.554646258Z 2022/08/22 00:16:23 [error] 11#11: *7618 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.20.0.2, server: , request: "GET /api/info HTTP/1.0", upstream: "http://172.20.0.5:6666/info", host: "client", referrer: "http://raspiserver/"
2022-08-22T00:16:23.555780328Z 172.20.0.2 -> GET /api/info HTTP/1.0 [504] - referer: http://raspiserver/ -
2022-08-22T00:16:23.557039988Z 2022/08/22 00:16:23 [error] 11#11: *7620 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 172.20.0.2, server: , request: "GET /api/info HTTP/1.0", upstream: "http://172.20.0.5:6666/info", host: "client", referrer: "http://raspiserver/"

[phil-flip]

Ok, after some free time, I finally got the booru exposed to the internet, so the behavior can be seen. I don't feel comfortable sharing the link here, so please reach out to me on Discord Phil | Flipper#3621 so I can give you the address there.

[phil-flip]

Ok, after fiddling around for some time and trying different configuration, I got it to work. It seems to be a nginx issue(?). At least it fixed for me, when I added the following 2 lines

      proxy_http_version 1.1;
      proxy_set_header Connection "";

my entire config looks like this:

events { }
http {
  server {
    server_name raspiserver;

    location / {
      # If pre-flight request
      if ($request_method = "OPTIONS") {
          add_header "Access-Control-Allow-Origin" "*";
          add_header "Access-Control-Allow-Methods" "GET, POST, PUT, DELETE, OPTIONS";
          add_header "Access-Control-Allow-Headers" "Authorization, Content-Type";

          add_header "Access-Control-Max-Age" 1728000;
          return 204;
      }

      # For all other requests
#     add_header Access-Control-Allow-Origin *;
      client_max_body_size 1073741824;
      add_header Access-Control-Allow-Methods "GET, POST, PUT, DELETE, OPTIONS";
      add_header Access-Control-Allow-Headers "Authorization, Content-Type";
      proxy_http_version 1.1;
      proxy_set_header Connection "";
      proxy_pass http://client:80;
    }
  }
}

It looks a little different to the default one, because I also had issues with CORS before.

[phil-flip]

I should add: it only improves loading by a little bit. So it might still be an issue, because I'm running a RPi4. But I have not been logged out since I added this and it works for me.

[phil-flip]

Unfortunately, while it "feels" to be happening less, it still happens

[phil-flip]

So I moved everything to a more powerful machine, but It's still an issue… It happened after some time, tho. I will "merge" this with the older issue, as this seems to be the same: 449