Pattern of sporadic timeouts

[syssi]

I'm trying to improve the reliability of miio requests. This is a common error in my home assistant log:

2018-02-10 03:52:59 ERROR (Thread-4) [miio.device] Got error when receiving: timed out
2018-02-10 03:52:59 WARNING (Thread-4) [miio.device] Retrying with incremented id, retries left: 3

I tried to reproduce the issue by "mirobo raw_command get_prop [...]". If I execute the command multiple times the timeout shows up occasionally. Next step was avoiding the device recovery:

# device.py
    def send(self, command: str, parameters: Any=None, retry_count=3, discover: bool=True) -> Any:
        if discover:
            self.do_discover()

# vacuum.py
    def raw_command(self, cmd, params):
        """Send a raw command to the robot."""
        self.send(cmd, params, 3, True)
        for x in range(0, 20000000):
            self.send(cmd, params, 3, False)

It's possible to query miio devices very fast. A Xiaomi Philips Bulb can handle 45req per second:

DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:37, id: 4163) << {'result': ['off', 1, 1, 0, 0], 'id': 4163}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4164}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:37, id: 4164) << {'result': ['off', 1, 1, 0, 0], 'id': 4164}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4165}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4165) << {'result': ['off', 1, 1, 0, 0], 'id': 4165}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4166}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4166) << {'result': ['off', 1, 1, 0, 0], 'id': 4166}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4167}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4167) << {'result': ['off', 1, 1, 0, 0], 'id': 4167}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4168}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4168) << {'result': ['off', 1, 1, 0, 0], 'id': 4168}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4169}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4169) << {'result': ['off', 1, 1, 0, 0], 'id': 4169}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4170}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4170) << {'result': ['off', 1, 1, 0, 0], 'id': 4170}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4171}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4171) << {'result': ['off', 1, 1, 0, 0], 'id': 4171}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4172}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4172) << {'result': ['off', 1, 1, 0, 0], 'id': 4172}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4173}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4173) << {'result': ['off', 1, 1, 0, 0], 'id': 4173}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4174}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4174) << {'result': ['off', 1, 1, 0, 0], 'id': 4174}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4175}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4175) << {'result': ['off', 1, 1, 0, 0], 'id': 4175}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4176}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4176) << {'result': ['off', 1, 1, 0, 0], 'id': 4176}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4177}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4177) << {'result': ['off', 1, 1, 0, 0], 'id': 4177}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4178}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4178) << {'result': ['off', 1, 1, 0, 0], 'id': 4178}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4179}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4179) << {'result': ['off', 1, 1, 0, 0], 'id': 4179}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4180}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4180) << {'result': ['off', 1, 1, 0, 0], 'id': 4180}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4181}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4181) << {'result': ['off', 1, 1, 0, 0], 'id': 4181}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4182}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4182) << {'result': ['off', 1, 1, 0, 0], 'id': 4182}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4183}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4183) << {'result': ['off', 1, 1, 0, 0], 'id': 4183}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4184}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4184) << {'result': ['off', 1, 1, 0, 0], 'id': 4184}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4185}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4185) << {'result': ['off', 1, 1, 0, 0], 'id': 4185}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4186}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4186) << {'result': ['off', 1, 1, 0, 0], 'id': 4186}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4187}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4187) << {'result': ['off', 1, 1, 0, 0], 'id': 4187}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4188}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4188) << {'result': ['off', 1, 1, 0, 0], 'id': 4188}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4189}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4189) << {'result': ['off', 1, 1, 0, 0], 'id': 4189}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4190}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4190) << {'result': ['off', 1, 1, 0, 0], 'id': 4190}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4191}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4191) << {'result': ['off', 1, 1, 0, 0], 'id': 4191}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4192}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4192) << {'result': ['off', 1, 1, 0, 0], 'id': 4192}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4193}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4193) << {'result': ['off', 1, 1, 0, 0], 'id': 4193}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4194}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4194) << {'result': ['off', 1, 1, 0, 0], 'id': 4194}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4195}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4195) << {'result': ['off', 1, 1, 0, 0], 'id': 4195}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4196}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4196) << {'result': ['off', 1, 1, 0, 0], 'id': 4196}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4197}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4197) << {'result': ['off', 1, 1, 0, 0], 'id': 4197}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4198}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4198) << {'result': ['off', 1, 1, 0, 0], 'id': 4198}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4199}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4199) << {'result': ['off', 1, 1, 0, 0], 'id': 4199}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4200}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4200) << {'result': ['off', 1, 1, 0, 0], 'id': 4200}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4201}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4201) << {'result': ['off', 1, 1, 0, 0], 'id': 4201}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4202}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4202) << {'result': ['off', 1, 1, 0, 0], 'id': 4202}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4203}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4203) << {'result': ['off', 1, 1, 0, 0], 'id': 4203}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4204}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4204) << {'result': ['off', 1, 1, 0, 0], 'id': 4204}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4205}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4205) << {'result': ['off', 1, 1, 0, 0], 'id': 4205}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4206}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4206) << {'result': ['off', 1, 1, 0, 0], 'id': 4206}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4207}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4207) << {'result': ['off', 1, 1, 0, 0], 'id': 4207}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4208}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4208) << {'result': ['off', 1, 1, 0, 0], 'id': 4208}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4209}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:38, id: 4209) << {'result': ['off', 1, 1, 0, 0], 'id': 4209}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4210}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:39, id: 4210) << {'result': ['off', 1, 1, 0, 0], 'id': 4210}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4211}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:01:39, id: 4211) << {'result': ['off', 1, 1, 0, 0], 'id': 4211}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4212}

