search

kagemomiji / airsonic-advanced

airsonic-advanced
GNU General Public License v3.0
154 stars 14 forks source link

[Bug]: After update to latest Edge Airsonic won't start, no error given #553

Closed bartmans closed 1 week ago

bartmans commented 1 month ago

What happened?

After update to latest Edge Airsonic won't start. It hangs without an error: 2024-07-24 15:58:57.110 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var)

2024-07-24 15:58:57.114 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default"

2024-07-24 15:59:02.796 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296

2024-07-24 15:59:03.175 INFO --- org.airsonic.player.Application : Detected Tomcat web server

2024-07-24 16:01:29.715 INFO --- l.database.core.HsqlDatabase : Set default schema name to PUBLIC

Steps to reproduce

Restart Airsonic latest

Version

11.1.4-SNAPSHOT (Edge)

Version Detail

Edge Release 11.1.4-SNAPSHOT.20240723133122

Operating System

Synology Docker

Java Version

17

Database

Other

DB Detail

Sqlite

Configuration paramter

Airsonic preferences. NOTE: This file is automatically generated. Do not modify while application is running

Airsonic preferences. NOTE: This file is automatically generated. Do not modify while application is running

EncryptionKeyPassword= EncryptionKeySalt= SettingsChanged=1720748956725 JWTKey=9eirnhrnn3pg65e1j0l6bjvteq DlnaEnabled=false DlnaServerName=Airsonic DlnaBaseLANURL=http://192.168.178.20:4041 DlnaServerId=8c88e797-a32e-4380-8cb1-537d025239de IndexString=A B C D E F G H I J K L M N O P Q R S T U V W X-Z(XYZ) IgnoredArticles=The El La Los Las Le Les De Het Een GenreSeparators=; Shortcuts= PlaylistFolder=/playlists MusicFileTypes=mp3 ogg oga aac m4a m4b flac wav wma aif aiff ape mpc shn mka opus alm 669 mdl far xm mod fnk imf it liq wow mtm ptm rtm stm s3m ult dmf dbm med okt emod sfx m15 mtn amf gdm stx gmc psm j2b umx amd rad hsc flx gtk mgt mtp wv VideoFileTypes=flv avi mpg mpeg mp4 m4v mkv mov wmv ogv divx m2ts webm CoverArtFileTypes2=cover.jpg cover.png cover.gif folder.jpg jpg jpeg gif png CoverArtSource=FILETAG CoverArtConcurrency=8 CoverArtQuality=90 SortAlbumsByYear=true GettingStartedEnabled=false WelcomeTitle=Sepulchrijn: Bart's Muziek WelcomeSubtitle=Beta WelcomeMessage2= LoginMessage= server.servlet.session.timeout=3600m Theme=ripserver LocaleLanguage=nl LocaleCountry= LocaleVariant= IndexCreationInterval=1 IndexCreationHour=2 FastCacheEnabled=false OrganizeByFolderStructure=true UploadsFolder=%{['USER_MUSIC_FOLDERS'][0]}/Incoming ExcludePattern=#recycle|@eaDir|gsdata|.mov IgnoreSymLinks=true DownloadBitrateLimit=0 UploadBitrateLimit=0 LdapEnabled=false LdapUrl=ldap://host.domain.com:389/cn=Users,dc=domain,dc=com LdapSearchFilter=(sAMAccountName={0}) LdapManagerDn= LdapAutoShadowing=false SmtpServer= SmtpEncryption=SSL/TLS SmtpPort=465 SmtpUser= SmtpFrom= SmtpPassword= CaptchaEnabled=false ReCaptchaSiteKey=6LeIxAcTAAAAAJcZVRqyHh71UMIEGNQ_MXjiZKhI HideIndexedFiles=false PodcastUpdateInterval=-1 PodcastEpisodeRetentionCount=2 PodcastEpisodeDownloadCount=0 spring.liquibase.parameters.mysqlVarcharLimit=384 DbBackupUpdateInterval=24 DbBackupRetentionCount=5 EnableCueIndexing=false

Proxy Server

Nginx

client detail

Firefox and Chrome

language

Dutch

Relevant log output

