openHAB - Filtering event logs

Pipe the output to grep…

Is that what you’re looking for?

yea but i was hoping for a permanent solution… i tried pretty much all of the log4j2 settings but nada… there must be a way though since we can exclude specific bindings and levels…

Paste an example of what you are seeing in the log that you’d like to filer out.

I want to filter anything with amazonechocontrol:smartHomeDevice or other regex compatible lines from log:tail ( i have no issue with log files filtering but that is not what i specifically want )

amazonechocontrol:smartHomeDevice:0a4c3487:517c0f67-cdd7-45c7-8dac-3cdcd8114a1b’

and tried this in the org.ops4j.pax.logging.cfg but no effect in karaf ssh…

    log4j2.appender.console.filter.1.type = Filters
    log4j2.appender.console.filter.1.a.type = RegexFilter
    log4j2.appender.console.filter.1.a.regex = .*amazonechocontrol.*
    log4j2.appender.console.filter.1.a.onMatch = DENY
    log4j2.appender.console.filter.1.a.onMismatch = ACCEPT

I quick question.

Is it possible to check out events that have already been filtered? I had a Item filtered and I would like to check out when changed the status yesterday and I do not know if it is stored in another file into the system.

Thanks.

When you filter the logs like this, that log statement is lost. That’s why I’m very much against filtering logs like this except in extreme circumstances. The whole purpose of logs is to preserve information like this so you can go back and see information like this. It’s better to let the log statements be written and use tools available to you to filter the logs based on what’s important to you at that time. Everything continues to be written but you can narrow down what you are looking at to just those lines that are relevant to what you are working on. And then, when something happens and you have to go back and do a forensic analysis, all the logs are there.

You cannot know ahead of time what logs will be relevant so let everything log as normal and search/filter the logs as needed.

2 Likes

yes, you are right.

I will try to minimize the filter.
Thanks.

@rlkoshak just chucked a link to your thread into the main post. When i wrote this up the intent was to keep stuff I didn’t want ‘out’ of the log, but I can see some users won’t always know the difference between filtering something to prevent it being logged, and filtering a log view to only show what they want. Thx.

2 Likes

I originally implemented log filtering both to reduce what I see in my log (understanding fully what it was doing) and to reduce writes to my SD card. I recently enabled ZRAM, which takes care of the latter goal. That didn’t occur to me until reading this just now.

If of any help, this is how I implemented a filter on events per item “categories”. Purpose was to make it easier to track particular events while debugging my scripts. Of course, following rules should be disabled once debugging is over as the rule trigger on all monitored items which adds useless processing.

  1. I created Group items for each category to monitor and attached the corresponding items to these groups. For example, to monitor items related to alarm system, I created a group named SEC_Alarm and assign to items in the definition in the .items file
    Group SEC_AlarmMode Number SEC_System_AlarmMode_G1 "Garage côté rue" <_garagerue> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_G2 "Garage de l'impasse" <_garageimpasse> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_Cave "Cave" <_cave> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_HomeAxs "Accès maison" <_access> (SEC_AlarmMode) {autoupdate = "false" } Number SEC_System_AlarmMode_HomeMvt "Mouvements maison" <_motion> (SEC_AlarmMode) {autoupdate = "false" }

  2. I created a Number item that holds the expected level of monitoring: 0=no monitoring, 1=monitor changes, 2=monitor commands, 3 (1+2)=monitor both changes and commands
    Number SYS_LogGroup_SEC_AlarmMode "SEC_AlarmMode" (SYS_LogGroup)
    This item is exposes in the sitemap and allows changing the log level from the UI

  3. I wrote rules to monitor the expected event (indeed I have 2 rules : one monitors change events and the other monitors command events):

import java.util.HashMap
val HashMap<String, String> itemChanges = newHashMap()
var found = false

rule "Log item change"
when
    Member of SEC_AlarmMode changed
then
    try{
        found = false
        SYS_LogGroup.members.forEach[GenericItem curLogGroup | 
            if(found == false){
                if(curLogGroup.state != NULL){
                    if(Integer.parseInt(curLogGroup.state.toString).bitwiseAnd(1) != 0){
                        val String logGroupName = curLogGroup.name.replace("SYS_LogGroup_", "")
                        if(triggeringItem.getGroupNames.contains(logGroupName)){
                            found = true
                            if(triggeringItem.state == NULL){
                                if(itemChanges.get(triggeringItem.name) != ""){
                                    logInfo("rules.sys." +  triggeringItem.name, "[" + logGroupName + "] " + triggeringItem.name + " changed from " + itemChanges.get(triggeringItem.name) + " to NULL")
                                    itemChanges.put(triggeringItem.name,"")
                                }
                            }
                            else{
                                if(itemChanges.get(triggeringItem.name) != triggeringItem.state.toString){
                                    logInfo("rules.sys.ItemChange", "[" + logGroupName + "] " + triggeringItem.name + " changed from " + itemChanges.get(triggeringItem.name) + " to " + triggeringItem.state.toString)
                                }
                                itemChanges.put(triggeringItem.name,triggeringItem.state.toString)
                            }
                        }
                    }
                }
            }
        ]
    }
    catch(Exception e){
        logWarn("rules.sys.ItemChange", triggeringItem.name + "=" + triggeringItem.state.toString)
    }
