Mylar db becoming permanently locked during search

Post any problems / bugs / issues that are Mylar-related in here.
Post Reply
billbord
Posts: 6
Joined: Wed Nov 06, 2019 3:00 pm

Mylar db becoming permanently locked during search

Post by billbord »

Hi -
I’m running Mylar in an unraid docker and have had issues with database locking ever since I switched to sabnzbd from nzbget a few days ago. Soon after startup the app pegs it’s core at 100% and starts spitting out database locked messages.

For the life of me I can’t figure it out. I turned off rss search and things got better for a few hours but then locked again when I set some snatched results to failed.

Are there sab settings that could be causing this? I’d rather not switch back to nzbget but I will if I have to. I don’t know how to change the command line flags for the docket so I’m not able to get debug logs from startup, but the few hundred lines before the lock are below.

Thanks for a great piece of software and any help you can provide.

2019-11-07 09:24:13 WARNING Database Error: database is locked
2019-11-07 09:23:52 WARNING sqlresult: UPDATE nzblog SET NZBName = ?, ID = ?, AltNZBName = ? WHERE IssueID = ? AND Provider = ?
2019-11-07 09:23:52 WARNING Database Error: database is locked
2019-11-07 09:23:30 WARNING sqlresult: UPDATE nzblog SET NZBName = ?, ID = ?, AltNZBName = ? WHERE IssueID = ? AND Provider = ?
2019-11-07 09:23:30 WARNING Database Error: database is locked
2019-11-07 09:23:08 WARNING sqlresult: UPDATE nzblog SET NZBName = ?, ID = ?, AltNZBName = ? WHERE IssueID = ? AND Provider = ?
2019-11-07 09:23:08 WARNING Database Error: database is locked
2019-11-07 09:22:47 WARNING sqlresult: UPDATE nzblog SET NZBName = ?, ID = ?, AltNZBName = ? WHERE IssueID = ? AND Provider = ?
2019-11-07 09:22:47 WARNING Database Error: database is locked
2019-11-07 09:22:26 WARNING sqlresult: UPDATE nzblog SET NZBName = ?, ID = ?, AltNZBName = ? WHERE IssueID = ? AND Provider = ?
2019-11-07 09:22:26 WARNING Database Error: database is locked
2019-11-07 09:22:06 INFO setting the alternate nzbname for this download grabbed by nzb.su in the nzblog to : MagnificentMs.Marvel0072019DigitalZone-Empire
2019-11-07 09:22:06 INFO setting the nzbid for this download grabbed by nzb.su in the nzblog to : 856bc156839b754bf475f0d4263fe1b2
2019-11-07 09:22:06 DEBUG Found matching comic...preparing to send to Updater with IssueID: 719440 and nzbname: Magnificent.Ms.Marvel.007.2019.Digital.Zone-Empire [MagnificentMs.Marvel0072019DigitalZone-Empire]
2019-11-07 09:22:06 INFO mylar.COMICINFO: [{'IssueID': u'719440', 'pack_numbers': None, 'IssueNumber': u'7', 'nzbtitle': u'Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)', 'nzbid': u'856bc156839b754bf475f0d4263fe1b2', 'size': '58.3 MB', 'newznab': None, 'ComicName': u'The Magnificent Ms. Marvel', 'provider': 'nzb.su', 'ComicID': u'117593', 'ComicVolume': None, 'modcomicname': u'The Magnificent Ms. Marvel', 'link': u'https://api.nzb.su/getnzb/856bc156839b7 ... ***removed***', 'IssueDate': u'2019-11-01', 'kind': 'usenet', 'torznab': None, 'SARC': None, 'oneoff': False, 'pack_issuelist': None, 'IssueArcID': None, 'comyear': '2019', 'nzbprov': 'nzb.su', 'tmpprov': 'nzb.su', 'pack': False}]
2019-11-07 09:22:06 INFO Successfully sent nzb file to SABnzbd
2019-11-07 09:22:06 INFO sendtosab: {'status': True, 'issueid': u'719440', 'apicall': True, 'nzo_id': u'SABnzbd_nzo_iLdHDo', 'queue': {'output': 'json', 'search': u'SABnzbd_nzo_iLdHDo', 'apikey': 'd37b48790f21dd6c07638ed288dbd365', 'mode': 'queue'}, 'comicid': u'117593'}
2019-11-07 09:22:06 INFO {u'status': True, u'nzo_ids': [u'SABnzbd_nzo_iLdHDo']}
2019-11-07 09:22:06 DEBUG Received API command: downloadNZB
2019-11-07 09:22:06 DEBUG Matched to key. Api set to : download mode.
2019-11-07 09:22:05 INFO sending now to http://192.168.86.17:8080/api
2019-11-07 09:22:05 INFO parameters set to {'nzbname': u'Magnificent.Ms.Marvel.007.2019.Digital.Zone-Empire.nzb', 'apikey': 'd37b48790f21dd6c07638ed288dbd365', 'name': u'http://172.19.0.7:8090/api?apikey=***re ... Empire.nzb', 'cmd': 'downloadNZB', 'cat': 'comics', 'priority': '-100', 'mode': 'addurl', 'output': 'json'}
2019-11-07 09:22:04 DEBUG Successfully changed permissions [0777 / 0777]
2019-11-07 09:21:29 DEBUG Cache Directory successfully found at : /config/mylar/cache. Ensuring proper permissions.
2019-11-07 09:21:29 INFO filen: MagnificentMs.Marvel0072019DigitalZone-Empire -- nzbname: Magnificent.Ms.Marvel.007.2019.Digital.Zone-Empire are not identical. Storing extra value as : MagnificentMs.Marvel0072019DigitalZone-Empire
2019-11-07 09:21:29 DEBUG [FILENAME] end nzbname: MagnificentMs.Marvel0072019DigitalZone-Empire
2019-11-07 09:21:29 DEBUG [FILENAME] nzbname (\s): MagnificentMs.Marvel0072019DigitalZone-Empire
2019-11-07 09:21:29 DEBUG [FILENAME] filename (remove chars): MagnificentMs.Marvel0072019DigitalZone-Empire
2019-11-07 09:21:29 DEBUG Status code returned: 200
2019-11-07 09:21:28 DEBUG [PAYLOAD-NONE] Download URL: https://api.nzb.su/getnzb/856bc156839b7 ... OKNOWTHISx [VerifySSL: True]
2019-11-07 09:21:28 DEBUG [FAILED_DOWNLOAD_CHECKER] This is not in the failed downloads list. Will continue with the download.
2019-11-07 09:21:28 INFO [FAILED_DOWNLOAD_CHECKER] Successfully marked this download as Good for downloadable content
2019-11-07 09:21:27 INFO prov : nzb.su[856bc156839b754bf475f0d4263fe1b2]
2019-11-07 09:21:27 INFO oneoff: False
2019-11-07 09:21:27 INFO IssueID: 719440
2019-11-07 09:21:27 INFO nzbid: 856bc156839b754bf475f0d4263fe1b2
2019-11-07 09:21:27 DEBUG link given by: nzb.su
2019-11-07 09:21:27 INFO Found The Magnificent Ms. Marvel (2019) #7 using nzb.su
2019-11-07 09:21:27 DEBUG issues match!
2019-11-07 09:21:27 DEBUG nzbname used for post-processing: Magnificent.Ms.Marvel.007.2019.Digital.Zone-Empire
2019-11-07 09:21:27 DEBUG [SEARCHER] end nzbname: Magnificent.Ms.Marvel.007.2019.Digital.Zone-Empire
2019-11-07 09:21:27 DEBUG [SEARCHER] nzbname (\s): Magnificent Ms Marvel 007 2019 Digital Zone-Empire
2019-11-07 09:21:27 DEBUG [SEARCHER] nzbname (remove chars): Magnificent Ms. Marvel 007 2019 Digital Zone-Empire
2019-11-07 09:21:27 DEBUG [SEARCHER] entry[title]: Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)
2019-11-07 09:21:27 DEBUG integer value of issue we have found : 7000
2019-11-07 09:21:27 DEBUG issue we found for is : 007
2019-11-07 09:21:27 DEBUG integer value of issue we are looking for : 7000
2019-11-07 09:21:27 DEBUG issue we are looking for is : 7
2019-11-07 09:21:27 DEBUG Series version detected as V1 (only series in existance with that title). Bypassing Year/Volume check
2019-11-07 09:21:27 DEBUG match_check: {'justthedigits': u'007', 'issueid': None, 'match_type': None, 'sub': None, 'comiclocation': None, 'booktype': 'issue', 'series_name': u'Magnificent Ms Marvel', 'comicfilename': u'Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)', 'annual_comicid': None, 'issue_year': '2019', 'volume': None, 'process_status': 'match', 'scangroup': u'Zone-Empire', 'alt_series': None, 'alt_issue': None, 'series_volume': None}
2019-11-07 09:21:27 DEBUG parsed_info: {'series_volume': None, 'booktype': 'issue', 'issueid': None, 'sub': None, 'comiclocation': None, 'reading_order': None, 'parse_status': 'success', 'dynamic_name': u'MagnificentMsMarvel', 'series_name': u'Magnificent Ms Marvel', 'comicfilename': u'Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)', 'issue_number': u'007', 'issue_year': '2019', 'scangroup': u'Zone-Empire', 'alt_series': None, 'alt_issue': None, 'series_name_decoded': 'Magnificent Ms Marvel'}
2019-11-07 09:21:27 DEBUG series title possibly: Magnificent Ms Marvel
2019-11-07 09:21:27 DEBUG sf_highest_series_pos: [u'Magnificent', u'Ms', u'Marvel']
2019-11-07 09:21:26 DEBUG issue verified as : 007
2019-11-07 09:21:26 DEBUG issue_position: 3
2019-11-07 09:21:26 DEBUG issue number :007
2019-11-07 09:21:26 DEBUG possible_issuenumbers: [{'position': 3, 'validcountchk': False, 'number': u'007', 'mod_position': 23}]
2019-11-07 09:21:26 DEBUG highest_series_position: 4
2019-11-07 09:21:26 DEBUG year verified as: 2019
2019-11-07 09:21:26 DEBUG year verified as : 2019
2019-11-07 09:21:26 DEBUG sctd: 2019
2019-11-07 09:21:26 DEBUG datecheck: [{'date': u'2019', 'position': 4, 'mod_position': 27}]
2019-11-07 09:21:26 DEBUG date: 2019
2019-11-07 09:21:26 DEBUG checking date : 2019
2019-11-07 09:21:26 DEBUG NEWLY SPLIT REORGD: [u'Magnificent', u'Ms', u'Marvel', u'007', u'(2019)', u'(Digital)']
2019-11-07 09:21:25 DEBUG Scanner group tag discovered: Zone-Empire
2019-11-07 09:21:25 DEBUG Entry: Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)
2019-11-07 09:21:25 DEBUG [CONV] Wed, 18 Sep 2019 14:32:38 -0400 is after store date of 2019-09-18
2019-11-07 09:21:25 DEBUG usedate: 2019-09-18
2019-11-07 09:21:25 DEBUG date used is : 2019-09-18
2019-11-07 09:21:25 DEBUG store date used is : 2019-09-18
2019-11-07 09:21:25 DEBUG size given as: 58.3 MB
2019-11-07 09:21:25 DEBUG comsize_b: 61128825
2019-11-07 09:21:24 DEBUG sub: Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)
2019-11-07 09:21:24 DEBUG checking search result: Magnificent Ms. Marvel 007 (2019) (Digital) (Zone-Empire)
2019-11-07 09:21:24 INFO no errors on data retrieval...proceeding
2019-11-07 09:21:21 DEBUG [SSL: True] Search URL: https://api.nzb.su/api?t=search&q=%20ma ... OKNOWTHISx
2019-11-07 09:21:21 INFO Pausing for 60 seconds before continuing to avoid hammering
2019-11-07 09:21:21 DEBUG findloop: 0 / findcount: 1
2019-11-07 09:21:21 INFO Shhh be very quiet...I'm looking for The Magnificent Ms. Marvel issue: 7 (2019) using nzb.su.
2019-11-07 09:21:21 DEBUG Initiating Search via : api
2019-11-07 09:21:21 DEBUG calpha/cnumber: None / None
2019-11-07 09:21:21 DEBUG search provider order is ['nzb.su', u'newznab: Nzbgeek']
2019-11-07 09:21:21 DEBUG Usenet Retention : 3500 days
2019-11-07 09:21:21 DEBUG There are : 2 nzb providers you have selected
2019-11-07 09:21:21 DEBUG There are 0 torrent providers you have selected.
2019-11-07 09:21:21 DEBUG nzbprovider(s): ['nzb.su', u'newznab: Nzbgeek']
2019-11-07 09:21:21 DEBUG Checking for torrent enabled.
2019-11-07 09:21:21 DEBUG Issue Title given as : None
2019-11-07 09:21:21 DEBUG Publisher is : Marvel
2019-11-07 09:21:21 INFO searching for issueid: 719440
2019-11-07 09:21:21 INFO [UPDATER] Updated the status (Snatched) complete for Mister Miracle Issue: 3
2019-11-07 09:21:21 DEBUG [UPDATER] Provider is Nzbgeek (newznab)
2019-11-07 09:21:21 INFO [UPDATER] Updating status to snatched
2019-11-07 09:21:21 DEBUG [UPDATER] issueid: 11584
2019-11-07 09:21:20 DEBUG [UPDATER] comicid: 2504
2019-11-07 09:21:20 DEBUG findit = found!
2019-11-07 09:21:18 INFO setting the nzbid for this download grabbed by Nzbgeek (newznab) in the nzblog to : ac4e440edd287653a8444266088c3a44
2019-11-07 09:21:18 DEBUG Found matching comic...preparing to send to Updater with IssueID: 11584 and nzbname: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:21:18 INFO mylar.COMICINFO: [{'IssueID': u'11584', 'pack_numbers': None, 'IssueNumber': u'3', 'nzbtitle': u'Mister Miracle 003 (2017) (2 covers) (digital) (Son of Ultron-Empire)', 'nzbid': u'3951301573e15a485678e78bdae0e438', 'size': '43.7 MB', 'newznab': None, 'ComicName': u'Mister Miracle', 'provider': 'nzb.su', 'ComicID': u'2504', 'ComicVolume': None, 'modcomicname': u'Mister Miracle', 'link': u'https://api.nzb.su/getnzb/3951301573e15 ... ***removed***', 'IssueDate': u'1971-08-31', 'kind': 'usenet', 'torznab': None, 'SARC': None, 'oneoff': False, 'pack_issuelist': None, 'IssueArcID': None, 'comyear': '1971', 'nzbprov': 'nzb.su', 'tmpprov': 'nzb.su', 'pack': False}, {'IssueID': u'11584', 'pack_numbers': None, 'IssueNumber': u'3', 'nzbtitle': u'Mister Miracle 003 (2017) (2 covers) (digital) (Son of Ultron-Empire)', 'nzbid': u'a7d18f86535384e9ec04ed1c90ba0c13', 'size': '43.7 MB', 'newznab': None, 'ComicName': u'Mister Miracle', 'provider': 'nzb.su', 'ComicID': u'2504', 'ComicVolume': None, 'modcomicname': u'Mister Miracle', 'link': u'https://api.nzb.su/getnzb/a7d18f8653538 ... ***removed***', 'IssueDate': u'1971-08-31', 'kind': 'usenet', 'torznab': None, 'SARC': None, 'oneoff': False, 'pack_issuelist': None, 'IssueArcID': None, 'comyear': '1971', 'nzbprov': 'nzb.su', 'tmpprov': 'nzb.su', 'pack': False}, {'IssueID': u'11584', 'pack_numbers': None, 'IssueNumber': u'3', 'nzbtitle': u'Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire', 'nzbid': u'ac4e440edd287653a8444266088c3a44', 'size': '43.7 MB', 'newznab': (u'Nzbgeek', u'https://api.nzbgeek.info', u'1', u'***removed***', u'15139', '1'), 'ComicName': u'Mister Miracle', 'provider': u'Nzbgeek', 'ComicID': u'2504', 'ComicVolume': None, 'modcomicname': u'Mister Miracle', 'link': u'https://api.nzbgeek.info/api?t=get&id=a ... ***removed***', 'IssueDate': u'1971-08-31', 'kind': 'usenet', 'torznab': None, 'SARC': None, 'oneoff': False, 'pack_issuelist': None, 'IssueArcID': None, 'comyear': '1971', 'nzbprov': 'newznab', 'tmpprov': u'Nzbgeek (newznab)', 'pack': False}]
2019-11-07 09:21:18 INFO Successfully sent nzb file to SABnzbd
2019-11-07 09:21:18 INFO sendtosab: {'status': True, 'issueid': u'11584', 'apicall': True, 'nzo_id': u'SABnzbd_nzo_IbOssK', 'queue': {'output': 'json', 'search': u'SABnzbd_nzo_IbOssK', 'apikey': 'd37b48790f21dd6c07638ed288dbd365', 'mode': 'queue'}, 'comicid': u'2504'}
2019-11-07 09:21:18 INFO {u'status': True, u'nzo_ids': [u'SABnzbd_nzo_IbOssK']}
2019-11-07 09:21:18 DEBUG Received API command: downloadNZB
2019-11-07 09:21:18 DEBUG Matched to key. Api set to : download mode.
2019-11-07 09:21:17 INFO sending now to http://192.168.86.17:8080/api
2019-11-07 09:21:17 INFO parameters set to {'nzbname': u'Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire.nzb', 'apikey': 'd37b48790f21dd6c07638ed288dbd365', 'name': u'http://172.19.0.7:8090/api?apikey=***re ... Empire.nzb', 'cmd': 'downloadNZB', 'cat': 'comics', 'priority': '-100', 'mode': 'addurl', 'output': 'json'}
2019-11-07 09:21:16 DEBUG Successfully changed permissions [0777 / 0777]
2019-11-07 09:20:21 DEBUG Cache Directory successfully found at : /config/mylar/cache. Ensuring proper permissions.
2019-11-07 09:20:21 DEBUG [FILENAME] end nzbname: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire.nzb
2019-11-07 09:20:21 DEBUG [FILENAME] nzbname (\s): Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire.nzb
2019-11-07 09:20:21 DEBUG [FILENAME] filename (remove chars): Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire.nzb
2019-11-07 09:20:20 DEBUG filename within nzb: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire.nzb
2019-11-07 09:20:20 DEBUG Status code returned: 200
2019-11-07 09:20:15 DEBUG [PAYLOAD-NONE] Download URL: https://api.nzbgeek.info/api?t=get&id=a ... OKNOWTHISx [VerifySSL: True]
2019-11-07 09:20:15 DEBUG [FAILED_DOWNLOAD_CHECKER] This is not in the failed downloads list. Will continue with the download.
2019-11-07 09:20:15 INFO [FAILED_DOWNLOAD_CHECKER] Successfully marked this download as Good for downloadable content
2019-11-07 09:20:15 INFO prov : Nzbgeek (newznab)[ac4e440edd287653a8444266088c3a44]
2019-11-07 09:20:14 INFO oneoff: False
2019-11-07 09:20:14 INFO IssueID: 11584
2019-11-07 09:20:14 INFO nzbid: ac4e440edd287653a8444266088c3a44
2019-11-07 09:20:14 DEBUG link given by: newznab
2019-11-07 09:20:14 INFO Found Mister Miracle (1971) #3 using Nzbgeek (newznab)
2019-11-07 09:20:14 DEBUG issues match!
2019-11-07 09:20:14 DEBUG nzbname used for post-processing: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:14 DEBUG [SEARCHER] end nzbname: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:14 DEBUG [SEARCHER] nzbname (\s): Mister Miracle 003 2017 2 covers digital Son of Ultron-Empire
2019-11-07 09:20:13 DEBUG [SEARCHER] nzbname (remove chars): Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:13 DEBUG [SEARCHER] entry[title]: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:13 DEBUG integer value of issue we have found : 3000
2019-11-07 09:20:13 DEBUG issue we found for is : 003
2019-11-07 09:20:13 DEBUG integer value of issue we are looking for : 3000
2019-11-07 09:20:13 DEBUG issue we are looking for is : 3
2019-11-07 09:20:13 DEBUG Series version detected as V1 (only series in existance with that title). Bypassing Year/Volume check
2019-11-07 09:20:12 DEBUG match_check: {'justthedigits': u'003', 'issueid': None, 'match_type': None, 'sub': None, 'comiclocation': None, 'booktype': 'issue', 'series_name': u'Mister Miracle', 'comicfilename': u'Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire', 'annual_comicid': None, 'issue_year': '2017', 'volume': None, 'process_status': 'match', 'scangroup': None, 'alt_series': None, 'alt_issue': None, 'series_volume': None}
2019-11-07 09:20:12 DEBUG parsed_info: {'series_volume': None, 'booktype': 'issue', 'issueid': None, 'sub': None, 'comiclocation': None, 'reading_order': None, 'parse_status': 'success', 'dynamic_name': u'MisterMiracle', 'series_name': u'Mister Miracle', 'comicfilename': u'Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire', 'issue_number': u'003', 'issue_year': '2017', 'scangroup': None, 'alt_series': None, 'alt_issue': None, 'series_name_decoded': 'Mister Miracle'}
2019-11-07 09:20:12 DEBUG series title possibly: Mister Miracle
2019-11-07 09:20:12 DEBUG sf_highest_series_pos: [u'Mister', u'Miracle']
2019-11-07 09:20:12 DEBUG issue verified as : 003
2019-11-07 09:20:12 DEBUG issue_position: 2
2019-11-07 09:20:12 DEBUG issue number :003
2019-11-07 09:20:12 DEBUG Already validated year, ignoring as possible issue number: 2017
2019-11-07 09:20:12 DEBUG yearposition: 3
2019-11-07 09:20:12 DEBUG hyphen located at position: 54
2019-11-07 09:20:12 DEBUG possible_issuenumbers: [{'position': 2, 'validcountchk': False, 'number': u'003', 'mod_position': 15}, {'position': 3, 'validcountchk': False, 'number': u'2017', 'mod_position': 19}]
2019-11-07 09:20:11 DEBUG highest_series_position: 3
2019-11-07 09:20:11 DEBUG year verified as: 2017
2019-11-07 09:20:11 DEBUG year verified as : 2017
2019-11-07 09:20:11 DEBUG sctd: 2019
2019-11-07 09:20:11 DEBUG datecheck: [{'date': u'2017', 'position': 3, 'mod_position': 19}]
2019-11-07 09:20:11 DEBUG date: 2017
2019-11-07 09:20:10 DEBUG checking date : 2017
2019-11-07 09:20:10 DEBUG NEWLY SPLIT REORGD: [u'Mister', u'Miracle', u'003', u'2017', u'2 covers', u'digital', u'Son', u'of', u'Ultron-Empire']
2019-11-07 09:20:10 DEBUG checking now: Ultron-Empire
2019-11-07 09:20:10 DEBUG NEW split_file3: [u'Mister', u'Miracle', u'003', u'2017', u'2', u'covers', u'digital', u'Son', u'of', u'Ultron-Empire']
2019-11-07 09:20:10 DEBUG Improperly formatted filename - there is no seperation using appropriate characters between wording.
2019-11-07 09:20:10 DEBUG Entry: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:10 DEBUG [CONV] Thu, 12 Oct 2017 12:14:52 +0000 is after store date of 1971-07-07
2019-11-07 09:20:09 DEBUG usedate: 1971-07-07
2019-11-07 09:20:09 DEBUG date used is : 1971-07-07
2019-11-07 09:20:09 DEBUG store date used is : 1971-07-07
2019-11-07 09:20:08 DEBUG size given as: 43.7 MB
2019-11-07 09:20:08 DEBUG comsize_b: 45818000
2019-11-07 09:20:08 DEBUG sub: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:08 DEBUG checking search result: Mister.Miracle.003.2017.2.covers.digital.Son.of.Ultron-Empire
2019-11-07 09:20:08 INFO no errors on data retrieval...proceeding
2019-11-07 09:20:02 DEBUG [SSL: True] Search URL: https://api.nzbgeek.info/api?t=search&q ... OKNOWTHISx
2019-11-07 09:20:02 INFO Pausing for 60 seconds before continuing to avoid hammering
2019-11-07 09:20:02 DEBUG findloop: 0 / findcount: 1
2019-11-07 09:20:02 INFO Shhh be very quiet...I'm looking for Mister Miracle issue: 3 (1971) using Nzbgeek (newznab).
2019-11-07 09:20:02 DEBUG Using Newznab host of : Nzbgeek
User avatar
evilhero
Site Admin
Posts: 2883
Joined: Sat Apr 20, 2013 3:43 pm
Contact:

Re: Mylar db becoming permanently locked during search

Post by evilhero »

What branch /commit of Mylar are you running ? How are you starting Mylar ?

Usually this was occuring in previous version of Mylar ( like ~ last year or so ), or can happen when too many searches are firing off without being added to the search queue first. The search queue was put in so that any search that's requested gets fed into the queue so that things don't get fired off all at the same time (ie. you hit manual search on like 5 items in a row within a few seconds), and as far as I'm aware that fixed alot of the db locking issues.

It's quite possible we missed a search task that's submitting direct requests instead of adhering to the queue workflow, in which case we'd have to look more into that.
billbord
Posts: 6
Joined: Wed Nov 06, 2019 3:00 pm

Re: Mylar db becoming permanently locked during search

Post by billbord »

Version: 5ffe8fbd3080e11884c6d11ad3aacbc9f6a73cb3 (master)

I’m using the latest version of linuxserver.io’s docker on Unraid.
User avatar
evilhero
Site Admin
Posts: 2883
Joined: Sat Apr 20, 2013 3:43 pm
Contact:

Re: Mylar db becoming permanently locked during search

Post by evilhero »

The 100% CPU pegging would indicate to me that one of the threads/jobs isn't exiting normally and so it's just caught in an endless loop of some kind. Tracking that down is going to be difficult as being able to duplicate the problem on another machine (namely mine) allows me to properly debug things, and I haven't been able to get the db locks to occur thus far.

