Nyuu just hangs at 99%, sometimes even at 100%

[df-a]

Hello,

Nyuu sometimes randomly hangs at 99%, sometimes even at 100%. It doesn't happen all the time.

I have skip-errors: true. I also have multiple servers configured, yet only one is configured for checking the articles posted.

This is what the built in web server reported after one recent such hang:

Time: Wed Nov 23 2022 23:27:25 GMT-0400 (Atlantic Standard Time)
Start time: Wed Nov 23 2022 22:01:00 GMT-0400 (Atlantic Standard Time)

Total articles: 7084 (4936.98 MiB)
Articles read: 7084 (100.00%) (+4 re-read)
Articles posted: 7083 (99.99%) (+6 re-posted)
Articles checked: 7083 (99.99%)
Errors skipped: 1 across 1 article(s)
Upload Rate (network|real): 1058.74 KiB/s | 974.98 KiB/s

Post queue size: 0 (0.00% full)
Check queue size: 0 + 0 delayed (0.00% full)
Check cache size: 0 (0.00% full)
Re-read queue size: 0

===== Post Connections' Status =====
Connection #1
  State: inactive for 70.662s
  Transfer: 23.13 KiB down / 331.52 MiB up
  Requests: 463 (463 posts)
  Reconnects: 0
  Errors: 1

Connection #2
  State: inactive for 70.145s
  Transfer: 24.92 KiB down / 358.83 MiB up
  Requests: 499 (499 posts)
  Reconnects: 0
  Errors: 1

Connection #3
  State: inactive for 69.291s
  Transfer: 22.63 KiB down / 326.3 MiB up
  Requests: 453 (453 posts)
  Reconnects: 0
  Errors: 1

Connection #4
  State: inactive for 1635.059s
  Transfer: 16.62 KiB down / 239.3 MiB up
  Requests: 332 (332 posts)
  Reconnects: 0
  Errors: 2

Connection #5
  State: idle for 250.779s
  Transfer: 105.7 KiB down / 677.51 MiB up
  Requests: 943 (943 posts)
  Reconnects: 0
  Errors: 0

Connection #6
  State: idle for 250.08s
  Transfer: 122.36 KiB down / 785.64 MiB up
  Requests: 1092 (1092 posts)
  Reconnects: 0
  Errors: 0

Connection #7
  State: idle for 251.017s
  Transfer: 77.34 KiB down / 499.07 MiB up
  Requests: 692 (692 posts)
  Reconnects: 0
  Errors: 5

Connection #8
  State: idle for 251.417s
  Transfer: 117.52 KiB down / 754.87 MiB up
  Requests: 1049 (1049 posts)
  Reconnects: 0
  Errors: 0

Connection #9
  State: idle for 250.468s
  Transfer: 29.17 KiB down / 279.75 MiB up
  Requests: 389 (389 posts)
  Reconnects: 0
  Errors: 0

Connection #10
  State: idle for 248.649s
  Transfer: 31.9 KiB down / 305.39 MiB up
  Requests: 425 (425 posts)
  Reconnects: 0
  Errors: 0

Connection #11
  State: idle for 246.116s
  Transfer: 27.58 KiB down / 264.56 MiB up
  Requests: 367 (367 posts)
  Reconnects: 0
  Errors: 0

Connection #12
  State: idle for 245.679s
  Transfer: 29.35 KiB down / 281.89 MiB up
  Requests: 391 (391 posts)
  Reconnects: 0
  Errors: 0

===== Check Connections' Status =====
Connection #1
  State: inactive for 60.52s
  Transfer: 360.33 KiB down / 357.58 KiB up
  Requests: 7224 (0 posts)
  Reconnects: 0
  Errors: 1

When this happens, I keep seeing NNTP connection lost echoed multiple times, but it doesn't finish the post

[animetosho]

Thanks for the report + info.

Could I get you to confirm the version of Nyuu you're using, as well as the error that occurred (look for [ERR ] in the log), ideally with some warnings before/after it?

[df-a]

I'm using 0.4.1

Could you please tell me the location of the log? I don't really know where it is

Also, it's happened again. This is nyuu output from just now

