[go: nahoru, domu]

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

1.5.11 HTTP Server Error 500 (downgrade solves issue) #2893

Closed
nicedevil007 opened this issue Jan 19, 2024 · 21 comments
Closed

1.5.11 HTTP Server Error 500 (downgrade solves issue) #2893

nicedevil007 opened this issue Jan 19, 2024 · 21 comments

Comments

@nicedevil007
Copy link
Contributor
nicedevil007 commented Jan 19, 2024

Tandoor Version

1.5.11

Setup

Docker / Docker-Compose

Reverse Proxy

Nginx Proxy Manager (NPM)

Other

No response

Bug description

I updated my environment on docker compose with the following docker compose file:

---
version: "3.9"
services:
  db_recipes:
    restart: always
    image: postgres:15-alpine
    container_name: tandoor_db
    volumes:
      - ./data:/var/lib/postgresql/data
      - ./backup:/backup
    environment:
      TIMEZONE: Europe/Berlin
      POSTGRES_PORT: 5432
      POSTGRES_USER: ###########
      POSTGRES_PASSWORD: ###########
      POSTGRES_DB: djangodb
  web_recipes:
    restart: always
    image: vabene1111/recipes:latest
    container_name: tandoor_web
    environment:
      ALLOWED_HOSTS: "*"
      SECRET_KEY: ###########
      TZ: Europe/Berlin
      DB_ENGINE: django.db.backends.postgresql
      POSTGRES_HOST: db_recipes
      POSTGRES_PORT: 5432
      POSTGRES_USER: ###########
      POSTGRES_PASSWORD: ###########
      POSTGRES_DB: djangodb
      FRACTION_PREF_DEFAULT: 1
      COMMENT_PREF_DEFAULT: 1
      SHOPPING_MIN_AUTOSYNC_INTERVAL: 5
      EMAIL_HOST: ###########
      EMAIL_PORT: 587
      EMAIL_HOST_USER: ###########
      EMAIL_HOST_PASSWORD: ###########
      EMAIL_USE_TLS: 1
      EMAIL_USE_SSL: 0
      DEFAULT_FROM_EMAIL: ###########
      ACCOUNT_EMAIL_SUBJECT_PREFIX: "###########"
      ENABLE_SIGNUP: 1
      ENABLE_PDF_EXPORT: 1
      SOCIAL_DEFAULT_ACCESS: 0
      SORT_TREE_BY_NAME: 1
      GUNICORN_MEDIA: 0
      DEBUG: 0
      DISABLE_TREE_FIX_STARTUP: 1
    volumes:
      - ./staticfiles:/opt/recipes/staticfiles
      - ./nginx_config:/opt/recipes/nginx/conf.d
      - ./mediafiles:/opt/recipes/mediafiles
    depends_on:
      - db_recipes
  nginx_recipes:
    image: nginx:mainline-alpine
    restart: always
    container_name: tandoor_nginx
    ports:
      - 8070:80
    depends_on:
      - web_recipes
    volumes:
      - ./nginx_config:/etc/nginx/conf.d:ro
      - ./staticfiles:/static:ro
      - ./mediafiles:/media:ro
volumes:
  nginx_config: null
  staticfiles: null
  mediafiles: null
  postgresql: null
networks: {}

It doesn't matter if I use local IP or DNS to access the IP.
If I use the tag on the docker image to revert back to 1.5.10 everything works.

    image: vabene1111/recipes:1.5.10

Relevant logs

This leads instant to the error:
image

@smilerz
Copy link
Collaborator
smilerz commented Jan 19, 2024

please provide logs

@anytimesoon
Copy link

This has happened to me also. Logs posted below. I can't see anything odd in them, though

