search

epoupon / lms

Lightweight Music Server. Access your self-hosted music using a web interface.
http://lms-demo.poupon.dev
GNU General Public License v3.0
1.15k stars 62 forks source link

3.30.0 crashes #249

Closed abdulocracy closed 2 years ago

abdulocracy commented 2 years ago

I'm running 3.30.0 on Docker x64.

It crashes with the following logs repeatedly:

lms  | ARG = /usr/bin/lms
lms  | ARG = --config=/var/lms/wt_config.xml
lms  | ARG = --docroot=/usr/share/lms/docroot/;/resources,/css,/images,/js,/favicon.ico
lms  | ARG = --approot=/usr/share/lms/approot
lms  | ARG = --deploy-path=/
lms  | ARG = --resources-dir=/usr/share/Wt/resources
lms  | ARG = --http-port=5082
lms  | ARG = --http-address=0.0.0.0
lms  | ARG = --threads=24
lms  | [2022-Jul-08 07:28:15.132] 1 - [info] "config: reading Wt config file: /var/lms/wt_config.xml (location = '/usr/bin/lms')"
lms  | [2022-Jul-08 07:28:15.132] 1 - [warning] "config: The behind-reverse-proxy configuration option is deprecated, use a <trusted-proxy-config> block instead"
lms  | [2022-Jul-08 07:28:15.133] 1 - [info] - [UTILS] Starting IO context with 24 threads...
lms  | [2022-Jul-08 07:28:15.134] 1 - [info] - [DB] Creating connection pool on file /var/lms/lms.db
lms  | [2022-Jul-08 07:28:15.164] 1 - [error] - [DB] Cannot create tables: Sqlite3: create table "cluster_type" (
lms  |   "id" integer primary key autoincrement,
lms  |   "version" integer not null,
lms  |   "name" text not null,
lms  |   "scan_settings_id" bigint,
lms  |   constraint "fk_cluster_type_scan_settings" foreign key ("scan_settings_id") references "scan_settings" ("id") on delete cascade deferrable initially deferred
lms  | ): table "cluster_type" already exists
lms  | [2022-Jul-08 07:28:15.165] 1 - [info] - [DB] Database version = 36, LMS binary version = 36
lms  | [2022-Jul-08 07:28:15.267] 1 - [info] - [COVER] JPEG export quality = 75
lms  | [2022-Jul-08 07:28:15.267] 1 - [info] - [COVER] Default cover path = '/usr/share/lms/approot//images/unknown-cover.jpg'
lms  | [2022-Jul-08 07:28:15.267] 1 - [info] - [COVER] Max cache size = 30000000
lms  | [2022-Jul-08 07:28:15.267] 1 - [info] - [COVER] Max file size = 10000000
lms  | [2022-Jul-08 07:28:15.267] 1 - [info] - [COVER] Preferred file names: cover,front
lms  | [2022-Jul-08 07:28:15.289] 1 - [info] - [DB UPDATER] skipDuplicateRecordingMBID = 0
lms  | [2022-Jul-08 07:28:15.289] 1 - [info] - [DB UPDATER] Using scan settings version 17
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [SCROBBLING] Starting service...
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [RECOMMENDATION] Reloading recommendation engines...
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [SCROBBLING] [listenbrainz] - Starting Listens synchronizer, maxSyncListenCount = 1000, _syncListensPeriod = 1 hours
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [SCROBBLING] [listenbrainz] - Starting Feedbacks synchronizer, maxSyncFeedbackCount = 1000, _syncFeedbacksPeriod = 1 hours
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [SCROBBLING] [listenbrainz] - Starting ListenBrainz scrobbler... API endpoint = 'https://api.listenbrainz.org'
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [SCROBBLING] Service started!
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] - [MAIN] Starting server...
lms  | [2022-Jul-08 07:28:15.290] 1 - [info] "WServer/wthttp: initializing built-in wthttpd"
lms  | [2022-Jul-08 07:28:15.291] 1 - [info] - [RECOMMENDATION] Initializing engine 'clusters'...
lms  | [2022-Jul-08 07:28:15.291] 1 - [info] - [RECOMMENDATION] Initializing engine 'clusters': complete
lms  | [2022-Jul-08 07:28:15.291] 1 - [info] - [RECOMMENDATION] Recommendation engines loaded!
lms  | [2022-Jul-08 07:28:15.291] 1 - [info] - [DB UPDATER] Scheduling next scan
lms  | [2022-Jul-08 07:28:15.291] 1 - [info] - [DB UPDATER] Using scan settings version 17
lms  | [2022-Jul-08 07:28:15.291] 1 - [info] - [DB UPDATER] Scheduling next scan at Sat Jul  9 06:00:00 2022
lms  |
lms  | [2022-Jul-08 07:28:15.293] 1 - [info] "wthttp: started server: http://0.0.0.0:5082"
lms  | [2022-Jul-08 07:28:15.293] 1 - [info] - [MAIN] Now running...
lms  | [2022-Jul-08 07:28:17.612] 1 - [info] "Wt: session created (#sessions = 1)"
lms  | [2022-Jul-08 07:28:17.613] 1 [/ kVFeERffeeABGohz] [info] "WEnvironment: UserAgent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0"
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.614] "GET /releases HTTP/1.1" 200 2352
lms  | [2022-Jul-08 07:28:17.640] 1 [/ kVFeERffeeABGohz] [warning] "WApplication: WApplication::addMetaHeader() with no effect"
lms  | [2022-Jul-08 07:28:17.649] 1 [/ kVFeERffeeABGohz] [info] - [UI] User 'abdulkadir' logged in from '83.5.235.110', user agent = Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.916] "GET /releases?wtd=kVFeERffeeABGohz&request=style&page=1 HTTP/1.1" 200 114
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.926] "GET /resources/moz-transitions.css HTTP/1.1" 200 6277
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.927] "GET /css/lms.css HTTP/1.1" 200 2040
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.927] "GET /css/bootstrap.solar.min.css HTTP/1.1" 200 180862
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.927] "GET /resources/font-awesome/css/font-awesome.min.css HTTP/1.1" 200 23739
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:17.940] "GET /releases?wtd=kVFeERffeeABGohz&sid=3149564612&webGL=true&scrW=960&scrH=600&tz=120&tzS=Europe%2FWarsaw&htmlHistory=true&deployPath=%2F&request=script&rand=4189403577 HTTP/1.1" 200 43364
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.135] "GET /js/bootstrap.bundle.min.js HTTP/1.1" 200 78129
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.162] "GET /js/mediaplayer.js HTTP/1.1" 200 9778
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.183] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 0
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.202] "GET /favicon.ico HTTP/1.1" 404 85
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.221] "GET /resources/font-awesome/fonts/fontawesome-webfont.woff2?v=4.3.0 HTTP/1.1" 200 56780
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.293] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4467&size=512 HTTP/1.1" 200 59253
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.361] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3265&size=512 HTTP/1.1" 200 17583
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.366] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4397&size=512 HTTP/1.1" 200 55733
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.369] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4034&size=512 HTTP/1.1" 200 41788
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.375] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4335&size=512 HTTP/1.1" 200 34003
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.382] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 8018
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.425] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3950&size=512 HTTP/1.1" 200 32783
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.447] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4105&size=128 HTTP/1.1" 200 4826
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.498] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4084&size=128 HTTP/1.1" 200 5340
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.534] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3235&size=128 HTTP/1.1" 200 4161
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.563] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4008&size=128 HTTP/1.1" 200 4672
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.626] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4284&size=128 HTTP/1.1" 200 5370
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.641] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4296&size=128 HTTP/1.1" 200 2586
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.642] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4728&size=512 HTTP/1.1" 200 51374
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.649] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3643&size=512 HTTP/1.1" 200 15186
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.655] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4274&size=128 HTTP/1.1" 200 2917
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.685] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 1709
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.716] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4450&size=512 HTTP/1.1" 200 31321
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.738] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4720&size=512 HTTP/1.1" 200 61474
lms  | [2022-Jul-08 07:28:18.740] 1 - [error] "Http::ResponseContinuation: WebWriteEvent::Error"
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.789] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3898&size=512 HTTP/1.1" 200 36974
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.793] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3071&size=512 HTTP/1.1" 200 37095
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.794] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4274&size=512 HTTP/1.1" 200 25950
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.803] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 1827
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.866] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 1742
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.886] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4237&size=512 HTTP/1.1" 200 84380
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.899] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3860&size=512 HTTP/1.1" 200 25571
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.969] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4117&size=512 HTTP/1.1" 200 28410
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.987] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3924&size=512 HTTP/1.1" 200 43180
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:18.995] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4429&size=512 HTTP/1.1" 200 12471
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.014] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3854&size=512 HTTP/1.1" 200 47212
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.016] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=2681&size=512 HTTP/1.1" 200 35840
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.032] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4627&size=512 HTTP/1.1" 200 31038
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.037] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4162&size=512 HTTP/1.1" 200 28064
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.050] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4438&size=512 HTTP/1.1" 200 17252
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.102] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3795&size=512 HTTP/1.1" 200 24196
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.125] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3154&size=512 HTTP/1.1" 200 46928
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.172] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4010&size=512 HTTP/1.1" 200 60285
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.185] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=3761&size=512 HTTP/1.1" 200 59367
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.210] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=2922&size=512 HTTP/1.1" 200 28715
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.337] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4078&size=512 HTTP/1.1" 200 29378
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:19.359] "GET /?wtd=kVFeERffeeABGohz&request=resource&resource=o1fbt5uo&ver=1&releaseid=4137&size=512 HTTP/1.1" 200 20363
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:22.428] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 0
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:22.432] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 1504
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:27.096] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 0
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:27.099] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 665
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:31.312] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 0
lms  | 172.20.0.2 - - [2022-Jul-08 07:28:31.321] "POST /?wtd=kVFeERffeeABGohz HTTP/1.1" 200 3380
lms  | [2022-Jul-08 07:28:45.324] 1 - [fatal] - [UTILS] Exception caught in IO context: std::bad_alloc
abdulocracy commented 2 years ago

