Help with unexpected python behavior

Development
1

Hello,
hoping to be in the right section.
I’m still trying to fix some problems of the max integration, but i can’t understand some very easy code is behaving differently from expected. Basically, i’m trying to have the control of the update period :slight_smile: this is the code i can’t fix:

    def update(self):
        """Pull the latest data from the MAX! Cube."""
        # Acquire mutex to prevent simultaneous update from multiple threads
        with self.mutex:
            # Only update every update_interval
            if ((time.monotonic() - self._updatets) >= self.scan_interval):
                _LOGGER.debug("Updating: monotonic %s, updatets %s, delta %s, scan_interval: %s", time.monotonic(), self._updatets, (time.monotonic() - self._updatets), self.scan_interval)

                try:
                    self.cube.update()
                except timeout:
                    _LOGGER.error("Max!Cube connection failed")
                    return False

                self._updatets = time.monotonic()
            else:
                _LOGGER.debug("Skipping update")

So, the scan_interval i set up is one second, but the update does not happen as soon as 1 second has passed, it behaves in this unexpected way:

2023-11-04 11:15:40.604 DEBUG (SyncWorker_4) [custom_components.maxcube] Updating: monotonic 365312.090535091, updatets 365282.199156116, delta 29.891383029986173, scan_interval: 1.0
2023-11-04 11:16:10.606 DEBUG (SyncWorker_8) [custom_components.maxcube] Updating: monotonic 365342.092137765, updatets 365312.194047301, delta 29.898091407958418, scan_interval: 1.0

why the hell is it waiting 30 seconds??
I thought this could be the minimum period the file is called, but the last debug line is spamming my log every millisecond or so, so i’m back to not understanding anything :slight_smile:

Any idea?
Thanks!

2

i really can’t sort this out, please help with some ideas, also of debugging :slight_smile:
i wondered if there could be any timeout in the update itself, in this case the mutex could block the update every 30 seconds waiting for the previous update to finish.
So i put a debug around the update call. It is taking something like 1 tenth. Non the problem.
What is really strange is that if i put a debut in the “else” branch (that should just be waiting for the next run), this branch runs for just some tenths (under a second), but the update is always coming after 30 seconds. I can’t understand this! Here is an example…
Thanks!

2023-11-07 22:33:17.699 ERROR (SyncWorker_26) [custom_components.maxcube] Update total time: 0.0887141227722168
2023-11-07 22:33:17.706 ERROR (SyncWorker_26) [custom_components.maxcube] 0.0031399860745295882
2023-11-07 22:33:17.709 ERROR (SyncWorker_17) [custom_components.maxcube] 0.006025178008712828
2023-11-07 22:33:17.711 ERROR (SyncWorker_1) [custom_components.maxcube] 0.008164952043443918
2023-11-07 22:33:17.713 ERROR (SyncWorker_10) [custom_components.maxcube] 0.010242762975394726
2023-11-07 22:33:17.715 ERROR (SyncWorker_8) [custom_components.maxcube] 0.012463074061088264
2023-11-07 22:33:17.717 ERROR (SyncWorker_9) [custom_components.maxcube] 0.014026224031113088
2023-11-07 22:33:17.718 ERROR (SyncWorker_6) [custom_components.maxcube] 0.015250895987264812
2023-11-07 22:33:17.720 ERROR (SyncWorker_27) [custom_components.maxcube] 0.01759765006136149
2023-11-07 22:33:17.723 ERROR (SyncWorker_12) [custom_components.maxcube] 0.019998550065793097
2023-11-07 22:33:17.724 ERROR (SyncWorker_16) [custom_components.maxcube] 0.02138981397729367
2023-11-07 22:33:17.726 ERROR (SyncWorker_15) [custom_components.maxcube] 0.023319405037909746
2023-11-07 22:33:17.728 ERROR (SyncWorker_22) [custom_components.maxcube] 0.02532345801591873
2023-11-07 22:33:17.730 ERROR (SyncWorker_25) [custom_components.maxcube] 0.027105643064714968
2023-11-07 22:33:17.731 ERROR (SyncWorker_13) [custom_components.maxcube] 0.02845346205867827
2023-11-07 22:33:17.733 ERROR (SyncWorker_29) [custom_components.maxcube] 0.03039781202096492
2023-11-07 22:33:17.735 ERROR (SyncWorker_2) [custom_components.maxcube] 0.03249686397612095
2023-11-07 22:33:17.737 ERROR (SyncWorker_21) [custom_components.maxcube] 0.03455723205115646
2023-11-07 22:33:17.739 ERROR (SyncWorker_11) [custom_components.maxcube] 0.0363785270601511
2023-11-07 22:33:17.741 ERROR (SyncWorker_24) [custom_components.maxcube] 0.038014417979866266
2023-11-07 22:33:17.743 ERROR (SyncWorker_8) [custom_components.maxcube] 0.04076364799402654
2023-11-07 22:33:17.745 ERROR (SyncWorker_23) [custom_components.maxcube] 0.04223385499790311
2023-11-07 22:33:17.747 ERROR (SyncWorker_6) [custom_components.maxcube] 0.04473516205325723
2023-11-07 22:33:17.750 ERROR (SyncWorker_27) [custom_components.maxcube] 0.047479782020673156
2023-11-07 22:33:17.752 ERROR (SyncWorker_20) [custom_components.maxcube] 0.049059136072173715
2023-11-07 22:33:17.755 ERROR (SyncWorker_3) [custom_components.maxcube] 0.052135437028482556

