Not sure if this is a bug or configuration error

[Surkaffe]

I had my Home Assistant setup offline for two months, and booted it up again yesterday. Since then, Im getting these (attached) messages in my logfile. I dont see the clock in AMS reader changing, so Im not relly sure what is going on?

I tried rebooting AMS reader and that didnt help.

Any suggestions would be appreciated.

Edit: So I tried connecting to AMS Reader with telnet and debugging activated:

[ArnieO]

It receives valid data, there seems to be some kind of time issue.
Can you show me the your config page?

[Surkaffe]

[ArnieO]

@Surkaffe : I don't see any issues here. And the timestamp in the upper right corner seems correct.

Please run a new Telnet debug with the setting "Verbose" when you activate it - so that we can study a payload from your meter.
Indicate the (approximate) correct time when you made the debug log. Due to the strange HA messages (alternating between 10:31 and 11:31), we need you to include several payloads.

[Surkaffe]

01: 7:14 AM 12/8/2025
02: 20:13 same day
03: 15:31 14/8/2025

Would it be worth a try if I factory reset the reader?

AMS reader 01.log
AMS reader 02.log
AMS reader 03.log

[ArnieO]

Due to vacation, we have not been able to look into this earlier - but will start working on it now. And we now have a quite identical feedback in this issue: #992
Based on the content of the frames in your data logs I can see you too are in Denmark.
Thank you for providing the logs, I'll analyze them now and revert.

[ArnieO]

We need @gskjold to look into this.

Modell frame fra: https://github.com/UtilitechAS/amsreader-firmware/blob/main/frames/Kamstup-Encrypted.raw

0F 00 00 00 00 
0C 07 E4 05 0C 02 0A 19 00 FF 80 00 80 // Package timestamp

02 41
0A 0E 4B 61 6D 73 74 72 75 70 5F 56 30 30 30 31 - List ID
09 06 01 01 01 08 00 FF 06 00 11 94 CA - Active+ Energy
09 06 01 01 02 08 00 FF 06 00 00 00 00 - Active- Energy
09 06 01 01 03 08 00 FF 06 00 00 12 7E - Reactive+ Energy
09 06 01 01 04 08 00 FF 06 00 09 55 0E - Reactive- Energy
09 06 01 01 00 00 01 FF 06 01 44 AD E1 - Electricity ID?
09 06 01 01 01 07 00 FF 06 00 00 05 CC - Active+ Instantaneous value
09 06 01 01 02 07 00 FF 06 00 00 00 00 - Active- Instantaneous value
09 06 01 01 03 07 00 FF 06 00 00 00 00 - Reactive+ Instantaneous value
09 06 01 01 04 07 00 FF 06 00 00 00 17 - Reactive- Instantaneous value
09 06 00 01 01 00 00 FF 09 0C 07 E4 05 0C 02 0A 19 00 FF 80 00 80 - Current date/time
09 06 01 01 20 07 00 FF 12 00 E5 - L1 Voltage Instantaneous value
09 06 01 01 34 07 00 FF 12 00 E5 - L2 Voltage Instantaneous value
09 06 01 01 48 07 00 FF 12 00 E3 - L3 Voltage Instantaneous value
09 06 01 01 1F 07 00 FF 06 00 00 00 4B - L1 Current Instantaneous value
09 06 01 01 33 07 00 FF 06 00 00 00 AA - L2 Current Instantaneous value
09 06 01 01 47 07 00 FF 06 00 00 01 E4 - L3 Current Instantaneous value
09 06 01 01 15 07 00 FF 06 00 00 00 71 - L1 Active+ Instantaneous value
09 06 01 01 29 07 00 FF 06 00 00 01 54 - L2 Active+ Instantaneous value
09 06 01 01 3D 07 00 FF 06 00 00 04 07 - L3 Active+ Instantaneous value
09 06 01 01 21 07 00 FF 12 00 4D - L1 (cos.phi) (PF) Instantaneous value
09 06 01 01 35 07 00 FF 12 00 5F - L2 (cos.phi) (PF) Instantaneous value
09 06 01 01 49 07 00 FF 12 00 62 - L3 (cos.phi) (PF) Instantaneous value
09 06 01 01 0D 07 00 FF 12 00 63 - Avegage (cos.phi) (PF) Inst. value
09 06 01 01 16 07 00 FF 06 00 00 00 00 - L1 Active- Instantaneous value
09 06 01 01 2A 07 00 FF 06 00 00 00 00 - L2 Active- Instantaneous value
09 06 01 01 3E 07 00 FF 06 00 00 00 00 - L3 Active- Instantaneous value
09 06 01 01 16 08 00 FF 06 00 00 00 00 - L1 Active- Energy
09 06 01 01 2A 08 00 FF 06 00 00 00 00 - L2 Active- Energy
09 06 01 01 3E 08 00 FF 06 00 00 00 00 - L3 Active- Energy
09 06 01 01 15 08 00 FF 06 00 0A 8F 97 - L1 Active+ Energy
09 06 01 01 29 08 00 FF 06 00 04 C1 53 - L2 Active+ Energy
09 06 01 01 3D 08 00 FF 06 00 02 43 E0 - L3 Active+ Energy