[2024-01-19 23:42:51 +0100] [1] [INFO] Starting gunicorn 20.1.0
[2024-01-19 23:42:51 +0100] [1] [INFO] Listening at: http://0.0.0.0:8080 (1)
[2024-01-19 23:42:51 +0100] [1] [INFO] Using worker: gthread
[2024-01-19 23:42:51 +0100] [12] [INFO] Booting worker with pid: 12
[2024-01-19 23:42:51 +0100] [13] [INFO] Booting worker with pid: 13
[2024-01-19 23:42:51 +0100] [14] [INFO] Booting worker with pid: 14
192.168.16.3 - - [19/Jan/2024:23:42:55 +0100] "GET / HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:55 +0100] "GET /search/ HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:55 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:56 +0100] "GET /favicon.ico HTTP/1.1" 404 6346 "https://recipes.delartigue.xyz/accounts/login/?next=/search/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:58 +0100] "GET / HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:58 +0100] "GET /search/ HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:59 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:42:59 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:43:03 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:43:09 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:43:32 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:43:35 +0100] "GET / HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:43:35 +0100] "GET /search/ HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:43:35 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:22 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:27 +0100] "GET / HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:27 +0100] "GET /search/ HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:28 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:32 +0100] "GET /search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Mobile Safari/537.36"
192.168.16.3 - - [19/Jan/2024:23:44:33 +0100] "GET /favicon.ico HTTP/1.1" 500 145 "https://recipes.delartigue.xyz/search/" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Mobile Safari/537.36"
192.168.16.3 - - [19/Jan/2024:23:44:35 +0100] "GET /service-worker.js HTTP/1.1" 500 145 "https://recipes.delartigue.xyz/service-worker.js" "Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Mobile Safari/537.36"
192.168.16.3 - - [19/Jan/2024:23:44:42 +0100] "GET / HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:44 +0100] "GET /search/ HTTP/1.1" 302 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"
192.168.16.3 - - [19/Jan/2024:23:44:44 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:121.0) Gecko/20100101 Firefox/121.0"

@smilerz
Copy link
Collaborator
smilerz commented Jan 19, 2024

is debug enabled? have you tried clearing the browser cache? any messages in browser console?

@danieljkemp
Copy link

I've got the same thing here. Looks like I was hit by this AND the keycloak allauth deprecation (with no breaking change in the patch notes, :( )

So I was trying to debug two things at once it turns out.

Nothing notable in the logs with debug turned on. The curious bit is, once I reset my django admin pass and fixed the OIDC config, a browser with an old session was functional, but a browser that had never logged in, and a private session both gave the 500 error and landed me here.

@vabene1111
Copy link
Collaborator

I did not mean to deprecated anything, must have been something in the changelog of django all Auth that I missed. Will take a look later

@danieljkemp
Copy link

Sorry for the passive aggressive response the culprit is
mentioned in
#2706

FWIIW their changes make sense, and updating auth libraries is always a good idea in general was just cuag off guard and had to go digging

Only an issue if already using Keycloak specifically, swapping was easier than I thought, but this 500 error bug made me think the oauth switch wasn't working

@nicedevil007
Copy link
Contributor Author

So does that mean you got it up an working again @danieljkemp? I don't use keycloak but I had Authentik in the past but I disabled it maybe 6-9 months ago.

@danieljkemp
Copy link

Keycloak works with the openid_connect allauth plugin. But currently only in a tab that previously had a valid session due to the above bug?

Private browser session and it gives the 500 as above and I haven't seen why in the logs (with debug on).

But hey at least I am 80% sure that keycloak is working right ;)

@smilerz
Copy link
Collaborator
smilerz commented Jan 20, 2024

Keycloak works with the openid_connect allauth plugin. But currently only in a tab that previously had a valid session due to the above bug?

Private browser session and it gives the 500 as above and I haven't seen why in the logs (with debug on).

But hey at least I am 80% sure that keycloak is working right ;)

Keycloak was deprecated in the allauth library.

@vabene1111
Copy link
Collaborator

Ok so has this been resolved? I cannot really help here since for me the update works fine and without any debug logs I cant see any error.

If you are still having issues please set DEBUG=1 in your .env and post the logs here when making the request.

@vabene1111
Copy link
Collaborator

I also added a note to the changelog regarding keycloak

@danieljkemp
Copy link

Ok so has this been resolved? I cannot really help here since for me the update works fine and without any debug logs I cant see any error.

If you are still having issues please set DEBUG=1 in your .env and post the logs here when making the request.

@anytimesoon @nicedevil007 Are you folks using OIDC plugins? I am still seeing the issue after updating keycloak to use OIDC directly in allauth. In a session with existing cookies the page loads with no errors, but it throws the 500 in a session without a session.