2023-11-07 22:33:47.701 ERROR (SyncWorker_7) [custom_components.maxcube] Update total time: 0.08917498588562012
2023-11-07 22:33:47.705 ERROR (SyncWorker_22) [custom_components.maxcube] 0.0032200959976762533
2023-11-07 22:33:47.708 ERROR (SyncWorker_8) [custom_components.maxcube] 0.00681124406401068
2023-11-07 22:33:47.710 ERROR (SyncWorker_25) [custom_components.maxcube] 0.008965722052380443
2023-11-07 22:33:47.713 ERROR (SyncWorker_20) [custom_components.maxcube] 0.011755970073863864
2023-11-07 22:33:47.715 ERROR (SyncWorker_2) [custom_components.maxcube] 0.013969966094009578
2023-11-07 22:33:47.718 ERROR (SyncWorker_4) [custom_components.maxcube] 0.01617390604224056
2023-11-07 22:33:47.719 ERROR (SyncWorker_18) [custom_components.maxcube] 0.01787555404007435
2023-11-07 22:33:47.721 ERROR (SyncWorker_10) [custom_components.maxcube] 0.01953268505167216
2023-11-07 22:33:47.723 ERROR (SyncWorker_23) [custom_components.maxcube] 0.021651052054949105
2023-11-07 22:33:47.725 ERROR (SyncWorker_28) [custom_components.maxcube] 0.023722567013464868
2023-11-07 22:33:47.727 ERROR (SyncWorker_14) [custom_components.maxcube] 0.0257317500654608
2023-11-07 22:33:47.729 ERROR (SyncWorker_26) [custom_components.maxcube] 0.02785200602374971
2023-11-07 22:33:47.731 ERROR (SyncWorker_6) [custom_components.maxcube] 0.03003098303452134
2023-11-07 22:33:47.734 ERROR (SyncWorker_15) [custom_components.maxcube] 0.03223688609432429
2023-11-07 22:33:47.736 ERROR (SyncWorker_12) [custom_components.maxcube] 0.03455132502131164
2023-11-07 22:33:47.739 ERROR (SyncWorker_27) [custom_components.maxcube] 0.03737455408554524
2023-11-07 22:33:47.741 ERROR (SyncWorker_29) [custom_components.maxcube] 0.039287663996219635
2023-11-07 22:33:47.743 ERROR (SyncWorker_19) [custom_components.maxcube] 0.04120945907197893
2023-11-07 22:33:47.745 ERROR (SyncWorker_1) [custom_components.maxcube] 0.043221938074566424
2023-11-07 22:33:47.746 ERROR (SyncWorker_13) [custom_components.maxcube] 0.0443059999961406
2023-11-07 22:33:47.747 ERROR (SyncWorker_9) [custom_components.maxcube] 0.045915798051282763
2023-11-07 22:33:47.749 ERROR (SyncWorker_18) [custom_components.maxcube] 0.04787614801898599
2023-11-07 22:33:47.750 ERROR (SyncWorker_5) [custom_components.maxcube] 0.04906284005846828
2023-11-07 22:33:47.752 ERROR (SyncWorker_23) [custom_components.maxcube] 0.05065999005455524
2023-11-07 22:33:47.754 ERROR (SyncWorker_21) [custom_components.maxcube] 0.05222062102984637
2023-11-07 22:33:48.665 ERROR (SyncWorker_26) [custom_components.maxcube] 0.9636706890305504
2023-11-07 22:33:48.673 ERROR (SyncWorker_16) [custom_components.maxcube] 0.9720373230520636
2023-11-07 22:33:48.684 ERROR (SyncWorker_24) [custom_components.maxcube] 0.983111726003699
2023-11-07 22:33:48.687 ERROR (SyncWorker_7) [custom_components.maxcube] 0.9854259060230106
2023-11-07 22:33:48.689 ERROR (SyncWorker_22) [custom_components.maxcube] 0.9878948800032958
2023-11-07 22:33:48.692 ERROR (SyncWorker_8) [custom_components.maxcube] 0.990293744020164
2023-11-07 22:33:48.693 ERROR (SyncWorker_8) [custom_components.maxcube] 0.9915045090019703
2023-11-07 22:33:48.695 ERROR (SyncWorker_19) [custom_components.maxcube] 0.9938979099970311
2023-11-07 22:33:48.697 ERROR (SyncWorker_20) [custom_components.maxcube] 0.9958828150993213
2023-11-07 22:33:48.700 ERROR (SyncWorker_13) [custom_components.maxcube] 0.9984358440851793
2023-11-07 22:33:48.702 ERROR (SyncWorker_9) [custom_components.maxcube] 1.0007088941056281
2023-11-07 22:33:48.704 ERROR (SyncWorker_11) [custom_components.maxcube] 1.0030849250033498
2023-11-07 22:33:48.707 ERROR (SyncWorker_10) [custom_components.maxcube] 1.0057885630521923