end`
  1. mute the “standard” event logging with :
    log:set ERROR smarthome.event.ItemStateChangedEvent

I am a bit ashamed to propose such an ugly workaround but at least it works. And I am afraid that the headless development of OH will let more of these awful tricks to develop as I have not seen one single improvement since OH 1.8 to improve script development despite the ever-changing XTend / JAVA / smarthome environment which forces us to review/readapt our code at every OH “upgrade” with no functional improvement for an end user like me.

OH is definitely a powerful modular tool but is not aimed at audience like me who would prefer concentrating on automation logic rather than Java and all that clumsy stuff.

So the ability to create Rules using the UI, the ability create Rules using Python, JavaScript, and Groovy, Node Red integration, HABApp, etc. are not improvements? The addition of Member of (which you are using here), triggeringItem, Item metadata, etc. were not improvements?

If you don’t want to write code, perhaps Node Red would be more appropriate for you. Or perhaps not upgrading would be a more appropriate choice. You can’t have improvements or new features or bug fixes with perfect backwards compatibility. IMO, the usability and capability of writing Rules in OH is hugely improved since 1.8.

It’s really hard to tell what this code does because of the lack of How to use code fences but this appears to just duplicate what events.log logs out. Maybe I don’t get it but it seems like a really complicated way to do:

grep 'MyItemName1\|MyItemName2` /var/log/openhab2/events.log

Which returns just those lines that reference MyItemName1 and MyItemName2. All this information already gets logged out by default and there are lots of tools available (there are powershell equivalents if you are on Windows) to only look at those lines that you care about at any given time.

There must be something I don’t understand here. I wouldn’t say it’s ugly but it is really not clear to me what this code does. It seems like it’s doing checks for things that are impossible. For example, the code keeps track of changes to the Item in a HashMap and then checks that HashMap later to see if the Item changed. But the Rule is triggered by a change. You would never have the case where the Rule triggered and the Item didn’t change state.

It looks like you are looping through all the members until you find a specific Item. Why not use filter? What’s the deal with the bitwiseAnd?

Maybe something like:

when
  Member of SEC_AlarmMode changed // Member of is new since OH 1.8
then
    val name = triggeringItem.name // triggeringItem is an implicit variable added since OH 1.8

    // filter to get all the members whos bitwaiseAnd(1) is not 0 and loop
    SYS_LogGroup.members.filter[ curLogGroup | (curLogGroup.state as Number).intValue.bitwiseAnd(1) != 0 ].forEach[ curLogGroup |
        val logGroupName = curLogGroup.name.replace("SYS_LogGroup_", "")

        // log if the triggeringItem is a member of curLogGroup, use the previousState implicit
        // variable instead of keeping track of them in a hashmap
        if(triggeringItem.groupNames.contains(logGroupName)){
            logInfo("rules.sys." + name, "[" + logGroupName + "] " + name + " changed from " + previousState + " to " + triggeringItem.state) // previousState I think was around even in OH 1.8
        }
    ]
end

It might make more sense if it’s broken into multiple lines:

when
  Member of SEC_AlarmMode changed // Member of is new since OH 1.8
then
    val name = triggeringItem.name // triggeringItem is an implicit variable added since OH 1.8

    val activeLogGroups = SYS_LogGroup.members.filter[ curLogGroup | 
        (curLogGroup.state as Number).intValue.bitwiseAnd(1) != 0 
    ]

    activeLogGroups.forEach[ curLogGroup |
        val logGroupName = curLogGroup.name.replace("SYS_LogGroup_", "")

        // log if the triggeringItem is a member of curLogGroup, use the previousState implicit
        // variable instead of keeping track of them in a hashmap
        if(triggeringItem.groupNames.contains(logGroupName)){
            logInfo("rules.sys." + name, "[" + logGroupName + "] " + name + " changed from " + previousState + " to " + triggeringItem.state) // previousState I think was around even in OH 1.8
        }
    ]
end

I’m still not certain I get exactly what this does but I think the above code will do the same as your original code.