2024-07-24 02:05:32.445  INFO --- o.a.p.s.MediaScannerService              : Scanned media library with 102377 entries.
2024-07-24 02:05:32.445  INFO --- o.a.p.s.MediaScannerService              : Persisting albums
2024-07-24 02:05:32.558  INFO --- o.a.p.s.MediaScannerService              : Persisting artists
2024-07-24 02:05:32.580  INFO --- o.a.p.s.MediaScannerService              : Persisting genres
2024-07-24 02:05:41.651  INFO --- o.a.p.s.MediaScannerService              : Updating genres
2024-07-24 02:05:41.693  INFO --- o.a.p.s.MediaScannerService              : Genre persistence successfully complete: true
2024-07-24 02:05:49.088  INFO --- o.a.p.s.MediaScannerService              : Marking non-present albums.
2024-07-24 02:05:49.223  INFO --- o.a.p.s.MediaScannerService              : Album persistence complete
2024-07-24 02:05:50.629  INFO --- o.a.p.s.MediaScannerService              : Marking non-present artists.
2024-07-24 02:05:50.640  INFO --- o.a.p.s.MediaScannerService              : Artist persistence complete
2024-07-24 02:05:50.640  INFO --- o.a.p.s.MediaScannerService              : Completed media library scan.
2024-07-24 02:05:50.643  INFO --- o.a.p.s.MediaScannerService              : Media library scan took 350s
2024-07-24 02:05:50.644  INFO --- o.a.p.s.MediaScannerService              : Media library scan completed.
2024-07-24 02:05:50.644  INFO --- o.a.p.service.PlaylistService            : Starting playlist import.
2024-07-24 02:05:50.721  INFO --- o.a.p.service.PlaylistService            : Completed playlist import.
2024-07-24 02:05:57.576  INFO --- o.a.p.s.MediaScannerService              : Indexing complete.
2024-07-24 09:48:07.575  INFO --- org.airsonic.player.Application          : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var)
2024-07-24 09:48:07.591  INFO --- org.airsonic.player.Application          : No active profile set, falling back to 1 default profile: "default"
2024-07-24 09:48:24.449  INFO --- o.a.p.service.SettingsService            : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296
2024-07-24 09:48:25.318  INFO --- org.airsonic.player.Application          : Detected Tomcat web server
2024-07-24 09:50:08.558  INFO --- l.database.core.HsqlDatabase             : Set default schema name to PUBLIC
2024-07-24 11:41:15.719  INFO --- l.c.StandardChangeLogHistoryService      : Reading from PUBLIC.DATABASECHANGELOG
2024-07-24 15:04:05.421  INFO --- org.airsonic.player.Application          : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var)
2024-07-24 15:04:05.424  INFO --- org.airsonic.player.Application          : No active profile set, falling back to 1 default profile: "default"
2024-07-24 15:04:14.699  INFO --- o.a.p.service.SettingsService            : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296
2024-07-24 15:04:14.994  INFO --- org.airsonic.player.Application          : Detected Tomcat web server
2024-07-24 15:07:46.138  INFO --- l.database.core.HsqlDatabase             : Set default schema name to PUBLIC
2024-07-24 15:58:57.110  INFO --- org.airsonic.player.Application          : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var)
2024-07-24 15:58:57.114  INFO --- org.airsonic.player.Application          : No active profile set, falling back to 1 default profile: "default"
2024-07-24 15:59:02.796  INFO --- o.a.p.service.SettingsService            : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296
2024-07-24 15:59:03.175  INFO --- org.airsonic.player.Application          : Detected Tomcat web server
2024-07-24 16:01:29.715  INFO --- l.database.core.HsqlDatabase             : Set default schema name to PUBLIC
kagemomiji commented 1 month ago

@bartmans If the logs stop at that point, it seems to be an issue with HSQLDB. Could you try recovering DB with a backup folder of HSQLDB?

bartmans commented 1 month ago

