dklinkman

dklinkman

@jkandasa Thanks for the cross-reference. Glad it isn't just me.

So far I only see this on the dashboard. I've had other pages open in a tab for days with no issue that I noticed. But my PC has 16GB ram too. So maybe just more headroom. I will try to observe other pages that update, like under Resources, and monitor memory. I will let you know if I see anything interesting.

If I can do any other specific diagnostics please let me know. Happy to do it.

Thanks for looking!!!! --D

dklinkman

This is a rule that evaluates a script, and when triggered tries to run operations for SMS(Twilio) and Pushbullet. The SMS and push work fine with other rules that have physical sensors. The SMS and push operations do not have any custom message. Just a title and when they work they use a default message. I enabled some debug logging and the result is below.

The script is pretty simple

var myImports = new JavaImporter(java.io, java.lang, java.util, java.text);

with (myImports) {
  var mcResult = true;
  var batteryLevel = mcApi.uidTag().getByUid("SensMicro1Node").resource.batteryLevel;
  if (batteryLevel > 80) {
    mcResult = false; // do not trigger (normally batteryLevel > just above is 30.  80 to 30 to 80 is used for troubleshooting)
  }
  // mcApi.logger().info("node-battery-check returned " + mcResult);
}

I can manipulate the condition by switching between 30 and 80 to make the rule return true or false for testing.

The problem I found was in the rule definition details logged at timestamp 11:38:35,130

Rule definition details:RuleDefinitionScript(super=RuleDefinitionAbstract(id=4, enabled=true, disabledByUser=false, disableWhenTrigger=false, reEnable=false, reEnableDelay=null, name=SensMicro1 Battery Check, resourceType=SCRIPT, resourceId=-1, conditionType=SCRIPT, timestamp=null, lastTrigger=1524065915130, ignoreDuplicate=true, triggered=true, dampeningType=NONE, dampening=DampeningAbstract(type=NONE), operationIds=[1, 2], operations=[OperationSendSMS(toPhoneNumbers=5551234567, customMessage=), OperationSendPushbulletNote(idens=1, channelTags=1, emails=xxxxxxxxx@xxxxxxxx.com, title=Test via Pushbullet, body=null)], actualValue=null, actualUnit=null), scriptFile=conditions/node-battery-check.js, scriptBindings={})

Here the actualValue and actualUnit and some others are null. In the code for Notification.java I see that actualUnit.length() is being called on the null value causing the null pointer exception. The exception is thrown from Notification.java:56

I guess I can report this as an issue but first I wanted to see if in fact there is something more that I need to add to my script or my rule to satisfy the rule details that are null in this scenario. Or in other words, how and with what do I set those details? And should I need to?

Thanks for looking!!! --D

The full debug log is below. I have obfuscated phone #s and emails

