Auto Log Backup Oddity

Black Hole

Black Hole

May contain traces of nut
The succession of logs seems complete, but why are the saves not always triggering at 1MB and some are less than 1KB?

1688133712725.png
 
Does the contents of the small file give any clue as to what was happening at the time?
Here is the code:
Code: 
        set logsize [$settings logsize]
        # Rotate log file if large enough.
        if {[file exists $::auto::logfile] &&
            [file size $::auto::logfile] > $logsize} {
                set tstamp [clock format [clock seconds] -format {%Y%m%d%H%M%S}]
                file rename -force $::auto::logfile "/mod/tmp/auto.$tstamp.log"
        }
I wonder if this another of those "0" problems? Can $settings logsize return this...
 
Given the above, it seems like it's returning a value less than 104.
Having looked at the code for $settings logsize, it can't return 0.
So it must be either negative or a value between 1 and 103 inclusive. Do you concur?
 
Last edited:
prpr said:
Does the contents of the small file give any clue as to what was happening at the time?
Click to expand...
There's been a purge since then. Here a couple of slightly less small files (581 and 582 bytes):
 

Attachments

  • auto.20230701215801.log.txt
    581 bytes · Views: 2
  • auto.20230701093702.log.txt
    582 bytes · Views: 1
It doesn't help. Can you add this and report back next time it happens:
Diff: 
--- /mod/webif/lib/auto/util.jim~
+++ /mod/webif/lib/auto/util.jim
@@ -18,6 +18,7 @@
        if {$::auto::logfd eq "unset"} {
                set ::auto::logfd [open "/mod/tmp/auto.log" "a+"]
        }