I have no clue what happened but it seems to have self corrected. I noticed today that AS Edge was running. Logs picks up hours later. 2024-07-25 00:31:19.900 INFO --- liquibase.ui.LoggerUIService : Database is up to date, no changesets to execute 2024-07-25 00:32:22.591 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-25 00:33:34.596 INFO --- liquibase.util.ShowSummaryUtil : UPDATE SUMMARY 2024-07-25 00:33:34.596 INFO --- liquibase.util.ShowSummaryUtil : Run: 0 2024-07-25 00:33:34.596 INFO --- liquibase.util.ShowSummaryUtil : Previously run: 308 2024-07-25 00:33:34.596 INFO --- liquibase.util.ShowSummaryUtil : Filtered out: 3 2024-07-25 00:33:34.597 INFO --- liquibase.util.ShowSummaryUtil : ------------------------------- 2024-07-25 00:33:34.597 INFO --- liquibase.util.ShowSummaryUtil : Total change sets: 311 2024-07-25 00:33:34.597 INFO --- liquibase.util.ShowSummaryUtil : FILTERED CHANGE SETS SUMMARY 2024-07-25 00:33:34.597 INFO --- liquibase.util.ShowSummaryUtil : DBMS mismatch: 3 2024-07-25 00:33:51.799 INFO --- liquibase.util.ShowSummaryUtil : Update summary generated 2024-07-25 00:34:41.050 INFO --- l.l.StandardLockService : Successfully released change log lock 2024-07-25 00:34:41.051 INFO --- liquibase.command.CommandScope : Command execution complete 2024-07-25 00:34:57.630 INFO --- o.a.p.s.TaskSchedulingService : Task db-backup scheduled 2024-07-25 00:34:57.641 INFO --- o.a.p.service.DatabaseService : Automatic DB backup scheduled to run every 24 hour(s), starting at 2024-07-24T22:39:57.614921646Z 2024-07-25 00:34:57.978 INFO --- o.a.p.s.search.IndexManager : Index was found (index version 19). 2024-07-25 00:34:57.980 INFO --- o.a.p.s.TaskSchedulingService : Task mediascanner-IndexingTask scheduled 2024-07-25 00:34:57.981 INFO --- o.a.p.s.MediaScannerService : Automatic media library scanning scheduled to run every 1 day(s), starting at 2024-07-25T02:00:00.979517777 2024-07-25 00:35:00.775 WARN --- r$InitializeUserDetailsManagerConfigurer : Global AuthenticationManager configured with an AuthenticationProvider bean. UserDetailsService beans will not be used for username/password login. Consider removing the AuthenticationProvider bean. Alternatively, consider using the UserDetailsService in a manually instantiated DaoAuthenticationProvider. 2024-07-25 00:35:09.173 INFO --- org.airsonic.player.Application : Started Application in 30973.763 seconds (process running for 30974.337) 2024-07-25 00:35:09.253 INFO --- o.a.player.service.PlayerService : Deleting old players 2024-07-25 00:35:09.602 INFO --- o.a.player.service.PlayerService : Complete Deleting old players 2024-07-25 00:35:09.663 INFO --- o.a.p.s.PodcastManagementService : Automatic default Podcast update disabled for podcasts 2024-07-25 00:35:09.665 INFO --- o.a.p.s.TaskSchedulingService : Task remote-playstatus-cleanup scheduled 2024-07-25 00:39:57.626 INFO --- o.a.p.service.DatabaseService : Starting scheduled DB backup 2024-07-25 00:40:00.453 INFO --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database backed up to /var/airsonic/backups/db.backup.20240725003957 2024-07-25 00:40:00.453 INFO --- o.a.p.service.DatabaseService : Backed up DB to location: /var/airsonic/backups/db.backup.20240725003957 2024-07-25 00:40:00.497 INFO --- o.a.p.service.DatabaseService : Completed scheduled DB backup 2024-07-25 02:00:01.039 INFO --- o.a.p.s.MediaScannerService : Starting media library scan with

bartmans commented 1 month ago

But on restart the same behaviour unfortunately.

bartmans commented 1 month ago