***********************************************************************
Below are 3 frames from "AMS reader 01.log"

Can be converted using https://www.gurux.fi/GuruxDLMSTranslator
--------------------------------------------------------------------------
0F 00 00 00 00 
0C 07 E9 08 0C 02 06 3A 1E FF 80 00 80 
02 41 
0A 0E 4B 61 6D 73 74 72 75 70 5F 56 30 30 30 31 
09 06 01 01 01 08 00 FF 06 00 27 18 D9 
09 06 01 01 02 08 00 FF 06 00 00 00 00 
09 06 01 01 03 08 00 FF 06 00 00 04 8B 
09 06 01 01 04 08 00 FF 06 00 11 87 B8 
09 06 01 01 00 00 01 FF 06 01 4E E2 02 
09 06 01 01 01 07 00 FF 06 00 00 01 AE 
09 06 01 01 02 07 00 FF 06 00 00 00 00 
09 06 01 01 03 07 00 FF 06 00 00 00 00 
09 06 01 01 04 07 00 FF 06 00 00 00 EF 
09 06 00 01 01 00 00 FF 09 0C 07 E9 08 0C 02 06 3A 1E FF 80 00 80 
09 06 01 01 20 07 00 FF 12 00 E8 
09 06 01 01 34 07 00 FF 12 00 E6 
09 06 01 01 48 07 00 FF 12 00 E8 
09 06 01 01 1F 07 00 FF 06 00 00 00 04 
09 06 01 01 33 07 00 FF 06 00 00 00 00 
09 06 01 01 47 07 00 FF 06 00 00 00 F9 
09 06 01 01 15 07 00 FF 06 00 00 00 00 
09 06 01 01 29 07 00 FF 06 00 00 00 00 
09 06 01 01 3D 07 00 FF 06 00 00 01 AE 
09 06 01 01 21 07 00 FF 12 00 00 
09 06 01 01 35 07 00 FF 12 00 64 
09 06 01 01 49 07 00 FF 12 00 58 
09 06 01 01 0D 07 00 FF 12 00 57 
09 06 01 01 16 07 00 FF 06 00 00 00 00 
09 06 01 01 2A 07 00 FF 06 00 00 00 00 
09 06 01 01 3E 07 00 FF 06 00 00 00 00 
09 06 01 01 16 08 00 FF 06 00 00 00 03 
09 06 01 01 2A 08 00 FF 06 00 00 00 00 
09 06 01 01 3E 08 00 FF 06 00 00 00 00 
09 06 01 01 15 08 00 FF 06 00 02 7B 8A 
09 06 01 01 29 08 00 FF 06 00 00 93 26 
09 06 01 01 3D 08 00 FF 06 00 24 0A 2C 

