Auto-Update failing - Githubissues

DrSeussFreak commented 5 years ago

Describe the bug I get notified of an update, I click update, and it does it's thing. Mylar restarts, and the update failed.

Screenshots/Logs

28-Feb-2019 18:47:46 - WARNING :: mylar._parse_feed.399 : Thread-12 : Error fetching RSS Feed Data from NZBHydra2: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
28-Feb-2019 18:47:47 - ERROR   :: mylar.setperms.1653 : Thread-12 : Could not change permissions : /opt/Mylar/cache. Exiting...
28-Feb-2019 18:47:53 - ERROR   :: mylar.runGit.58 : MAIN : Error: None
28-Feb-2019 18:47:53 - ERROR   :: mylar.runGit.59 : MAIN : Git returned bad info. Are you sure this is a git installation? [fatal: unable to access 'https://github.com/evilhero/mylar/': Problem with the SSL CA cert (path? access rights?)
]
28-Feb-2019 18:47:53 - ERROR   :: mylar.update.219 : MAIN : Couldn't download latest version
28-Feb-2019 18:48:03 - WARNING :: mylar._parse_feed.399 : Thread-12 : Error fetching RSS Feed Data from NZBHydra2: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
28-Feb-2019 18:48:04 - ERROR   :: mylar.setperms.1653 : Thread-12 : Could not change permissions : /opt/Mylar/cache. Exiting...

Environment (please complete the following information): Ubuntu 18.04 Version: 71af02a9238732cf02efc00481b2937e82a8473b (development)

Additional information I have a self signed certificate in place, for ssl on the site.

I can update via

git reset --hard
git pull

evilhero commented 5 years ago

Your git isn't setup to use the required https settings that are required for git cloning (your system seems setup to perform git commands with the http site). Mylar enforces git checking against the https site as that's the norm for most. Self-signed certificates have no impact on git pulls

First google hit says (basically):

git config --global http.sslVerify true
apt-get install ca-certificates
edit your .gitconfig file in your user's home directory ( vi ~/.gitconfig) and change/edit:
```
    sslVerify = true
    sslCAinfo = /etc/ssl/certs/ca-certificates.crt
```

DrSeussFreak commented 5 years ago

The only reason I brought of the self signed cert,w as that the issue started at the same time.

I have moade those changes, but nothing has changed, it still fails with the same log entries

28-Feb-2019 20:19:22 - WARNING :: mylar._parse_feed.399 : Thread-12 : Error fetching RSS Feed Data from NZBHydra2: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
28-Feb-2019 20:19:23 - ERROR   :: mylar.setperms.1653 : Thread-12 : Could not change permissions : /opt/Mylar/cache. Exiting...
28-Feb-2019 20:19:41 - WARNING :: mylar._parse_feed.399 : Thread-12 : Error fetching RSS Feed Data from NZBHydra2: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
28-Feb-2019 20:19:42 - ERROR   :: mylar.setperms.1653 : Thread-12 : Could not change permissions : /opt/Mylar/cache. Exiting...

barbequesauce commented 5 years ago

So the cache line is likely something to do with permissions on the file system - what user is mylar running under? What’s the ACL on the cache directory and below?

The other line is a certificate issue where Mylar and NZBHydra can’t communicate, which is likely related to your self-signed cert. Not sure how much we can help you with that, other than to suggest you confirm your certificate availability to both tools...

barbequesauce commented 5 years ago

That said - that extract did not say anything about updating, and that was your original issue. Can you update in-app now?

DrSeussFreak commented 5 years ago

I cannot, but no log entries are being made. I did a manual update, as I want to troubleshoot the error connecting to my nzbhydra2 instance, and I will test the update feature again with the next commit

evilhero commented 5 years ago

Because you're using a self signed cert, you need to make sure to turn off ssl verification for that newznab entry within mylar so that it doesn't try to verify the certificate as being valid.

DrSeussFreak commented 5 years ago

It isn't that simple, sadly it seems ubuntu won't accept the certificate

Verify return code: 21 (unable to verify the first certificate)

barbequesauce commented 5 years ago

Might want to try a Let’sEncrypt cert instead of a self-signed cert...

DrSeussFreak commented 5 years ago

I'll look into that, thanks

DrSeussFreak commented 5 years ago

You know, even with SSL Verify disabled, it doesn't work, yet sonarr and radarr, on the same ubuntu box, work fine with the ssl cert.

evilhero commented 5 years ago

Those 2 apps don't use python, so the ssl stuff is completely different on how its handled by the underlying system.

Can you enable debug logs and try again? Seeing the url that's being requested helps as does the context leading up.

You can also try putting [nzbhydra]after the name in the name field for the newznab entry (not the host field). Since hydra doesn't support calls to the /rss endpoint, it has to use the /api endpoints which it will do initially if you use the above indicator (as opposed to falling back upon initial failure)

DrSeussFreak commented 5 years ago