Yep it took the same time but eventually AS started. I then used a DB from backup from 5 days ago. Same error. I then deleted the db directoy and let AS start without. Same error. Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL TLS-SRP UnixSockets zstd PATH=/opt/java/openjdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin CONTEXTPATH=/
/\ () ()
/ \ _
/ /\ \ | | '|/ |/ | ' | |/ |
/ __ | | | __ \ () | | | | | (
// __|| |/\/|| ||_|___|

2024-07-26 09:37:20.700 DEBUG --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database backup not required for driver version 2.7.3 connecting (and if needed, upgrading) DB version 2.7 2024-07-26 09:37:20.709 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var) 2024-07-26 09:37:20.710 DEBUG --- org.airsonic.player.Application : Running with Spring Boot v3.3.2, Spring v6.1.11 2024-07-26 09:37:20.712 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default" 2024-07-26 09:37:40.874 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296 2024-07-26 09:37:41.775 INFO --- org.airsonic.player.Application : Detected Tomcat web server 2024-07-26 09:37:41.775 DEBUG --- org.airsonic.player.Application : Attempting to optimize tomcat 2024-07-26 09:37:41.776 DEBUG --- org.airsonic.player.Application : Tomcat optimizations complete 2024-07-26 09:38:59.628 INFO --- l.database.core.HsqlDatabase : Set default schema name to PUBLIC Docker USER id: 0 Docker PUID env: 1026 Docker USER group: 0 Docker PGID env: 100 usermod: no changes Process will run as: User: 1026 Group: 100 openjdk 17.0.10 2024-01-16 OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7) OpenJDK 64-Bit Server VM Temurin-17.0.10+7 (build 17.0.10+7, mixed mode, sharing) JAVA_OPTS=-Xmx4096M -Dserver.forward-headers-strategy=NATIVE -Dlogging.level.org.airsonic=DEBUG ffmpeg version 4.4.2-0ubuntu0.22.04.1 Copyright (c) 2000-2021 the FFmpeg developers built with gcc 11 (Ubuntu 11.2.0-19ubuntu1) configuration: --prefix=/usr --extra-version=0ubuntu0.22.04.1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared libavutil 56. 70.100 / 56. 70.100 libavcodec 58.134.100 / 58.134.100 libavformat 58. 76.100 / 58. 76.100 libavdevice 58. 13.100 / 58. 13.100 libavfilter 7.110.100 / 7.110.100 libswscale 5. 9.100 / 5. 9.100 libswresample 3. 9.100 / 3. 9.100 libpostproc 55. 9.100 / 55. 9.100 curl 7.81.0 (x86_64-pc-linux-gnu) libcurl/7.81.0 OpenSSL/3.0.2 zlib/1.2.11 brotli/1.0.9 zstd/1.4.8 libidn2/2.3.2 libpsl/0.21.0 (+libidn2/2.3.2) libssh/0.9.6/openssl/zlib nghttp2/1.43.0 librtmp/2.3 OpenLDAP/2.5.17 Release-Date: 2022-01-05 Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL TLS-SRP UnixSockets zstd PATH=/opt/java/openjdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin CONTEXTPATH=/
/\ () ()
/ \ _
/ /\ \ | | '|/ |/ | ' | |/ |
/ __ | | | __ \ () | | | | | (
// __|| |/\/|| ||_|___|

2024-07-26 09:42:27.853 WARN --- o.a.p.u.LegacyHsqlMigrationUtil : Failed to determine HSQLDB database version java.io.FileNotFoundException: /var/airsonic/db/airsonic.properties at org.springframework.core.io.FileSystemResource.getInputStream(FileSystemResource.java:196) ~[spring-core-6.1.11.jar:6.1.11] at org.springframework.core.io.support.PropertiesLoaderUtils.fillProperties(PropertiesLoaderUtils.java:134) ~[spring-core-6.1.11.jar:6.1.11] at org.springframework.core.io.support.PropertiesLoaderUtils.loadProperties(PropertiesLoaderUtils.java:123) ~[spring-core-6.1.11.jar:6.1.11] at org.airsonic.player.util.LegacyHsqlMigrationUtil.getHsqlDbVersion(LegacyHsqlMigrationUtil.java:32) ~[classes/:na] at org.airsonic.player.util.LegacyHsqlMigrationUtil.isHsqlDbBackupNeeded(LegacyHsqlMigrationUtil.java:64) ~[classes/:na] at org.airsonic.player.util.LegacyHsqlMigrationUtil.upgradeFileHsqlDbIfNeeded(LegacyHsqlMigrationUtil.java:158) ~[classes/:na] at org.airsonic.player.spring.StartupEventListener.onApplicationEvent(StartupEventListener.java:17) ~[classes/:na] at org.airsonic.player.spring.StartupEventListener.onApplicationEvent(StartupEventListener.java:1) ~[classes/:na] at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:185) ~[spring-context-6.1.11.jar:6.1.11] at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:178) ~[spring-context-6.1.11.jar:6.1.11] at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:156) ~[spring-context-6.1.11.jar:6.1.11] at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:138) ~[spring-context-6.1.11.jar:6.1.11] at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.context.event.EventPublishingRunListener.contextPrepared(EventPublishingRunListener.java:87) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.SpringApplicationRunListeners.lambda$contextPrepared$3(SpringApplicationRunListeners.java:68) ~[spring-boot-3.3.2.jar:3.3.2] at java.base/java.lang.Iterable.forEach(Unknown Source) ~[na:na] at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.SpringApplicationRunListeners.contextPrepared(SpringApplicationRunListeners.java:68) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.SpringApplication.prepareContext(SpringApplication.java:402) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.SpringApplication.run(SpringApplication.java:334) ~[spring-boot-3.3.2.jar:3.3.2] at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:149) ~[spring-boot-3.3.2.jar:3.3.2] at org.airsonic.player.Application.main(Application.java:74) ~[classes/:na] 2024-07-26 09:42:27.872 DEBUG --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database not found, won't back up 2024-07-26 09:42:27.881 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var) 2024-07-26 09:42:27.882 DEBUG --- org.airsonic.player.Application : Running with Spring Boot v3.3.2, Spring v6.1.11 2024-07-26 09:42:27.884 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default" 2024-07-26 09:42:33.233 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296 2024-07-26 09:42:33.589 INFO --- org.airsonic.player.Application : Detected Tomcat web server 2024-07-26 09:42:33.590 DEBUG --- org.airsonic.player.Application : Attempting to optimize tomcat 2024-07-26 09:42:33.591 DEBUG --- org.airsonic.player.Application : Tomcat optimizations complete 2024-07-26 09:43:45.259 INFO --- l.database.core.HsqlDatabase : Set default schema name to PUBLIC