[INFO] All file(s) read...
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[WARN] Post check failed to find posted article t4twdv8t84gj4i4imsk3t3ibkiqzjhc@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article zan82w3475t6xf9ouz83nwcjuhbs4sn@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article e6zbtq46bptdymz7jppspzx4f2c3moa@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article jji664pqpg4ghdhnn564izsd5mtbb6i@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article 6mmdyft9n4a3i9iafo72jzgksq3r73k@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article u29otsb6cqjw9ygur3up3dcgaj8hti3@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article da6ox9657hjfzshs9c9qibt6axk6gag@nyuu; re-posting... (retry 1/5)
[WARN] Post check failed to find posted article ubc27shcawqttg9myk6nue2wkekcnet@nyuu; re-posting... (retry 1/5)
[WARN] Got "441 Posting Failed. Article refused E3" response when posting article ubc27shcawqttg9myk6nue2wkekcnet@nyuu; will retry (attempt 1/5)
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
 99.93%  [================================== ] 0 B/s, ETA -

[animetosho]

Well the log will likely vary by run, so it's possible you don't get an error on some runs.

Would you happened to have changed the check-tries, check-delay or check-retry-delay options? I suspect that posts are not being found during check, and Nyuu is stalling whilst waiting for them to appear.
Since you're not checking on the same server as some posts are made, perhaps it's taking time for the articles to propagate.

Perhaps I can see if there's a way to make it more obvious that it's stalling on checks. Otherwise, you can use the --verbose option to confirm it's making check attempts.

[df-a]

This is a part of my config. I will be using the --verbose option upon next try
I have since tried with each server having 1 check connection, and it happened again today but just less frequent this time
Maybe I should leave the group option as '[]'?

Is there a way to tell it to just finish if it tested and found, say, 99% of the post already? 99% w/ pars should be pretty much safe to assume the posts is up 100%. It seems to hang on not finding 1 (out of sometimes thousands of) article.

I use config.js for most of the config options

Servers :

// server 1
{
	connect: { 
		host: 'news.server.foo',
		port: 443, 
		rejectUnauthorized: true,
		highWaterMark: 0, 
	},
	secure: true, 
	user: 'username',
	password: 'password',
	
	timeout: 60000, 
	connTimeout: 60000, 
	postTimeout: 180000, 
	reconnectDelay: 150000, 
	connectRetries: 5,
	requestRetries: 10, 
	retryBadResp: false, 
	postRetries: 5, 
	postRetryDelay: 200000, 
	postFailReconnect: false, 
	errorTeardown: false, 
	closeTimeout: 10000, 
	keepAlive: false, 
	onPostTimeout: null, 
	tcpKeepAlive: false, 
	uploadChunkSize: 192*1024, 
	postMethod: 'POST', 
	
	
	throttleRate: {
		size: 0, 
		time: 0  
	},
	throttleChunkTime: 2000, 
	
	postConnections: 4, 
	checkConnections: 1, 
	
	
}

These are my check options

/** Post Check Options **/
check: {
	delay: 5000, 
	recheckDelay: 100000, 
	tries: 5, 
	group: 'bit.test', 
	postRetries: 5, 
	queueCache: null, 
	queueBuffer: 15000, 
},

skipErrors: true, 
maxPostErrors: 0, 
useLazyConnect: false, 

[animetosho]

With multiple servers, actions are currently done randomly against them, so there's no guarantee that checks are performed on the same server that posts are.

Yeah I thought you may have changed those options - basically that says that if a post isn't found via check, wait 100s and check again. Repeat this up to 4 times, and repost if not found. After reposting, repeat this whole check process - meaning that an article not accepted by the host could hold up the process for quite a long time.
In your first post, the check connection was inactive for 60s, which is within the 100s delay time set, so that's probably the reason.

Is there a way to tell it to just finish if it tested and found, say, 99% of the post already? 99% w/ pars should be pretty much safe to assume the posts is up 100%.

That's a neat idea - I'll look into that.

[df-a]

That's a neat idea - I'll look into that.
Thanks, would be awesome

I have kept a close eye on the primary issue that happened, and it hasn't occurred again yet. I can't recall having made any changes to the main config. When it does, I'll report again, hopefully with better evidence

Edit: I actually did add a check connection to each server. I have noticed some servers do eat up bandwidth even when only posting, which is not optimal for blocks long run, which is why I disabled it in the first place

[df-a]

