Logging to external File does not work reliable

*** Platform information:**

  • Hardware: Raspberry PI 3B+_
  • OS: openHABianPi 4.19.58-v7+
  • Java Runtime Environment: openjdk version “1.8.0_152”
    OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
    OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
  • openHAB version: 2.4.0-1

*** Issue of the topic:** I created a separate logfile (Drucker.log) to log the power-consumption of my 3D-Printer. It is the third time that I have created separate logfile but this time it seems like it is not working reliably. It sometimes writes something in the logfile and sometimes it does not. Additionally I write every log into the normal openhab.log file, which works like a charm … so I think it is definitely not a matter of “what I want to be logged” but “how I want to log it” or “how the separate logfile is configured”

*** Please post configurations (if applicable):**

  • Services configuration related to the issue
    I also added the KaleaBapi and KaleaWindi-logfile configuration as a reference. These two work without a problem. (“Bapi” is slang/baby-language and means “food” and “Windi” means “diaper” - I hope you learned something new today :slight_smile: )
### Custom Loggers ###
# Logger - KaleaBapi
log4j2.logger.KaleaBapi.name = org.eclipse.smarthome.model.script.KaleaBapi
log4j2.logger.KaleaBapi.level = INFO
log4j2.logger.KaleaBapi.additivity = false
log4j2.logger.KaleaBapi.appenderRefs = KaleaBapi
log4j2.logger.KaleaBapi.appenderRef.Kalea.ref = KALEABAPI

# Logger - KaleaWindi
log4j2.logger.KaleaWindi.name = org.eclipse.smarthome.model.script.KaleaWindi
log4j2.logger.KaleaWindi.level = INFO
log4j2.logger.KaleaWindi.additivity = false
log4j2.logger.KaleaWindi.appenderRefs = KaleaWindi
log4j2.logger.KaleaWindi.appenderRef.Kalea.ref = KALEAWINDI

# Logger - 3D Drucker
log4j2.logger.Drucker.name = org.eclipse.smarthome.model.script.Drucker
log4j2.logger.Drucker.level = INFO
log4j2.logger.Drucker.additivity = false
log4j2.logger.Drucker.appenderRefs = Drucker
log4j2.logger.Drucker.appenderRef.Kalea.ref = DRUCKER
### Custom Appenders ###
# KaleaBapi
log4j2.appender.KaleaBapi.name = KALEABAPI
log4j2.appender.KaleaBapi.type = RollingRandomAccessFile
log4j2.appender.KaleaBapi.fileName = /var/log/openhab2/KaleaBapi.log
log4j2.appender.KaleaBapi.filePattern = /var/log/openhab2/KaleaBapi.log.%i
log4j2.appender.KaleaBapi.immediateFlush = true
log4j2.appender.KaleaBapi.append = true
log4j2.appender.KaleaBapi.layout.type = PatternLayout
log4j2.appender.KaleaBapi.layout.pattern = %d{dd-MMM-yyyy HH:mm}: %m%n
log4j2.appender.KaleaBapi.policies.type = Policies
log4j2.appender.KaleaBapi.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.KaleaBapi.policies.size.size = 10MB
log4j2.appender.KaleaBapi.strategy.type = DefaultRolloverStrategy
log4j2.appender.KaleaBapi.strategy.max = 10

# KaleaWindi
log4j2.appender.KaleaWindi.name = KALEAWINDI
log4j2.appender.KaleaWindi.type = RollingRandomAccessFile
log4j2.appender.KaleaWindi.fileName = /var/log/openhab2/KaleaWindi.log
log4j2.appender.KaleaWindi.filePattern = /var/log/openhab2/KaleaWindi.log.%i
log4j2.appender.KaleaWindi.immediateFlush = true
log4j2.appender.KaleaWindi.append = true
log4j2.appender.KaleaWindi.layout.type = PatternLayout
log4j2.appender.KaleaWindi.layout.pattern = %d{dd-MMM-yyyy HH:mm}: %m%n
log4j2.appender.KaleaWindi.policies.type = Policies
log4j2.appender.KaleaWindi.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.KaleaWindi.policies.size.size = 10MB
log4j2.appender.KaleaWindi.strategy.type = DefaultRolloverStrategy
log4j2.appender.KaleaWindi.strategy.max = 10

# Drucker
log4j2.appender.Drucker.name = DRUCKER
log4j2.appender.Drucker.type = RollingRandomAccessFile
log4j2.appender.Drucker.fileName = /var/log/openhab2/Drucker.log
log4j2.appender.Drucker.filePattern = /var/log/openhab2/Drucker.log.%i
log4j2.appender.Drucker.immediateFlush = true
log4j2.appender.Drucker.append = true
log4j2.appender.Drucker.layout.type = PatternLayout
log4j2.appender.Drucker.layout.pattern = %d{dd-MMM-yyyy HH:mm}: %m%n
log4j2.appender.Drucker.policies.type = Policies
log4j2.appender.Drucker.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.Drucker.policies.size.size = 10MB
log4j2.appender.Drucker.strategy.type = DefaultRolloverStrategy
log4j2.appender.Drucker.strategy.max = 10

  • Rules code related to the issue
