Upgrade to Gitea 1.15.0 - service doesn't start properly - StaticUrlPrefix

[shezay]

• Gitea version (or commit ref): 1.15.0
• Git version: 2.25.1
• Operating system: Ubuntu 20.04.1 LTS using gitea-1.15.0-linux-amd64 and running it with systemd
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No
• Log gist:

2021/08/23 08:52:58 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 15 (for task-level) adding 1 workers with group id: 1
2021/08/23 08:53:00 ...dules/setting/log.go:333:newLogService() [I] Gitea Log Mode: File(File:trace)
2021/08/23 08:53:00 ...dules/setting/log.go:250:generateNamedLogger() [I] Router Log: Console(console:trace)
2021/08/23 08:53:00 ...les/setting/cache.go:73:newCacheService() [I] Cache Service Enabled
2021/08/23 08:53:00 ...les/setting/cache.go:88:newCacheService() [I] Last Commit Cache Service Enabled
2021/08/23 08:53:00 ...s/setting/session.go:77:newSessionService() [I] Session Service Enabled
2021/08/23 08:53:00 ...s/storage/storage.go:158:initAttachments() [I] Initialising Attachment storage with type:
2021/08/23 08:53:00 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at /var/lib/gitea/data/attachments
2021/08/23 08:53:00 ...s/storage/storage.go:152:initAvatars() [I] Initialising Avatar storage with type:
2021/08/23 08:53:00 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at /var/lib/gitea/data/avatars
2021/08/23 08:53:00 ...s/storage/storage.go:170:initRepoAvatars() [I] Initialising Repository Avatar storage with type:
2021/08/23 08:53:00 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at /var/lib/gitea/data/repo-avatars
2021/08/23 08:53:00 ...s/storage/storage.go:164:initLFS() [I] Initialising LFS storage with type:
2021/08/23 08:53:00 ...les/storage/local.go:47:NewLocalStorage() [I] Creating new Local Storage at /var/lib/gitea/data/lfs
2021/08/23 08:53:00 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: push_update-channel (QID: 1)
2021/08/23 08:53:00 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: push_update-level (QID: 2)
2021/08/23 08:53:00 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: push_update (QID: 3)
2021/08/23 08:53:00 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: notification-service-channel (QID: 4)
2021/08/23 08:53:00 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: push_update Starting
2021/08/23 08:53:00 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: push_update Waiting til closed
2021/08/23 08:53:00 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 1 (for push_update-channel) adding 1 workers with group id: 1
2021/08/23 08:53:00 ...ue/queue_bytefifo.go:96:Run() [D] level: push_update-level Starting
2021/08/23 08:53:00 ...ue/queue_bytefifo.go:104:Run() [T] level: push_update-level Waiting til closed
2021/08/23 08:53:00 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 2 (for push_update-level) adding 1 workers with group id: 1
2021/08/23 08:53:00 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: notification-service-level (QID: 5)
2021/08/23 08:53:00 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: notification-service (QID: 6)
2021/08/23 08:53:00 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: notification-service Starting
2021/08/23 08:53:00 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: notification-service Waiting til closed
2021/08/23 08:53:00 ...ue/queue_bytefifo.go:96:Run() [D] level: notification-service-level Starting
2021/08/23 08:53:00 ...ue/queue_bytefifo.go:104:Run() [T] level: notification-service-level Waiting til closed
2021/08/23 08:53:00 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 4 (for notification-service-channel) adding 1 workers with group id: 1
2021/08/23 08:53:00 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 5 (for notification-service-level) adding 1 workers with group id: 1
2021/08/23 08:53:00 routers/init.go:150:GlobalInit() [I] SQLite3 Supported
2021/08/23 08:53:00 routers/init.go:68:initDBEngine() [I] Beginning ORM engine initialization.
2021/08/23 08:53:00 routers/init.go:75:initDBEngine() [I] ORM engine initialization attempt #1/10...
2021/08/23 08:53:00 ...om/urfave/cli/app.go:524:HandleAction() [I] PING DATABASE mysql
2021/08/23 08:53:01 ...rfave/cli/command.go:173:Run() [W] Table project column board_type db type is INT, struct type is INT UNSIGNED
2021/08/23 08:53:01 ...rfave/cli/command.go:173:Run() [W] Table project column type db type is INT, struct type is INT UNSIGNED
2021/08/23 08:53:01 ...rfave/cli/command.go:173:Run() [W] Table session has column created_unix but struct has not related field
2021/08/23 08:53:01 routers/init.go:155:GlobalInit() [I] ORM engine initialization successful!
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: update_mirrors
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: repo_health_check
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: check_repo_stats
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: archive_cleanup
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: sync_external_users
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: deleted_branches_cleanup
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: cleanup_hook_task_table
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_inactive_accounts
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_repo_archives
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: git_gc_repos
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: resync_all_sshkeys
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: resync_all_sshprincipals
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: resync_all_hooks
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: reinit_missing_repos
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_missing_repos
2021/08/23 08:53:01 ...odules/cron/tasks.go:120:RegisterTask() [D] Registering task: delete_generated_repository_avatars
2021/08/23 08:53:01 models/repo.go:1750:DeleteOldRepositoryArchives() [T] Doing: ArchiveCleanup
2021/08/23 08:53:01 models/repo.go:1842:CheckRepoStats() [T] Doing: CheckRepoStats
2021/08/23 08:53:01 models/branches.go:610:RemoveOldDeletedBranches() [T] Doing: DeletedBranchesCleanup
2021/08/23 08:53:01 models/repo.go:1759:DeleteOldRepositoryArchives() [T] Finished: ArchiveCleanup
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: issue_indexer (QID: 7)
2021/08/23 08:53:01 ...er/issues/indexer.go:142:func2() [I] PID 107950: Initializing Issue Indexer: bleve
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: repo_stats_update-channel (QID: 8)
2021/08/23 08:53:01 ...er/issues/indexer.go:171:func2() [D] Created Bleve Indexer
2021/08/23 08:53:01 ...er/issues/indexer.go:221:func3() [I] Issue Indexer Initialization took 10.414124ms
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:96:Run() [D] level: issue_indexer Starting
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:104:Run() [T] level: issue_indexer Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 7 (for issue_indexer) adding 1 workers with group id: 1
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: repo_stats_update-level (QID: 9)
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: repo_stats_update (QID: 10)
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: pr_patch_checker-channel (QID: 11)
2021/08/23 08:53:01 ...ueue_disk_channel.go:162:Run() [D] PersistableChannelUniqueQueue: repo_stats_update Starting
2021/08/23 08:53:01 ...ueue_disk_channel.go:192:Run() [T] PersistableChannelUniqueQueue: repo_stats_update Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 8 (for repo_stats_update-channel) adding 1 workers with group id: 1
2021/08/23 08:53:01 ...xer/stats/indexer.go:38:populateRepoIndexer() [I] Populating the repo stats indexer with existing repositories
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:96:Run() [D] unique-level: repo_stats_update-level Starting
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:104:Run() [T] unique-level: repo_stats_update-level Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 9 (for repo_stats_update-level) adding 1 workers with group id: 1
2021/08/23 08:53:01 ...xer/stats/indexer.go:84:populateRepoIndexer() [I] Done (re)populating the repo stats indexer with existing repositories
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: pr_patch_checker-level (QID: 12)
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: pr_patch_checker (QID: 13)
2021/08/23 08:53:01 ...ueue_disk_channel.go:162:Run() [D] PersistableChannelUniqueQueue: pr_patch_checker Starting
2021/08/23 08:53:01 ...ueue_disk_channel.go:192:Run() [T] PersistableChannelUniqueQueue: pr_patch_checker Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 11 (for pr_patch_checker-channel) adding 1 workers with group id: 1
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:96:Run() [D] unique-level: pr_patch_checker-level Starting
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:104:Run() [T] unique-level: pr_patch_checker-level Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 12 (for pr_patch_checker-level) adding 1 workers with group id: 1
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: task-channel (QID: 14)
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: task-level (QID: 15)
2021/08/23 08:53:01 ...les/queue/manager.go:134:Add() [T] Queue Manager registered: task (QID: 16)
2021/08/23 08:53:01 ...ueue_disk_channel.go:137:Run() [D] PersistableChannelQueue: task Starting
2021/08/23 08:53:01 ...ueue_disk_channel.go:160:Run() [T] PersistableChannelQueue: task Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 14 (for task-channel) adding 1 workers with group id: 1
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:96:Run() [D] level: task-level Starting
2021/08/23 08:53:01 ...ue/queue_bytefifo.go:104:Run() [T] level: task-level Waiting til closed
2021/08/23 08:53:01 .../queue/workerpool.go:213:commonRegisterWorkers() [T] WorkerPool: 15 (for task-level) adding 1 workers with group id: 1