It happened again. This is the output of the web server:

Time: Sun Dec 04 2022 17:34:50 GMT-0400 (Atlantic Standard Time)
Start time: Sun Dec 04 2022 15:48:42 GMT-0400 (Atlantic Standard Time)

Total articles: 3956 (2762.12 MiB)
Articles read: 3956 (100.00%) (+2 re-read)
Articles posted: 3955 (99.97%) (+2 re-posted)
Articles checked: 3955 (99.97%)
Errors skipped: 1 across 1 article(s)
Upload Rate (network|real): 459.62 KiB/s | 444.01 KiB/s

Post queue size: 0 (0.00% full)
Check queue size: 0 + 0 delayed (0.00% full)
Check cache size: 0 (0.00% full)
Re-read queue size: 0

===== Post Connections' Status =====
Connection #1
  State: inactive for 3701.12s
  Transfer: 12.33 KiB down / 176.16 MiB up
  Requests: 245 (245 posts)
  Reconnects: 2
  Errors: 4

Connection #2
  State: inactive for 3549.209s
  Transfer: 11.77 KiB down / 168.1 MiB up
  Requests: 234 (234 posts)
  Reconnects: 2
  Errors: 3

Connection #3
  State: inactive for 3548.673s
  Transfer: 12.41 KiB down / 177.76 MiB up
  Requests: 247 (247 posts)
  Reconnects: 2
  Errors: 3

Connection #4
  State: inactive for 3548.078s
  Transfer: 9.97 KiB down / 141.37 MiB up
  Requests: 198 (198 posts)
  Reconnects: 2
  Errors: 3

Connection #5
  State: inactive for 3432.144s
  Transfer: 52.71 KiB down / 338.73 MiB up
  Requests: 470 (470 posts)
  Reconnects: 2
  Errors: 3

Connection #6
  State: inactive for 2545.154s
  Transfer: 59.55 KiB down / 383.99 MiB up
  Requests: 533 (533 posts)
  Reconnects: 1
  Errors: 7

Connection #7
  State: inactive for 3430.213s
  Transfer: 60.68 KiB down / 389.21 MiB up
  Requests: 541 (541 posts)
  Reconnects: 2
  Errors: 3

Connection #8
  State: inactive for 3429.801s
  Transfer: 62.21 KiB down / 399.97 MiB up
  Requests: 555 (555 posts)
  Reconnects: 2
  Errors: 3

Connection #9
  State: inactive for 3430.995s
  Transfer: 17.2 KiB down / 164.58 MiB up
  Requests: 228 (228 posts)
  Reconnects: 1
  Errors: 2

Connection #10
  State: inactive for 3431.248s
  Transfer: 19.95 KiB down / 190.72 MiB up
  Requests: 265 (265 posts)
  Reconnects: 1
  Errors: 2

Connection #11
  State: inactive for 3426.757s
  Transfer: 18.62 KiB down / 178.17 MiB up
  Requests: 247 (247 posts)
  Reconnects: 1
  Errors: 2

Connection #12
  State: inactive for 3428.592s
  Transfer: 15.83 KiB down / 150.93 MiB up
  Requests: 210 (210 posts)
  Reconnects: 2
  Errors: 3

===== Check Connections' Status =====
Connection #1
  State: inactive for 2658.246s
  Transfer: 66.73 KiB down / 66.11 KiB up
  Requests: 1329 (0 posts)
  Reconnects: 2
  Errors: 3

Connection #2
  State: inactive for 3421.681s
  Transfer: 74.88 KiB down / 75.79 KiB up
  Requests: 1530 (0 posts)
  Reconnects: 1
  Errors: 2

Connection #3
  State: inactive for 3422.932s
  Transfer: 60.43 KiB down / 59.31 KiB up
  Requests: 1197 (0 posts)
  Reconnects: 1
  Errors: 2

I haven't ended the process yet. It's reporting inactivity for a long long time, much longer than in the settings.

in terminal I see