rule "Log Printer powerconsumption"
when
        Item OctoprintPrinterState changed from Finishing to Operational
then
   
        logInfo("Drucker", "Print "+ OctoprintJobFileName.state + " finished using " + Drucker_kWh_current.state + " kWh Power")
        logInfo("OctoPrint", "Print "+ OctoprintJobFileName.state + " finished using " + Drucker_kWh_current.state + " kWh Power")
        sendCommand(CreateLogs, ON)
        logInfo("OctoPrint", "Print Completed")

end

The “OctoPrint”-Log works but the “Drucker”-Log does not. If I change the “Drucker” Log to log in one of the other custom logfiles (“KaleaWindi”, see configuration below) log It works like a charm too.

  • Item configuration
Switch CreateLogs {channel="exec:command:openhablogs:run", autoupdate="false"}
  • Thing Configuration
Thing exec:command:openhablogs [command="/etc/openhab2/scripts/openhablogs.sh", interval=0, autorun=false]
  • openhablogs.sh Script:
    I had a lot of "^@"s in the Drucker.log file. I didn’t know how else to get rid of them so I sed’ed them out, but then I deleted the openhab cache and now I don’t get these errors anymore so I commented them out.
#!/bin/bash
#sed 's/\^@//g' /var/log/openhab2/Drucker.log > /var/log/openhab2/Drucker_clean.log
#mv /var/log/openhab2/Drucker_clean.log /var/log/openhab2/Drucker.log
tac /var/log/openhab2/KaleaBapi.log | head -n 20 > /etc/openhab2/html/KaleaBapi.log
tac /var/log/openhab2/KaleaWindi.log | head -n 20 > /etc/openhab2/html/KaleaWindi.log
tac /var/log/openhab2/Drucker.log | head -n 50 > /etc/openhab2/html/Drucker.log

  • Sitemap configuration
    I don’t think this is relevant but I will post this part anyway.
Webview url="http://192.168.1.4:8080/static/Drucker.log" height=4
  • If logs where generated please post these here using code fences:
    openhab.log
2019-09-11 16:15:28.138 [INFO ] [pse.smarthome.model.script.OctoPrint] - Print Mittelteil_0.2mm_PLA_MK3S_1h24m.gcode finished using 0.137 kWh Power
2019-09-11 17:17:33.902 [INFO ] [pse.smarthome.model.script.OctoPrint] - Print MiniWheel_0.2mm_PLA_MK3S_46m.gcode finished using 0.084 kWh Power
2019-09-11 18:05:16.105 [INFO ] [pse.smarthome.model.script.OctoPrint] - Print MiniWheel_0.2mm_PLA_MK3S_46m.gcode finished using 0.080 kWh Power
2019-09-11 19:33:56.871 [INFO ] [pse.smarthome.model.script.OctoPrint] - Print Mittelteil_0.2mm_PLA_MK3S_1h24m.gcode finished using 0.142 kWh Power
2019-09-12 00:15:23.738 [INFO ] [pse.smarthome.model.script.OctoPrint] - Print BoxV4_und_V5_0.2mm_PLA_MK3S_4h14m.gcode finished using 0.188 kWh Power

Drucker.log

11-Sep-2019 10:58: Print: Track_set_0.2mm_PLA_MK3S_48m.gcode finished using 0.086 kWh Power
11-Sep-2019 22:24: Print BoxV4_und_V5_0.2mm_PLA_MK3S_4h14m.gcode finished using 0.201 kWh Power

I tried clearing the cache, ending and restarting the openhab service, (multiple) restarts and renaming the logfile (it was called “3DDrucker” previously).

Thanks for reading the whole post btw :slight_smile:

The zwave example works fine, try to adapt this to your needs:

2 Likes

I actually thought I did … but I checked again now and found an error in my Custom Loggers. All of them had the same error in the appenderRef-line.

log4j2.logger.KaleaBapi.appenderRef.Kalea.ref = KALEABAPI
log4j2.logger.KaleaWindi.appenderRef.Kalea.ref = KALEAWINDI
log4j2.logger.Drucker.appenderRef.Kalea.ref = DRUCKER

I guess it should be

log4j2.logger.KaleaBapi.appenderRef.Kaleabapi.ref = KALEABAPI
log4j2.logger.KaleaWindi.appenderRef.KaleaWindi.ref = KALEAWINDI
log4j2.logger.Drucker.appenderRef.Drucker.ref = DRUCKER

restarting openhab now to find out if that changed anything :slight_smile:

Edit: looks like it did …
well … instead of looking for the error elsewhere for days and writing down the configs and describing the error I should have just read the (f-ing) manual :slight_smile:

Thanks @sihui :slight_smile:

1 Like