bartmans commented 1 month ago

What is the previou PR build? If that one works, it pretty much points to something in the new image and my setup.

bartmans commented 1 month ago

PR-532 works. Docker USER id: 0 Docker PUID env: 1026 Docker USER group: 0 Docker PGID env: 100 Process will run as: User: 1026 Group: 100 openjdk 17.0.10 2024-01-16 OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7) OpenJDK 64-Bit Server VM Temurin-17.0.10+7 (build 17.0.10+7, mixed mode, sharing) JAVA_OPTS=-Xmx4096M -Dserver.forward-headers-strategy=NATIVE -Dlogging.level.org.airsonic=DEBUG ffmpeg version 4.4.2-0ubuntu0.22.04.1 Copyright (c) 2000-2021 the FFmpeg developers built with gcc 11 (Ubuntu 11.2.0-19ubuntu1) configuration: --prefix=/usr --extra-version=0ubuntu0.22.04.1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared libavutil 56. 70.100 / 56. 70.100 libavcodec 58.134.100 / 58.134.100 libavformat 58. 76.100 / 58. 76.100 libavdevice 58. 13.100 / 58. 13.100 libavfilter 7.110.100 / 7.110.100 libswscale 5. 9.100 / 5. 9.100 libswresample 3. 9.100 / 3. 9.100 libpostproc 55. 9.100 / 55. 9.100 curl 7.81.0 (x86_64-pc-linux-gnu) libcurl/7.81.0 OpenSSL/3.0.2 zlib/1.2.11 brotli/1.0.9 zstd/1.4.8 libidn2/2.3.2 libpsl/0.21.0 (+libidn2/2.3.2) libssh/0.9.6/openssl/zlib nghttp2/1.43.0 librtmp/2.3 OpenLDAP/2.5.17 Release-Date: 2022-01-05 Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL TLS-SRP UnixSockets zstd PATH=/opt/java/openjdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin CONTEXTPATH=/
/\ () ()
/ \ _
/ /\ \ | | '|/ |/ | ' | |/ |
/ __ | | | __ \ () | | | | | (
// __|| |/\/|| ||_|___|

2024-07-26 13:14:34.489 DEBUG --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database backup not required for driver version 2.7.3 connecting (and if needed, upgrading) DB version 2.7 2024-07-26 13:14:34.498 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var) 2024-07-26 13:14:34.499 DEBUG --- org.airsonic.player.Application : Running with Spring Boot v3.3.1, Spring v6.1.10 2024-07-26 13:14:34.501 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default" 2024-07-26 13:14:56.112 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296 2024-07-26 13:14:57.070 INFO --- org.airsonic.player.Application : Detected Tomcat web server 2024-07-26 13:14:57.070 DEBUG --- org.airsonic.player.Application : Attempting to optimize tomcat 2024-07-26 13:14:57.072 DEBUG --- org.airsonic.player.Application : Tomcat optimizations complete 2024-07-26 13:15:08.623 INFO --- l.database.core.HsqlDatabase : Set default schema name to PUBLIC 2024-07-26 13:15:14.619 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-26 13:15:14.991 INFO --- l.l.StandardLockService : Successfully acquired change log lock 2024-07-26 13:15:14.995 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-26 13:15:15.053 INFO --- l.l.StandardLockService : Successfully released change log lock 2024-07-26 13:15:15.055 INFO --- liquibase.command.CommandScope : Command execution complete 2024-07-26 13:15:16.108 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-26 13:15:16.310 INFO --- liquibase.ui.LoggerUIService : Database is up to date, no changesets to execute 2024-07-26 13:15:16.314 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-26 13:15:16.349 INFO --- liquibase.util.ShowSummaryUtil : UPDATE SUMMARY 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : Run: 0 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : Previously run: 308 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : Filtered out: 3 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : ------------------------------- 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : Total change sets: 311 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : FILTERED CHANGE SETS SUMMARY 2024-07-26 13:15:16.350 INFO --- liquibase.util.ShowSummaryUtil : DBMS mismatch: 3 2024-07-26 13:15:16.355 INFO --- liquibase.util.ShowSummaryUtil : Update summary generated 2024-07-26 13:15:16.713 INFO --- l.l.StandardLockService : Successfully released change log lock 2024-07-26 13:15:16.714 INFO --- liquibase.command.CommandScope : Command execution complete 2024-07-26 13:15:31.543 INFO --- o.a.p.s.TaskSchedulingService : Task db-backup scheduled 2024-07-26 13:15:31.544 INFO --- o.a.p.service.DatabaseService : Automatic DB backup scheduled to run every 24 hour(s), starting at 2024-07-26T11:20:31.538400314Z 2024-07-26 13:15:31.769 INFO --- o.a.p.s.search.IndexManager : Index was found (index version 19). 2024-07-26 13:15:31.776 INFO --- o.a.p.s.TaskSchedulingService : Task mediascanner-IndexingTask scheduled 2024-07-26 13:15:31.777 INFO --- o.a.p.s.MediaScannerService : Automatic media library scanning scheduled to run every 1 day(s), starting at 2024-07-27T02:00:00.770212849 2024-07-26 13:15:35.495 WARN --- r$InitializeUserDetailsManagerConfigurer : Global AuthenticationManager configured with an AuthenticationProvider bean. UserDetailsService beans will not be used for username/password login. Consider removing the AuthenticationProvider bean. Alternatively, consider using the UserDetailsService in a manually instantiated DaoAuthenticationProvider. 2024-07-26 13:15:43.324 INFO --- org.airsonic.player.Application : Started Application in 79.646 seconds (process running for 96.244) 2024-07-26 13:15:43.359 INFO --- o.a.player.service.PlayerService : Deleting old players 2024-07-26 13:15:43.613 INFO --- o.a.player.service.PlayerService : Complete Deleting old players 2024-07-26 13:15:43.692 INFO --- o.a.p.s.PodcastManagementService : Automatic default Podcast update disabled for podcasts 2024-07-26 13:15:43.700 INFO --- o.a.p.s.TaskSchedulingService : Task remote-playstatus-cleanup scheduled