2023-11-07 22:34:17.704 ERROR (SyncWorker_13) [custom_components.maxcube] Update total time: 0.0892486572265625
2023-11-07 22:34:17.708 ERROR (SyncWorker_27) [custom_components.maxcube] 0.0034011680399999022
2023-11-07 22:34:17.712 ERROR (SyncWorker_15) [custom_components.maxcube] 0.007449700031429529
2023-11-07 22:34:17.715 ERROR (SyncWorker_29) [custom_components.maxcube] 0.010914533981122077
2023-11-07 22:34:17.719 ERROR (SyncWorker_2) [custom_components.maxcube] 0.014960806933231652
2023-11-07 22:34:17.723 ERROR (SyncWorker_21) [custom_components.maxcube] 0.018363752984441817
2023-11-07 22:34:17.725 ERROR (SyncWorker_9) [custom_components.maxcube] 0.020352973020635545
2023-11-07 22:34:17.727 ERROR (SyncWorker_18) [custom_components.maxcube] 0.02251333894673735
2023-11-07 22:34:17.729 ERROR (SyncWorker_10) [custom_components.maxcube] 0.024024785961955786
2023-11-07 22:34:17.731 ERROR (SyncWorker_6) [custom_components.maxcube] 0.026484093978069723
2023-11-07 22:34:17.734 ERROR (SyncWorker_17) [custom_components.maxcube] 0.029092437005601823
2023-11-07 22:34:17.735 ERROR (SyncWorker_26) [custom_components.maxcube] 0.030319849960505962
2023-11-07 22:34:17.737 ERROR (SyncWorker_7) [custom_components.maxcube] 0.03237077302765101
2023-11-07 22:34:17.739 ERROR (SyncWorker_16) [custom_components.maxcube] 0.034437139984220266
2023-11-07 22:34:17.741 ERROR (SyncWorker_22) [custom_components.maxcube] 0.03684518893714994
2023-11-07 22:34:17.743 ERROR (SyncWorker_13) [custom_components.maxcube] 0.03891329700127244
2023-11-07 22:34:17.745 ERROR (SyncWorker_3) [custom_components.maxcube] 0.040924035012722015
2023-11-07 22:34:17.747 ERROR (SyncWorker_8) [custom_components.maxcube] 0.04259233293123543
2023-11-07 22:34:17.749 ERROR (SyncWorker_29) [custom_components.maxcube] 0.044778865994885564
2023-11-07 22:34:17.752 ERROR (SyncWorker_4) [custom_components.maxcube] 0.047354264999739826
2023-11-07 22:34:17.754 ERROR (SyncWorker_28) [custom_components.maxcube] 0.04919000493828207
2023-11-07 22:34:17.756 ERROR (SyncWorker_1) [custom_components.maxcube] 0.050993670942261815
2023-11-07 22:34:17.758 ERROR (SyncWorker_19) [custom_components.maxcube] 0.05367654992733151
2023-11-07 22:34:17.760 ERROR (SyncWorker_10) [custom_components.maxcube] 0.055403309990651906
2023-11-07 22:34:17.761 ERROR (SyncWorker_23) [custom_components.maxcube] 0.05690807197242975
2023-11-07 22:34:17.763 ERROR (SyncWorker_24) [custom_components.maxcube] 0.058743405039422214