It might also be reasonable to go about it from the other direction.

    val name = triggeringItem.name
    
    // filter down to just those Groups that triggeringItem is a member of that 
    val activeLogGroups = triggeringItem.groupNames.filter[ grp | 
        SYS_LogGroup.members.findFirst[ logGrp |
            (logGrp.state as Number).intValue.bitwiseAnd(1) != 0
        ]
    ]

    activeLogGroups.forEach[ curLogGroup |
        val logGroupName = curLogGroup.name.replace("SYS_LogGroup_", "")
        logInfo("rules.sys." + name, "[" + logGroupName + "] " + name + " changed from " + previousState + " to " + triggeringItem.state) 
    ]

I’m not 100% I got either of these exactly correct but they should show some ways to make the code more concise.

My point is to be challenging: I strongly believe OH is by far the most robust and versatile home automation framework. Otherwise, I would have given up :slight_smile:
For sure, these are valuable technical improvements from a conceptual standpoint. I am just pointing out that, as a developer focused on the automation logic, I miss efficiency and usability of rules environment. Sometimes it takes me hours to write one single line of code just because (1) the package DSL + XTend + Java is touchy about the syntax, (2) because the VSCode IDE is sometimes not reporting errors properly and (3) because it take very long before a modified .rules file is loaded and ready for testing in OH. This is irritating but does not depreciates core strengths of OH (if I list them all, my post will be far longer).

I want to write code with an efficient debugging/IDE. My previous home automation what built on Python. I rewrote it all in DSL-style when migrating to OH… My current DSL config is around 4600 lines of code! And Python came in to OH afterwards :frowning: :slight_smile:
The syntaxic “mix” between Java / XTend was so painful that I fear to experience the same if migrating back to Python again…

Yes, grep is fine for few items but becomes unhandy when many items are involved. I am also using a 3rd party log viewer but filtering “on the fly” is more convenient to me. My intend is not replace the standard logger that is alreay configurable using org.ops4j.pax.logging. But it provides a configurable “on the fly” filtering method that can be useful and shoudl remain temporary while debugging (at least that is useful to me).

I initially used a filter, but for some reason, this raised errors time to time which remains a mystery to me, so that “ugly” multilined code.

The bitWiseAnd determines which event (change, update, command) should be logged based on the value of the “Filter items” in the sitemap belows.: I run similar rules to log commands and updates.
The hashmap was a workaround to catch a strange behaviour where the logging rule was triggered repeateadly, especially for updates(don’t ask me why: I gave up searching). But I agree that this hashmap should be useless.

So use Scripted Automation which which addresses almost all of these errors. That’s why in OH 3 Scripted Automation is likely to become the default instead of Rules DSL. All the things you complain about Rules DSL is simply not going to ever get any better.

Python has been an option, though admittedly a somewhat fringe option until about OH 2.3, since at least OH 1.7.

Hmmm, depending on the error it might be because the members are changing state while the filter is taking place. Though the same problem usually kills a forEach so without seeing the error itself I can only speculate.

How old is this Rule? Was it written before Member of triggers? That behavior would make sense if that were the case. If you’ve seen this error with the Member of triggers, have you filed an issue?

The next-gen scripting engine is promising for basic automation through programming bricks.
It would be great if these bricks could be mixed with lower-level programming language such as Python or Java so anyone has the choice to combine ready-to-use the “high level bricks” and to design “low level programming routine”

Eventghost and Tasker are nice examples of scripting tools

Both tools combine high level bricks using events/triggers logic + level coding (with Java scripting for Tasker or Python scripting in Eventghost)
Let’s not misunderstand : I am not trying to compare Eventghost or Tasker with OH. Tasker is limited to Windows platform, has no UI capability, little interoperability and very limited device support. Tasker is limited to Android with a singular lack of logic in implementation and terrific designer IDE.

Without low-coding capability, I will have to merge to Python (it will be hard work but I love structuraton of Python language )

Back to my rule, I rolled back to my misleading rule and this is the error I could not fix. For the hashmap, the intend was to return the previous state / command to build the logInfo() line

rule "Log item change filter"

when
    Member of SYS_Settings changed
    or Member of AX received update
    or Member of USR received update
    or Member of ECL received update
    or...
then
    SYS_LogGroup.members.filter[ GenericItem curLogGroup | 
        if(curLogGroup.state==NULL)false} else{Integer.parseInt(curLogGroup.state.toString).bitwiseAnd(1) != 0}
    ].forEach[ GenericItem curLogGroup | 
            val String logGroupName = curLogGroup.name.replace("SYS_LogGroup_", "")
            if(triggeringItem.getGroupNames.contains(logGroupName)){
                logInfo("rules.log.ItemChange", "" + logGroupName + "] " + triggeringItem.name + " changed from " + itemChanges.get(triggeringItem.name) + " to " + triggeringItem.state.toString)
                itemChanges.put(triggeringItem.name,triggeringItem.state.toString)
            }
    ]