kagemomiji commented 1 month ago

@bartmans Could you try ghcr.io/kagemomiji/airsonic-advanced:edge-11.1.4-SNAPSHOT.20240722222158? It is the previous edge image.

bartmans commented 1 month ago

Previous edge ghcr.io/kagemomiji/airsonic-advanced:edge-11.1.4-SNAPSHOT.20240722222158 works.

kagemomiji commented 1 month ago

@bartmans The most likely reason is the upgrade Spring Boot to v3.3.2. Since it seems an issue related to Liquibase from your logs, could you please try the image from ghcr.io/kagemomiji/airsonic-advanced:pr-554 which includes updates related to Liquibase?

bartmans commented 1 month ago

No pr-554 won't boot so most likely causing trouble.

kagemomiji commented 1 month ago

@bartmans I have created the image which spring boot is downgraded to v3.3.1. Colud you try it? ghcr.io/kagemomiji/airsonic-advanced:pr-555

bartmans commented 1 month ago

Pr-555 won't boot.

kagemomiji commented 1 month ago

@bartmans I have built pr-555 which org.eclipse.persistence.moxy is downgraded to v4.0.3. Could you pull pr-555 again and try?

bartmans commented 1 month ago

No still won''t boot. There is a definitie delay after the Tomcat stuff. When compared to last working build and this one.