2018-04-18 11:38:35,056 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleListener:50] Before Evaluate, rule:rule
2018-04-18 11:38:35,127 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.scripts.McScriptEngine:95] McScript(engineName=null, mimeType=null, extension=js, name=/mnt/drive2/mycontroller/conf/resources/scripts/conditions/node-battery-check.js, canonicalPath=null, type=OPERATION, size=0, lastModified=0, bindings={}), \nResult: true
2018-04-18 11:38:35,129 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.scripts.McScriptEngine:96] Script bindings:[{myImports=[object JavaImporter], mcResult=true, batteryLevel=56}]\nMcScript(engineName=null, mimeType=null, extension=js, name=/mnt/drive2/mycontroller/conf/resources/scripts/conditions/node-battery-check.js, canonicalPath=null, type=OPERATION, size=0, lastModified=0, bindings={})
2018-04-18 11:38:35,130 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McConditionScript:77] Rule evaluate result:true
2018-04-18 11:38:35,130 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleAbstract:192] Dampening evaluate result:true
2018-04-18 11:38:35,130 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleAbstract:193] Rule definition details:RuleDefinitionScript(super=RuleDefinitionAbstract(id=4, enabled=true, disabledByUser=false, disableWhenTrigger=false, reEnable=false, reEnableDelay=null, name=SensMicro1 Battery Check, resourceType=SCRIPT, resourceId=-1, conditionType=SCRIPT, timestamp=null, lastTrigger=1524065915130, ignoreDuplicate=true, triggered=true, dampeningType=NONE, dampening=DampeningAbstract(type=NONE), operationIds=[1, 2], operations=[OperationSendSMS(toPhoneNumbers=5551234567, customMessage=), OperationSendPushbulletNote(idens=1, channelTags=1, emails=xxxxxxxxx@xxxxxxxx.com, title=Test via Pushbullet, body=null)], actualValue=null, actualUnit=null), scriptFile=conditions/node-battery-check.js, scriptBindings={})
2018-04-18 11:38:35,136 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleListener:56] After Evaluate, status:true, rule:rule
2018-04-18 11:38:35,137 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleListener:33] About to execute the rule:rule
2018-04-18 11:38:35,137 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleAbstract:203] Operations going to execute:[OperationSendSMS(toPhoneNumbers=5551234567, customMessage=), OperationSendPushbulletNote(idens=1, channelTags=1, emails=xxxxxxxxx@xxxxxxxx.com, title=Test via Pushbullet, body=null)]
2018-04-18 11:38:35,138 ERROR [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.operation.model.OperationSendSMS:104] Exception,
java.lang.NullPointerException: null
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:56)
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:69)
        at org.mycontroller.standalone.operation.model.OperationSendSMS.execute(OperationSendSMS.java:101)
        at org.mycontroller.standalone.rule.McRuleAbstract.execute(McRuleAbstract.java:206)
        at org.easyrules.core.DefaultRulesEngine.applyRules(DefaultRulesEngine.java:177)
        at org.easyrules.core.DefaultRulesEngine.fireRules(DefaultRulesEngine.java:124)
        at org.mycontroller.standalone.rule.McRuleEngine.execute(McRuleEngine.java:103)
        at org.mycontroller.standalone.rule.McRuleEngine.doRun(McRuleEngine.java:161)
        at org.knowm.sundial.Job.execute(Job.java:56)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:178)
        at org.quartz.core.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:515)
SLF4J: Failed toString() invocation on an object of type [org.mycontroller.standalone.scripts.McScript]
Reported exception:
java.lang.NullPointerException
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:56)
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:69)
        at java.lang.String.valueOf(String.java:2994)
        at java.lang.StringBuilder.append(StringBuilder.java:131)
        at java.util.AbstractMap.toString(AbstractMap.java:559)
        at java.lang.String.valueOf(String.java:2994)
        at java.lang.StringBuilder.append(StringBuilder.java:131)
        at org.mycontroller.standalone.scripts.McScript.toString(McScript.java:41)
        at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:299)
        at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:271)
        at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:233)
        at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:173)
        at ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(LoggingEvent.java:293)
        at ch.qos.logback.classic.spi.LoggingEvent.prepareForDeferredProcessing(LoggingEvent.java:206)
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:223)
        at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
        at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414)
        at ch.qos.logback.classic.Logger.debug(Logger.java:490)
        at org.mycontroller.standalone.scripts.McScriptEngine.executeScript(McScriptEngine.java:95)
        at org.mycontroller.standalone.operation.model.Operation.updateTemplate(Operation.java:102)
        at org.mycontroller.standalone.operation.model.OperationSendPushbulletNote.execute(OperationSendPushbulletNote.java:116)
        at org.mycontroller.standalone.rule.McRuleAbstract.execute(McRuleAbstract.java:206)
        at org.easyrules.core.DefaultRulesEngine.applyRules(DefaultRulesEngine.java:177)
        at org.easyrules.core.DefaultRulesEngine.fireRules(DefaultRulesEngine.java:124)
        at org.mycontroller.standalone.rule.McRuleEngine.execute(McRuleEngine.java:103)
        at org.mycontroller.standalone.rule.McRuleEngine.doRun(McRuleEngine.java:161)
        at org.knowm.sundial.Job.execute(Job.java:56)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:178)
        at org.quartz.core.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:515)
