Query params lost when retrying a request on token expired

[jasonacox]

Originally posted by @ndlarge in #452

Hi all,
First of all, huge thanks to @jasonacox and @uzlonewolf for this wonderful piece of software!

What am I trying to achieve? Transfer voltage, power, energy consumed etc measurements from a Tuya-compliant WIFI power meter into an influxdb database for further visualization and analysis.

How am I going about it? On a Raspberry Pi, every 10 minutes I run a script that first checks for the latest measurement timestamp already in the influxdb, then calls getdevicelog() with appropriate start and end times. As my power meter is rather talkative, 10 minutes worth of logs is about 1000 records, so it takes ~10 "fetches" to get all the data.

What is my problem? Everything works like a charm in general, but every now and then I see 5-10 minute gaps in my measurement sequences. I checked the Tuya cloud online and the missing data is there, so Tuya is not to blame here.
I turned on debugging and tinituya started logging every single request for me.
And here's what I see:

DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/token?grant_type=1 HTTP/1.1" 200 232
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/token?grant_type=1 HEADERS={'secret': 'xxx, 'client_id': xxx', 'sign': 'xxx', 't': '1706537103276', 'sign_method': 'HMAC-SHA256', 'mode': 'cors'} response code=200 text={"result":{"access_token":"xxx","expire_time":1,"refresh_token":"xxx","uid":"xxx"},"success":true,"t":1706537103606,"tid":"xxx"} token=None
DEBUG:tinytuya.core:server_time_offset: 0
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/devices/xxx/logs?end_time=1706537103649&query_type=1&size=100&start_time=1706536496790&type=7 HTTP/1.1" 200 None
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/devices/xxx/logs?end_time=1706537103649&query_type=1&size=100&start_time=1706536496790&type=7 HEADERS={'client_id': 'xxx', 'sign': 'xxx', 't': '1706537103651', 'sign_method': 'HMAC-SHA256', 'mode': 'cors', 'access_token': 'xxx'} response code=200 text={"result":{"current_row_key":"NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAzMTc2NzI4MTlfN18xMzI=","device_id":"xxx","has_next":true,"logs":[{"code":"Current","event_from":"1","event_id":7,"event_time":1706537102988,"status":"1","value":"4598"},{"code":"CurrentB","event_from":"1","event_id":7,"event_time":1706537102963,"status":"1","value":"1763"},
...
{"code":"PowerFactorC","event_from":"1","event_id":7,"event_time":1706537037173,"status":"1","value":"58"},{"code":"ActivePower","event_from":"1","event_id":7,"event_time":1706537035214,"status":"1","value":"706"},{"code":"ActivePowerC","event_from":"1","event_id":7,"event_time":1706537035200,"status":"1","value":"187"}],"next_row_key":"NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAzMTc3NDA2MjBfN18xMTM="},"success":true,"t":1706537103971,"tid":"xxx"} token=xxx
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/devices/xxx/logs?end_time=1706537103649&query_type=1&size=100&start_row_key=NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAzMTc3NDA2MjBfN18xMTM%3D&start_time=1706536496790&type=7 HTTP/1.1" 200 110
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/devices/xxx/logs?end_time=1706537103649&query_type=1&size=100&start_row_key=NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAzMTc3NDA2MjBfN18xMTM%3D&start_time=1706536496790&type=7 HEADERS={'client_id': 'xxx', 'sign': 'xxx', 't': '1706537104063', 'sign_method': 'HMAC-SHA256', 'mode': 'cors', 'access_token': 'xxx'} response code=200 text={"code":1010,"msg":"token invalid","success":false,"t":1706537104337,"tid":"xxx"} token=ceb37b5875dfa7b949ddf199142a0278
DEBUG:tinytuya.core:Token Expired - Try to renew
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/token?grant_type=1 HTTP/1.1" 200 235
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/token?grant_type=1 HEADERS={'secret': 'xxx', 'client_id': 'xxx', 'sign': 'xxx', 't': '1706537104378', 'sign_method': 'HMAC-SHA256', 'mode': 'cors'} response code=200 text={"result":{"access_token":"xxx","expire_time":7200,"refresh_token":"xxx","uid":"xxx"},"success":true,"t":1706537104669,"tid":"xxx"} token=None
DEBUG:tinytuya.core:server_time_offset: 0
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/devices/xxx/logs HTTP/1.1" 200 117
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/devices/xxx/logs HEADERS={'client_id': 'xxx', 'sign': 'xxx', 't': '1706537104711', 'sign_method': 'HMAC-SHA256', 'mode': 'cors', 'access_token': 'xxx'} response code=200 text={"code":40000303,"msg":"Parameter error!","success":false,"t":1706537105016,"tid":"xxx"} token=xxx