2024-07-29 09:05:57.875 DEBUG --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database backup not required for driver version 2.7.3 connecting (and if needed, upgrading) DB version 2.7 2024-07-29 09:05:57.908 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var) 2024-07-29 09:05:57.910 DEBUG --- org.airsonic.player.Application : Running with Spring Boot v3.3.2, Spring v6.1.11 2024-07-29 09:05:57.915 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default" 2024-07-29 09:06:05.439 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296 2024-07-29 09:06:05.883 INFO --- org.airsonic.player.Application : Detected Tomcat web server 2024-07-29 09:06:05.884 DEBUG --- org.airsonic.player.Application : Attempting to optimize tomcat 2024-07-29 09:06:05.887 DEBUG --- org.airsonic.player.Application : Tomcat optimizations complete 2024-07-29 09:09:52.001 INFO --- l.database.core.HsqlDatabase : Set default schema name to PUBLIC 2024-07-29 09:11:00.930 DEBUG --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database backup not required for driver version 2.7.3 connecting (and if needed, upgrading) DB version 2.7 2024-07-29 09:11:00.941 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var) 2024-07-29 09:11:00.943 DEBUG --- org.airsonic.player.Application : Running with Spring Boot v3.3.2, Spring v6.1.11 2024-07-29 09:11:00.948 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default" 2024-07-29 09:11:08.319 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296 2024-07-29 09:11:08.770 INFO --- org.airsonic.player.Application : Detected Tomcat web server 2024-07-29 09:11:08.771 DEBUG --- org.airsonic.player.Application : Attempting to optimize tomcat 2024-07-29 09:11:08.773 DEBUG --- org.airsonic.player.Application : Tomcat optimizations complete 2024-07-29 09:13:31.508 DEBUG --- o.a.p.u.LegacyHsqlMigrationUtil : HSQLDB database backup not required for driver version 2.7.3 connecting (and if needed, upgrading) DB version 2.7 2024-07-29 09:13:31.524 INFO --- org.airsonic.player.Application : Starting Application using Java 17.0.10 with PID 1 (/app/WEB-INF/classes started by au in /var) 2024-07-29 09:13:31.528 DEBUG --- org.airsonic.player.Application : Running with Spring Boot v3.3.1, Spring v6.1.10 2024-07-29 09:13:31.531 INFO --- org.airsonic.player.Application : No active profile set, falling back to 1 default profile: "default" 2024-07-29 09:13:38.624 INFO --- o.a.p.service.SettingsService : Java: 17.0.10+7, OS: Linux, Memory (max bytes): 4294967296 2024-07-29 09:13:39.004 INFO --- org.airsonic.player.Application : Detected Tomcat web server 2024-07-29 09:13:39.005 DEBUG --- org.airsonic.player.Application : Attempting to optimize tomcat 2024-07-29 09:13:39.006 DEBUG --- org.airsonic.player.Application : Tomcat optimizations complete 2024-07-29 09:13:43.796 INFO --- l.database.core.HsqlDatabase : Set default schema name to PUBLIC 2024-07-29 09:13:47.240 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-29 09:13:47.654 INFO --- l.l.StandardLockService : Successfully acquired change log lock 2024-07-29 09:13:47.660 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-29 09:13:47.724 INFO --- l.l.StandardLockService : Successfully released change log lock 2024-07-29 09:13:47.727 INFO --- liquibase.command.CommandScope : Command execution complete 2024-07-29 09:13:49.015 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-29 09:13:49.255 INFO --- liquibase.ui.LoggerUIService : Database is up to date, no changesets to execute 2024-07-29 09:13:49.265 INFO --- l.c.StandardChangeLogHistoryService : Reading from PUBLIC.DATABASECHANGELOG 2024-07-29 09:13:49.328 INFO --- liquibase.util.ShowSummaryUtil : UPDATE SUMMARY 2024-07-29 09:13:49.329 INFO --- liquibase.util.ShowSummaryUtil : Run: 0 2024-07-29 09:13:49.332 INFO --- liquibase.util.ShowSummaryUtil : Previously run: 308 2024-07-29 09:13:49.335 INFO --- liquibase.util.ShowSummaryUtil : Filtered out: 3 2024-07-29 09:13:49.336 INFO --- liquibase.util.ShowSummaryUtil : ------------------------------- 2024-07-29 09:13:49.336 INFO --- liquibase.util.ShowSummaryUtil : Total change sets: 311 2024-07-29 09:13:49.336 INFO --- liquibase.util.ShowSummaryUtil : FILTERED CHANGE SETS SUMMARY 2024-07-29 09:13:49.336 INFO --- liquibase.util.ShowSummaryUtil : DBMS mismatch: 3 2024-07-29 09:13:49.341 INFO --- liquibase.util.ShowSummaryUtil : Update summary generated 2024-07-29 09:13:49.435 INFO --- l.l.StandardLockService : Successfully released change log lock 2024-07-29 09:13:49.436 INFO --- liquibase.command.CommandScope : Command execution complete 2024-07-29 09:13:58.710 INFO --- o.a.p.s.TaskSchedulingService : Task db-backup scheduled 2024-07-29 09:13:58.712 INFO --- o.a.p.service.DatabaseService : Automatic DB backup scheduled to run every 24 hour(s), starting at 2024-07-29T07:18:58.704169145Z 2024-07-29 09:13:58.940 INFO --- o.a.p.s.search.IndexManager : Index was found (index version 19). 2024-07-29 09:13:58.942 INFO --- o.a.p.s.TaskSchedulingService : Task mediascanner-IndexingTask scheduled 2024-07-29 09:13:58.943 INFO --- o.a.p.s.MediaScannerService : Automatic media library scanning scheduled to run every 1 day(s), starting at 2024-07-30T02:00:00.941293119 2024-07-29 09:14:01.197 WARN --- r$InitializeUserDetailsManagerConfigurer : Global AuthenticationManager configured with an AuthenticationProvider bean. UserDetailsService beans will not be used for username/password login. Consider removing the AuthenticationProvider bean. Alternatively, consider using the UserDetailsService in a manually instantiated DaoAuthenticationProvider. 2024-07-29 09:14:06.241 INFO --- org.airsonic.player.Application : Started Application in 37.375 seconds (process running for 40.313) 2024-07-29 09:14:06.279 INFO --- o.a.player.service.PlayerService : Deleting old players 2024-07-29 09:14:06.477 INFO --- o.a.player.service.PlayerService : Complete Deleting old players 2024-07-29 09:14:06.522 INFO --- o.a.p.s.PodcastManagementService : Automatic default Podcast update disabled for podcasts 2024-07-29 09:14:06.525 INFO --- o.a.p.s.TaskSchedulingService : Task remote-playstatus-cleanup scheduled