[WARN] Post check failed to find posted article K4gy1CJWMOTdP3kvr103eKdb1RidrWAlgSE@6QcfdK; re-posting... (retry 1/5)
[WARN] Got "441 Posting Failed. Article refused E3" response when posting article K4gy1CJWMOTdP3kvr103eKdb1RidrWAlgSE@6QcfdK; will retry (attempt 1/5)
[INFO] Reading file xAmTUxiGPnpb0bY4z40hpqa5.7z.vol063+060.par2...
[WARN] Post check failed to find posted article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; re-posting... (retry 1/5)
[WARN] Got "441 Article posting failed" response when posting article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; will retry (attempt 1/5)
[INFO] All file(s) read...
[INFO] NNTP connection lost
[WARN] Got "441 Article posting failed" response when posting article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; will retry (attempt 2/5)
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[WARN] Got "441 Article posting failed" response when posting article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; will retry (attempt 3/5)
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[INFO] NNTP connection lost
[WARN] Got "441 Article posting failed" response when posting article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; will retry (attempt 4/5)
[WARN] Got "441 Article posting failed" response when posting article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; will retry (attempt 5/5)
[ERR ] Post rejected (Server could not accept post ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN, returned: 441 Article posting failed) for article ki1bTM1cZz1JcdcIIrYrj2jfgm3RvjpzZ9V@FuU1RN; continuing regardless
[INFO] NNTP connection lost
[INFO] NNTP connection lost
 99.97%  [================================== ] 0 B/s, ETA -

[animetosho]

Not sure what the cause is there :/

Are the settings largely the same as those above?
Is the log you posted mostly complete? If you could also add the --log-time parameter next time, it might help correlate events.

Otherwise, I'll look into this a bit more, and beef up diagnostics/info to help track it down.

Thanks for the update.

[animetosho]

I've added more info to the status server if you visit /debug (shows active timers and handles).

If you're still getting random stalls, the info shown there might help.

[df-a]

Thank you for the update.

Upgraded local install to the latest commit yields the following results:

[INFO] All file(s) read...
 99.82%  [==================================-] awaiting check on 1 article(s)

And then it shows as

[INFO] All file(s) read...
[WARN] Post check failed to find posted article XuBdXgOuQaDmZwWwPjAvWyBo-1643242453098@nyuu; re-posting... (retry 1/5)
[INFO] Finished uploading 180.29 MiB in 00:08:58.368 (342.91 KiB/s). Network upload rate: 697.32 KiB/s

So far so good, I'll keep testing it out to see where/if it hangs

[df-a]

It hasn't happened in awhile, but today just had the first hang-up after the update

Time: Sun Jan 15 2023 09:32:36 GMT-0400 (Atlantic Standard Time)
Start time: Sun Jan 15 2023 08:48:22 GMT-0400 (Atlantic Standard Time)

Total articles: 1918 (1317.81 MiB)
Articles read: 1918 (100.00%) (+1 re-read)
Articles posted: 1917 (99.95%) (+2 re-posted)
Articles checked: 1917 (99.95%) (+112 re-checked)
Errors skipped: 0 across 0 article(s)
Upload Rate (network|real): 1116.76 KiB/s | 508.21 KiB/s

Post queue size: 0 (0.00% full)
Check queue size: 0 + 0 delayed (0.00% full)
Re-read queue size: 0

Article activity: 1 posting, 0 checking
Articles awaiting check: 0 + 0 awaiting re-check

===== Post Connections' Status =====
Connection #1
  State: inactive for 1253.122s
  Transfer: 5371 B down / 72.55 MiB up
  Requests: 104 (104 posts)
  Connects: 1
  Errors: 1

Connection #2
  State: inactive for 1250.729s
  Transfer: 4606 B down / 62.6 MiB up
  Requests: 89 (89 posts)
  Connects: 1
  Errors: 1

Connection #3
  State: inactive for 1249.728s
  Transfer: 5728 B down / 78.48 MiB up
  Requests: 111 (111 posts)
  Connects: 1
  Errors: 1

Connection #4
  State: inactive for 1693.607s
  Transfer: 2994 B down / 40.6 MiB up
  Requests: 57 (57 posts)
  Connects: 1
  Errors: 2

Connection #5
  State: inactive for 1131.055s
  Transfer: 8986 B down / 83.36 MiB up
  Requests: 117 (117 posts)
  Connects: 1
  Errors: 1

Connection #6
  State: inactive for 1132.634s
  Transfer: 3951 B down / 35.72 MiB up
  Requests: 51 (51 posts)
  Connects: 1
  Errors: 1