Sometimes a request fails. The device will be/must recovered/discovered again:

DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:05:24, id: 4748) << {'result': ['off', 1, 1, 0, 0], 'id': 4748}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4749}
ERROR:miio.device:Got error when receiving: timed out
WARNING:miio.device:Retrying with incremented id, retries left: 3
DEBUG:miio.protocol:Unable to decrypt, returning raw bytes: b''
DEBUG:miio.device:Got a response: Container: 
    data = Container: 
        value =  (total 0)
        offset1 = 32
        offset2 = 32
        data =  (total 0)
        length = 0
    header = Container: 
        value = Container: 
            length = 32
            unknown = 0
            device_id = 039aa0b0 (total 8)
            ts = 1970-01-01 00:05:29
        offset1 = 0
        offset2 = 16
        data = !1\x00 \x00\x00\x00\x00\x03\x9a\xa0\xb0\x00\x00\x01I (total 16)
        length = 16
    checksum = \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00 (total 16)
DEBUG:miio.device:Discovered b'039aa0b0' with ts: 1970-01-01 00:05:29, token: b'00000000000000000000000000000000'
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4850}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:05:29, id: 4850) << {'result': ['off', 1, 1, 0, 0], 'id': 4850}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4851}
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:05:29, id: 4851) << {'result': ['off', 1, 1, 0, 0], 'id': 4851}

This could be the frequency of failed requests:

$ grep -B2 "Got error when receiving: timed out" test.log
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:05:24, id: 4748) << {'result': ['off', 1, 1, 0, 0], 'id': 4748}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 4749}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:06:59, id: 8852) << {'result': ['off', 1, 1, 0, 0], 'id': 8852}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 8853}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:07:22, id: 9805) << {'result': ['off', 1, 1, 0, 0], 'id': 9805}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 9806}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:07:29, id: 9998) << {'result': ['off', 1, 1, 0, 0], 'id': 9998}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 0}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:00:31, id: 1323) << {'result': ['off', 1, 1, 0, 0], 'id': 1323}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 1324}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:00:41, id: 1550) << {'result': ['off', 1, 1, 0, 0], 'id': 1550}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 1551}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:02:20, id: 5971) << {'result': ['off', 1, 1, 0, 0], 'id': 5971}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 5972}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:03:58, id: 9998) << {'result': ['off', 1, 1, 0, 0], 'id': 9998}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 0}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:02:12, id: 5742) << {'result': ['off', 1, 1, 0, 0], 'id': 5742}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 5743}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:02:57, id: 7544) << {'result': ['off', 1, 1, 0, 0], 'id': 7544}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 7545}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:192.168.132.37:54321 (ts: 1970-01-01 00:03:54, id: 9998) << {'result': ['off', 1, 1, 0, 0], 'id': 9998}
DEBUG:miio.device:192.168.132.37:54321 >>: {'params': ['power', 'bright', 'cct', 'snm', 'dv'], 'method': 'get_prop', 'id': 0}
ERROR:miio.device:Got error when receiving: timed out

[syssi]

Failing requests with a proper timestamp. Does the bulb crashs sometimes (ts: 1970-01-01 00:00:00)?

