search

TomBursch / kitchenowl

KitchenOwl is a self-hosted grocery list and recipe manager. The backend is made with Flask and the frontend with Flutter. Easily add items to your shopping list before you go shopping. You can also create recipes and add items based on what you want to cook.
https://kitchenowl.org/
GNU Affero General Public License v3.0
1.29k stars 76 forks source link

Bug: Constant connection loss #239

Open alphasierracharly opened 1 year ago

alphasierracharly commented 1 year ago

Is this urgent?

Yes

What parts are affected

Backend

What are the Server/Client versions of KitchenOwl

Latest

What's the problem 🤔

Hi all, I get constant disconnection from the server on a selfhostet instance and if it is working, it is generally very slow and almost irresponsive Below is the seemingly relevant log entry found in the backend logs. The frontens is entered via nginx as well. I tried both, mobile and web and both via nginx and directly via local IP. All with the same result as described above.

Share your logs

[2023-09-12 21:05:29,166] WARNING in config: Unauthorized: IP 172.21.0.1 reused the same refresh token, loging out user

[pid: 27|app: 0|req: 366/366] 172.21.0.1 () {54 vars in 1017 bytes} [Tue Sep 12 21:05:28 2023] GET /api/auth/refresh => generated 20 bytes in 1053 msecs (HTTP/1.1 401) 2 headers in 89 bytes (3 switches on core 198)

Share your configuration

version: "3"
services:
    front:
        image: tombursch/kitchenowl-web:latest
        restart: unless-stopped
        container_name: kitchenowl-front
        ports:
        - "8030:80"
        depends_on:
        - back
    back:
        image: tombursch/kitchenowl:latest
        restart: unless-stopped
        container_name: kitchenowl-back
        environment:
        - JWT_SECRET_KEY=randomstring
        volumes:
        - /volume1/docker/kitchenowl:/data
TomBursch commented 1 year ago

Hmm strange, do you have logs of some other slow responses? The one you provided is slow but only because somehow the same auth token was used twice, which logs out all sessions related to that token, which I haven't really optimized speed wise since it shouldn't occur during normal use. It's still weird that this happened at all. Are all your apps up to date?

alphasierracharly commented 1 year ago

I have the instance running on a Synology DS920+ with all apps up to date. Usually everything is responsive. This issue happened on the android app and the web interface. Both with local access and via nginx.

This is the typical log of back: [pid: 27|app: 0|req: 3330/3330] 172.21.0.1 () {62 vars in 1243 bytes} [Thu Sep 14 08:42:52 2023] GET /socket.io/?EIO=4&transport=websocket => generated 27 bytes in 0 msecs (HTTP/1.1 400) 2 headers in 94 bytes (3 switches on core 198)

And front: 172.21.0.1 - - [14/Sep/2023:08:42:52 +0000] "GET /socket.io/?EIO=4&transport=websocket HTTP/1.1" 400 38 "-" "Dart/3.1 (dart:io)" "myIP, 198.41.242.221"

The later IP in the frontend log being a cloudflare IP.

alphasierracharly commented 1 year ago

The login to the server works and it finds the created household, but then looses connection upon opening the household and the issue reads: Hmmmm... couldn't reach server I accessed the brower interface from a local IP to exclude nginx or cloudflare as potential error points.

Here are full logs from start of the containers to arrival of connection loss from front-end to back-end:

Front-End-Logs

