search

seanmorley15 / AdventureLog

Self-hostable travel tracker and trip planner.
https://adventurelog.app
Other
562 stars 15 forks source link

[BUG] Failed to fetch visited adventures #318

Closed Afaren57 closed 1 month ago

Afaren57 commented 1 month ago

Describe the bug I can't access anymore to my adventures, collections or the map. Country visited still works and new user created can still access to it's adventure or collection page. However, he can't create any collection or adventure. When he tries, I get this error from DB logs :

2024-09-24 17:43:30.601 UTC [1320] ERROR: column adventures_adventure.date does not exist at character 346

2024-09-24 17:43:30.601 UTC [1320] HINT: Perhaps you meant to reference the column "adventures_adventure.name".

2024-09-24 17:43:30.601 UTC [1320] STATEMENT: SELECT "adventures_adventure"."id", "adventures_adventure"."user_id_id", "adventures_adventure"."type", "adventures_adventure"."name", "adventures_adventure"."location", "adventures_adventure"."activity_types", "adventures_adventure"."description", "adventures_adventure"."rating", "adventures_adventure"."link", "adventures_adventure"."image", "adventures_adventure"."date", "adventures_adventure"."end_date", "adventures_adventure"."is_public", "adventures_adventure"."longitude", "adventures_adventure"."latitude", "adventures_adventure"."collection_id", "adventures_adventure"."created_at", "adventures_adventure"."updated_at" FROM "adventures_adventure" WHERE "adventures_adventure"."collection_id" = 'xxxxxxxxxxxxxxxxxxxxxxxxxxxx'::uuid

For my own user, when I try to go to collection page, I have those logs : From frontend :