$ grep -B2 "Got error when receiving: timed out" test.log | grep -v 192.168.132.37
DEBUG:miio.device:REQ 17:11:45 (ts: 1970-01-01 00:21:55, id: 9998) << {'id': 9998, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:12:06 (ts: 1970-01-01 00:00:22, id: 831) << {'id': 831, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:12:19 (ts: 1970-01-01 00:00:35, id: 1283) << {'id': 1283, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:12:37 (ts: 1970-01-01 00:00:53, id: 1894) << {'id': 1894, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:12:57 (ts: 1970-01-01 00:01:13, id: 2701) << {'id': 2701, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:13:08 (ts: 1970-01-01 00:01:24, id: 3063) << {'id': 3063, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:13:20 (ts: 1970-01-01 00:01:35, id: 3452) << {'id': 3452, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:13:31 (ts: 1970-01-01 00:01:47, id: 3848) << {'id': 3848, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:13:49 (ts: 1970-01-01 00:02:04, id: 4525) << {'id': 4525, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:14:06 (ts: 1970-01-01 00:02:22, id: 5188) << {'id': 5188, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:14:24 (ts: 1970-01-01 00:02:39, id: 5829) << {'id': 5829, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:14:41 (ts: 1970-01-01 00:02:56, id: 6349) << {'id': 6349, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:14:58 (ts: 1970-01-01 00:03:14, id: 7008) << {'id': 7008, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:15:06 (ts: 1970-01-01 00:03:22, id: 7250) << {'id': 7250, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:16:11 (ts: 1970-01-01 00:04:26, id: 9998) << {'id': 9998, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:16:22 (ts: 1970-01-01 00:00:12, id: 354) << {'id': 354, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:16:36 (ts: 1970-01-01 00:00:26, id: 754) << {'id': 754, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:16:46 (ts: 1970-01-01 00:00:36, id: 1084) << {'id': 1084, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:16:59 (ts: 1970-01-01 00:00:48, id: 1528) << {'id': 1528, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:05 (ts: 1970-01-01 00:00:54, id: 1677) << {'id': 1677, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:11 (ts: 1970-01-01 00:01:00, id: 1812) << {'id': 1812, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:21 (ts: 1970-01-01 00:01:11, id: 2164) << {'id': 2164, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:29 (ts: 1970-01-01 00:01:18, id: 2386) << {'id': 2386, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:37 (ts: 1970-01-01 00:01:27, id: 2644) << {'id': 2644, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:45 (ts: 1970-01-01 00:01:34, id: 2829) << {'id': 2829, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:17:54 (ts: 1970-01-01 00:01:43, id: 3103) << {'id': 3103, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:18:11 (ts: 1970-01-01 00:02:00, id: 3781) << {'id': 3781, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:18:29 (ts: 1970-01-01 00:02:18, id: 4452) << {'id': 4452, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:18:36 (ts: 1970-01-01 00:02:25, id: 4626) << {'id': 4626, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:18:45 (ts: 1970-01-01 00:02:34, id: 4894) << {'id': 4894, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:18:53 (ts: 1970-01-01 00:02:42, id: 5124) << {'id': 5124, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:19:01 (ts: 1970-01-01 00:02:50, id: 5378) << {'id': 5378, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:19:09 (ts: 1970-01-01 00:02:58, id: 5608) << {'id': 5608, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:19:17 (ts: 1970-01-01 00:03:07, id: 5870) << {'id': 5870, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out
--
DEBUG:miio.device:REQ 17:19:27 (ts: 1970-01-01 00:03:17, id: 6199) << {'id': 6199, 'result': ['off', 1, 1, 0, 0]}
ERROR:miio.device:Got error when receiving: timed out

[syssi]

There is a magic id/seq >= 9999 which resets the timestamp: https://github.com/rytilahti/python-miio/blob/master/miio/device.py#L289

This causes a reboot of the philips bulb (the light turns off for a second).

[mouth4war]

I've seen the reboots happening in my bulbs too. So why does the timestamp need to be reset in the first place? 45/sec sounds like transitions should be possible too!

[syssi]

@mouth4war I'm trying to fix the issue here: #211

[syssi]

You are right: If we are able to improve the device handling (reduce the number of discoveries) transitions will be possible.

[wfriesen]

I'm also seeing these timeouts, using the Chuangmi IR Remote Controller. The connection seems to get "lost" after 5-10 minutes without sending a command.

Here is a log of a successful payload:

2018-02-26 06:59:50 DEBUG (Thread-17) [homeassistant.components.remote.xiaomi_miio] Sending payload: 'raw:Z6XHAL0BAACkAgAA0QIAAOYFAAARBgAABxEAAKgRAAD2EQAASBIAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABWMQExMQEBMQEBMQEBMTEBMQExMTExATExMQEBAQExAQExMTEBAQEBAQEBATExMTExgVcxATExAQExAQExAQExMQExAUExMTEBMTExAQEBATEBATExMQEBAQEBAgEBMTExMTEB'
2018-02-26 06:59:50 DEBUG (Thread-17) [miio.device] 192.168.86.60:54321 >>: {'method': 'miIO.ir_play', 'id': 3, 'params': {'code': 'Z6XHAL0BAACkAgAA0QIAAOYFAAARBgAABxEAAKgRAAD2EQAASBIAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABWMQExMQEBMQEBMQEBMTEBMQExMTExATExMQEBAQExAQExMTEBAQEBAQEBATExMTExgVcxATExAQExAQExAQExMQExAUExMTEBMTExAQEBATEBATExMQEBAQEBAgEBMTExMTEB', 'freq': 38400}}
2018-02-26 06:59:50 DEBUG (Thread-17) [miio.device] 192.168.86.60:54321 (ts: 1970-01-10 04:12:53, id: 3) << {'result': 0, 'id': 3}

and then some time later a failed one:

2018-02-26 07:07:48 DEBUG (Thread-19) [miio.device] 192.168.86.60:54321 >>: {'method': 'miIO.ir_play', 'id': 4, 'params': {'code': 'Z6XHAL0BAACkAgAA0QIAAOYFAAARBgAABxEAAKgRAAD2EQAASBIAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABWMQExMQEBMQEBMQEBMTEBMQExMTExATExMQEBAQExAQExMTEBAQEBAQEBATExMTExgVcxATExAQExAQExAQExMQExAUExMTEBMTExAQEBATEBATExMQEBAQEBAgEBMTExMTEB', 'freq': 38400}}
2018-02-26 07:07:53 ERROR (Thread-19) [miio.device] Got error when receiving: timed out
2018-02-26 07:07:53 WARNING (Thread-19) [miio.device] Retrying with incremented id, retries left: 3
2018-02-26 07:07:53 DEBUG (Thread-19) [miio.protocol] Unable to decrypt, returning raw bytes: b''
2018-02-26 07:07:53 DEBUG (Thread-19) [miio.device] Got a response: Container:
    data = Container:
        offset2 = 32
        offset1 = 32
        data =  (total 0)
        value =  (total 0)
        length = 0
    header = Container:
        offset2 = 16
        offset1 = 0
        data = !1\x00 \x00\x00\x00\x00\x03\xef\x95q\x00\x0c\x1a\xa8 (total 16)
        value = Container:
            length = 32
            unknown = 0
            device_id = \x03\xef\x95q (total 4)
            ts = 1970-01-10 04:20:56
        length = 16
    checksum = \xaca\x83\xd5\xb8\x07\x143? #\x93\x06\x19\xba\xd3 (total 16)
2018-02-26 07:07:53 DEBUG (Thread-19) [miio.device] Discovered 03ef9571 with ts: 1970-01-10 04:20:56, token: b'00000000000000000000000000000000'
2018-02-26 07:07:53 DEBUG (Thread-19) [miio.device] 192.168.86.60:54321 >>: {'method': 'miIO.ir_play', 'id': 105, 'params': {'code': 'Z6XHAL0BAACkAgAA0QIAAOYFAAARBgAABxEAAKgRAAD2EQAASBIAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABWMQExMQEBMQEBMQEBMTEBMQExMTExATExMQEBAQExAQExMTEBAQEBAQEBATExMTExgVcxATExAQExAQExAQExMQExAUExMTEBMTExAQEBATEBATExMQEBAQEBAgEBMTExMTEB', 'freq': 38400}}
2018-02-26 07:07:53 DEBUG (Thread-19) [miio.device] 192.168.86.60:54321 (ts: 1970-01-10 04:20:57, id: 105) << {'result': 0, 'id': 105}

[syssi]

@wfriesen Do you own a rooted android device and can you provide the mihome plugin apk of the chuangmi ir controller? If there is a "get_prop" command available we could contact the device periodically without sending infrared commands. Another solution is discovering the device always in front of every infrared command.

[mouth4war]

@syssi Just curious about the transitions. Do they look possible now that the bug has been fixed? Or has it not been fixed by that id = 9999 fix and the lazy discover disable

[syssi]

Sorry about this feature. It's not on my roadmap because it's so intense/hard to implement.

[mouth4war]

Isn't there another platform we can use as template? Let me see if I can find something to start it off. Thanks for your amazing work on miio, as always 🙂

…

On Sat 11 Aug, 2018, 11:42 PM Sebastian Muszynski, ***@***.***> wrote: Sorry about this feature. It's not on my roadmap because it's so intense/hard to implement. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#210 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/Ac4Xc7lRZJsE4-kj2jx5I_5xnVThGWYBks5uPx6egaJpZM4SA_op> .