search

animetosho / Nyuu

Flexible usenet binary posting tool
221 stars 32 forks source link

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

Open df-a opened 1 year ago

df-a commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

animetosho commented 1 year ago

Thanks for the info.
Actually, the status output you posted does suggest something messed up - it shouldn't be possible for all connections to be inactive whilst "Article activity: 1 posting". I suspect an error caused it, but I can't fathom what it could've been.
I'll look at adding more info to help trace down the cause, when it occurs.

animetosho commented 1 year ago

Changed the status screen to show a bit more info - hopefully that helps with tracking things down better.

Let me know if you encounter the issue again with the new code. Thanks!

df-a commented 1 year ago

This only happens on a slow connection. I haven't seen a single fail since upgrading speed.

I don't understand why, but I've literally had 0 incidences since. I think you can close this ticket, even though the actual reason why it failed we don't know yet.

duhagppn commented 9 months ago

I'm running into hanging issues. using 0.4.1 

[2024-01-10 15:27:52.716][DBG ] Post check successful for article <removed>
[2024-01-10 15:27:58.956][WARN] NNTP connection error occurred: Response timed out (post-data); will retry post-upload request (attempt 1/5)
[2024-01-10 15:27:58.957][DBG ] Connecting to nntp://news.vipernews.com:119...
[2024-01-10 15:27:58.993][DBG ] NNTP connection established
[2024-01-10 15:27:59.693][WARN] NNTP connection failed: Unexpected response to auth pass (code: 502): connection limit (40) reached, reconnecting after 15 second(s)... (attempt 1/1)
[2024-01-10 15:28:10.998][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:28:14.694][DBG ] Connecting to nntp://news.vipernews.com:119...
[2024-01-10 15:28:14.724][DBG ] NNTP connection established
[2024-01-10 15:28:15.634][ERR ] NNTP connection failed: Unexpected response to auth pass (code: 502): connection limit (40) reached
[2024-01-10 15:28:15.634][ERR ] NNTPError: NNTP connection failed: Unexpected response to auth pass (code: 502): connection limit (40) reached
[2024-01-10 15:28:40.999][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:29:11.000][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:29:41.001][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:30:11.002][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:30:41.003][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:31:11.004][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:31:41.004][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:32:11.005][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:32:41.006][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
[2024-01-10 15:32:46.699][DBG ] NNTP connection lost
[2024-01-10 15:33:11.006][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
(continues)
[2024-01-10 16:38:11.094][INFO] Article posting progress: 33808 read, 33807 posted, 33807 checked
Posted: 33807/33808 (100.00%) @ 0 B/s (network: 5267.39 KiB/s) ETA -

HTTP debug server output:

Start time: Wed Jan 10 2024 15:21:10 GMT+0000 (Coordinated Universal Time)

Total articles: 33808 (22.57 GiB)
Articles read: 33808 (100.00%)
Articles posted: 33807 (100.00%)
Articles checked: 33807 (100.00%)
Errors skipped: 2 across 0 article(s)
Upload Rate (network|real): 4963.94 KiB/s | 4810.34 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: 0 posting, 0 checking
Articles awaiting check: 0 + 0 awaiting re-check

===== Post Connections' Status =====
Connection #1
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.1s
  Transfer: 58.23 KiB down / 361.85 MiB up
  Requests: post (513)
  Connects: 1
  Errors: connection_lost (1)

Connection #2
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.049s
  Transfer: 247.98 KiB down / 1542.86 MiB up
  Requests: post (2188)
  Connects: 1
  Errors: connection_lost (1)

Connection #3
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.426s
  Transfer: 118.5 KiB down / 737.07 MiB up
  Requests: post (1045)
  Connects: 1
  Errors: connection_lost (1)

Connection #4
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.023s
  Transfer: 249.23 KiB down / 1551.15 MiB up
  Requests: post (2199)
  Connects: 1
  Errors: connection_lost (1)

Connection #5
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.019s
  Transfer: 237.44 KiB down / 1477.76 MiB up
  Requests: post (2095)
  Connects: 1
  Errors: connection_lost (1)

Connection #6
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.994s
  Transfer: 248.55 KiB down / 1546.88 MiB up
  Requests: post (2193)
  Connects: 1
  Errors: connection_lost (1)

Connection #7
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.994s
  Transfer: 125.86 KiB down / 782.96 MiB up
  Requests: post (1110)
  Connects: 1
  Errors: connection_lost (1)

Connection #8
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.994s
  Transfer: 246.39 KiB down / 1533.26 MiB up
  Requests: post (2174)
  Connects: 1
  Errors: connection_lost (1)

Connection #9
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.687s
  Transfer: 120.99 KiB down / 752.57 MiB up
  Requests: post (1067)
  Connects: 1
  Errors: connection_lost (1)

Connection #10
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.029s
  Transfer: 114.65 KiB down / 713.14 MiB up
  Requests: post (1011)
  Connects: 1
  Errors: connection_lost (1)

Connection #11
  State: finished

Connection #12
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.101s
  Transfer: 113.51 KiB down / 706.1 MiB up
  Requests: post (1001)
  Connects: 1
  Errors: connection_lost (1)

Connection #13
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.073s
  Transfer: 56.99 KiB down / 354.09 MiB up
  Requests: post (502)
  Connects: 1
  Errors: connection_lost (1)

Connection #14
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.072s
  Transfer: 249.91 KiB down / 1555.14 MiB up
  Requests: post (2205)
  Connects: 1
  Errors: connection_lost (1)

Connection #15
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.835s
  Transfer: 54.83 KiB down / 340.7 MiB up
  Requests: post (483)
  Connects: 1
  Errors: connection_lost (1)

Connection #16
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.019s
  Transfer: 116.91 KiB down / 727.17 MiB up
  Requests: post (1031)
  Connects: 1
  Errors: connection_lost (1)

Connection #17
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.938s
  Transfer: 56.53 KiB down / 351.28 MiB up
  Requests: post (498)
  Connects: 1
  Errors: connection_lost (1)

Connection #18
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.723s
  Transfer: 57.55 KiB down / 357.1 MiB up
  Requests: post (507)
  Connects: 1
  Errors: connection_lost (1)

Connection #19
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.824s
  Transfer: 59.93 KiB down / 372.41 MiB up
  Requests: post (528)
  Connects: 1
  Errors: connection_lost (1)

Connection #20
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.917s
  Transfer: 122.01 KiB down / 758.98 MiB up
  Requests: post (1076)
  Connects: 1
  Errors: connection_lost (1)

Connection #21
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.863s
  Transfer: 56.31 KiB down / 349.38 MiB up
  Requests: post (496)
  Connects: 1
  Errors: connection_lost (1)

Connection #22
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.019s
  Transfer: 244.01 KiB down / 1518.39 MiB up
  Requests: post (2153)
  Connects: 1
  Errors: connection_lost (1)

Connection #23
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4223.023s
  Transfer: 239.48 KiB down / 1490.16 MiB up
  Requests: post (2113)
  Connects: 1
  Errors: connection_lost (1)

Connection #24
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.974s
  Transfer: 57.44 KiB down / 356.92 MiB up
  Requests: post (506)
  Connects: 1
  Errors: connection_lost (1)

Connection #25
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.907s
  Transfer: 122.69 KiB down / 763.2 MiB up
  Requests: post (1082)
  Connects: 1
  Errors: connection_lost (1)

Connection #26
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.66s
  Transfer: 58.35 KiB down / 362.56 MiB up
  Requests: post (514)
  Connects: 1
  Errors: connection_lost (1)

Connection #27
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.365s
  Transfer: 56.76 KiB down / 352.22 MiB up
  Requests: post (500)
  Connects: 1
  Errors: connection_lost (1)

Connection #28
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.863s
  Transfer: 52.34 KiB down / 325.18 MiB up
  Requests: post (461)
  Connects: 1
  Errors: connection_lost (1)

Connection #29
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.824s
  Transfer: 116.57 KiB down / 725.12 MiB up
  Requests: post (1028)
  Connects: 1
  Errors: connection_lost (1)

Connection #30
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4222.918s
  Transfer: 120.42 KiB down / 748.58 MiB up
  Requests: post (1062)
  Connects: 1
  Errors: connection_lost (1)

===== Check Connections' Status =====
Connection #1
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.403s
  Transfer: 145.87 KiB down / 143.06 KiB up
  Requests: stat (2816)
  Connects: 1
  Errors: connection_lost (1)

Connection #2
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.345s
  Transfer: 304.15 KiB down / 298.35 KiB up
  Requests: stat (5874)
  Connects: 1
  Errors: connection_lost (1)

Connection #3
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.747s
  Transfer: 149.39 KiB down / 146.52 KiB up
  Requests: stat (2884)
  Connects: 1
  Errors: connection_lost (1)

Connection #4
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.528s
  Transfer: 154.46 KiB down / 151.49 KiB up
  Requests: stat (2982)
  Connects: 1
  Errors: connection_lost (1)

Connection #5
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.588s
  Transfer: 154.62 KiB down / 151.64 KiB up
  Requests: stat (2985)
  Connects: 1
  Errors: connection_lost (1)

Connection #6
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4216.997s
  Transfer: 185.46 KiB down / 181.91 KiB up
  Requests: stat (3581)
  Connects: 1
  Errors: connection_lost (1)

Connection #7
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.464s
  Transfer: 177.55 KiB down / 174.14 KiB up
  Requests: stat (3428)
  Connects: 1
  Errors: connection_lost (1)

Connection #8
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.634s
  Transfer: 152.91 KiB down / 149.97 KiB up
  Requests: stat (2952)
  Connects: 1
  Errors: connection_lost (1)

Connection #9
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.665s
  Transfer: 149.49 KiB down / 146.62 KiB up
  Requests: stat (2886)
  Connects: 1
  Errors: connection_lost (1)

Connection #10
  Host: news.vipernews.com:119
  State: inactive [no requests] for 4217.634s
  Transfer: 177.08 KiB down / 173.68 KiB up
  Requests: stat (3419)
  Connects: 1
  Errors: connection_lost (1)

===== Active Timers =====
[none]

===== Other =====
Check cache size: 0 (0.00% full)
Active Handles: Server, Socket

config is default. when opening the nzb you can see that one of the parts is missing: 731/732

edit: another hang on the upload directly after: 

[2024-01-10 17:01:21.372][DBG ] Post check successful for article <removed>
[2024-01-10 17:01:36.033][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked
[2024-01-10 17:02:06.034][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked
[2024-01-10 17:02:36.035][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked
[2024-01-10 17:03:06.036][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked
[2024-01-10 17:03:36.037][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked
[2024-01-10 17:04:06.037][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked
[2024-01-10 17:04:36.038][INFO] Article posting progress: 62497 read, 62496 posted, 62496 checked

HTTP server:

===== Active Timers =====
[none]

===== Other =====
Check cache size: 0 (0.00% full)
Active Handles: Socket (39), Server
animetosho commented 8 months ago

Thanks for the detailed info @duhagppn !

I can see the cause of your first example. A skipped [ERR ] NNTP connection failed, with post checking enabled, can cause Nyuu to stall at the end.
Unsure about your second example though, as it seems to be missing info. But if the same error showed up, it'd probably be the same thing.

I'll look at implementing a fix for the stall. Regardless, you can avoid connection rejections by lowering your connection count.

I suspect your issue may be different from what @df-a reported, as I saw no mention of "NNTP connection failed" errors.
Actually I never really got much info on the errors with df-a's runs. A number of things seem to point towards the same issue, and given that there probably won't be further info on the matter, I'll make the assumption that it is indeed the same.

df-a commented 8 months ago

I'm fairly certain this is an issue with vipernews as well, could you try with a different provider @duhagppn ?

duhagppn commented 7 months ago

was confident this was fixed but woke up to anotherr hung process.

Time: Thu Feb 22 2024 07:25:36 GMT+0000 (Coordinated Universal Time)
Start time: Wed Feb 21 2024 23:57:32 GMT+0000 (Coordinated Universal Time)

Total articles: 152461 (101.72 GiB)
Articles read: 152461 (100.00%)
Articles posted: 152461 (100.00%)
Articles checked: 152460 (100.00%)
Errors skipped: 4 across 0 article(s)
Upload Rate (network|real): 4095.82 KiB/s | 3967.26 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: 0 posting, 0 checking
Articles awaiting check: 0 + 0 awaiting re-check

===== Post Connections' Status =====
Connection #1
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.898s
  Transfer: 874.76 KiB down / 5447.75 MiB up
  Requests: post (7721)
  Connects: 1
  Time Idle: 3099.981s (74.91%)
  Errors: connection_lost (1)

Connection #2
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.814s
  Transfer: 884.96 KiB down / 5509.08 MiB up
  Requests: post (7811)
  Connects: 1
  Time Idle: 3074.761s (74.30%)
  Errors: connection_lost (1)

Connection #3
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.781s
  Transfer: 930.84 KiB down / 5794.69 MiB up
  Requests: post (8216)
  Connects: 1
  Time Idle: 3210.572s (77.58%)
  Errors: connection_lost (1)

Connection #4
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.792s
  Transfer: 951 KiB down / 5921.24 MiB up
  Requests: post (8394)
  Connects: 1
  Time Idle: 3212.859s (77.64%)
  Errors: connection_lost (1)

Connection #5
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.781s
  Transfer: 860.94 KiB down / 5357.35 MiB up
  Requests: post (7599)
  Connects: 1
  Time Idle: 3084.635s (74.54%)
  Errors: connection_lost (1)

Connection #6
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.781s
  Transfer: 893.23 KiB down / 5561.38 MiB up
  Requests: post (7884)
  Connects: 1
  Time Idle: 3073.747s (74.27%)
  Errors: connection_lost (1)

Connection #7
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.781s
  Transfer: 902.97 KiB down / 5621.71 MiB up
  Requests: post (7970)
  Connects: 1
  Time Idle: 3237.643s (78.23%)
  Errors: connection_lost (1)

Connection #8
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.778s
  Transfer: 918.04 KiB down / 5714.73 MiB up
  Requests: post (8103)
  Connects: 1
  Time Idle: 3240.939s (78.32%)
  Errors: connection_lost (1)

Connection #9
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.898s
  Transfer: 899.46 KiB down / 5598.24 MiB up
  Requests: post (7939)
  Connects: 1
  Time Idle: 3218.319s (77.77%)
  Errors: connection_lost (1)

Connection #10
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.781s
  Transfer: 929.37 KiB down / 5786.08 MiB up
  Requests: post (8203)
  Connects: 1
  Time Idle: 3232.779s (78.12%)
  Errors: connection_lost (1)

Connection #11
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.781s
  Transfer: 930.95 KiB down / 5794.76 MiB up
  Requests: post (8217)
  Connects: 1
  Time Idle: 3209.914s (77.56%)
  Errors: connection_lost (1)

Connection #12
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.898s
  Transfer: 887.57 KiB down / 5525.62 MiB up
  Requests: post (7834)
  Connects: 1
  Time Idle: 3090.821s (74.69%)
  Errors: connection_lost (1)

Connection #13
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.91s
  Transfer: 914.98 KiB down / 5694.88 MiB up
  Requests: post (8076)
  Connects: 1
  Time Idle: 3239.556s (78.29%)
  Errors: connection_lost (1)

Connection #14
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.799s
  Transfer: 927.67 KiB down / 5772.14 MiB up
  Requests: post (8188)
  Connects: 1
  Time Idle: 3213.903s (77.66%)
  Errors: connection_lost (1)

Connection #15
  State: finished

Connection #16
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.778s
  Transfer: 901.05 KiB down / 5609.17 MiB up
  Requests: post (7953)
  Connects: 1
  Time Idle: 3060.864s (73.96%)
  Errors: connection_lost (1)

Connection #17
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.778s
  Transfer: 921.55 KiB down / 5735.93 MiB up
  Requests: post (8134)
  Connects: 1
  Time Idle: 3239.435s (78.27%)
  Errors: connection_lost (1)

Connection #18
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.898s
  Transfer: 936.5 KiB down / 5827.87 MiB up
  Requests: post (8266)
  Connects: 1
  Time Idle: 3226.762s (77.97%)
  Errors: connection_lost (1)

Connection #19
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.777s
  Transfer: 892.78 KiB down / 5557.68 MiB up
  Requests: post (7880)
  Connects: 1
  Time Idle: 3072.152s (74.27%)
  Errors: connection_lost (1)

Connection #20
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22739.898s
  Transfer: 899.23 KiB down / 5596.28 MiB up
  Requests: post (7937)
  Connects: 1
  Time Idle: 3080.945s (74.45%)
  Errors: connection_lost (1)

===== Check Connections' Status =====
Connection #1
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.768s
  Transfer: 861.16 KiB down / 844.86 KiB up
  Requests: stat (16636)
  Connects: 1
  Time Idle: 3826.104s (92.54%)
  Errors: connection_lost (1)

Connection #2
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.767s
  Transfer: 833.42 KiB down / 817.64 KiB up
  Requests: stat (16100)
  Connects: 1
  Time Idle: 3896.964s (94.17%)
  Errors: connection_lost (1)

Connection #3
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.758s
  Transfer: 866.6 KiB down / 850.19 KiB up
  Requests: stat (16741)
  Connects: 1
  Time Idle: 3872.13s (93.57%)
  Errors: connection_lost (1)

Connection #4
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.77s
  Transfer: 864.01 KiB down / 847.65 KiB up
  Requests: stat (16691)
  Connects: 1
  Time Idle: 3823.045s (92.39%)
  Errors: connection_lost (1)

Connection #5
  State: finished

Connection #6
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.769s
  Transfer: 889.63 KiB down / 872.79 KiB up
  Requests: stat (17186)
  Connects: 1
  Time Idle: 3806.494s (91.98%)
  Errors: connection_lost (1)

Connection #7
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.769s
  Transfer: 903.24 KiB down / 886.14 KiB up
  Requests: stat (17449)
  Connects: 1
  Time Idle: 3800.269s (91.84%)
  Errors: connection_lost (1)

Connection #8
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.77s
  Transfer: 884.45 KiB down / 867.71 KiB up
  Requests: stat (17086)
  Connects: 1
  Time Idle: 3804.474s (91.93%)
  Errors: connection_lost (1)

Connection #9
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.769s
  Transfer: 852.31 KiB down / 836.18 KiB up
  Requests: stat (16465)
  Connects: 1
  Time Idle: 3884.224s (93.86%)
  Errors: connection_lost (1)

Connection #10
  Host: news.vipernews.com:119
  State: inactive [no requests] for 22734.769s
  Transfer: 888.49 KiB down / 871.67 KiB up
  Requests: stat (17164)
  Connects: 1
  Time Idle: 3867.163s (93.47%)
  Errors: connection_lost (1)

===== Active Timers =====
[none]

===== Other =====
Check cache size: 0 (0.00% full)
Active Handles: Server, Socket

these are the only posting errors:

[WARN] NNTP connection error occurred: Response timed out (post-data); will retry post-upload request (attempt 1/5)
[WARN] NNTP connection failed: Unexpected response to auth pass (code: 502): Authentication Failed, reconnecting after 15 second(s)... (attempt 1/1)
[ERR ] NNTP connection failed: Unexpected response to auth pass (code: 502): Authentication Failed
[ERR ] NNTPError: NNTP connection failed: Unexpected response to auth pass (code: 502): Authentication Failed
[WARN] NNTP connection error occurred: Response timed out (stat); will retry stat request (attempt 1/5)
[WARN] NNTP connection failed: Unexpected response to auth pass (code: 502): Authentication Failed, reconnecting after 15 second(s)... (attempt 1/1)
[ERR ] NNTP connection failed: Unexpected response to auth pass (code: 502): Authentication Failed
[ERR ] NNTPError: NNTP connection failed: Unexpected response to auth pass (code: 502): Authentication Failed
[INFO] All file(s) read...
Checked: 152460 (100.00%)
animetosho commented 7 months ago

Thanks for the report - that's quite weird, so I'll investigate more.

From the looks of things, at least that post seems like it did complete.

df-a commented 7 months ago

I believe it's a ViperNews issue. I removed ViperNews from my servers and I haven't had this problem again.

Something is going on with ViperNews

@duhagppn Could you please try with a different server and report back?

duhagppn commented 7 months ago

Thanks for the report - that's quite weird, so I'll investigate more.

From the looks of things, at least that post seems like it did complete.

although it reached 100% the post was incomplete - there was 1 file completely missing from the nzb. 20 .par2 index files, 19 media files, 140 .par2 volumes + 1 nfo. I did kill the process once it was clear the upload was stalled, but surely what was already posted should've been written to the nzb?

@df-a I don't have any other posting accounts to try with, certainly not at 15 eur/20 usd a block like farm or usenet express :rofl:

personally I think the issue is less with vipernews specifically and more to do with how nyuu is handling posting/checking/retries when encountering things like authentication or timeout issues. in the previous post log for example, you can see Connection #15 is the only one with "finished" where others are listing their transfer & idle stats etc.

is there a combination of the log & progress options to output standard info to the terminal while writing debug output to a log file?

animetosho commented 7 months ago

although it reached 100% the post was incomplete - there was 1 file completely missing from the nzb. 20 .par2 index files, 19 media files, 140 .par2 volumes + 1 nfo. I did kill the process once it was clear the upload was stalled, but surely what was already posted should've been written to the nzb?

Ah, that's unfortunate.

I think I've found the issue - if a check connection gets lost, the post it's checking also does too, so the process doesn't complete. This should be fixed in the latest code.

The NZB is written as the upload is progressing, but keep in mind that it has to be done in order, and can't "go backwards". If post checking is enabled, segments can only be written once the check is successful, since a failed check may result in a re-post, which could mean a different message ID.
In your case, a single post's check got lost, thus all subsequent posts will be waiting for that one to complete, before being written out.

is there a combination of the log & progress options to output standard info to the terminal while writing debug output to a log file?

No, though the debug info isn't particularly useful. The progress server is currently the most useful for these types of issues.

duhagppn commented 7 months ago

thanks, I've updated to the latest version and will let you know if it occurs again. fingers crossed it's all fixed