Hello,
I noticed twice that email notifications does not work after a bit of uptime and they come back if I relaunch the api.
Can you suggest the best way to make a bugreport for this? How to set the config and in case how to launch the api.
Thanks
Apart that, dunno atm if it is worth to open a separate ticket I noticed that:
in the log appears:
2022-09-27T09:33:38.952708819Z: ERROR ▶ mail/func1 1d2f Error closing the mail server connection: %s
not connected to SMTP server
While the email in the fact has been sent.
But the strange thing is:
My user has id 1. My collegue has id 3 and another user (added by me for test) added with the cli has id 6
I create a ticket and I have assigned it to the test user with id 6. The email related to user 6 don’t get notifications while user 3 gets the email that says that I have assigned the ticket to the user 6 …I’m a bit confused…
Another test I did:
I’m using mysql, so notifications table has 17 rows, so I have created a new task and assigned to the test user that have id 6, this is what I have in the notifications table after that:
select * from notifications where id > ‘17’;
| 18 | 3 | {“doer”:{“id”:1,“name”:“”,“username”:“ME”,“email”:“MY_EMAIL”,“created”:“0001-01-01T00:00:00Z”,“updated”:“0001-01-01T00:00:00Z”},“task”:{“id”:42,“title”:“t”,“description”:“”,“done”:false,“done_at”:“0001-01-01T00:00:00Z”,“due_date”:“0001-01-01T00:00:00Z”,“reminder_dates”:null,“list_id”:1,“repeat_after”:0,“repeat_mode”:0,“priority”:0,“start_date”:“0001-01-01T00:00:00Z”,“end_date”:“0001-01-01T00:00:00Z”,“assignees”:null,“labels”:null,“hex_color”:“”,“percent_done”:0,“identifier”:“”,“index”:17,“related_tasks”:null,“attachments”:null,“is_favorite”:false,“created”:“2022-09-27T09:48:04Z”,“updated”:“2022-09-27T09:48:04Z”,“bucket_id”:7,“position”:2752512,“kanban_position”:2752512,“created_by”:null},“assignee”:{“id”:6,“name”:“”,“username”:“test”,“created”:“2022-09-27T09:15:02Z”,“updated”:“2022-09-27T09:15:23Z”}} | task.assigned | 0 | NULL | 2022-09-27 09:48:15 |
So notifiable_id is 3 while in the json the assignee id is 6
What I’m missing?
Can you enable debug logging and check if there’s anything about notifications in there?
If you’re able to reliably reproduce it I’d love a bugreport over in the repo.
There’s been an issue and a fix about this: Error closing the mail server connection · Issue #48 · go-vikunja/api · GitHub
Does the other user have email notifications enabled? Are they subscribed to the list/namespace/task?
The json is the content of the notification, the notifiable_id is the user receiving the notification. The notification is about how you assigned user 6 to the task so that’s in the json.
Sure, I have already enabled it.
Would you mind to make a new minor release so I can test it?
Everyone has notifications enabled. User 3 is not subscribed to list/namespace/task
Right, so why user 3 is in there?
Does the unstable build work for you?
Then that explains why they don’t get notifications.
Because you assigned the task to them.
let’s make less confusion 
MariaDB [vikunja]> select id,username from users;
±—±---------+
| id | username |
±—±---------+
| 1 | ago |
| 3 | Gigi |
| 5 | kravasi |
| 4 | Lamu |
| 2 | lenz |
| 6 | test |
±—±---------+
So I assigned the ticket to user 6/test and the notification was sent to 3/Gigi
The question remains: why the notification has been sento to 3/Gigi (that is completely unknown to the transaction) instead of 6/test that is the assignee ?
With the unstable version, the emails about the task assignments works again, so let’s see what happens…I didn’t understand why notifications went to the wrong user…
Is user 3 subscribed to the list?
no, it isn’t subscribed to any list.
Hi, I have another case where I didn’t get notifications:
grep -R "task 101"
standard.log:2022-10-13T09:06:55.247189329+02:00: DEBUG ▶ models/Handle 724c Sending task assigned notifications to 0 subscribers for task 101
while in the UI it has assigned to me:
What else I can provide to debug the issue?
NOTE: This i what I have for now:
grep "/101" http.log
2022-10-13T09:06:16.431072017+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 26.279µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:16.431116531+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101/comments?page=1 40.776µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:16.707982341+02:00: WEB ▶ $IP GET 200 /api/v1/tasks/101/comments?page=1 5.5427ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:16.710810731+02:00: WEB ▶ $IP GET 200 /api/v1/tasks/101 8.715834ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:23.189237366+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 38.541µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:23.219221758+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 10.498331ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:24.956039196+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 8.743073ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:29.303795352+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 30.557µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:29.331971709+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 9.562534ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:30.019190253+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 8.194669ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:34.733162331+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 39.343µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:34.761995414+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 9.408367ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:40.699308138+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 33.603µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:40.963698216+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 39.543µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:40.972666959+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 9.545159ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:40.993383134+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 7.797057ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:51.651770957+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101 37.65µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:51.93403377+02:00: WEB ▶ $IP POST 200 /api/v1/tasks/101 7.71899ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:55.218668329+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/101/assignees 33.843µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:55.246634341+02:00: WEB ▶ $IP PUT 201 /api/v1/tasks/101/assignees 9.461194ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:56.856865051+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/subscriptions/task/101 48.601µs - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
2022-10-13T09:06:56.880766474+02:00: WEB ▶ $IP PUT 201 /api/v1/subscriptions/task/101 4.809178ms - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:105.0) Gecko/20100101 Firefox/105.0
grep 'T09:06' events.log
2022-10-13T09:06:15.025668387+02:00: DEBUG ▶ [EVENTS] 709d Sending msg to subscriber, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa, topic=task.created
2022-10-13T09:06:15.025721907+02:00: DEBUG ▶ [EVENTS] 709e Sent message to subscriber, topic=task.created, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa
2022-10-13T09:06:15.025753996+02:00: DEBUG ▶ [EVENTS] 709f Received message, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa
2022-10-13T09:06:15.025773393+02:00: DEBUG ▶ [EVENTS] 70a0 Message acked, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa
2022-10-13T09:06:15.025783402+02:00: DEBUG ▶ [EVENTS] 70a1 Message acked, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa, topic=task.created
2022-10-13T09:06:15.025793781+02:00: DEBUG ▶ [EVENTS] 70a2 Sending msg to subscriber, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa, topic=task.created
2022-10-13T09:06:15.025803799+02:00: DEBUG ▶ [EVENTS] 70a3 Sent message to subscriber, topic=task.created, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa
2022-10-13T09:06:15.025824828+02:00: DEBUG ▶ [EVENTS] 70a4 Received message, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa
2022-10-13T09:06:15.025942067+02:00: DEBUG ▶ [EVENTS] 70a5 Message acked, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa
2022-10-13T09:06:15.025955623+02:00: DEBUG ▶ [EVENTS] 70a6 Message acked, message_uuid=a1de219c-44f3-4b20-a901-22b03fb933fa, topic=task.created
2022-10-13T09:06:23.218946845+02:00: DEBUG ▶ [EVENTS] 70fb Sending msg to subscriber, message_uuid=ee0dc505-d247-4e0b-b96e-d07e3e19949b, topic=task.updated
2022-10-13T09:06:23.218975458+02:00: DEBUG ▶ [EVENTS] 70fc Sent message to subscriber, message_uuid=ee0dc505-d247-4e0b-b96e-d07e3e19949b, topic=task.updated
2022-10-13T09:06:23.219006877+02:00: DEBUG ▶ [EVENTS] 70fd Received message, message_uuid=ee0dc505-d247-4e0b-b96e-d07e3e19949b
2022-10-13T09:06:23.219124728+02:00: DEBUG ▶ [EVENTS] 70fe Message acked, message_uuid=ee0dc505-d247-4e0b-b96e-d07e3e19949b
2022-10-13T09:06:23.219143904+02:00: DEBUG ▶ [EVENTS] 70ff Message acked, message_uuid=ee0dc505-d247-4e0b-b96e-d07e3e19949b, topic=task.updated
2022-10-13T09:06:24.955584477+02:00: DEBUG ▶ [EVENTS] 711c Sending msg to subscriber, message_uuid=64deac97-4dab-457f-922e-002e7761fd43, topic=task.updated
2022-10-13T09:06:24.955635313+02:00: DEBUG ▶ [EVENTS] 711d Sent message to subscriber, message_uuid=64deac97-4dab-457f-922e-002e7761fd43, topic=task.updated
2022-10-13T09:06:24.95566094+02:00: DEBUG ▶ [EVENTS] 711e Received message, message_uuid=64deac97-4dab-457f-922e-002e7761fd43
2022-10-13T09:06:24.955754976+02:00: DEBUG ▶ [EVENTS] 711f Message acked, message_uuid=64deac97-4dab-457f-922e-002e7761fd43
2022-10-13T09:06:24.955763542+02:00: DEBUG ▶ [EVENTS] 7120 Message acked, message_uuid=64deac97-4dab-457f-922e-002e7761fd43, topic=task.updated
2022-10-13T09:06:29.331509046+02:00: DEBUG ▶ [EVENTS] 7147 Sending msg to subscriber, message_uuid=a19cdb3d-540d-4ae2-a9ce-86572a23e6a8, topic=task.updated
2022-10-13T09:06:29.331538971+02:00: DEBUG ▶ [EVENTS] 7148 Sent message to subscriber, message_uuid=a19cdb3d-540d-4ae2-a9ce-86572a23e6a8, topic=task.updated
2022-10-13T09:06:29.33157065+02:00: DEBUG ▶ [EVENTS] 7149 Received message, message_uuid=a19cdb3d-540d-4ae2-a9ce-86572a23e6a8
2022-10-13T09:06:29.331722985+02:00: DEBUG ▶ [EVENTS] 714a Message acked, message_uuid=a19cdb3d-540d-4ae2-a9ce-86572a23e6a8
2022-10-13T09:06:29.331735819+02:00: DEBUG ▶ [EVENTS] 714b Message acked, message_uuid=a19cdb3d-540d-4ae2-a9ce-86572a23e6a8, topic=task.updated
2022-10-13T09:06:30.018800446+02:00: DEBUG ▶ [EVENTS] 7168 Sending msg to subscriber, message_uuid=5dc1ef4f-5df1-487d-a43f-89bc651b28b3, topic=task.updated
2022-10-13T09:06:30.018836412+02:00: DEBUG ▶ [EVENTS] 7169 Sent message to subscriber, message_uuid=5dc1ef4f-5df1-487d-a43f-89bc651b28b3, topic=task.updated
2022-10-13T09:06:30.018878972+02:00: DEBUG ▶ [EVENTS] 716a Received message, message_uuid=5dc1ef4f-5df1-487d-a43f-89bc651b28b3
2022-10-13T09:06:30.01904397+02:00: DEBUG ▶ [EVENTS] 716b Message acked, message_uuid=5dc1ef4f-5df1-487d-a43f-89bc651b28b3
2022-10-13T09:06:30.019064288+02:00: DEBUG ▶ [EVENTS] 716c Message acked, message_uuid=5dc1ef4f-5df1-487d-a43f-89bc651b28b3, topic=task.updated
2022-10-13T09:06:34.761559248+02:00: DEBUG ▶ [EVENTS] 718f Sending msg to subscriber, message_uuid=39ce61d5-4f85-4dc7-ba63-56e427941140, topic=task.updated
2022-10-13T09:06:34.761598452+02:00: DEBUG ▶ [EVENTS] 7190 Sent message to subscriber, message_uuid=39ce61d5-4f85-4dc7-ba63-56e427941140, topic=task.updated
2022-10-13T09:06:34.761638797+02:00: DEBUG ▶ [EVENTS] 7191 Received message, message_uuid=39ce61d5-4f85-4dc7-ba63-56e427941140
2022-10-13T09:06:34.761802262+02:00: DEBUG ▶ [EVENTS] 7192 Message acked, message_uuid=39ce61d5-4f85-4dc7-ba63-56e427941140
2022-10-13T09:06:34.761822881+02:00: DEBUG ▶ [EVENTS] 7193 Message acked, topic=task.updated, message_uuid=39ce61d5-4f85-4dc7-ba63-56e427941140
2022-10-13T09:06:40.972165724+02:00: DEBUG ▶ [EVENTS] 71c0 Sending msg to subscriber, message_uuid=b0de6272-8d3a-4f72-bf10-f23d6523191e, topic=task.updated
2022-10-13T09:06:40.972214214+02:00: DEBUG ▶ [EVENTS] 71c1 Sent message to subscriber, message_uuid=b0de6272-8d3a-4f72-bf10-f23d6523191e, topic=task.updated
2022-10-13T09:06:40.972255801+02:00: DEBUG ▶ [EVENTS] 71c2 Received message, message_uuid=b0de6272-8d3a-4f72-bf10-f23d6523191e
2022-10-13T09:06:40.972386015+02:00: DEBUG ▶ [EVENTS] 71c3 Message acked, message_uuid=b0de6272-8d3a-4f72-bf10-f23d6523191e
2022-10-13T09:06:40.972398378+02:00: DEBUG ▶ [EVENTS] 71c4 Message acked, message_uuid=b0de6272-8d3a-4f72-bf10-f23d6523191e, topic=task.updated
2022-10-13T09:06:40.992860488+02:00: DEBUG ▶ [EVENTS] 71e1 Sending msg to subscriber, message_uuid=0ed676ea-5d87-415b-9e10-28fcc413d448, topic=task.updated
2022-10-13T09:06:40.992897958+02:00: DEBUG ▶ [EVENTS] 71e2 Sent message to subscriber, message_uuid=0ed676ea-5d87-415b-9e10-28fcc413d448, topic=task.updated
2022-10-13T09:06:40.992927603+02:00: DEBUG ▶ [EVENTS] 71e3 Received message, message_uuid=0ed676ea-5d87-415b-9e10-28fcc413d448
2022-10-13T09:06:40.993040854+02:00: DEBUG ▶ [EVENTS] 71e4 Message acked, message_uuid=0ed676ea-5d87-415b-9e10-28fcc413d448
2022-10-13T09:06:40.993058176+02:00: DEBUG ▶ [EVENTS] 71e5 Message acked, message_uuid=0ed676ea-5d87-415b-9e10-28fcc413d448, topic=task.updated
2022-10-13T09:06:51.933709806+02:00: DEBUG ▶ [EVENTS] 7212 Sending msg to subscriber, message_uuid=c0549c19-71c4-43fa-acd2-b56461fe30d8, topic=task.updated
2022-10-13T09:06:51.933737007+02:00: DEBUG ▶ [EVENTS] 7213 Sent message to subscriber, message_uuid=c0549c19-71c4-43fa-acd2-b56461fe30d8, topic=task.updated
2022-10-13T09:06:51.933785397+02:00: DEBUG ▶ [EVENTS] 7214 Received message, message_uuid=c0549c19-71c4-43fa-acd2-b56461fe30d8
2022-10-13T09:06:51.933904058+02:00: DEBUG ▶ [EVENTS] 7215 Message acked, message_uuid=c0549c19-71c4-43fa-acd2-b56461fe30d8
2022-10-13T09:06:51.93391607+02:00: DEBUG ▶ [EVENTS] 7216 Message acked, message_uuid=c0549c19-71c4-43fa-acd2-b56461fe30d8, topic=task.updated
2022-10-13T09:06:55.246019063+02:00: DEBUG ▶ [EVENTS] 7247 Sending msg to subscriber, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539, topic=task.assignee.created
2022-10-13T09:06:55.24604991+02:00: DEBUG ▶ [EVENTS] 7248 Sent message to subscriber, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539, topic=task.assignee.created
2022-10-13T09:06:55.246077342+02:00: DEBUG ▶ [EVENTS] 7249 Received message, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539
2022-10-13T09:06:55.247779199+02:00: DEBUG ▶ [EVENTS] 7250 Message acked, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539
2022-10-13T09:06:55.247810918+02:00: DEBUG ▶ [EVENTS] 7251 Message acked, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539, topic=task.assignee.created
2022-10-13T09:06:55.247828701+02:00: DEBUG ▶ [EVENTS] 7252 Sending msg to subscriber, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539, topic=task.assignee.created
2022-10-13T09:06:55.247841315+02:00: DEBUG ▶ [EVENTS] 7253 Sent message to subscriber, topic=task.assignee.created, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539
2022-10-13T09:06:55.247864909+02:00: DEBUG ▶ [EVENTS] 7254 Received message, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539
2022-10-13T09:06:55.249161519+02:00: DEBUG ▶ [EVENTS] 7257 Message acked, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539
2022-10-13T09:06:55.249175937+02:00: DEBUG ▶ [EVENTS] 7258 Message acked, message_uuid=40f5f3b1-4be1-4281-852f-f7affbc7e539, topic=task.assignee.created
grep "mail server" standard.log
2022-10-13T17:21:32.708303434+02:00: INFO ▶ mail/func1 12060 Closed connection to mail server
The last line indicates there weren’t connection to the mail server at ~ 09:06 but only at 17:21 that is the time when I closed that task.
The “task assigned notification” you mentioned from the docs is one where a user gets an email address when they are assigned to a task. Is that what you’re looking for?
I’m sorry but I didn’t understand. Can you rephrase?
What I meant is:
- User A created a task
- User A assigned the task to User B
- User B did not get a notification while in the same scenario he did (so works randomly?)
Hope is more clear now.
Is user B subscribed to the namespace/list/task?
We don’t use subscription on namespace/list, instead we use subscription to the task.
So usually user B is subscribed when user A assigns the task, but sometimes it does not happen all the times.
In other words, after assignment, user B got an email like this:
This does not happen all the times, like in the case posted here:
So how to debug why at the assignment time user B does not receive notification?
Thanks
NOTE:
if it can help, we discovered that assignee receives the notification in case of comments, so as workaround we write the description as comment instead of as description so we are sure we get notifications about the new tasks.
mmhh so basically the assignee gets notifications about comments (that means the subscription itself is working) but not always when they are assigned to the task?
Can you check if that’s a timing problem? When a lot of changes are made in a short period of time Vikunja will try to avoid spamming you with a lot of notifications. This should only happen for direct task attributes, assignees are separate from that.
Exactly.
I asked all to be disconnected and I made a test. From an account, I opened a task ans assigned it to my user(ago), and I didn’t get notifications.
Here is what I was able to see with tail -f *.log in the meantime:
2022-10-19T09:05:48.63576686+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/lists/3 32.51µs -
==> events.log <==
2022-10-19T09:05:48.671316382+02:00: DEBUG ▶ [EVENTS] 1352e Sending msg to subscriber, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b, topic=task.created
2022-10-19T09:05:48.671544067+02:00: DEBUG ▶ [EVENTS] 1352f Sent message to subscriber, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b, topic=task.created
2022-10-19T09:05:48.671579053+02:00: DEBUG ▶ [EVENTS] 13530 Received message, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b
2022-10-19T09:05:48.671703055+02:00: DEBUG ▶ [EVENTS] 13531 Message acked, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b
2022-10-19T09:05:48.671715137+02:00: DEBUG ▶ [EVENTS] 13532 Message acked, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b, topic=task.created
2022-10-19T09:05:48.671724885+02:00: DEBUG ▶ [EVENTS] 13533 Sending msg to subscriber, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b, topic=task.created
2022-10-19T09:05:48.671732329+02:00: DEBUG ▶ [EVENTS] 13534 Sent message to subscriber, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b, topic=task.created
2022-10-19T09:05:48.671750353+02:00: DEBUG ▶ [EVENTS] 13535 Received message, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b
2022-10-19T09:05:48.671765191+02:00: DEBUG ▶ [EVENTS] 13536 Message acked, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b
2022-10-19T09:05:48.671772585+02:00: DEBUG ▶ [EVENTS] 13537 Message acked, topic=task.created, message_uuid=385b0b90-3a8d-4249-b6cc-9b9f6602565b
==> http.log <==
2022-10-19T09:05:48.671916554+02:00: WEB ▶ $IP PUT 201 /api/v1/lists/3 8.473216ms -
2022-10-19T09:05:50.025324337+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/155/comments?page=1 38.122µs -
2022-10-19T09:05:50.025600413+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/155 29.775µs -
2022-10-19T09:05:50.054031018+02:00: WEB ▶ $IP GET 200 /api/v1/tasks/155/comments?page=1 6.115783ms -
2022-10-19T09:05:50.057954416+02:00: WEB ▶ $IP GET 200 /api/v1/tasks/155 6.789053ms -
==> standard.log <==
2022-10-19T09:05:50.16698936+02:00: DEBUG ▶ initials/GetAvatar 13564 Initials avatar for user 1 and size 48 not cached, creating...
==> http.log <==
2022-10-19T09:05:50.186954733+02:00: WEB ▶ $IP GET 200 /api/v1/avatar/testapi?size=48 20.640713ms -
2022-10-19T09:05:52.762988234+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/notifications?page=1 32.259µs -
2022-10-19T09:05:52.783875591+02:00: WEB ▶ $IP GET 200 /api/v1/notifications?page=1 1.225949ms -
2022-10-19T09:05:56.296650243+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/lists/3/listusers?s=ag&page=1 38.571µs -
2022-10-19T09:05:56.336393539+02:00: WEB ▶ $IP GET 200 /api/v1/lists/3/listusers?s=ag&page=1 7.744877ms -
2022-10-19T09:05:56.524828953+02:00: WEB ▶ $IP GET 200 /api/v1/lists/3/listusers?s=ag&page=1 2.940623ms -
2022-10-19T09:05:56.857341076+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/lists/3/listusers?s=ago&page=1 38.452µs -
2022-10-19T09:05:56.891195322+02:00: WEB ▶ $IP GET 200 /api/v1/lists/3/listusers?s=ago&page=1 3.003901ms -
2022-10-19T09:05:57.828347029+02:00: WEB ▶ $IP OPTIONS 204 /api/v1/tasks/155/assignees 27.051µs -
==> standard.log <==
2022-10-19T09:05:57.829128057+02:00: DEBUG ▶ upload/GetAvatar 1358b Uploaded avatar for user 2 and size 32 not cached, resizing and caching.
==> events.log <==
2022-10-19T09:05:57.86205957+02:00: DEBUG ▶ [EVENTS] 135a7 Sending msg to subscriber, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa, topic=task.assignee.created
2022-10-19T09:05:57.862088354+02:00: DEBUG ▶ [EVENTS] 135a8 Sent message to subscriber, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa, topic=task.assignee.created
2022-10-19T09:05:57.862120022+02:00: DEBUG ▶ [EVENTS] 135a9 Received message, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa
2022-10-19T09:05:57.863559211+02:00: DEBUG ▶ [EVENTS] 135b0 Message acked, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa
2022-10-19T09:05:57.8635796+02:00: DEBUG ▶ [EVENTS] 135b1 Message acked, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa, topic=task.assignee.created
2022-10-19T09:05:57.863590809+02:00: DEBUG ▶ [EVENTS] 135b2 Sending msg to subscriber, topic=task.assignee.created, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa
2022-10-19T09:05:57.863599736+02:00: DEBUG ▶ [EVENTS] 135b3 Sent message to subscriber, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa, topic=task.assignee.created
2022-10-19T09:05:57.863622889+02:00: DEBUG ▶ [EVENTS] 135b4 Received message, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa
==> standard.log <==
2022-10-19T09:05:57.862885343+02:00: DEBUG ▶ models/Handle 135ab Sending task assigned notifications to 0 subscribers for task 155
==> http.log <==
2022-10-19T09:05:57.863049037+02:00: WEB ▶ $IP PUT 201 /api/v1/tasks/155/assignees 9.813932ms -
==> events.log <==
2022-10-19T09:05:57.865093747+02:00: DEBUG ▶ [EVENTS] 135b7 Message acked, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa
2022-10-19T09:05:57.865114786+02:00: DEBUG ▶ [EVENTS] 135b8 Message acked, message_uuid=7aab24ca-a371-4c78-8047-5a64378814aa, topic=task.assignee.created
==> http.log <==
2022-10-19T09:05:57.894174507+02:00: WEB ▶ $IP GET 200 /api/v1/avatar/ago?size=32 65.853836ms -
==> standard.log <==
2022-10-19T09:05:57.902935431+02:00: DEBUG ▶ upload/GetAvatar 135bc Uploaded avatar for user 2 and size 24 not cached, resizing and caching.
==> http.log <==
2022-10-19T09:05:57.977509366+02:00: WEB ▶ $IP GET 200 /api/v1/avatar/ago?size=24 75.092363ms -
==> standard.log <==
2022-10-19T09:06:00.000542781+02:00: DEBUG ▶ models/getTasksWithRemindersDueAndTheirUsers 135bf [Task Reminder Cron] Looking for reminders between 2022-10-19 09:06:00 +0200 CEST and 2022-10-19 09:07:00 +0200 CEST to send...
2022-10-19T09:06:00.001818423+02:00: DEBUG ▶ models/getTasksWithRemindersDueAndTheirUsers 135c1 [Task Reminder Cron] Found 0 reminders
2022-10-19T09:06:00.005263097+02:00: DEBUG ▶ models/func1 135cc [Undone Overdue Tasks Reminder] Sending reminders to 0 users
Important:
the topic was started as “Email stop to work until restart” but right now, I’m not able to fix with a restart of the api service or an entire machine reboot.
From the code that got executed it looks like your user (ago) is not subscribed to the task (or at least that’s the only way the Sending task assigned notifications to 0 subscribers for task 155 could happen). This seems to indicate there’s something wrong with the subscription and not with my earlier theory of Vikunja throttling notifications.
Can you set the db logging to debug and check for a select query to the subscriptions table when you assign that user?
I got a task assigned. The UI reports that it was created at:
2022-10-22T12:17:26+02:00
So at that time in database.log I get:
# cat database.log | grep -i select | grep subscriptions
2022-10-22T12:17:11.941998959+02:00: INFO ▶ [DATABASE] 2f184 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists WHERE id=?) AND entity_type=?)) LIMIT 1 [6 3 2 3 1] - 731.467µs
2022-10-22T12:17:28.077255945+02:00: INFO ▶ [DATABASE] 2f2d3 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) LIMIT 1 [6 189 3 189 1 189 2] - 654.985µs
2022-10-22T12:19:05.708499506+02:00: INFO ▶ [DATABASE] 2f869 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) [189 3 189 1 189 2] - 1.224479ms
2022-10-22T12:19:05.709866019+02:00: INFO ▶ [DATABASE] 2f873 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) LIMIT 1 [2 189 3 189 1 189 2] - 672.226µs
2022-10-22T12:19:08.433268683+02:00: INFO ▶ [DATABASE] 2f882 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) LIMIT 1 [6 189 3 189 1 189 2] - 714.885µs
2022-10-22T12:19:26.772538395+02:00: INFO ▶ [DATABASE] 2f8ea [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) [189 3 189 1 189 2] - 811.866µs
2022-10-22T12:20:31.29988919+02:00: INFO ▶ [DATABASE] 2fa77 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (entity_type = ? AND user_id = ?) AND `entity_id` IN (?,?) [1 2 2 3] - 4.409839ms
2022-10-22T12:20:33.033681917+02:00: INFO ▶ [DATABASE] 2fb39 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists WHERE id=?) AND entity_type=?)) LIMIT 1 [2 3 2 3 1] - 523.689µs
2022-10-22T12:20:36.401018101+02:00: INFO ▶ [DATABASE] 2fda1 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) LIMIT 1 [2 189 3 189 1 189 2] - 554.336µs
2022-10-22T12:20:38.49235151+02:00: INFO ▶ [DATABASE] 2feb4 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists INNER JOIN tasks ON lists.id = tasks.list_id WHERE tasks.id=?) AND entity_type=?) OR (entity_id=(SELECT list_id FROM tasks WHERE id=?) AND entity_type=?)) LIMIT 1 [2 189 3 189 1 189 2] - 158.556µs
2022-10-22T12:20:38.535643455+02:00: INFO ▶ [DATABASE] 2fef4 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (user_id = ?) AND ((entity_id=? AND entity_type=?) OR (entity_id=(SELECT namespace_id FROM lists WHERE id=?) AND entity_type=?)) LIMIT 1 [2 3 2 3 1] - 726.457µs
2022-10-22T12:20:38.540703249+02:00: INFO ▶ [DATABASE] 2ff02 [SQL] SELECT `id`, `entity_type`, `entity_id`, `user_id`, `created` FROM `subscriptions` WHERE (entity_type = ? AND user_id = ?) AND `entity_id` IN (?,?) [1 2 2 3] - 409.275µs
Maybe some lines of logs are not relevant but I’m including them as well.
When did the request to PUT 201 /api/v1/tasks/155/assignees happen? Can you also send the http logs for the same period as the db?