Navidrome upgrade failed from 1.2.5 to 1.2.6

[ForsakenRei]

TrueNAS-SCALE-23.10.1

App Version: 0.51.0 Chart Version: 1.2.5

When trying to upgrade to chart version 1.2.6, app will stuck on deploying, pod log looks like this:

time="2024-01-26T14:01:39Z" level=fatal msg="Failed to apply new migrations" error="ERROR go migration: "20231209211223_alter_lyric_column.go": failed to run go migration: disk I/O error: permission denied

No setting or permission of host path changed: apps:apps with 775, user id is 568.

It seems I'm not the only one having this issue. And this is the second time I have the same issue with Navidrome so it might worth reporting it back. https://www.truenas.com/community/threads/unable-to-update-applications-on-latest-tn-scale.116020/

[ForsakenRei]

https://github.com/navidrome/navidrome/issues/2805 might be related

[stavros-k]

To be honest this error does not make much sense.

.go code/files are compiled to one or more binaries, but this error indicates that navidrome tries to access the .go file directly.

I've tried to look how navidrome loads those files, but I don't think it actually tries to access this file. So the issue is not directly there.

I would understand if it had issues opening the database file (sqlite), but that would have errored far before the migration step.

Can you please share the full logs, maybe this helps pinpoint the source. or at least help me navigate on the code.

Thanks

[ForsakenRei]

@stavros-k

2024-02-19 20:15:06.583004-05:00Version: 0.51.1 (6d253225) 2024-02-19 20:15:06.583009-05:002024-02-19T20:15:06.583009179-05:00 2024-02-19 20:15:06.586294-05:00time="2024-02-20T01:15:06Z" level=info msg="Upgrading DB Schema to latest version" 2024-02-19 20:15:06.613746-05:00time="2024-02-20T01:15:06Z" level=fatal msg="Failed to apply new migrations" error="ERROR go migration: "20240122223340_add_default_values_to_null_columns.go.go": failed to run go migration: disk I/O error: permission denied"

All the logs from that pod, is there any other logs I can grab?

[zgs225]

I occurs same issue when I upgrade navidrome from 0.49.x to 0.51.1 in my k3s cluster.

[Eliot-Mess]

Same error here

2024-02-19 23:57:05.939422-05:00Version: 0.51.1 (6d253225)
2024-02-19 23:57:05.939430-05:002024-02-19T23:57:05.939430281-05:00
2024-02-19 23:57:05.943285-05:00time="2024-02-20T04:57:05Z" level=info msg="Upgrading DB Schema to latest version"
2024-02-19 23:57:05.953036-05:00time="2024-02-20T04:57:05Z" level=fatal msg="Failed to apply new migrations" error="ERROR go migration: \"20231209211223_alter_lyric_column.go\": failed to run go migration: disk I/O error: permission denied"

[stavros-k]

I occurs same issue when I upgrade navidrome from 0.49.x to 0.51.1 in my k3s cluster.

Is this k3s cluster a self-managed one or you mean the k3s managed by truenas? Just want to make sure the issue is isolated on our chart, and not something upstream.

[stavros-k]

I did a test on my local machine,

• installed the chart with 0.49.3 with hostPath for both data and music
• loaded up some songs
• upgraded the chart to 0.51.1

I had no migration issues.

---

Can you do an ls -l <path-to-navidrome-directories ?

Mine look like this:

❯ ls -la     
total 12
drwxr-xr-x 4 root root 4 Φεβ  20 15:14 .
drwxr-xr-x 5 root root 5 Φεβ  20 15:14 ..
drwxr-xr-x 3  568  568 6 Φεβ  20 15:17 data
drwxr-xr-x 3  568  568 3 Φεβ  20 15:15 music

and

❯ ls data -la
total 466
drwxr-xr-x 3  568  568       6 Φεβ  20 15:17 .
drwxr-xr-x 4 root root       4 Φεβ  20 15:14 ..
drwxr-xr-x 4  568  568       4 Φεβ  20 15:15 cache
-rw-r--r-- 1  568  568  475136 Φεβ  20 15:17 navidrome.db
-rw-r--r-- 1  568  568   32768 Φεβ  20 15:20 navidrome.db-shm
-rw-r--r-- 1  568  568 4128272 Φεβ  20 15:20 navidrome.db-wal

[ForsakenRei]

Can you do an ls -l <path-to-navidrome-directories ?

Here's mine, looks normal right?

I linked a navidrome issue above so I'm not sure if it's upstream or not.

[stavros-k]

Yea this looks good to me.

I don't really know how else I would debug this, as I've tried few installs and upgrades and all worked for me.

I'll leave this open for now, to collect feedback.

[stavros-k]

Hey, considering that there aren't any reports yet, and there isn't any concrete reproduction steps, I'll close this for now. If someone stumps on this issue, feel free to comment if you have any reproduction steps and we can look into it again.