I've rolled back to 3.29 and it still crashes with the same message. This started after upgrading to 3.30 yesterday.

abdulocracy commented 2 years ago

I restored to a backup from before the upgrade, and can recreate the breakage introduced by 3.30.

epoupon commented 2 years ago

Looks like there is no memory available. Could you check memory when running lms? Is there something special you do on the interface to make it crash?

abdulocracy commented 2 years ago

I wasn't doing anything particular, just starting to play any song. I can't reproduce the behavior right now, perhaps the server was in an OOM state when I reported the bug, however unlikely it seems. Please close, I'll reopen if I can reproduce. Thanks. :)

abdulocracy commented 2 years ago

I'm still experiencing this issue, the server is nowhere near OOM and the container is far from its limit. I don't think it's an OOM issue.

abdulocracy commented 2 years ago

Here's a slightly more detailed crash log.

Edit: never mind, it's the same log, for some reason it's malformed. Maybe less butchered it.

lms  | 172.20.0.2 - - [2022-Jul-13 06:01:32.484] "POST /?wtd=pShiPWMX3Hgko2Jx HTTP/1.1" 200 0
lms  | 172.20.0.2 - - [2022-Jul-13 06:01:32.485] "POST /?wtd=pShiPWMX3Hgko2Jx HTTP/1.1" 200 96
lms  | [flac @ 0x7f768ed85680] Could not find codec parameters for stream 1 (Video: mjpeg, none): unspecified size
lms  | Consider increasing the value for the 'analyzeduration' and 'probesize' options
lms  | 172.20.0.2 - - [2022-Jul-13 06:01:32.711] "GET /release/mbid/?wtd=pShiPWMX3Hgko2Jx&request=resource&resource=o1rj
7an6&ver=1&trackid=45750&size=128 HTTP/1.1" 200 4165T /release/mbid/?wtd=pShiPWMX3Hgko2Jx&request=resource&resource=o1rj
7anc&ver=1&trackid=45750&bitrate=192000&format=2 HTTP/1.1" 200 4238896ht in IO context: std::bad_alloc
epoupon commented 2 years ago

Ok, will try the docker version to see if I can reproduce. Here what I get so far: image Looks like the RES memory usage is quite limited for now

epoupon commented 2 years ago

By the way, did you set some constraint? (see https://docs.docker.com/config/containers/resource_constraints/)

abdulocracy commented 2 years ago

I have no resource constraints on the container, so it's got plenty of room to grow when it fails.

epoupon commented 2 years ago

Another question: do you play transcoded tracks? Could you by chance run using full debug output? log-config = "*"; in lms.conf

abdulocracy commented 2 years ago

Yes, I play transcoded tracks. Here's the full log: lms.log

abdulocracy commented 2 years ago

It seems to always happen when the 'love' feedbacks are queued to be sent.

epoupon commented 2 years ago

Ok, thanks for the valuable log file. I have found something bad in the code involved that is very likely to explain your crash. Will schedule a hotfix asap

abdulocracy commented 2 years ago

Thank you very much for the prompt fix. :)

epoupon commented 2 years ago

@abdulocracy can you update your docker image and confirm the problem is gone for you?

abdulocracy commented 2 years ago

I've updated, will test and let you know if the issue persists.