kagemomiji commented 1 month ago

@bartmans I need more detail, could you add -Dlogging.level.liquibase=DEBUG to JAVA_OPT? I don't have Synology Docker environment, so I have not reproduced your issue yet.

bartmans commented 1 month ago

No problem happy to provide. This is with PR-555 and extra debugging: I will leave this running until it eventually boots and (re)post the logs. Edit: [https://gist.github.com/bartmans/9926d0d094ca8d506b343a72f65ff635]

bartmans commented 1 month ago

Still not finished: https://gist.github.com/bartmans/9926d0d094ca8d506b343a72f65ff635

Finished, complete logs in the gist. Once running AS performs just like regular, responsive & fast.

bartmans commented 2 weeks ago

Problem is still present in recent edge releases. With my limited knowledge I googled and came up with: https://github.com/liquibase/liquibase/issues/6178

I know from other Dockers that Synology hardware has issues with randomization: https://mariushosting.com/synology-common-docker-issues-and-fixes/ (point 11)

That would make the cause https://github.com/kagemomiji/airsonic-advanced/pull/552

kagemomiji commented 1 week ago

@bartmans Thank you for looking into this.

I have created a version with the targeted library downgraded.

Please pull the image from ghcr.io/kagemomiji/airsonic-advance:pr-555 again and give it a try.

bartmans commented 1 week ago

Yes, PR 555 works like its supposed to. Startup is quick again!

I think this is fixed in 3.16.0 of org.apache.commons:commons-lang3 https://issues.apache.org/jira/browse/LANG-1745 https://commons.apache.org/proper/commons-lang/changes-report.html#a3.16.0

kagemomiji commented 1 week ago

@bartmans The latest edge-release includes version 3.16.0 of Library org.apache.commons:commons-lang3. Is everything working as expected?

bartmans commented 1 week ago

No :latest is a slow starter. So the new version of org.apache.commons:commons-lang3 doesn't include a fix.

I can help raising an issue, not sure how to do this.

kagemomiji commented 1 week ago

@bartmans I will release version with org.apache.commons:commons-lang3 downgraded. The issue is addressed in the next version of Liquibase, and we will upgrade it along with that release. If the same issue occurs after upgrading Liquibase, please open a new issue.