Log Rotation aber Diskspace wird nicht frei gegeben

[robi]

Hallo
Bin ein Neuling in Python und habe folgende Situation die ich nicht lösen kann.
Python 2.7.11, Device: S4 CommPro X, sitec-systems
Dieser Code initialisiert das Logging, nach 10M soll es rotiert werden und 3 Versionen aufbehalten werden. Was auch soweit funktioniert.
Allerdings, das Filesystem in dem /var/log sitzt wächst ständig an bis es 100% voll ist. Alle Files zusammen gezählt brauchen aber nur ca. 10% des Filesystems.
Das Python Script läuft permanent (24x7) weil es Messungen macht. Ist das Filesystem voll und stoppe ich das Script fällt das Filesystem schlagartig auch ca. 10% runter.
Also werden die Blöcke trotz rotieren nicht freigegeben.
Hat jemand dazu eine Lösung?

Code: Alles auswählen

# initialize logging
level = logging.getLevelName(log_level.upper())
log_file_format = '%(levelname)s: %(asctime)s %(message)s'
log_cons_format = '%(levelname)s: %(asctime)s %(message)s'
logging.basicConfig(format=log_file_format,
                    filename=log_dir + '/labjack.log',
                    encoding='utf-8',
                    level=level)

logger_cons = logging.StreamHandler(sys.stdout)
logger_cons.setLevel(level)
log_fmt = logging.Formatter(fmt=log_cons_format,datefmt='%H:%M:%S')
logger_cons.setFormatter(log_fmt)
rotator = logging.handlers.RotatingFileHandler(log_dir + '/labjack.log',
                                                maxBytes=10000000,
                                                backupCount=3)
logging.getLogger('').addHandler(logger_cons)
logging.getLogger('').addHandler(rotator)

logging.info('MSG09 Program started')

Grüße robi

[__deets__]

Das das beenden des Skriptes da einen Einfluss hat, finde ich bemerkenswert. Sind denn die problematischen alten logs im System zu sehen, während das Skript noch läuft?

[nezzcarth]

Welches Dateisystem kommt da zum Einsatz? Vielleicht Btrfs?

[paddie]

Das hatte ich hier auch schon mal (allerdings ohne Python). Datei löschen ging, wurde auch nicht mehr angezeigt. Aber ein anderer Dienst hatte die Datei immernoch geöffnet und so wurde der Platz eben nicht freigegeben. Scheinbar hat das Script nicht alle Handler auf die gelöschten Dateien entfernt oder irgend etwas anderes hat die Logs auch noch geöffnet.

Vielleicht einfach mal mit lsof prüfen wovon die Datei noch geöffnet wurde.

[__blackjack__]

@robi: Nur geraten, aber bei `basicConfig()` konfigurierst Du eine Logdatei mit dem gleichen Namen, die aber *nicht* rotiert wird. Könnte da die Datei sein, die ewig weiterwächst, die man aber nicht “findet“, weil der Eintrag im Verzeichnis ”wegrotiert” wird weil da der gleiche Dateiname für das rotierende Log verwendet wird?

[narpfel]

Ich habe die gleiche Vermutung wie __blackjack__, `lsof` zeigt für den Prozess eine endlos wachsende Datei `labjack.log.3 (deleted)` an. Vermutlich also die „originale“ `labjack.log`-Datei, die durch den `RotatingFileHandler` mehrfach umbenannt und dann gelöscht wurde, aber noch vom in `basicConfig` erstellten `FileHandler` offen gehalten wird.

[robi]

Hallo
Danke für die Tipps.
1) Filesystem ist tmpfs
2) Das ist leider ein abgestriptes Linux von sitec, das hat kein lsof
3) Ich habe das Coding jetzt geändert, läuft aber noch nicht so wie ich will. Da würde ich nochmal Hilfe brauchen.
Habe das Rotieren als Handler zu basicConfig hinzugefügt. So wie ich das verstanden habe, brauche ich jetzt kein filename in basicConfig angeben.
Das Logging auf die Console funktioniert, allerdings ins Logfile wird nichts geschrieben. Was stimmt da noch nicht.

Code: Alles auswählen

# initialize logging
level = logging.getLevelName(log_level.upper())
log_file_format = '%(levelname)s: %(asctime)s %(message)s'
log_cons_format = '%(levelname)s: %(asctime)s %(message)s'
rotator = logging.handlers.RotatingFileHandler(log_dir + '/labjack.log',
                                                maxBytes=10000000,
                                                encoding='utf-8',
                                                backupCount=3)