Description

We upgraded gitea from 1.14.6 to 1.15.0 and the service doesn't appear to start. It does write logs continously, though.
go version is 1.16.7, same as when we run gitea 1.14.6 (Set minimum supported version of go to 1.16 (#16710))
And we've changed the assets path (Move (custom) assets into subpath /assets (#15219))
We also renamed StaticUrlPrefix to AssetUrlPrefix (#15779) on the custom files.

The logs are on 'Trace' mode and were showing up over and over. I only noticed some warnings:

2021/08/23 08:53:01 ...rfave/cli/command.go:173:Run() [W] Table project column board_type db type is INT, struct type is INT UNSIGNED
2021/08/23 08:53:01 ...rfave/cli/command.go:173:Run() [W] Table project column type db type is INT, struct type is INT UNSIGNED
2021/08/23 08:53:01 ...rfave/cli/command.go:173:Run() [W] Table session has column created_unix but struct has not related field

We reverted to the 1.14.6 version. But we're unsure of what we missed.

Thank you for your time.
And for future reference, should i ask this sort of thing on the discord?

[zeripath]

Is that all the logs you have? You seem to have given us only part of the logs, for example I'm not seeing a [F], evidence of a restart or the attempt to bind to the port.

Some pointers though:

• DEBUG logging would usually suffice see https://docs.gitea.io/en-us/logging-configuration/#debugging-problems TRACE should really only be used with expression settings to interrogate certain things.
• The Warning messages you've put up above are not an issue - you can safely ignore them or attempt to use gitea doctor recreate-table project to make them go away. That you've highlighted them tells me though that you're seeing them often - meaning that the service is constantly restarting further confirming that you've not given me all the logs though.
• To further highlight that the DB warning can be ignored:

2021/08/23 08:53:01 routers/init.go:155:GlobalInit() [I] ORM engine initialization successful!

means that the DB has successfully migrated and initialised - so this isn't likely to be a DB problem. (I will never say never with MySQL though.)

• I can see that you have changed several low-level settings - we need to see your app.ini (suitably sanitised).

It's often helpful to do both discord and here - but discord is often quicker to sort things out.

[shezay]

app.ini.txt
logs.txt

I've attached the app.ini file and the logs after a restart. We changed the log level to 'debug'.
The first line was the last line when we stopped the service. After that we started it and let it run for a minute.

[zeripath]

Can you check your journald? We're still missing the reason why the program is repeatedly dying just after logging this:

2021/08/23 11:28:24 ...ue/queue_bytefifo.go:96:Run() [D] level: task-level Starting

My suspicion is that something will be being written to stdout there. Something somewhere is causing an unguarded panic in a goroutine or calling an unguarded os.Exit(...).

(This is why the debugging logging advice says to use console output not file - so we get all of this information.)

---

However I do see:

[database]
...
CHARSET=ut8

This should usually be utf8mb4 on MySQL. It's not the cause of this problem - but you're going to face issues with emoji and then needing to use gitea convert in future.

[zeripath]

I have a feeling that this is going to be a custom template issue similar to #16784.

[shezay]

We tried starting it without the "custom" folder and gitea seems to work.

I was worried i did the "public" to "assets" change wrong.
How is the /custom/ folder structure supposed to look?
We currently have this:
custom/
├── assets
│      └── img
│              └── [some images]
└── templates
       ├── base
       │      ├── footer_content.tmpl
       │      ├── footer.tmpl
       │      └── head.tmpl
       └── home.tmpl

[zeripath]

Journalctl will tell you what the problem is.

There is a panic in template compilation which will be being emitted on stdout. A pr to ensure that this goes to the logs in the future has just been merged.

The panic will most likely be related to the use of staticurlprefix which should be changed to asseturlprefix as per our published breaking changes.

Look at your templates and journalctl.

[zeripath]

agh just realised I closed this by mistake. @shezay could you confirm that my comment above is correct?

[shezay]

There was a panic regarding the templates. I don't remember what it was now, the logs about that got lost in the terminal and have been trying to change the templates to see if they'll work. And we made them work for the most part.

Also, I had changed staticurlprefix to asseturlprefix, however it doesn't seem to be able to find the images on the assets folder (getting 404 errors).

Other than that, gitea 1.15.0 seems to be working okay! It just can't find the assets folder or i have set up something incorrectly.
I'm currently looking at the docs regarding templates to see if there is something I did wrong.

Thank you so much for time!

[zeripath]

I was worried i did the "public" to "assets" change wrong.
How is the /custom/ folder structure supposed to look?
We currently have this:
custom/
├── assets
│      └── img
│              └── [some images]
└── templates
       ├── base
       │      ├── footer_content.tmpl
       │      ├── footer.tmpl
       │      └── head.tmpl
       └── home.tmpl

Ah I've just realised what you mean here.

You don't need to change the filesystem! move the assets folder back to public - change your templates to add an assets/ prefix if you need them.

[shezay]

omg that was it haha i was just thinking too "what if i rename it to public again".
I just misunderstood that haha.
All good now!

[zeripath]

Sorry that you had such a difficult time getting this upgrade working.

Following #16788 the panic will now go to the logs properly - which should help prevent future issues. This has been backported to the 1.15 branch and will be in 1.15.1.

[shezay]

No problem! It was honestly just me misunderstanding something.
Thank you for your help

[solarchemist]

Definitely template-related.
I have two gitea instances on the same VPS. Only one of them broke when upgrading from 1.14 to 1.15 (the one that uses a custom theme).

Fixed by changing {{StaticUrlPrefix}} in /var/lib/gitea/<instance>/custom/templates/home.tmpl to {{AssetUrlPrefix}} as suggested by @zeripath above and restarting the systemd job.