2018-04-18 11:38:35,154 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.scripts.McScriptEngine:95] [FAILED toString()], \nResult: Test via Pushbullet
SLF4J: Failed toString() invocation on an object of type [java.util.HashMap]
Reported exception:
java.lang.NullPointerException
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:56)
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:69)
        at java.lang.String.valueOf(String.java:2994)
        at java.lang.StringBuilder.append(StringBuilder.java:131)
        at java.util.AbstractMap.toString(AbstractMap.java:559)
        at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:299)
        at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:271)
        at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:233)
        at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:173)
        at ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(LoggingEvent.java:293)
        at ch.qos.logback.classic.spi.LoggingEvent.prepareForDeferredProcessing(LoggingEvent.java:206)
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:223)
        at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
        at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414)
        at ch.qos.logback.classic.Logger.debug(Logger.java:490)
        at org.mycontroller.standalone.scripts.McScriptEngine.executeScript(McScriptEngine.java:96)
        at org.mycontroller.standalone.operation.model.Operation.updateTemplate(Operation.java:102)
        at org.mycontroller.standalone.operation.model.OperationSendPushbulletNote.execute(OperationSendPushbulletNote.java:116)
        at org.mycontroller.standalone.rule.McRuleAbstract.execute(McRuleAbstract.java:206)
        at org.easyrules.core.DefaultRulesEngine.applyRules(DefaultRulesEngine.java:177)
        at org.easyrules.core.DefaultRulesEngine.fireRules(DefaultRulesEngine.java:124)
        at org.mycontroller.standalone.rule.McRuleEngine.execute(McRuleEngine.java:103)
        at org.mycontroller.standalone.rule.McRuleEngine.doRun(McRuleEngine.java:161)
        at org.knowm.sundial.Job.execute(Job.java:56)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:178)
        at org.quartz.core.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:515)
SLF4J: Failed toString() invocation on an object of type [org.mycontroller.standalone.scripts.McScript]
Reported exception:
java.lang.NullPointerException
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:56)
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:69)
        at java.lang.String.valueOf(String.java:2994)
        at java.lang.StringBuilder.append(StringBuilder.java:131)
        at java.util.AbstractMap.toString(AbstractMap.java:559)
        at java.lang.String.valueOf(String.java:2994)
        at java.lang.StringBuilder.append(StringBuilder.java:131)
        at org.mycontroller.standalone.scripts.McScript.toString(McScript.java:41)
        at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:299)
        at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:271)
        at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:233)
        at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:173)
        at ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(LoggingEvent.java:293)
        at ch.qos.logback.classic.spi.LoggingEvent.prepareForDeferredProcessing(LoggingEvent.java:206)
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:223)
        at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
        at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414)
        at ch.qos.logback.classic.Logger.debug(Logger.java:490)
        at org.mycontroller.standalone.scripts.McScriptEngine.executeScript(McScriptEngine.java:96)
        at org.mycontroller.standalone.operation.model.Operation.updateTemplate(Operation.java:102)
        at org.mycontroller.standalone.operation.model.OperationSendPushbulletNote.execute(OperationSendPushbulletNote.java:116)
        at org.mycontroller.standalone.rule.McRuleAbstract.execute(McRuleAbstract.java:206)
        at org.easyrules.core.DefaultRulesEngine.applyRules(DefaultRulesEngine.java:177)
        at org.easyrules.core.DefaultRulesEngine.fireRules(DefaultRulesEngine.java:124)
        at org.mycontroller.standalone.rule.McRuleEngine.execute(McRuleEngine.java:103)
        at org.mycontroller.standalone.rule.McRuleEngine.doRun(McRuleEngine.java:161)
        at org.knowm.sundial.Job.execute(Job.java:56)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:178)
        at org.quartz.core.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:515)
