500 Internal Server Error when selecting Unsplash background image

MisterSanders · 29 August 2022 21:46

Hi! I’m trying to make use of the Unsplash background image feature. Everything’s fine until the end – I can select a background option from the List properties, see default Unsplash images, search and see results for images. But when I select an Unsplash image to use, I get the following toast message and the UI stays parked on the gallery of images:

Error
Request failed with status code 500
Internal Server Error

Here’s an screenshot:

Some information about what I’m using:

Frontend Version: 0.19.1
API Version: v0.19.2
installed on Unraid using the Community Applications with the following extra environment variables:
- VIKUNJA_BACKGROUNDS_ENABLED = true
- VIKUNJA_BACKGROUNDS_PROVIDERS_UNSPLASH_ENABLED = true
- VIKUNJA_BACKGROUNDS_PROVIDERS_UNSPLASH_ACCESSTOKEN = my Unsplash application Access Key. The sample config.yml file reads “accesstoken” on line 266, which I assume is the same as “Access Key” in my Unsplash application
- VIKUNJA_BACKGROUNDS_PROVIDERS_UNSPLASH_APPLICATIONID = my application id taken from the URL, as instructed in the sample config.yml file (line 270).

I’m not sure what I might have missed. I’m so close, seeing and searching Unsplash within Vikunja. I just need that final selection to work.
I wish I could supply some logs, but I’m not sure which ones or where I would find them. If anyone has an idea to try to get me that last piece home, or how I can provide some more useful information, please let me know.

kjgcoop · 1 July 2023 07:33

Did anybody find a solution for this?

I just noticed this problem tonight, but I haven’t tried to change a background for like a month, so it may have existed for a while.

I’m running unstable because I like to live dangerously. Actually it’s because I wanted to import from Vikunja Cloud and that required a newer version than what was stable at the time. I pulled the latest images about 20 minutes ago.

Any help would be much appreciated.

EDIT: This is what the logs have to say:
api_1 | 2023-07-01T07:17:07.634805484Z: ERROR handler/GetProjectBackground 1b3 open files/28: no such file or directory

Just for science, I created files/28, but I’m getting the same error. I tried it a few times and it was always 28.

kolaente · 2 July 2023 16:30

Does the error happen during the change of backgrounds? Or when retrieving it?

Does it work if you remove the background and then try to set a new one?

Does it work if you try to set one on a new project?

kjgcoop · 8 July 2023 10:06

I can see the potential backgrounds, but after I click one and it fires off the request to /v1/projects/[id]/backgrounds/unsplash, that’s the one that returns the 500. I’m not sure whether the process has problems retrieving it from Unsplash or gets it but then it has problems setting it as that background.

I created a new project and was able to add a background with no problem.

When I upload a file from my machine as opposed to Unsplash, I get the same error in the logs and 500 status code.

Thanks for your help.

kolaente · 8 July 2023 11:48

Can you enable debug logs and check if there’s any useful information around the error?

And this happens every time you set a background, regardless if via unsplash or direct upload, but only on one specific project?

kjgcoop · 8 July 2023 15:49

I can replace the image on the new project I created to test with using Unsplash. Since it didn’t give me any guff, I didn’t try uploading from my computer. You probably know what uneventful logs look like, but I’m going to include them just in case it’s helpful to have a comparison:

api_1 | 2023-07-08T15:41:30.975639331Z: DEBUG unsplash/Set 1aa Downloaded unsplash photo djfaqT2giLc
api_1 | 2023-07-08T15:41:31.125334576Z: DEBUG unsplash/Set 1ab Pinged unsplash download endpoint for photo djfaqT2giLc
api_1 | 2023-07-08T15:41:31.134399896Z: DEBUG unsplash/Set 1b0 Saved unsplash photo djfaqT2giLc as file 158 with new entry 23
api_1 | 2023-07-08T15:41:31.142618465Z: WEB 172.18.0.3 POST 200 /api/v1/projects/209/backgrounds/unsplash 974.316442ms - Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0
proxy_1 | 71.238.66.77 - - [08/Jul/2023:15:41:31 +0000] “POST /api/v1/projects/209/backgrounds/unsplash HTTP/1.1” 200 410 “http://[IP address]/projects/209/settings/background” “Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0” “-”

