Logging own log entries into different own log files

[anfaenger (rud)]

• Platform: Raspberry Pi 3 Model B Rev 1.2

  • openHABian configuration [master]v1.4.1-411(ecf59c4)
  • OS: Raspbian GNU/Linux 9 (stretch)
  • [08:15:23] openhabian@openHABianPi:~$ java -version
  • 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 2.3.0-1 (Release Build)

############################################################

I’m trying to setup logging into seperate files.

What worked so far:

1. When I set:

log4j2.logger.weatherunderground.level = DEBUG

then I get debug information in my own file weatherunderground.log as it should be.

2. I can create my own log entries in rules.

What does not work is to get my own log entries showing up in different log-files.
For example the sonos log entries should appear in Sonos.log and Rollladen log entries should appear in Rollladen.log.

My setup:

For testing I created different rule-files.

Every rule-file contains a similar rule that sends a log info when system is started.
For example the content of Sonos.rules looks like this:

rule "rSonos_SystemStarted"
    when   
            System started 
    then   
                logInfo("Sonos","***************** System started! Sonos-Logging activ.")
    end

or Rollladen.rules looks like this:

rule "rRollladen_SystemStarted"
    when   
            System started 
    then   
                logInfo("Rollladen","***************** System started! Rollladen-Logging activ.")
    end

As told before the problem is: When system starts, all log information is sent to the same log file instead of the log file it belongs to. All of my other own log files are empty!

Content of astro.log is:

22-Jul-2018 10:44:52.079 [INFO ] [org.eclipse.smarthome.model.script.Sonos          ] - ***************** System started! Sonos-Logging is activ.
22-Jul-2018 10:44:52.104 [INFO ] [org.eclipse.smarthome.model.script.Rollladen      ] - ***************** System started! Rollladen-Logging activ.
22-Jul-2018 10:44:52.090 [INFO ] [org.eclipse.smarthome.model.script.astro          ] - ***************** System started! Astro-Logging activ.
22-Jul-2018 10:44:52.135 [INFO ] [org.eclipse.smarthome.model.script.ZWave          ] - ***************** System started! ZWave-Logging activ.
22-Jul-2018 10:44:52.139 [INFO ] [.eclipse.smarthome.model.script.weatherunderground] - ***************** System started! Weatherunderground-Logging activ

I guess I made a mistake in the configuration file org.ops4j.pax.logging.cfg.
Probably (for example) log4j2.logger.Sonos.name = org.eclipse.smarthome.model.script is wrong, but I don’t know how to fix it and couldn’t find a solution: (@Dim: I read your post , that helped a little, so maybe you can help again.)

Here is what I have appended to org.ops4j.pax.logging.cfg:

### Custom Loggers ###

# MyLogger - astro.log
log4j2.logger.astro.name = org.eclipse.smarthome.model.script
log4j2.logger.astro.level = INFO
log4j2.logger.astro.additivity = false
log4j2.logger.astro.appenderRefs = astro
log4j2.logger.astro.appenderRef.astro.ref = astro

# MyLogger - Rollladen.log
log4j2.logger.Rollladen.name = org.eclipse.smarthome.model.script
log4j2.logger.Rollladen.level = INFO
log4j2.logger.Rollladen.additivity = false
log4j2.logger.Rollladen.appenderRefs = Rollladen
log4j2.logger.Rollladen.appenderRef.Rollladen.ref = Rollladen

# MyLogger - Sonos.log
log4j2.logger.Sonos.name = org.eclipse.smarthome.binding.sonos
log4j2.logger.Sonos.level = INFO
log4j2.logger.Sonos.additivity = false
log4j2.logger.Sonos.appenderRefs = Sonos
log4j2.logger.Sonos.appenderRef.Sonos.ref = SONOS

# MyLogger - weatherunderground
log4j2.logger.weatherunderground.name = org.eclipse.smarthome.binding.weatherunderground
log4j2.logger.weatherunderground.level = INFO
log4j2.logger.weatherunderground.additivity = false
log4j2.logger.weatherunderground.appenderRefs = weatherunderground
log4j2.logger.weatherunderground.appenderRef.weatherunderground.ref = WEATHERUNDERGROUND

