search

nzbgetcom / nzbget

Efficient usenet downloader
https://nzbget.com
GNU General Public License v2.0
350 stars 16 forks source link

Completion extension support #143

Closed Moolynx closed 6 months ago

Moolynx commented 10 months ago

The existing Completion extension (https://forum.nzbget.net/viewtopic.php?t=1736) doesn't work anymore in Python 3. Is there any support to migrate this to Python 3 compatibility?

luckedea commented 10 months ago

Yes absolutely, will pick this one up soon.

dnzbk commented 9 months ago

@Moolynx Added support for Python 3.8+, feel free to try v2.0 release.

sdburrows commented 9 months ago

@dnzbk

I am currently on NZBGet testing build 20240126, running the latest Completion script resulting in failure in download. Please see a snippet of the log below (read from bottom up):

WARNING Tue Jan 30 2024 07:20:46    Completion: Socket: 23 _ssl.c:983: The handshake operation timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:20:44    Completion: Socket: 21 _ssl.c:983: The handshake operation timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:20:38    Completion: Socket: 18 _ssl.c:983: The handshake operation timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:20:36    Completion: Socket: 17 _ssl.c:983: The handshake operation timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:20:15    Completion: Skipping current server as it is replying very slow on header requests for this NZB file
WARNING Tue Jan 30 2024 07:17:47    Completion: Socket: 34 _ssl.c:983: The handshake operation timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:17:39    Completion: Socket: 29 _ssl.c:983: The handshake operation timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:17:22    Completion: Socket: 10 timed out, check host, port and number of connections settings for server news.frugalusenet.com
WARNING Tue Jan 30 2024 07:14:59    Blocking Frugal (news.frugalusenet.com) for 10 sec
ERROR   Tue Jan 30 2024 07:14:59    Could not read from TLS-Socket: Connection closed by remote host
ERROR   Tue Jan 30 2024 07:14:59    Could not read from TLS-Socket: Connection closed by remote host
INFO    Tue Jan 30 2024 07:11:04    Completion: Requested [1/1011] articles, 1 failed.
INFO    Tue Jan 30 2024 07:10:37    Completion: context = ssl.SSLContext(ssl.PROTOCOL_SSLv23)
INFO    Tue Jan 30 2024 07:10:37    Completion: X:\NZBGet\Scripts\Completion.py:980: DeprecationWarning: ssl.PROTOCOL_TLS is deprecated

Somehow, the script (both old and new) caused NZBGet to have TLS error resulting in broken download. Disabling completion script would complete it. The files should be 100% complete as this file is only 5 days old, but it reported failed articles.

dnzbk commented 9 months ago

@sdburrows

I updated the protocols, but I couldn't reproduce the problem you are having. Probably because I am using another news server. Could you please test the fixed version on your environment? Getting useful information about your OS and Python would also be helpful.

Completion.zip

sdburrows commented 9 months ago

@dnzbk

I have tested the latest version and the download wont start at all (just paused) and here is the log below. I am on Windows 11, python 3.12.1. My observations are:

  1. Completion seems to take several minutes to check files
  2. It seems to check across my backup servers
  3. There is always 1 failed article
  4. Redownload without script is successful
  5. I also had hanging downloads (not logged here). I normally max out my available connections from usenet provider which I suspect is related to completion script taking up additional server connection, causing the server to reject connection. 
INFO    Thu Feb 01 2024 07:31:31    Deleting file WinPE 11-10-8 Sergei Strelec v2023.04.18 (x86-x64).part04.rar from download queue
INFO    Thu Feb 01 2024 07:31:31    Deleting file WinPE 11-10-8 Sergei Strelec v2023.04.18 (x86-x64).part03.rar from download queue
INFO    Thu Feb 01 2024 07:31:31    Deleting file WinPE 11-10-8 Sergei Strelec v2023.04.18 (x86-x64).part02.rar from download queue
INFO    Thu Feb 01 2024 07:31:31    Deleting file WinPE 11-10-8 Sergei Strelec v2023.04.18 (x86-x64).part01.rar from download queue
WARNING Thu Feb 01 2024 07:31:31    Completion: Forcing failure of NZB:
INFO    Thu Feb 01 2024 07:31:31    Completion: Failed ratio for server: bonus.frugalusenet.com: 0.2%. Server check completed in 152.94 sec.
WARNING Thu Feb 01 2024 07:31:31    Completion: Skipping current server as it is replying very slow on header requests for this NZB file
INFO    Thu Feb 01 2024 07:30:40    Completion: Requested [1/11450] articles, 1 failed.
INFO    Thu Feb 01 2024 07:30:40    Completion: Exception LINE: None: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:30:00    Executing scheduler-script Completion.py
INFO    Thu Feb 01 2024 07:28:58    Completion: ValueError: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:28:58    Completion: super(SSLContext, SSLContext).verify_mode.__set__(self, value)
INFO    Thu Feb 01 2024 07:28:58    Completion: File "XXX\Programs\Python\Python312\Lib\ssl.py", line 680, in verify_mode
INFO    Thu Feb 01 2024 07:28:58    Completion: ^^^^^^^^^^^^^^^^^^^
INFO    Thu Feb 01 2024 07:28:58    Completion: context.verify_mode = ssl.CERT_NONE
INFO    Thu Feb 01 2024 07:28:58    Completion: File "X:\NZBGet\Scripts\Completion.py", line 981, in create_sockets
INFO    Thu Feb 01 2024 07:28:58    Completion: Traceback (most recent call last):
INFO    Thu Feb 01 2024 07:28:58    Completion: Using server: bonus.frugalusenet.com
INFO    Thu Feb 01 2024 07:28:58    Completion: Failed ratio for server: news.frugalusenet.com: 0.2%. Server check completed in 152.98 sec.
WARNING Thu Feb 01 2024 07:28:58    Completion: Skipping current server as it is replying very slow on header requests for this NZB file
INFO    Thu Feb 01 2024 07:28:07    Completion: Requested [1/11450] articles, 1 failed.
INFO    Thu Feb 01 2024 07:28:07    Completion: Exception LINE: None: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:26:25    Completion: ValueError: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:26:25    Completion: super(SSLContext, SSLContext).verify_mode.__set__(self, value)
INFO    Thu Feb 01 2024 07:26:25    Completion: File "XXX\Programs\Python\Python312\Lib\ssl.py", line 680, in verify_mode
INFO    Thu Feb 01 2024 07:26:25    Completion: ^^^^^^^^^^^^^^^^^^^
INFO    Thu Feb 01 2024 07:26:25    Completion: context.verify_mode = ssl.CERT_NONE
INFO    Thu Feb 01 2024 07:26:25    Completion: File "X:\NZBGet\Scripts\Completion.py", line 981, in create_sockets
INFO    Thu Feb 01 2024 07:26:25    Completion: Traceback (most recent call last):
INFO    Thu Feb 01 2024 07:26:25    Completion: Using server: news.frugalusenet.com
INFO    Thu Feb 01 2024 07:26:25    Completion: Failed ratio for server: block.cheapnews.eu: 0.1%. Server check completed in 38.88 sec.
INFO    Thu Feb 01 2024 07:26:12    Completion: Requested [1/11450] articles, 1 failed.
INFO    Thu Feb 01 2024 07:26:12    Completion: Exception LINE: None: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:25:47    Completion: ValueError: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:25:47    Completion: super(SSLContext, SSLContext).verify_mode.__set__(self, value)
INFO    Thu Feb 01 2024 07:25:47    Completion: File "XXX\Programs\Python\Python312\Lib\ssl.py", line 680, in verify_mode
INFO    Thu Feb 01 2024 07:25:47    Completion: ^^^^^^^^^^^^^^^^^^^
INFO    Thu Feb 01 2024 07:25:47    Completion: context.verify_mode = ssl.CERT_NONE
INFO    Thu Feb 01 2024 07:25:47    Completion: File "X:\NZBGet\Scripts\Completion.py", line 981, in create_sockets
INFO    Thu Feb 01 2024 07:25:47    Completion: Traceback (most recent call last):
INFO    Thu Feb 01 2024 07:25:46    Completion: Using server: block.cheapnews.eu
INFO    Thu Feb 01 2024 07:25:46    Completion: Failed ratio for server: ssl-eu.astraweb.com: 0.2%. Server check completed in 153.35 sec.
WARNING Thu Feb 01 2024 07:25:46    Completion: Skipping current server as it is replying very slow on header requests for this NZB file
INFO    Thu Feb 01 2024 07:24:55    Completion: Requested [1/11450] articles, 1 failed.
INFO    Thu Feb 01 2024 07:24:55    Completion: Exception LINE: None: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:23:13    Completion: ValueError: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:23:13    Completion: super(SSLContext, SSLContext).verify_mode.__set__(self, value)
INFO    Thu Feb 01 2024 07:23:13    Completion: File "XXX\Programs\Python\Python312\Lib\ssl.py", line 680, in verify_mode
INFO    Thu Feb 01 2024 07:23:13    Completion: ^^^^^^^^^^^^^^^^^^^
INFO    Thu Feb 01 2024 07:23:13    Completion: context.verify_mode = ssl.CERT_NONE
INFO    Thu Feb 01 2024 07:23:13    Completion: File "X:\NZBGet\Scripts\Completion.py", line 981, in create_sockets
INFO    Thu Feb 01 2024 07:23:13    Completion: Traceback (most recent call last):
INFO    Thu Feb 01 2024 07:23:13    Completion: Using server: ssl-eu.astraweb.com
INFO    Thu Feb 01 2024 07:23:13    Completion: Failed ratio for server: news.usenet.farm: 0.2%. Server check completed in 153.19 sec.
WARNING Thu Feb 01 2024 07:23:13    Completion: Skipping current server as it is replying very slow on header requests for this NZB file
INFO    Thu Feb 01 2024 07:22:22    Completion: Requested [1/11450] articles, 1 failed.
INFO    Thu Feb 01 2024 07:22:22    Completion: Exception LINE: None: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:20:40    Completion: ValueError: Cannot set verify_mode to CERT_NONE when check_hostname is enabled.
INFO    Thu Feb 01 2024 07:20:40    Completion: super(SSLContext, SSLContext).verify_mode.__set__(self, value)
INFO    Thu Feb 01 2024 07:20:40    Completion: File "XXX\Programs\Python\Python312\Lib\ssl.py", line 680, in verify_mode
INFO    Thu Feb 01 2024 07:20:40    Completion: ^^^^^^^^^^^^^^^^^^^
INFO    Thu Feb 01 2024 07:20:40    Completion: context.verify_mode = ssl.CERT_NONE
INFO    Thu Feb 01 2024 07:20:40    Completion: File "X:\NZBGet\Scripts\Completion.py", line 981, in create_sockets
INFO    Thu Feb 01 2024 07:20:40    Completion: Traceback (most recent call last):
INFO    Thu Feb 01 2024 07:20:40    Completion: Using server: news.usenet.farm
INFO    Thu Feb 01 2024 07:20:40    Completion: Maximum failed articles limit for NZB: 0.0%
INFO    Thu Feb 01 2024 07:20:40    Completion: Checking: "Kali-linux-2019-AMD64.nzb.queued"
INFO    Thu Feb 01 2024 07:20:40    Completion: X:\NZBGet\NZB\Kali-linux-2019-AMD64.nzb.queued
INFO    Thu Feb 01 2024 07:20:39    Executing queue-script Completion.py for Kali-linux-2019-AMD64
INFO    Thu Feb 01 2024 07:20:39    FakeDetector: Moving last rar-file to the top: WinPE 11-10-8 Sergei Strelec v2023.04.18 (x86-x64).part42.rar
INFO    Thu Feb 01 2024 07:20:39    FakeDetector: Sorting inner files for earlier fake detection for Kali-linux-2019-AMD64
INFO    Thu Feb 01 2024 07:20:39    Executing queue-script FakeDetector.py for Kali-linux-2019-AMD64
INFO    Thu Feb 01 2024 07:20:39    Reordering files for Kali-linux-2019-AMD64
INFO    Thu Feb 01 2024 07:20:39    Collection Kali-linux-2019-AMD64 added to queue
INFO    Thu Feb 01 2024 07:20:39    Adding collection Kali-linux-2019-AMD64.nzb to queue
INFO    Thu Feb 01 2024 07:20:39    Executing scan-script Completion.py for Kali-linux-2019-AMD64.nzb
INFO    Thu Feb 01 2024 07:20:35    Reordering files for Kali-linux-2019-AMD64
INFO    Thu Feb 01 2024 07:20:35    Queue Kali-linux-2019-AMD64 @ dl.dognzb.cr
INFO    Thu Feb 01 2024 07:20:10    Executing scheduler-script Completion.py
INFO    Thu Feb 01 2024 07:20:10    Scheduler: unpausing download
INFO    Thu Feb 01 2024 07:20:10    nzbget 22.2-testing-20240126 service-mode
dnzbk commented 9 months ago

@sdburrows

Thanks for the tests. It was very helpful. I was able to reproduce the problem and fix it. I even improved the script a bit by adding the ability to set the minimum TLS version. The default value (TLSv1_1) should work well with usenet servers you mentioned. I have prepared a new version of the script so it would be helpful if you could confirm that everything is really working now.

Completion_test.zip

sdburrows commented 9 months ago

@dnzbk

The good news is I stopped receiving error messages. The bad news is it keeps telling me I have missing articles. I have tried downloading a few different files and they all came back the same i.e. 1 failed and 101 failed.

Download just paused afterwards. 

WARNING | Tue Feb 06 2024 07:12:57 | Completion: "XXXX.nzb.queued", remains paused for next check, no suitable/complete DUPEs found in history
-- | -- | --
INFO | Tue Feb 06 2024 07:12:57 | Completion: Failed ratio for server: bonus.frugalusenet.com: 14.6%. Server check completed in 17.18 sec.
INFO | Tue Feb 06 2024 07:12:56 | Completion: Requested [101/1007] articles, 101 failed.
INFO | Tue Feb 06 2024 07:12:56 | Completion: Requested [1/1007] articles, 1 failed.
INFO | Tue Feb 06 2024 07:12:40 | Completion: Using server: bonus.frugalusenet.com
INFO | Tue Feb 06 2024 07:12:40 | Completion: Failed ratio for server: news.frugalusenet.com: 12.4%. Server check completed in 14.27 sec.
INFO | Tue Feb 06 2024 07:12:39 | Completion: Requested [101/1007] articles, 101 failed.
INFO | Tue Feb 06 2024 07:12:39 | Completion: Requested [1/1007] articles, 1 failed.
INFO | Tue Feb 06 2024 07:12:25 | Completion: Using server: news.frugalusenet.com
INFO | Tue Feb 06 2024 07:12:25 | Completion: Failed ratio for server: block.cheapnews.eu: 10.7%. Server check completed in 4.13 sec.
INFO | Tue Feb 06 2024 07:12:25 | Completion: Requested [101/1007] articles, 101 failed.
INFO | Tue Feb 06 2024 07:12:25 | Completion: Requested [1/1007] articles, 1 failed.
INFO | Tue Feb 06 2024 07:12:21 | Completion: Using server: block.cheapnews.eu
INFO | Tue Feb 06 2024 07:12:21 | Completion: Failed ratio for server: ssl-eu.astraweb.com: 14.9%. Server check completed in 14.15 sec.
INFO | Tue Feb 06 2024 07:12:21 | Completion: Requested [101/1007] articles, 101 failed.
INFO | Tue Feb 06 2024 07:12:21 | Completion: Requested [1/1007] articles, 1 failed.
INFO | Tue Feb 06 2024 07:12:07 | Completion: Using server: ssl-eu.astraweb.com
INFO | Tue Feb 06 2024 07:12:07 | Completion: Failed ratio for server: news.usenet.farm: 14.3%. Server check completed in 16.16 sec.
INFO | Tue Feb 06 2024 07:12:05 | Completion: Requested [101/1007] articles, 101 failed.
INFO | Tue Feb 06 2024 07:12:05 | Completion: Requested [1/1007] articles, 1 failed.
INFO | Tue Feb 06 2024 07:11:51 | Completion: context.minimum_version = get_min_tls_version(MIN_TLS_VERSION)
INFO | Tue Feb 06 2024 07:11:51 | Completion: X:\NZBGet\Scripts\Completion.py:998: DeprecationWarning: ssl.TLSVersion.TLSv1_1 is deprecated
INFO | Tue Feb 06 2024 07:11:51 | Completion: Using server: news.usenet.farm
INFO | Tue Feb 06 2024 07:11:51 | Completion: Maximum failed articles limit for NZB: 10.099999999999994%
dnzbk commented 9 months ago

@sdburrows

Thank you for the feedback.

The problem with SSL hasn't been solved and this extension needs more development time, I'll work on it soon.

sdburrows commented 6 months ago

@dnzbk

Hi, has there been any more updates on this? I have disabled this extension for months now, hoping for a fix...

dnzbk commented 6 months ago

@sdburrows

One of my top priorities right now. Sorry for taking so long.

sdburrows commented 6 months ago

@dnzbk Thanks! Look forward to it!

dnzbk commented 6 months ago

@sdburrows

Fixed all the bugs I could find. Could you test the new version on your side to see if everything works fine now? If so, I will add this version to the extension manager, thanks.

Completion.zip

sdburrows commented 6 months ago

@dnzbk

Thanks for the update. So far, so good. I haven't received any error messages. It does take a while to get started when an NZB is added, about 1 minute (see log). Two other observations:

  1. Maximum failed articles limit (CheckLimit) for NZB is set at 10% in the settings but it logs as 10.9999%, why is this showing like this (may be this is cosmetic only)?
  2. Why is it using my backup server for completion check rather than my main? More of a curiosity, I specifically set Server to 1 (main) and Fill Server to 2,3,4..., yet it still use 2 Is it meant to do this? I think it is fine to use fill server to check i.e. if main server failed, the fill server is meant to be as a backup anyway or is the reasoning when downloading, main server might be maxed out, so fill server is used so as not to disrupt the main download? 
INFO    Sun May 05 2024 18:24:12    Completion: Overall check completed in 51.69 sec.
INFO    Sun May 05 2024 18:24:12    Completion: Resuming: "D:\NZBGet\NZB\TEST.nzb.queued"
INFO    Sun May 05 2024 18:24:12    Completion: Failed ratio for server: news.usenet.farm: 0.0%. Server check completed in 51.65 sec.
INFO    Sun May 05 2024 18:24:12    Completion: All requested article replies received, 0 failed.
INFO    Sun May 05 2024 18:24:11    Completion: Requested [1062/1062] articles, 0 failed.
INFO    Sun May 05 2024 18:24:09    Completion: Requested [796/1062] articles, 0 failed.
INFO    Sun May 05 2024 18:24:06    Completion: Requested [531/1062] articles, 0 failed.
INFO    Sun May 05 2024 18:24:04    Completion: Requested [265/1062] articles, 0 failed.
INFO    Sun May 05 2024 18:24:01    Completion: Requested [107/1062] articles, 0 failed.
INFO    Sun May 05 2024 18:24:00    Completion: Requested [1/1062] articles, 0 failed.
INFO    Sun May 05 2024 18:23:20    Completion: Using server: news.usenet.farm
INFO    Sun May 05 2024 18:23:20    Completion: Maximum failed articles limit for NZB: 10.099999999999994%
INFO    Sun May 05 2024 18:23:20    Completion: Checking: "D:\NZBGet\NZB\TEST.nzb.queued"
INFO    Sun May 05 2024 18:23:20    Completion: D:\NZBGet\NZB\TEST.nzb.queued
INFO    Sun May 05 2024 18:23:20    Executing queue-script Completion for TEST
sdburrows commented 6 months ago

Found some error messages as I unpause my queue: 

INFO | Mon May 06 2024 07:09:23 | Completion: TypeError: can only concatenate str (not "NoneType") to str
INFO | Mon May 06 2024 07:09:23 | Completion: ~~~~~~~~~~~~~~^~~~~~~~
INFO | Mon May 06 2024 07:09:23 | Completion: print('Checking: "' + nzb[1] + '"')
INFO | Mon May 06 2024 07:09:23 | Completion: File "D:\NZBGet\Scripts\Completion\main.py", line 233, in get_nzb_status
INFO | Mon May 06 2024 07:09:23 | Completion: ^^^^^^^^^^^^^^^^^^^
INFO | Mon May 06 2024 07:09:23 | Completion: if get_nzb_status(nzb):
INFO | Mon May 06 2024 07:09:23 | Completion: File "D:\NZBGet\Scripts\Completion\main.py", line 1777, in get_prio_nzb
INFO | Mon May 06 2024 07:09:23 | Completion: get_prio_nzb(jobs["result"], paused_jobs)
INFO | Mon May 06 2024 07:09:23 | Completion: File "D:\NZBGet\Scripts\Completion\main.py", line 1808, in scheduler_call
INFO | Mon May 06 2024 07:09:23 | Completion: scheduler_call()
INFO | Mon May 06 2024 07:09:23 | Completion: File "D:\NZBGet\Scripts\Completion\main.py", line 1951, in main
INFO | Mon May 06 2024 07:09:23 | Completion: main()
INFO | Mon May 06 2024 07:09:23 | Completion: File "D:\NZBGet\Scripts\Completion\main.py", line 1982, in <module>
INFO | Mon May 06 2024 07:09:23 | Completion: Traceback (most recent call last):
dnzbk commented 6 months ago

@sdburrows

Thanks for the feedback. It was very useful.

  1. According to the code, this message has nothing to do with CheckLimit. The result relies on the CriticalHealth value that comes from the NZBGet and is calculated using the following formula: failed_limit = 100 - nzb_critical_health / 10.0 CriticalHealth - Calculated critical health of the group, in permille. 1000 means 100.0%. The critical health is calculated based on the number and size of par-files. Lower values are better.

  2. Could not reproduce. Completion always tries to use the main server first (unless it is turned off of course) and then checks the others - this is exactly the behavior I observed when I was testing.

  3. Fixed.

Fixed version Another round of testing on your side would be very helpful, thanks!

sdburrows commented 6 months ago

@dnzbk, I completed my test, no more errors. Some quality of life improvements (suggestions only):

  1. Apply decimal place rounding on Maximum failed articles limit as it shows up as 10.09999999% to 10.1% or something
  2. Currently when checking for completion, the status is shown as paused, can we change that to Checkingor something and have the progress bar show checking progress in % similar Sabnzb
dnzbk commented 6 months ago

@sdburrows

Thanks for testing and your suggestions.

  1. Yes I will, no problem;
  2. This one is more complicated to implement. Right now, NZBGet doesn't provide a way to set the status to "Checked" or something similar via RPC. You could create another issue with this suggestion and I'll get back to it as soon as I have more free time, thanks.
sdburrows commented 6 months ago

New request added: https://github.com/nzbgetcom/nzbget/issues/265

I guess you can close this issue now. Thanks for your help :)

sdburrows commented 6 months ago

@dnzbk apologies to resuscitate this, why does completion shows 4x the log every so often even though I have no download in the queue

INFO | Wed May 08 2024 07:13:00 | Executing scheduler-script Completion
-- | -- | --
INFO | Wed May 08 2024 07:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 07:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 07:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 07:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 06:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 05:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 04:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 03:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 02:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:45:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:30:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:15:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:00:00 | Executing scheduler-script Completion
INFO | Wed May 08 2024 01:00:00 | Executing scheduler-script Completion
dnzbk commented 6 months ago

@sdburrows

No worries.

Could you check SETTINGS->EXTENSION SCRIPTS->EXTENSIONS? Maybe Completion was accidentally specified twice or even more.

Regarding the logging time interval, this is completely normal behavior for the scheduler extension. As you may have noticed in the logs, the script is executed every 15 min of every hour as it's set in the taskTime option.

sdburrows commented 6 months ago

@dnzbk, I have only specified it once (see screenshot). Not sure what is happening here

EDIT: I have restarted the computer and the problem went away!

Screenshot 2024-05-09 071040

Thanks for the explanation on tasktime.