2023-09-17T15:00:33.514349602Z /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
2023-09-17T15:00:33.515006401Z /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
2023-09-17T15:00:33.515311003Z /docker-entrypoint.sh: Launching /docker-entrypoint.d/01-kitchenowl-customization.sh
2023-09-17T15:00:33.515850428Z /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
2023-09-17T15:00:33.549451160Z 10-listen-on-ipv6-by-default.sh: info: Getting the checksum of /etc/nginx/conf.d/default.conf
2023-09-17T15:00:33.660456815Z 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf differs from the packaged version
2023-09-17T15:00:33.660624407Z /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
2023-09-17T15:00:33.664175628Z 20-envsubst-on-templates.sh: Running envsubst on /etc/nginx/templates/default.conf.template to /etc/nginx/conf.d/default.conf
2023-09-17T15:00:33.666359905Z /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
2023-09-17T15:00:33.668003197Z /docker-entrypoint.sh: Configuration complete; ready for start up
2023-09-17T15:00:33.814565089Z 2023/09/17 15:00:33 [notice] 1#1: using the "epoll" event method
2023-09-17T15:00:33.814742123Z 2023/09/17 15:00:33 [notice] 1#1: nginx/1.24.0
2023-09-17T15:00:33.814799411Z 2023/09/17 15:00:33 [notice] 1#1: built by gcc 12.2.1 20220924 (Alpine 12.2.1_git20220924-r4) 
2023-09-17T15:00:33.814844700Z 2023/09/17 15:00:33 [notice] 1#1: OS: Linux 4.4.302+
2023-09-17T15:00:33.814879942Z 2023/09/17 15:00:33 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2023-09-17T15:00:33.815011215Z 2023/09/17 15:00:33 [notice] 1#1: start worker processes
2023-09-17T15:00:33.815073611Z 2023/09/17 15:00:33 [notice] 1#1: start worker process 36
2023-09-17T15:00:33.815118903Z 2023/09/17 15:00:33 [notice] 1#1: start worker process 37
2023-09-17T15:00:33.815155632Z 2023/09/17 15:00:33 [notice] 1#1: start worker process 38
2023-09-17T15:00:33.815190999Z 2023/09/17 15:00:33 [notice] 1#1: start worker process 39
2023-09-17T15:01:03.556870324Z 127.0.0.1 - - [17/Sep/2023:15:01:03 +0000] "GET / HTTP/1.1" 200 1548 "-" "curl/8.2.1" "-"
2023-09-17T15:01:34.004683896Z 127.0.0.1 - - [17/Sep/2023:15:01:34 +0000] "GET / HTTP/1.1" 200 1548 "-" "curl/8.2.1" "-"
2023-09-17T15:02:04.549681326Z 127.0.0.1 - - [17/Sep/2023:15:02:04 +0000] "GET / HTTP/1.1" 200 1548 "-" "curl/8.2.1" "-"
2023-09-17T15:02:06.413385243Z 172.22.0.1 - - [17/Sep/2023:15:02:06 +0000] "GET /version.json?cachebuster=1694962926413 HTTP/1.1" 200 92 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:06.417199330Z 172.22.0.1 - - [17/Sep/2023:15:02:06 +0000] "GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V HTTP/1.1" 200 52 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:06.667575466Z 172.22.0.1 - - [17/Sep/2023:15:02:06 +0000] "GET /api/onboarding HTTP/1.1" 200 21 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:26.195610853Z 172.22.0.1 - - [17/Sep/2023:15:02:26 +0000] "POST /api/auth HTTP/1.1" 200 563 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:26.208065723Z 172.22.0.1 - - [17/Sep/2023:15:02:26 +0000] "GET /socket.io/?EIO=4&transport=polling&t=lmnl6bhf HTTP/1.1" 200 108 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:26.915766528Z 172.22.0.1 - - [17/Sep/2023:15:02:26 +0000] "GET /api/user HTTP/1.1" 200 1610 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:29.464606877Z 172.22.0.1 - - [17/Sep/2023:15:02:29 +0000] "POST /socket.io/?EIO=4&transport=polling&t=lmnl6bhs&sid=Id41AHGwanomA1P8AAAA HTTP/1.1" 200 12 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:29.465146814Z 172.22.0.1 - - [17/Sep/2023:15:02:29 +0000] "GET /socket.io/?EIO=4&transport=polling&t=lmnl6bht&sid=Id41AHGwanomA1P8AAAA HTTP/1.1" 200 43 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:30.257397530Z 172.22.0.1 - - [17/Sep/2023:15:02:30 +0000] "GET /api/household HTTP/1.1" 200 502 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:32.145003330Z 172.22.0.1 - - [17/Sep/2023:15:02:32 +0000] "GET /api/household/1 HTTP/1.1" 200 500 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:32.910868270Z 172.22.0.1 - - [17/Sep/2023:15:02:32 +0000] "GET /api/household/1/shoppinglist HTTP/1.1" 200 99 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:35.014139886Z 172.22.0.1 - - [17/Sep/2023:15:02:35 +0000] "GET /api/household/1/tag HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:35.272779668Z 127.0.0.1 - - [17/Sep/2023:15:02:35 +0000] "GET / HTTP/1.1" 200 1548 "-" "curl/8.2.1" "-"
2023-09-17T15:02:36.200573225Z 172.22.0.1 - - [17/Sep/2023:15:02:36 +0000] "GET /api/household/1/recipe HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"

2023-09-17T15:02:37.046850618Z 172.22.0.1 - - [17/Sep/2023:15:02:37 +0000] "GET /api/household/1/planner HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:37.949454007Z 172.22.0.1 - - [17/Sep/2023:15:02:37 +0000] "GET /api/household/1/planner/recent-recipes HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:38.546946870Z 172.22.0.1 - - [17/Sep/2023:15:02:38 +0000] "GET /api/household/1/planner/suggested-recipes HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:39.499400173Z 172.22.0.1 - - [17/Sep/2023:15:02:39 +0000] "GET /api/household/1/expense/categories HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:40.490333182Z 172.22.0.1 - - [17/Sep/2023:15:02:40 +0000] "GET /api/household/1/expense?view=0 HTTP/1.1" 200 3 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:40.491349450Z 172.22.0.1 - - [17/Sep/2023:15:02:40 +0000] "GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V HTTP/1.1" 200 52 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:40.491935145Z 172.22.0.1 - - [17/Sep/2023:15:02:40 +0000] "POST /socket.io/?EIO=4&transport=polling&t=lmnl6i8q&sid=Id41AHGwanomA1P8AAAA HTTP/1.1" 200 12 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:40.510931803Z 172.22.0.1 - - [17/Sep/2023:15:02:40 +0000] "POST /socket.io/?EIO=4&transport=polling&t=lmnl6mir&sid=Id41AHGwanomA1P8AAAA HTTP/1.1" 200 12 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:02:40.511038426Z 172.22.0.1 - - [17/Sep/2023:15:02:40 +0000] "GET /socket.io/?EIO=4&transport=polling&t=lmnl6e0a&sid=Id41AHGwanomA1P8AAAA HTTP/1.1" 200 5 "http://192.168.178.48:8035/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36" "-"
2023-09-17T15:03:06.178757082Z 127.0.0.1 - - [17/Sep/2023:15:03:06 +0000] "GET / HTTP/1.1" 200 1548 "-" "curl/8.2.1" "-"