2023-11-07 22:34:47.704 ERROR (SyncWorker_27) [custom_components.maxcube] Update total time: 0.087982177734375
2023-11-07 22:34:47.707 ERROR (SyncWorker_4) [custom_components.maxcube] 0.0030317649943754077
2023-11-07 22:34:47.711 ERROR (SyncWorker_16) [custom_components.maxcube] 0.006613172008655965
2023-11-07 22:34:47.715 ERROR (SyncWorker_9) [custom_components.maxcube] 0.010119467973709106
2023-11-07 22:34:47.717 ERROR (SyncWorker_22) [custom_components.maxcube] 0.012386203976348042
2023-11-07 22:34:47.720 ERROR (SyncWorker_12) [custom_components.maxcube] 0.015173692954704165
2023-11-07 22:34:47.723 ERROR (SyncWorker_7) [custom_components.maxcube] 0.018546342966146767
2023-11-07 22:34:47.726 ERROR (SyncWorker_17) [custom_components.maxcube] 0.021292536985129118
2023-11-07 22:34:47.728 ERROR (SyncWorker_15) [custom_components.maxcube] 0.02407774794846773
2023-11-07 22:34:47.731 ERROR (SyncWorker_8) [custom_components.maxcube] 0.026551055954769254
2023-11-07 22:34:47.734 ERROR (SyncWorker_19) [custom_components.maxcube] 0.029142361949197948
2023-11-07 22:34:47.736 ERROR (SyncWorker_21) [custom_components.maxcube] 0.031199304037727416
2023-11-07 22:34:47.739 ERROR (SyncWorker_28) [custom_components.maxcube] 0.03349731699563563
2023-11-07 22:34:47.741 ERROR (SyncWorker_23) [custom_components.maxcube] 0.036298398044891655
2023-11-07 22:34:47.743 ERROR (SyncWorker_14) [custom_components.maxcube] 0.038891723030246794
2023-11-07 22:34:47.745 ERROR (SyncWorker_30) [custom_components.maxcube] 0.04092542396392673
2023-11-07 22:34:47.748 ERROR (SyncWorker_27) [custom_components.maxcube] 0.043219530023634434
2023-11-07 22:34:47.751 ERROR (SyncWorker_4) [custom_components.maxcube] 0.046995323966257274
2023-11-07 22:34:47.755 ERROR (SyncWorker_16) [custom_components.maxcube] 0.05013266101013869
2023-11-07 22:34:47.756 ERROR (SyncWorker_9) [custom_components.maxcube] 0.052102252026088536
2023-11-07 22:34:47.758 ERROR (SyncWorker_22) [custom_components.maxcube] 0.05337442399468273
2023-11-07 22:34:47.759 ERROR (SyncWorker_12) [custom_components.maxcube] 0.05505753599572927
2023-11-07 22:34:47.763 ERROR (SyncWorker_7) [custom_components.maxcube] 0.05810348503291607
2023-11-07 22:34:47.765 ERROR (SyncWorker_17) [custom_components.maxcube] 0.06012026104144752
2023-11-07 22:34:47.766 ERROR (SyncWorker_18) [custom_components.maxcube] 0.061832334962673485
2023-11-07 22:34:47.768 ERROR (SyncWorker_8) [custom_components.maxcube] 0.06330420903395861
2023-11-07 22:34:48.666 ERROR (SyncWorker_5) [custom_components.maxcube] 0.9611942319897935
2023-11-07 22:34:48.670 ERROR (SyncWorker_20) [custom_components.maxcube] 0.9655597979435697
2023-11-07 22:34:48.673 ERROR (SyncWorker_23) [custom_components.maxcube] 0.9690638720057905
2023-11-07 22:34:48.677 ERROR (SyncWorker_1) [custom_components.maxcube] 0.9721019889693707
2023-11-07 22:34:48.679 ERROR (SyncWorker_30) [custom_components.maxcube] 0.9749004970071837
2023-11-07 22:34:48.683 ERROR (SyncWorker_27) [custom_components.maxcube] 0.9784554590005428
2023-11-07 22:34:48.687 ERROR (SyncWorker_0) [custom_components.maxcube] 0.981909460038878
2023-11-07 22:34:48.689 ERROR (SyncWorker_16) [custom_components.maxcube] 0.9842177509563044
2023-11-07 22:34:48.692 ERROR (SyncWorker_6) [custom_components.maxcube] 0.987103387946263
2023-11-07 22:34:48.694 ERROR (SyncWorker_22) [custom_components.maxcube] 0.9896760639967397
2023-11-07 22:34:48.697 ERROR (SyncWorker_12) [custom_components.maxcube] 0.9922978329705074
2023-11-07 22:34:48.699 ERROR (SyncWorker_7) [custom_components.maxcube] 0.9944587550126016
2023-11-07 22:34:48.701 ERROR (SyncWorker_17) [custom_components.maxcube] 0.9963276239577681