As you can see, on the first "fetch" a properly formed URL with all the necessary query params is passed and a perfectly formed response is received.
The second perfectly formed fetch with proper start_row_key is rejected with "1010 token invalid" response (why? that is another question).
And then on retry an URL with no query parameters at all is passed (https://openapi.tuyaeu.com/v1.0/devices/xxx/logs) and obviously the response is "40000303 Parameter error!". And as there's no error handling visible, the function simply stops here and returns what it has (one fetch out of ten).

When I look into the code for _tuyaplatform(), here's what I see:

    def _tuyaplatform(self, uri, action='GET', post=None, ver='v1.0', recursive=False, query=None, content_type=None):
 ...
        # Check to see if token is expired
        if "token invalid" in response.text:
            if recursive is True:
                log.debug("Failed 2nd attempt to renew token - Aborting")
                return None
            log.debug("Token Expired - Try to renew")
            self._gettoken()
            if not self.token:
                log.debug("Failed to renew token")
                return None
            else:
                return self._tuyaplatform(uri, action, post, ver, True)

But uri variable is just pure path with no query parameters, you probably need to pass query as well to the recursive call to the function? Like this:

              return self._tuyaplatform(uri, action, post, ver, True, query)

Would appreciate any feedback.

[jasonacox]

I believe we actually want to pass the entire context to the recursion:

              return self._tuyaplatform(uri, action, post, ver, True, query, content_type)

[ndlarge]

Thank you for confirming the bug and opening an issue.
I did some further experimenting with changed code (passing the query to the recursion) and here's what happens:

DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/devices/xxx/logs?end_time=1706594703065&query_type=1&size=100&start_row_key=NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAyNjAyMTIyMDlfN18xMDI%3D&start_time=1706594093089&type=7 HTTP/1.1" 200 110
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/devices/xxx/logs?end_time=1706594703065&query_type=1&size=100&start_row_key=NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAyNjAyMTIyMDlfN18xMDI%3D&start_time=1706594093089&type=7 HEADERS={'client_id': 'xxx', 'sign': 'F698D11A8DD38D20B8ED2E76517EB79E48F533B3B462611FC99C3B299CC500BD', 't': '1706594703861', 'sign_method': 'HMAC-SHA256', 'mode': 'cors', 'access_token': '09713a250341a6ae236a81017d4ec096'} response code=200 text={"code":1010,"msg":"token invalid","success":false,"t":1706594704137,"tid":"82a8bc84bf3511eea28be2dee5a60296"} token=09713a250341a6ae236a81017d4ec096
DEBUG:tinytuya.core:Token Expired - Try to renew
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/token?grant_type=1 HTTP/1.1" 200 235
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/token?grant_type=1 HEADERS={'secret': 'xxx', 'client_id': 'xxx', 'sign': '0EF6317217EE3BA5B47DA7D463405A95B3C225CCCD55CE45249D5CC6BA8FF49B', 't': '1706594704180', 'sign_method': 'HMAC-SHA256', 'mode': 'cors'} response code=200 text={"result":{"access_token":"3eac7c4bfd85de6e42825b10db346e38","expire_time":7200,"refresh_token":"ab8aecdf89cdbe5af1bba4b5afd4abf3","uid":"xxx"},"success":true,"t":1706594704467,"tid":"82d8eeebbf3511eea28be2dee5a60296"} token=None
DEBUG:tinytuya.core:server_time_offset: 0
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): openapi.tuyaeu.com:443
DEBUG:urllib3.connectionpool:https://openapi.tuyaeu.com:443 "GET /v1.0/devices/xxx/logs?end_time=1706594703065&query_type=1&size=100&start_row_key=NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAyNjAyMTIyMDlfN18xMDI%3D&start_time=1706594093089&type=7 HTTP/1.1" 200 109
DEBUG:tinytuya.core:GET: URL=https://openapi.tuyaeu.com/v1.0/devices/xxx/logs?end_time=1706594703065&query_type=1&size=100&start_row_key=NjFmMDhiMDRia3ppYmFhYjFlY2EzNjJmOTE4OWZiXzkyMjMzNzAzMzAyNjAyMTIyMDlfN18xMDI%3D&start_time=1706594093089&type=7 HEADERS={'client_id': 'xxx', 'sign': 'A8621F491CB9743BAAA096439D459117DB0AC4E8F2CBFE38564E1B3D246B7650', 't': '1706594704512', 'sign_method': 'HMAC-SHA256', 'mode': 'cors', 'access_token': '3eac7c4bfd85de6e42825b10db346e38'} response code=200 text={"code":1004,"msg":"sign invalid","success":false,"t":1706594704792,"tid":"830cd60abf3511ee8eb5fe6a6f85d0cd"} token=3eac7c4bfd85de6e42825b10db346e38

