Log not working

[mikulik86]

Hi,
my snapraid-runner instance is not writing to log.
My /opt/snapraid-runner/snapraid-runner.conf:

[logging]
; logfile to write to, leave empty to disable
file = /home/mikulik86/snapraid.log
; maximum logfile size in KiB, leave empty for infinite
maxsize = 50000

What am I doing wrong?

[trewok]

Having the same issue, was a solution ever found?

[mikulik86]

Not by me...

[tmanka]

I also have this issue....

if I run manually the log tries to write but the date is not prepended:

-rw-r--r-- 1 root root 4849 May 4 18:07 _Snapraid-runner.log

I typically run this from roots cron:

# m h  dom mon dow   command
00 02 * * * python3 /opt/snapraid-runner/snapraid-runner.py -c /opt/snapraid-runner/snapraid-runner.conf

So I am not getting a log file anywhere (that I can find) and def not where I configure it to write to.

[snapraid]
; path to the snapraid executable
executable = /usr/bin/snapraid
; path to the snapraid config to be used
config = /etc/snapraid.conf
; abort operation if there are more deletes than this, set to -1 to disable
;deletethreshold = 250
deletethreshold = -1
[logging]
; log path to write to
filepath = /home/name/snapraid/log/

; logfile to write to, leave empty to disable
file = _Snapraid-runner.log
; maximum logfile size in KiB, leave empty for infinite
;maxsize = 5000

I can redirect to a log file....but something is off the native functionality to write a log is not running....below is my output from my redirected log.

a@a:~/temp$ tail -f snaplogmanual.log                                                           
2023-05-04 18:06:43,665 [OUTPUT]   sched 29% | *****************                                        
2023-05-04 18:06:43,665 [OUTPUT]    misc  0% |                                                          
2023-05-04 18:06:43,665 [OUTPUT]             |__________________________________________________________
____                                                                                                    
2023-05-04 18:06:43,665 [OUTPUT]                            wait time (total, less is better)           
2023-05-04 18:06:43,665 [OUTPUT]                                                                        
2023-05-04 18:06:43,665 [OUTPUT] Everything OK                                                          
2023-05-04 18:06:44,675 [OUTPUT] Saving state to /var/snapraid.content...                               
2023-05-04 18:06:44,675 [OUTPUT] Saving state to /mnt/disk1/.snapraid.content...                        
2023-05-04 18:06:44,675 [OUTPUT] Saving state to /mnt/disk2/.snapraid.content...                        
2023-05-04 18:06:44,675 [OUTPUT] Saving state to /mnt/disk3/.snapraid.content...                        
2023-05-04 18:06:58,973 [OUTPUT] Verifying...                                                           
2023-05-04 18:07:03,073 [OUTPUT] Verified /var/snapraid.content in 4 seconds                            
2023-05-04 18:07:04,691 [OUTPUT] Verified /mnt/disk3/.snapraid.content in 5 seconds                     
2023-05-04 18:07:04,889 [OUTPUT] Verified /mnt/disk1/.snapraid.content in 5 seconds                     
2023-05-04 18:07:06,503 [OUTPUT] Verified /mnt/disk2/.snapraid.content in 7 seconds                     
2023-05-04 18:07:07,641 [INFO  ] ************************************************************           
2023-05-04 18:07:07,643 [INFO  ] Running scrub...                                                       
2023-05-04 18:07:07,667 [OUTPUT] Self test...                                                           
2023-05-04 18:07:07,801 [OUTPUT] Loading state from /var/snapraid.content...                            
2023-05-04 18:07:11,761 [OUTPUT] Using 1676 MiB of memory for the file-system.                          
2023-05-04 18:07:11,761 [OUTPUT] Initializing...                                                        
2023-05-04 18:07:13,728 [OUTPUT] Using 80 MiB of memory for 64 cached blocks.                           
2023-05-04 18:07:13,729 [OUTPUT] Selecting...                                                           
2023-05-04 18:07:13,850 [OUTPUT] Scrubbing...                                                           
2023-05-04 18:07:13,885 [OUTPUT] Nothing to do                                                          
2023-05-04 18:07:14,373 [INFO  ] ************************************************************           
2023-05-04 18:07:14,374 [INFO  ] All done                                                               
2023-05-04 18:07:16,056 [INFO  ] Run finished successfully     

I looked inside snapraid-runner.conf and snapraid-runner.py I am guessing this section has the logging:

log_format = logging.Formatter(
    "%(asctime)s [%(levelname)-6.6s] %(message)s")

and this is the section that says if you have the variable defined in your config file you should log:

if config["logging"]["file"]:
    max_log_size = max(config["logging"]["maxsize"], 0) * 1024
    file_logger = logging.handlers.RotatingFileHandler(
        config["logging"]["file"],
        maxBytes=max_log_size,
        backupCount=9)
    file_logger.setFormatter(log_format)
    root_logger.addHandler(file_logger)

So as you can see from my config file (and the other example in this thread) they are populated

so the logging SHOULD be happening AND putting in the date and time. It looks like asctime is not working?

or maybe something in

import logging
import logging.handlers

[tmanka]

I brute forced around this until an RCA can be found...updated my crontab to redirect...not graceful but it works...not sure I need to cd into the dir first (I actually doubt it). For anyone that stumbles upon this it can work for now.

00 02 * * * cd /home/name/snapraid/log && python3 /opt/snapraid-runner/snapraid-runner.py -c /opt/snapraid-runner/snapraid-runner.conf &>> /home/name/snapraid/log/$(date +%F)_Snapraid-runner.log

[tmanka]

...my work around works when run manually but not through cron....still looking

[ljo123]

I'm having this issue too. The log works just fine if I run manually but does not work if run by cron. I'm on ubuntu 22.04.

Manual command:

sudo python3 /opt/snapraid-runner/snapraid-runner.py -c /opt/snapraid-runner/snapraid-runner.conf

Crontab command (under root user):

python3 /opt/snapraid-runner/snapraid-runner.py -c /opt/snapraid-runner/snapraid-runner.conf > /dev/null

Snapraid-runnner config:

[logging]
; logfile to write to, leave empty to disable
file = snapraid.log
; maximum logfile size in KiB, leave empty for infinite
maxsize = 5000

All of this was working until recently so I'm not sure if the cause is in the snapraid-runner code or something has broken elsewhere.

Also the email notification log looks correct.

Edit: FIXED! The issue is caused by python buffering

If you run the cronjob unbuffered then file logging works again. Just add -u to your cronjob like this:

python3 -u /opt/snapraid-runner/snapraid-runner.py -c /opt/snapraid-runner/snapraid-runner.conf > /dev/null

One small snag though - on ubuntu this caused the file to be created in the root user's home directory so I had to change the logging file location to the full path not just file = snapraid.log as above.

[Chronial]

Are you sure the -u made any difference there? I would strongly assume that it has always written the log file in the root home – that's what you specified in your config after all.

[ljo123]

Previously it had all been working and was writing to the user home even though it was running under root cron but with the regular user logged in too. Anyway with -u and the full path specified its all working like before so I'm not going to mess with it.