2024-09-24T17:46:34.884649874Z Failed to fetch visited adventures`

From backend :

2024-09-24T17:46:34.879972733Z Traceback (most recent call last):

2024-09-24T17:46:34.880156494Z File "/usr/local/lib/python3.10/site-packages/django/core/handlers/exception.py", line 55, in inner

2024-09-24T17:46:34.880215771Z response = get_response(request)

2024-09-24T17:46:34.880260786Z File "/usr/local/lib/python3.10/site-packages/django/core/handlers/base.py", line 197, in _get_response

2024-09-24T17:46:34.880312439Z response = wrapped_callback(request, *callback_args, **callback_kwargs)

2024-09-24T17:46:34.880358531Z File "/usr/local/lib/python3.10/site-packages/django/views/decorators/csrf.py", line 65, in _view_wrapper

2024-09-24T17:46:34.880413502Z return view_func(request, *args, **kwargs)

2024-09-24T17:46:34.880457869Z File "/usr/local/lib/python3.10/site-packages/rest_framework/viewsets.py", line 124, in view

2024-09-24T17:46:34.880522680Z return self.dispatch(request, *args, **kwargs)

2024-09-24T17:46:34.880569086Z File "/usr/local/lib/python3.10/site-packages/rest_framework/views.py", line 509, in dispatch

2024-09-24T17:46:34.880617744Z response = self.handle_exception(exc)

2024-09-24T17:46:34.880661901Z File "/usr/local/lib/python3.10/site-packages/rest_framework/views.py", line 469, in handle_exception

2024-09-24T17:46:34.880710299Z self.raise_uncaught_exception(exc)

2024-09-24T17:46:34.880752621Z File "/usr/local/lib/python3.10/site-packages/rest_framework/views.py", line 480, in raise_uncaught_exception

2024-09-24T17:46:34.880801112Z raise exc

2024-09-24T17:46:34.880872711Z File "/usr/local/lib/python3.10/site-packages/rest_framework/views.py", line 506, in dispatch

2024-09-24T17:46:34.880921073Z response = handler(request, *args, **kwargs)

2024-09-24T17:46:34.880967449Z File "/code/adventures/views.py", line 342, in list

2024-09-24T17:46:34.881013706Z collections = self.paginate_and_respond(queryset, request)

2024-09-24T17:46:34.881058206Z File "/code/adventures/views.py", line 504, in paginate_and_respond

2024-09-24T17:46:34.881105833Z return paginator.get_paginated_response(serializer.data)

2024-09-24T17:46:34.881155664Z File "/usr/local/lib/python3.10/site-packages/rest_framework/serializers.py", line 795, in data

2024-09-24T17:46:34.881205033Z ret = super().data

2024-09-24T17:46:34.881246620Z File "/usr/local/lib/python3.10/site-packages/rest_framework/serializers.py", line 249, in data

2024-09-24T17:46:34.881298186Z self._data = self.to_representation(self.instance)

2024-09-24T17:46:34.881345677Z File "/usr/local/lib/python3.10/site-packages/rest_framework/serializers.py", line 713, in to_representation

2024-09-24T17:46:34.881393784Z return [

2024-09-24T17:46:34.881432311Z File "/usr/local/lib/python3.10/site-packages/rest_framework/serializers.py", line 714, in

2024-09-24T17:46:34.881497805Z self.child.to_representation(item) for item in iterable

2024-09-24T17:46:34.881549927Z File "/code/adventures/serializers.py", line 152, in to_representation

2024-09-24T17:46:34.881613586Z representation = super().to_representation(instance)

2024-09-24T17:46:34.881657866Z File "/usr/local/lib/python3.10/site-packages/rest_framework/serializers.py", line 538, in to_representation

2024-09-24T17:46:34.881707404Z ret[field.field_name] = field.to_representation(attribute)

2024-09-24T17:46:34.881768585Z File "/usr/local/lib/python3.10/site-packages/rest_framework/serializers.py", line 713, in to_representation

2024-09-24T17:46:34.881829126Z return [

2024-09-24T17:46:34.881874483Z File "/usr/local/lib/python3.10/site-packages/django/db/models/query.py", line 400, in iter

2024-09-24T17:46:34.881928008Z self._fetch_all()

2024-09-24T17:46:34.881969731Z File "/usr/local/lib/python3.10/site-packages/django/db/models/query.py", line 1928, in _fetch_all

2024-09-24T17:46:34.882018465Z self._result_cache = list(self._iterable_class(self))

2024-09-24T17:46:34.882062421Z File "/usr/local/lib/python3.10/site-packages/django/db/models/query.py", line 91, in iter

2024-09-24T17:46:34.882112046Z results = compiler.execute_sql(

2024-09-24T17:46:34.882154703Z File "/usr/local/lib/python3.10/site-packages/django/db/models/sql/compiler.py", line 1562, in execute_sql

2024-09-24T17:46:34.882204510Z cursor.execute(sql, params)

2024-09-24T17:46:34.882246070Z File "/usr/local/lib/python3.10/site-packages/django/db/backends/utils.py", line 79, in execute

2024-09-24T17:46:34.882294734Z return self._execute_with_wrappers(

2024-09-24T17:46:34.882337066Z File "/usr/local/lib/python3.10/site-packages/django/db/backends/utils.py", line 92, in _execute_with_wrappers

2024-09-24T17:46:34.882454328Z return executor(sql, params, many, context)

2024-09-24T17:46:34.882524977Z File "/usr/local/lib/python3.10/site-packages/django/db/backends/utils.py", line 100, in _execute

2024-09-24T17:46:34.882579424Z with self.db.wrap_database_errors:

2024-09-24T17:46:34.882628121Z File "/usr/local/lib/python3.10/site-packages/django/db/utils.py", line 91, in exit

2024-09-24T17:46:34.882677740Z raise dj_exc_value.with_traceback(traceback) from exc_value

2024-09-24T17:46:34.882725724Z File "/usr/local/lib/python3.10/site-packages/django/db/backends/utils.py", line 105, in _execute

2024-09-24T17:46:34.882778839Z return self.cursor.execute(sql, params)

2024-09-24T17:46:34.882825105Z django.db.utils.ProgrammingError: column adventures_adventure.date does not exist

2024-09-24T17:46:34.882873976Z LINE 1: ...dventure"."link", "adventures_adventure"."image", "adventure...

2024-09-24T17:46:34.882923595Z ^

2024-09-24T17:46:34.882965586Z HINT: Perhaps you meant to reference the column "adventures_adventure.name".

2024-09-24T17:46:34.883012506Z

2024-09-24T17:46:34.883050514Z "GET /api/collections/?order_by=updated_at HTTP/1.1" 500 145

2024-09-24T17:46:34.922467403Z "GET /auth/user/ HTTP/1.1" 200 315

and from db :

2024-09-24 17:46:34.877 UTC [1335] ERROR: column adventures_adventure.date does not exist at character 346

2024-09-24 17:46:34.877 UTC [1335] HINT: Perhaps you meant to reference the column "adventures_adventure.name".

2024-09-24 17:46:34.877 UTC [1335] STATEMENT: SELECT "adventures_adventure"."id", "adventures_adventure"."user_id_id", "adventures_adventure"."type", "adventures_adventure"."name", "adventures_adventure"."location", "adventures_adventure"."activity_types", "adventures_adventure"."description", "adventures_adventure"."rating", "adventures_adventure"."link", "adventures_adventure"."image", "adventures_adventure"."date", "adventures_adventure"."end_date", "adventures_adventure"."is_public", "adventures_adventure"."longitude", "adventures_adventure"."latitude", "adventures_adventure"."collection_id", "adventures_adventure"."created_at", "adventures_adventure"."updated_at" FROM "adventures_adventure" WHERE "adventures_adventure"."collection_id" = 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxx'::uuid

For me, there is a problem with the db and furthermore with the adventure_adventure.date column, but I'm not expert in this and I don't know how I could repair it.

To Reproduce Steps to reproduce the behavior:

  1. Created an account in v0.6.0 with tags latest in docker-compose
  2. Created adventures and collections
  3. Update backend and frontend with latest tags few days ago
  4. Suddenly can't open pages adventures, collection or map, everything else seems to work normally

Expected behavior Should be able to access adventures and collections

Screenshots N/A

Docker Compose N/A (it was working before and did not change the compose

Additional context Add any other context about the problem here.

seanmorley15 commented 1 month ago

Hi @Afaren57, I (unfortunately) know the root cause of the issue. A few days ago as described by you, between the hours of around 1am and 10am EST, the latest docker image contained a development bug that should have been pushed to a development branch. This update contained a partial database migration that is meant for a future release. The new update moves over to a new Visit model with start and end dates, but this migration basically deleted the current start and end_date fields without being ready for a full migration. Long story short, this is my fault and I'm very very sorry for any trouble this causes. I believe that if you fetch the now latest version that contains the fix, one of two things will need to happen:

  1. It works automatically (most likely not the case because the migration has already run)
  2. Manual migration - by using docker exec into the server container, run the command python manage.py migrate. This will bring back the correct columns to the adventure table. There is one issue with all of this that cannot be fixed, the old dates are lost... I am very sorry for all of this because at the end of the day, I am learning how to be a developer through AdventureLog and I assure that the right measures will be put in place to prevent this from ever happening again. I know I fall into this trap too but database backups are key for apps like this that rely of your data storage for the future. Feel free to join the Discord server posted in discussions if you need any help, I understand this stuff can be tricky to figure out.

Very sorry about this and I hope you help you soon.

Afaren57 commented 1 month ago

Don't worry, this also happened because I was so eagered to be able to share and manage the collections with the friends I am planning my next trip with I did all the updates when' available. Thanks Watchtower to send me notifications when it happens, I should have waited the next stable update ^^

I think that to avoid this issue from happening again, a beta branch opposed to the stable one would be nice. It would prevent watchtower to fetch every little patch until the big milestones, unless you switch yourself from latest to beta branch.

Anyway, let's get back to my issue. As you said, 1 did not work so I tried the second option you gave me to manually update. Unfortunately, it didn't worked. Here is the result of the command in the server container :

python manage.py migrate

Operations to perform: Apply all migrations: account, admin, adventures, auth, authtoken, contenttypes, sessions, sites, socialaccount, users, worldtravel

Running migrations: No migrations to apply.

I'll join the discord soon, but I think that if someone encounter the same problem, it may be nice to post the solution here on github in order to make it easier to find :)

Anyway, adventure log has a nice potential and everyone does mistakes so don't blame yourself too hard, I am eager to see it continue to evolve :)

TheBig-O commented 1 month ago

Unfortunately, I had the same issues and the fix didn't work. I pulled the new image and then tried the migrations. The response was:

Operations to perform:
  Apply all migrations: account, admin, adventures, auth, authtoken, contenttypes, sessions, sites, socialaccount, users, worldtravel
Running migrations:
  No migrations to apply.

Is there something else I can try?

The error I see in the logs is:

Internal Server Error: /api/adventures/search/
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/django/db/backends/utils.py", line 105, in _execute
    return self.cursor.execute(sql, params)
psycopg2.errors.UndefinedColumn: column adventures_adventure.date does not exist
LINE 1: ...dventure"."link", "adventures_adventure"."image", "adventure...
                                                             ^
HINT:  Perhaps you meant to reference the column "adventures_adventure.name".
The above exception was the direct cause of the following exception:
seanmorley15 commented 1 month ago

Thanks so much everyone for being understanding,

I have been investigating a fix for this and have found the following solution to work:

  1. Docker exec into the server (backend) container and reach its command line
  2. Run python manage.py dbshell to access the database command line
  3. Run ALTER TABLE adventures_adventure ADD COLUMN IF NOT EXISTS date DATE NULL, ADD COLUMN IF NOT EXISTS end_date DATE NULL; to add back the missing columns.

I hope this helps!

Afaren57 commented 1 month ago

I just tried it, I can access again to my collections and adventures, thanks :D

As you said, dares are lost, but it's less a hassle than having to redo everything :)

TheBig-O commented 1 month ago

Well, we're making progress. Now, I'm getting a new error when I try to edit an adventure to add the dates back in.

Error forwarding request: TypeError: fetch failed
    at node:internal/deps/undici/undici:12618:11
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5) {
  cause: InvalidArgumentError: invalid connection header
      at processHeader (node:internal/deps/undici/undici:7565:17)
      at new Request (node:internal/deps/undici/undici:7356:13)
      at [http1 build request] (node:internal/deps/undici/undici:7486:16)
      at [dispatch] (node:internal/deps/undici/undici:8598:139)
      at Client.Intercept (node:internal/deps/undici/undici:8278:20)
      at Client.dispatch (node:internal/deps/undici/undici:6861:44)
      at [dispatch] (node:internal/deps/undici/undici:7092:32)
      at Pool.dispatch (node:internal/deps/undici/undici:6861:44)
      at [dispatch] (node:internal/deps/undici/undici:10230:27)
      at Agent.Intercept (node:internal/deps/undici/undici:8278:20) {
    code: 'UND_ERR_INVALID_ARG'
  }
}

I've logged out, restarted the stack, and cleared cookies. All result in the error above. Any ideas why I'm seeing this now? Thanks for the help with this. I'll keep at it.

seanmorley15 commented 1 month ago

Hey @TheBig-O, this seems like its a frontend log but its most likely caused by an issue with the backend, can you possibly send a picture of the backend server logs? Thanks!

TheBig-O commented 1 month ago

I pulled this from the server container:

"GET /api/adventures/a6a7c2c0-5841-4815-9d1b-bcfa83ba99d9/ HTTP/1.1" 200 1516
"GET /api/collections/c639666b-8a58-4041-91f9-57d095d072c7/ HTTP/1.1" 200 3549
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/activity-types/types/ HTTP/1.1" 200 157
"GET /auth/user/ HTTP/1.1" 200 307
"GET /auth/user/ HTTP/1.1" 200 307
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/adventures/a6a7c2c0-5841-4815-9d1b-bcfa83ba99d9/ HTTP/1.1" 200 1516
"GET /api/collections/c639666b-8a58-4041-91f9-57d095d072c7/ HTTP/1.1" 200 3549
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/adventures/filtered?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=false&page=1 HTTP/1.1" 301 0
Ordering by: -updated_at
"GET /api/adventures/filtered/?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=false&page=1 HTTP/1.1" 200 52
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/adventures/filtered?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=on&page=1 HTTP/1.1" 301 0
Ordering by: -updated_at
"GET /api/adventures/filtered/?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=on&page=1 HTTP/1.1" 200 19915
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/activity-types/types/ HTTP/1.1" 200 157
"GET /auth/user/ HTTP/1.1" 200 307

If you need others, let me know. Thanks!

seanmorley15 commented 1 month ago

Hmmm, I don't see anything being reported in these logs... Did you try and create/edit an adventure while recording these logs? I would assume your docker compose is fine if you did not change it.

TheBig-O commented 1 month ago

Everything I do in the web app results in an error "Internal Server Error" I just tried creating a new adventure and the result was the same. Even clicking on "search" for a location presents that error. I haven't changed anything in the docker-compose, but I'm going to go back to the example, double check and try again.

seanmorley15 commented 1 month ago

Ok keep me updated!

TheBig-O commented 1 month ago

Okay. I deleted everything and went back to a previous version of the database and my original docker-compose. The error still exists. (I went back to the 8th of September for a replacement database.) Any thoughts on why I'm getting a server error? I kinda out of ideas.

seanmorley15 commented 1 month ago

I have not seen the error you posted before. Is there any chance you can run through the motions of doing whatever causes the error while having the logs of the backend server open so you can send a screenshot of what they say is sending out a 500 internal server error? Thanks,

TheBig-O commented 1 month ago

I just tried going backward in releases to [v0.5.2]. As soon as it started up, everything worked perfectly except for the images. For some reason, I'm not seeing any of the images. I was able to edit any of the adventures and also add a new one. I don't know if this helps, but I figured I would pass it along.

When I put the tag back to "latest", I immediately got the internal server error again. So, I'm lost at what to try next. (But the images showed up.)

seanmorley15 commented 1 month ago

Images would not work when going back in releases because versions after v0.5.2 use a different model for images and v0.5.2 does not recognize that. I am confused as well, without the server logs I don't know the root cause of this issue because I did not experience this during my testing to find the command to fix the issue before Feel free to send any information that could help me help you!

TheBig-O commented 1 month ago

Below is a pull from each of the logs immediately after start up. In fact, it is the startup right after I changed it back to the "latest" tag. This is everything in the logs. Let me know what else I can add. I'm happy to do whatever I can to help out. I appreciate your help in sleuthing through this

# adventurelog_web Log 

The origin to be set is: https://trek.example.com
Listening on 0.0.0.0:3000
[]
Error forwarding request: TypeError: fetch failed
    at node:internal/deps/undici/undici:12618:11
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5) {
  cause: InvalidArgumentError: invalid connection header
      at processHeader (node:internal/deps/undici/undici:7565:17)
      at new Request (node:internal/deps/undici/undici:7356:13)
      at [http1 build request] (node:internal/deps/undici/undici:7486:16)
      at [dispatch] (node:internal/deps/undici/undici:8598:139)
      at Intercept (node:internal/deps/undici/undici:8278:20)
      at [Intercepted Dispatch] (node:internal/deps/undici/undici:6845:16)
      at Client.dispatch (node:internal/deps/undici/undici:6861:44)
      at [dispatch] (node:internal/deps/undici/undici:7092:32)
      at Pool.dispatch (node:internal/deps/undici/undici:6861:44)
      at [dispatch] (node:internal/deps/undici/undici:10230:27) {
    code: 'UND_ERR_INVALID_ARG'
  }
}

---
# adventurelog_server Log
PostgreSQL is up - continuing...
Operations to perform:
  Apply all migrations: account, admin, adventures, auth, authtoken, contenttypes, sessions, sites, socialaccount, users, worldtravel
Running migrations:
  No migrations to apply.
Creating superuser...
Superuser already exists.
Flag for af already exists
Country Afghanistan prepared
...
State ZW-MN prepared
State ZW-MS prepared
State ZW-MI prepared
All data imported successfully
Watching for file changes with StatReloader
Performing system checks...
System check identified no issues (0 silenced).
September 26, 2024 - 02:57:04
Django version 5.0.8, using settings 'main.settings'
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.
all values are hidden
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/adventures/filtered?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=on&page=1 HTTP/1.1" 301 0
Ordering by: -updated_at
"GET /api/adventures/filtered/?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=on&page=1 HTTP/1.1" 200 19931
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/adventures/759a0168-153a-4c7b-9965-c05e5afdc996/ HTTP/1.1" 200 1605
"GET /api/collections/a2f61314-008e-4bf7-a491-c1e6d96b350b/ HTTP/1.1" 200 12142
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/activity-types/types/ HTTP/1.1" 200 157
"GET /auth/user/ HTTP/1.1" 200 307

---
# adventurelog_nginx Log

/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
/docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
10-listen-on-ipv6-by-default.sh: info: can not modify /etc/nginx/conf.d/default.conf (read-only file system?)
/docker-entrypoint.sh: Sourcing /docker-entrypoint.d/15-local-resolvers.envsh
/docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
/docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
/docker-entrypoint.sh: Configuration complete; ready for start up
2024/09/26 02:56:50 [notice] 1#1: using the "epoll" event method
2024/09/26 02:56:50 [notice] 1#1: nginx/1.27.1
2024/09/26 02:56:50 [notice] 1#1: built by gcc 12.2.0 (Debian 12.2.0-14) 
2024/09/26 02:56:50 [notice] 1#1: OS: Linux 6.1.0-0.deb11.21-amd64
2024/09/26 02:56:50 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2024/09/26 02:56:50 [notice] 1#1: start worker processes
2024/09/26 02:56:50 [notice] 1#1: start worker process 21
2024/09/26 02:56:50 [notice] 1#1: start worker process 22
2024/09/26 02:56:50 [notice] 1#1: start worker process 23
2024/09/26 02:56:50 [notice] 1#1: start worker process 24
2024/09/26 02:56:50 [notice] 1#1: start worker process 25
2024/09/26 02:56:50 [notice] 1#1: start worker process 26
2024/09/26 02:56:50 [notice] 1#1: start worker process 27
2024/09/26 02:56:50 [notice] 1#1: start worker process 28

---
# adventurelog_db Log
PostgreSQL Database directory appears to contain a database; Skipping initialization
2024-09-26 01:49:00.242 UTC [1] LOG:  starting PostgreSQL 16.4 (Debian 16.4-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-09-26 01:49:00.242 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-09-26 01:49:00.242 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2024-09-26 01:49:00.244 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-09-26 01:49:00.247 UTC [30] LOG:  database system was interrupted; last known up at 2024-09-08 05:16:37 UTC
2024-09-26 01:49:00.508 UTC [31] FATAL:  the database system is starting up
2024-09-26 01:49:00.579 UTC [30] LOG:  database system was not properly shut down; automatic recovery in progress
2024-09-26 01:49:00.581 UTC [30] LOG:  redo starts at 0/A275BE8
2024-09-26 01:49:00.591 UTC [30] LOG:  invalid record length at 0/A38CD48: expected at least 24, got 0
2024-09-26 01:49:00.591 UTC [30] LOG:  redo done at 0/A38CD10 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2024-09-26 01:49:00.595 UTC [28] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-09-26 01:49:00.622 UTC [28] LOG:  checkpoint complete: wrote 1132 buffers (6.9%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.021 s, sync=0.003 s, total=0.028 s; sync files=25, longest=0.001 s, average=0.001 s; distance=1116 kB, estimate=1116 kB; lsn=0/A38CD48, redo lsn=0/A38CD48
2024-09-26 01:49:00.625 UTC [1] LOG:  database system is ready to accept connections
2024-09-26 01:54:00.720 UTC [28] LOG:  checkpoint starting: time
2024-09-26 01:54:39.231 UTC [28] LOG:  checkpoint complete: wrote 386 buffers (2.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=38.496 s, sync=0.009 s, total=38.511 s; sync files=75, longest=0.004 s, average=0.001 s; distance=5968 kB, estimate=5968 kB; lsn=0/A960F88, redo lsn=0/A960F50
2024-09-26 02:39:01.128 UTC [28] LOG:  checkpoint starting: time
2024-09-26 02:39:02.042 UTC [28] LOG:  checkpoint complete: wrote 10 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.903 s, sync=0.004 s, total=0.915 s; sync files=8, longest=0.003 s, average=0.001 s; distance=12 kB, estimate=5372 kB; lsn=0/A964260, redo lsn=0/A964228
2024-09-26 02:44:01.140 UTC [28] LOG:  checkpoint starting: time
2024-09-26 02:44:01.752 UTC [28] LOG:  checkpoint complete: wrote 7 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.603 s, sync=0.004 s, total=0.613 s; sync files=7, longest=0.003 s, average=0.001 s; distance=13 kB, estimate=4836 kB; lsn=0/A9678C8, redo lsn=0/A967890
2024-09-26 02:59:02.052 UTC [28] LOG:  checkpoint starting: time
2024-09-26 02:59:33.745 UTC [28] LOG:  checkpoint complete: wrote 317 buffers (1.9%); 0 WAL file(s) added, 0 removed, 0 recycled; write=31.684 s, sync=0.005 s, total=31.693 s; sync files=26, longest=0.002 s, average=0.001 s; distance=2615 kB, estimate=4614 kB; lsn=0/ABF5868, redo lsn=0/ABF5830
seanmorley15 commented 1 month ago

Thanks @TheBig-O, with these logs provided , there does not seem to be anything wrong with the backend, although there are no POST requests made during this time which are most likely causing problems, not GET requests. If you indeed guarantee that these logs were provided during the creation/edit of an adventure, I would be more confused because then the frontend forwarding is causing the issue. Now if this is the case, let me know because I have not seen this before! Otherwise, try and use the app by creating/editing some adventures then take logs including some POST requests. Thanks a lot for your continued efforts!

TheBig-O commented 1 month ago

Hi, sorry it took so long to answer. Yes, those are the logs from the start. I'll run process again in a few minutes and send the logs from another round. Hopefully, I'll see some post requests. More to follow.

TheBig-O commented 1 month ago

Okay. I went back through the process and the logs are below. I stopped the stack and restarted it. This cleared the immediate logs so I have a clean run. I started the stack, attempted to create a new adventure and immediately got an internal server error. I did not see any post requests, as you'll see in the logs below.

# Web
The origin to be set is: https://trek.example.com
Listening on 0.0.0.0:3000
[]
Error forwarding request: TypeError: fetch failed
    at node:internal/deps/undici/undici:12618:11
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5) {
  cause: InvalidArgumentError: invalid connection header
      at processHeader (node:internal/deps/undici/undici:7565:17)
      at new Request (node:internal/deps/undici/undici:7356:13)
      at [http1 build request] (node:internal/deps/undici/undici:7486:16)
      at [dispatch] (node:internal/deps/undici/undici:8598:139)
      at Client.Intercept (node:internal/deps/undici/undici:8278:20)
      at Client.dispatch (node:internal/deps/undici/undici:6861:44)
      at [dispatch] (node:internal/deps/undici/undici:7092:32)
      at Pool.dispatch (node:internal/deps/undici/undici:6861:44)
      at [dispatch] (node:internal/deps/undici/undici:10230:27)
      at Agent.Intercept (node:internal/deps/undici/undici:8278:20) {
    code: 'UND_ERR_INVALID_ARG'
  }
}

# Server
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.
all values are hidden
"GET /auth/user/ HTTP/1.1" 200 307
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/adventures/filtered?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=false&page=1 HTTP/1.1" 301 0
Ordering by: -updated_at
"GET /api/adventures/filtered/?types=visited,planned&order_by=updated_at&order_direction=asc&include_collections=false&page=1 HTTP/1.1" 200 52
"GET /auth/user/ HTTP/1.1" 200 307
"GET /api/activity-types/types/ HTTP/1.1" 200 157
"GET /auth/user/ HTTP/1.1" 200 307

# DB
PostgreSQL Database directory appears to contain a database; Skipping initialization
2024-09-27 00:07:48.512 UTC [1] LOG:  starting PostgreSQL 16.4 (Debian 16.4-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-09-27 00:07:48.512 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-09-27 00:07:48.512 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2024-09-27 00:07:48.514 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-09-27 00:07:48.518 UTC [28] LOG:  database system was shut down at 2024-09-27 00:06:40 UTC
2024-09-27 00:07:48.525 UTC [1] LOG:  database system is ready to accept connections

# NGINX
/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
/docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
10-listen-on-ipv6-by-default.sh: info: can not modify /etc/nginx/conf.d/default.conf (read-only file system?)
/docker-entrypoint.sh: Sourcing /docker-entrypoint.d/15-local-resolvers.envsh
/docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
/docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
/docker-entrypoint.sh: Configuration complete; ready for start up
2024/09/27 00:07:49 [notice] 1#1: using the "epoll" event method
2024/09/27 00:07:49 [notice] 1#1: nginx/1.27.1
2024/09/27 00:07:49 [notice] 1#1: built by gcc 12.2.0 (Debian 12.2.0-14) 
2024/09/27 00:07:49 [notice] 1#1: OS: Linux 6.1.0-0.deb11.21-amd64
2024/09/27 00:07:49 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2024/09/27 00:07:49 [notice] 1#1: start worker processes
2024/09/27 00:07:49 [notice] 1#1: start worker process 21
2024/09/27 00:07:49 [notice] 1#1: start worker process 22
2024/09/27 00:07:49 [notice] 1#1: start worker process 23
2024/09/27 00:07:49 [notice] 1#1: start worker process 24
2024/09/27 00:07:49 [notice] 1#1: start worker process 25
2024/09/27 00:07:49 [notice] 1#1: start worker process 26
2024/09/27 00:07:49 [notice] 1#1: start worker process 27
2024/09/27 00:07:49 [notice] 1#1: start worker process 28
TheBig-O commented 1 month ago

Okay. I deleted everything and started from scratch with the stack. I only kept my docker-compose file. (I backed up the database.) After doing all this the result is identical.

image

I'm really not sure what's going on. The version before the database change worked great and I could add or edit any of the adventures. Now, I can see them, but not adjust them in the web interface. (I can make changes through the Django admin panel and they show in the web interface afterward.) Any thoughts?

TheBig-O commented 1 month ago

I continue to fight with this, but have not found any workable solutions. I installed this on another computer and had the same results. Any ideas?

seanmorley15 commented 1 month ago

@TheBig-O, I just released a big update that completely overhauls how dates and visits work. This means that if the dates are still the issue, starting up the new version will trigger a migration and resync the database how it should be. Try docker compose pull && docker compose up -d and let me know if this fixes it. I hope this helps!

TheBig-O commented 1 month ago

I can now add and edit adventures. My original response was going to be: "Unfortunately, I still cannot add or edit any adventures. I tried several things. I even stopped the stack, deleted all images and started over. I tried different browsers and different computers. All had the same results." Then, I had a thought about what might be affecting the headers. It turns out it was something I hadn't thought about before and I should have. I have Authelia performing all my security and it was active on the web container. When I deactivated it, I was immediately able to save changes and add new items. (I use Authelia to add 2fa.) So, now, I am going to go back and see what I can figure out about Authelia's headers that causes the errors. It is clearly inserting something that is confusing the Adventurelog server. I don't know that there is a way to overcome that since Authelia likely can't operate without putting things in the header.
At least I'm back up and running and if anyone else has these issues, you can tell them why.

In looking at the headers that are sent when I have Authelia enabled, I see the following: HTTP Status Code: 302 (Found/Redirect) Location Header: There is a Location header that redirects to https://auth.example.com/?rd=https://trek.example.com/. This indicates that a request to trek.example.com is being intercepted and redirected to auth.example.com for authentication via Authelia.

I'm not sure if that information helps you. While I'm not hard over on using Authelia, it would be good to find a way to overcome the issue. (Or at least a workaround.)

seanmorley15 commented 1 month ago

@TheBig-O, wow that's interesting! I would not have thought of that! I'm glad you got it working now, this info will be useful if someone else has this issue. I can try and look into the root cause when I have some time. Thanks for bearing with me, enjoy using AdventureLog 😊

TheBig-O commented 1 month ago

@seanmorley15, I feel bad that it took me this long to think about what Authelia was doing to the headers. I'll keep thinking about options that might work. I'm glad I'm back to adding new adventures! I really like what you've put together!