Once you start up Mylar, does it hit the db locking almost right away without you doing anything ? Or is there some kind of sequence you do prior to the db locks occuring ?

I don't think it has anything to do with SABnzbd per-se, I mean lots of people use SAB + Mylar fine without any db locking issue occurring. Now if you have both the ComicRN script running as well as CDH then that might cause some issues, but not usually db locking as that's (from my experience thus far) has usually been in relation to search threads firing off simultaneously and that looks like what's happening here based on those lock logs.

You can start Mylar with the -v switch to enable verbose logging on startup, however I am not a docker person so unfortunately I can't assist with how to add options to the startup call of a docker module. I'd need to see the full debug logs to see where the db locks are occuring on a code workflow basis, and the debug logs (not from the GUI, but the log files themselves) provide line numbers referencing specific lines in the code.
billbord
Posts: 6
Joined: Wed Nov 06, 2019 3:00 pm

Re: Mylar db becoming permanently locked during search

Post by billbord »

With RSS search on it pegs the CPU almost immediately and locks after a few minutes. With that option turned off it ran fine all night, pulling down several issues. It didn't lock until this morning when I reset some snatched downloads to failed (separate question, but should the post-processor be setting these to failed when post-processing fails? I'm not using the ComicRN script, just the built-in post-processor.).

Agreed on Sab itself not being the culprit - it could be a complete red herring. I thought that something in my setup may be incorrect and is leaving these threads hanging which eventually overwhelms the DB, but my last computer science class was 14 years ago and I'm certainly not a professional :) Hopefully the logs can answer this definitively.

I'll figure out how to rebuild the container with the -v option and post the logs tonight. Thanks!
User avatar
evilhero
Site Admin
Posts: 2883
Joined: Sat Apr 20, 2013 3:43 pm
Contact:

Re: Mylar db becoming permanently locked during search

Post by evilhero »

Now that's interesting - setting items to failed, from my recollection, might reinitiate a search that isn't tied to the search queue workflow pattern. So if you do it multiple times in succession to different issues, it would cause a db lockup at some point subsequent to that due to it trying to write stuff to the db at the same time.

If you have failed download handling enabled, it would mark it as failed during post-processing (if that was where it occured) and then auto-rety for a different result (if you have the auto-retry enabled for failed download handling). As far as failed searches, I don't think Mylar will mark items that fail to download in your client as failed within Mylar itself - tbh, it's been awhile since I looked at that so if that's what you're inquiring about, I'd need to dig further into what it is that Mylar actually does in that regards.

With RSS enabled, I'm betting that you have the search on startup option enabled as well (on the 2nd tab in the configuration) ? Enabling that causes the search to fire off immediately at the same time as the RSS fires off, so if issues are found at the same time or even when the RSS caches (cause it caches the results of the RSS feeds so it writes it to the db) it would cause lockups.