2019-03-01 08:30:35 | WARNING | Testing failed to NZBHydra2 [nzbhydra] [HOST:indexer-01:9088][SSL:True]
-- | -- | --
2019-03-01 08:30:35 | WARNING | Unable to connect: No connection adapters were found for 'indexer-01:9088/api'
2019-03-01 08:30:35 | INFO | host: indexer-01:9088/api
2019-03-01 08:30:03 | WARNING | Testing failed to NZBHydra2 [HOST:indexer-01:9088][SSL:True]
2019-03-01 08:30:03 | WARNING | Unable to connect: No connection adapters were found for 'indexer-01:9088/api'
2019-03-01 08:30:03 | INFO | host: indexer-01:9088/api
2019-03-01 08:28:16 | WARNING | Testing failed to NZBHydra2 [HOST:https://indexer-01:9088/nzbhydra][SSL:True]
2019-03-01 08:28:16 | WARNING | Unable to connect: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
2019-03-01 08:28:16 | INFO | host: https://indexer-01:9088/nzbhydra/api
2019-03-01 08:28:12 | WARNING | Testing failed to NZBHydra2 [HOST:https://indexer-01:9088/rss][SSL:True]
2019-03-01 08:28:12 | WARNING | Unable to connect: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
2019-03-01 08:28:12 | INFO | host: https://indexer-01:9088/rss/api
2019-03-01 08:28:08 | WARNING | Testing failed to NZBHydra2 [HOST:https://indexer-01:9088/api][SSL:True]
2019-03-01 08:28:08 | WARNING | Unable to connect: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
2019-03-01 08:28:08 | INFO | host: https://indexer-01:9088/api/api
2019-03-01 08:27:56 | DEBUG | ReScheduled job: Folder Monitor to 2019-03-01 14:30:56
2019-03-01 08:27:56 | INFO | [FOLDER-CHECK] Finished checking for newly snatched downloads
2019-03-01 08:27:56 | WARNING | There were no files located - check the debugging logs if you think this is in error.
2019-03-01 08:27:56 | INFO | there are 0 files.
2019-03-01 08:27:56 | DEBUG | [POST-PROCESSING] Manual Run initiated
2019-03-01 08:27:56 | DEBUG | [POST-PROCESSING] Manual Run Post-Processing enabled.
2019-03-01 08:27:56 | DEBUG | [POST-PROCESSING] nzb folder: /torrents/done
2019-03-01 08:27:56 | DEBUG | [POST-PROCESSING] nzb name: Manual Run
2019-03-01 08:27:56 | INFO | [FOLDER-CHECK] Checking folder /torrents/done for newly snatched downloads
2019-03-01 08:27:32 | WARNING | Testing failed to NZBHydra2 [HOST:https://indexer-01:9088][SSL:True]
2019-03-01 08:27:32 | WARNING | Unable to connect: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
2019-03-01 08:27:32 | INFO | host: https://indexer-01:9088/api
2019-03-01 08:26:57 | WARNING | Testing failed to NZBHydra2 [HOST:https://indexer-01:9088][SSL:True]
2019-03-01 08:26:57 | WARNING | Unable to connect: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
2019-03-01 08:26:57 | INFO | host: https://indexer-01:9088/api
2019-03-01 08:26:38 | DEBUG | If you can read this message, debug logging is now working
2019-03-01 08:26:38 | INFO | Verbose (DEBUG) logging is enabled
2019-03-01 08:24:56 | WARNING | There were no files located - check the debugging logs if you think this is in error.
2019-03-01 08:21:56 | WARNING | There were no files located - check the debugging logs if you think this is in error.
2019-03-01 08:18:56 | WARNING | There were no files located - check the debugging logs if you think this is in error.

screen shot 2019-03-01 at 8 32 22 am

It seems to be trying to verify SSL even though I have it unchecked

evilhero commented 5 years ago

The testing option might not be working properly against the verify option.

Try doing just a manual search for one specific issue instead of just trying the test and/or the rss options. You should also specify the protocol for your provider. Make sure to enable debug logging so that when we ask for it (and you know we will, cause that's just how we roll), you'll be able to provide the log showing the search run.

DrSeussFreak commented 5 years ago

2019-03-01 09:19:28 | DEBUG | ReScheduled job: Folder Monitor to 2019-03-01 15:22:28
-- | -- | --
2019-03-01 09:19:28 | INFO | [FOLDER-CHECK] Finished checking for newly snatched downloads
2019-03-01 09:19:28 | WARNING | There were no files located - check the debugging logs if you think this is in error.
2019-03-01 09:19:28 | INFO | there are 0 files.
2019-03-01 09:19:28 | DEBUG | [POST-PROCESSING] Manual Run initiated
2019-03-01 09:19:28 | DEBUG | [POST-PROCESSING] Manual Run Post-Processing enabled.
2019-03-01 09:19:28 | DEBUG | [POST-PROCESSING] nzb folder: /torrents/done
2019-03-01 09:19:28 | DEBUG | [POST-PROCESSING] nzb name: Manual Run
2019-03-01 09:19:28 | INFO | [FOLDER-CHECK] Checking folder /torrents/done for newly snatched downloads
2019-03-01 09:18:50 | INFO | [WANTED-SEARCH] Now Queueing Firefly (2018) #4 for search
2019-03-01 09:18:50 | INFO | Initiating manual search for Firefly issue: 4
2019-03-01 09:18:50 | DEBUG | mode: want
2019-03-01 09:18:50 | DEBUG | ComicID: 115251
2019-03-01 09:18:43 | DEBUG | If you can read this message, debug logging is now working
2019-03-01 09:18:43 | INFO | Verbose (DEBUG) logging is enabled

seems to work, seems just an error during validation (can that be fixed?).

When the next commit is pushed, I can test updating again

evilhero commented 5 years ago

The validation can't be suppressed as you're telling Mylar to basically assume it's a valid certificate, when it isn't (personal cert is considered insecure for various reasons). This is meant to inform the user that it's an insecure connection (and it's almost equivalent to using just http as far as validation goes), so us suppressing the message isn't doing anyone any good. I'm still not sure why it's trying to validate - nothing in the code points to it doing anything differently for nzbhydra, so we'll have to do some testing to see what's happening.

Was there a different message during the search ? (I'm assuming it was an insecure warning that would appear in the console, not in the logs - but I could be wrong).

DrSeussFreak commented 5 years ago

added a new series, manually checked nzbhydra2, and found issue 14, but no results found

From logs

01-Mar-2019 10:21:52 - DEBUG   :: mylar.queueissue.1339 : Thread-43 : ComicID: 109575
01-Mar-2019 10:21:52 - DEBUG   :: mylar.queueissue.1340 : Thread-43 : mode: want
01-Mar-2019 10:21:52 - INFO    :: mylar.queueissue.1430 : Thread-43 : Initiating manual search for Sonic the Hedgehog issue: 14
01-Mar-2019 10:21:52 - INFO    :: mylar.queueissue.1473 : Thread-43 : [WANTED-SEARCH] Now Queueing Sonic the Hedgehog (2018) #14 for search
01-Mar-2019 10:22:31 - INFO    :: mylar.run.2810 : Thread-21 : [FOLDER-CHECK] Checking folder /torrents/done for newly snatched downloads
01-Mar-2019 10:22:31 - DEBUG   :: mylar.Process.358 : Thread-21 : [POST-PROCESSING] nzb name: Manual Run
01-Mar-2019 10:22:31 - DEBUG   :: mylar.Process.359 : Thread-21 : [POST-PROCESSING] nzb folder: /torrents/done
01-Mar-2019 10:22:31 - DEBUG   :: mylar.Process.367 : Thread-21 : [POST-PROCESSING] Manual Run Post-Processing enabled.
01-Mar-2019 10:22:31 - DEBUG   :: mylar.Process.399 : Thread-21 : [POST-PROCESSING] Manual Run initiated
01-Mar-2019 10:22:31 - INFO    :: mylar.traverse_directories.1354 : Thread-21 : there are 0 files.
01-Mar-2019 10:22:31 - WARNING :: mylar.Process.405 : Thread-21 : There were no files located - check the debugging logs if you think this is in error.
01-Mar-2019 10:22:31 - INFO    :: mylar.run.2813 : Thread-21 : [FOLDER-CHECK] Finished checking for newly snatched downloads
01-Mar-2019 10:22:31 - DEBUG   :: mylar.job_management.3559 : Thread-21 : ReScheduled job: Folder Monitor to 2019-03-01 16:25:31

from console

2019-03-01 10:22:31 | DEBUG | ReScheduled job: Folder Monitor to 2019-03-01 16:25:31
-- | -- | --
2019-03-01 10:22:31 | INFO | [FOLDER-CHECK] Finished checking for newly snatched downloads
2019-03-01 10:22:31 | WARNING | There were no files located - check the debugging logs if you think this is in error.
2019-03-01 10:22:31 | INFO | there are 0 files.
2019-03-01 10:22:31 | DEBUG | [POST-PROCESSING] Manual Run initiated
2019-03-01 10:22:31 | DEBUG | [POST-PROCESSING] Manual Run Post-Processing enabled.
2019-03-01 10:22:31 | DEBUG | [POST-PROCESSING] nzb folder: /torrents/done
2019-03-01 10:22:31 | DEBUG | [POST-PROCESSING] nzb name: Manual Run
2019-03-01 10:22:31 | INFO | [FOLDER-CHECK] Checking folder /torrents/done for newly snatched downloads
2019-03-01 10:21:52 | INFO | [WANTED-SEARCH] Now Queueing Sonic the Hedgehog (2018) #14 for search
2019-03-01 10:21:52 | INFO | Initiating manual search for Sonic the Hedgehog issue: 14
2019-03-01 10:21:52 | DEBUG | mode: want
2019-03-01 10:21:52 | DEBUG | ComicID: 109575

evilhero commented 5 years ago

You're missing the entire search log from the results. Once it says it's queueing, there should be some information as to the search being performed.

If however, there was a previous traceback the search engine can't fire off properly as it's being locked.

Try restarting Mylar and then searching again for a specific issue, you should receive information about it loading the item from the queue and then see the search results (which are important to see what's being returned as I don't use hydra).

DrSeussFreak commented 5 years ago

Working on this now. On a positive note, auto-update just worked for the new commit.

Version: 3aa96d63788b76dea3ee53d3d3355ce18b132519 (development)

DrSeussFreak commented 5 years ago

01-Mar-2019 10:36:35 - WARNING :: mylar.daemonize.272 : MAIN : There are [<_MainThread(MAIN, started 140644521580352)>, <Thread(AUTO-COMPLETE-NZB, started 140644445726464)>] active threads. Daemonizing may cause                         strange behavior.
01-Mar-2019 10:36:54 - INFO    :: mylar.toggleVerbose.3842 : CP Server Thread-4 : Verbose (DEBUG) logging is enabled
01-Mar-2019 10:36:54 - DEBUG   :: mylar.toggleVerbose.3843 : CP Server Thread-4 : If you can read this message, debug logging is now working
01-Mar-2019 10:37:01 - DEBUG   :: mylar.queueissue.1339 : Thread-13 : ComicID: 109575
01-Mar-2019 10:37:01 - DEBUG   :: mylar.queueissue.1340 : Thread-13 : mode: want
01-Mar-2019 10:37:01 - INFO    :: mylar.queueissue.1430 : Thread-13 : Initiating manual search for Sonic the Hedgehog issue: 13
01-Mar-2019 10:37:01 - INFO    :: mylar.queueissue.1473 : Thread-13 : [WANTED-SEARCH] Now Queueing Sonic the Hedgehog (2018) #13 for search
01-Mar-2019 10:37:02 - INFO    :: mylar.search_queue.3127 : SEARCH-QUEUE : [SEARCH-QUEUE] Now loading item from search queue: {'comicname': u'Sonic the Hedgehog', 'issueid': u'699938', 'seriesyear': u'2018', 'booktype': u'Print', 'issuenumber': u'13', 'comicid': u'109575'}
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.63 : SEARCH-QUEUE : Publisher is : IDW
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.71 : SEARCH-QUEUE : Issue Title given as : None
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.102 : SEARCH-QUEUE : Checking for torrent enabled.
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.153 : SEARCH-QUEUE : nzbprovider(s): [u'newznab: NZBHydra2']
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.156 : SEARCH-QUEUE : There are 0 torrent providers you have selected.
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.161 : SEARCH-QUEUE : There are : 1 nzb providers you have selected
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.163 : SEARCH-QUEUE : Usenet Retention : 1500 days
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.180 : SEARCH-QUEUE : search provider order is [u'newznab: NZBHydra2']
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.247 : SEARCH-QUEUE : calpha/cnumber: None / None
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.257 : SEARCH-QUEUE : srchloop: 2
01-Mar-2019 10:37:02 - DEBUG   :: mylar.search_init.284 : SEARCH-QUEUE : Initiating Search via : api
01-Mar-2019 10:37:02 - DEBUG   :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 10:37:02 - INFO    :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 10:37:02 - DEBUG   :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 10:37:02 - INFO    :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 10:37:02 - DEBUG   :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: indexer-01:9088/api?t=search&q=sonic%20hedgehog%20013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 10:37:02 - WARNING :: mylar.NZB_SEARCH.762 : SEARCH-QUEUE : General Error fetching data from newznab: No connection adapters were found for 'indexer-01:9088/api?t=search&q=sonic%20hedgehog%20013&o=xml&cat=7030&apikey=<removed>&maxage=1500'
01-Mar-2019 10:37:02 - ERROR   :: mylar.excepthook.315 : SEARCH-QUEUE : Uncaught exception: Traceback (most recent call last):
  File "/opt/Mylar/mylar/logger.py", line 337, in new_run
    old_run(*args, **kwargs)
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/opt/Mylar/mylar/helpers.py", line 3133, in search_queue
    ss_queue = mylar.search.searchforissue(item['issueid'])
  File "/opt/Mylar/mylar/search.py", line 1847, in searchforissue
    foundNZB, prov = search_init(ComicName, IssueNumber, str(IssueYear), SeriesYear, Publisher, IssueDate, StoreDate, actissueid, AlternateSearch, UseFuzzy, ComicVersion, SARC=SARC, IssueArcID=IssueArcID, mode=mode, rsscheck=rsscheck, ComicID=ComicID, filesafe=Comicname_filesafe, allow_packs=allow_packs, oneoff=oneoff, manual=manual, torrentid_32p=TorrentID_32p, digitaldate=DigitalDate, booktype=booktype)
  File "/opt/Mylar/mylar/search.py", line 360, in search_init
    findit = NZB_SEARCH(ComicName, IssueNumber, ComicYear, SeriesYear, Publisher, IssueDate, StoreDate, searchprov, send_prov_count, IssDateFix, IssueID, UseFuzzy, newznab_host, ComicVersion=ComicVersion, SARC=SARC, IssueArcID=IssueArcID, RSS="no", ComicID=ComicID, issuetitle=issuetitle, unaltered_ComicName=unaltered_ComicName, allow_packs=allow_packs, oneoff=oneoff, cmloopit=cmloopit, manual=manual, torznab_host=torznab_host, torrentid_32p=torrentid_32p, digitaldate=digitaldate, booktype=booktype)
  File "/opt/Mylar/mylar/search.py", line 763, in NZB_SEARCH
    if e.r.status_code == 503:
AttributeError: 'InvalidSchema' object has no attribute 'r'

DrSeussFreak commented 5 years ago

If I open a browser to

https://indexer-01:9088/api?t=search&q=sonic%20hedgehog%20013&o=xml&cat=7030&apikey=

I do see output that I would expect.

I disabled all torrent searches while we test this.

evilhero commented 5 years ago

The no connection adapters error is indicating that the newznab provider url for hydra needs to be preceded by either https:// or http://)

DrSeussFreak commented 5 years ago

01-Mar-2019 11:03:11 - WARNING :: mylar.daemonize.272 : MAIN : There are [<_MainThread(MAIN, started 140000139929408)>, <Thread(AUTO-COMPLETE-NZB, started 140000064075520)>] active threads. Daemonizing may cause                         strange behavior.
01-Mar-2019 11:03:32 - INFO    :: mylar.toggleVerbose.3842 : CP Server Thread-4 : Verbose (DEBUG) logging is enabled
01-Mar-2019 11:03:32 - DEBUG   :: mylar.toggleVerbose.3843 : CP Server Thread-4 : If you can read this message, debug logging is now working
01-Mar-2019 11:03:35 - DEBUG   :: mylar.queueissue.1339 : Thread-13 : ComicID: 109575
01-Mar-2019 11:03:35 - DEBUG   :: mylar.queueissue.1340 : Thread-13 : mode: want
01-Mar-2019 11:03:35 - INFO    :: mylar.queueissue.1430 : Thread-13 : Initiating manual search for Sonic the Hedgehog issue: 13
01-Mar-2019 11:03:35 - INFO    :: mylar.queueissue.1473 : Thread-13 : [WANTED-SEARCH] Now Queueing Sonic the Hedgehog (2018) #13 for search
01-Mar-2019 11:03:36 - INFO    :: mylar.search_queue.3127 : SEARCH-QUEUE : [SEARCH-QUEUE] Now loading item from search queue: {'comicname': u'Sonic the Hedgehog', 'issueid': u'699938', 'seriesyear': u'2018', 'booktype': u'Print', 'issuenumber': u'13', 'comicid': u'109575'}
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.63 : SEARCH-QUEUE : Publisher is : IDW
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.71 : SEARCH-QUEUE : Issue Title given as : None
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.102 : SEARCH-QUEUE : Checking for torrent enabled.
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.153 : SEARCH-QUEUE : nzbprovider(s): [u'newznab: NZBHydra2']
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.156 : SEARCH-QUEUE : There are 0 torrent providers you have selected.
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.161 : SEARCH-QUEUE : There are : 1 nzb providers you have selected
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.163 : SEARCH-QUEUE : Usenet Retention : 1500 days
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.180 : SEARCH-QUEUE : search provider order is [u'newznab: NZBHydra2']
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.247 : SEARCH-QUEUE : calpha/cnumber: None / None
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.257 : SEARCH-QUEUE : srchloop: 2
01-Mar-2019 11:03:36 - DEBUG   :: mylar.search_init.284 : SEARCH-QUEUE : Initiating Search via : api
01-Mar-2019 11:03:36 - DEBUG   :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 11:03:36 - INFO    :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 11:03:36 - DEBUG   :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 11:03:36 - INFO    :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 11:03:36 - DEBUG   :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: https://indexer-01:9088/api?t=search&q=sonic%20hedgehog%20013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 11:03:36 - WARNING :: mylar.NZB_SEARCH.758 : SEARCH-QUEUE : Connection error trying to retrieve data from newznab: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
01-Mar-2019 11:03:36 - INFO    :: mylar.search_init.396 : SEARCH-QUEUE : Could not find Issue 13 of Sonic the Hedgehog (2018) using NZBHydra2 [api]
01-Mar-2019 11:04:06 - DEBUG   :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 11:04:06 - INFO    :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 11:04:06 - DEBUG   :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 11:04:06 - INFO    :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 11:04:06 - DEBUG   :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: https://indexer-01:9088/api?t=search&q=sonic%20hedgehog%2013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 11:04:07 - WARNING :: mylar.NZB_SEARCH.758 : SEARCH-QUEUE : Connection error trying to retrieve data from newznab: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
01-Mar-2019 11:04:07 - INFO    :: mylar.search_init.396 : SEARCH-QUEUE : Could not find Issue 13 of Sonic the Hedgehog (2018) using NZBHydra2 [api]
01-Mar-2019 11:04:07 - DEBUG   :: mylar.search_init.427 : SEARCH-QUEUE : findit: {'status': False}
01-Mar-2019 11:04:07 - INFO    :: mylar.search_init.431 : SEARCH-QUEUE : Finished searching via : api. Issue not found - status kept as Wanted.

It still seems to try to verify SSL, even though it is disabled

evilhero commented 5 years ago

Check your config.ini - it's saying that your verify is still set to True for some reason, and it only pulls it directly from your ini (ie. it's set to default to False code-wise). Paste in the config.ini line for extra_newzanbs (blank/xxx out your uuid, apikey - but leave the rest intact)

It's also warning about your daemonize at the top of every log you're posting - make sure you've shutdown Mylar entirely as you shouldn't be getting any messages about threads running when it daemonizes unless there's something else occuring outside of the ordinary.

DrSeussFreak commented 5 years ago

I did a complete shutdown of the service before I started the service, not sure why that is finding a problem there

extra_newznabs = NZBHydra2, https://indexer-01:9088, 0, <removed>, , 1

evilhero commented 5 years ago

Yeah the daemonize warning isn't a good one - usually it means the threads are gonna hammer each other and something's gonna die.

Make sure there's no other instance of Mylar running (ie. ps -xg will show all user jobs).

Also on the 1st tab of the configuration it will show what your config.ini location is, make sure that that's the file you're checking against.

DrSeussFreak commented 5 years ago

it is the correct config.ini location

mylar@media-01:~$ ps -xg
   PID TTY      STAT   TIME COMMAND
 20286 ?        Sl     0:04 /usr/bin/python Mylar.py --quiet --daemon --nolaunch --pidfile=/var/run/mylar/mylar.pid --datadir=/opt/Mylar --port=9093
 20865 pts/0    S      0:00 -su
 20872 pts/0    R+     0:00 ps -xg

evilhero commented 5 years ago

Have you tried with a different naming than indexer-01, maybe the ip if it's not on the same machine as mylar - if it's on the same machine, try localhost?

There's definitely something amiss here cause mylar doesn't set the verify true unless specifically told to, which is from the ini.

Do you only have the one newznab entry in your newznab list?

DrSeussFreak commented 5 years ago

It is on a different machine, and I had the IP in place when we saw the problem last night, I switched to a the hostname afterwards.

DrSeussFreak commented 5 years ago

with IP in place

01-Mar-2019 12:06:50 - INFO    :: mylar.NZB_SEARCH.803 : SEARCH-QUEUE : no errors on data retrieval...proceeding
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.844 : SEARCH-QUEUE : checking search result: Sonic The Hedgehog 013 (2019) (Oroboros-DCP)
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.854 : SEARCH-QUEUE : sub: Sonic The Hedgehog 013 (2019) (Oroboros-DCP)
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.903 : SEARCH-QUEUE : comsize_b: 39415800
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.940 : SEARCH-QUEUE : size given as: 37.6 MB
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.986 : SEARCH-QUEUE : store date used is : 2019-02-06
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.987 : SEARCH-QUEUE : date used is : 2019-02-06
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1030 : SEARCH-QUEUE : usedate: 2019-02-06
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1076 : SEARCH-QUEUE : [CONV] Wed, 06 Feb 2019 16:41:38 +0000 is after store date of 2019-02-06
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1096 : SEARCH-QUEUE : Entry: Sonic The Hedgehog 013 (2019) (Oroboros-DCP)
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.287 : SEARCH-QUEUE : Scanner group tag discovered: Oroboros-DCP
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.392 : SEARCH-QUEUE : NEWLY SPLIT REORGD: [u'Sonic', u'The', u'Hedgehog', u'013', u'(2019)']
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.427 : SEARCH-QUEUE : checking date : 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.430 : SEARCH-QUEUE : date: 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.740 : SEARCH-QUEUE : datecheck: [{'date': u'2019', 'position': 4, 'mod_position': 23}]
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.746 : SEARCH-QUEUE : sctd: 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.755 : SEARCH-QUEUE : year verified as : 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.761 : SEARCH-QUEUE : year verified as: 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.784 : SEARCH-QUEUE : highest_series_position: 4
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.790 : SEARCH-QUEUE : possible_issuenumbers: [{'position': 3, 'validcountchk': False, 'number': u'013', 'mod_position': 19}]
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.862 : SEARCH-QUEUE : issue_position: 3
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.879 : SEARCH-QUEUE : issue verified as : 013
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.1003 : SEARCH-QUEUE : sf_highest_series_pos: [u'Sonic', u'The', u'Hedgehog']
01-Mar-2019 12:06:50 - DEBUG   :: mylar.parseit.1035 : SEARCH-QUEUE : series title possibly: Sonic The Hedgehog
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1113 : SEARCH-QUEUE : parsed_info: {'series_volume': None, 'booktype': 'issue', 'issueid': None, 'sub': None, 'comiclocation': None, 'reading_order': None, 'parse_status': 'success', 'dynamic_name': u'Sonic|Hedgehog', 'series_name': u'Sonic The Hedgehog', 'comicfilename': u'Sonic The Hedgehog 013 (2019) (Oroboros-DCP)', 'issue_number': u'013', 'issue_year': '2019', 'scangroup': u'Oroboros-DCP', 'alt_series': None, 'alt_issue': None, 'series_name_decoded': 'Sonic The Hedgehog'}
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1122 : SEARCH-QUEUE : match_check: {'justthedigits': u'013', 'issueid': None, 'match_type': None, 'sub': None, 'comiclocation': None, 'booktype': 'issue', 'series_name': u'Sonic The Hedgehog', 'comicfilename': u'Sonic The Hedgehog 013 (2019) (Oroboros-DCP)', 'annual_comicid': None, 'issue_year': '2019', 'volume': None, 'process_status': 'match', 'scangroup': u'Oroboros-DCP', 'alt_series': None, 'alt_issue': None, 'series_volume': None}
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1186 : SEARCH-QUEUE : year detected: 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1188 : SEARCH-QUEUE : year looking for: 2019
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1190 : SEARCH-QUEUE : 2019 - right years match baby!
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1368 : SEARCH-QUEUE : issue we are looking for is : 13
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1369 : SEARCH-QUEUE : integer value of issue we are looking for : 13000
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1376 : SEARCH-QUEUE : issue we found for is : 013
01-Mar-2019 12:06:50 - DEBUG   :: mylar.NZB_SEARCH.1378 : SEARCH-QUEUE : integer value of issue we have found : 13000
01-Mar-2019 12:06:50 - DEBUG   :: mylar.nzbname_create.2013 : SEARCH-QUEUE : [SEARCHER] entry[title]: Sonic The Hedgehog 013 (2019) (Oroboros-DCP)
01-Mar-2019 12:06:50 - DEBUG   :: mylar.nzbname_create.2018 : SEARCH-QUEUE : [SEARCHER] nzbname (remove chars): Sonic The Hedgehog 013  2019   Oroboros-DCP 
01-Mar-2019 12:06:50 - DEBUG   :: mylar.nzbname_create.2023 : SEARCH-QUEUE : [SEARCHER] nzbname (\s): Sonic The Hedgehog 013 2019 Oroboros-DCP
01-Mar-2019 12:06:50 - DEBUG   :: mylar.nzbname_create.2030 : SEARCH-QUEUE : [SEARCHER] end nzbname: Sonic.The.Hedgehog.013.2019.Oroboros-DCP
01-Mar-2019 12:06:50 - DEBUG   :: mylar.nzbname_create.2035 : SEARCH-QUEUE : nzbname used for post-processing: Sonic.The.Hedgehog.013.2019.Oroboros-DCP
01-Mar-2019 12:06:50 - DEBUG   :: mylar.searcher.2090 : SEARCH-QUEUE : issues match!
01-Mar-2019 12:06:50 - INFO    :: mylar.searcher.2109 : SEARCH-QUEUE : Found Sonic the Hedgehog (2019) #13 using NZBHydra2 (newznab)
01-Mar-2019 12:06:50 - DEBUG   :: mylar.searcher.2111 : SEARCH-QUEUE : link given by: newznab
01-Mar-2019 12:06:50 - INFO    :: mylar.searcher.2114 : SEARCH-QUEUE : nzbid: 5707761160829037471
01-Mar-2019 12:06:50 - INFO    :: mylar.searcher.2115 : SEARCH-QUEUE : IssueID: 699938
01-Mar-2019 12:06:50 - INFO    :: mylar.searcher.2116 : SEARCH-QUEUE : oneoff: False
01-Mar-2019 12:06:50 - INFO    :: mylar.failed_check.244 : SEARCH-QUEUE : prov  : NZBHydra2 (newznab)[5707761160829037471]
01-Mar-2019 12:06:50 - INFO    :: mylar.failed_check.255 : SEARCH-QUEUE : [FAILED_DOWNLOAD_CHECKER] Successfully marked this download as Good for downloadable content
01-Mar-2019 12:06:50 - DEBUG   :: mylar.searcher.2134 : SEARCH-QUEUE : [FAILED_DOWNLOAD_CHECKER] This is not in the failed downloads list. Will continue with the download.
01-Mar-2019 12:06:50 - DEBUG   :: mylar.searcher.2214 : SEARCH-QUEUE : [PAYLOAD-NONE] Download URL: https://10.0.1.75:9088/getnzb/api/5707761160829037471?apikey=xYOUDONTNEEDTOKNOWTHISx [VerifySSL: False]
01-Mar-2019 12:06:51 - DEBUG   :: mylar.searcher.2234 : SEARCH-QUEUE : Status code returned: 200
01-Mar-2019 12:06:51 - DEBUG   :: mylar.searcher.2273 : SEARCH-QUEUE : [FILENAME] filename (remove chars): SonicTheHedgehog0132019Oroboros-DCP.cbr
01-Mar-2019 12:06:51 - DEBUG   :: mylar.searcher.2276 : SEARCH-QUEUE : [FILENAME] nzbname (\s): SonicTheHedgehog0132019Oroboros-DCP
01-Mar-2019 12:06:51 - DEBUG   :: mylar.searcher.2278 : SEARCH-QUEUE : [FILENAME] end nzbname: SonicTheHedgehog0132019Oroboros-DCP
01-Mar-2019 12:06:51 - INFO    :: mylar.searcher.2284 : SEARCH-QUEUE : filen: SonicTheHedgehog0132019Oroboros-DCP -- nzbname: Sonic.The.Hedgehog.013.2019.Oroboros-DCP are not identical. Storing extra value as : SonicTheHedgehog0132019Oroboros-DCP
01-Mar-2019 12:06:51 - DEBUG   :: mylar.searcher.2289 : SEARCH-QUEUE : Cache Directory successfully found at : /opt/Mylar/cache. Ensuring proper permissions.
01-Mar-2019 12:06:51 - ERROR   :: mylar.setperms.1654 : SEARCH-QUEUE : Could not change permissions : /opt/Mylar/cache. Exiting...
01-Mar-2019 12:06:51 - INFO    :: mylar.sender.42 : SEARCH-QUEUE : parameters set to {'nzbname': u'Sonic.The.Hedgehog.013.2019.Oroboros-DCP.nzb', 'apikey': '<removed>', 'name': u'media-01:9093/api?apikey=<removed>&cmd=downloadNZB&nzbname=Sonic.The.Hedgehog.013.2019.Oroboros-DCP.nzb', 'cmd': 'downloadNZB', 'cat': 'comics', 'priority': '1', 'mode': 'addurl', 'output': 'json'}
01-Mar-2019 12:06:51 - INFO    :: mylar.sender.43 : SEARCH-QUEUE : sending now to https://10.0.1.72:9090/api
01-Mar-2019 12:06:51 - INFO    :: mylar.sender.50 : SEARCH-QUEUE : {u'status': True, u'nzo_ids': [None]}
01-Mar-2019 12:06:51 - ERROR   :: mylar.excepthook.315 : SEARCH-QUEUE : Uncaught exception: Traceback (most recent call last):
  File "/opt/Mylar/mylar/logger.py", line 337, in new_run
    old_run(*args, **kwargs)
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/opt/Mylar/mylar/helpers.py", line 3133, in search_queue
    ss_queue = mylar.search.searchforissue(item['issueid'])
  File "/opt/Mylar/mylar/search.py", line 1847, in searchforissue
    foundNZB, prov = search_init(ComicName, IssueNumber, str(IssueYear), SeriesYear, Publisher, IssueDate, StoreDate, actissueid, AlternateSearch, UseFuzzy, ComicVersion, SARC=SARC, IssueArcID=IssueArcID, mode=mode, rsscheck=rsscheck, ComicID=ComicID, filesafe=Comicname_filesafe, allow_packs=allow_packs, oneoff=oneoff, manual=manual, torrentid_32p=TorrentID_32p, digitaldate=DigitalDate, booktype=booktype)
  File "/opt/Mylar/mylar/search.py", line 360, in search_init
    findit = NZB_SEARCH(ComicName, IssueNumber, ComicYear, SeriesYear, Publisher, IssueDate, StoreDate, searchprov, send_prov_count, IssDateFix, IssueID, UseFuzzy, newznab_host, ComicVersion=ComicVersion, SARC=SARC, IssueArcID=IssueArcID, RSS="no", ComicID=ComicID, issuetitle=issuetitle, unaltered_ComicName=unaltered_ComicName, allow_packs=allow_packs, oneoff=oneoff, cmloopit=cmloopit, manual=manual, torznab_host=torznab_host, torrentid_32p=torrentid_32p, digitaldate=digitaldate, booktype=booktype)
  File "/opt/Mylar/mylar/search.py", line 1479, in NZB_SEARCH
    searchresult = searcher(nzbprov, nzbname, mylar.COMICINFO, links, IssueID, ComicID, tmpprov, newznab=newznab_host, torznab=torznab_host, rss=RSS)
  File "/opt/Mylar/mylar/search.py", line 2613, in searcher
    sendtosab = ss.sender()
  File "/opt/Mylar/mylar/sabnzbd.py", line 53, in sender
    'nzo_id': ''.join(sendresponse['nzo_ids']),
TypeError: sequence item 0: expected string, NoneType found

01-Mar-2019 12:08:11 - DEBUG   :: mylar.dbUpdate.85 : Thread-18 : Refresh sequence set to fire every 5 minutes for 7 day(s)
01-Mar-2019 12:08:11 - DEBUG   :: mylar.job_management.3559 : Thread-18 : ReScheduled job: DB Updater to 2019-03-01 18:13:11
01-Mar-2019 12:08:11 - INFO    :: mylar.dbUpdate.353 : Thread-18 : Update complete

evilhero commented 5 years ago

So that worked.

Now it's a sab problem. Do you have CDH enabled or are you using the ComicRN script? What version of sabnzbd are you running? What does the test connection return?

DrSeussFreak commented 5 years ago

Sab 2.3.8 beta1

screen shot 2019-03-01 at 2 08 47 pm

I use CDH

evilhero commented 5 years ago

Did it actually send the nzb to your client or did nothing get there?

Also you have a permissions problem with the cache folder. Mylar needs to send the nzb there first before sending it to your client, so if it can't write to it - she no send. You can also turn off enforce permissions and that should pass that error, provided mylar can write to that directory.

DrSeussFreak commented 5 years ago

nothing made it to sabnzbd, don't see anything there.

I've seen the cache error message, not sure why, as I have 777 permissions with mylar:mylar as owner, and it was recursive.

drwxrwxrwx 67 mylar mylar 69632 Mar 1 12:06 cache

I am seeing some nzb's in the directory, and recent ones, but nothing made it to sabnzbd

screen shot 2019-03-01 at 3 26 55 pm

evilhero commented 5 years ago

Try turning off enforce permissions in mylar, save the config and restart mylar. The nzo_ids being nothing usually only happens when a non-compliant version of sabnzbd is being used, and you're current (albeit beta)

DrSeussFreak commented 5 years ago

Done, the cache warning has gone away, still getting the daemonize warning, which is odd, as there is no other process going for mylar...

01-Mar-2019 15:37:05 - WARNING :: mylar.daemonize.272 : MAIN : There are [<_MainThread(MAIN, started 139952172312384)>, <Thread(AUTO-COMPLETE-NZB, started 139952096458496)>] active threads. Daemonizing may cause strange behavior.

searched for an issue

01-Mar-2019 15:39:23 - INFO    :: mylar.toggleVerbose.3842 : CP Server Thread-5 : Verbose (DEBUG) logging is enabled
01-Mar-2019 15:39:23 - DEBUG   :: mylar.toggleVerbose.3843 : CP Server Thread-5 : If you can read this message, debug logging is now working
01-Mar-2019 15:39:53 - DEBUG   :: mylar.queueissue.1339 : Thread-13 : ComicID: 109575
01-Mar-2019 15:39:53 - DEBUG   :: mylar.queueissue.1340 : Thread-13 : mode: want
01-Mar-2019 15:39:53 - INFO    :: mylar.queueissue.1430 : Thread-13 : Initiating manual search for Sonic the Hedgehog issue: 13
01-Mar-2019 15:39:53 - INFO    :: mylar.queueissue.1473 : Thread-13 : [WANTED-SEARCH] Now Queueing Sonic the Hedgehog (2018) #13 for search
01-Mar-2019 15:39:54 - INFO    :: mylar.search_queue.3127 : SEARCH-QUEUE : [SEARCH-QUEUE] Now loading item from search queue: {'comicname': u'Sonic the Hedgehog', 'issueid': u'699938', 'seriesyear': u'2018', 'booktype': u'Print', 'issuenumber': u'13', 'comicid': u'109575'}
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.63 : SEARCH-QUEUE : Publisher is : IDW
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.71 : SEARCH-QUEUE : Issue Title given as : None
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.102 : SEARCH-QUEUE : Checking for torrent enabled.
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.153 : SEARCH-QUEUE : nzbprovider(s): [u'newznab: NZBHydra2']
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.156 : SEARCH-QUEUE : There are 0 torrent providers you have selected.
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.161 : SEARCH-QUEUE : There are : 1 nzb providers you have selected
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.163 : SEARCH-QUEUE : Usenet Retention : 1500 days
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.180 : SEARCH-QUEUE : search provider order is [u'newznab: NZBHydra2']
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.247 : SEARCH-QUEUE : calpha/cnumber: None / None
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.257 : SEARCH-QUEUE : srchloop: 2
01-Mar-2019 15:39:54 - DEBUG   :: mylar.search_init.284 : SEARCH-QUEUE : Initiating Search via : api
01-Mar-2019 15:39:54 - DEBUG   :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 15:39:54 - INFO    :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 15:39:54 - DEBUG   :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 15:39:54 - INFO    :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 15:39:54 - DEBUG   :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: https://10.0.1.75:9088/api?t=search&q=sonic%20hedgehog%20013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 15:39:54 - WARNING :: mylar.NZB_SEARCH.758 : SEARCH-QUEUE : Connection error trying to retrieve data from newznab: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
01-Mar-2019 15:39:54 - INFO    :: mylar.search_init.396 : SEARCH-QUEUE : Could not find Issue 13 of Sonic the Hedgehog (2018) using NZBHydra2 [api]
01-Mar-2019 15:40:08 - INFO    :: mylar.run.2810 : Thread-14 : [FOLDER-CHECK] Checking folder /torrents/done for newly snatched downloads
01-Mar-2019 15:40:08 - DEBUG   :: mylar.Process.358 : Thread-14 : [POST-PROCESSING] nzb name: Manual Run
01-Mar-2019 15:40:08 - DEBUG   :: mylar.Process.359 : Thread-14 : [POST-PROCESSING] nzb folder: /torrents/done
01-Mar-2019 15:40:08 - DEBUG   :: mylar.Process.367 : Thread-14 : [POST-PROCESSING] Manual Run Post-Processing enabled.
01-Mar-2019 15:40:08 - DEBUG   :: mylar.Process.399 : Thread-14 : [POST-PROCESSING] Manual Run initiated
01-Mar-2019 15:40:08 - INFO    :: mylar.traverse_directories.1355 : Thread-14 : there are 0 files.
01-Mar-2019 15:40:08 - WARNING :: mylar.Process.405 : Thread-14 : There were no files located - check the debugging logs if you think this is in error.
01-Mar-2019 15:40:08 - INFO    :: mylar.run.2813 : Thread-14 : [FOLDER-CHECK] Finished checking for newly snatched downloads
01-Mar-2019 15:40:08 - DEBUG   :: mylar.job_management.3559 : Thread-14 : ReScheduled job: Folder Monitor to 2019-03-01 21:43:08
01-Mar-2019 15:40:24 - DEBUG   :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 15:40:24 - INFO    :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 15:40:24 - DEBUG   :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 15:40:24 - INFO    :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 15:40:24 - DEBUG   :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: https://10.0.1.75:9088/api?t=search&q=sonic%20hedgehog%2013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 15:40:24 - WARNING :: mylar.NZB_SEARCH.758 : SEARCH-QUEUE : Connection error trying to retrieve data from newznab: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
01-Mar-2019 15:40:24 - INFO    :: mylar.search_init.396 : SEARCH-QUEUE : Could not find Issue 13 of Sonic the Hedgehog (2018) using NZBHydra2 [api]
01-Mar-2019 15:40:24 - DEBUG   :: mylar.search_init.427 : SEARCH-QUEUE : findit: {'status': False}
01-Mar-2019 15:40:24 - INFO    :: mylar.search_init.431 : SEARCH-QUEUE : Finished searching via : api. Issue not found - status kept as Wanted.

evilhero commented 5 years ago

Your verify switched back to True again... The previous log it was False and it was able to retrieve the results fine.

Try doing a sudo systemctl stop mylar, sudo systemctl status mylar, and then run it directly from the within the mylar directory from the command line as python Mylar.py -v.

Then try the search again.. Something is flipping the ssl to True somehow.

DrSeussFreak commented 5 years ago

root@media-01:~# systemctl stop mylar
root@media-01:/opt/Mylar# ps -ef | grep mylar
root      23293  23255  0 15:52 pts/0    00:00:00 grep --color=auto mylar
root@media-01:/opt/Mylar# systemctl status mylar
● mylar.service - starts instance of Mylar
   Loaded: loaded (/etc/init.d/mylar; enabled; vendor preset: enabled)
   Active: inactive (dead) since Fri 2019-03-01 15:52:03 CST; 29s ago
  Process: 23272 ExecStop=/etc/init.d/mylar stop (code=exited, status=0/SUCCESS)
  Process: 22961 ExecStart=/etc/init.d/mylar start (code=exited, status=0/SUCCESS)

Mar 01 15:37:04 media-01 mylar[22961]:  * Starting mylar
Mar 01 15:37:05 media-01 mylar[22961]: log language set to en_US
Mar 01 15:37:05 media-01 mylar[22961]: Quiet logging mode enabled...
Mar 01 15:37:05 media-01 mylar[22961]: Initializing startup sequence....
Mar 01 15:37:05 media-01 mylar[22961]:    ...done.
Mar 01 15:37:05 media-01 systemd[1]: Started starts instance of Mylar.
Mar 01 15:52:03 media-01 systemd[1]: Stopping starts instance of Mylar...
Mar 01 15:52:03 media-01 mylar[23272]:  * Stopping mylar
Mar 01 15:52:03 media-01 mylar[23272]:    ...done.
Mar 01 15:52:03 media-01 systemd[1]: Stopped starts instance of Mylar.
root@media-01:/opt/Mylar# python Mylar.py -v
log language set to en_US
Verbose/Debugging mode enabled...
Initializing startup sequence....
01-Mar-2019 15:53:08 - DEBUG :: mylar.configure.767 : MainThread : Log dir: /opt/Mylar/logs
01-Mar-2019 15:53:08 - DEBUG :: mylar.configure.894 : MainThread : Setting ComicTagger settings default path to : /opt/Mylar/lib/comictaggerlib/ct_settings
01-Mar-2019 15:53:08 - INFO :: mylar.configure.908 : MainThread : [SAB-MONITOR] Completed post-processing handling enabled for SABnzbd. Attempting to background load....
01-Mar-2019 15:53:08 - INFO :: mylar.configure.914 : MainThread : [AUTO-COMPLETE-NZB] Succesfully started Completed post-processing handling for SABnzbd - will now monitor for completed nzbs within sabnzbd and post-process automatically...
01-Mar-2019 15:53:08 - INFO :: mylar.initialize.185 : MainThread : Checking to see if the database has all tables....
01-Mar-2019 15:53:08 - INFO :: mylar.csv_load.1204 : MainThread : Populating Base Exception listings into Mylar....
01-Mar-2019 15:53:08 - INFO :: mylar.csv_load.1206 : MainThread : Populating Custom Exception listings into Mylar....
01-Mar-2019 15:53:08 - INFO :: mylar.dbcheck.1150 : MainThread : Ensuring DB integrity - Removing all Erroneous Comics (ie. named None)
01-Mar-2019 15:53:08 - INFO :: mylar.dbcheck.1152 : MainThread : Correcting Null entries that make the main page break on startup.
01-Mar-2019 15:53:08 - INFO :: mylar.initialize.199 : MainThread : Successfully discovered local IP and locking it in as : 10.0.1.71
01-Mar-2019 15:53:08 - DEBUG :: mylar.initialize.211 : MainThread : Logger set to use : Rotational Log Handler (default)
01-Mar-2019 15:53:08 - DEBUG :: mylar.initialize.244 : MainThread : SEARCH_TIER_DATE set to : 2019-02-15
01-Mar-2019 15:53:08 - INFO :: mylar.initialize.258 : MainThread : Remapping the sorting to allow for new additions.
01-Mar-2019 15:53:08 - INFO :: mylar.ComicSort.759 : MainThread : Sucessfully ordered 954 series in your watchlist.
01-Mar-2019 15:53:08 - INFO :: mylar.validateAndCreateDirectory.1567 : MainThread : [DIRECTORY-CHECK] Found comic directory: /opt/Mylar
01-Mar-2019 15:53:08 - INFO :: mylar.initialize.72 : MAIN : Starting Mylar on https://0.0.0.0:9093/
01-Mar-2019 15:53:08 - INFO :: mylar.versionload.309 : MAIN : Version information: development [3aa96d63788b76dea3ee53d3d3355ce18b132519]
01-Mar-2019 15:53:11 - DEBUG :: mylar.checkGithub.181 : MAIN : Comparing currently installed version [3aa96d63788b76dea3ee53d3d3355ce18b132519] with latest github version [3aa96d63788b76dea3ee53d3d3355ce18b132519]
01-Mar-2019 15:53:11 - INFO :: mylar.checkGithub.196 : MAIN : Mylar is up to date
01-Mar-2019 15:53:11 - INFO :: mylar.start.352 : MAIN : DB Updater sccheduled to fire every 5 minutes
01-Mar-2019 15:53:11 - DEBUG :: mylar.start.362 : MAIN : [AUTO-SEARCH] Search last run @ 2019-03-01 20:18:19.149384
01-Mar-2019 15:53:11 - DEBUG :: mylar.start.372 : MAIN : [AUTO-SEARCH] Scheduling next run @ 2019-03-02 02:18:19.149393 every 360 minutes
01-Mar-2019 15:53:11 - INFO :: mylar.start.386 : MAIN : [SAB-MONITOR] Completed post-processing handling enabled for SABnzbd. Attempting to background load....
01-Mar-2019 15:53:11 - INFO :: mylar.start.392 : MAIN : [AUTO-COMPLETE-NZB] Succesfully started Completed post-processing handling for SABnzbd - will now monitor for completed nzbs within sabnzbd and post-process automatically....
01-Mar-2019 15:53:11 - INFO :: mylar.start.396 : MAIN : [SEARCH-QUEUE] Attempting to background load the search queue....
01-Mar-2019 15:53:11 - INFO :: mylar.start.401 : MAIN : [POST-PROCESS-QUEUE] Post Process queue enabled & monitoring for api requests....
01-Mar-2019 15:53:11 - INFO :: mylar.start.404 : MAIN : [POST-PROCESS-QUEUE] Succesfully started Post-Processing Queuer....
01-Mar-2019 15:53:11 - INFO :: mylar.start.420 : MAIN : [WEEKLY] Checking for existance of Weekly Comic listing...
01-Mar-2019 15:53:11 - DEBUG :: mylar.start.445 : MAIN : [WEEKLY] Scheduling next run for @ 2019-03-02 00:28:14.191607 every 4 hours
01-Mar-2019 15:53:11 - INFO :: mylar.start.478 : MAIN : [FOLDER MONITOR] Enabling folder monitor for : /torrents/done every 3 minutes.
01-Mar-2019 15:53:11 - INFO :: mylar.start.486 : MAIN : Firing up the Background Schedulers now....
01-Mar-2019 15:53:11 - INFO :: mylar.start.490 : MAIN : Background Schedulers successfully started...
01-Mar-2019 15:53:18 - INFO :: mylar.on_login.120 : CP Server Thread-4 : DrSeussFreak successfully logged on.
01-Mar-2019 15:53:40 - DEBUG :: mylar.queueissue.1339 : Thread-13 : ComicID: 109575
01-Mar-2019 15:53:40 - DEBUG :: mylar.queueissue.1340 : Thread-13 : mode: want
01-Mar-2019 15:53:40 - INFO :: mylar.queueissue.1430 : Thread-13 : Initiating manual search for Sonic the Hedgehog issue: 13
01-Mar-2019 15:53:40 - INFO :: mylar.queueissue.1473 : Thread-13 : [WANTED-SEARCH] Now Queueing Sonic the Hedgehog (2018) #13 for search
01-Mar-2019 15:53:41 - INFO :: mylar.search_queue.3127 : SEARCH-QUEUE : [SEARCH-QUEUE] Now loading item from search queue: {'comicname': u'Sonic the Hedgehog', 'issueid': u'699938', 'seriesyear': u'2018', 'booktype': u'Print', 'issuenumber': u'13', 'comicid': u'109575'}
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.63 : SEARCH-QUEUE : Publisher is : IDW
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.71 : SEARCH-QUEUE : Issue Title given as : None
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.102 : SEARCH-QUEUE : Checking for torrent enabled.
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.153 : SEARCH-QUEUE : nzbprovider(s): [u'newznab: NZBHydra2']
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.156 : SEARCH-QUEUE : There are 0 torrent providers you have selected.
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.161 : SEARCH-QUEUE : There are : 1 nzb providers you have selected
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.163 : SEARCH-QUEUE : Usenet Retention : 1500 days
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.180 : SEARCH-QUEUE : search provider order is [u'newznab: NZBHydra2']
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.247 : SEARCH-QUEUE : calpha/cnumber: None / None
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.257 : SEARCH-QUEUE : srchloop: 2
01-Mar-2019 15:53:41 - DEBUG :: mylar.search_init.284 : SEARCH-QUEUE : Initiating Search via : api
01-Mar-2019 15:53:41 - DEBUG :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 15:53:41 - INFO :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 15:53:41 - DEBUG :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 15:53:41 - INFO :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 15:53:41 - DEBUG :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: https://10.0.1.75:9088/api?t=search&q=sonic%20hedgehog%20013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 15:53:41 - WARNING :: mylar.NZB_SEARCH.758 : SEARCH-QUEUE : Connection error trying to retrieve data from newznab: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
01-Mar-2019 15:53:41 - INFO :: mylar.search_init.396 : SEARCH-QUEUE : Could not find Issue 13 of Sonic the Hedgehog (2018) using NZBHydra2 [api]
01-Mar-2019 15:54:11 - DEBUG :: mylar.NZB_SEARCH.487 : SEARCH-QUEUE : Using Newznab host of : NZBHydra2
01-Mar-2019 15:54:11 - INFO :: mylar.NZB_SEARCH.514 : SEARCH-QUEUE : Shhh be very quiet...I'm looking for Sonic the Hedgehog issue: 13 (2019) using NZBHydra2 (newznab).
01-Mar-2019 15:54:11 - DEBUG :: mylar.NZB_SEARCH.578 : SEARCH-QUEUE : findloop: 0 / findcount: 1
01-Mar-2019 15:54:11 - INFO :: mylar.NZB_SEARCH.731 : SEARCH-QUEUE : Pausing for 60 seconds before continuing to avoid hammering
01-Mar-2019 15:54:11 - DEBUG :: mylar.NZB_SEARCH.749 : SEARCH-QUEUE : [SSL: True] Search URL: https://10.0.1.75:9088/api?t=search&q=sonic%20hedgehog%2013&o=xml&cat=7030&apikey=xUDONTNEEDTOKNOWTHISx
01-Mar-2019 15:54:12 - WARNING :: mylar.NZB_SEARCH.758 : SEARCH-QUEUE : Connection error trying to retrieve data from newznab: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:726)
01-Mar-2019 15:54:12 - INFO :: mylar.search_init.396 : SEARCH-QUEUE : Could not find Issue 13 of Sonic the Hedgehog (2018) using NZBHydra2 [api]
01-Mar-2019 15:54:12 - DEBUG :: mylar.search_init.427 : SEARCH-QUEUE : findit: {'status': False}
01-Mar-2019 15:54:12 - INFO :: mylar.search_init.431 : SEARCH-QUEUE : Finished searching via : api. Issue not found - status kept as Wanted.

evilhero commented 5 years ago

In the log a few above, where it has the nzo_ids error and you were using the IP - you tailed the log and it cut right at the point where it indicates the url/verify that was attempted for the search.

That worked, but now its not - so what was the url/verify in that log or the lines that are missing from the start?

DrSeussFreak commented 5 years ago

nothing changed there

evilhero commented 5 years ago

See if you can find that log from the nzo_ids error and it'll show what the settings were - there's no reason as to why it would work once, then fail if nothing has changed (it just doesn't make sense atm)

DrSeussFreak commented 5 years ago

I cleared the logs a bit ago, after one of the shutdowns, tried to clear up the clutter, make it easier to review.

As far as settings go, nothing has changed, outside of what you have recommended

evilhero commented 5 years ago

From discussion on irc, check to see what the user is that's actually running mylar: ps auxwww | grep mylar

DrSeussFreak commented 5 years ago

root@media-01:~# ps auxwww | grep mylar
mylar     23437  0.1  2.1 2443864 133316 ?      Sl   Mar01   1:36 /usr/bin/python Mylar.py --quiet --daemon --nolaunch --pidfile=/var/run/mylar/mylar.pid --datadir=/opt/Mylar --port=9093
root      32359  0.0  0.0  13136  1060 pts/0    S+   14:05   0:00 grep --color=auto mylar

DrSeussFreak commented 5 years ago

I am going to close this, as when i rebuilt my home lab, this issue went away (the update issue to be clear)

evilhero / mylar

Auto-Update failing #2222