Reported events from device being ignored/ not logged by ST API / not being logged?

I have a custom edge driver controlling an energy monitor, which allows for configurable report intervals. Its worked well for many moons now. Recently I wanted more frequent reports, but found when I reduced the interval they are not getting captured by ST correctly. I previously had a ~10-min interval that worked, and tried changing to 2-minutes… but the ST API logs seem to ignore “more frequent” report events with that change.

I’ve used logcat to capture real-time logs from the hub, and the actual reporting interval from the device seems to work as I expect – down to a few seconds. But the ST API (or rather, the values reported by the app and the events list I see in the web brower API) ignores most of them.

Below is a log from a capture showing an event (2024-06-05T21:44:00.621469471Z) that was captured (i.e. value shown in ST) and an event (2024-06-05T21:42:00.681504290Z) from 2 minutes prior that was ignored. The logs show similar handling for both, and I don’t see any error messages in the log.

Is there some restriction on event frequency on the ST side I’m missing? I’m a relative novice so not sure how to further debug the issue.

2024-06-05T21:42:00.681504290Z INFO Z-Wave Electric Meter GenX [GRH] v4  <ZwaveDevice: x-1e0b-44e0-86c5-4d77f7602e01 [82] (Net (-MR) Energy Meter)> received Z-Wave command: {args={delta_time=0, meter_type="ELECTRIC_METER", meter_value=-5109.056, precision=3, previous_meter_value=0.0, rate_type="IMPORT", scale="WATTS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="NONE", payload="\x21\x74\xFF\xB2\x0A\xC0\x00\x00\x00\x00\x00\x00", src_channel=0, version=3}
2024-06-05T21:42:00.684548790Z TRACE Z-Wave Electric Meter GenX [GRH] v4  Found ZwaveDispatcher handler in zwave_electric_meter
2024-06-05T21:42:00.687204415Z INFO Z-Wave Electric Meter GenX [GRH] v4  <ZwaveDevice: x-1e0b-44e0-86c5-4d77f7602e01 [82] (Net (-MR) Energy Meter)> emitting event: {"attribute_id":"power","capability_id":"powerMeter","component_id":"main","state":{"unit":"W","value":-5109.056}}
2024-06-05T21:42:00.693019957Z TRACE Z-Wave Electric Meter GenX [GRH] v4  Found ZwaveDispatcher handler in zwave_electric_meter
2024-06-05T21:42:00.696399707Z DEBUG Z-Wave Electric Meter GenX [GRH] v4  Net (-MR) Energy Meter device thread event handled
2024-06-05T21:42:00.763454957Z TRACE Z-Wave Electric Meter GenX [GRH] v4  Received event with handler unnamed

[snip...]

2024-06-05T21:44:00.621469471Z TRACE Z-Wave Electric Meter GenX [GRH] v4  Received event with handler unnamed
2024-06-05T21:44:00.648372763Z INFO Z-Wave Electric Meter GenX [GRH] v4  <ZwaveDevice:x-1e0b-44e0-86c5-4d77f7602e01 [82] (Net (-MR) Energy Meter)> received Z-Wave command: {args={delta_time=0, meter_type="ELECTRIC_METER", meter_value=-5087.217, precision=3, previous_meter_value=0.0, rate_type="IMPORT", scale="WATTS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="NONE", payload="\x21\x74\xFF\xB2\x60\x0F\x00\x00\x00\x00\x00\x00", src_channel=0, version=3}
2024-06-05T21:44:00.651743555Z TRACE Z-Wave Electric Meter GenX [GRH] v4  Found ZwaveDispatcher handler in zwave_electric_meter
2024-06-05T21:44:00.654488846Z INFO Z-Wave Electric Meter GenX [GRH] v4  <ZwaveDevice: x-1e0b-44e0-86c5-4d77f7602e01 [82] (Net (-MR) Energy Meter)> emitting event: {"attribute_id":"power","capability_id":"powerMeter","component_id":"main","state":{"unit":"W","value":-5087.217}}
2024-06-05T21:44:00.661332263Z TRACE Z-Wave Electric Meter GenX [GRH] v4  Found ZwaveDispatcher handler in zwave_electric_meter
2024-06-05T21:44:00.680521138Z DEBUG Z-Wave Electric Meter GenX [GRH] v4  Net (-MR) Energy Meter device thread event handled

Hi, @georgeh
I asked the engineering team about your case. I’ll keep you posted.

2 Likes

Ran across this today that may explain it:

About all you’ll see is:

The trouble is that document does have apparent differences from numbers published elsewhere in more frequently updated documents (e.g. in the number of Locations a User fan be associated with) and it is hard to know whether to take it at face value. Not that it is very clear to start with.

An event every two minutes seems to meet the guidelines to me. One every ten or twenty seconds clearly wouldn’t unless someone was manually twiddling that fast.

For some time now smartthings have introduced a filter of events from the hub, driver, to the platform events.

Affects temperature, power and energy information, which I have checked, there may be more

It does not affect the trigger of the routines, I have checked it because at first I had doubts.
This could say that there is another endpoint in the API where all events should be stored.

The worst thing is that the routines are triggered and you cannot see the event that triggered it, because it is filtered and it is impossible to debug these routines, a shame!!

The only way to see all the events is in the CLI, you can see how they are issued and those that do not meet the filter are lost.

For temperature events you can see the real events in the app’s graph and the filtered ones in the history. It seems like a waste of information to me, which is not useful for much or to confuse.

Hi, @georgeh!

Following up, I asked the engineering team about this and they asked if you’re sending the flag state_change=true for those events (as shown in this example) because if the measured value hasn’t changed, it is not considered a state update so it can be filtered out.

If you’re sending that flag, but still see this behavior, please send the Hub and driver logs for the team to take a closer look. The Hub logs are sent as follows:

  1. In the Advanced Users app, enter the “Hubs” section
  2. Enter the corresponding Hub and click on “Dump Hub logs”
  3. Confirm the process by clicking on “Dump Hub logs” again in the pop-up.
  4. You’ll get a green box at the top confirming the Hub logs were requested.
1 Like

I believe the value had changed, but I don’t know if the state_change flag is sent or not.

Based on Mariano’s reply, is there reason to check on the state_change flag as a solution, or is the filter going to impact the result anyway?

Hi @nayelyz

I believe that for certain capabilities, power, energy, temperature,… a change in the value is not always considered state_change = true.

I have an aeotec gen5 device configured to send the values ​​every 1 minute and it is like a clock and yet the events are filtered by time and/or change of an amount in the value that I do not know.

W values ​​trigger routines and it is impossible to debug them when you have doubts or want to fine-tune the operation of the routine.

The A and V values ​​are also sent every minute and these are not filtered, but don’t say anything that they will be filtered tomorrow. :wink:

Ah, but you mean in the app, right? If you check the history with the CLI command smartthings devices:history deviceId, do they all appear?
If so, that “filter” might be happening only in the app.

Are the same in App, CLI History and advanced users “events”

────────────────────────────────────────────────────────────────────────────
 Time               Component  Capability          Attribute  Value
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:48:27  main       currentMeasurement  current    "-1.787" A
 2024-6-6 21:48:27  main       voltageMeasurement  voltage    "230.192" V
 2024-6-6 21:47:28  main       currentMeasurement  current    "-1.813" A
 2024-6-6 21:47:27  main       voltageMeasurement  voltage    "226.668" V
 2024-6-6 21:46:29  main       energyMeter         energy     "107.307" kWh
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:46:28  main       powerMeter          power      "-353.341" W
 2024-6-6 21:46:27  main       currentMeasurement  current    "-1.779" A
 2024-6-6 21:46:27  main       voltageMeasurement  voltage    "226.295" V
 2024-6-6 21:45:27  main       currentMeasurement  current    "-1.848" A
 2024-6-6 21:45:26  main       voltageMeasurement  voltage    "224.867" V
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:44:27  main       currentMeasurement  current    "-1.835" A
 2024-6-6 21:44:26  main       voltageMeasurement  voltage    "224.017" V
 2024-6-6 21:43:27  main       currentMeasurement  current    "-1.833" A
 2024-6-6 21:43:26  main       voltageMeasurement  voltage    "222.653" V
 2024-6-6 21:42:27  main       currentMeasurement  current    "-1.843" A
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:42:26  main       voltageMeasurement  voltage    "223.754" V
 2024-6-6 21:41:27  main       currentMeasurement  current    "-1.837" A
 2024-6-6 21:41:26  main       voltageMeasurement  voltage    "224.06" V
 2024-6-6 21:40:27  main       currentMeasurement  current    "-1.85" A
 2024-6-6 21:40:26  main       voltageMeasurement  voltage    "225.601" V
────────────────────────────────────────────────────────────────────────────
? Fetch more history records ([y]/n)? y
────────────────────────────────────────────────────────────────────────────
 Time               Component  Capability          Attribute  Value
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:39:27  main       currentMeasurement  current    "-1.867" A
 2024-6-6 21:39:26  main       voltageMeasurement  voltage    "225.449" V
 2024-6-6 21:38:27  main       currentMeasurement  current    "-1.652" A
 2024-6-6 21:38:27  main       voltageMeasurement  voltage    "226.343" V
 2024-6-6 21:37:27  main       currentMeasurement  current    "-1.64" A
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:37:26  main       voltageMeasurement  voltage    "225.138" V
 2024-6-6 21:36:27  main       currentMeasurement  current    "-1.595" A
 2024-6-6 21:36:26  main       voltageMeasurement  voltage    "223.684" V
 2024-6-6 21:35:27  main       currentMeasurement  current    "-1.652" A
 2024-6-6 21:35:26  main       voltageMeasurement  voltage    "222.082" V
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:34:27  main       currentMeasurement  current    "-1.376" A
 2024-6-6 21:34:26  main       voltageMeasurement  voltage    "223.443" V
 2024-6-6 21:33:27  main       currentMeasurement  current    "-1.367" A
 2024-6-6 21:33:27  main       voltageMeasurement  voltage    "223.74" V
 2024-6-6 21:32:29  main       energyMeter         energy     "107.382" kWh
────────────────────────────────────────────────────────────────────────────
 2024-6-6 21:32:28  main       powerMeter          power      "-217.575" W
 2024-6-6 21:32:27  main       currentMeasurement  current    "-1.341" A
 2024-6-6 21:32:26  main       voltageMeasurement  voltage    "224.591" V
 2024-6-6 21:31:27  main       currentMeasurement  current    "-1.403" A
 2024-6-6 21:31:26  main       voltageMeasurement  voltage    "222.893" V
────────────────────────────────────────────────────────────────────────────

@nayelyz
In CLI logs all A, V, W, KWh events are emitted every 1 minute

2024-06-06T20:21:26.884078433Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:21:26.922979850Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=230.18, precision=3, previous_meter_value=230.64, rate_type="IMPORT", scale="VOLTS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="S0", payload="\xA1\x64\x00\x03\x83\x24\x00\x3C\x00\x03\x84\xF0", src_channel=0, version=3}
2024-06-06T20:21:26.929812350Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:21:26.942776975Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"voltage","capability_id":"voltageMeasurement","component_id":"main","state":{"unit":"V","value":230.18}}
2024-06-06T20:21:26.948174850Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:21:27.823454350Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:21:27.856586183Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=-1.46, precision=3, previous_meter_value=-1.73, rate_type="IMPORT", scale="AMPERES", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="S0", payload="\xA1\x6C\xFF\xFF\xFA\x4C\x00\x3C\xFF\xFF\xF9\x3E", src_channel=0, version=3}
2024-06-06T20:21:28.092834850Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:21:28.131605142Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"current","capability_id":"currentMeasurement","component_id":"main","state":{"unit":"A","value":-1.46}}
2024-06-06T20:21:28.140364725Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:21:28.350329933Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:21:28.750097600Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=-249.841, precision=3, previous_meter_value=-331.593, rate_type="IMPORT", scale="WATTS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, 
encap="S0", payload="\x21\x74\xFF\xFC\x30\x0F\x00\x3C\xFF\xFA\xF0\xB7", src_channel=0, version=3}
2024-06-06T20:21:28.768654058Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:21:28.773441308Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"power","capability_id":"powerMeter","component_id":"main","state":{"unit":"W","value":-249.841}}
2024-06-06T20:21:28.783005475Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:21:28.910313850Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:21:28.953003517Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=107.109, precision=3, previous_meter_value=107.114, rate_type="IMPORT", scale="KILOWATT_HOURS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="S0", payload="\x21\x64\x00\x01\xA2\x65\x00\x3C\x00\x01\xA2\x6A", src_channel=0, version=3}
2024-06-06T20:21:28.959689225Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:21:28.964404225Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"energy","capability_id":"energyMeter","component_id":"main","state":{"unit":"kWh","value":107.109}}
2024-06-06T20:21:28.976031100Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:22:26.884836899Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:22:26.922976482Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=229.906, precision=3, previous_meter_value=230.18, rate_type="IMPORT", scale="VOLTS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="S0", payload="\xA1\x64\x00\x03\x82\x12\x00\x3C\x00\x03\x83\x24", src_channel=0, version=3}
2024-06-06T20:22:26.929638440Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:22:26.943063524Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"voltage","capability_id":"voltageMeasurement","component_id":"main","state":{"unit":"V","value":229.906}}
2024-06-06T20:22:26.948478565Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:22:27.596778524Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:22:27.632882107Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=-1.512, precision=3, previous_meter_value=-1.46, rate_type="IMPORT", scale="AMPERES", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="S0", payload="\xA1\x6C\xFF\xFF\xFA\x18\x00\x3C\xFF\xFF\xFA\x4C", src_channel=0, version=3}
2024-06-06T20:22:27.872919274Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:22:27.903614857Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"current","capability_id":"currentMeasurement","component_id":"main","state":{"unit":"A","value":-1.512}}
2024-06-06T20:22:27.969594940Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:22:28.463488149Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:22:28.476037274Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=-260.386, precision=3, previous_meter_value=-249.841, rate_type="IMPORT", scale="WATTS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, 
encap="S0", payload="\x21\x74\xFF\xFC\x06\xDE\x00\x3C\xFF\xFC\x30\x0F", src_channel=0, version=3}
2024-06-06T20:22:28.864578732Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:22:28.921466691Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"power","capability_id":"powerMeter","component_id":"main","state":{"unit":"W","value":-260.386}}
2024-06-06T20:22:28.972710149Z DEBUG Z-Wave Electric Meter Mc  Energía Solar device thread event handled
2024-06-06T20:22:28.982690649Z TRACE Z-Wave Electric Meter Mc  Received event with handler unnamed
2024-06-06T20:22:29.021006857Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> received Z-Wave command: {args={delta_time=60, meter_type="ELECTRIC_METER", meter_value=107.104, precision=3, previous_meter_value=107.109, rate_type="IMPORT", scale="KILOWATT_HOURS", size=4}, cmd_class="METER", cmd_id="REPORT", dst_channels={}, encap="S0", payload="\x21\x64\x00\x01\xA2\x60\x00\x3C\x00\x01\xA2\x65", src_channel=0, version=3}
2024-06-06T20:22:29.027567649Z TRACE Z-Wave Electric Meter Mc  Found ZwaveDispatcher handler in zwave_electric_meter -> aeotec gen5 meter
2024-06-06T20:22:29.039280732Z INFO Z-Wave Electric Meter Mc  <ZwaveDevice: 77f1ec9f-5879-47c8-a813-428b72b8596a [2B] (Excedente Solar)> emitting event: {"attribute_id":"energy","capability_id":"energyMeter","component_id":"main","state":{"unit":"kWh","value":107.104}}

A selective events Filter between hub and platform history events exists somewhere ???

Hi, @Mariano_Colmenarejo
Sorry, I forgot to reply, I created a ticket about this when you mentioned it. I haven’t received feedback yet but I was able to replicate the behavior.
In my tests of events sent every two minutes, we saw the Hub emitted them correctly but they were “lost” somewhere else, so that’s what needs further investigation.

Hi @nayelyz,

It seems like a selective filter for certain capabilities with many possible events and reduces them.
The only problem is, if you want to debug routines and you don’t know that there is a filter that eliminates some of the events then you go crazy and you don’t understand anything.