+       puts $::auto::logfd "Logsize is $logsize"
 }
 
 proc ::auto::log {msg {level 1}} {
 
OK, shouldn't take long...

This is HDR3. My other active machines have zero byte rotations, the difference possibly accounted for by differences in log levels.
 
123 bytes:
Code: 
Logsize is 1048576
02/07/2023 13:34:02 - Aborting, not yet time to run.
02/07/2023 13:34:02 -   elapsed (minutes): 0 (<10)

123 bytes:
Code: 
Logsize is 1048576
02/07/2023 16:41:01 - Aborting, not yet time to run.
02/07/2023 16:41:01 -   elapsed (minutes): 0 (<10)

What is $logsize supposed to represent? It's constant throughout. Here's an extract from the current auto.log (400k+):

Code: 
Logsize is 1048576
02/07/2023 16:41:01 - Auto de-queue starting
02/07/2023 16:41:01 - Registered decrypt with priority 900
02/07/2023 16:41:01 - Registered mp3 with priority 300
02/07/2023 16:41:01 - Registered mpg with priority 300
02/07/2023 16:41:01 - Registered shrink with priority 400
02/07/2023 16:41:01 - Registered arbookmarks with priority 500
02/07/2023 16:41:01 - Registered detectads with priority 200
02/07/2023 16:41:01 - Registered qtube with priority 200
02/07/2023 16:41:01 - Registered thumb with priority 100
02/07/2023 16:41:01 - Auto de-queue processed 0 items in 0.171 seconds.
Logsize is 1048576
02/07/2023 16:42:01 - Auto de-queue starting
02/07/2023 16:42:01 - Registered decrypt with priority 900
02/07/2023 16:42:01 - Registered mp3 with priority 300
02/07/2023 16:42:01 - Registered mpg with priority 300
02/07/2023 16:42:01 - Registered shrink with priority 400
02/07/2023 16:42:01 - Registered arbookmarks with priority 500
02/07/2023 16:42:01 - Registered detectads with priority 200
Logsize is 1048576
02/07/2023 16:42:01 - Aborting, not yet time to run.
02/07/2023 16:42:01 -   elapsed (minutes): 1 (<10)
02/07/2023 16:42:01 - Registered qtube with priority 200
02/07/2023 16:42:01 - Registered thumb with priority 100
02/07/2023 16:42:01 - Auto de-queue processed 0 items in 0.166 seconds.
Logsize is 1048576
02/07/2023 16:43:01 - Auto de-queue starting
Logsize is 1048576
02/07/2023 16:43:01 - Aborting, not yet time to run.
02/07/2023 16:43:01 -   elapsed (minutes): 2 (<10)
02/07/2023 16:43:01 - Registered decrypt with priority 900
02/07/2023 16:43:01 - Registered mp3 with priority 300
02/07/2023 16:43:01 - Registered mpg with priority 300
02/07/2023 16:43:01 - Registered shrink with priority 400
02/07/2023 16:43:01 - Registered arbookmarks with priority 500
02/07/2023 16:43:01 - Registered detectads with priority 200
02/07/2023 16:43:01 - Registered qtube with priority 200
02/07/2023 16:43:01 - Registered thumb with priority 100
02/07/2023 16:43:01 - Auto de-queue processed 0 items in 0.153 seconds.
Logsize is 1048576...
 
Black Hole said:
What is $logsize supposed to represent?
Click to expand...
How big the log file can get before it gets rotated to the timed/dated files and a new one started. I can't find where it gets set as there appears to be no UI for it. The 1M value is hardcoded when it can't read the value from the WebIf's database.
I'm perplexed currently.
Can you try this:
Code: 
--- util.jim~
+++ util.jim
@@ -7,6 +7,7 @@
 proc ::auto::loginit {} {
        variable settings
        set logsize [$settings logsize]
+       set fsize [file size $::auto::logfile]
        # Rotate log file if large enough.
        if {[file exists $::auto::logfile] &&
            [file size $::auto::logfile] > $logsize} {
@@ -18,6 +19,7 @@
        if {$::auto::logfd eq "unset"} {
                set ::auto::logfd [open "/mod/tmp/auto.log" "a+"]
        }
+       puts $::auto::logfd "Logsize is $logsize, size is $fsize"
 }

 proc ::auto::log {msg {level 1}} {
 
I think I see what's happening. Before it gets rotated, the auto.log is growing normally... but then it gets rotated and the resulting file is truncated for some reason (no, I don't know how a rename operation can truncate a file, but nonetheless).
 
Damn, this time it didn't.

Code: 
HDRFOX3# ls -l auto*                                                                              
-rw-rw-rw- 1 root root  1.1M Jul  2 13:33 auto.20230702133401.log                                 
-rw-rw-rw- 1 root root   123 Jul  2 13:34 auto.20230702133402.log
-rw-rw-rw- 1 root root   123 Jul  2 16:41 auto.20230702164101.log
-rw-rw-rw- 1 root root   123 Jul  2 19:39 auto.20230702193902.log
-rw-rw-rw- 1 root root  1.1M Jul  2 22:46 auto.20230702224701.log
-rw-rw-rw- 1 root root  3.7K Jul  2 22:51 auto.log
-rw------- 1 root root 1008K Jul  2 22:40 auto.snapshot.log
HDRFOX3#

The snapshot file is one I was making to try to preserve the file content.

Here's the problem: the only log rotation which appears authentically short is the 13:34 one (just one minute after the previous). The others are at intervals of three hours, and should be the full 1MB.

The size report is showing the right thing.
 
Black Hole said:
Curiously, it does appear to be deleting old logs even though that's set to "0"
Click to expand...
It's deleting them because you're telling it to keep 2. The log management only runs at startup, so I've discovered. Is this box on 24/7?
 
I wonder if this is a race condition between scan and deq which are the only things that use the aforementioned util.jim. From crontab:
Code: 
* * * * * /mod/webif/lib/auto/scan >/dev/null 2>>/mod/tmp/auto.log
* * * * * /mod/webif/lib/auto/deq >/dev/null 2>>/mod/tmp/auto.log
both are processing the log file at the exact same time. They are protected by locks from multiple instances of themselves, but not from each other.
 
prpr said:
It's deleting them because you're telling it to keep 2.
Click to expand...
Doh!

prpr said:
The log management only runs at startup
Click to expand...
That explains a few things! The list becomes quite long, but then gets pruned if I've had to reboot. Perhaps the prune process needs to be triggered whenever there is a rotation.

prpr said:
I wonder if this is a race condition between scan and deq
Click to expand...
I can't explain the timestamps situation in post 13, but I have spotted something: the reported size sometimes lags behind, duplicating a previous value. If that happens immediately after a rotation has been triggered, then another rotation gets triggered in short order.
 
Tail of auto.20230703084501.log (1.05MB):
Code: 
03/07/2023 05:20:06 - Auto processing completed in 64.714 seconds.
Logsize is 1048576, size is 1038019
03/07/2023 05:21:02 - Aborting, not yet time to run.
03/07/2023 05:21:02 -   elapsed (minutes): 0 (<10)
Logsize is 1048576, size is 1038019
03/07/2023 05:21:02 - Auto de-queue starting
03/07/2023 05:21:02 - Registered decrypt with priority 900
03/07/2023 05:21:02 - Registered mp3 with priority 300
03/07/2023 05:21:02 - Registered mpg with priority 300
03/07/2023 05:21:02 - Registered shrink with priority 400
03/07/2023 05:21:02 - Registered arbookmarks with priority 500
03/07/2023 05:21:02 - Registered detectads with priority 200
03/07/2023 05:21:02 - Registered qtube with priority 200
03/07/2023 05:21:02 - Registered thumb with priority 100
03/07/2023 05:21:02 - Auto de-queue processed 0 items in 0.317 seconds.
Logsize is 1048576, size is 1038777
03/07/2023 05:22:01 - Auto de-queue starting
03/07/2023 05:22:01 - Registered decrypt with priority 900
03/07/2023 05:22:01 - Registered mp3 with priority 300
03/07/2023 05:22:01 - Registered mpg with priority 300
03/07/2023 05:22:01 - Registered shrink with priority 400
03/07/2023 05:22:01 - Registered arbookmarks with priority 500
03/07/2023 05:22:01 - Registered detectads with priority 200
03/07/2023 05:22:01 - Registered qtube with priority 200
03/07/2023 05:22:01 - Registered thumb with priority 100
Logsize is 1048576, size is 1039148
03/07/2023 05:22:02 - Aborting, not yet time to run.
03/07/2023 05:22:02 -   elapsed (minutes): 1 (<10)
03/07/2023 05:22:02 - Auto de-queue processed 0 items in 0.163 seconds.
Logsize is 1048576, size is 1039535
03/07/2023 05:23:02 - Auto de-queue starting
03/07/2023 05:23:02 - Registered decrypt with priority 900
03/07/2023 05:23:02 - Registered mp3 with priority 300
03/07/2023 05:23:02 - Registered mpg with priority 300
Logsize is 1048576, size is 1039675
03/07/2023 05:23:02 - Aborting, not yet time to run.
03/07/2023 05:23:02 -   elapsed (minutes): 2 (<10)
03/07/2023 05:23:02 - Registered shrink with priority 400
03/07/2023 05:23:02 - Registered arbookmarks with priority 500
03/07/2023 05:23:02 - Registered detectads with priority 200
03/07/2023 05:23:02 - Registered qtube with priority 200
03/07/2023 05:23:02 - Registered thumb with priority 100
03/07/2023 05:23:02 - Auto de-queue processed 0 items in 0.295 seconds.
Logsize is 1048576, size is 1040293
03/07/2023 05:24:01 - Auto de-queue starting
03/07/2023 05:24:01 - Registered decrypt with priority 900
03/07/2023 05:24:01 - Registered mp3 with priority 300
03/07/2023 05:24:01 - Registered mpg with priority 300
03/07/2023 05:24:01 - Registered shrink with priority 400
03/07/2023 05:24:01 - Registered arbookmarks with priority 500
03/07/2023 05:24:02 - Registered detectads with priority 200
03/07/2023 05:24:02 - Registered qtube with priority 200
03/07/2023 05:24:02 - Registered thumb with priority 100
03/07/2023 05:24:02 - Auto de-queue processed 0 items in 0.379 seconds.
Logsize is 1048576, size is 1040839
03/07/2023 05:24:02 - Aborting, not yet time to run.
03/07/2023 05:24:02 -   elapsed (minutes): 3 (<10)
Logsize is 1048576, size is 1041051
03/07/2023 05:25:02 - Aborting, not yet time to run.
03/07/2023 05:25:02 -   elapsed (minutes): 4 (<10)
Logsize is 1048576, size is 1041051
03/07/2023 05:25:02 - Auto de-queue starting
03/07/2023 05:25:02 - Registered decrypt with priority 900
03/07/2023 05:25:02 - Registered mp3 with priority 300
03/07/2023 05:25:02 - Registered mpg with priority 300
03/07/2023 05:25:02 - Registered shrink with priority 400
03/07/2023 05:25:02 - Registered arbookmarks with priority 500
03/07/2023 05:25:02 - Registered detectads with priority 200
03/07/2023 05:25:02 - Registered qtube with priority 200
03/07/2023 05:25:02 - Registered thumb with priority 100
03/07/2023 05:25:02 - Auto de-queue processed 0 items in 0.186 seconds.
Logsize is 1048576, size is 1041809
03/07/2023 05:26:02 - Auto de-queue starting
Logsize is 1048576, size is 1041809
03/07/2023 05:26:02 - Aborting, not yet time to run.
03/07/2023 05:26:02 -   elapsed (minutes): 5 (<10)
03/07/2023 05:26:02 - Registered decrypt with priority 900
03/07/2023 05:26:02 - Registered mp3 with priority 300
03/07/2023 05:26:02 - Registered mpg with priority 300
03/07/2023 05:26:02 - Registered shrink with priority 400
03/07/2023 05:26:02 - Registered arbookmarks with priority 500
03/07/2023 05:26:02 - Registered detectads with priority 200
03/07/2023 05:26:02 - Registered qtube with priority 200
03/07/2023 05:26:02 - Registered thumb with priority 100
03/07/2023 05:26:02 - Auto de-queue processed 0 items in 0.252 seconds.
Logsize is 1048576, size is 1042567
03/07/2023 05:27:02 - Auto de-queue starting
03/07/2023 05:27:02 - Registered decrypt with priority 900
03/07/2023 05:27:02 - Registered mp3 with priority 300
03/07/2023 05:27:02 - Registered mpg with priority 300
03/07/2023 05:27:02 - Registered shrink with priority 400
03/07/2023 05:27:02 - Registered arbookmarks with priority 500
03/07/2023 05:27:02 - Registered detectads with priority 200
03/07/2023 05:27:02 - Registered qtube with priority 200
03/07/2023 05:27:02 - Registered thumb with priority 100
03/07/2023 05:27:02 - Auto de-queue processed 0 items in 0.335 seconds.
Logsize is 1048576, size is 1043185
03/07/2023 05:27:02 - Aborting, not yet time to run.
03/07/2023 05:27:02 -   elapsed (minutes): 6 (<10)
Logsize is 1048576, size is 1043325
03/07/2023 05:28:02 - Aborting, not yet time to run.
03/07/2023 05:28:02 -   elapsed (minutes): 7 (<10)
Logsize is 1048576, size is 1043325
03/07/2023 05:28:02 - Auto de-queue starting
03/07/2023 05:28:02 - Registered decrypt with priority 900
03/07/2023 05:28:02 - Registered mp3 with priority 300
03/07/2023 05:28:02 - Registered mpg with priority 300
03/07/2023 05:28:02 - Registered shrink with priority 400
03/07/2023 05:28:02 - Registered arbookmarks with priority 500
03/07/2023 05:28:02 - Registered detectads with priority 200
03/07/2023 05:28:02 - Registered qtube with priority 200
03/07/2023 05:28:02 - Registered thumb with priority 100
03/07/2023 05:28:02 - Auto de-queue processed 0 items in 0.361 seconds.
Logsize is 1048576, size is 1044083
03/07/2023 05:29:02 - Aborting, not yet time to run.
03/07/2023 05:29:02 -   elapsed (minutes): 8 (<10)
Logsize is 1048576, size is 1044223
03/07/2023 05:29:02 - Auto de-queue starting
03/07/2023 05:29:02 - Registered decrypt with priority 900
03/07/2023 05:29:02 - Registered mp3 with priority 300
03/07/2023 05:29:02 - Registered mpg with priority 300
03/07/2023 05:29:02 - Registered shrink with priority 400
03/07/2023 05:29:02 - Registered arbookmarks with priority 500
03/07/2023 05:29:02 - Registered detectads with priority 200
03/07/2023 05:29:02 - Registered qtube with priority 200
03/07/2023 05:29:02 - Registered thumb with priority 100
03/07/2023 05:29:02 - Auto de-queue processed 0 items in 0.243 seconds.
Logsize is 1048576, size is 1044841
03/07/2023 05:30:02 - Auto de-queue starting
03/07/2023 05:30:02 - Registered decrypt with priority 900
03/07/2023 05:30:02 - Registered mp3 with priority 300
03/07/2023 05:30:02 - Registered mpg with priority 300
03/07/2023 05:30:02 - Registered shrink with priority 400
Logsize is 1048576, size is 1044841
03/07/2023 05:30:02 - Aborting, not yet time to run.
03/07/2023 05:30:02 -   elapsed (minutes): 9 (<10)
03/07/2023 05:30:02 - Registered arbookmarks with priority 500
03/07/2023 05:30:02 - Registered detectads with priority 200
03/07/2023 05:30:02 - Registered qtube with priority 200
03/07/2023 05:30:02 - Registered thumb with priority 100
03/07/2023 05:30:02 - Auto de-queue processed 0 items in 0.164 seconds.
Logsize is 1048576, size is 1045599
03/07/2023 05:31:02 - Auto de-queue starting
Logsize is 1048576, size is 1045599
03/07/2023 05:31:02 - Auto processing starting
03/07/2023 05:31:02 - Registered decrypt with priority 900
03/07/2023 05:31:02 - Registered decrypt with priority 600 (::decrypt::run)
03/07/2023 05:31:02 - Registered dedup with priority 800 (::dedup::run)
03/07/2023 05:31:02 - Registered expire with priority 900 (::expire::run)
03/07/2023 05:31:02 - Registered mp3 with priority 300
03/07/2023 05:31:02 - Registered mp3 with priority 300 (::mp3::run)
03/07/2023 05:31:02 - Registered mpg with priority 300
03/07/2023 05:31:02 - Registered mpg with priority 300 (::mpg::run)
03/07/2023 05:31:02 - Registered shrink with priority 400
03/07/2023 05:31:02 - Registered shrink with priority 400 (::shrink::run)
03/07/2023 05:31:02 - Registered skip with priority 990 (::skip::run)
03/07/2023 05:31:02 - Registered arbookmarks with priority 500
03/07/2023 05:31:02 - Registered detectads with priority 200
03/07/2023 05:31:02 - Registered qtube with priority 200
03/07/2023 05:31:02 - Registered thumb with priority 100
03/07/2023 05:31:02 - Registered detectads with priority 300 (::detectads::run)
03/07/2023 05:31:02 - Registered disabledso with priority 1000 (::disabledso::run)
03/07/2023 05:31:02 - Auto de-queue processed 0 items in 0.161 seconds.
03/07/2023 05:31:02 - Registered disableota with priority 1000 (::disableota::run)
03/07/2023 05:31:02 - Registered flatview with priority 650 (::flatview::run)
03/07/2023 05:31:02 - Registered sweeper with priority 700 (::sweeper::run)
03/07/2023 05:31:02 - Registered flag 'sweeper' for sweeper
03/07/2023 05:31:02 - Scanning media for flags...
03/07/2023 05:31:04 - Scan completed (1.669 seconds)
03/07/2023 05:31:04 - Active flags: decryptR decrypt expire
.
. [560 lines of finding nothing to do]
.
03/07/2023 05:32:11 - Auto processing completed in 69.362 seconds.

auto.20230703084501.log (618 bytes), I presume the "1068473" triggered the ending of the previous file:
Code: 
Logsize is 1048576, size is 1068473
03/07/2023 08:45:01 - Auto de-queue starting
03/07/2023 08:45:01 - Registered decrypt with priority 900
03/07/2023 08:45:01 - Registered mp3 with priority 300
03/07/2023 08:45:01 - Registered mpg with priority 300
03/07/2023 08:45:01 - Registered shrink with priority 400
03/07/2023 08:45:01 - Registered arbookmarks with priority 500
03/07/2023 08:45:01 - Registered detectads with priority 200
03/07/2023 08:45:01 - Registered qtube with priority 200
03/07/2023 08:45:01 - Registered thumb with priority 100
03/07/2023 08:45:02 - Auto de-queue processed 0 items in 0.426 seconds.

Top of auto.log (currently 383KB):
Code: 
Logsize is 1048576, size is 1068473
03/07/2023 08:45:01 - Aborting, not yet time to run.
03/07/2023 08:45:01 -   elapsed (minutes): 0 (<10)
Logsize is 1048576, size is 140
03/07/2023 08:46:01 - Auto de-queue starting
03/07/2023 08:46:01 - Registered decrypt with priority 900
03/07/2023 08:46:01 - Registered mp3 with priority 300
03/07/2023 08:46:01 - Registered mpg with priority 300
03/07/2023 08:46:01 - Registered shrink with priority 400
Logsize is 1048576, size is 217
.
.
.

The lack of refresh of "size" seems to be the culprit.
 
prpr said:
I wonder if this is a race condition between scan and deq which are the only things that use the aforementioned util.jim. From crontab:
Code: 
* * * * * /mod/webif/lib/auto/scan >/dev/null 2>>/mod/tmp/auto.log
* * * * * /mod/webif/lib/auto/deq >/dev/null 2>>/mod/tmp/auto.log
both are processing the log file at the exact same time. They are protected by locks from multiple instances of themselves, but not from each other.
Click to expand...
It is deliberate that scan and deq are not serialised - it was the rasion d'etre for splitting the old auto process into scan and deq - you don't want to delay quick actions in scan delayed by very long running actions such as detectads and audio extraction.

There is no good reason for both halves to use the same log file other than the suspicion that some parts of the code possibly referred to "auto.log" directly rather than using the $::auto::logfd and $::auto::logfile global variables to get the log stream details

As well as the auto.log specific rotation code in util.jim referred to above there is also general log stream rotation somewhere else that handles rotation of all other logs - sorry cant be more specific since I'm in deepest Pembrokeshire for a week with no access to humax other than RS

If a deq task already has auto.log open for write when it is rotated it will continue to write to the original, renamed, file which is why some of the log files are larger than the target log file size.
 
Last edited:
Black Hole said:
The lack of refresh of "size" seems to be the culprit.
Click to expand...
The timestamps seem to confirm the race condition to me. The file size command in Jim is just a thin wrapper round the standard stat/stat64 API call, so I think it unlikely that it's a filesystem problem.
 
A fix for this race condition has been implemented in the latest webif beta. Please feedback as to the success or otherwise.
 
You must log in or register to reply here.
Back
Top