search

kagemomiji / airsonic-advanced

airsonic-advanced
GNU General Public License v3.0
175 stars 15 forks source link

Failed to obtain JDBC Connection; ....... Connection is not available, request timed out after 30000ms #86

Open litebito opened 1 year ago

litebito commented 1 year ago

(cross post from https://github.com/airsonic-advanced/airsonic-advanced/issues/969 as requested) Since upgrading to 11.0.2.20230116143321 – January 16, 2023 at 3:33:21 PM CET (version from https://github.com/kagemomiji/airsonic-advanced)

I see the following error in the airsonic.log regularly (about every minute or 2 when airsonic is refreshing or rescanning

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. Steps to reproduce

Install version 11.0.2.20230116143321 – January 16, 2023 at 3:33:21 PM CET (version from https://github.com/kagemomiji/airsonic-advanced)
Rescan media folders
look at airsonic.log

System information

Airsonic version:
11.0.2.20230116143321
Operating system:
CentOS 7.9
Java version:
openjdk version "18.0.2" 2022-07-19
OpenJDK Runtime Environment 21.9 (build 18.0.2+9)
OpenJDK 64-Bit Server VM 21.9 (build 18.0.2+9, mixed mode, sharing)
Proxy server: None
Client: Firefox 109.0
kagemomiji commented 1 year ago

@litebito

I am confused because 11.0.2.20230116143321 has not been released. So could you tell me the commit hash you use.

And also I want the following information.

  1. your database type(mysql, postgresql, etc) and version
  2. your execution parameter
litebito commented 1 year ago

Hi, is this the info you are looking for? Commit hash : https://github.com/kagemomiji/airsonic-advanced/commit/d37ed15c99087c7a6e19d108bad364d22b61a196 Version 11.0.2.20230116143321 – January 16, 2023 at 3:33:21 PM CET [Commit: d37ed15c99087c7a6e19d108bad364d22b61a196]

  1. I'm using the internal database image
  2. execution parameters:

/usr/bin/java -Xmx2048m -Xms2048m -Dairsonic.home=/var/airsonic -Dserver.servlet.contextPath=/ -Dserver.port=14040 -Dfile.encoding=UTF-8 -Dsun.jnu.encoding=UTF-8

Or from /etc/sysconfig/airsonic

# Set the location of the standalone war to use
JAVA_JAR=/var/airsonic/airsonic.war

# Set any java opts separated by spaces
JAVA_OPTS=-Xmx2048m -Xms2048m 

# Set a different location for airsonic home.
# If this path is /var/libresonic or even contains "libresonic",
# the data from a previous libresonic can be used as is (i.e. without
# renaming libresonic.properties,db/libresonic*,etc
AIRSONIC_HOME=/var/airsonic

# Change the port to listen on
PORT=14040

# Change the path that is listened on
CONTEXT_PATH=/

# Add any java args. These are different than JAVA_OPTS in that
# they are passed directly to the program. The default is empty:
#JAVA_ARGS=

# Note that there are several settings for spring boot, not explicitly listed
# here, but can be used in either JAVA_OPTS or JAVA_ARGS. The full list
# can be found here:
# https://docs.spring.io/spring-boot/docs/1.4.5.RELEASE/reference/htmlsingle/#common-application-properties
# For example to set debug across the board:
#JAVA_ARGS=--debug

JAVA_ARGS=--logging.level.org.airsonic=info
kagemomiji commented 1 year ago

@litebito I tried to reproduce your problem, but could not. Could you set JAVA_ARGS=--logging.level.org.airsonic=debug and upload airsonic.log text

The-Exterminator commented 1 year ago

Try to downgrade you Java version to 11 or 12 first

litebito commented 1 year ago

@kagemomiji You probably can close this issue, I have not seen this in the logs for some time now. It may have been resolved by one of the various upgrades on the server...

litebito commented 1 year ago

I spoke too soon ...... 

2023-05-01 13:53:18.544  WARN --- o.h.e.j.spi.SqlExceptionHelper           : SQL Error: 0, SQLState: null
2023-05-01 13:53:18.545 ERROR --- o.h.e.j.spi.SqlExceptionHelper           : HikariPool-1 - Connection is not available, request timed out after 30000ms.
2023-05-01 13:53:18.592  WARN --- o.h.e.j.spi.SqlExceptionHelper           : SQL Error: 0, SQLState: null
2023-05-01 13:53:18.592 ERROR --- o.h.e.j.spi.SqlExceptionHelper           : HikariPool-1 - Connection is not available, request timed out after 30000ms.
2023-05-01 13:53:18.594  WARN --- o.h.e.j.spi.SqlExceptionHelper           : SQL Error: 0, SQLState: null
2023-05-01 13:53:18.594 ERROR --- o.h.e.j.spi.SqlExceptionHelper           : HikariPool-1 - Connection is not available, request timed out after 30000ms.

suddenly lots of the above ...................................

2023-05-01 14:00:21.689  WARN --- o.a.p.service.PlaylistService            : File in playlist '(b) My Musicals.m3u' not found: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
2023-05-01 14:00:21.689  WARN --- o.a.p.service.PlaylistService            : File in playlist '(b) My Musicals.m3u' not found: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
2023-05-01 14:00:28.192  WARN --- o.h.e.j.spi.SqlExceptionHelper           : SQL Error: 0, SQLState: null

I've a feeling this starts to appear after a while, when the airsonic server has been seeing a lot of activity (importing, cleaning, deleting)

Is this related to an issue like this?: https://stackoverflow.com/questions/65532078/hikaripool-connection-not-available-after-long-i-o-operation-for-concurrent-requ

kagemomiji commented 1 year ago

@litebito Regarding #215, I noticed that you have set the Do a full scan parameter to true, which could result in excessive disk and DB accesses. Could you set it to false from Settings -> media folders page.

litebito commented 1 year ago

Hi,

I indeed set to do a full scan, but at 4am in the morning image that is to compensate for files or playlists which gave an error during smart scans (when I add or update files/playlists, it only imports or updates those in the database, that is still a smartscan, no?) If a file fails to be imported during a smartscan, it will not try it again, as it would not be newer than the latest smartscan, no?

Or am misinterpreting this setting?

kagemomiji commented 1 year ago

@litebito

Here is my understanding of the behavior of library scan and the "Do a full scan" option. Is it same with you?

Do a full scan is a system-wide option, so whether you manually execute a library scan or execute it through a scheduled job, the behavior will be the same.

If you disable the "Do a full scan" option, Airsonic will only register files to the database that are not yet registered . Enabling the option will trigger a comparison between the database and the files on disk, and if any changes are detected, the database information will be updated accordingly.

litebito commented 1 year ago

@litebito

Here is my understanding of the behavior of library scan and the "Do a full scan" option. Is it same with you?

Do a full scan is a system-wide option, so whether you manually execute a library scan or execute it through a scheduled job, the behavior will be the same.

If you disable the "Do a full scan" option, Airsonic will only register files to the database that are not yet registered . Enabling the option will trigger a comparison between the database and the files on disk, and if any changes are detected, the database information will be updated accordingly.

Hi,

so I thought it worked like this, if full scan is enabled:

kagemomiji commented 1 year ago

@litebito

There are two other scanning mechanisms.

  1. If you disable the "Fast access mode", when you access certain albums, artists, folders and tracks, a library scanning will be performed under the folder.
  2. if you edit some playlist files in the Playlist folder, the playlist will be reloaded automatically.
litebito commented 7 months ago

Hi,

don't know if this ever can be solved, but I'm still seeing these timeouts, even with the version of today

2024-04-07 17:21:44.539 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:21:44.539 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:21:48.187 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:21:48.187 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:21:51.134 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:21:51.134 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:21:51.156 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:21:51.156 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:21:51.157 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:21:51.157 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:21:55.177 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:21:55.177 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:00.290 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:00.290 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:00.309 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:00.309 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:03.496 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:03.496 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:06.836 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:06.836 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:13.056 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:13.056 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:16.195 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:16.196 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:25.482 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:25.482 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:25.487 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2024-04-07 17:22:25.488 ERROR --- o.h.e.j.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms. 2024-04-07 17:22:28.429 WARN --- o.h.e.j.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null

kagemomiji commented 7 months ago

@litebito

If possible, could you provide the airsonic.log from startup until the issue occurs? Having information before the error occurs could help in identifying the cause.