Can be converted using https://www.gurux.fi/GuruxDLMSTranslator 
--------------------------------------------------------------------------
0F 00 00 00 00 
0C 07 E9 08 0C 02 06 3A 28 FF 80 00 80 
02 41 
0A 0E 4B 61 6D 73 74 72 75 70 5F 56 30 30 30 31 
09 06 01 01 01 08 00 FF 06 00 27 18 D9 
09 06 01 01 02 08 00 FF 06 00 00 00 00 
09 06 01 01 03 08 00 FF 06 00 00 04 8B 
09 06 01 01 04 08 00 FF 06 00 11 87 B8 
09 06 01 01 00 00 01 FF 06 01 4E E2 02 
09 06 01 01 01 07 00 FF 06 00 00 01 AB 
09 06 01 01 02 07 00 FF 06 00 00 00 00 
09 06 01 01 03 07 00 FF 06 00 00 00 00 
09 06 01 01 04 07 00 FF 06 00 00 00 EF 
09 06 00 01 01 00 00 FF 09 0C 07 E9 08 0C 02 06 3A 28 FF 80 00 80 
09 06 01 01 20 07 00 FF 12 00 E8 
09 06 01 01 34 07 00 FF 12 00 E6 
09 06 01 01 48 07 00 FF 12 00 E8 
09 06 01 01 1F 07 00 FF 06 00 00 00 04 
09 06 01 01 33 07 00 FF 06 00 00 00 00 
09 06 01 01 47 07 00 FF 06 00 00 00 F9 
09 06 01 01 15 07 00 FF 06 00 00 00 00 
09 06 01 01 29 07 00 FF 06 00 00 00 00 
09 06 01 01 3D 07 00 FF 06 00 00 01 AB 
09 06 01 01 21 07 00 FF 12 00 00 
09 06 01 01 35 07 00 FF 12 00 64 
09 06 01 01 49 07 00 FF 12 00 58 
09 06 01 01 0D 07 00 FF 12 00 57 
09 06 01 01 16 07 00 FF 06 00 00 00 00 
09 06 01 01 2A 07 00 FF 06 00 00 00 00 
09 06 01 01 3E 07 00 FF 06 00 00 00 00 
09 06 01 01 16 08 00 FF 06 00 00 00 03 
09 06 01 01 2A 08 00 FF 06 00 00 00 00 
09 06 01 01 3E 08 00 FF 06 00 00 00 00 
09 06 01 01 15 08 00 FF 06 00 02 7B 8A 
09 06 01 01 29 08 00 FF 06 00 00 93 26 
09 06 01 01 3D 08 00 FF 06 00 24 0A 2C

Can NOT be converted using https://www.gurux.fi/GuruxDLMSTranslator 
Error: "Invalid data type: 7"
--------------------------------------------------------------------------
0F 00 00 00 00 
0C 07 E9 08 0C 02 06 3A 32 FF 80 00 80 
02 41 
0A 0E 4B 61 6D 73 74 72 75 70 5F 56 30 30 30 31 
09 06 01 01 01 08 00 FF 06 00 27 18 D9 
09 06 01 01 02 08 00 FF 06 00 00 00 00 
09 06 01 01 03 08 00 FF 06 00 00 04 8B 
09 06 01 01 04 08 00 FF 06 00 11 87 B8 
09 06 01 01 00 00 01 FF 06 01 4E E2 02 
09 06 01 01 01 07 00 FF 06 00 00 01 AA 
09 06 01 01 02 07 00 FF 06 00 00 00 00 
09 06 01 01 03 07 00 FF 06 00 00 00 00 
09 06 01 01 04 07 00 FF 06 00 00 00 ED 
09 06 00 01 01 00 00 FF 09 0C 07 E9 08 0C 02 06 3A 32 FF 80 00 80 
09 06 01 01 20 07 00 FF 12 00 E8 
09 06 01 01 34 07 00 FF 12 00 E6 
09 06 01 01 48 07 00 FF 12 00 E7 
09 06 01 01 1F 07 00 FF 06 00 00 00 04 
09 06 01 01 33 07 00 FF 06 00 00 00 00 
09 06 01 01 47 07 00 FF 06 00 00 00 F9 
09 06 01 01 15 07 00 FF 06 00 
09 06 01 01 3D 07 00 FF 06 00 00 01 AA 
09 06 01 01 21 07 00 FF 12 00 00 
09 06 01 01 35 07 00 FF 12 00 64 
09 06 01 01 49 07 00 FF 12 00 58 
09 06 01 01 0D 07 00 FF 12 00 57 
09 06 01 01 16 07 00 FF 06 00 00 00 00 
09 06 01 01 2A 07 00 FF 06 00 00 00 00 
09 06 01 01 3E 07 00 FF 06 00 00 00 00 
09 06 01 01 16 08 00 FF 06 00 00 00 03 
09 06 01 01 2A 08 00 FF 06 00 00 00 00 
09 06 01 01 3E 08 00 FF 06 00 00 00 00 
09 06 01 01 15 08 00 FF 06 00 02 7B 8A 
09 06 01 01 29 08 00 FF 06 00 00 93 26 
09 06 01 01 3D 08 00 FF 06 00 24 0A 2C

