[SOLVED] Conflicting Set Reaction Groups Appear to Fire Simultaneously in Single Rule Evaluation

[3rdStng]

MSR: latest-23078-d592d400
--Docker image on unRAID
Hubitat: 2.3.5.121

I was having an issue this morning where MSR wasn't seeing any hub updates from my Hubitat. In looking at the logs I was seeing pages of "reactor.log size hit rotation limit, rotating" messages. I purged these logs and restarted MSR thinking the logs were the cause of being stuck or something. I also changed the default from 2 MB and 5 logs to 3 MB and 9 logs. Long story short, that wasn't the issue and my HE needed a reboot. I had just rebooted a couple of days ago, so I didn't think that was the problem.

Back on topic here. Everything seems to be communicating and MSR is seeing the updates now, however I feel that my logs filled up way too fast. Granted 3 MB isn't very large these days. Is it normal to take about 45 minutes to fill up nine 3 MB log files? Or does this seem excessive? I only changed the size and qty in my logging.yaml file.

[Crille]

What does the rest of the config look like in logging.yaml. Any level above 4?

[3rdStng]

My Rule and Engine levels are at 5. But I've never touched them personally. Maybe these are inherited from a build long ago? Should these be a 4?

---
logging:
  default:
    level: 4
    streams:
      - type: console
        level: 0
      - type: file
        name: "reactor.log"
        maxsize: 3  # megabytes max size
        keep: 9     # copies of old logs
        #
        # capture_console: if true, (most) console output will be captured to
        #                  this stream (if you have multiple streams, this
        #                  feature can only be used by ONE of them). If you
        #                  turn this on (true), set the "console" type stream
        #                  (above) log level to 0 to avoid duplicate logging
        #                  entries. The default is false, console not captured.
        #capture_console: true
  app:
    level: 4
  httpapi:
    level: 4
  httpproxy:
    level: 4
  wsapi:
    level: 4
  Structure:
    level: 4
  Controller:
    level: 4
  OWMWeatherController:
    level: 4
  VeraController:
    level: 4
  HubitatController:
    level: 4
  HassController:
    level: 4
  Rule:
    level: 5
  Engine:
    level: 5

[3rdStng]

Lowering these two down to a 4 do not appear to have any change on the speed of the log rotation

[Crille]

Did you restart Reactor after changing the levels?

[3rdStng]

@Crille Yes

[Crille]

OK, any hints in the log? Anything other than Rule:INFO? If not, do you have a lot of rules triggered by frequent entity updates? I've moved my most frequent entities triggering rules to global expressions resulting in true/false, and used the expression as trigger instead to lower log entries of rule evaluation every 5-10 seconds so my 5, 2MB kept logs, span from late morning to early evening. 9, 3MB in 45 minutes doesn't seem normal to me.
I have all my loglevels at 4.

Edit: "doesn't seem normal to me."
If the devices triggering the rules are extremely chatty, the amount of logging is of course "normal".

[3rdStng]

It does appear to mostly be related to rules that have to do with my Life360 presence sensors.

Correction to my log level comment above. Changing the rules and engine to 4 did slow things down a bit. I saved that changed and restarted my docker at 7:43 AM. I'm just shy of 2 hours now to fill/rotate all 9 logs.

[3rdStng]

If I am understanding your global expressions correctly. Are you saying you moved your rule triggers to an expression and then changed the trigger to be the value of the expression?

Original rule checking presence:

Now as a global expression:

With an updated trigger:

When Life360 updates, won't it force the expression to revalidate its value? Are these not logged?

[Crille]

Yes, that's how I do it. The expressions are evaluated every time the Life360 updates but if the result of the expression doesn't change, the rule will not trigger an evaluation. Evaluation of global expressions is not logged, at least not at level 4.

[3rdStng]

Thank you. I changed all my rules that had a presence sensor written in them. As well as a few other rules that have an app that phones home every minute. Just restarted MSR for good measure and can see a different. I'm over 30 minutes right now between .log and .log.1.

[toggledbits]

Note that you can also set the logging level for rules to level 3, and it would eliminate all of the log entries for when evaluations are being triggered and what is triggering them.

Another option is to set the log level for specific rules to a lower (quieter) value. You need to know the rule ID, which is displayed when you open the rule detail panel on the Rule Sets page (click the right-pointing arrow next to the rule name to open the panel; the ID is at the bottom of the panel).

  Rule:  # log level for all rules
    level: 4
  # Override default Rule log level for a specific rule
  "Rule#rule-la04ghp7":  # note quotes must be used here
    level: 3

[3rdStng]

@toggledbits Awesome. Thank you.

I know you know, but for others, the rule ID is also noted in the logs. Makes it easier to copy and paste without having to look up the ID within the GUI.