It’s had problems on every pre-existing project I’ve tried. Here’s the relevant portion of the logs with debugging turned on when attempting to grab from Unsplash:

api_1 | 2023-07-08T15:31:25.923378935Z: DEBUG unsplash/Set 0d2 Downloaded unsplash photo tmD2T6L4cWA
api_1 | 2023-07-08T15:31:26.039088613Z: DEBUG unsplash/Set 0d3 Pinged unsplash download endpoint for photo tmD2T6L4cWA
api_1 | 2023-07-08T15:31:26.043554721Z: ERROR handler/SetBackground 0d6 file 30 does not exist
api_1 | 2023-07-08T15:31:26.044463704Z: WEB 172.18.0.3 POST 500 /api/v1/projects/207/backgrounds/unsplash 131.37018ms - Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0

This is from when I upload my own file:

proxy_1 | 71.238.66.77 - - [08/Jul/2023:15:36:24 +0000] “PUT /api/v1/projects/207/backgrounds/upload HTTP/1.1” 500 36 “http://[IP address]/projects/207/settings/background” “Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0” “-”
api_1 | 2023-07-08T15:36:24.678345555Z: ERROR handler/UploadBackground 117 file 30 does not exist
api_1 | 2023-07-08T15:36:24.679010912Z: WEB 172.18.0.3 PUT 500 /api/v1/projects/207/backgrounds/upload 413.685378ms - Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0

Does that offer some clues?

Thanks again.

kolaente · 10 July 2023 14:23

And the old background files it’s trying to remove exist on disk? Does the user running have permission to remove or edit them?

kjgcoop · 11 July 2023 23:49

It doesn’t look like files/30 does exist. Just for fun, I created it with touch files/30 but the error remained the same.

Do you mean Vikunja user? I’m the only user, so it shouldn’t be a permissions problem. If you mean the OS user Vikunja runs as, it should. It can CRUD other files.

kolaente · 13 July 2023 16:55

This seems really strange.

Yeah I mean the user Vikunja runs as.

If you do a ls -lah on the files folder, are all files owned by the same user?

kjgcoop · 14 July 2023 20:25

They are.

It occurred to me that I made the board by duplicating another. I got an error when I duplicated the project, but it appeared anyway, so I mentally set the error aside to deal with later. I bet this is an artifact of it not having copied completely.

If you think this is a promising idea to pursue, do you want me to open a new ticket for the project duplication error since it’s a new issue?

I tried to duplicate the problem board. Here are the logs:

api_1       | 2023-07-14T20:05:47.583332318Z: DEBUG	▶ models/Create 50f2 Duplicated project 207 into new project 211
api_1       | 2023-07-14T20:05:47.592682181Z: DEBUG	▶ models/Handle 50fe Sending project created notifications to 0 subscribers for project 211
api_1       | 2023-07-14T20:05:47.617331048Z: DEBUG	▶ models/Create 5118 Duplicated all buckets from project 207 into 211
api_1       | 2023-07-14T20:05:48.220876505Z: DEBUG	▶ models/duplicateTasks 56d2 Duplicated all tasks from project 207 into 211
api_1       | 2023-07-14T20:05:48.227429431Z: DEBUG	▶ models/duplicateTasks 56e4 Duplicated attachment 45 into 50 from project 207 into 211
api_1       | 2023-07-14T20:05:48.232878Z: DEBUG	▶ models/duplicateTasks 56ef Duplicated attachment 47 into 51 from project 207 into 211
api_1       | 2023-07-14T20:05:48.233817872Z: DEBUG	▶ models/duplicateTasks 56f0 Duplicated all attachments from project 207 into 211
api_1       | 2023-07-14T20:05:48.313389598Z: DEBUG	▶ models/duplicateTasks 574c Duplicated all labels from project 207 into 211
api_1       | 2023-07-14T20:05:48.315213145Z: DEBUG	▶ models/duplicateTasks 574e Duplicated all assignees from project 207 into 211
api_1       | 2023-07-14T20:05:48.334303616Z: DEBUG	▶ models/duplicateTasks 575f Duplicated all comments from project 207 into 211
api_1       | 2023-07-14T20:05:48.344082871Z: DEBUG	▶ models/duplicateTasks 5765 Duplicated all task relations from project 207 into 211
api_1       | 2023-07-14T20:05:48.344151896Z: DEBUG	▶ models/Create 5766 Duplicating background 30 from project 207 into 211
api_1       | 2023-07-14T20:05:48.346118601Z: ERROR	▶ handler/CreateWeb 5768 file 30 does not exist
api_1       | 2023-07-14T20:05:48.346221117Z: WEB 	▶ 172.18.0.3  PUT 500 /api/v1/projects/207/duplicate 777.789981ms - Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0
proxy_1     | 71.238.66.77 - - [14/Jul/2023:20:05:48 +0000] "PUT /api/v1/projects/207/duplicate HTTP/1.1" 500 36 "http://137.184.112.65/projects/207/settings/duplicate" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/114.0" "-"

