The export is from Vikunja Cloud. I upload it to my local Docker installation, wait about a minute, then I get a 502 in response to a PUT request to /api/v1/migration/vikunja-file/migrate. The uploaded file is 40 MB, so I increased the max file size in nginx.conf and config.yml. I can upload other files without incident.
Any guidance on where I might find applicable logs? A tail on the nginx container’s /var/log/nginx/error.log file hangs.
Thank you!
What’s in the api logs?
Is it exactly one minute? Then it might be a request limit of nginx.
I went in the api container but didn’t see anything in /var/log - where should I be looking?
I’ll investigate the nginx timeout.
Thank you for your help! I’m totally loving Vikunja, thank you for bringing it to the world!
If you didn’t explicitly configure log output to file, check the stdout via the docker logs command.
Thanks for the kind words!
I ran docker log -f, and I got the expected results about the notifications API endpoint that all seem to be behaving as normal, then a bunch of errors. The UI kept acting like it was still importing. When it finally acknowledged to the user that the process had failed, no more logs appeared in docker, like there was a delayed reaction in the frontend.
These are the relevant log messages:
2023-03-16T21:14:03.202591511Z: WEB ▶ 172.18.0.4 GET 200 /api/v1/notifications?page=1 3.177956ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:14:13.13062945Z: WEB ▶ 172.18.0.4 GET 200 /api/v1/notifications?page=1 2.244199ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:14:23.126512062Z: WEB ▶ 172.18.0.4 GET 200 /api/v1/notifications?page=1 3.97223ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.578151804Z: ERROR ▶ handler/ReadAllWeb 0d3 dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.586732684Z: ERROR ▶ handler/ReadAllWeb 0d5 dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.590623988Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 281.954281ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.594056847Z: ERROR ▶ handler/ReadAllWeb 0d7 dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.594210246Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 307.970282ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.59491335Z: ERROR ▶ handler/ReadAllWeb 0d9 dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.595003901Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 162.217737ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.595178091Z: ERROR ▶ handler/ReadAllWeb 0db dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.595258015Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 239.466992ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.616436534Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 286.13105ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.766902346Z: ERROR ▶ handler/ReadAllWeb 0dd dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.772756145Z: ERROR ▶ handler/ReadAllWeb 0df dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.774837063Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 123.864362ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.778463784Z: ERROR ▶ handler/ReadAllWeb 0e1 dial tcp 172.18.0.5:3306: connect: connection refused
2023-03-16T21:15:48.778535012Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 90.436167ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
2023-03-16T21:15:48.800871329Z: WEB ▶ 172.18.0.4 GET 500 /api/v1/notifications?page=1 123.716233ms - Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
Any help would be much appreciated.
Thank you!
That reads like your database crashed. Anything in the logs of that container?
You’re right, it seems to be dying. When I watch the log while attempting the import, nothing shows up, but when I look at it again after, it indicates that it restarted. I’m not an expert in MySQL logging, but it it seems like all the messages in the log are normal startup messages:
Version: '10.11.2-MariaDB-1:10.11.2+maria~ubu2204' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
2023-03-21 05:58:15+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.2+maria~ubu2204 started.
2023-03-21 05:58:16+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2023-03-21 05:58:16+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.2+maria~ubu2204 started.
2023-03-21 05:58:16+00:00 [Note] [Entrypoint]: MariaDB upgrade not required
2023-03-21 5:58:16 0 [Note] Starting MariaDB 10.11.2-MariaDB-1:10.11.2+maria~ubu2204 source revision cafba8761af55ae16cc69c9b53a341340a845b36 as process 1
2023-03-21 5:58:16 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-03-21 5:58:17 0 [Note] InnoDB: Number of transaction pools: 1
2023-03-21 5:58:17 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-03-21 5:58:17 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2023-03-21 5:58:17 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOMEM: try larger memory locked limit, ulimit -l, or https://mariadb.com/kb/en/systemd/#configuring-limitmemlock under systemd (262144 bytes required)
2023-03-21 5:58:17 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
2023-03-21 5:58:17 0 [Note] InnoDB: Initializing buffer pool, total size = 50.000MiB, chunk size = 1.000MiB
2023-03-21 5:58:17 0 [Note] InnoDB: Completed initialization of buffer pool
2023-03-21 5:58:17 0 [Note] InnoDB: File system buffers for log disabled (block size=512 bytes)
2023-03-21 5:58:17 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=403840
2023-03-21 5:58:17 0 [Note] InnoDB: Starting final batch to recover 3 pages from redo log.
2023-03-21 5:58:17 0 [Note] InnoDB: 128 rollback segments are active.
2023-03-21 5:58:17 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2023-03-21 5:58:17 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2023-03-21 5:58:17 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2023-03-21 5:58:17 0 [Note] InnoDB: log sequence number 404774; transaction id 1327
2023-03-21 5:58:17 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2023-03-21 5:58:17 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-03-21 5:58:17 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
2023-03-21 5:58:17 0 [Note] InnoDB: Buffer pool(s) load completed at 230321 5:58:17
2023-03-21 5:58:17 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-03-21 5:58:17 0 [Note] Server socket created on IP: '::'.
2023-03-21 5:58:17 0 [Note] mariadbd: ready for connections.
Version: '10.11.2-MariaDB-1:10.11.2+maria~ubu2204' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
A couple times it’s reported:
Aborted connection 64 to db: [db name] user: [username] host: '172.18.0.2' (Got an error reading communication packets)
In light of that error, I tried tweaking a few config variables in /etc/mysql/mariadb.conf.d/5-server.cnf as suggested by https://dev.mysql.com/doc/refman/8.0/en/innodb-parameters.html#sysvar_innodb_log_file_size and innodb - MySQL: Error reading communication packets - Database Administrators Stack Exchange among other sources. They include:
The top two warnings materialized after I tweaked one of the above settings (I don’t remember which). I haven’t sought it out to change back since I know it’s not the root issue. I’m not inclined to believe the third (about rotating logs) is relevant.
Just for science, I exported the data from my self-hosted instance (two lists, one of which has maybe five items) and re-imported it to the same instance. It returned a 500 error. The API container said:
2023-03-21T06:06:26.724587809Z: ERROR ▶ migration/InsertFromStructure 2cb [creating structure] Error while creating structure: List identifier is not unique.
I don’t know if that’s helpful, but I thought I’d mention it in case it’s a clue.
Sorry to keep asking for more and more from you. I appreciate all the help you’ve provided.
Thank you!
Not sure either, but shouldn’t there be more logs somewhere else?
That should not happen. Can you check the exported json for list idenfifiers? My first guess from the top of my head would be they are empty and the import does not handle it properly.
New error! Hooray!
I scaled up the RAM from 512 MB to 1 GB and now I’m getting a 500 instead of a 502. The API container says:
2023-03-26T08:20:24.503961928Z: - ▶ echo recover.go:113 [PANIC RECOVER] runtime error: invalid memory address or nil pointer dereference goroutine 366 [running]:
github.com/labstack/echo/v4/middleware.RecoverWithConfig.func1.1.1()
/go/pkg/mod/github.com/labstack/echo/v4@v4.10.2/middleware/recover.go:93 +0x14e
panic({0x12dd4c0, 0x214e630})
/usr/local/go/src/runtime/panic.go:884 +0x213
archive/zip.(*File).findBodyOffset(0x0)
/usr/local/go/src/archive/zip/reader.go:345 +0x33
archive/zip.(*File).Open(0x0)
/usr/local/go/src/archive/zip/reader.go:223 +0x33
code.vikunja.io/api/pkg/modules/migration/vikunja-file.(*FileMigrator).Migrate(0x17cf810?, 0x143121e?, {0x17b3380?, 0xc0000240e8?}, 0x4120c7?)
/go/src/code.vikunja.io/api/pkg/modules/migration/vikunja-file/vikunja.go:144 +0x1385
code.vikunja.io/api/pkg/modules/migration/handler.(*FileMigratorWeb).Migrate(0xa0b980?, {0x17cf810, 0xc0004b0280})
/go/src/code.vikunja.io/api/pkg/modules/migration/handler/handler_file.go:61 +0x150
github.com/labstack/echo-jwt/v4.Config.ToMiddleware.func2.1({0x17cf810, 0xc0004b0280})
/go/pkg/mod/github.com/labstack/echo-jwt/v4@v4.1.0/jwt.go:237 +0x41d
code.vikunja.io/api/pkg/routes.registerAPIRoutes.func1.1({0x17cf810, 0xc0004b0280})
/go/src/code.vikunja.io/api/pkg/routes/routes.go:225 +0x1cb
github.com/labstack/echo/v4.(*Echo).add.func1({0x17cf810, 0xc0004b0280})
/go/pkg/mod/github.com/labstack/echo/v4@v4.10.2/echo.go:575 +0x51
github.com/labstack/echo/v4/middleware.CORSWithConfig.func1.1({0x17cf810, 0xc0004b0280})
/go/pkg/mod/github.com/labstack/echo/v4@v4.10.2/middleware/cors.go:264 +0x8b8
github.com/labstack/echo/v4/middleware.RecoverWithConfig.func1.1({0x17cf810, 0xc0004b0280})
/go/pkg/mod/github.com/labstack/echo/v4@v4.10.2/middleware/recover.go:119 +0xfe
github.com/labstack/echo/v4/middleware.LoggerWithConfig.func2.1({0x17cf810, 0xc0004b0280})
/go/pkg/mod/github.com/labstack/echo/v4@v4.10.2/middleware/logger.go:126 +0xe2
github.com/labstack/echo/v4.(*Echo).ServeHTTP(0xc0004d6480, {0x17bb380?, 0xc0018cc620}, 0xc0000bc900)
/go/pkg/mod/github.com/labstack/echo/v4@v4.10.2/echo.go:662 +0x3d1
net/http.serverHandler.ServeHTTP({0x17b79f0?}, {0x17bb380, 0xc0018cc620}, 0xc0000bc900)
/usr/local/go/src/net/http/server.go:2936 +0x316
net/http.(*conn).serve(0xc000345050, {0x17bbd10, 0xc00036ac30})
/usr/local/go/src/net/http/server.go:1995 +0x612
created by net/http.(*Server).Serve
/usr/local/go/src/net/http/server.go:3089 +0x5ed
goroutine 1 [chan receive, 4 minutes]:
code.vikunja.io/api/pkg/cmd.glob..func25(0x2161380?, {0x142cb86?, 0x0?, 0x0?})
/go/src/code.vikunja.io/api/pkg/cmd/web.go:102 +0x19e
github.com/spf13/cobra.(*Command).execute(0x2161380, {0xc000040050, 0x0, 0x0})
/go/pkg/mod/github.com/spf13/cobra@v1.6.1/command.go:920 +0x847
github.com/spf13/cobra.(*Command).ExecuteC(0x2161380)
/go/pkg/mod/github.com/spf13/cobra@v1.6.1/command.go:1044 +0x3bd
github.com/spf13/cobra.(*Command).Execute(...)
/go/pkg/mod/github.com/spf13/cobra@v1.6.1/command.go:968
code.vikunja.io/api/pkg/cmd.Execute()
/go/src/code.vikunja.io/api/pkg/cmd/cmd.go:44 +0x25
main.main()
/go/src/code.vikunja.io/api/main.go:22 +0x17
goroutine 9 [select, 4 minutes]:
database/sql.(*DB).connectionOpener(0xc00044ef70, {0x17bbc68, 0xc0003d9400})
/usr/local/go/src/database/sql/sql.go:1218 +0x8d
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:791 +0x18d
goroutine 357 [select, 1 minutes]:
database/sql.(*DB).connectionCleaner(0xc00044ef70, 0xc00036001c?)
/usr/local/go/src/database/sql/sql.go:1061 +0xa7
created by database/sql.(*DB).startCleanerLocked
/usr/local/go/src/database/sql/sql.go:1048 +0x105
goroutine 15 [select, 4 minutes]:
github.com/robfig/cron/v3.(*Cron).run(0xc0004b0140)
/go/pkg/mod/github.com/robfig/cron/v3@v3.0.1/cron.go:263 +0xab9
created by github.com/robfig/cron/v3.(*Cron).Start
/go/pkg/mod/github.com/robfig/cron/v3@v3.0.1/cron.go:222 +0xca
goroutine 16 [chan receive, 4 minutes]:
github.com/ThreeDotsLabs/watermill/message.(*Router).Run(0xc0000c0c40, {0x17bbca0?, 0xc000044070?})
/go/pkg/mod/github.com/!three!dots!labs/watermill@v1.2.0/message/router.go:370 +0x2bd
code.vikunja.io/api/pkg/events.InitEvents()
/go/src/code.vikunja.io/api/pkg/events/events.go:95 +0
Do you know what that might mean?
For anybody who comes later, this was the clue that lead me to believe it may be a memory issue: docker events reported:
2023-03-26T08:05:51.017896999Z container oom [detailed container description omitted for the sake of brevity]
2023-03-26T08:05:51.860586909Z container die [more details]
I learned from OOM in docker container - Stack Overflow that oom means out of memory.
I should have added that whereas before I was getting a 502, after increasing the memory, it was a 500. docker events had nothing to say for itself. I bumped it up to 2 GB, but I’m still seeing the 500, so it’s probably not a memory issue right now.
That’s an error that should never happen. Probably not related to not enough memory available.
From looking at the code for that part, it seems like an attachment file could not be found. Can you check in the zip file if there is a file in the files folder for each attachment in the json?
I ran the data.json through a beautifier for easier use of grep. That’s the data_beautified.json file mentioned below.
I have 42 boards. There are 57 files (51 JPEG and 6 PNG) in the files/ according to find files -type f, but the following search in data.json returned nothing:
grep 'attachments": ' data_beautified.json | grep -v '"attachments": \[' | grep -v 'attachments": null'
Is that the right property to be looking for?
I got 168 results (all unique) when I looked for background images (they’re all of Unsplash):
grep background_file_id data_beautified.json
That’s also the number of IDs in the JSON file with the value 297:
grep '^ "id":' data_beautified.json | grep 297 | wc -l
When I searched not-unique, I get 203 results:
grep '^ "id":' data_beautified.json | wc -l
I took casual look at the 57 files and they all appear to be undamaged. It tracks that most of them are background images, but there are a couple files that were actually attached.
Thanks again for your time.
EDIT: I got the number of not-unique IDs wrong when I first posted this. Also, I posted the wrong command for how I came to the number of times 297 appears. Sorry for any confusion.
Can you check if there are any attachments? IIRC they should be null if none are present but I could be wrong.
I searched with grep '"attachments": ' data.json and got two unique values:
"attachments": null,
"attachments": [
I thought I remembered the background attachments being a different property, so I ran grep '"attachments' data.json | grep -v '"attachments": ' but got nothing.
Is that the information you’re looking for?
I should have added that there are 131 instances of ‘“attachments”: [’. I took a look at a couple and they seemed OK. Here’s an example I picked at random:
"attachments": [
{
"id": 562,
"task_id": 56807,
"created_by": {
"id": 297,
"name": "KJ",
"username": "[username]",
"created": "2023-03-08T06:45:34Z",
"updated": "2023-03-25T16:56:11Z"
},
"file": {
"id": 1166,
"name": "Screenshot_20230324_102328.jpg",
"mime": "",
"size": 393360,
"created": "2023-03-24T17:22:53Z"
},
"created": "2023-03-24T17:22:53Z"
}
],
Is there a file in the files folder with the file id in attachments.file.id for each attachment?
It doesn’t look like it. The sample ID from above which I chose at random is 562. I ran `ls files/5* and found no directories. I didn’t do any further searching. Is that what you’re looking for? If you want me to take a comprehensive inventory of what the differences are, is there a relatively easy way to automate that search?
Thanks again for your time and for the fantastic free/OSS software you’ve brought into the world.
I just realized I was looking at attachments.id as oppose to attachments.file.id. There is indeed a files/1166 (the one from the example above). I just looked at the one file. Do you want me to do a detailed inventory?
EDITED TO ADD:
In terms of an easy way to automate the search: I’m going to attempt to throw together a quick script. Even though it doesn’t exist yet, I wanted to mention this before you spend a lot of time digging into a potential easy way to run the search.
SECOND ADDENDUM:
According to my script: There are 142 file IDs in data.json. There are 127 files referenced in data.json but that don’t exist on the filesystem. There are 15 files that are both referenced in json.data and exist on the filesystem.
There are 57 files in ./files/; there are 42 files that are in the directory but not referenced in data.json. This jives with the 15 figure given above.
Thanks again.
Huh! That sounds like something that shouldn’t happen. Are these missing files all file attachments? (Not backgrounds or avatars)
Can you check if this is a problem only in the dump or on the instance you exported the dump from as well? Checking this would be a little easier there: for each entry in the files table, there should be a file with its ID in the files/ directory.
Within a given list, I searched for tasks.attachments.file.id. Background file have their own per-list property, background_file_id, correct?
I exported Vikunja Cloud, so I don’t have access to its files/ directory 
At least half of those 142 files were originally uploaded to Trello. Is it possible that for whatever reason, it wasn’t able to get them from Trello? I have one board there with about 80 images. I go in Trello and I see the images, but I don’t see them in Vikunja Cloud. I divorced Trello a few years ago, and they’ve since put in a limit on how many boards one can have in the free workspace. I believe that means they trimmed each workspace to 10 boards and made the other boards inaccessible to me (I don’t remember how many boards each workspace had, but I think two of the three workspaces had more than 10). That said, the board with the 80 attachments is not one of the ones it hid.
If I may be so bold as to speculate, is it possible that something like the following happened? Vikunja Cloud asked Trello for its information, Trello handed over the board information but not all the attachments and/or Vikunja Cloud had some kind of problem downloading the attachments. I exported from Vikunja Cloud, and it gave me what it had, including the references to the missing files. I uploaded Vikunja Cloud’s export to the self-hosted Vikunja instance that I set up, and that instance has a problem with the missing files.
I don’t think Trello gives up its attachments easily. I have a vague recollection that Wekan couldn’t upload them either.
Does that answer all your questions?
Thanks again!