Don't worry about the lack of computer expertise, not everyone works in IT and honestly, having worked in IT - some of the people working in IT, really shouldn't be. If you can get those debug logs, they should be more than enough for us to try and duplicate the issue on our end and come up with some kind of solution in a hopefully not long timeframe.
billbord
Posts: 6
Joined: Wed Nov 06, 2019 3:00 pm

Re: Mylar db becoming permanently locked during search

Post by billbord »

Interesting - the post-processor is definitely leaving those issues in snatched status and not attempting another download, even with failed-download handling turned on. I wonder if there's a permission issue banging around somewhere.

You're correct about RSS search on startup being enabled. I can turn that off and set it to run at a reasonable interval - what do you recommend?

Either way I believe I can get a shell inside the container, kill the mylar.py process, then relaunch with the -v flag. I'll update soon.
billbord
Posts: 6
Joined: Wed Nov 06, 2019 3:00 pm

Re: Mylar db becoming permanently locked during search

Post by billbord »

Well if nothing else I've learned a good bit about docker today. It was NOT as easy as killing the process and restarting it with the -v flag, but I can now see the verbose logs.

https://pastebin.com/tpwVreyZ

I thought I was in the clear for a while but I'm still seeing database locking - the first instance I can find is at 22:55:38 - I tried to snip a relevant portion. If there's an easier way to post more than 512kb let me know and I'll do it. I bumped up the log size/number of logs so I'd capture the issue.

Many thanks for the snappy response and help thus far.
User avatar
evilhero
Site Admin
Posts: 2883
Joined: Sat Apr 20, 2013 3:43 pm
Contact:

Re: Mylar db becoming permanently locked during search

Post by evilhero »

Yep that's just what I figured was happening, and your logs confirmed it too.

Thread-7 is the thread that you initiated when you manually marked an issue as Wanted. Marking an issue as Wanted submits the search thread to start immediately. Unfortunately, your RSS was running concurrently at that time and the too bonked heads during their respective jobs, and caused the deadlock of the db.

I have this issue (amongst probably a craptonne more) fixed on my local repo, but because of my recent pc problems these all just accumulated and now it's one big commit - which I honestly can't do, cause it's literally far too huge & encompassing for me to just push out without testing.

I think I might be able to cherrypick the fix for the db lock out tho, but it might take me a day, mainly due to free time more than anything. I'll update this when the fix goes live so you can update and verify on your end.
billbord
Posts: 6
Joined: Wed Nov 06, 2019 3:00 pm

Re: Mylar db becoming permanently locked during search

Post by billbord »

Awesome, I'll just stop doing that for the time being :) Thanks again for the help.
Post Reply