The first frame above, converted to XML:

<DataNotification>
  <LongInvokeIdAndPriority Value="00000000" />
  <!--2025-08-12 06:58:30-->
  <DateTime Value="07E9080C02063A1EFF800080" />
  <NotificationBody>
    <DataValue>
      <Structure Qty="41" >
        <String Value="Kamstrup_V0001" />
        <!--1.1.1.8.0.255-->
        <OctetString Value="0101010800FF" />
        <UInt32 Value="002718D9" />
        <!--1.1.2.8.0.255-->
        <OctetString Value="0101020800FF" />
        <UInt32 Value="00000000" />
        <!--1.1.3.8.0.255-->
        <OctetString Value="0101030800FF" />
        <UInt32 Value="0000048B" />
        <!--1.1.4.8.0.255-->
        <OctetString Value="0101040800FF" />
        <UInt32 Value="001187B8" />
        <!--1.1.0.0.1.255-->
        <OctetString Value="0101000001FF" />
        <UInt32 Value="014EE202" />
        <!--1.1.1.7.0.255-->
        <OctetString Value="0101010700FF" />
        <UInt32 Value="000001AE" />
        <!--1.1.2.7.0.255-->
        <OctetString Value="0101020700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.3.7.0.255-->
        <OctetString Value="0101030700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.4.7.0.255-->
        <OctetString Value="0101040700FF" />
        <UInt32 Value="000000EF" />
        <!--0.1.1.0.0.255-->
        <OctetString Value="0001010000FF" />
        <!--2025-08-12 06:58:30-->
        <OctetString Value="07E9080C02063A1EFF800080" />
        <!--1.1.32.7.0.255-->
        <OctetString Value="0101200700FF" />
        <UInt16 Value="00E8" />
        <!--1.1.52.7.0.255-->
        <OctetString Value="0101340700FF" />
        <UInt16 Value="00E6" />
        <!--1.1.72.7.0.255-->
        <OctetString Value="0101480700FF" />
        <UInt16 Value="00E8" />
        <!--1.1.31.7.0.255-->
        <OctetString Value="01011F0700FF" />
        <UInt32 Value="00000004" />
        <!--1.1.51.7.0.255-->
        <OctetString Value="0101330700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.71.7.0.255-->
        <OctetString Value="0101470700FF" />
        <UInt32 Value="000000F9" />
        <!--1.1.21.7.0.255-->
        <OctetString Value="0101150700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.41.7.0.255-->
        <OctetString Value="0101290700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.61.7.0.255-->
        <OctetString Value="01013D0700FF" />
        <UInt32 Value="000001AE" />
        <!--1.1.33.7.0.255-->
        <OctetString Value="0101210700FF" />
        <UInt16 Value="0000" />
        <!--1.1.53.7.0.255-->
        <OctetString Value="0101350700FF" />
        <UInt16 Value="0064" />
        <!--1.1.73.7.0.255-->
        <OctetString Value="0101490700FF" />
        <UInt16 Value="0058" />
        <!--1.1.13.7.0.255-->
        <OctetString Value="01010D0700FF" />
        <UInt16 Value="0057" />
        <!--1.1.22.7.0.255-->
        <OctetString Value="0101160700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.42.7.0.255-->
        <OctetString Value="01012A0700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.62.7.0.255-->
        <OctetString Value="01013E0700FF" />
        <UInt32 Value="00000000" />
        <!--1.1.22.8.0.255-->
        <OctetString Value="0101160800FF" />
        <UInt32 Value="00000003" />
        <!--1.1.42.8.0.255-->
        <OctetString Value="01012A0800FF" />
        <UInt32 Value="00000000" />
        <!--1.1.62.8.0.255-->
        <OctetString Value="01013E0800FF" />
        <UInt32 Value="00000000" />
        <!--1.1.21.8.0.255-->
        <OctetString Value="0101150800FF" />
        <UInt32 Value="00027B8A" />
        <!--1.1.41.8.0.255-->
        <OctetString Value="0101290800FF" />
        <UInt32 Value="00009326" />
        <!--1.1.61.8.0.255-->
        <OctetString Value="01013D0800FF" />
        <UInt32 Value="00240A2C" />
      </Structure>
    </DataValue>
  </NotificationBody>
