Overdue tasks listed twice in reminder e-mail

woosting · 24 September 2022 22:02

When configuring the overdue tasks reminder e-mail I do get the e-mail, but the tasks are all listed twice in it (using the self-hosted container version)?

I’m unsure whether it reproduces on Try as I do not receive any e-mail from there / timezone is off.

Anyone else experiencing double tasks in the reminder e-mail and/or anything I can do to troubleshoot (more than willing to put in the effort)?

OFF-TOPIC: Thanks @kolaente for this very nice FOSS solution to task management! It looks very promising (and is the best feature-complete stand-alone system of its kind that I know of)!

kolaente · 26 September 2022 12:28

I didn’t experience this yet. What due dates have these tasks set? When do you get the reminder emails? Does this happen every day? Can you check if there’s anything in the logs with the log level set to debug?

Thanks!

woosting · 26 September 2022 17:51

I’ve removed them but the “test” one has the following due date:

24 Sep 2022, 21:00:00

woosting · 26 September 2022 17:52

I get the reminder e-mails at the exact time that I configure them to be sent out (personal account setting).

So that seems to work nicely (with the problem of the report-contents to double all overdue tasks in 100% of the times in my case).

To be clear I get the right (single) e-mail but the message itself has all overdue tasks double in it (report generating part seems off). Frontend Version: 0.19.1 / API Version: v0.19.2

woosting · 26 September 2022 17:55

Will try to do that. I will need to figure out how to do it in the docker version (probably setting the right environment variable), but I’ll let you know!

You are referring to the api service logging, right @kolaente?

I will also ask another person to test on my Vikunja server (see whether it may be account-bound for some odd reason; but that’s just me “shooting in the dark”).

woosting · 26 September 2022 18:18

Log output:

api_1       | 2022-09-26T18:11:00.000482614Z: DEBUG     ▶ models/getTasksWithRemindersDueAndTheirUsers 14a [Task Reminder Cron] Looking for reminders between 2022-09-26 18:11:00 +0000 GMT and 2022-09-26 18:12:00 +0000 GMT to send...
api_1       | 2022-09-26T18:11:00.003130898Z: DEBUG     ▶ models/getTasksWithRemindersDueAndTheirUsers 15f [Task Reminder Cron] Found 0 reminders
api_1       | 2022-09-26T18:11:00.006712105Z: DEBUG     ▶ models/func1 181 [Undone Overdue Tasks Reminder] Sending reminders to 1 users
api_1       | 2022-09-26T18:11:00.007691355Z: DEBUG     ▶ models/func1 182 [Undone Overdue Tasks Reminder] Sent reminder email for 6 tasks to user 2

Note the logs makes notion of 6 tasks while in fact there are only 3 tasks currently overdue.

I think something is wrong with the report-generating in itself (not the e-mail functionality) although I do get the following ERROR as well:

api_1       | 2022-09-26T18:11:30.063787743Z: ERROR     ▶ mail/func1 18f Error closing the mail server connection: %s

woosting · 26 September 2022 18:20

Probably unrelated, but possibly an issue nevertheless I also get the following (while starting the server):

api_1       | 2022-09-26T18:08:26.110600403Z: CRITICAL  ▶ migration/Migrate 002 Migration failed: dial tcp 192.168.208.2:3306: connect: connection refused

kolaente · 27 September 2022 14:59

I’m not sure where this is coming from. My own instance works fine. There is a way which may solve this but I’d like to understand where it’s coming from.

yup, that’s unrelated. This may happen when the db container takes longer to start than the api container. Docker-Compose should just restart the api container in that case.

woosting · 27 September 2022 16:37

My bad I read this (clearly mentioned) in the documentation… Sorry for clouding the topic at hand.

woosting · 27 September 2022 16:44

That seems to be the right attitude indeed; digging for the root cause enabling a solid fix instead of applying a quick 'n dirty workaround (further increasing trust in (the future of) Vikunja as a tool and you as its developer/founder)!