# MyLogger - ZWave.log
log4j2.logger.ZWave.name = org.eclipse.smarthome.model.script
log4j2.logger.ZWave.level = INFO
log4j2.logger.ZWave.additivity = false
log4j2.logger.ZWave.appenderRefs = ZWave
log4j2.logger.ZWave.appenderRef.ZWave.ref = ZWave


### Custom Appenders ###

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

# My File appender - Rollladen.log
log4j2.appender.Rollladen.name = Rollladen
log4j2.appender.Rollladen.type = RollingRandomAccessFile
log4j2.appender.Rollladen.fileName = /var/log/openhab2/Rollladen.log
log4j2.appender.Rollladen.filePattern = /var/log/openhab2/Rollladen.log.%i
log4j2.appender.Rollladen.immediateFlush = true
log4j2.appender.Rollladen.append = true
log4j2.appender.Rollladen.layout.type = PatternLayout
log4j2.appender.Rollladen.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.Rollladen.policies.type = Policies
log4j2.appender.Rollladen.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.Rollladen.policies.size.size = 10MB
log4j2.appender.Rollladen.strategy.type = DefaultRolloverStrategy
log4j2.appender.Rollladen.strategy.max = 10

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

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

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

[Dim (Angelos)]

@anfaenger

Probably (for example) log4j2.logger.Sonos.name = org.eclipse.smarthome.model.script is wrong

Yup… it’s wrong
For each Custom Logger, you need to use a unique name

If you want to log your own logInfo stuff, then use:

log4j2.logger.Sonos.name = org.eclipse.smarthome.model.script.Sonos

If you want to log the output from a Binding, use it’s Symbolic name:

log4j2.logger.ZWave.name = org.openhab.binding.zwave
log4j2.logger.astro.name = org.eclipse.smarthome.binding.astro

you can find the Symbolic names using the console command: bundle:list -s

[anfaenger (rud)]

Great. It works! Thanks, you have helped me a lot.

There is one more point, I would like to achieve
When I choose

log4j2.logger.Sonos.name = org.eclipse.smarthome.model.script.Sonos,

it works for my own rules loginfo entries and when I choose

log4j2.logger.Sonos.name = org.eclipse.smarthome.binding.sonos,

it works for the binding log entries.

But not together. That means, with the following code, I only get log entries coming from the binding, but those coming from my rules are missing:

# MyLogger - Sonos (Rules)
log4j2.logger.Sonos.name = org.eclipse.smarthome.model.script.Sonos
log4j2.logger.Sonos.level = INFO
log4j2.logger.Sonos.additivity = false
log4j2.logger.Sonos.appenderRefs = Sonos
log4j2.logger.Sonos.appenderRef.Sonos.ref = SONOS

# MyLogger - Sonos (Binding)
log4j2.logger.Sonos.name = org.eclipse.smarthome.binding.sonos
log4j2.logger.Sonos.level = INFO
log4j2.logger.Sonos.additivity = false
log4j2.logger.Sonos.appenderRefs = Sonos
log4j2.logger.Sonos.appenderRef.Sonos.ref = SONOS

So my question is: Is it also possible to have this both running and logging into the same file named Sonos.log?
That would be perfect. Thanks again!

[Dim (Angelos)]

@anfaenger

Is it also possible to have this both running and logging into the same file named Sonos.log?

yes, with 2 loggers and 1 appender (it should work… I haven’t tested it)

edit: you need to use different aliases for them

log4j2.logger.Sonos_Rules.name = org.eclipse.smarthome.model.script.Sonos
...
log4j2.logger.Sonos_Binding.name = org.eclipse.smarthome.binding.sonos
...

[anfaenger (rud)]

Above I have two loggers, and the appender is

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

But that don’t work.
So I have probably a mistake, that I don’t see.
Can you see the mistake?

[Dim (Angelos)]

@anfaenger

Above I have two loggers

I edited my reply above.
You need to have 2 unique logger aliases which point (refer) to 1 appender
Your appender config looks good

[anfaenger (rud)]

Yes, been a litte to fast. I just saw your edit.
I will try this. Thanks

[anfaenger (rud)]

Ok, I got it!

For all interested in the entire code to get Binding and Rule logs into one log file:

# MyLogger - Sonos (Rules)
log4j2.logger.Sonos_Rules.name = org.eclipse.smarthome.model.script.Sonos
log4j2.logger.Sonos_Rules.level = INFO
log4j2.logger.Sonos_Rules.additivity = false
log4j2.logger.Sonos_Rules.appenderRefs = Sonos
log4j2.logger.Sonos_Rules.appenderRef.Sonos.ref = SONOS

