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.

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

Trying to find cause of issue #2345 #2347

Merged
merged 5 commits into from Nov 25, 2022

Conversation

puzzledsab
Copy link
Contributor

See #2345 for comments about the issue.

@sanderjo
Copy link
Contributor

Can I already verify this?

I did this:

git clone https://github.com/puzzledsab/sabnzbd.git puzzledsab
cd puzzledsab/
./SABnzbd.py -b1 

As expected: traceback still there

git branch -a
git checkout origin/bugfix/non_usenetserver
./SABnzbd.py -b1

... and traceback still there. Version seems correct: 3.8.0-develop [1c4a5da]

Is this the correct method?

image

@puzzledsab
Copy link
Contributor Author

@sanderjo : That should be correct, could you try the updated version?

else:
# nothing returned, so there was a connection problem
logging.debug("%s: No successful IP connection was possible using happyeyeballs", self.host)
if not ip or cfg.load_balancing == 0 or len(self.info) == 1:
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not correct. Missing ()

@sanderjo
Copy link
Contributor

I tried, with a fresh clone from your repo. But SAB keeps hanging on www.google.nl. So far is has not fallen back / switched over to the next (working) newsserver.

Version: 3.8.0-develop [28b18cb]

2022-11-21 20:59:58,208::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:00:01,213::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:00:01,214::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3005 ms
2022-11-21 21:00:01,214::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:00:01,214::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:01:01,275::INFO::[notifier:123] Sending notification: Warning - Failed to connect: timed out 2a00:1450:400e:802::2003:119 (type=warning, job_cat=None)
2022-11-21 21:01:01,275::WARNING::[newswrapper:406] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:01:01,284::DEBUG::[downloader:978] Re-adding article TqHaSdLuNlWvAaFqZlHqZzJr-1658672640762@nyuu from sometestfile-100MB.part02.rar to server <Server: www.google.nl:119>
2022-11-21 21:02:01,359::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:02:04,362::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:02:04,362::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3003 ms
2022-11-21 21:02:04,362::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:02:04,363::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:03:04,402::INFO::[newswrapper:404] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:03:04,434::DEBUG::[downloader:978] Re-adding article TqHaSdLuNlWvAaFqZlHqZzJr-1658672640762@nyuu from sometestfile-100MB.part02.rar to server <Server: www.google.nl:119>
2022-11-21 21:04:04,506::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:04:07,543::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:04:07,544::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3037 ms
2022-11-21 21:04:07,544::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:04:07,544::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:05:07,603::INFO::[newswrapper:404] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:05:07,622::INFO::[downloader:673] 1@news.eweka.nl: Initiating connection
2022-11-21 21:05:07,641::INFO::[happyeyeballs:97] Quickest IP address for news.eweka.nl (port 563, preferipv6 False) is 81.171.92.205
2022-11-21 21:05:07,641::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 18 ms
2022-11-21 21:05:07,642::DEBUG::[downloader:186] news.eweka.nl: Connecting to address 81.171.92.205
2022-11-21 21:05:07,709::INFO::[newswrapper:346] 1@news.eweka.nl: Connected using TLSv1.3 (TLS_AES_256_GCM_SHA384)
2022-11-21 21:05:08,707::INFO::[downloader:890] Connecting 1@news.eweka.nl finished

(SABnzbd.py:79084): Gtk-CRITICAL **: 21:05:09.378: gtk_widget_get_scale_factor: assertion 'GTK_IS_WIDGET (widget)' failed
2022-11-21 21:06:07,856::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:06:10,879::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:06:10,879::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3022 ms
2022-11-21 21:06:10,880::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:06:10,880::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:07:10,938::INFO::[newswrapper:404] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:07:10,948::DEBUG::[downloader:978] Re-adding article SdNiSzMzVdJkFtTtGtJyEcKi-1658672640859@nyuu from sometestfile-100MB.part02.rar to server <Server: www.google.nl:119>



@puzzledsab
Copy link
Contributor Author

puzzledsab commented Nov 21, 2022

Did you sett the Google server as optional? Otherwise it won't be disabled.

Required: Will never give up trying to download an article unless it can connect to the server and it says it's missing.
Optional: Will(/should) deactivate the server completely for 10 minutes if there are problems like this.
Neither: Will try all articles three times before giving up and moving on to the next article.

It should probably be changed in to a single drop down choice because selecting both makes no sense.

@sanderjo
Copy link
Contributor

Did you sett the Google server as optional? Otherwise it won't be disabled.

Ah. Yes. Now I have. And it went OK. No more tracebacks.

So people have to check Optional under Advanced? And the reason for that is to avoid falling back automaticall/default to blockservers?