2018-04-18 11:38:35,162 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.scripts.McScriptEngine:96] Script bindings:[[FAILED toString()]]\n[FAILED toString()]
2018-04-18 11:38:35,175 ERROR [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.operation.model.OperationSendPushbulletNote:120] Exception,
java.lang.NullPointerException: null
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:56)
        at org.mycontroller.standalone.operation.Notification.toString(Notification.java:69)
        at org.mycontroller.standalone.operation.model.OperationSendPushbulletNote.execute(OperationSendPushbulletNote.java:117)
        at org.mycontroller.standalone.rule.McRuleAbstract.execute(McRuleAbstract.java:206)
        at org.easyrules.core.DefaultRulesEngine.applyRules(DefaultRulesEngine.java:177)
        at org.easyrules.core.DefaultRulesEngine.fireRules(DefaultRulesEngine.java:124)
        at org.mycontroller.standalone.rule.McRuleEngine.execute(McRuleEngine.java:103)
        at org.mycontroller.standalone.rule.McRuleEngine.doRun(McRuleEngine.java:161)
        at org.knowm.sundial.Job.execute(Job.java:56)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:178)
        at org.quartz.core.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:515)
2018-04-18 11:38:35,179 DEBUG [Quartz_Scheduler_Worker-10] [org.mycontroller.standalone.rule.McRuleListener:44] Rule executed successfully:rule

dklinkman

@jkandasa Thanks for the cross-reference. Glad it isn't just me.

So far I only see this on the dashboard. I've had other pages open in a tab for days with no issue that I noticed. But my PC has 16GB ram too. So maybe just more headroom. I will try to observe other pages that update, like under Resources, and monitor memory. I will let you know if I see anything interesting.

If I can do any other specific diagnostics please let me know. Happy to do it.

Thanks for looking!!!! --D

dklinkman

I mostly use Chrome. My dashboard is the default with a few widgets added. A few sensor values, and temp and humidity graphs. After a while (or even in just 5 minutes sometimes) the page blows up with an "oh snap" error. I was able to capture a memory profile over one minute on the page, and saved it to a file. I don't know how to use it but maybe it will be helpful. My impression is that there's a memory leak. But I don't know how to tell if it's Chrome, the page, or something else.

The memory profile is over 200MB so can't upload it here. But if you think it would help you can get it from this shared link memory profile snapshot

Chrome: Version 65.0.3325.181 (Official Build) (64-bit)
MyController: mycontroller-dist-standalone-1.3.0-SNAPSHOT-single.jar
MyController running on Ubuntu 14.04LTS (I think)
Java: VM version 1.8.0_161-b12
Chrome runs on Windows 7 Professional 64bit

Very repeatable. Just need to keep the dashboard open. Same thing happens when I keep the page open on my work computer.

Thanks!!!!! --D

dklinkman

@jkandasa Thank you for that. Works better. No more NPE. Pushbullet and Twilio are now complaining though. A Pushbullet message did get through, but not Twilio. I'll have to dig into those API errors and see if I can figure out what they are not happy about. I don't know if it's a general problem or something related to my script.

Separate random question. Is there a forum post or blog where you talk about the changes and additions from version 2.0 to 3.0? Since I am now running a 3.0 development snapshot

Thanks!!! --D

dklinkman

I was looking at the api for the rule and some other objects to try and figure out how I could set those null values from my script. But I couldn't figure it out. What I did instead was create a virtual sensor on the node to hold the battery percentage. So now I just use the sensor normally. Works great. I could also go into the node code and add the battery sensor definition and update logic there.

I think your easy fix is the way to go. But maybe just default each of null values to an empty string instead of arbitrary default message. The generic message will still be generic, can be overridden with a custom message, and best of all doesn't throw exceptions and now SMS and push from any script will work.

If you have an idea of how I can use the script api to create or set one of those values I'd love a hint. I don't need a full solution, just a nudge in the right direction.

Thanks!! --D

dklinkman