Connection #7
  State: inactive for 1132.073s
  Transfer: 6517 B down / 60.81 MiB up
  Requests: 85 (85 posts)
  Connects: 1
  Errors: 1

Connection #8
  State: inactive for 1129.407s
  Transfer: 7293 B down / 66.39 MiB up
  Requests: 95 (95 posts)
  Connects: 1
  Errors: 1

Connection #9
  State: inactive for 1129.406s
  Transfer: 7965 B down / 75.07 MiB up
  Requests: 104 (104 posts)
  Connects: 1
  Errors: 1

Connection #10
  State: inactive for 1133.139s
  Transfer: 20 KiB down / 128.37 MiB up
  Requests: 179 (179 posts)
  Connects: 1
  Errors: 1

Connection #11
  State: inactive for 1133.8s
  Transfer: 18.2 KiB down / 116.42 MiB up
  Requests: 163 (163 posts)
  Connects: 1
  Errors: 1

Connection #12
  State: inactive for 1133.546s
  Transfer: 19.98 KiB down / 127.57 MiB up
  Requests: 179 (179 posts)
  Connects: 1
  Errors: 1

Connection #13
  State: inactive for 1130.815s
  Transfer: 22.44 KiB down / 139.99 MiB up
  Requests: 201 (201 posts)
  Connects: 1
  Errors: 1

Connection #14
  State: inactive for 1104.366s
  Transfer: 5543 B down / 34.65 MiB up
  Requests: 48 (48 posts)
  Connects: 2
  Errors: 2

Connection #15
  State: inactive for 1129.868s
  Transfer: 12.55 KiB down / 79.21 MiB up
  Requests: 112 (112 posts)
  Connects: 1
  Errors: 1

Connection #16
  State: inactive for 1129.858s
  Transfer: 12.97 KiB down / 82.64 MiB up
  Requests: 116 (116 posts)
  Connects: 1
  Errors: 1

Connection #17
  State: inactive for 1129.138s
  Transfer: 12.21 KiB down / 77.48 MiB up
  Requests: 109 (109 posts)
  Connects: 1
  Errors: 1

===== Check Connections' Status =====
Connection #1
  State: inactive for 1219.3s
  Transfer: 23.85 KiB down / 24.51 KiB up
  Requests: 499 (0 posts)
  Connects: 1
  Errors: 1

Connection #2
  State: inactive for 1124.256s
  Transfer: 24.77 KiB down / 24.33 KiB up
  Requests: 497 (0 posts)
  Connects: 1
  Errors: 1

Connection #3
  State: inactive for 1124.335s
  Transfer: 25.71 KiB down / 26.28 KiB up
  Requests: 537 (0 posts)
  Connects: 1
  Errors: 1

Connection #4
  State: inactive for 1123.974s
  Transfer: 23.74 KiB down / 24.31 KiB up
  Requests: 498 (0 posts)
  Connects: 1
  Errors: 1

This time there is no "extra info" shown, only no ETA

[INFO] Reading file backup.rar.vol007+008.par2...
[INFO] Reading file backup.rar.vol015+016.par2...
[INFO] Reading file backup.rar.vol031+032.par2...
[INFO] Reading file backup.rar.vol063+064.par2...
[INFO] All file(s) read...
 99.95%  [================================== ] 0 B/s, ETA -

I have to say that this is the very first time it happened since updating, and I have been testing it quite exhaustively

[animetosho]

Thanks for all the testing + info!

It looks like a post got stuck somewhere, but I can't think of a cause.

Are you able to post a full log? The details suggest that errors occurred, but your posted log doesn't show what they are.
Also, could you post the output from [status server URL]/debug next time? That page should include info like 'Active Timers'.
Finally, it you could post a full list of your settings (mask out stuff where necessary), that'd be great.

[df-a]

It's possible I may have jumped the gun on that one, I think it got stuck and was retrying. It only happened that one occasion though. As we have established, I have liberal retries because my connection sucks.

I tried again with a much longer queue and left it to do it's thing, and haven't found any messages of failure yet. I think that one example was because I was scrutinizing it too closely and caught it before it could handle the erroring gracefully mostly because of my liberal error-handling settings.

I think everything works nicely as it's intended right now

Edit: I will do the /debug page next time, and will post my settings in full too