2022-11-21 21:38:36,062::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:38:39,066::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:38:39,066::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3003 ms
2022-11-21 21:38:39,066::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:38:39,066::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:39:39,126::INFO::[notifier:123] Sending notification: Warning - Failed to connect: timed out 2a00:1450:400e:802::2003:119 (type=warning, job_cat=None)
2022-11-21 21:39:39,126::WARNING::[newswrapper:406] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:39:39,139::DEBUG::[downloader:978] Re-adding article XyLjFiRjRuWmHeVhHmIhIzTg-1658672641200@nyuu from sometestfile-100MB.part03.rar to server <Server: www.google.nl:119>
2022-11-21 21:40:39,210::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:40:42,215::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:40:42,215::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3005 ms
2022-11-21 21:40:42,215::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:40:42,215::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:41:42,274::INFO::[newswrapper:404] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:41:42,284::DEBUG::[downloader:978] Re-adding article XyLjFiRjRuWmHeVhHmIhIzTg-1658672641200@nyuu from sometestfile-100MB.part03.rar to server <Server: www.google.nl:119>
2022-11-21 21:42:42,357::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:42:45,386::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:42:45,386::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3028 ms
2022-11-21 21:42:45,387::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:42:45,387::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:43:45,448::INFO::[newswrapper:404] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:43:45,460::INFO::[downloader:673] 1@news.eweka.nl: Initiating connection
2022-11-21 21:43:45,490::INFO::[happyeyeballs:97] Quickest IP address for news.eweka.nl (port 563, preferipv6 False) is 81.171.92.205
2022-11-21 21:43:45,491::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 30 ms
2022-11-21 21:43:45,491::DEBUG::[downloader:186] news.eweka.nl: Connecting to address 81.171.92.205
2022-11-21 21:43:45,554::INFO::[newswrapper:346] 1@news.eweka.nl: Connected using TLSv1.3 (TLS_AES_256_GCM_SHA384)
2022-11-21 21:43:46,558::INFO::[downloader:890] Connecting 1@news.eweka.nl finished

(SABnzbd.py:81410): Gtk-CRITICAL **: 21:43:47.219: gtk_widget_get_scale_factor: assertion 'GTK_IS_WIDGET (widget)' failed
2022-11-21 21:44:45,727::INFO::[downloader:673] 1@www.google.nl: Initiating connection
2022-11-21 21:44:48,730::INFO::[happyeyeballs:97] Quickest IP address for www.google.nl (port 119, preferipv6 False) is None
2022-11-21 21:44:48,730::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 3002 ms
2022-11-21 21:44:48,730::DEBUG::[downloader:189] www.google.nl: No successful IP connection was possible using happyeyeballs
2022-11-21 21:44:48,731::DEBUG::[downloader:193] www.google.nl: Connecting to address 2a00:1450:400e:802::2003
2022-11-21 21:45:48,790::INFO::[newswrapper:404] Failed to connect: timed out 2a00:1450:400e:802::2003:119
2022-11-21 21:45:48,800::DEBUG::[downloader:978] Re-adding article IvKxDaYbZkGhMsJiZcXtMhFk-1658672641311@nyuu from sometestfile-100MB.part03.rar to server <Server: www.google.nl:119>
2022-11-21 21:45:48,800::DEBUG::[downloader:223] Resetting article queue for <Server: www.google.nl:119>
2022-11-21 21:45:48,801::INFO::[notifier:123] Sending notification: Warning - Server www.google.nl will be ignored for 10 minutes (type=warning, job_cat=None)
2022-11-21 21:45:48,801::WARNING::[downloader:501] Server www.google.nl will be ignored for 10 minutes
2022-11-21 21:45:48,801::DEBUG::[downloader:1028] Set planned server resume www.google.nl in 10 mins
2022-11-21 21:45:48,801::DEBUG::[downloader:955] Thread 1@www.google.nl: forcing disconnect
2022-11-21 21:45:48,801::INFO::[downloader:673] 2@news.eweka.nl: Initiating connection
2022-11-21 21:45:48,825::INFO::[happyeyeballs:97] Quickest IP address for news.eweka.nl (port 563, preferipv6 False) is 81.171.92.205
2022-11-21 21:45:48,825::DEBUG::[happyeyeballs:99] Happy Eyeballs lookup and port connect took 23 ms
2022-11-21 21:45:48,825::DEBUG::[downloader:186] news.eweka.nl: Connecting to address 81.171.92.205
2022-11-21 21:45:48,826::INFO::[downloader:673] 3@news.eweka.nl: Initiating connection
2022-11-21 21:45:48,826::DEBUG::[downloader:175] news.eweka.nl: Re-using address 81.171.92.205
2022-11-21 21:45:48,826::INFO::[downloader:673] 4@news.eweka.nl: Initiating connection
2022-11-21 21:45:48,826::DEBUG::[downloader:175] news.eweka.nl: Re-using address 81.171.92.205
2022-11-21 21:45:48,827::INFO::[downloader:673] 5@news.eweka.nl: Initiating connection
2022-11-21 21:45:48,827::DEBUG::[downloader:175] news.eweka.nl: Re-using address 81.171.92.205
2022-11-21 21:45:48,827::INFO::[downloader:673] 6@news.eweka.nl: Initiating connection
2022-11-21 21:45:48,827::DEBUG::[downloader:175] news.eweka.nl: Re-using address 81.171.92.205