I don't get much from the debug logs. Things fail before they can hit an oauth provider at all

[2024-01-22 14:37:22 +0100] [7] [DEBUG] GET /
172.30.3.27 - - [22/Jan/2024:14:37:22 +0100] "GET / HTTP/1.1" 302 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0"
[2024-01-22 14:37:22 +0100] [7] [DEBUG] GET /search/
172.30.3.27 - - [22/Jan/2024:14:37:22 +0100] "GET /search/ HTTP/1.1" 302 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0"
[2024-01-22 14:37:22 +0100] [7] [DEBUG] GET /accounts/login/
172.30.3.27 - - [22/Jan/2024:14:37:22 +0100] "GET /accounts/login/?next=/search/ HTTP/1.1" 500 145 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0"
[2024-01-22 14:37:22 +0100] [7] [DEBUG] GET /favicon.ico
172.30.3.27 - - [22/Jan/2024:14:37:22 +0100] "GET /favicon.ico HTTP/1.1" 404 6370 "https://recipes.especiallyrelative.net/accounts/login/?next=/search/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0"

This is all I get in the debug logs, nothing is seen from the keycloak side, the browser does not show any requests other than these either.

@anytimesoon
Copy link

I'm not using any special auth service. Just whatever is provided by tandoor. So, I don't think this was related to auth in my case.

I dont have access to my laptop this week, so can't help much more than that at the moment, I'm afraid.

If this issue is ongoing next week, I'll chime in again. Sorry about that

@nicedevil007
Copy link
Contributor Author
nicedevil007 commented Jan 22, 2024

I removed the OIDC part with authentik months ago, I guess more than 2-3 Updates are gone since that.
Here is my output of the webgui after enabling debug=1

<html>
<body>
<!--StartFragment--><h1 style="padding: 0px; margin: 0px; font-weight: normal; color: rgb(0, 0, 0); font-family: sans-serif; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; white-space: normal; text-decoration-thickness: initial; text-decoration-style: initial; text-decoration-color: initial;">ProgrammingError at /</h1><pre class="exception_value" style="padding: 0px; margin: 10px 0px; font-size: 1.5em; white-space: pre-wrap; word-break: break-word; font-family: sans-serif; color: rgb(87, 87, 87); font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: 400; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-thickness: initial; text-decoration-style: initial; text-decoration-color: initial;">column cookbook_space.space_theme does not exist
LINE 1: ...kbook_space"."name", "cookbook_space"."image_id", "cookbook_...
                                                             ^
</pre>
Request Method: | GET
-- | --
https://xxxxxxxxxxxxx
4.2.7
ProgrammingError
column cookbook_space.space_theme does not exist LINE 1: ...kbook_space"."name", "cookbook_space"."image_id", "cookbook_...                                                              ^
/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py, line 89, in _execute
cookbook.views.views.index
/opt/recipes/venv/bin/python
3.10.13
['/opt/recipes',  '/opt/recipes/venv/bin',  '/usr/local/lib/python310.zip',  '/usr/local/lib/python3.10',  '/usr/local/lib/python3.10/lib-dynload',  '/opt/recipes/venv/lib/python3.10/site-packages']
Mon, 22 Jan 2024 21:30:32 +0100

<!--EndFragment-->
</body>
</html>

@smilerz
Copy link
Collaborator
smilerz commented Jan 22, 2024

can you provide the container logs starting at initial boot?

@nicedevil007
Copy link
Contributor Author

Sure, have to restore a backup right now because I'm testing other stuff as well.

I just took the whole compose and created a complete new environment, deleted the old one, all volumes deleted etc.
Again, this was/is my docker-compose.yaml