</DataNotification>

The first frame above, decoded from XML:

[zarilion]

I’m having the same issue. Norway. Latest version reader and HA. Seems to have started August 11th at 04:12 in the morning.

[zarilion]

Klive

[zarilion]

Could you be so kind as to run a Telnet debug and share the logfile with us?

I'll get that done when I get home :)

[ArnieO]

Perfect. If you don't want to post it here you can email it to [email protected]

[zarilion]

Sent you a logfile

[ArnieO]

Thank you very much!

[gskjold]

This is kind of hard to test without a meter, but here goes:
esp32s2.zip

[Surkaffe]

I tried updating manually (browser) a few moments ago, and it seems there is no change.
I will have to wait until tomorrow before I have the time to make an upgrade through USB to see if that will help.

[ArnieO]

Did the firmware version number (upper left corner) change? You should se letters and numbers in stead of "v2.4.7"

[gskjold]

Found issue, new test:
esp32s2.zip

[gskjold]

Sending the meter clock and the data timestamp whenever it is updated from the meter is intended behaviour.

Also, the message you are seeing in the telnet log is just saying that there is sufficient data to update the internal data storage with hourly and daily graph data, but it is not the correct time to do it. The only time it will update this data storage is when passing the top of the hour. In other words, not related to your original issue about MQTT/HA.

[KDYR]

"whenever it is updated from the meter is intended behaviour" - that would be fine, because I expect that to happen rarely.
The current issue is that two messages are sent every 10 sec and according to your explanation no update is made that often.
A message when an update is indeed made seems relevant.
Thanks

[gskjold]

The data timestamp and the meter timestamp is updated every time the meter sends data, which in your case is every 10s (I'm guessing Kamstrup meter)

[KDYR]

I may have missed it, but I do not recall that the AMS-Leser posted these frequent log entries in the past.

In any case - now the subject has been brought up - I don't understand why the AMS-Leser would send log telegrams about such standard events. What is the logic justifying telegrams for these local/internal AMS-leser events? There are other frequent events like "HDLC frame read", "LLC frame read", "GCM frame read", "DLMS frame read", "Received valid DLMS", "Used 1012ms to read HAN port" and probably more, that do not cause any MQTT telegram to be sent. I don't even see a log entry for the syncing that was explained to happen "at the top of the hour". For de-bugging it could perhaps be useful but in daily operation?

Anyway, to conclude this I created #1029 with a proposal for a configuration option.

[gskjold]

Anything you find in the telnet log is for debugging purposes and has no value in daily operation. The only reason you are seeing this is because you have enabled telnet and set it to debug level. If you set it to "Warning" or "Info" it will restrict to more readable logging. When you use "Debug" or "Verbose", the output is intended for developers to see decision making and raw data, and was never designed for interpretation by the end user.