# MyLogger - Sonos (Binding)
log4j2.logger.Sonos_Binding.name = org.eclipse.smarthome.binding.sonos
log4j2.logger.Sonos_Binding.level = INFO
log4j2.logger.Sonos_Binding.additivity = false
log4j2.logger.Sonos_Binding.appenderRefs = Sonos
log4j2.logger.Sonos_Binding.appenderRef.Sonos.ref = SONOS

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

Once again, thank you very much and have a nice evening!

Edit: Changed DEBUG into INFO.

[Dim (Angelos)]

@anfaenger

log4j2.logger.Sonos_Binding.level = DEBUG

careful… this will fill up your log file quite fast

glad you got your setup working

[csi_oh (Christian)]

Hi @anfaenger,

how would you write custom logs in that particular case?

logInfo("LoggerName", "LoggingText")?

Many thanks & BR,
Chris

[anfaenger (rud)]

Hi,
first copy the code from post 8 into your file org.ops4j.pax.logging.cfg.
Then replace every “Sonos” with “LoggerName”.

You don’t need the section “# MyLogger - Sonos (Binding)” when there is no binding called LoggerName
With this done, your logInfo("LoggerName", "LoggingText") should work.

Regards

[csi_oh (Christian)]

Hi there, works like a charm. TY!

BR,
Chris

[miroslav_sotiroff]

Hi there! I made own log file with your help. Thank you guys…
I made separate log file to collect errors of my devices which communicate with OpenHab2.
I would like to configure the layout of the log:

09-Dec-2019 14:45:21.631 [INFO ] [clipse.smarthome.model.script.AlarmsOfConntrollers] - testing...
09-Dec-2019 16:15:35.481 [INFO ] [clipse.smarthome.model.script.AlarmsOfConntrollers] - testing 1

Is it possible to remove this part from the log:

 [clipse.smarthome.model.script.AlarmsOfConntrollers]

My logging.cfg:

# MyLogger - AlarmsOfConntrollers (Rules)
log4j2.logger.Controler_Alarm_Colectror.name = org.eclipse.smarthome.model.script.AlarmsOfConntrollers
log4j2.logger.Controler_Alarm_Colectror.level = INFO
log4j2.logger.Controler_Alarm_Colectror.additivity = false
log4j2.logger.Controler_Alarm_Colectror.appenderRefs = AlarmsOfConntrollers
log4j2.logger.Controler_Alarm_Colectror.appenderRef.AlarmsOfConntrollers.ref = AlarmsOfConntrollers

# My File appender - AlarmsOfConntrollers.log
log4j2.appender.Controler_Alarm_Colectror.name = AlarmsOfConntrollers
log4j2.appender.Controler_Alarm_Colectror.type = RollingRandomAccessFile
log4j2.appender.Controler_Alarm_Colectror.fileName = /etc/openhab2/html/WebLog/AlarmsOfConntrollers.log
log4j2.appender.Controler_Alarm_Colectror.filePattern = /etc/openhab2/html/WebLog/AlarmsOfConntrollers.log.%i
log4j2.appender.Controler_Alarm_Colectror.immediateFlush = true
log4j2.appender.Controler_Alarm_Colectror.append = true
log4j2.appender.Controler_Alarm_Colectror.layout.type = PatternLayout
log4j2.appender.Controler_Alarm_Colectror.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n
log4j2.appender.Controler_Alarm_Colectror.policies.type = Policies
log4j2.appender.Controler_Alarm_Colectror.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.Controler_Alarm_Colectror.policies.size.size = 10MB
log4j2.appender.Controler_Alarm_Colectror.strategy.type = DefaultRolloverStrategy
log4j2.appender.Controler_Alarm_Colectror.strategy.max = 10

Thanks!

[t2610 (Tobias Beljanski)]

@miroslav_sotiroff

Is it possible to remove this part from the log:

 [clipse.smarthome.model.script.AlarmsOfConntrollers]

Hi,

you have to change your logging cfg file from

log4j2.appender.Controler_Alarm_Colectror.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n

to

log4j2.appender.Controler_Alarm_Colectror.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] - %m%n