I am still in anticipation for the feedback of my “tester” (see if this also occurs with her account on my server instance). I’ll post the results here in this thread once I get it (or when I’ve tested myself with another account). Other than that I could ditch the containers and rebuild (but that would: A) not get us closer to the root-cause, and B) is probably pointless).

Let me know if there is anything else I could do on my side (as it seems to be tied to my context, for now)… I’m open to setup a shared troubleshooting session through Signal, or any channel you prefer, for live testing if you are up for that.

kolaente · 27 September 2022 17:32

Right now I’m not sure. What’s bothering me is that all these due dates are at different hours. If they were the same that could explain it under certain conditions but like that it does not make sense.

What version are you running btw?

woosting · 27 September 2022 18:16

Frontend Version: 0.19.1
API Version: v0.19.2

According to the about box in the web UI (account settings / hamburger menu).

woosting · 28 September 2022 00:01

It seems even more specific (and weird); it seems account-bound!

Other people on my running instance do not get the double entries in their overdue reminder e-mail… We even tested with having someone else and me assigned to the same task (came out single in the other person’s, but double in mine… )

What are the account-bound setting that could influence the report generating function, I wonder.

kolaente · 28 September 2022 18:10

Can you set the database logging to debug so that we can see the queries? That might get us more insight.

woosting · 28 September 2022 20:42

Good call (should’ve thought of that myself…).

However, although I tried setting the following env. variables:

version: '3.7'
  
services:
  db:
    image: mariadb:10
    command: --character-set-server=utf8mb4 --collation-server=utf8mb4_unicode_ci
    environment:
      MYSQL_ROOT_PASSWORD: #####
      MYSQL_USER: vikunja
      MYSQL_PASSWORD: #####
      MYSQL_DATABASE: vikunja
      VIKUNJA_LOG_DATABASE: stdout
      VIKUNJA_LOG_DATABASELEVEL: DEBUG
    volumes:
      - ./db:/var/lib/mysql
    restart: unless-stopped

my (docker processed) logs did not seem to show any additional logging; outputting little to no further output after the following:

...
db_1        | 2022-09-28 20:17:40 0 [Note] InnoDB: log sequence number 2332050; transaction id 6700
db_1        | 2022-09-28 20:17:40 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
db_1        | 2022-09-28 20:17:40 0 [Note] Plugin 'FEEDBACK' is disabled.
db_1        | 2022-09-28 20:17:40 0 [Note] InnoDB: Buffer pool(s) load completed at 220928 20:17:40
db_1        | 2022-09-28 20:17:40 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
db_1        | 2022-09-28 20:17:40 0 [Note] Server socket created on IP: '0.0.0.0'.
db_1        | 2022-09-28 20:17:40 0 [Note] Server socket created on IP: '::'.
db_1        | 2022-09-28 20:17:40 0 [Note] mariadbd: ready for connections.
db_1        | Version: '10.9.3-MariaDB-1:10.9.3+maria~ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Am I missing something here?

kolaente · 29 September 2022 09:48

You’ll need to set the env variables at the api container, not the mariadb one. The logs will show up in the api log stream as well.

woosting · 29 September 2022 10:57

DOH! Of course… the db service is technically not even Vikunja but the generic Mariadb image… so no use in feeding it Vikunja specific env. variables… check…

OUTPUT (triggered at the time the overdue-notification e-mail is checked/sent out):

