[bug] Fresh install has uwsgi timeout from nginx

[scott-grimes]

Dashboard will not load on a fresh install. nginx times out.

.env

# Essential
DASHBOARD_DOMAIN=dashboard.mydomain
API_DOMAIN=api.mydomain
VPN_DOMAIN=openvpn.mydomain

EMAIL_DJANGO_DEFAULT=example@example.org

# Postgres
DB_USER=asdf
DB_PASS=fdsa
DB_NAME=openwisp
DB_ADMIN_PASS=password

# Influxdb
INFLUXDB_USER=asdf
INFLUXDB_PASS=fdsa
INFLUXDB_NAME=openwisp
INFLUXDB_ADMIN_PASS=password

# A random key, cannot be edited once set
DJANGO_SECRET_KEY=fdsaasdf

# Set to Yes to enable letsencrypt
SSL_CERT_MODE=SelfSigned

TZ=America/New_York
CERT_ADMIN_EMAIL=example@example.org

# VPN
VPN_NAME=testtest
VPN_CLIENT_NAME=management-vpn

openwisp dashboard logs:

[uWSGI] getting INI configuration from uwsgi.ini
*** Starting uWSGI 2.0.20 (64bit) on [Thu Sep  8 17:28:57 2022] ***
compiled with version: 10.2.1 20210110 on 08 September 2022 02:34:56
os: Linux-5.10.25-linuxkit #1 SMP Tue Mar 23 09:27:39 UTC 2021
nodename: 8f6977ec868f
machine: x86_64
clock source: unix
detected number of CPU cores: 6
current working directory: /opt/openwisp
writing pidfile to /opt/openwisp/uwsgi.pid
detected binary path: /usr/local/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
chdir() to /opt/openwisp
your memory page size is 4096 bytes
 *** WARNING: you have enabled harakiri without post buffering. Slow upload could be rejected on post-unbuffered webservers *** 
detected max file descriptor number: 1048576
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address 0.0.0.0:8000 fd 3
Python version: 3.10.7 (main, Sep  7 2022, 22:06:44) [GCC 10.2.1 20210110]
Python main interpreter initialized at 0x55ed155ee600
python threads support enabled
your server socket listen backlog is limited to 0 connections
your mercy for graceful operations on workers is 60 seconds
*** Operational MODE: no-workers ***
WSGI app 0 (mountpoint='') ready in 2 seconds on interpreter 0x55ed155ee600 pid: 97 (default app)
spawned uWSGI master process (pid: 97)

nginx logs:

2022/09/08 17:31:06 [error] 37#37: *63 upstream timed out (110: Operation timed out) while connecting to upstream, client: 172.18.0.11, server: dashboard.internal, request: "GET /admin/login/ HTTP/1.1", upstream: "uwsgi://172.18.0.5:8000", host: "dashboard.internal"
[f73fd7c838ca] - - [08/Sep/2022:17:31:06 -0400] "GET /admin/login/ HTTP/1.1" status: 504 160 "-" "Wget" http_x_forwarded_for: - - remote_addr: 172.18.0.11 - realip_remote_addr: 172.18.0.11 - real_ip: 172.18.0.11
2022/09/08 17:32:11 [error] 37#37: *65 upstream timed out (110: Operation timed out) while connecting to upstream, client: 172.18.0.11, server: dashboard.internal, request: "GET /admin/login/ HTTP/1.1", upstream: "uwsgi://172.18.0.5:8000", host: "dashboard.internal"
[f73fd7c838ca] - - [08/Sep/2022:17:32:11 -0400] "GET /admin/login/ HTTP/1.1" status: 504 160 "-" "Wget" http_x_forwarded_for: - - remote_addr: 172.18.0.11 - realip_remote_addr: 172.18.0.11 - real_ip: 172.18.0.11
2022/09/08 17:33:16 [error] 37#37: *67 upstream timed out (110: Operation timed out) while connecting to upstream, client: 172.18.0.11, server: dashboard.internal, request: "GET /admin/login/ HTTP/1.1", upstream: "uwsgi://172.18.0.5:8000", host: "dashboard.internal"
[f73fd7c838ca] - - [08/Sep/2022:17:33:16 -0400] "GET /admin/login/ HTTP/1.1" status: 504 160 "-" "Wget" http_x_forwarded_for: - - remote_addr: 172.18.0.11 - realip_remote_addr: 172.18.0.11 - real_ip: 172.18.0.11

[scott-grimes]

looks like I mis-interpreted the .env file. some of those values must explicitly be set because they do not have defaults within the images.

UWSGI_PROCESSES=2
UWSGI_THREADS=2
UWSGI_LISTEN=100

were the culprits in this case. checking the /opt/openwisp/uwsgi.ini file in the dashboard container revealed the issue

