Logging in Python rule: how log to custom file

I have several Python rules that output various messages to the log. I’ve configured pax.logging.cfg with a few custom log files that I’ve been using successfully with DSL rules and I’d like to do the same with my Python rules. One of the custom log files is configured like this:

# Heating rules
log4j2.logger.heating.name = org.eclipse.smarthome.model.script.heating
log4j2.logger.heating.level = DEBUG
log4j2.logger.heating.additivity = false
log4j2.logger.heating.appenderRefs = heating
log4j2.logger.heating.appenderRef.mqtt.ref = HEATING

# Heating rules
log4j2.appender.heating.name = HEATING
log4j2.appender.heating.type = RollingRandomAccessFile
log4j2.appender.heating.fileName = /var/log/openhab2/heating.log
log4j2.appender.heating.filePattern = /var/log/openhab2/heating.log.%i
log4j2.appender.heating.immediateFlush = true
log4j2.appender.heating.append = true
log4j2.appender.heating.layout.type = PatternLayout
log4j2.appender.heating.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n
log4j2.appender.heating.policies.type = Policies
log4j2.appender.heating.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.heating.policies.size.size = 200MB
log4j2.appender.heating.strategy.type = DefaultRolloverStrategy
log4j2.appender.heating.strategy.max = 1

I’ve tried using the following code in one of my python heating rules to output to the heating log:

from core.log import logging, LOG_PREFIX

log = logging.getLogger("heating")

log.info("Heating: boost mode engaged due to room ({}), set point = ({}), temp = ({}).".format( triggeringRoomGroup, setPointItem.state, thermostatItem.state ))

However, I don’t see any messages in /var/log/openhab/heating.log. What am I doing wrong?

You could do…

from core.log import logging, LOG_PREFIX

log = logging.getLogger("org.eclipse.smarthome.model.script.heating")

Or, add another logger…

log4j2.logger.jython_heating.name = jsr223.jython.heating
log4j2.logger.jython_heating.level = DEBUG
log4j2.logger.jython_heating.additivity = false
log4j2.logger.jython_heating.appenderRefs = jython_heating
log4j2.logger.jython_heating.appenderRef.mqtt.ref = HEATING

You could also change jsr223.jython.heating to jsr223.jython.the_name_of_my_rule, so that you don’t have to log to a separate logger in your rule and just use the log attribute of the rule function.

It’s so obvious now that you’ve pointed it out! Thanks!

I have a few different rules for various heating functions so I find it useful to create several different custom log files and use them in several rules rather than use a logger per rule.

Try naming your rules like “heating.This heating rule” and “heating.That heating rule”. I think this should work for you, so that you can use the rule log attribute and not having to create separate loggers.

Sorry, I think I’m being a bit dense but I don’t quite follow you. Here’s one of my rules that I’ve just reconfigured to use logging.getLogger:

@rule("Boiler central heating set point weather compensation rule", description="This rule calculates the central heating set point based on the outdoor temperature", tags=["Example"])
@when("Item SensorHygrometerOutdoor_Temperature received update")
def dev_boiler_heating_set_point_rule(event):
    minOutdoorTemp      = -5
    maxOutdoorTemp      = 20
    maxFlowTemp         = 70
    minFlowTemp         = 25
    calculatedSetpoint  = 0

    log = logging.getLogger("org.eclipse.smarthome.model.script.heating")

    outdoorTempRange    = maxOutdoorTemp - minOutdoorTemp
    deltaFlowTemp       = maxFlowTemp - minFlowTemp

    outdoorTemp = round(float(str(event.itemState)))
    # clamp the outdoor temperature values to upper and lower limits
    if outdoorTemp < minOutdoorTemp:
        outdoorTemp = minOutdoorTemp
    if outdoorTemp > maxOutdoorTemp:
        outdoorTemp = maxOutdoorTemp

    calculatedSetpoint = ((outdoorTempRange - (outdoorTemp - minOutdoorTemp)) / outdoorTempRange ) * deltaFlowTemp + minFlowTemp + items["BoilerHeatingWeatherCompSetPointBoost"].floatValue()
    calculatedSetpoint = round(calculatedSetpoint)

    if calculatedSetpoint < minFlowTemp:
        calculatedSetpoint = minFlowTemp
    if calculatedSetpoint > maxFlowTemp:
        calculatedSetpoint = maxFlowTemp
    
    events.sendCommand(ir.getItem("BoilerHeatingWeatherCompSetPoint"), calculatedSetpoint)
    # dev_boiler_heating_set_point_rule.log.info("Heating: Calculated set point is ({}), outdoor temp is ({}).".format( calculatedSetpoint, outdoorTemp ))
    log.info("Heating: Calculated set point is ({}), outdoor temp is ({}).".format( calculatedSetpoint, outdoorTemp ))

Do you mean I’d change the rule name to look like this:

@rule("heating.Boiler central heating set point weather compensation rule", description="This rule calculates the central heating set point based on the outdoor temperature", tags=["Example"])
    @when("Item SensorHygrometerOutdoor_Temperature received update")
    def dev_boiler_heating_set_point_rule(event):

or:

@rule("Boiler central heating set point weather compensation rule", description="This rule calculates the central heating set point based on the outdoor temperature", tags=["Example"])
        @when("Item SensorHygrometerOutdoor_Temperature received update")
        def heating.dev_boiler_heating_set_point_rule(event):

and then use this sort of code to write to the log:

dev_boiler_heating_set_point_rule.log.info("Heating: Calculated set point is ({}), outdoor temp is ({}).".format( calculatedSetpoint, outdoorTemp ))

I can’t seem to get either way to work.

The name of the rule is used for the logger, appended to LOG_PREFIX. So, if you have a logger configured like this (mind the cases)…

log4j2.logger.jython_heating.name = jsr223.jython.heating
log4j2.logger.jython_heating.level = DEBUG
log4j2.logger.jython_heating.additivity = false
log4j2.logger.jython_heating.appenderRefs = Jython_Heating
log4j2.logger.jython_heating.appenderRef.Jython_Heating.ref = HEATING

… you can then simply change the name of your rule to have it picked up by the logger…

@rule("heating.Boiler central heating set point weather compensation rule", description="This rule calculates the central heating set point based on the outdoor temperature", tags=["Example"])
@when("Item SensorHygrometerOutdoor_Temperature received update")
def dev_boiler_heating_set_point_rule(event):

Is that clearer?