api_1       | 2022-09-29T10:54:00.006750748Z: DEBUG     ▶ models/getTasksWithRemindersDueAndTheirUsers 4d8 [Task Reminder Cron] Looking for reminders between 2022-09-29 10:54:00 +0000 GMT and 2022-09-29 10:55:00 +0000 GMT to send...
api_1       | 2022-09-29T10:54:00.007998873Z: INFO      ▶ [DATABASE] 4d9 [SQL] SELECT `id`, `title`, `description`, `done`, `done_at`, `due_date`, `list_id`, `repeat_after`, `repeat_mode`, `priority`, `start_date`, `end_date`, `hex_color`, `percent_done`, `index`, `uid`, `created`, `updated`, `bucket_id`, `position`, `kanban_position`, `created_by_id` FROM `tasks` WHERE (due_date is not null and due_date < ?) AND (done = false) [2022-09-30 00:55:00] - 1.261723ms
api_1       | 2022-09-29T10:54:00.008069922Z: DEBUG     ▶ [DATABASE] 4da empty zone key[due_date] : 2022-08-29 19:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008095617Z: DEBUG     ▶ [DATABASE] 4db empty zone key[created] : 2022-08-27 19:12:34 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008103794Z: DEBUG     ▶ [DATABASE] 4dc empty zone key[updated] : 2022-08-27 19:21:40 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008120671Z: DEBUG     ▶ [DATABASE] 4dd empty zone key[done_at] : 2022-09-24 19:31:02 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008132478Z: DEBUG     ▶ [DATABASE] 4de empty zone key[due_date] : 2022-09-25 06:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008143982Z: DEBUG     ▶ [DATABASE] 4df empty zone key[start_date] : 2022-09-25 05:15:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008150556Z: DEBUG     ▶ [DATABASE] 4e0 empty zone key[end_date] : 2022-09-25 05:30:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008159189Z: DEBUG     ▶ [DATABASE] 4e1 empty zone key[created] : 2022-09-02 23:59:41 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008164573Z: DEBUG     ▶ [DATABASE] 4e2 empty zone key[updated] : 2022-09-24 19:31:02 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008179451Z: DEBUG     ▶ [DATABASE] 4e3 empty zone key[done_at] : 2022-09-24 19:31:08 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008186136Z: DEBUG     ▶ [DATABASE] 4e4 empty zone key[due_date] : 2022-09-25 06:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008194335Z: DEBUG     ▶ [DATABASE] 4e5 empty zone key[start_date] : 2022-09-25 05:30:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008199585Z: DEBUG     ▶ [DATABASE] 4e6 empty zone key[end_date] : 2022-09-25 06:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008208145Z: DEBUG     ▶ [DATABASE] 4e7 empty zone key[created] : 2022-09-04 21:01:28 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008218404Z: DEBUG     ▶ [DATABASE] 4e8 empty zone key[updated] : 2022-09-25 20:03:41 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008234121Z: DEBUG     ▶ [DATABASE] 4e9 empty zone key[due_date] : 2022-09-24 19:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008257798Z: DEBUG     ▶ [DATABASE] 4ea empty zone key[created] : 2022-09-24 19:47:41 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008280242Z: DEBUG     ▶ [DATABASE] 4eb empty zone key[updated] : 2022-09-24 21:41:48 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.008411745Z: INFO      ▶ [DATABASE] 4ec [SQL] SELECT * FROM `task_reminders` INNER JOIN `tasks` ON tasks.id = task_reminders.task_id WHERE (reminder >= ? and reminder < ?) AND (tasks.done = false) [2022-09-28 22:54:00 2022-09-30 00:55:00] - 1.58949ms
api_1       | 2022-09-29T10:54:00.008446693Z: DEBUG     ▶ models/getTasksWithRemindersDueAndTheirUsers 4ed [Task Reminder Cron] Found 0 reminders
api_1       | 2022-09-29T10:54:00.009367867Z: INFO      ▶ [DATABASE] 4ee [SQL] SELECT users.* FROM `users` LEFT JOIN `tasks` ON tasks.created_by_id = users.id WHERE `tasks`.`id` IN (?,?,?,?) AND users.overdue_tasks_reminders_enabled=? GROUP BY tasks.id, users.id, users.username, users.email, users.name, users.timezone [1 22 30 39 true] - 1.004245ms
api_1       | 2022-09-29T10:54:00.009438184Z: DEBUG     ▶ [DATABASE] 4ef empty zone key[created] : 2022-08-27 19:10:49 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009480241Z: DEBUG     ▶ [DATABASE] 4f0 empty zone key[updated] : 2022-09-28 16:39:01 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009509724Z: DEBUG     ▶ [DATABASE] 4f1 empty zone key[created] : 2022-08-27 20:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009518277Z: DEBUG     ▶ [DATABASE] 4f2 empty zone key[updated] : 2022-09-29 10:53:47 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009545346Z: DEBUG     ▶ [DATABASE] 4f3 empty zone key[created] : 2022-08-27 20:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009556332Z: DEBUG     ▶ [DATABASE] 4f4 empty zone key[updated] : 2022-09-29 10:53:47 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009582462Z: DEBUG     ▶ [DATABASE] 4f5 empty zone key[created] : 2022-08-27 20:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009590608Z: DEBUG     ▶ [DATABASE] 4f6 empty zone key[updated] : 2022-09-29 10:53:47 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.009963467Z: INFO      ▶ [DATABASE] 4f7 [SQL] SELECT `id`, `title`, `description`, `done`, `done_at`, `due_date`, `list_id`, `repeat_after`, `repeat_mode`, `priority`, `start_date`, `end_date`, `hex_color`, `percent_done`, `index`, `uid`, `created`, `updated`, `bucket_id`, `position`, `kanban_position`, `created_by_id` FROM `tasks` WHERE `id` IN (?,?,?,?) [1 22 30 39] - 320.872µs
api_1       | 2022-09-29T10:54:00.010015865Z: DEBUG     ▶ [DATABASE] 4f8 empty zone key[due_date] : 2022-08-29 19:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010045235Z: DEBUG     ▶ [DATABASE] 4f9 empty zone key[created] : 2022-08-27 19:12:34 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010080381Z: DEBUG     ▶ [DATABASE] 4fa empty zone key[updated] : 2022-08-27 19:21:40 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010122499Z: DEBUG     ▶ [DATABASE] 4fb empty zone key[done_at] : 2022-09-24 19:31:02 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010134818Z: DEBUG     ▶ [DATABASE] 4fc empty zone key[due_date] : 2022-09-25 06:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010144105Z: DEBUG     ▶ [DATABASE] 4fd empty zone key[start_date] : 2022-09-25 05:15:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010152157Z: DEBUG     ▶ [DATABASE] 4fe empty zone key[end_date] : 2022-09-25 05:30:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010165986Z: DEBUG     ▶ [DATABASE] 4ff empty zone key[created] : 2022-09-02 23:59:41 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010173703Z: DEBUG     ▶ [DATABASE] 500 empty zone key[updated] : 2022-09-24 19:31:02 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010202796Z: DEBUG     ▶ [DATABASE] 501 empty zone key[done_at] : 2022-09-24 19:31:08 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010222406Z: DEBUG     ▶ [DATABASE] 502 empty zone key[due_date] : 2022-09-25 06:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010249846Z: DEBUG     ▶ [DATABASE] 503 empty zone key[start_date] : 2022-09-25 05:30:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010257204Z: DEBUG     ▶ [DATABASE] 504 empty zone key[end_date] : 2022-09-25 06:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010267213Z: DEBUG     ▶ [DATABASE] 505 empty zone key[created] : 2022-09-04 21:01:28 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010273041Z: DEBUG     ▶ [DATABASE] 506 empty zone key[updated] : 2022-09-25 20:03:41 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010293777Z: DEBUG     ▶ [DATABASE] 507 empty zone key[due_date] : 2022-09-24 19:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010320025Z: DEBUG     ▶ [DATABASE] 508 empty zone key[created] : 2022-09-24 19:47:41 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010335842Z: DEBUG     ▶ [DATABASE] 509 empty zone key[updated] : 2022-09-24 21:41:48 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.010848083Z: INFO      ▶ [DATABASE] 50a [SQL] SELECT task_id, users.* FROM `task_assignees` INNER JOIN `users` ON task_assignees.user_id = users.id WHERE `task_id` IN (?,?,?,?) AND users.overdue_tasks_reminders_enabled=? [1 22 30 39 true] - 461.614µs
api_1       | 2022-09-29T10:54:00.010941965Z: DEBUG     ▶ [DATABASE] 50b empty zone key[created] : 2022-08-27 20:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011016748Z: DEBUG     ▶ [DATABASE] 50c empty zone key[updated] : 2022-09-29 10:53:47 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011069502Z: DEBUG     ▶ [DATABASE] 50d empty zone key[created] : 2022-08-27 20:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011093932Z: DEBUG     ▶ [DATABASE] 50e empty zone key[updated] : 2022-09-29 10:53:47 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011135488Z: DEBUG     ▶ [DATABASE] 50f empty zone key[created] : 2022-08-27 20:00:00 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011148403Z: DEBUG     ▶ [DATABASE] 510 empty zone key[updated] : 2022-09-29 10:53:47 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011187171Z: DEBUG     ▶ [DATABASE] 511 empty zone key[created] : 2022-08-27 19:10:49 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011202775Z: DEBUG     ▶ [DATABASE] 512 empty zone key[updated] : 2022-09-28 16:39:01 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.011277267Z: DEBUG     ▶ models/func1 513 [Undone Overdue Tasks Reminder] Sending reminders to 1 users
api_1       | 2022-09-29T10:54:00.011702016Z: DEBUG     ▶ models/func1 514 [Undone Overdue Tasks Reminder] Sent reminder email for 6 tasks to user 2
api_1       | 2022-09-29T10:54:00.285946658Z: INFO      ▶ [DATABASE] 515 [SQL] SELECT `id`, `notifiable_id`, `notification`, `name`, `subject_id`, `read_at`, `created` FROM `notifications` WHERE (notifiable_id = ?) ORDER BY id DESC LIMIT 50 [2] - 496.805µs
api_1       | 2022-09-29T10:54:00.286035246Z: DEBUG     ▶ [DATABASE] 516 empty zone key[read_at] : 2022-08-30 20:53:26 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.286056654Z: DEBUG     ▶ [DATABASE] 517 empty zone key[created] : 2022-08-30 18:59:12 +0000 UTC | zone: UTC | location: {name:UTC zone:[] tx:[] extend: cacheStart:0 cacheEnd:0 cacheZone:<nil>}
api_1       |
api_1       | 2022-09-29T10:54:00.286852636Z: INFO      ▶ [DATABASE] 518 [SQL] SELECT count(*) FROM `notifications` WHERE (notifiable_id = ?) [2] - 729.859µs
api_1       | 2022-09-29T10:54:00.287340051Z: WEB       ▶ 31.201.240.248  GET 200 /api/v1/notifications?page=1 2.026851ms - Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:105.0) Gecko/20100101 Firefox/105.0

kolaente · 29 September 2022 11:15

Are you using database caching? Does it work if you disable it?

woosting · 29 September 2022 11:48

I did not set it explicitly (at least not knowingly, and I do not see any cache related entries in my docker-compose.yml). Nevertheless I’ve added the following, sadly to no avail (still 6 in the e-mail instead of the three actual tasks):

VIKUNJA_CACHE_ENABLED: 'false'

I expected that much as VIKUNJA_CACHE_ENABLED should already be false by default according to the documentation. But now I’ve tested also having it set explicitly to false (sadly not fixing the issue).

But I do agree this “feels” like a caching thing. Might there be another DB cache specific variable to explicitly disable?

kolaente · 29 September 2022 15:52

Caching should be disabled if you didn’t enable it yourself.

If you run this query in the db, how many tasks do you get back?

SELECT * FROM `tasks` WHERE (due_date is not null and due_date < '2022-09-30 00:55:00') AND (done = false)

There should be more log output from the query you sent until a message like "[Undone Overdue Tasks Reminder] Sent reminder email for %d tasks to user %d - can you send the full output? The query from above gets all tasks which are currently overdue and then another one should come after that to figure out for which users the task is overdue.