For science, I un-archived then tried to duplicate the original project. It showed the same error as above about file 30 not existing. Which makes sense, if it doesn’t exist, everybody’s going to run into the problem of it not existing.

I went to delete the project, but it also had an error. The logs again reported file 30’s non-existence as a problem, but the board disappeared from the list as though it had been deleted.

Thanks for your help!

kjgcoop · 14 July 2023 20:41

I went traipsing around in the database and select * from files where id in (20, 30) returned only the row for 20. I’m entertaining the notion of adding a row for 30. Do you think that would end disastrously?

kolaente · 22 August 2023 16:02

The logs seem to indicate the background was duplicated. Does the new duplicated project have a background? Can you check in the db if the background_file_id is different from the original project?

Riley · 28 August 2023 02:01

I find myself dealing with this as well suddenly. I added a background image to a project that I normally use as a template for projects. Then I duplicated the project and I ran into the same stuff. 500 error upon duplicating the project. But then the project DID show up. Now I can’t delete the duplicate or the original because they all refer to this same 500 error about “can’t find file”. I went so far as to copy files/26 to files/27 (27 is the one mine complains about) and file 26 does show up now as the background for these ones I can’t delete, but still it complains that it can’t delete files/27 because it does not exist.

@kjgcoop did you ever try jamming that extra line into the database? Any adverse effects?

For reference, this is my current version:

/app/vikunja # ./vikunja version
Vikunja api version v0.21.0
Built with go1.20.5

kolaente · 29 August 2023 11:20

Was there any error in the logs when you got that 500 error message while duplicating?

Riley · 31 August 2023 12:17

This is what I see in the logs at the time of an attempted duplication (docker log, if something more specific is desired, let me know what you’re after and I’ll happily track it down):

023-08-31T12:11:44.157957705Z: WEB 	▶ 192.168.1.16  GET 200 /api/v1/projects/8 6.379788ms - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36
2023-08-31T12:11:45.155711263Z: WEB 	▶ 192.168.1.16  GET 200 /api/v1/notifications?page=1 2.100313ms - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36
2023-08-31T12:11:47.157986497Z: ERROR	▶ handler/CreateWeb 14a63 file 27 does not exist
2023-08-31T12:11:47.158052935Z: WEB 	▶ 192.168.1.16  PUT 500 /api/v1/projects/8/duplicate 240.033684ms - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36

Likewise, if I try to delete the project that has the incorrect background:

2023-08-31T12:14:05.241260257Z: WEB 	▶ 192.168.1.16  GET 200 /api/v1/projects/8/tasks?page=1 2.678104ms - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36
2023-08-31T12:14:07.733963386Z: ERROR	▶ handler/DeleteWeb 14aa7 file 27 does not exist
2023-08-31T12:14:07.734041771Z: WEB 	▶ 192.168.1.16  DELETE 500 /api/v1/projects/8 5.961417ms - Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36