I see that the retry request is now formed properly with all the query params (at first sight) but still it returns a new error now: 1004 sign invalid.
If debugging the first error was kind of obvious (the URL clearly wrong), here I must admit that I'm out of my depth with all this tokens and signing stuff, so I'm afraid someone more knowledgeable will have to look at this.
In my log excerpt I have replaced any potentially confidential stuff with xxx, but if I replaced anything that you need to debug please let me know.

[jasonacox]

Thanks @ndlarge - Does it ever start working again? If so, do you see anything different in the logs when it starts working?

[ndlarge]

Oh yes, on the next cron run it works as if nothing's happened, gets a new token, most of the time it succeeds to get all the fetches intact but every few hours it gets this 'token invalid' error on a random fetch, then 'sign invalid' on retry and then, as it only specifically checks for 'token invalid' to retry it just stops and returns the current response with the error. And as getdevicelog() does not do any error checking at all and just checks for has_next to loop further, it stops and returns whatever part of the full log it has.
Now if only the tuya api call could be forced to return log entries in ascending time order then on the next run my script would start from the last timestamp available and cover the gap but unfortunately it returns them in descending order starting from the very last, so the first fetch contains chronologically last entries creating the gap that cannot be covered by my simple algorithm.

[jasonacox]

Hum... It may be good to change the failure logic to raise an exception then have the script start over. If that fixes it, it isn't some odd Tuya API rate limit issue, but something wrong with the token renewal logic. I haven't been able to replicate it but I'm likely not running it long enough.

            if not self.token:
                log.debug("Failed to renew token")
                raise ValueError("Failed to renew token") 

I may have time to look at it this weekend.

[ndlarge]

It happens randomly to me and so far I have not been able to find any system to it. I thought it might be because I was requesting too many fetches in too little time. Added time.sleep(1) between fetches, the errors did not go away. Then I thought it might be because I was requesting token renewals too often (every 10 minutes). I started storing the token in a file and passing the old token to Cloud(). Now the script doesn't request a token on every run but still have the errors now and then.
The key question of course is why Tuya cloud would reject a perfectly good brand new token as "expired". But for the moment I guess the only thing we could realistically do on this side is improve error handling and just retry properly when it happens. I'm afraid my python skills are not quite up to the task (a week ago I did not know what it is :)