Back-End-Logs

2023-09-17T14:58:21.288240649Z /usr/src/kitchenowl/migrations/env.py:21: DeprecationWarning: 'get_engine' is deprecated and will be removed in Flask-SQLAlchemy 3.2. Use 'engine' or 'engines[key]' instead. If you're using Flask-Migrate or Alembic, you'll need to update your 'env.py' file.
2023-09-17T14:58:21.288849461Z   return current_app.extensions['migrate'].db.get_engine()
2023-09-17T14:58:21.288907186Z /usr/src/kitchenowl/migrations/env.py:21: DeprecationWarning: 'get_engine' is deprecated and will be removed in Flask-SQLAlchemy 3.2. Use 'engine' or 'engines[key]' instead. If you're using Flask-Migrate or Alembic, you'll need to update your 'env.py' file.
2023-09-17T14:58:21.288954468Z   return current_app.extensions['migrate'].db.get_engine()
2023-09-17T14:58:21.290596604Z INFO  [alembic.runtime.migration] Context impl SQLiteImpl.
2023-09-17T14:58:21.290669624Z INFO  [alembic.runtime.migration] Will assume non-transactional DDL.
2023-09-17T14:58:26.156990864Z 
Upgrading households...:   0%|          | 0/1 [00:00<?, ?it/s]
Upgrading households...: 100%|██████████| 1/1 [00:00<00:00,  1.26it/s]
Upgrading households...: 100%|██████████| 1/1 [00:00<00:00,  1.26it/s]
2023-09-17T14:58:26.891416849Z [uWSGI] getting INI configuration from wsgi.ini
2023-09-17T14:58:27.078642401Z *** Starting uWSGI 2.0.22 (64bit) on [Sun Sep 17 14:58:26 2023] ***
2023-09-17T14:58:27.078727469Z compiled with version: 12.2.0 on 15 September 2023 06:46:39
2023-09-17T14:58:27.078770120Z os: Linux-4.4.302+ #64570 SMP Tue Jun 13 21:39:55 CST 2023
2023-09-17T14:58:27.078813236Z nodename: b9823251de32
2023-09-17T14:58:27.078844631Z machine: x86_64
2023-09-17T14:58:27.078874492Z clock source: unix
2023-09-17T14:58:27.078904887Z pcre jit disabled
2023-09-17T14:58:27.078939057Z detected number of CPU cores: 4
2023-09-17T14:58:27.078971253Z current working directory: /usr/src/kitchenowl
2023-09-17T14:58:27.079005709Z detected binary path: /opt/venv/bin/uwsgi
2023-09-17T14:58:27.079053391Z uWSGI running as root, you can use --uid/--gid/--chroot options
2023-09-17T14:58:27.079091810Z *** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
2023-09-17T14:58:27.079132575Z your memory page size is 4096 bytes
2023-09-17T14:58:27.079166285Z detected max file descriptor number: 1048576
2023-09-17T14:58:27.079201175Z - async cores set to 200 - fd table size: 1048576
2023-09-17T14:58:27.079233475Z lock engine: pthread robust mutexes
2023-09-17T14:58:27.079263467Z thunder lock: disabled (you can enable it with --thunder-lock)
2023-09-17T14:58:27.079298256Z uwsgi socket 0 bound to TCP address 0.0.0.0:5000 fd 3
2023-09-17T14:58:27.079383848Z uWSGI running as root, you can use --uid/--gid/--chroot options
2023-09-17T14:58:27.079416144Z *** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
2023-09-17T14:58:27.079446091Z Python version: 3.11.5 (main, Sep  7 2023, 12:46:15) [GCC 12.2.0]
2023-09-17T14:58:27.079482527Z Python main interpreter initialized at 0x7f2c5bc826b8
2023-09-17T14:58:27.079513078Z uWSGI running as root, you can use --uid/--gid/--chroot options
2023-09-17T14:58:27.079548968Z *** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
2023-09-17T14:58:27.079586567Z python threads support enabled
2023-09-17T14:58:27.079616595Z your server socket listen backlog is limited to 100 connections
2023-09-17T14:58:27.079658286Z your mercy for graceful operations on workers is 60 seconds
2023-09-17T14:58:27.079691155Z mapped 4307328 bytes (4206 KB) for 200 cores
2023-09-17T14:58:27.079726017Z *** Operational MODE: async ***
2023-09-17T14:58:27.079757237Z uWSGI running as root, you can use --uid/--gid/--chroot options
2023-09-17T14:58:27.079786499Z *** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
2023-09-17T14:58:27.079819276Z spawned uWSGI master process (pid: 26)
2023-09-17T14:58:27.079851243Z spawned uWSGI worker 1 (pid: 27, cores: 200)
2023-09-17T14:58:30.360785587Z WSGI app 0 (mountpoint='') ready in 4 seconds on interpreter 0x7f2c5bc826b8 pid: 27 (default app)
2023-09-17T14:58:30.361215176Z *** running gevent loop engine [addr:0x561c26355650] ***
2023-09-17T14:59:16.467813473Z [pid: 27|app: 0|req: 1/1]  () {16 vars in 245 bytes} [Sun Sep 17 14:59:16 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
2023-09-17T15:00:17.095697614Z [pid: 27|app: 0|req: 2/2]  () {16 vars in 245 bytes} [Sun Sep 17 15:00:17 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
2023-09-17T15:01:17.707155134Z [pid: 27|app: 0|req: 3/3]  () {16 vars in 245 bytes} [Sun Sep 17 15:01:17 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)

17T15:02:06.417363417Z [pid: 27|app: 0|req: 4/4] 172.22.0.1 () {46 vars in 1094 bytes} [Sun Sep 17 15:02:06 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
2023-09-17T15:02:06.667478342Z [pid: 27|app: 0|req: 5/5] 172.22.0.1 () {46 vars in 1036 bytes} [Sun Sep 17 15:02:06 2023] GET /api/onboarding => generated 21 bytes in 131 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
2023-09-17T15:02:18.364152232Z [pid: 27|app: 0|req: 6/6]  () {16 vars in 245 bytes} [Sun Sep 17 15:02:18 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
2023-09-17T15:02:26.195057271Z [pid: 27|app: 0|req: 7/7] 172.22.0.1 () {52 vars in 1166 bytes} [Sun Sep 17 15:02:24 2023] POST /api/auth => generated 563 bytes in 1613 msecs (HTTP/1.1 200) 2 headers in 72 bytes (3 switches on core 199)

2023-09-17T15:02:26.208040815Z [pid: 27|app: 0|req: 8/8] 172.22.0.1 () {48 vars in 1387 bytes} [Sun Sep 17 15:02:26 2023] GET /socket.io/?EIO=4&transport=polling&t=lmnl6bhf => generated 97 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 100 bytes (3 switches on core 199)
2023-09-17T15:02:26.915735832Z [pid: 27|app: 0|req: 9/9] 172.22.0.1 () {48 vars in 1314 bytes} [Sun Sep 17 15:02:26 2023] GET /api/user => generated 1610 bytes in 702 msecs (HTTP/1.1 200) 2 headers in 73 bytes (3 switches on core 199)
2023-09-17T15:02:29.464606854Z [pid: 27|app: 0|req: 10/10] 172.22.0.1 () {54 vars in 1573 bytes} [Sun Sep 17 15:02:26 2023] POST /socket.io/?EIO=4&transport=polling&t=lmnl6bhs&sid=Id41AHGwanomA1P8AAAA => generated 2 bytes in 2548 msecs (HTTP/1.1 200) 3 headers in 142 bytes (3 switches on core 199)
2023-09-17T15:02:29.465461544Z [pid: 27|app: 0|req: 11/11] 172.22.0.1 () {48 vars in 1437 bytes} [Sun Sep 17 15:02:29 2023] GET /socket.io/?EIO=4&transport=polling&t=lmnl6bht&sid=Id41AHGwanomA1P8AAAA => generated 32 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 100 bytes (3 switches on core 198)
2023-09-17T15:02:30.257390802Z [pid: 27|app: 0|req: 12/12] 172.22.0.1 () {48 vars in 1324 bytes} [Sun Sep 17 15:02:29 2023] GET /api/household => generated 502 bytes in 792 msecs (HTTP/1.1 200) 2 headers in 72 bytes (3 switches on core 199)
2023-09-17T15:02:32.145007529Z [pid: 27|app: 0|req: 13/13] 172.22.0.1 () {48 vars in 1328 bytes} [Sun Sep 17 15:02:30 2023] GET /api/household/1 => generated 500 bytes in 1888 msecs (HTTP/1.1 200) 2 headers in 72 bytes (3 switches on core 198)
2023-09-17T15:02:32.910598400Z [pid: 27|app: 0|req: 14/14] 172.22.0.1 () {48 vars in 1354 bytes} [Sun Sep 17 15:02:32 2023] GET /api/household/1/shoppinglist => generated 99 bytes in 765 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
2023-09-17T15:02:35.014241061Z [pid: 27|app: 0|req: 15/15] 172.22.0.1 () {48 vars in 1336 bytes} [Sun Sep 17 15:02:32 2023] GET /api/household/1/tag => generated 3 bytes in 2103 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 198)
2023-09-17T15:02:36.200573579Z [pid: 27|app: 0|req: 16/16] 172.22.0.1 () {48 vars in 1342 bytes} [Sun Sep 17 15:02:35 2023] GET /api/household/1/recipe => generated 3 bytes in 1186 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 199)
2023-09-17T15:02:37.046860623Z [pid: 27|app: 0|req: 17/17] 172.22.0.1 () {48 vars in 1344 bytes} [Sun Sep 17 15:02:36 2023] GET /api/household/1/planner => generated 3 bytes in 846 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 198)
2023-09-17T15:02:37.948931098Z [pid: 27|app: 0|req: 18/18] 172.22.0.1 () {48 vars in 1374 bytes} [Sun Sep 17 15:02:37 2023] GET /api/household/1/planner/recent-recipes => generated 3 bytes in 902 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 199)
2023-09-17T15:02:38.546882934Z [pid: 27|app: 0|req: 19/19] 172.22.0.1 () {48 vars in 1380 bytes} [Sun Sep 17 15:02:37 2023] GET /api/household/1/planner/suggested-recipes => generated 3 bytes in 598 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 198)
2023-09-17T15:02:39.499435409Z [pid: 27|app: 0|req: 20/20] 172.22.0.1 () {48 vars in 1366 bytes} [Sun Sep 17 15:02:38 2023] GET /api/household/1/expense/categories => generated 3 bytes in 952 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 199)
2023-09-17T15:02:40.490519383Z [pid: 27|app: 0|req: 21/21] 172.22.0.1 () {48 vars in 1357 bytes} [Sun Sep 17 15:02:39 2023] GET /api/household/1/expense?view=0 => generated 3 bytes in 991 msecs (HTTP/1.1 200) 2 headers in 70 bytes (3 switches on core 198)
2023-09-17T15:02:40.491382320Z [pid: 27|app: 0|req: 23/22] 172.22.0.1 () {48 vars in 1384 bytes} [Sun Sep 17 15:02:40 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 198)
2023-09-17T15:02:40.491839099Z [pid: 27|app: 0|req: 24/23] 172.22.0.1 () {54 vars in 1573 bytes} [Sun Sep 17 15:02:40 2023] POST /socket.io/?EIO=4&transport=polling&t=lmnl6i8q&sid=Id41AHGwanomA1P8AAAA => generated 2 bytes in 0 msecs (HTTP/1.1 200) 3 headers in 142 bytes (3 switches on core 197)
2023-09-17T15:02:40.510863981Z [pid: 27|app: 0|req: 25/24] 172.22.0.1 () {54 vars in 1573 bytes} [Sun Sep 17 15:02:40 2023] POST /socket.io/?EIO=4&transport=polling&t=lmnl6mir&sid=Id41AHGwanomA1P8AAAA => generated 2 bytes in 0 msecs (HTTP/1.1 200) 3 headers in 142 bytes (3 switches on core 197)
2023-09-17T15:02:40.511039209Z [pid: 27|app: 0|req: 25/25] 172.22.0.1 () {48 vars in 1437 bytes} [Sun Sep 17 15:02:40 2023] GET /socket.io/?EIO=4&transport=polling&t=lmnl6e0a&sid=Id41AHGwanomA1P8AAAA => generated 0 bytes in 20 msecs (HTTP/1.1 200) 2 headers in 100 bytes (3 switches on core 199)
2023-09-17T15:03:19.125106891Z [pid: 27|app: 0|req: 26/26]  () {16 vars in 245 bytes} [Sun Sep 17 15:03:19 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
DeMyrax commented 1 year ago

Here the same problem, after log in it takes only a few seconds and I am kicked out or the error message appears that it could not establish a connection.

TomBursch commented 1 year ago

@DeMyrax Could you provide some information about the client you used and, if possible, some backend logs of when that happens?

spammads commented 1 year ago

Got the same issues as OP. App is extremely slow and constant logouts appear. Using v80 with the latest frontend. Log complains about reusing the same refresh token:

*Edit: Formatting

[pid: 75|app: 0|req: 20639/30077] 10.244.4.191 () {50 vars in 1008 bytes} [Sat Oct 14 08:27:51 2023] GET /api/household/1/expense/categories => generated 33 bytes in 3 msecs (HTTP/1.1 401) 2 headers in 81 bytes (3 switches on core 197)
[pid: 75|app: 0|req: 20639/30078] 10.244.4.191 () {62 vars in 1249 bytes} [Sat Oct 14 08:27:35 2023] GET /socket.io/?EIO=4&transport=websocket => generated 126 bytes in 16375 msecs (HTTP/1.1 101) 4 headers in 164 bytes (2 switches on core 198)
[pid: 75|app: -1|req: -1/30079]  () {0 vars in 0 bytes} [Sat Oct 14 08:27:51 2023]   => generated 0 bytes in 0 msecs ( 0) 0 headers in 0 bytes (1 switches on core 199)
[pid: 75|app: -1|req: -1/30080]  () {0 vars in 0 bytes} [Sat Oct 14 08:27:51 2023]   => generated 0 bytes in 0 msecs ( 0) 0 headers in 0 bytes (1 switches on core 199)
[pid: 75|app: 0|req: 20640/30081] 10.244.4.32 () {50 vars in 967 bytes} [Sat Oct 14 08:27:51 2023] GET /api/onboarding => generated 21 bytes in 1 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20641/30082] 10.244.4.182 () {50 vars in 1026 bytes} [Sat Oct 14 08:27:51 2023] GET /api/health/8M4F88S8ooi4sMbLBfkkV7ctWwgibW6V => generated 52 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 71 bytes (3 switches on core 199)
[2023-10-14 08:27:51,941] WARNING in config: Unauthorized: IP 10.244.4.182 reused the same refresh token, loging out user
[pid: 75|app: 0|req: 20642/30083] 10.244.4.182 () {50 vars in 974 bytes} [Sat Oct 14 08:27:51 2023] GET /api/auth/refresh => generated 20 bytes in 331 msecs (HTTP/1.1 401) 2 headers in 89 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20643/30084] 10.244.4.182 () {52 vars in 1038 bytes} [Sat Oct 14 08:27:55 2023] GET /api/household/1/expense => generated 15419 bytes in 326 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20644/30085] 10.244.4.191 () {52 vars in 1038 bytes} [Sat Oct 14 08:27:55 2023] GET /api/household/1/expense => generated 15419 bytes in 457 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 198)
[pid: 75|app: 0|req: 20645/30086] 10.244.4.191 () {52 vars in 1040 bytes} [Sat Oct 14 08:27:56 2023] GET /api/shoppinglist/1/items => generated 1760 bytes in 356 msecs (HTTP/1.1 200) 2 headers in 73 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20646/30087] 10.244.4.191 () {52 vars in 1040 bytes} [Sat Oct 14 08:27:56 2023] GET /api/shoppinglist/1/items => generated 1760 bytes in 592 msecs (HTTP/1.1 200) 2 headers in 73 bytes (3 switches on core 198)
[pid: 75|app: 0|req: 20647/30088] 10.244.4.182 () {52 vars in 1038 bytes} [Sat Oct 14 08:27:57 2023] GET /api/household/1/expense => generated 15419 bytes in 214 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20648/30089] 10.244.4.191 () {52 vars in 1038 bytes} [Sat Oct 14 08:27:57 2023] GET /api/household/1/expense => generated 15419 bytes in 1581 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 198)
[pid: 75|app: 0|req: 20649/30090] 10.244.4.32 () {52 vars in 1037 bytes} [Sat Oct 14 08:27:58 2023] GET /api/household/1/expense => generated 15419 bytes in 331 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20650/30091] 10.244.4.32 () {52 vars in 1037 bytes} [Sat Oct 14 08:27:59 2023] GET /api/household/1/expense => generated 15419 bytes in 961 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 198)
[pid: 75|app: 0|req: 20651/30092] 10.244.4.191 () {52 vars in 1038 bytes} [Sat Oct 14 08:28:00 2023] GET /api/household/1/expense => generated 15419 bytes in 892 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20652/30093] 10.244.4.182 () {52 vars in 1038 bytes} [Sat Oct 14 08:28:01 2023] GET /api/household/1/expense => generated 15419 bytes in 481 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 198)
[pid: 75|app: 0|req: 20653/30094] 10.244.4.182 () {52 vars in 1038 bytes} [Sat Oct 14 08:28:01 2023] GET /api/household/1/expense => generated 15419 bytes in 1840 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20654/30095] 10.244.4.32 () {50 vars in 958 bytes} [Sat Oct 14 08:28:03 2023] GET /api/household/1/expense => generated 15419 bytes in 1488 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 198)
[pid: 75|app: -1|req: -1/30096]  () {0 vars in 0 bytes} [Sat Oct 14 08:28:04 2023]   => generated 0 bytes in 0 msecs ( 0) 0 headers in 0 bytes (1 switches on core 199)
[pid: 75|app: -1|req: -1/30097]  () {0 vars in 0 bytes} [Sat Oct 14 08:28:04 2023]   => generated 0 bytes in 0 msecs ( 0) 0 headers in 0 bytes (1 switches on core 199)
[pid: 75|app: 0|req: 20655/30098] 10.244.4.32 () {50 vars in 958 bytes} [Sat Oct 14 08:28:04 2023] GET /api/household/1/expense => generated 15419 bytes in 369 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 199)
[pid: 75|app: 0|req: 20656/30099] 10.244.4.191 () {50 vars in 959 bytes} [Sat Oct 14 08:28:05 2023] GET /api/household/1/expense => generated 15419 bytes in 371 msecs (HTTP/1.1 200) 2 headers in 74 bytes (3 switches on core 198)
Poldi1977 commented 1 year ago

