Data posted to influx with incorrect timestamp if user does not live in UTC timezone

[RoninTech]

Thanks for this!

I am setting up my new Mi body composition scale 2 so that my raspberry pi inserts our data into an influxdb and we view the data with a grafana dashboard. I have the database being correctly populated every time we step on the scale.

I edited the grafana_dashboard.json file to reference our names but for some reason grafana says there is no data. The influxdb data source is connected and says "Data source is working" with a big green check mark.

While editing the grafana_dashboard.json I noticed on line 631 that there appears to be an undefined variable being used:

SELECT mean(\"macro_fat\") FROM \"miscale_peter_scores\" WHERE $timeFilter GROUP BY time(1d) fill(null)

Do you recall how you setup this $timeFilter in grafana or am I barking up the wrong tree? EDIT: Yes, $timeFilter is correct and I am barking up the wrong tree. See below.

Thanks again!

[RoninTech]

Never mind. I found a reference to $timeFilter being the global time range variable selected by the user in the dashboard.

I have found that if I remove the time aspect of the grafana generated queries to influxdb then data is returned. This valid query sent from grafana returns no data, which makes sense as my data is timestamped hours in the future :

SELECT mean(protein) FROM historydata.autogen.miscale_ronintech WHERE time >= now() - 2d AND time <= now() GROUP BY time(1d)

Whereas this query returns the protein mean of the 2 data points in the influxdb:

SELECT mean(protein) FROM historydata.autogen.miscale_ronintech

I think I am in some weird timezone config hell and if I check the dashboard in a few hours it will show the new data points. For some reason the influxdb nanosecond epoch timestamps for my data entries are a few hours in my future so queries from grafana which only look to the past, aren't getting anything back.

Now I just need to figure out why my timestamps shown by

SELECT * FROM historydata.autogen.miscale_ronintech

Are giving me future timestamps:

> SELECT * FROM historydata.autogen.miscale_ronintech
name: miscale_ronintech
time                bmi   bmr  bone fat   ffm   ffmi  impedance lbm   metabolic_age muscle protein tdee visceral water weight
----                ---   ---  ---- ---   ---   ----  --------- ---   ------------- ------ ------- ---- -------- ----- ------
1663678584000000000 23.22 1302 2.73 22.62 54.21 18.11 597       54.58 42.2          51.04  20.36   1562 7.19     53.08 69.5
1663683990000000000 23.31 1306 2.74 22.81 54.27 18.13 600       54.64 42.58         51.1   20.31   1567 7.32     52.95 69.75
>

Using an online converter on the second timestamp 1663683990000000000 gives:

Assuming that this timestamp is in nanoseconds (1 billionth of a second):
GMT: Tuesday, 20 September 2022 14:26:30
Your time zone: Tuesday, 20 September 2022 21:26:30 GMT+07:00
Relative: In 4 hour

I looked at the code and it looks like it is providing the timestamp to the influxdb client when writing to the DB. Do you know if there is a timezone associated with the passed in timestamp? I wonder if the time needs to be converted to UTC before giving it to influx? The ha-miscale log for the second influx entry above shows:

2022-09-20 14:26:40,829 - INFO > MIBFS: Publish to INFLUXDB: miscale_ronintech, Time:2022-09-20 14:26:30, fields:{'metabolic_age': 42.58, 'bmi': 23.31, 'weight': 69.75, 'impedance': 600, 'lbm': 54.64, 'fat': 22.81, 'visceral': 7.32, 'water': 52.95, 'bone': 2.74, 'muscle': 51.1, 'protein': 20.31, 'bmr': 1306.0, 'ffm': 54.27, 'ffmi': 18.13, 'tdee': 1567} (lib.calcdata:76)

"Time:2022-09-20 14:26:30" at my +7 timezone should be 1663658790, not 1663683990 as shown in the influx timestamp above. So the influx timestamp is +7 hours off, (21:26:30 instead of 14:26:30), which happens to be my timezone difference. Coincidence?

"date" on my raspberry pi debian (64 bit bullseye) host machine shows: Tue 20 Sep 2022 07:06:57 PM +07 "date" on my influx docker shows: Tue Sep 20 12:06:57 UTC 2022 "date" on my grafana docker shows: Tue Sep 20 12:06:57 UTC 2022

Any ideas?

[RoninTech]

I have confirmed that there is a bug caused by writing into the influx database with an incorrect UTC timestamp (unless you do actually live in UTC timezone).

When posting data to influx, it assumes that either the timestamp is correctly adjusted to UTC or that you include your TZ offset. 2 ways to handle it are to first adjust your local time to UTC before posting to the DB, or include your local TZ offset in the timestamp passed to the DB. It was an easy couple of line fix using the second method.

To illustrate, lets say I step on the scale at "2022-09-22 10:08:36" in my non-UTC timezone, lets say +0700. The program will write the data into the influx db as "2022-09-22 10:08:36". Influx stores this as as a UTC timestamp. Unfortunately, "2022-09-22 10:08:36" at UTC is +0700 hours in my future, so if someone (like grafana) queries for data it will not see this future data until 7 hours have passed. The fix for me was to add a DATEFORMAT_LOCAL_OFFSET to the timestamp before posting it to influx. For me, DATEFORMAT_LOCAL_OFFSET = '+0700', so "2022-09-22 10:08:36" becomes "2022-09-22 10:08:36+0700" before giving it to influx and now influx has the correct UTC timestamps on the data points.

After making the change, my database has the correct UTC times in it, so when grafana queries influx, it has access to all of the data in the DB. There should no longer be data points added to the future. I have included a patch file for the fix that I made.

At first I thought I should change conf.py, line 17 from:

DATEFORMAT_MISCAN = '%Y-%m-%d %H:%M:%S'

to:

DATEFORMAT_MISCAN = '%Y-%m-%d %H:%M:%S%z'

Unfortunately, this broke some other stuff so I decided to make the simple but probably less elegant change that I did.

fix_UTC_timestamps_on_influx_posts.zip

[zibous]

@RoninTech

Thanks for the info, works if the locale time is used in the influxdb. In my use case, however, I always use the UTC timezone timestamp for all of them, otherwise I have errors when changing from summer to winter time.

[RoninTech]

2022-09-23 14:03:00,639 - DEBUG > MIBFS: Connect to influxdb localhost database: historydata (lib.influxdata:73) 2022-09-23 14:03:00,642 - INFO > MIBFS: Publish to INFLUXDB: miscale_helen, Time:2022-09-23 14:02:53, fields:{'metabolic_age': 60.81, 'bmi': 26.91, 'weight': 71.05, 'impedance': 536, 'lbm': 52.35, 'fat': 34.04, 'visceral': 8.93, 'water': 47.1, 'bone': 3.6, 'muscle': 43.27, 'protein': 13.8, 'bmr': 1195.0, 'ffm': 47.93, 'ffmi': 18.15, 'tdee': 1434} (lib.calcdata:76) 2022-09-23 14:03:00,643 - INFO > MIBFS: Paul1 (lib.influxdata:76) 2022-09-23 14:03:00,643 - INFO > MIBFS: Post to influxdb localhost database: historydata time: 2022-09-23 14:02:53+0700 (lib.influxdata:76)

Sorry, I must be missing something because as you can see from the logs, writes to influx do not use UTC timestamps. Maybe you aren't using influx and so don't see this or your local TZ is actually UTC?

Writes to influx pull the timestamp from the scale data. If influx writes used UTC then the problem I see would not appear. I had to add the +0700 that you see concatenated on the second timestamp (2022-09-23 14:02:53+0700) in the above log to get correct timestamps in influx. I see the weakness of my hardcoded TZ offset solution not adapting to daylight savings.

So I just need to figure out where to convert the timestamp to UTC in the write to influx scenario.

[zibous]

So I just need to figure out where to convert the timestamp to UTC in the write to influx scenario.

I use the ESP variant to query the data from the MISCALE. These are published via MQTT and then processed with the Python script. The timestamp therefore only comes from the MISCALE application.

Miscale2 --> MQTT --> Calcdata --> Influxdb.

The timestamp is used from the ESP32 Miscale.

char dt[32];
        sprintf(dt, "%s-%02d-%02d %02d:%02d:%02d", String(stoi2(hex, 4)), stoi(hex, 8), stoi(hex, 10), stoi(hex, 12), stoi(hex, 14), stoi(hex, 16));
        String scaleTime = String(dt);

see: https://github.com/zibous/ha-miscale2/blob/master/esp32/src/main.cpp

And published to the influxdb with calcdata.py:

def bodyScores2Influxdb(self):
        if not self.ready:
            return False
        if self.bodyscores and INFLUXDB_MEASUREMENT:
            try:
                measurement = "{}{}{}".format(INFLUXDB_MEASUREMENT, self.user.lower(), '_scores')
                ifx = influxdata.InfuxdbCient()
                ifx_flields = {}
                ifx_flields['score'] = self.bodyscores['score']
                ifx_flields['weight'] = self.bodyscores['deltas']['weight']
                ifx_flields['fat'] = self.bodyscores['deltas']['fat']
                ifx_flields['water'] = self.bodyscores['deltas']['water']
                ifx_flields['muscle'] = self.bodyscores['deltas']['muscle']
                ifx_flields['visceral'] = self.bodyscores['deltas']['visceral']
                ifx_flields['protein'] = self.bodyscores['deltas']['protein']
                ifx_flields['energie'] = self.bodyscores['engergieexp']
                ifx_flields['macro_prot'] = self.bodyscores['macronut']['protein']
                ifx_flields['macro_kh'] = self.bodyscores['macronut']['carbohydrates']
                ifx_flields['macro_fat'] = self.bodyscores['macronut']['fat']
                if ifx_flields:
                    log.info("Publish to INFLUXDB: {}, Time:{}, fields:{}".format(measurement, self.data['timestamp'], ifx_flields))
                    ## -----------------------------------------------------------------------------
                    ## self.data['timestamp'] = MQTT attribute from the Miscale ESP32 Application
                    ## -----------------------------------------------------------------------------
                    ifx.post(ifx_flields, measurement, self.data['timestamp'])
                    return True

            except BaseException as e:
                log.error(f"Error {__name__}, Tag: {INFLUXDB_MEASUREMENT + self.user.lower()} {str(e)} line {sys.exc_info()[-1].tb_lineno}")
                pass

Sep 23 07:12:43 zeusus service_mqtt.sh[1798102]: #033[38;21m2022-09-23 07:12:43,051 - 
   INFO  > MIBCS2: Publish to INFLUXDB: miscale_peter, 
  Time:2022-09-23 07:12:07, 
            fields:
             {'bmi': 23.28, 'weight': 71.3, 'impedance': 558, 
            'lbm': 55.37, 'fat': 13.61, 'visceral': 7.6, 'water': 55.18, 
             'bone': 3.7, 'muscle': 51.43, 'protein': 20.14, 'bmr': 1215.0, 
             'tdee': 2552, 'metabolic_age': 45.61, 'poi': 13.3, 
             'bodytype': 'Ausgeglichen', 'ffm': 54.87, 'ffmi': 17.92} 
            (lib.calcdata:76)#033[0m

[RoninTech]

Ah, there we go. I am using your app.py in the provided "MQTT-less mode".

It looks like you are doing some timezone offset adjustment in main.cpp for the ESP variant that isn't being done for the python app in "MQTT-less" mode.

// For UTC +1.00 : 1 * 60 * 60 : 3600
const long gmtOffset_sec = 3600;
const int daylightOffset_sec = 0;  // no daylightOffset !

So for that log snippet you posted above, is "2022-09-23 07:12:07" not your actual local time but your localtime adjusted to UTC?

For others that may be interested in this python app in "MQTT-less" mode use case, I have made a new patch. It no longer relies on a hardcoded offset that doesn't handle daylight savings changes. Here is a log snippet showing how the non-UTC timestamp comes into the influxdate.post function and gets converted from the hosts local timezone to UTC:

2022-09-23 16:53:07,778 - DEBUG > MIBFS: Connect to influxdb localhost database: historydata (lib.influxdata:73) 2022-09-23 16:53:07,779 - INFO > MIBFS: Publish to INFLUXDB: miscale_helen, Time:2022-09-23 16:53:04, fields:{'metabolic_age': 59.65, 'bmi': 26.91, 'weight': 71.05, 'impedance': 508, 'lbm': 52.54, 'fat': 33.77, 'visceral': 8.93, 'water': 47.29, 'bone': 3.61, 'muscle': 43.44, 'protein': 13.85, 'bmr': 1195.0, 'ffm': 48.12, 'ffmi': 18.22, 'tdee': 1434} (lib.calcdata:76) 2022-09-23 16:53:07,781 - INFO > MIBFS: Post to influxdb localhost database: historydata time: 2022-09-23 09:53:04+00:00 (lib.influxdata:76)

So "Time:2022-09-23 16:53:04", which is my local time, gets converted to it's UTC equivalent of "time: 2022-09-23 09:53:04+00:00" before insertion into the DB.

New patch is attached.

local_to_utc_fix.zip