end

And this is enigmatic error which occured (no stack to trace anything). And because I am not a Java/XTend specialist, I gave up and returned to my ugly-but-working code.

2020-05-07 22:50:50.336 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'log.rules'
2020-05-07 22:52:01.943 [INFO ] [me.model.script.rules.log.ItemChange] - [ECL] ECL_mRDC_Salon_lampe changed from null to ON
2020-05-07 22:52:01.965 [INFO ] [me.model.script.rules.log.ItemChange] - [ECL_Proxy] PROXY_ECL_mRDC_Salon_lampe changed from null to ON
2020-05-07 22:52:16.203 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Log item change filter': null
2020-05-07 22:52:16.208 [INFO ] [me.model.script.rules.log.ItemChange] - [ECL] ECL_mRDC_Salon_lampe changed from ON to OFF

By programming bricks, do you mean like libraries where, for example, there are PRs for a number of the design pattern concepts, other integrations, and all sorts of community developed libraries to use?

Or do you mean more like importing and configuring a ready made Rule from a template so you don’t have to look at the code at all?

And of course, in either case you have access to create your own Scripts using the supported language of choice.

As for the error…
Is the same Item a member of more than one of the Groups that triggers the Rule? Is it likely that this Rule will be triggered multiple times at the same time?

Yes: this is exactly what I expect: embed my own script written with a language that gives access to more programming features such as hashmap, lists, loops, global variables, and functions.
So anyone can choose or mix any of the 3 levels : (1) use the ready-to-use rules templates, (2) build the rules from the logical bricks and things/items exposed to the rule engine, (3) design his own bricks with a standard language (Python or Java, anything but standard) and get native interoperability between the 3 levels of design. I suspect that this is what is coming and I can’t wait but in the meanwhile, I try to maintain my modular layers in the DSL-style

No, the rule should only be triggered once per item because each one belongs to one single functional category (group ECL=lighting device and group PROXY_ECL=lighting command layer). They belong to other groups mRDC_Salon (living-room=location group) and ECL_Salon (living-room lighting group to allow driving groups of lights = scenes ). They are not monitored by this rule.

Switch  ECL_mRDC_Salon_lampe            "Lampe du salon"       <light> (mRDC_Salon, ECL_Salon, ECL)                    { channel="zwave:device:142f34cb:node36:switch_binary" }
Switch  PROXY_ECL_mRDC_Salon_lampe      "Lampe du salon"       <light> (mRDC_Salon, ECL_Proxy)                     {autoupdate="false"}

Ultimately, I think the root cause is the fact that Rules DSL Rules are not thread safe (a problem that doesn’t exist in Scripted Automation) so my recommendation for the fix would be to rewrite the Rule in Scripted Automation, probably Python at this point.

When/if you do, you might consider using Item Metadata instead of Groups which might give you a bit more control over how the Rule triggers which in turn will simplify the code itself. See JSR223 Jython Replacement for Expire Binding for an example of doing just that to replace the Expire binding using Rules.

I am not a thread or coding specialist but I suspected there was something about this.
I already delt with several “processes” that would have required a real-threaded approach (IR queue, notification queue) that I addressed with a dirty queue.lock()/unlock. But I understand that thread-safe implementation my requires more resources which would prevent OH to run on lightweighted systems.

For sure, I will have to migrate again one day. Already looked to JSR few years ago but the install seemed so complicated on a Windows platform that I gave up. Switching to another OS is much time to spend when you are not used to it and I still have one critical sub-system (wired door/gate opener) fully coded in Python/Eventghost, bound using MQTT to OH, which forces me to maintain a MS Windows machine.
It is always frustrating to rework existing code when you are not a profesional/fast coder and when you have so many “new” features coming everyday in your home automation todo list !

There is an open report on openHAB core

So far as I can see, there is some issue in the bowels of openHAB (probably about multi threading, yes) where iterating the members of a Group in a DSL rule while the Group is also being updated by “someone else” sometimes returns null.

That’s good fit for your rule - it triggers from member update and chunters along, iterating a Group. Meantime that update will also be causing Group(s) to update/review their own status in parallel, because of member update.

I have doubts this would be circumvented by NGRE unless it is using some completely different mechanism to examine Groups? Certainly throw different symptoms, sure.

1 Like

See Design Pattern: Gate Keeper which shows a better way to handle that.

Even on Windows now it’s just an add-on. See [beta testers wanted!] Jython addon w/ helper libraries (requires OH 2.5.x). It’s not merged so you have to install it manually (i.e. drop 1 jar file into the addons folder) and that’s it. It’s pretty simple now to get started.