version: "3.9"
services:
  db_recipes:
    restart: always
    image: postgres:15-alpine
    container_name: tandoor_db
    volumes:
      - ./data:/var/lib/postgresql/data
      - ./backup:/backup
    environment:
      - TZ=${TZ}
      - POSTGRES_PORT=${POSTGRES_PORT}
      - POSTGRES_USER=${POSTGRES_USER}
      - POSTGRES_PASSWORD=${POSTGRES_PASSWORD}
      - POSTGRES_DB=${POSTGRES_DB}
  web_recipes:
    restart: always
    image: vabene1111/recipes:1.5.11
    container_name: tandoor_web
    environment:
      - ALLOWED_HOSTS=${ALLOWED_HOSTS}
      - SECRET_KEY=${SECRET_KEY}
      - TZ=${TZ}
      - DB_ENGINE=${DB_ENGINE}
      - POSTGRES_HOST=${POSTGRES_HOST}
      - POSTGRES_PORT=${POSTGRES_PORT}
      - POSTGRES_USER=${POSTGRES_USER}
      - POSTGRES_PASSWORD=${POSTGRES_PASSWORD}
      - POSTGRES_DB=${POSTGRES_DB}
      - FRACTION_PREF_DEFAULT=${FRACTION_PREF_DEFAULT}
      - COMMENT_PREF_DEFAULT=${COMMENT_PREF_DEFAULT}
      - SHOPPING_MIN_AUTOSYNC_INTERVAL=${SHOPPING_MIN_AUTOSYNC_INTERVAL}
      - EMAIL_HOST=${EMAIL_HOST}
      - EMAIL_PORT=${EMAIL_PORT}
      - EMAIL_HOST_USER=${EMAIL_HOST_USER}
      - EMAIL_HOST_PASSWORD=${EMAIL_HOST_PASSWORD}
      - EMAIL_USE_TLS=${EMAIL_USE_TLS}
      - EMAIL_USE_SSL=${EMAIL_USE_SSL}
      - DEFAULT_FROM_EMAIL=${DEFAULT_FROM_EMAIL}
      - ACCOUNT_EMAIL_SUBJECT_PREFIX=${ACCOUNT_EMAIL_SUBJECT_PREFIX}
      - ENABLE_SIGNUP=${ENABLE_SIGNUP}
      - ENABLE_PDF_EXPORT=${ENABLE_PDF_EXPORT}
      - SOCIAL_DEFAULT_ACCESS=${SOCIAL_DEFAULT_ACCESS}
      - SORT_TREE_BY_NAME=${SORT_TREE_BY_NAME}
      - GUNICORN_MEDIA=${GUNICORN_MEDIA}
      - DEBUG=${DEBUG}
      - DISABLE_TREE_FIX_STARTUP=${DISABLE_TREE_FIX_STARTUP}
    volumes:
      - ./staticfiles:/opt/recipes/staticfiles
      - ./nginx_config:/opt/recipes/nginx/conf.d
      - ./mediafiles:/opt/recipes/mediafiles
    depends_on:
      - db_recipes
  nginx_recipes:
    image: nginx:mainline-alpine
    restart: always
    container_name: tandoor_nginx
    ports:
      - 8070:80
    depends_on:
      - web_recipes
    volumes:
      - ./nginx_config:/etc/nginx/conf.d:ro
      - ./staticfiles:/static:ro
      - ./mediafiles:/media:ro
volumes:
  nginx_config: null
  staticfiles: null
  mediafiles: null
  postgresql: null
networks: {}

this one the .env file for this stack:

ALLOWED_HOSTS="*"
SECRET_KEY=###############
TZ=Europe/Berlin
DB_ENGINE=django.db.backends.postgresql
POSTGRES_HOST=db_recipes
POSTGRES_PORT=5432
POSTGRES_USER=djangouser
POSTGRES_PASSWORD=###############
POSTGRES_DB=djangodb
FRACTION_PREF_DEFAULT=1
COMMENT_PREF_DEFAULT=1
SHOPPING_MIN_AUTOSYNC_INTERVAL=5
EMAIL_HOST=###############
EMAIL_PORT=587
EMAIL_HOST_USER=###############
EMAIL_HOST_PASSWORD=###############
EMAIL_USE_TLS=1
EMAIL_USE_SSL=0
DEFAULT_FROM_EMAIL=###############
ACCOUNT_EMAIL_SUBJECT_PREFIX="###############"
ENABLE_SIGNUP=1
ENABLE_PDF_EXPORT=1
SOCIAL_DEFAULT_ACCESS=0
SORT_TREE_BY_NAME=1
GUNICORN_MEDIA=0
DEBUG=1
DISABLE_TREE_FIX_STARTUP=1

This leads to a not accessible webui at all. I can't even do the normal localipadress:port stuff to get access to it.
docker ends with this:

tandoor_web    |   Applying oauth2_provider.0001_initial... OK
tandoor_web    |   Applying oauth2_provider.0002_auto_20190406_1805... OK
tandoor_web    |   Applying oauth2_provider.0003_auto_20201211_1314... OK
tandoor_web    |   Applying oauth2_provider.0004_auto_20200902_2022... OK
tandoor_web    |   Applying oauth2_provider.0005_auto_20211222_2352... OK
tandoor_web    |   Applying oauth2_provider.0006_alter_application_client_secret... OK
tandoor_web    |   Applying oauth2_provider.0007_application_post_logout_redirect_uris... OK
tandoor_web    |   Applying sessions.0001_initial... OK
tandoor_web    |   Applying sites.0001_initial... OK
tandoor_web    |   Applying sites.0002_alter_domain_unique... OK
tandoor_web    |   Applying socialaccount.0001_initial... OK
tandoor_web    |   Applying socialaccount.0002_token_max_lengths... OK
tandoor_web    |   Applying socialaccount.0003_extra_data_default_dict... OK
tandoor_web    |   Applying socialaccount.0004_app_provider_id_settings... OK
tandoor_web    |   Applying socialaccount.0005_socialtoken_nullable_app... OK
tandoor_web    |   Applying socialaccount.0006_alter_socialaccount_extra_data... OK
tandoor_web    | Generating static files
tandoor_web    | js-reverse file written to /opt/recipes/cookbook/static/django_js_reverse
tandoor_web    | 
tandoor_web    | 649 static files copied to '/opt/recipes/staticfiles', 1705 post-processed.
tandoor_web    | Done
tandoor_web    | [2024-01-22 21:44:33 +0100] [1] [INFO] Starting gunicorn 20.1.0
tandoor_web    | [2024-01-22 21:44:33 +0100] [1] [INFO] Listening at: http://0.0.0.0:8080 (1)
tandoor_web    | [2024-01-22 21:44:33 +0100] [1] [INFO] Using worker: gthread
tandoor_web    | [2024-01-22 21:44:33 +0100] [14] [INFO] Booting worker with pid: 14
tandoor_web    | [2024-01-22 21:44:34 +0100] [15] [INFO] Booting worker with pid: 15
tandoor_web    | [2024-01-22 21:44:34 +0100] [16] [INFO] Booting worker with pid: 16

I will post docker stuff from the previous installation in a few minutes, this here was all done with a fresh new installation

@smilerz
Copy link
Collaborator
smilerz commented Jan 22, 2024

is that full log or did you truncate it? those migrations don't look complete.

@nicedevil007
Copy link
Contributor Author

is that full log or did you truncate it? those migrations don't look complete.

that was ofc truncated, but for this evening I will stop here, I did the roleback to backup where 1.5.10 was working and updated to 1.5.11 and here is the complete log after a fresh start of the 1.5.11 with the files from a previous 1.5.10 installation:

/opt/stacks/tandoor # docker compose logs
tandoor_db  | 
tandoor_db  | PostgreSQL Database directory appears to contain a database; Skipping initialization
tandoor_db  | 
tandoor_db  | 2024-01-22 20:58:57.285 UTC [1] LOG:  starting PostgreSQL 15.5 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
tandoor_db  | 2024-01-22 20:58:57.285 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
tandoor_db  | 2024-01-22 20:58:57.285 UTC [1] LOG:  listening on IPv6 address "::", port 5432
tandoor_db  | 2024-01-22 20:58:57.296 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
tandoor_db  | 2024-01-22 20:58:57.307 UTC [24] LOG:  database system was shut down at 2024-01-22 20:58:45 UTC
tandoor_db  | 2024-01-22 20:58:57.312 UTC [1] LOG:  database system is ready to accept connections
tandoor_db  | 2024-01-22 20:58:59.041 UTC [29] ERROR:  invalid input syntax for type integer: "2345232-cherry"
tandoor_db  | 2024-01-22 20:58:59.041 UTC [29] STATEMENT:  ALTER TABLE "cookbook_food" ALTER COLUMN "fdc_id" TYPE integer USING "fdc_id"::integer
tandoor_nginx  | /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
tandoor_nginx  | /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
tandoor_nginx  | /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
tandoor_nginx  | 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf is not a file or does not exist
tandoor_nginx  | /docker-entrypoint.sh: Sourcing /docker-entrypoint.d/15-local-resolvers.envsh
tandoor_nginx  | /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
tandoor_nginx  | /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
tandoor_nginx  | /docker-entrypoint.sh: Configuration complete; ready for start up
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: using the "epoll" event method
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: nginx/1.25.3
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: built by gcc 12.2.1 20220924 (Alpine 12.2.1_git20220924-r10) 
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: OS: Linux 6.5.11-7-pve
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1024:524288
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: start worker processes
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: start worker process 20
tandoor_nginx  | 2024/01/22 20:58:57 [notice] 1#1: start worker process 21
tandoor_nginx  | 2024/01/22 20:58:58 [error] 20#20: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.1, server: localhost, request: "GET / HTTP/1.1", upstream: "http://172.25.0.3:8080/", host: "COOKBOOK.MYDOMAIN.EXAMPLE"
tandoor_nginx  | 172.25.0.1 - - [22/Jan/2024:20:58:58 +0000] "GET / HTTP/1.1" 502 4295 "-" "axios/1.6.0" "10.0.42.6"
tandoor_web    | Checking configuration...
tandoor_web    | Waiting for database to be ready...
tandoor_web    | Database is ready
tandoor_web    | Migrating database
tandoor_web    | Operations to perform:
tandoor_web    |   Apply all migrations: account, admin, auth, authtoken, contenttypes, cookbook, oauth2_provider, sessions, sites, socialaccount
tandoor_web    | Running migrations:
tandoor_web    | Traceback (most recent call last):
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py", line 87, in _execute
tandoor_web    |     return self.cursor.execute(sql)
tandoor_web    | psycopg2.errors.InvalidTextRepresentation: invalid input syntax for type integer: "2345232-cherry"
tandoor_web    | 
tandoor_web    | 
tandoor_web    | The above exception was the direct cause of the following exception:
tandoor_web    | 
tandoor_web    | Traceback (most recent call last):
tandoor_web    |   File "/opt/recipes/manage.py", line 15, in <module>
tandoor_web    |     execute_from_command_line(sys.argv)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/core/management/__init__.py", line 442, in execute_from_command_line
tandoor_web    |     utility.execute()
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/core/management/__init__.py", line 436, in execute
tandoor_web    |     self.fetch_command(subcommand).run_from_argv(self.argv)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/core/management/base.py", line 412, in run_from_argv
tandoor_web    |     self.execute(*args, **cmd_options)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/core/management/base.py", line 458, in execute
tandoor_web    |     output = self.handle(*args, **options)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/core/management/base.py", line 106, in wrapper
tandoor_web    |     res = handle_func(*args, **kwargs)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/core/management/commands/migrate.py", line 356, in handle
tandoor_web    |     post_migrate_state = executor.migrate(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/migrations/executor.py", line 135, in migrate
tandoor_web    |     state = self._migrate_all_forwards(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/migrations/executor.py", line 167, in _migrate_all_forwards
tandoor_web    |     state = self.apply_migration(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/migrations/executor.py", line 252, in apply_migration
tandoor_web    |     state = migration.apply(state, schema_editor)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/migrations/migration.py", line 132, in apply
tandoor_web    |     operation.database_forwards(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/migrations/operations/fields.py", line 235, in database_forwards
tandoor_web    |     schema_editor.alter_field(from_model, from_field, to_field)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/base/schema.py", line 830, in alter_field
tandoor_web    |     self._alter_field(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/postgresql/schema.py", line 288, in _alter_field
tandoor_web    |     super()._alter_field(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/base/schema.py", line 1055, in _alter_field
tandoor_web    |     self.execute(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/postgresql/schema.py", line 48, in execute
tandoor_web    |     return super().execute(sql, None)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/base/schema.py", line 201, in execute
tandoor_web    |     cursor.execute(sql, params)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py", line 102, in execute
tandoor_web    |     return super().execute(sql, params)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py", line 67, in execute
tandoor_web    |     return self._execute_with_wrappers(
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py", line 80, in _execute_with_wrappers
tandoor_web    |     return executor(sql, params, many, context)
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
tandoor_web    |     with self.db.wrap_database_errors:
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/utils.py", line 91, in __exit__
tandoor_web    |     raise dj_exc_value.with_traceback(traceback) from exc_value
tandoor_web    |   File "/opt/recipes/venv/lib/python3.10/site-packages/django/db/backends/utils.py", line 87, in _execute
tandoor_web    |     return self.cursor.execute(sql)
tandoor_web    | django.db.utils.DataError: invalid input syntax for type integer: "2345232-cherry"
tandoor_web    | 
tandoor_web    |   Applying cookbook.0205_alter_food_fdc_id_alter_propertytype_fdc_id...Generating static files
tandoor_web    | js-reverse file written to /opt/recipes/cookbook/static/django_js_reverse
tandoor_web    | 
tandoor_web    | 1 static file copied to '/opt/recipes/staticfiles', 648 unmodified, 1397 post-processed.
tandoor_web    | Done
tandoor_web    | [2024-01-22 21:59:05 +0100] [1] [INFO] Starting gunicorn 20.1.0
tandoor_web    | [2024-01-22 21:59:05 +0100] [1] [INFO] Listening at: http://0.0.0.0:8080 (1)
tandoor_web    | [2024-01-22 21:59:05 +0100] [1] [INFO] Using worker: gthread
tandoor_web    | [2024-01-22 21:59:05 +0100] [12] [INFO] Booting worker with pid: 12
tandoor_web    | [2024-01-22 21:59:05 +0100] [13] [INFO] Booting worker with pid: 13
tandoor_web    | [2024-01-22 21:59:05 +0100] [14] [INFO] Booting worker with pid: 14

@smilerz
Copy link
Collaborator
smilerz commented Jan 22, 2024

duplicate #2894

@nicedevil007
Copy link
Contributor Author

is that full log or did you truncate it? those migrations don't look complete.

here the not truncated one with a complete fresh docker compose (I just added _test to all names of the containers etc.)

/opt/stacks/tandoor_test # docker compose logs -f
tandoor_web_test    | Checking configuration...
tandoor_web_test    | [WARNING]
tandoor_web_test    | Nginx configuration file could not be found at the default location!
tandoor_web_test    | Path: /opt/recipes/nginx/conf.d/Recipes.conf
tandoor_web_test    | Waiting for database to be ready...
tandoor_web_test    | 
tandoor_web_test    | Database not reachable. Maximum attempts exceeded.
tandoor_web_test    | Please check logs above - misconfiguration is very likely.
tandoor_web_test    | Make sure the DB container is up and POSTGRES_HOST is set properly.
tandoor_web_test    | Shutting down container.
tandoor_web_test    | Checking configuration...
tandoor_web_test    | [WARNING]
tandoor_web_test    | Nginx configuration file could not be found at the default location!
tandoor_web_test    | Path: /opt/recipes/nginx/conf.d/Recipes.conf
tandoor_web_test    | Waiting for database to be ready...
tandoor_nginx_test  | /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
tandoor_nginx_test  | /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
tandoor_nginx_test  | /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
tandoor_nginx_test  | 10-listen-on-ipv6-by-default.sh: info: /etc/nginx/conf.d/default.conf is not a file or does not exist
tandoor_nginx_test  | /docker-entrypoint.sh: Sourcing /docker-entrypoint.d/15-local-resolvers.envsh
tandoor_nginx_test  | /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
tandoor_nginx_test  | /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
tandoor_nginx_test  | /docker-entrypoint.sh: Configuration complete; ready for start up
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: using the "epoll" event method
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: nginx/1.25.3
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: built by gcc 12.2.1 20220924 (Alpine 12.2.1_git20220924-r10) 
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: OS: Linux 6.5.11-7-pve
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1024:524288
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: start worker processes
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: start worker process 20
tandoor_nginx_test  | 2024/01/22 21:04:42 [notice] 1#1: start worker process 21
tandoor_db_test     | The files belonging to this database system will be owned by user "postgres".
tandoor_db_test     | This user must also own the server process.
tandoor_db_test     | 
tandoor_db_test     | The database cluster will be initialized with locale "en_US.utf8".
tandoor_db_test     | The default database encoding has accordingly been set to "UTF8".
tandoor_db_test     | The default text search configuration will be set to "english".
tandoor_db_test     | 
tandoor_db_test     | Data page checksums are disabled.
tandoor_db_test     | 
tandoor_db_test     | fixing permissions on existing directory /var/lib/postgresql/data ... ok
tandoor_db_test     | creating subdirectories ... ok
tandoor_db_test     | selecting dynamic shared memory implementation ... posix
tandoor_db_test     | selecting default max_connections ... 100
tandoor_db_test     | selecting default shared_buffers ... 128MB
tandoor_db_test     | selecting default time zone ... Europe/Berlin
tandoor_db_test     | creating configuration files ... ok
tandoor_db_test     | running bootstrap script ... ok
tandoor_db_test     | sh: locale: not found
tandoor_db_test     | 2024-01-22 22:04:42.648 CET [31] WARNING:  no usable system locales were found
tandoor_db_test     | performing post-bootstrap initialization ... ok
tandoor_db_test     | syncing data to disk ... ok
tandoor_db_test     | 
tandoor_db_test     | 
tandoor_db_test     | Success. You can now start the database server using:
tandoor_db_test     | 
tandoor_db_test     |     pg_ctl -D /var/lib/postgresql/data -l logfile start
tandoor_db_test     | 
tandoor_db_test     | initdb: warning: enabling "trust" authentication for local connections
tandoor_db_test     | initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
tandoor_db_test     | waiting for server to start....2024-01-22 22:04:43.596 CET [37] LOG:  starting PostgreSQL 15.5 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
tandoor_db_test     | 2024-01-22 22:04:43.598 CET [37] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
tandoor_db_test     | 2024-01-22 22:04:43.606 CET [40] LOG:  database system was shut down at 2024-01-22 22:04:43 CET
tandoor_db_test     | 2024-01-22 22:04:43.611 CET [37] LOG:  database system is ready to accept connections
tandoor_db_test     |  done
tandoor_db_test     | server started
tandoor_db_test     | CREATE DATABASE
tandoor_db_test     | 
tandoor_db_test     | 
tandoor_db_test     | /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
tandoor_db_test     | 
tandoor_db_test     | 2024-01-22 22:04:43.739 CET [37] LOG:  received fast shutdown request
tandoor_db_test     | waiting for server to shut down....2024-01-22 22:04:43.745 CET [37] LOG:  aborting any active transactions
tandoor_db_test     | 2024-01-22 22:04:43.748 CET [37] LOG:  background worker "logical replication launcher" (PID 43) exited with exit code 1
tandoor_db_test     | 2024-01-22 22:04:43.748 CET [38] LOG:  shutting down
tandoor_db_test     | 2024-01-22 22:04:43.752 CET [38] LOG:  checkpoint starting: shutdown immediate
tandoor_db_test     | 2024-01-22 22:04:44.469 CET [38] LOG:  checkpoint complete: wrote 920 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.006 s, sync=0.697 s, total=0.722 s; sync files=301, longest=0.009 s, average=0.003 s; distance=4235 kB, estimate=4235 kB
tandoor_db_test     | 2024-01-22 22:04:44.474 CET [37] LOG:  database system is shut down
tandoor_db_test     |  done
tandoor_db_test     | server stopped
tandoor_db_test     | 
tandoor_db_test     | PostgreSQL init process complete; ready for start up.
tandoor_db_test     | 
tandoor_db_test     | 2024-01-22 22:04:44.559 CET [1] LOG:  starting PostgreSQL 15.5 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
tandoor_db_test     | 2024-01-22 22:04:44.559 CET [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
tandoor_db_test     | 2024-01-22 22:04:44.559 CET [1] LOG:  listening on IPv6 address "::", port 5432
tandoor_db_test     | 2024-01-22 22:04:44.565 CET [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
tandoor_db_test     | 2024-01-22 22:04:44.572 CET [53] LOG:  database system was shut down at 2024-01-22 22:04:44 CET
tandoor_db_test     | 2024-01-22 22:04:44.578 CET [1] LOG:  database system is ready to accept connections

@nicedevil007
Copy link
Contributor Author

ok, so we wait for the fix :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants
@smilerz @vabene1111 @danieljkemp @nicedevil007 @anytimesoon and others