2023-11-07 22:35:17.703 ERROR (SyncWorker_15) [custom_components.maxcube] Update total time: 0.08596968650817871
3

Firstly, very hard to see what is going on by only posting a smal subset of code. What is self.update_interval set to?

Where is this code in your integration and how is it being called? Have you set SCAN_INTERVAL constant?

time.monotonic() is not in seconds but fractions of a second. Use time.time() to get seconds if you self.update_interval is in seconds.

Depending on where your update function is, this can be being called repeatedly and so it could be hitting your debug line very frequently.

EDIT: see this part of the docs

4

thanks for the feedback
to me it’s clear that the integration is called only every 30 seconds (indeed, if i set a update_interval under 30, it updates every 30, otherwise it’s going up to 60)
I have no idea why, but this is how the system seems to work, so I concluded i have to rewrite the integration from scratch to have different timings, maybe this will be the occasion also to turn it to the async world
the fun part is that this is an official integration

5

damn every time i look at this i found out something new…
still need some help from who knows how to code integrations :smiley:

still talking about this integration:

The update function at the end of the init file manages the SCAN_INTERVAL that is configured.
However, this function is called by the platforms called by the setup function through the “load_platform” call.
Well, the problem is that the loaded platform do now use the scan_interval to work! this explains the starting behavior (the update of the base function only every 30 seconds)
Assuming this is not the right working mode, how should i tell the loaded platform to update every SCAN_INTERVAL seconds? is this possible?

Please allow me to start again sleeping at night instead of thinking to this code ahah
thanks!

6

Ok, the basic issue is that you are not telling HA to update on your scan interval. As the default for most entity domains in 30s, whatever you are setting your scan interval value to, is not applied.

To show this, in your binary_sensor.py file, add a constant like this.

SCAN_INTERVAL = timedelta(seconds=10)

You will now see the binary sensor will update every 10 seconds not 30 but your climate device will still update every 30s.

To be able to set a different update interval for each instance of your integration, there are numerous ways to do this but i think using the data update coordinator method is probably best as this will do a scheduled update from the max cube and then the entities will update from that. If you have each entity scheduling its update (like you currently have) you are calling updates from the maxcube device more frequently than needed, ie if you have 5 entities per instance, it is calling it 5 times per round of updates. Using a data update coordinator, you call update once.

The link to the developer docs i posted previously is for this. I dont think this is too much of a change to your existing code as you make your make your MaxCubeHandle class the update coordinator and then slightly amend your update routine in each entity type.