Thanks!

[amtux]

Version: TrueNAS-SCALE-22.12.4.2 Upgrade from 0.49.3_1.0.3 -> 0.51.1_1.2.6

im running into the same issue as well. navidrome pod starts crashlooping with failed to run go migration: disk I/O error: permission denied in logs.

ls -l /mnt/storage/ix-applications/releases/navidrome/volumes/ix_volumes/data
total 362
drwxr-xr-x 4 apps apps       4 Jul 11  2023 cache
-rw-r--r-- 1 apps apps  782336 Mar  1 15:53 navidrome.db
-rw-r--r-- 1 apps apps   32768 Mar  1 16:08 navidrome.db-shm
-rw-r--r-- 1 apps apps 1244272 Mar  1 16:08 navidrome.db-wal

find . ! -user apps | wc -l
0

[amtux]

I ended up deleting data/ and starting fresh with 1.2.6 so I wouldn't have to deal with this.

[ForsakenRei]

I ended up deleting data/ and starting fresh with 1.2.6 so I wouldn't have to deal with this.

I ended up with the same thing, sad but no other choices.

[stavros-k]

Did this happen on previews upgrades on only during the upgrade to 0.51.1?

[raskitoma]

Had the same error with previous and current upgrade.

Tried to reset permissions, ACL, etc. Nothing worked.

Same "failed to run go migration: disk I/O error: permission denied" error.

Only solution, 2 times in a row: Delete app data folder and start again.

[Jeff-WuYo]

My error looks like this, it doesn't even let my upgrade.

 Error: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/middlewared/job.py", line 427, in run
    await self.future
  File "/usr/lib/python3/dist-packages/middlewared/job.py", line 465, in __run_body
    rv = await self.method(*([self] + args))
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/schema/processor.py", line 177, in nf
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/schema/processor.py", line 44, in nf
    res = await f(*args, **kwargs)
          ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/plugins/chart_releases_linux/upgrade.py", line 115, in upgrade
    await self.upgrade_chart_release(job, release, options)
  File "/usr/lib/python3/dist-packages/middlewared/plugins/chart_releases_linux/upgrade.py", line 265, in upgrade_chart_release
    config, context = await self.middleware.call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1399, in call
    return await self._call(
           ^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1342, in _call
    return await methodobj(*prepared_call.args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/plugins/chart_releases_linux/chart_release.py", line 339, in normalise_and_validate_values
    dict_obj = await self.middleware.call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1399, in call
    return await self._call(
           ^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1342, in _call
    return await methodobj(*prepared_call.args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/plugins/chart_releases_linux/validation.py", line 72, in validate_values
    verrors.check()
  File "/usr/lib/python3/dist-packages/middlewared/service_exception.py", line 70, in check
    raise self
middlewared.service_exception.ValidationErrors: [EINVAL] chart_release_create.navidromeStorage.music.hostPathConfig.acl: /mnt/azide/app_data/Navidrome_Music: path contains existing data and `force` was not specified

I think my issue might be different, I'm no expert, feel free to correct me if I'm wrong. There's a Force Flag in the setting, but I am scare of losing data or some shenanigan.

[ForsakenRei]

I think my issue might be different, I'm no expert, feel free to correct me if I'm wrong. There's a Force Flag in the setting, but I am scare of losing data or some shenanigan.

Sadly I think everyone in this thread eventually did a fresh reinstall...

[stavros-k]

I'm reopening this, but I'd like to have access to a machine that has this issue, in order to investigate more.

Because it still does not make sense for a db migration to fail due to permissions issues, considering that the application runs without problems using the same database...

[virtualdxs]

My box is hitting the same issue. Permissions are correct; did a chown to verify. Same error:

time="2024-04-21T01:07:18Z" level=debug msg="Opening DataBase" dbPath="/data/navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on" driver=sqlite3
time="2024-04-21T01:07:18Z" level=info msg="Upgrading DB Schema to latest version"
time="2024-04-21T01:07:18Z" level=fatal msg="Failed to apply new migrations" error="ERROR go migration: \"20231209211223_alter_lyric_column.go\": failed to run go migration: disk I/O error: permission denied"

I can provide access to the box to debug.

[stavros-k]

@virtualdxs Can you please send me a mail at [email protected], in order to arrange it? Thanks

[flobere]

Same issue, same app/charts version as OP with same log except erroring on \"20240122223340_add_default_values_to_null_columns.go.go\"

[stavros-k]

I'll still need access to a machine for troubleshooting. but in the meantime, I'd also suggest opening an issue upstream.

I'm still confused how it can error out while migrating, while it was using the same database right before the upgrade without issues. Which I would really like to find the root cause :D

[virtualdxs]

@stavros-k I sent you an email shortly after your comment here. I'll resend; can you confirm you received it?

[stavros-k]

Hello, yes got it! replied to the email. Thanks