I have the problem too. There are permanent disconnections.

image

Poldi1977 commented 1 year ago

I was able to find a solution for myself. As mentioned in issue #268, I set the FRONT_URL variable in the backend section. Since then I don't have any disconnections anymore.

spammads commented 1 year ago

This did not resolve my issue unfortunately. Even when setting FRONT_URL this issue still persists over here. I'm starving without proper Grocery-Mgmt.

giacomocerquone commented 1 year ago

This did not resolve my issue unfortunately. Even when setting FRONT_URL this issue still persists over here. I'm starving without proper Grocery-Mgmt.

You have to be certain you're passing the correct value inside the FRONT_URL. It depends a lot on your installation method. I'm under docker, for example, and I've run both the images (back and front) within the same custom_network so I was setting the FRONT_URL with the name of the container: KitchenOwl-Web:8123 but this will not work since the browser, when accessing the web app, directs its API calls to my host machine IP.

So make sure you set something like FRONT_URL=192.168.x.x:your-port

I don't have time to debug the app and I don't have much experience with Flask and python, but this issue shouldn't be that hard to solve, I've managed identical problems in node and react/angular, etc. too for example.

TomBursch commented 1 year ago

I'm a bit confused how setting FRONT_URL solves this for some of you. It just adds CORS headers to the response with that URL. Technically, #268 is unrelated to the disconnects.