Finally, file 27 does exist:

/app/vikunja/files # ls -la 
total 46304
drwxrwxrwx    1 vikunja  vikunja        132 Aug 29 13:17 .
drwxr-xr-x    1 vikunja  vikunja         32 Aug 28 01:38 ..
-rw-r--r--    1 vikunja  vikunja        329 Aug 17 00:02 .env
-rw-r--r--    1 vikunja  vikunja     132904 Aug  5 01:02 1
-rw-r--r--    1 vikunja  vikunja     110185 Aug  6 15:45 10
-rw-r--r--    1 vikunja  vikunja      24146 Aug  6 15:48 11
-rw-r--r--    1 vikunja  vikunja     183189 Aug  6 15:49 12
-rw-r--r--    1 vikunja  vikunja      22926 Aug  6 15:51 13
-rw-r--r--    1 vikunja  vikunja     384397 Aug  6 21:19 14
-rw-r--r--    1 vikunja  vikunja      28576 Aug  6 23:28 15
-rw-r--r--    1 vikunja  vikunja     168581 Aug  6 23:30 17
-rw-r--r--    1 vikunja  vikunja     175431 Aug 10 01:16 18
-rw-r--r--    1 vikunja  vikunja      12371 Aug  5 02:19 2
-rw-r--r--    1 vikunja  vikunja     885467 Aug 15 23:37 20
-rw-r--r--    1 vikunja  vikunja     874595 Aug 15 23:42 21
-rw-r--r--    1 vikunja  vikunja    1645397 Aug 15 23:56 22
-rw-r--r--    1 vikunja  vikunja     472266 Aug 28 00:31 24
-rw-r--r--    1 vikunja  vikunja     504901 Aug 28 01:08 26
-rw-r--r--    1 vikunja  vikunja     504901 Aug 28 01:47 27
-rw-r--r--    1 vikunja  vikunja    4385306 Aug 28 01:10 28
-rw-r--r--    1 vikunja  vikunja    4385306 Aug 28 01:17 29
-rw-r--r--    1 vikunja  vikunja    4385306 Aug 28 01:17 30
-rw-r--r--    1 vikunja  vikunja    3361019 Aug 28 01:41 31
-rw-r--r--    1 vikunja  vikunja    3361019 Aug 28 01:41 32
-rw-r--r--    1 vikunja  vikunja     164266 Aug 29 13:17 33
-rw-r--r--    1 vikunja  vikunja      32772 Aug  5 05:51 4
-rw-r--r--    1 vikunja  vikunja     162170 Aug  5 13:46 6
-rw-r--r--    1 vikunja  vikunja      90505 Aug  6 15:20 8
-rw-r--r--    1 vikunja  vikunja    1076497 Aug  6 15:39 9

I copied 26 to 27 so it would be a valid jpg. The background does actually show up as 26’s image. It leads me to believe that the “file” is stored elsewhere (a database row) which is why @kjgcoop’s thought of the row in the database was intriguing to me. I haven’t inspected that part yet.

kjgcoop · 31 August 2023 15:09

@Riley I did try adding the database row, to no avail. It was a while ago, so I don’t remember the details.

kjgcoop · 1 September 2023 01:44

I duplicated a couple boards today and I didn’t run into this problem. I duplicated a third board and it did have the problem with the backgrounds.

I haven’t looked at the logs yet, but I wanted to post an update since it’s more than just me seeing this.

kolaente · 7 September 2023 08:53

I’ve tried debugging this but without any luck. Does this work for you on try btw?

kjgcoop · 12 September 2023 05:15

I haven’t been able to reproduce it on try. @Riley, have you?

Thanks, both of you!

Riley · 12 September 2023 22:22

I was able to repro on the try instance. I uploaded a random image from my phone, didn’t use whatever images were already available. Mine is the Rileytest project. And yes I got a 500 error when trying to duplicate it.

I hit the button several times, so maybe it would be easier to stumble across the result in logs