having a further problem however: logging in fails. using the default admin:admin credentials I get a 302 response to the POST with a location of /admin/, but this simply takes me back to the login page.

[atb00ker]

having a further problem however: logging in fails. using the default admin:admin credentials I get a 302 response to the POST with a location of /admin/, but this simply takes me back to the login page.

I have heard about this from some other folks as well, but they fail to help me find information for debugging. In past, most people have just reset their machines / installed newer version of debian/ubuntu and it worked! 😄

[atb00ker]

UWSGI_PROCESSES=2 UWSGI_THREADS=2 UWSGI_LISTEN=100

This might have been a newer change, the correct thing to do is have default for these! 😄

[scott-grimes]

@atb00ker

hmm I'm pulling the latest docker images openwisp/openwisp-dashboard:latest, sha256:e5351cb8e1ad0d4eecac6278591e1b315a9151c79b5139c1e2cb34e5e4db033a

I've also tried building using the current master branch, both give the same result with the 302 responst to POST bringing me back to the login page

heres the logs of the dashboard container

[875931634a3f] - pid: 156 - (-) {16 vars in 169 bytes} [Fri Sep 23 19:05:20 2022] GET / => generated 0 bytes in 560 msecs (HTTP/1.1 302) 8 headers in 241 bytes (1 switches on core 0)
[875931634a3f] - pid: 156 - (-) {16 vars in 169 bytes} [Fri Sep 23 19:05:20 2022] GET / => generated 0 bytes in 555 msecs (HTTP/1.1 302) 8 headers in 241 bytes (1 switches on core 1)
[875931634a3f] - pid: 154 - (-) {16 vars in 169 bytes} [Fri Sep 23 19:05:20 2022] GET / => generated 0 bytes in 648 msecs (HTTP/1.1 302) 8 headers in 241 bytes (1 switches on core 0)
[875931634a3f] - pid: 154 - (-) {16 vars in 169 bytes} [Fri Sep 23 19:05:20 2022] GET / => generated 0 bytes in 643 msecs (HTTP/1.1 302) 8 headers in 241 bytes (1 switches on core 1)
[875931634a3f] - pid: 154 172.18.0.11 (-) {32 vars in 380 bytes} [Fri Sep 23 19:05:25 2022] GET /admin/login/ => generated 2777 bytes in 142 msecs (HTTP/1.1 200) 10 headers in 518 bytes (1 switches on core 0)
[875931634a3f] - pid: 154 172.18.0.1 (-) {56 vars in 1030 bytes} [Fri Sep 23 19:05:50 2022] GET /admin/login/?next=/admin/ => generated 2790 bytes in 10 msecs (HTTP/1.1 200) 10 headers in 518 bytes (1 switches on core 1)
[875931634a3f] - pid: 156 172.18.0.1 (-) {64 vars in 1213 bytes} [Fri Sep 23 19:06:01 2022] POST /admin/login/?next=/admin/ => generated 0 bytes in 250 msecs (HTTP/1.1 302) 14 headers in 805 bytes (1 switches on core 0)
[875931634a3f] - pid: 156 172.18.0.1 (-) {58 vars in 1018 bytes} [Fri Sep 23 19:06:01 2022] GET /admin/ => generated 0 bytes in 1 msecs (HTTP/1.1 302) 10 headers in 380 bytes (1 switches on core 1)
[875931634a3f] - pid: 156 172.18.0.1 (-) {58 vars in 1055 bytes} [Fri Sep 23 19:06:01 2022] GET /admin/login/?next=/admin/ => generated 2790 bytes in 74 msecs (HTTP/1.1 200) 10 headers in 518 bytes (1 switches on core 0)
[875931634a3f] - pid: 156 172.18.0.1 (-) {64 vars in 1213 bytes} [Fri Sep 23 19:07:02 2022] POST /admin/login/?next=/admin/ => generated 0 bytes in 420 msecs (HTTP/1.1 302) 14 headers in 805 bytes (1 switches on core 1)
[875931634a3f] - pid: 154 172.18.0.1 (-) {58 vars in 1018 bytes} [Fri Sep 23 19:07:03 2022] GET /admin/ => generated 0 bytes in 26 msecs (HTTP/1.1 302) 10 headers in 380 bytes (1 switches on core 0)
[875931634a3f] - pid: 154 172.18.0.1 (-) {58 vars in 1055 bytes} [Fri Sep 23 19:07:03 2022] GET /admin/login/?next=/admin/ => generated 2790 bytes in 20 msecs (HTTP/1.1 200) 10 headers in 518 bytes (1 switches on core 1)

and a screenshot. happy to provide any other debugging info you'd like!

[atb00ker]

Thanks a lot, unfortunately, I didn't get around to checking this. Will ping when I do! 😄

[nemesifier]

Should be fixed on latest master, please reopen if that's not the case.