I'm still unable to reproduce the disconnect. Can someone send me their browser network log of when this happens? Or if someone has some more time, text me on matrix such that we can debug this interactively/together.

giacomocerquone commented 1 year ago

I'm a bit confused how setting FRONT_URL solves this for some of you. It just adds CORS headers to the response with that URL. Technically, #268 is unrelated to the disconnects.

I'm still unable to reproduce the disconnect. Can someone send me their browser network log of when this happens? Or if someone has some more time, text me on matrix such that we can debug this interactively/together.

I'll do it ASAP. In the meantime, I'm going also to add that when this was happening, I tried opening the container's log and nothing was in there but I've opened the network tab too and I saw socket.io continuously obsessing and spamming connection attempts that were going into failure. My very superficial guess, is that this happens, and then the server goes down probably for too many connections (?) but this is just speculation.

Also, the socket.io errors didn't seem to be CORS errors honestly, they were generic 400 errors... but for this too, I shall check again

I don't know/use matrix, do you have discord?

TomBursch commented 1 year ago

My discord username is t0mxd

My very superficial guess, is that https://github.com/TomBursch/kitchenowl/issues/268 happens, and then the server goes down probably for too many connections (?) but this is just speculation.

This could be the case, but others showed some logs where the refresh token rotation failed, i.e: [2023-10-14 08:27:51,941] WARNING in config: Unauthorized: IP 10.244.4.182 reused the same refresh token, loging out user

For other to try: FRONT_URL needs to be exactly the URL you type into your browser (e.g. on the main instance this is FRONT_URL: "https://app.kitchenowl.org")

giacomocerquone commented 1 year ago

Ok, the two issues are definitely connected. I lost a good 10 minutes to reproduce this because just removing the FRONT_URL variable from the running backend container and restarting it, the web app wasn't absolutely showing any kind of issue (which is already strange but I don't know what's happening there).

I managed to reproduce the exact issue re-creating a container together with its volume with the following config (notice the wrong FRONT_URL value that should instead have my machine's local ip):

Screenshot 2023-11-09 alle 09 40 23

Take a look at the video and notice how it continuously keeps disconnecting from the backend while socket.io continuously spams retries: https://www.loom.com/share/952c38079e2040da9903f78da27e1e90?sid=36880c35-8265-41fe-9921-a8316d059a99

I think at this point you could also replicate this yourself (just be sure to input localhost as FRONT_URL and host the frontend on another machine's IP in your local network) but I'll share the errors with you on Discord. Furthermore, I advise you to customize the retry delay of socket.io, it's clearly out of its mind and cripples the entire client too.

BONUS: Yes it seems a CORS issue specifically with socket.io but my previous hint was correct: it didn't seem a CORS error because "true" CORS errors happen in pre-flight while this is a plain 400 with a custom string returned by your flask backend.

TomBursch commented 12 months ago

I've published a new release. Can some of you please report back if that resolves the issue for them?

I'm starving without proper Grocery-Mgmt.

Another thing I wanted to say is that the releases are tagged, so if a new version breaks something for you, you can always use a specific tag, for example :v83 instead of :latest.

dotnjet commented 10 months ago

I still have the same issue with the latest version. It keeps me logging in again and again.

Goliath67 commented 9 months ago

I also have this issue ! It strikes me that everybody with the problem is running kitchenowl on a Synology NAS. I would add a little detail to this ... I have the problem on my NAS running DSM 7.2.1 with the new "Container Manager", but it is working fine on my DSM 6.2.4 with Docker. I don't know if this can help anyone work out what is going on ?

FelixBurkhard commented 8 months ago

I am also running kitchenowl on synology DSM7 and I am facing the same issue. I am getting logged out when using the iOS App, using the browser I get very slow responses (>2s for every request). I started investigating a bit by adding some print statements with timestamps for the path of the auth route and the problem seems to be with SQLAlchemy. adding these lines (and some others)

class DbModelMixin(object):
    def save(self) -> Self:
        """
        Persist changes to current instance in db
        """
        try:
            print(f"{datetime.now()}: saving: adding...")
            db.session.add(self)
            print(f"{datetime.now()}: saving: added")
            print(f"{datetime.now()}: saving: commiting...")
            db.session.commit()
            print(f"{datetime.now()}: saving: committed")
        except Exception as e:
            db.session.rollback()
            raise e

        return self

gives me these logs

2024-03-12 17:33:27.765990: starting auth action                                 
2024-03-12 17:33:27.766084: creating refresh token                               
2024-03-12 17:33:27.767357: saving: adding...                                    
2024-03-12 17:33:27.767531: saving: added                                        
2024-03-12 17:33:27.767549: saving: commiting...                                 
2024-03-12 17:33:29.366312: saving: committed                                    
2024-03-12 17:33:29.366375: created refresh token                                
2024-03-12 17:33:29.366419: creating access token                                
2024-03-12 17:33:29.366442: creating flask access token                          
2024-03-12 17:33:29.370344: creating access token model                          
2024-03-12 17:33:29.374192: start saving model                                   
2024-03-12 17:33:29.374261: saving: adding...                                    
2024-03-12 17:33:29.374405: saving: added                                        
2024-03-12 17:33:29.374424: saving: commiting...                                 
2024-03-12 17:33:31.054860: saving: committed                                    
2024-03-12 17:33:31.054920: finished saving model                                
2024-03-12 17:33:31.054955: created access token

so db.session.commit() takes more than a second to complete. I assume the read access is slow as well, but it is not yet confirmed. Not sure if this is just an issue with kitchenowl or if it would be better to open an issue with SQLAlchemy or Synology. But before doing so it might make sense to try it out with a minimal example. Not sure if I will find the time to do this anytime soon, so if anyone wants to go forward from here please feel free.

I am also not sure how this is related to the inital issues of constant logouts but the two issues seem to be connected.

Edit: Since the issue seems to be DB related I tried out if using postgres as engine fixes the issue but sadly the requests are still slow.

johannesfrey commented 8 months ago

I am also running kitchenowl on synology DSM7 and I am facing the same issue. I am getting logged out when using the iOS App, using the browser I get very slow responses (>2s for every request). I started investigating a bit by adding some print statements with timestamps for the path of the auth route and the problem seems to be with SQLAlchemy. adding these lines (and some others)

class DbModelMixin(object):
    def save(self) -> Self:
        """
        Persist changes to current instance in db
        """
        try:
            print(f"{datetime.now()}: saving: adding...")
            db.session.add(self)
            print(f"{datetime.now()}: saving: added")
            print(f"{datetime.now()}: saving: commiting...")
            db.session.commit()
            print(f"{datetime.now()}: saving: committed")
        except Exception as e:
            db.session.rollback()
            raise e

        return self

gives me these logs

2024-03-12 17:33:27.765990: starting auth action                                 
2024-03-12 17:33:27.766084: creating refresh token                               
2024-03-12 17:33:27.767357: saving: adding...                                    
2024-03-12 17:33:27.767531: saving: added                                        
2024-03-12 17:33:27.767549: saving: commiting...                                 
2024-03-12 17:33:29.366312: saving: committed                                    
2024-03-12 17:33:29.366375: created refresh token                                
2024-03-12 17:33:29.366419: creating access token                                
2024-03-12 17:33:29.366442: creating flask access token                          
2024-03-12 17:33:29.370344: creating access token model                          
2024-03-12 17:33:29.374192: start saving model                                   
2024-03-12 17:33:29.374261: saving: adding...                                    
2024-03-12 17:33:29.374405: saving: added                                        
2024-03-12 17:33:29.374424: saving: commiting...                                 
2024-03-12 17:33:31.054860: saving: committed                                    
2024-03-12 17:33:31.054920: finished saving model                                
2024-03-12 17:33:31.054955: created access token

so db.session.commit() takes more than a second to complete. I assume the read access is slow as well, but it is not yet confirmed. Not sure if this is just an issue with kitchenowl or if it would be better to open an issue with SQLAlchemy or Synology. But before doing so it might make sense to try it out with a minimal example. Not sure if I will find the time to do this anytime soon, so if anyone wants to go forward from here please feel free.

I am also not sure how this is related to the inital issues of constant logouts but the two issues seem to be connected.

I don't have any data to prove my claim, but it seems to be related to this. I had the log out issue only when I was using a slow NFS as persistence. After changing that the issue did never occur again. So it could really be related to slow storage.

alphasierracharly commented 5 months ago

I solved the issue of slow response times by moving container manager (synology docker) and the docker image for kitchenowl (version 0.5.1) off the HDD onto the NVME SSD. Performance is now with instant responsetime instead of 2-5 seconds and no more random logouts

need4swede commented 3 months ago

I have the same issue - but I'm not on a synology NAS.

It had been running great for months, but I recently had to rebuild my storage array and re-deploy everything. Since then, Kitchen Owl has been very unresponsive and it keeps kicking me out on the iOS app.

My drive speeds should not be an issue, as I'm hitting well over SATA SSD performance marks. However, I switched to using a docker volume instead of mounting the database and the problem went away - so there definitely seems to be some sort of I/O issue.