rotator.setLevel(level)
logging.basicConfig(format=log_file_format,
                    encoding='utf-8',
                    level=level,
                    handlers=[rotator],
                    )

logger_cons = logging.StreamHandler(sys.stdout)
logger_cons.setLevel(level)
log_fmt_cons = logging.Formatter(fmt=log_cons_format,datefmt='%H:%M:%S')
log_fmt_file = logging.Formatter(fmt=log_file_format,datefmt='%H:%M:%S')
logger_cons.setFormatter(log_fmt_cons)
logging.getLogger('').addHandler(logger_cons)

logging.info('MSG09 Program started')

Danke im voraus.

[robi]

Ich habe das Logging ein wenig umgebaut, das Problem besteht aber immer noch.
Das Rotieren ist jetzt ein Handler von basicConfig und das ganze Logging ist jetzt instanziert um vom default Logging wegzukommen.
Ich habe jetzt 2 Situationen von denen ich nicht wegkomme:
1) Wenn ich in basicConfig den den Parameter filename entferne, dann wird zwar das Logfile angelegt aber nichts reingeschrieben.
2) Gebe ich filename an, wird das Logfile geschrieben und rotiert aber das Filesystem wächst weiter an. Siehe Output unten.

Über Tipps wäre ich dankbar.

Code: Alles auswählen

# initialize logging
level = logging.getLevelName(log_level.upper())
log_file = log_dir + '/labjack.log'
log_file_format = '%(levelname)s: %(asctime)s %(message)s'
log_cons_format = '%(levelname)s: %(asctime)s %(message)s'
log_fmt_cons = logging.Formatter(fmt=log_cons_format,datefmt='%H:%M:%S')
log_fmt_file = logging.Formatter(fmt=log_file_format,datefmt='%H:%M:%S')

logger = logging.getLogger('LabJack_Log')

# define log rotation
rotator = logging.handlers.RotatingFileHandler(
                                                filename=log_file,
                                                maxBytes=10000000,
                                                encoding='utf-8',
                                                backupCount=3
                                              )
rotator.setLevel(level)

# define file logging
baseLog = logging.basicConfig(
                              filename=log_file,
                              format=log_file_format,
                              encoding='utf-8',
                              level=level,
                              handlers=[rotator]
                              )

# define console logging
logger_cons = logging.StreamHandler(sys.stdout)
logger_cons.setLevel(level)
logger_cons.setFormatter(log_fmt_cons)

logger.addHandler(logger_cons)
logger.addHandler(rotator)

logger.info('MSG09 Program started')

Filesystem vor und nach Stopp des Python Scripts.
Das Verzeichnis /var/log ist ein Symlink auf /var/volatile/log.

Code: Alles auswählen

root@kri-uwh0002:# ls -l /var/log/la*; df -h
-rw-r--r--    1 root     root        682622 Sep 21 02:36 /var/log/labjack.log
-rw-r--r--    1 root     root       9999989 Sep 21 02:24 /var/log/labjack.log.1
-rw-r--r--    1 root     root       9999934 Sep 20 23:16 /var/log/labjack.log.2
-rw-r--r--    1 root     root       9999982 Sep 20 20:09 /var/log/labjack.log.3
-rw-r--r--    1 root     root           292 Sep 18 08:12 /var/log/lastlog
Filesystem                Size      Used Available Use% Mounted on
ubi0:rootfs             313.6M     99.4M    214.2M  32% /
devtmpfs                 87.7M         0     87.7M   0% /dev
tmpfs                   247.9M    212.0K    247.7M   0% /run
tmpfs                   247.9M    198.2M     49.6M  80% /var/volatile
root@kri-uwh0002:# /etc/init.d/labjack.sh stop
Stopping labjack: OK
root@kri-uwh0002:# ls -l /var/log/la*; df -h
-rw-r--r--    1 root     root        747052 Sep 21 02:38 /var/log/labjack.log
-rw-r--r--    1 root     root       9999989 Sep 21 02:24 /var/log/labjack.log.1
-rw-r--r--    1 root     root       9999934 Sep 20 23:16 /var/log/labjack.log.2
-rw-r--r--    1 root     root       9999982 Sep 20 20:09 /var/log/labjack.log.3
-rw-r--r--    1 root     root           292 Sep 18 08:12 /var/log/lastlog
Filesystem                Size      Used Available Use% Mounted on
ubi0:rootfs             313.6M     99.4M    214.2M  32% /
devtmpfs                 87.7M         0     87.7M   0% /dev
tmpfs                   247.9M    212.0K    247.7M   0% /run
tmpfs                   247.9M     29.7M    218.2M  12% /var/volatile