Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

3.30.0 crashes #249

Closed
abdulocracy opened this issue Jul 8, 2022 · 16 comments · Fixed by #250
Closed

3.30.0 crashes #249

abdulocracy opened this issue Jul 8, 2022 · 16 comments · Fixed by #250
Labels
bug
Milestone
v3.30.1

Comments

@abdulocracy
Copy link

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
Copy link
Author

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

@abdulocracy
Copy link
Author

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

@epoupon
Copy link
Owner

epoupon commented Jul 8, 2022

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
Copy link
Author

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
Copy link
Author

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 abdulocracy reopened this Jul 13, 2022
@abdulocracy
Copy link
Author

abdulocracy commented Jul 13, 2022 •
edited
Loading

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
Copy link
Owner

epoupon commented Jul 13, 2022

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
Copy link
Owner

epoupon commented Jul 13, 2022

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

@abdulocracy
Copy link
Author

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

@epoupon
Copy link
Owner

epoupon commented Jul 13, 2022 •
edited
Loading

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

@abdulocracy
Copy link
Author

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

@abdulocracy
Copy link
Author

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

epoupon added a commit that referenced this issue Jul 13, 2022
@epoupon
Listenbrainz: skip tracks that do not have mbid instead of crashing. f…
7eb2676 
…ixes #249
@epoupon
Copy link
Owner

epoupon commented Jul 13, 2022 •
edited
Loading

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

@epoupon epoupon closed this as completed Jul 13, 2022
@epoupon epoupon added the bug label Jul 13, 2022
@epoupon epoupon added this to the v3.30.1 milestone Jul 13, 2022
@epoupon epoupon mentioned this issue Jul 13, 2022
Merged
@abdulocracy
Copy link
Author

Thank you very much for the prompt fix. :)

@epoupon
Copy link
Owner

epoupon commented Jul 14, 2022

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

@abdulocracy
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
v3.30.1
Development

Successfully merging a pull request may close this issue.

Release candidate v3.30.1 epoupon/lms
2 participants
@epoupon @abdulocracy