image

@sanderjo
Copy link
Contributor

I removed the Optional check, and no download (as expected), but ... nice Warnings. A pity those contains IP addresses (not the server name), but at least this should be an alert to a user (like me).

image

@puzzledsab
Copy link
Contributor Author

Good point about the IP address. It might be useful in some cases for debugging, but probably not for most users. I changed it to www.google.nl:8888 (142.250.74.3).

Besides that it seems like this fixes at least two issues, the stack traces when using happy with this kind of non reachable server and making sure they aren't skipped if they are marked as required. I'm less sure about the implementation. Particularly the check for the warning message. Maybe it should be done elsewhere. My problem is that it's normally done in the section where NNTP status messages are checked and it never reaches that point.

@sanderjo
Copy link
Contributor

Much better!

Do you understand why there are only two warnings?

image

@puzzledsab
Copy link
Contributor Author

It prints a warning if the error message has changed since last check and those strings contain different IPs.

@Safihre
Copy link
Member

Safihre commented Nov 22, 2022

So in this case (unreachable server), there's no difference between Required and no special setting?
But when there is NNTP-problems, then Required makes sure we wait while without Required we would give them a timeout?
Just double checking!

@puzzledsab
Copy link
Contributor Author

puzzledsab commented Nov 22, 2022

So in this case (unreachable server), there's no difference between Required and no special setting?

There weren't, but there will be with this patch because it will no longer stop trying to fetch an article after 3 tries.

But when there is NNTP-problems, then Required makes sure we wait while without Required we would give them a timeout?

Yes.

Maybe it would be better if it was consistent, but problems are a bit different. Some of the NNTP problems would cause SAB to hammer the server if we just ignored it and tried again when required is set. The unreachable server error has a fairly long time out and is done in separate threads so it doesn't cause the same problems if we don't give up. It also lets the user continue downloading if there are articles available for other servers.

@Safihre
Copy link
Member

Safihre commented Nov 23, 2022

This stuff is a bit of a mess (not because of this PR, but historically).
I was investigating the purpose of nw.error_msg and saw this:

if nw.nntp and nw.nntp.error_msg:
# Already showed error
self.__reset_nw(nw)
else:
self.__reset_nw(nw, "timed out", warn=True)
server.bad_cons += 1
self.maybe_block_server(server)

And then checking, I saw this:
def maybe_block_server(self, server: Server):
# Was it resolving problem?
if server.info is False:
# Warn about resolving issues
errormsg = T("Cannot connect to server %s [%s]") % (server.host, T("Server name does not resolve"))
if server.errormsg != errormsg:
server.errormsg = errormsg
logging.warning(errormsg)
if not server.required:
logging.warning(T("Server %s will be ignored for %s minutes"), server.host, _PENALTY_TIMEOUT)

It seems that failing to connect should be reported there but somehow isn't?

@puzzledsab
Copy link
Contributor Author

The maybe_block_server part only triggers if server.info is False. In this case we are using a valid host name but the server doesn't respond on that port or it's not an NNTP server. Also I didn't want to trigger that part because it specifically says "Server name does not resolve", which would be wrong. That could be changed, of course.

Another difference is that maybe_block_server uses server.errormsg, while newswrapper sets server.warning. I don't understand what the conceptual differences between those variables are.

@Safihre
Copy link
Member

Safihre commented Nov 23, 2022

Pff I am trying to understand the current error handling code and how we could improve it, but it's really some thick spaghetti. I feel there should be a way to consolidate this better and avoid having 3 spots where we handle errors.
This PR seems fine so we can probably merge and then try to improve things.

The difference between the server.errormsg and server.warning should be that warnings can happen for example to a single thread, while errors should are fully blocking a server. I hope that is correctly implemented.

@Safihre Safihre merged commit ee2b2b2 into sabnzbd:develop Nov 25, 2022
@puzzledsab puzzledsab deleted the bugfix/non_usenetserver branch November 28, 2022 21:22
puzzledsab added a commit to puzzledsab/sabnzbd that referenced this pull request Dec 5, 2022
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Sep 19, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants