log not working consistently in UI rules

[rkoshak]

I have one rule with a script action:

var {log, items, things, metadata, osgi} = (log === undefined) ? require('openhab') : {log, items, things, metadata, osgi};
var runtime = require('@runtime');
var logger = log('Alarm');

var currToD = items.getItem("TimeOfDay").state;
if(currToD == "BED" || currToD == "NIGHT") {
  logger.info("The alarm went off and it's dark, transitioning to MORNING")
  items.getItem("TimeOfDay").sendCommand("MORNING");
}
else {
  logger.warn("The alarm went off but it's not BED or NIGHT")
}

Works like a champ. But one thing that is unique about this rule is that it's run from another rule or run manually.

2021-12-01 15:30:07.334 [WARN ] [script.js.alarm                     ] - The alarm went off but it's not BED or NIGHT           [Alarm at source <unknown>, line 53]

In this script action, however, the logger does nothing.

var my_logger = (my_logger === undefined) ? Java.type("org.slf4j.LoggerFactory").getLogger("org.openhab.model.script.rules_tools.All Away") : my_logger;
my_logger.info("Running all away");

var {log, items, things, metadata, osgi} = (log === undefined) ? require('openhab') : {log, items, things, metadata, osgi};
var runtime = require('@runtime');
var logger = log('Alarm');
logger.info("Loaded library");
my_logger.info("Loaded library but logging with own logger");
console.log("Test");

var name = items.getItem(event.itemName).label.split("'")[0]
my_logger.info("{} has changed state", name)
if(name == "Everyone" && event.itemState == runtime.ON) {
  name = "Someone"
}

var status = " is unknown: " + event.itemState;
if(event.itemState == runtime.ON) {
  status = " has arrived";
}
else if(event.itemState == runtime.OFF) {
  status = " is away";
}

my_logger.info(name + status);

I get the logs from my_logger but not logger (or console.log but I already know that's not yet implemented). This action is in a rule that is triggered from an Item event. It took me forever to understand that was why I wasn't seeing anything in the logs.

But log also isn't working from my scrathpad rule either.

[rkoshak]

Never mind, needed to add

    <Logger level="INFO" name="script.js">
      <AppenderRef ref="LOGFILE"/>
      <AppenderRef ref="OSGI"/>
    </Logger>

to log4j2.xml.

However, most users should not have to do this so I'd recommend that a namespace already logged out by OH (e.g. org.openhab.model.script ) be used instead of script.js) or have script added to the default log4j2.xml file. UI users will not know nor be happy if a stock OH install doesn't log properly.

I can't explain why my first rule worked. There must be a regex or something somewhere on "alarm".

[digitaldan]

Yeah, i have in the list of TODO's on openhab/openhab-addons#11656 to add something to openhab-core default xml log config like org.openhab.model.script with default level of DEBUG (since only user scripts should be using it)

[jpg0]

FYI I originally chose that shorter namespace for scripts because it seemed simpler and also allowed some level of disambiguation from logs coming from openHAB code, making it much easier to immediately see your logs rather than others. The assumption was that they would be script.<language>.<filename>. I have no problem with reverting back to the standard OH namespaces though.