From caaf323e67f1968151d0022a470ee24da12688ca Mon Sep 17 00:00:00 2001 From: uzlonewolf Date: Tue, 14 Mar 2023 01:44:58 -0700 Subject: [PATCH 1/2] Rework logging --- tinytuya/BulbDevice.py | 10 +- tinytuya/Cloud.py | 31 ++-- tinytuya/Contrib/IRRemoteControlDevice.py | 38 ++-- tinytuya/Contrib/ThermostatDevice.py | 23 +-- tinytuya/__main__.py | 17 +- tinytuya/core.py | 207 ++++++++++++---------- tinytuya/scanner.py | 6 +- 7 files changed, 182 insertions(+), 150 deletions(-) diff --git a/tinytuya/BulbDevice.py b/tinytuya/BulbDevice.py index fd435d4b..54496f44 100644 --- a/tinytuya/BulbDevice.py +++ b/tinytuya/BulbDevice.py @@ -242,7 +242,7 @@ def set_version(self, version): # pylint: disable=W0621 else: # response has no dps self.bulb_type = "B" - log.debug("bulb type set to %s", self.bulb_type) + self.log.debug("bulb type set to %s", self.bulb_type) def turn_on(self, switch=0, nowait=False): """Turn the device on""" @@ -312,7 +312,7 @@ def set_colour(self, r, g, b, nowait=False): nowait(bool): True to send without waiting for response. """ if not self.has_colour: - log.debug("set_colour: Device does not appear to support color.") + self.log.debug("set_colour: Device does not appear to support color.") # return error_json(ERR_FUNCTION, "set_colour: Device does not support color.") if not 0 <= r <= 255: return error_json( @@ -353,7 +353,7 @@ def set_hsv(self, h, s, v, nowait=False): nowait(bool): True to send without waiting for response. """ if not self.has_colour: - log.debug("set_hsv: Device does not appear to support color.") + self.log.debug("set_hsv: Device does not appear to support color.") # return error_json(ERR_FUNCTION, "set_hsv: Device does not support color.") if not 0 <= h <= 1.0: return error_json( @@ -519,7 +519,7 @@ def set_brightness(self, brightness, nowait=False): if state["mode"] == "white": # for white mode use DPS for brightness if not self.has_brightness: - log.debug("set_brightness: Device does not appear to support brightness.") + self.log.debug("set_brightness: Device does not appear to support brightness.") # return error_json(ERR_FUNCTION, "set_brightness: Device does not support brightness.") payload = self.generate_payload( CONTROL, {self.DPS_INDEX_BRIGHTNESS[self.bulb_type]: brightness} @@ -569,7 +569,7 @@ def set_colourtemp(self, colourtemp, nowait=False): nowait(bool): True to send without waiting for response. """ if not self.has_colourtemp: - log.debug("set_colourtemp: Device does not appear to support colortemp.") + self.log.debug("set_colourtemp: Device does not appear to support colortemp.") # return error_json(ERR_FUNCTION, "set_colourtemp: Device does not support colortemp.") if self.bulb_type == "A" and not 0 <= colourtemp <= 255: return error_json( diff --git a/tinytuya/Cloud.py b/tinytuya/Cloud.py index 87e5d465..a3ab6517 100644 --- a/tinytuya/Cloud.py +++ b/tinytuya/Cloud.py @@ -84,6 +84,7 @@ def __init__(self, apiRegion=None, apiKey=None, apiSecret=None, apiDeviceID=None self.new_sign_algorithm = new_sign_algorithm self.server_time_offset = 0 self.use_old_device_list = False + self.log = log.getChild('Cloud') if (not apiKey) or (not apiSecret): try: @@ -205,11 +206,11 @@ def _tuyaplatform(self, uri, action='GET', post=None, ver='v1.0', recursive=Fals # Send Request to Cloud and Get Response if action == 'GET': response = requests.get(url, headers=headers) - log.debug( + self.log.debug( "GET: URL=%s HEADERS=%s response code=%d text=%s token=%s", url, headers, response.status_code, response.text, self.token ) else: - log.debug( + self.log.debug( "POST: URL=%s HEADERS=%s DATA=%s", url, headers, body, ) response = requests.post(url, headers=headers, data=body) @@ -217,12 +218,12 @@ def _tuyaplatform(self, uri, action='GET', post=None, ver='v1.0', recursive=Fals # 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") + self.log.debug("Failed 2nd attempt to renew token - Aborting") return None - log.debug("Token Expired - Try to renew") + self.log.debug("Token Expired - Try to renew") self._gettoken() if not self.token: - log.debug("Failed to renew token") + self.log.debug("Failed to renew token") return None else: return self._tuyaplatform(uri, action, post, ver, True) @@ -258,7 +259,7 @@ def _gettoken(self): # round it to 2 minutes to try and factor out any processing delays self.server_time_offset = round( ((response_dict['t'] / 1000.0) - time.time()) / 120 ) self.server_time_offset *= 120 - log.debug("server_time_offset: %r", self.server_time_offset) + self.log.debug("server_time_offset: %r", self.server_time_offset) self.token = response_dict['result']['access_token'] return self.token @@ -280,7 +281,7 @@ def _getuid(self, deviceid=None): response_dict['code'] = -1 if 'msg' not in response_dict: response_dict['msg'] = 'Unknown Error' - log.debug( + self.log.debug( "Error from Tuya Cloud: %r", response_dict['msg'], ) return error_json( @@ -322,10 +323,10 @@ def _get_all_devices(self): has_more = False if type(result) == dict: - log.debug( 'Cloud response:' ) - log.debug( json.dumps( result, indent=2 ) ) + self.log.debug( 'Cloud response:' ) + self.log.debug( json.dumps( result, indent=2 ) ) else: - log.debug( 'Cloud response: %r', result ) + self.log.debug( 'Cloud response: %r', result ) # format it the same as before, basically just moves result->devices into result for i in result: @@ -381,7 +382,7 @@ def _get_hw_addresses( self, maclist, devices ): # returns id, mac, uuid (and sn if available) uri = 'devices/factory-infos?device_ids=%s' % (",".join(devices[:50])) result = self._tuyaplatform(uri) - log.debug( json.dumps( result, indent=2 ) ) + self.log.debug( json.dumps( result, indent=2 ) ) if 'result' in result: for dev in result['result']: if 'id' in dev: @@ -438,7 +439,7 @@ def _getdevice(self, param='status', deviceid=None): response_dict = self._tuyaplatform(uri) if not response_dict['success']: - log.debug( + self.log.debug( "Error from Tuya Cloud: %r", response_dict['msg'], ) return response_dict @@ -476,7 +477,7 @@ def getdps(self, deviceid=None): response_dict = self._tuyaplatform(uri, ver='v1.1') if not response_dict['success']: - log.debug( + self.log.debug( "Error from Tuya Cloud: %r", response_dict['msg'], ) return response_dict @@ -496,7 +497,7 @@ def sendcommand(self, deviceid=None, commands=None): response_dict = self._tuyaplatform(uri,action='POST',post=commands) if not response_dict['success']: - log.debug( + self.log.debug( "Error from Tuya Cloud: %r", response_dict['msg'], ) return response_dict @@ -516,7 +517,7 @@ def getconnectstatus(self, deviceid=None): response_dict = self._tuyaplatform(uri, ver='v1.0') if not response_dict['success']: - log.debug("Error from Tuya Cloud: %r", response_dict['msg']) + self.log.debug("Error from Tuya Cloud: %r", response_dict['msg']) return(response_dict["result"]["online"]) def getdevicelog(self, deviceid=None, start=None, end=None, evtype=None, size=0, max_fetches=50, start_row_key=None, params=None): diff --git a/tinytuya/Contrib/IRRemoteControlDevice.py b/tinytuya/Contrib/IRRemoteControlDevice.py index 12a27d2f..4ce607b0 100644 --- a/tinytuya/Contrib/IRRemoteControlDevice.py +++ b/tinytuya/Contrib/IRRemoteControlDevice.py @@ -118,6 +118,8 @@ from ..core import Device, log, CONTROL +classlog = log.getChild('IRRemoteControlDevice') + class IRRemoteControlDevice(Device): CMD_SEND_KEY_CODE = "send_ir" # Command to start sending a key DP_SEND_IR = "201" # ir_send, send and report (read-write) @@ -188,17 +190,17 @@ def detect_control_type( self ): if status and 'dps' in status: # original devices using DPS 201/202 if self.DP_SEND_IR in status['dps']: - log.debug( 'Detected control type 1' ) + self.log.debug( 'Detected control type 1' ) self.control_type = 1 break # newer devices using DPS 1-13 elif self.DP_MODE in status['dps']: - log.debug( 'Detected control type 2' ) + self.log.debug( 'Detected control type 2' ) self.control_type = 2 break status = self._send_receive(None) if not self.control_type: - log.warning( 'Detect control type failed! control_type= must be set manually' ) + self.log.warning( 'Detect control type failed! control_type= must be set manually' ) elif status: # try and make sure no data is waiting to be read status = self._send_receive(None) @@ -245,7 +247,7 @@ def study_end( self ): self.send_command( 'study_exit' ) def receive_button( self, timeout=30 ): - log.debug("Receiving button") + self.log.debug("Receiving button") # Exit study mode in case it's enabled self.study_end() # Enable study mode @@ -264,14 +266,14 @@ def receive_button( self, timeout=30 ): if timeo < 1: timeo = 1 self.set_socketTimeout(timeo) - log.debug("Waiting for button...") + self.log.debug("Waiting for button...") response = self._send_receive(None) if response == None: # Nothing received - log.debug("Timeout") + self.log.debug("Timeout") elif type(response) != dict or "dps" not in response: # Some unexpected result - log.debug("Unexpected response: %r", response) + self.log.debug("Unexpected response: %r", response) response_code = response # Some error message? Pass it. break elif self.DP_LEARNED_ID in response["dps"]: @@ -285,7 +287,7 @@ def receive_button( self, timeout=30 ): break else: # Unknown DPS - log.debug("Unknown DPS in response: %r", response) + self.log.debug("Unknown DPS in response: %r", response) response_code = response # Pass it if we do not get a response we like # try again finally: @@ -301,12 +303,12 @@ def receive_button( self, timeout=30 ): return response_code def send_button( self, base64_code ): - log.debug( 'Sending Learned Button: ' + base64_code) + self.log.debug( 'Sending Learned Button: ' + base64_code) self.print_pulses( base64_code ) return self.send_command( 'send', {'base64_code': base64_code} ) def send_key( self, head, key ): - log.debug( 'Sending Key: %r / %r', head, key ) + self.log.debug( 'Sending Key: %r / %r', head, key ) return self.send_command( 'send', { 'head': head, 'key': key } ) @staticmethod @@ -346,8 +348,8 @@ def print_pulses( base64_code, use_log=None ): else: pulses = IRRemoteControlDevice.base64_to_pulses(base64_code) message = "Pulses and gaps (microseconds): " + ' '.join([f'{"p" if i % 2 == 0 else "g"}{pulses[i]}' for i in range(len(pulses))]) - if log.getEffectiveLevel() <= logging.DEBUG: - log.debug( message ) + if classlog.getEffectiveLevel() <= logging.DEBUG: + classlog.debug( message ) return message @staticmethod @@ -496,7 +498,7 @@ def head_key_to_pulses( head, key ): @staticmethod def pulses_to_head_key( pulses, fudge=0.1, freq=38 ): - mylog = log.getChild( 'pulses_to_head_key' ) + mylog = classlog.getChild( 'pulses_to_head_key' ) if len(pulses) < 2: return None @@ -1070,10 +1072,10 @@ def width_encoded_to_pulses( uint32, start_mark=9000, start_space=4500, pulse_on def pulses_to_width_encoded( pulses, start_mark=None, start_space=None, pulse_threshold=None, space_threshold=None ): ret = [ ] if len(pulses) < 68: - log.debug('Length of pulses must be a multiple of 68! (2 start + 64 data + 2 trailing)') + classlog.debug('Length of pulses must be a multiple of 68! (2 start + 64 data + 2 trailing)') return ret if (pulse_threshold is None) and (space_threshold is None): - log.debug('"pulse_threshold" and/or "space_threshold" must be supplied!') + classlog.debug('"pulse_threshold" and/or "space_threshold" must be supplied!') return ret if start_mark is not None: @@ -1083,11 +1085,11 @@ def pulses_to_width_encoded( pulses, start_mark=None, start_space=None, pulse_th while( len(pulses) >= 68 ): if start_mark is not None: if pulses[0] < (start_mark * 0.75) or pulses[0] > (start_mark * 1.25): - log.debug('The start mark is not the correct length') + classlog.debug('The start mark is not the correct length') return ret if start_space is not None: if pulses[1] < (start_space * 0.75) or pulses[1] > (start_space * 1.25): - log.debug('The start space is not the correct length') + classlog.debug('The start space is not the correct length') return ret pulses = pulses[2:] @@ -1109,7 +1111,7 @@ def pulses_to_width_encoded( pulses, start_mark=None, start_space=None, pulse_th if (pulse_match is not None) and (space_match is not None): if pulse_match != space_match: - log.debug('Both "pulse_threshold" and "space_threshold" are supplied and bit %d conflicts with both!' % i) + classlog.debug('Both "pulse_threshold" and "space_threshold" are supplied and bit %d conflicts with both!' % i) return ret res = space_match elif pulse_match is None: diff --git a/tinytuya/Contrib/ThermostatDevice.py b/tinytuya/Contrib/ThermostatDevice.py index 0e3940a0..ac3306e7 100644 --- a/tinytuya/Contrib/ThermostatDevice.py +++ b/tinytuya/Contrib/ThermostatDevice.py @@ -215,7 +215,7 @@ import struct import base64 -from ..core import Device, log, HEART_BEAT, DP_QUERY, CONTROL +from ..core import Device, HEART_BEAT, DP_QUERY, CONTROL class ThermostatDevice(Device): """ @@ -379,7 +379,7 @@ def parseValue( self, key, val ): break if not dps: - log.warn( 'Requested key %r not found!' % key ) + self.log.warn( 'Requested key %r not found!' % key ) return False ddata = self.dps_data[dps] @@ -392,7 +392,7 @@ def parseValue( self, key, val ): if 'enum' in ddata: if val not in ddata['enum']: - log.warn( 'Requested value %r for key %r/%r not in enum list %r ! Setting anyway...' % (val, dps, key, ddata['enum']) ) + self.log.warn( 'Requested value %r for key %r/%r not in enum list %r ! Setting anyway...' % (val, dps, key, ddata['enum']) ) if 'base64' in ddata: val = base64.b64encode( val ).decode('ascii') @@ -455,7 +455,7 @@ def _process_response( self, data ): for k in self.dps_data: if k in data['dps'] and 'high_resolution' in self.dps_data[k]: self.high_resolution = self.dps_data[k]['high_resolution'] - log.info('ThermostatDevice: high-resolution is now %r' % self.high_resolution) + self.log.info('ThermostatDevice: high-resolution is now %r' % self.high_resolution) break for k in data['dps']: @@ -491,7 +491,7 @@ def _process_response( self, data ): if 'enum' in self.dps_data[k]: if val not in self.dps_data[k]['enum']: - log.warn( 'Received value %r for key %r/%r not in enum list %r ! Perhaps enum list needs to be updated?' % (val, k, name, self.dps_data[k]['enum']) ) + self.log.warn( 'Received value %r for key %r/%r not in enum list %r ! Perhaps enum list needs to be updated?' % (val, k, name, self.dps_data[k]['enum']) ) if 'alt' in self.dps_data[k]: data['changed'].append( self.dps_data[k]['alt'] ) @@ -616,7 +616,8 @@ def __bytes__( self ): coolto -= coolmod if coolmod >= 25: coolto += 50 - log.info( 'CF is: %r %r %r cool: %r %r %r', cf, self.heatto, heatto / 100, self.coolto, coolto / 100, self.time ) + # FIXME: make a logger available here + #log.info( 'CF is: %r %r %r cool: %r %r %r', cf, self.heatto, heatto / 100, self.coolto, coolto / 100, self.time ) # if self.time is a string then it needs to be in 24-hour HH:MM[:SS] format! if isinstance( self.time, str ): @@ -773,7 +774,7 @@ def setPeriod( self, day, period, **kwargs ): if self.day_data[day][period][0] > 3 and self.day_data[day][period][1] < 1440: if self.day_data[day][period][0] != 0xFF: - log.warn('Selected participation flag is out of range, setting to %d', period) + self.parent.log.warn('Selected participation flag is out of range, setting to %d', period) self.day_data[day][period][0] = period & 3 def setCF( self, cf ): @@ -783,7 +784,7 @@ def update( self, data ): self.have_data = False if len(data) % 7 != 0: - log.warn( 'Schedule data is in an unknown format, ignoring schedule' ) + self.parent.log.warn( 'Schedule data is in an unknown format, ignoring schedule' ) return False cf = self.parent.getCF( self.cf ) @@ -793,7 +794,7 @@ def update( self, data ): day = data[offset:offset+daylen] if len(day) % 7 != 0: - log.warn( 'Schedule day data for day %d is in an unknown format, ignoring schedule' % dow ) + self.parent.log.warn( 'Schedule day data for day %d is in an unknown format, ignoring schedule' % dow ) return False periods = len(day) / 7 @@ -804,7 +805,7 @@ def update( self, data ): perioddata = day[dayoffset:dayoffset+7] if len(perioddata) != 7: - log.warn( 'Schedule period data for period %d on day %d is in an unknown format, ignoring schedule' % (period, dow) ) + self.parent.log.warn( 'Schedule period data for period %d on day %d is in an unknown format, ignoring schedule' % (period, dow) ) return False newdata = struct.unpack( '>BHhh', perioddata ) @@ -1143,6 +1144,6 @@ def __bytes__( self ): try: return struct.pack( self.struct_format, *(getattr(self, k) for k in self.keys) ) except: - log.exception( 'Error while attempting to pack %s with %r/%r/%r/%r/%r/%r/%r/%r/%r/%r/%r/%r', self.struct_format, *(getattr(self, k) for k in self.keys) ) + self.parent_sensorlist.parent_device.log.exception( 'Error while attempting to pack %s with %r/%r/%r/%r/%r/%r/%r/%r/%r/%r/%r/%r', self.struct_format, *(getattr(self, k) for k in self.keys) ) raise diff --git a/tinytuya/__main__.py b/tinytuya/__main__.py index 62cba9b6..4dd53fdd 100644 --- a/tinytuya/__main__.py +++ b/tinytuya/__main__.py @@ -16,8 +16,6 @@ # Modules import sys import tinytuya -from . import wizard -from . import scanner retries = None state = 0 @@ -27,6 +25,7 @@ last_force = False broadcast_listen = True assume_yes = False +debug = False for i in sys.argv: if i==sys.argv[0]: @@ -52,7 +51,7 @@ elif i.lower() == "-yes" or i.lower() == "-y": assume_yes = True elif i.lower() == "-debug" or i.lower() == "-d": - tinytuya.set_debug(True) + debug = True elif last_force and len(i) > 6: this_force = True force_list.append( i ) @@ -67,6 +66,18 @@ if force and len(force_list) > 0: force = force_list +tinytuya.set_debug(debug, color) +#if debug: +# if color: +# logging.basicConfig( format="\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[39;2m%(message)s\x1b[0m", level=logging.DEBUG ) +# else: +# logging.basicConfig( level=logging.DEBUG ) + +if state == 1: + from . import wizard +else: + from . import scanner + # State 0 = Run Network Scan if state == 0: scanner.scan(scantime=retries, color=color, forcescan=force, discover=broadcast_listen, assume_yes=assume_yes) diff --git a/tinytuya/core.py b/tinytuya/core.py index 585886a5..43969c7a 100644 --- a/tinytuya/core.py +++ b/tinytuya/core.py @@ -67,7 +67,7 @@ import struct import sys import time -from colorama import init +from colorama import init, Fore, Back, Style # Backward compatibility for python2 try: @@ -90,9 +90,9 @@ version = __version__ = "%d.%d.%d" % version_tuple __author__ = "jasonacox" -log = logging.getLogger(__name__) -# Uncomment the following to set debug mode or call set_debug() -# logging.basicConfig(level=logging.DEBUG) +log = logging.getLogger('tinytuya') +log._tinytuya_use_color = True +log._tinytuya_created_formatter = False log.debug("%s version %s", __name__, __version__) log.debug("Python %s on %s", sys.version, sys.platform) @@ -333,13 +333,22 @@ def hex2bin(x): def set_debug(toggle=True, color=True): """Enable tinytuya verbose logging""" + log._tinytuya_use_color = color + + if color: + # \x1b[39;2m + fmt = "\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[31;1m%(message)s\x1b[0m" + else: + fmt = "%(levelname)s:%(name)s:%(message)s" + + if len(log.root.handlers) == 0: + log._tinytuya_created_formatter = True + logging.basicConfig(format=fmt) + else: #elif log._tinytuya_created_formatter: + fmt = logging.Formatter(fmt) + log.root.handlers[0].setFormatter(fmt) + if toggle: - if color: - logging.basicConfig( - format="\x1b[31;1m%(levelname)s:%(message)s\x1b[0m", level=logging.DEBUG - ) - else: - logging.basicConfig(format="%(levelname)s:%(message)s", level=logging.DEBUG) log.setLevel(logging.DEBUG) log.debug("TinyTuya [%s]\n", __version__) else: @@ -386,7 +395,7 @@ def pack_message(msg, hmac_key=None): return data -def unpack_message(data, hmac_key=None, header=None, no_retcode=False): +def unpack_message(data, hmac_key=None, header=None, no_retcode=False, uselog=log): """Unpack bytes into a TuyaMessage.""" if header is None: header = parse_header(data) @@ -408,7 +417,7 @@ def unpack_message(data, hmac_key=None, header=None, no_retcode=False): raise ValueError( 'unpack_message() cannot handle message format %08X' % header.prefix ) if len(data) < msg_len: - log.debug('unpack_message(): not enough data to unpack payload! need %d but only have %d', header_len+header.length, len(data)) + uselog.debug('unpack_message(): not enough data to unpack payload! need %d but only have %d', header_len+header.length, len(data)) raise DecodeError('Not enough data to unpack payload') end_len = struct.calcsize(end_fmt) @@ -425,13 +434,13 @@ def unpack_message(data, hmac_key=None, header=None, no_retcode=False): have_crc = binascii.crc32(data[:(header_len+header.length)-end_len]) & 0xFFFFFFFF if suffix != SUFFIX_VALUE: - log.debug('Suffix prefix wrong! %08X != %08X', suffix, SUFFIX_VALUE) + uselog.debug('Suffix prefix wrong! %08X != %08X', suffix, SUFFIX_VALUE) if crc != have_crc: if hmac_key: - log.debug('HMAC checksum wrong! %r != %r', binascii.hexlify(have_crc), binascii.hexlify(crc)) + uselog.debug('HMAC checksum wrong! %r != %r', binascii.hexlify(have_crc), binascii.hexlify(crc)) else: - log.debug('CRC wrong! %08X != %08X', have_crc, crc) + uselog.debug('CRC wrong! %08X != %08X', have_crc, crc) crc_good = crc == have_crc iv = None elif header.prefix == PREFIX_6699_VALUE: @@ -479,7 +488,6 @@ def parse_header(data): #seqno |= unknown << 32 total_length = payload_len + header_len + len(SUFFIX_6699_BIN) else: - #log.debug('Header prefix wrong! %08X != %08X', prefix, PREFIX_VALUE) raise DecodeError('Header prefix wrong! %08X is not %08X or %08X' % (prefix, PREFIX_55AA_VALUE, PREFIX_6699_VALUE)) # sanity check. currently the max payload length is somewhere around 300 bytes @@ -508,7 +516,7 @@ def error_json(number=None, payload=None): return json.loads('{ "Error":"%s", "Err":"%s", "Payload":%s }' % vals) -def find_device(dev_id=None, address=None): +def find_device(dev_id=None, address=None, uselog=log): """Scans network for Tuya devices with either ID = dev_id or IP = address Parameters: @@ -520,7 +528,7 @@ def find_device(dev_id=None, address=None): """ if dev_id is None and address is None: return (None, None, None) - log.debug("Listening for device %s on the network", dev_id) + uselog.debug("Listening for device %s on the network", dev_id) # Enable UDP listening broadcasting mode on UDP port 6666 - 3.1 Devices client = socket.socket(socket.AF_INET, socket.SOCK_DGRAM, socket.IPPROTO_UDP) client.setsockopt(socket.SOL_SOCKET, socket.SO_BROADCAST, 1) @@ -558,10 +566,10 @@ def find_device(dev_id=None, address=None): gwId = result["gwId"] version = result["version"] product_id = '' if 'productKey' not in result else result['productKey'] - log.debug( 'find() received broadcast from %r: %r', ip, result ) + uselog.debug( 'find_device() received broadcast from %r: %r', ip, result ) except: result = {"ip": ip} - log.debug( 'find() failed to decode broadcast from %r: %r', addr, data ) + uselog.debug( 'find_device() failed to decode broadcast from %r: %r', addr, data ) continue # Check to see if we are only looking for one device @@ -581,7 +589,7 @@ def find_device(dev_id=None, address=None): client.close() if ret is None: ret = {'ip':None, 'version':None, 'id':None, 'product_id':None, 'data':{}} - log.debug( 'find() is returning: %r', ret ) + uselog.debug( 'find_device() is returning: %r', ret ) return ret def device_info( dev_id ): @@ -716,6 +724,7 @@ def __init__( self.received_wrong_cid_queue = [] self.local_nonce = b'0123456789abcdef' # not-so-random random key self.remote_nonce = b'' + self.set_debug(False, color=log._tinytuya_use_color) if not local_key: local_key = "" @@ -737,14 +746,14 @@ def __init__( if not self.cid: # not fatal as the user could have set the device_id to the cid # in that case dev_type should be 'zigbee' to set the proper fields in requests - log.debug( 'Child device but no cid/node_id given!' ) + self.log.debug( 'Child device but no cid/node_id given!' ) XenonDevice.set_version(self, self.parent.version) self.parent._register_child(self) elif (not address) or address == "Auto" or address == "0.0.0.0": # try to determine IP address automatically - bcast_data = find_device(dev_id) + bcast_data = find_device(dev_id, uselog=self.log) if bcast_data['ip'] is None: - log.debug("Unable to find device on network (specify IP address)") + self.log.debug("Unable to find device on network (specify IP address)") raise Exception("Unable to find device on network (specify IP address)") self.address = bcast_data['ip'] self.set_version(float(bcast_data['version'])) @@ -760,7 +769,7 @@ def __init__( self.dev_type = 'zigbee' elif self.dev_type == 'zigbee' and not self.cid: # this probably won't work, but it might - log.debug( 'Zigbee device but no cid/node_id given, using dev_id as the cid!' ) + self.log.debug( 'Zigbee device but no cid/node_id given, using dev_id as the cid!' ) def __del__(self): # In case we have a lingering socket connection, close it @@ -805,13 +814,13 @@ def _get_socket(self, renew): return True except socket.timeout as err: # unable to open socket - log.debug( + self.log.debug( "socket unable to connect (timeout) - retry %d/%d", retries, self.socketRetryLimit ) except Exception as err: # unable to open socket - log.debug( + self.log.debug( "socket unable to connect (exception) - retry %d/%d", retries, self.socketRetryLimit, exc_info=True ) @@ -837,7 +846,7 @@ def _recv_all(self, length): while length > 0: newdata = self.socket.recv(length) if not newdata or len(newdata) == 0: - log.debug("_recv_all(): no data? %r", newdata) + self.log.debug("_recv_all(): no data? %r", newdata) # connection closed? tries -= 1 if tries == 0: @@ -868,8 +877,8 @@ def _receive(self): prefix_offset_6699 = data.find( PREFIX_6699_BIN ) while prefix_offset_55AA != 0 and prefix_offset_6699 != 0: - log.debug('Message prefix not at the beginning of the received data!') - log.debug('Offset 55AA: %d, 6699: %d, Received data: %r', prefix_offset_55AA, prefix_offset_6699, data) + self.log.debug('Message prefix not at the beginning of the received data!') + self.log.debug('Offset 55AA: %d, 6699: %d, Received data: %r', prefix_offset_55AA, prefix_offset_6699, data) if prefix_offset_55AA < 0 and prefix_offset_6699 < 0: data = data[1-prefix_len:] else: @@ -885,17 +894,17 @@ def _receive(self): if remaining > 0: data += self._recv_all( remaining ) - log.debug("received data=%r", binascii.hexlify(data)) + self.log.debug("received data=%r", binascii.hexlify(data)) hmac_key = self.local_key if self.version >= 3.4 else None no_retcode = False #None if self.version >= 3.5 else False - return unpack_message(data, header=header, hmac_key=hmac_key, no_retcode=no_retcode) + return unpack_message(data, header=header, hmac_key=hmac_key, no_retcode=no_retcode, uselog=self.log) # similar to _send_receive() but never retries sending and does not decode the response def _send_receive_quick(self, payload, recv_retries, from_child=None): # pylint: disable=W0613 if self.parent: return self.parent._send_receive_quick(payload, recv_retries, from_child=self) - log.debug("sending payload quick") + self.log.debug("sending payload quick") if not self._get_socket(False): return None enc_payload = self._encode_message(payload) if type(payload) == MessagePayload else payload @@ -915,9 +924,9 @@ def _send_receive_quick(self, payload, recv_retries, from_child=None): # pylint: return msg recv_retries -= 1 if recv_retries == 0: - log.debug("received null payload (%r) but out of recv retries, giving up", msg) + self.log.debug("received null payload (%r) but out of recv retries, giving up", msg) else: - log.debug("received null payload (%r), fetch new one - %s retries remaining", msg, recv_retries) + self.log.debug("received null payload (%r), fetch new one - %s retries remaining", msg, recv_retries) return False def _send_receive(self, payload, minresponse=28, getresponse=True, decode_response=True, from_child=None): @@ -964,7 +973,7 @@ def _send_receive(self, payload, minresponse=28, getresponse=True, decode_respon # send request to device try: if payload is not None and do_send: - log.debug("sending payload") + self.log.debug("sending payload") enc_payload = self._encode_message(payload) if type(payload) == MessagePayload else payload self.socket.sendall(enc_payload) time.sleep(self.sendWait) # give device time to respond @@ -978,19 +987,19 @@ def _send_receive(self, payload, minresponse=28, getresponse=True, decode_respon partial_success = True msg = rmsg if (not msg or len(msg.payload) == 0) and recv_retries <= max_recv_retries: - log.debug("received null payload (%r), fetch new one - retry %s / %s", msg, recv_retries, max_recv_retries) + self.log.debug("received null payload (%r), fetch new one - retry %s / %s", msg, recv_retries, max_recv_retries) recv_retries += 1 if recv_retries > max_recv_retries: success = True else: success = True - log.debug("received message=%r", msg) + self.log.debug("received message=%r", msg) if not getresponse: # legacy/default mode avoids persisting socket across commands self._check_socket_close() return None except (KeyboardInterrupt, SystemExit) as err: - log.debug("Keyboard Interrupt - Exiting") + self.log.debug("Keyboard Interrupt - Exiting") raise except socket.timeout as err: # a socket timeout occurred @@ -1001,13 +1010,13 @@ def _send_receive(self, payload, minresponse=28, getresponse=True, decode_respon do_send = True retries += 1 self._check_socket_close(True) - log.debug( + self.log.debug( "Timeout in _send_receive() - retry %s / %s", retries, self.socketRetryLimit ) # if we exceed the limit of retries then lets get out of here if retries > self.socketRetryLimit: - log.debug( + self.log.debug( "Exceeded tinytuya retry limit (%s)", self.socketRetryLimit ) @@ -1020,7 +1029,7 @@ def _send_receive(self, payload, minresponse=28, getresponse=True, decode_respon time.sleep(0.1) self._get_socket(True) except DecodeError as err: - log.debug("Error decoding received data - read retry %s/%s", recv_retries, max_recv_retries, exc_info=True) + self.log.debug("Error decoding received data - read retry %s/%s", recv_retries, max_recv_retries, exc_info=True) recv_retries += 1 if recv_retries > max_recv_retries: # we recieved at least 1 valid message with a null payload, so the send was successful @@ -1035,17 +1044,17 @@ def _send_receive(self, payload, minresponse=28, getresponse=True, decode_respon do_send = True retries += 1 self._check_socket_close(True) - log.debug( + self.log.debug( "Network connection error in _send_receive() - retry %s/%s", retries, self.socketRetryLimit, exc_info=True ) # if we exceed the limit of retries then lets get out of here if retries > self.socketRetryLimit: - log.debug( + self.log.debug( "Exceeded tinytuya retry limit (%s)", self.socketRetryLimit ) - log.debug("Unable to connect to device ") + self.log.debug("Unable to connect to device ") # timeout reached - return error json_payload = error_json(ERR_CONNECT) return json_payload @@ -1066,7 +1075,7 @@ def _send_receive(self, payload, minresponse=28, getresponse=True, decode_respon def _process_message( self, msg, dev_type=None, from_child=None, minresponse=28, decode_response=True ): # null packet, nothing to decode if not msg or len(msg.payload) == 0: - log.debug("raw unpacked message = %r", msg) + self.log.debug("raw unpacked message = %r", msg) # legacy/default mode avoids persisting socket across commands self._check_socket_close() return None @@ -1078,18 +1087,18 @@ def _process_message( self, msg, dev_type=None, from_child=None, minresponse=28, # and return payload decrypted try: # Data available: seqno cmd retcode payload crc - log.debug("raw unpacked message = %r", msg) + self.log.debug("raw unpacked message = %r", msg) result = self._decode_payload(msg.payload) if result is None: - log.debug("_decode_payload() failed!") + self.log.debug("_decode_payload() failed!") except: - log.debug("error unpacking or decoding tuya JSON payload", exc_info=True) + self.log.debug("error unpacking or decoding tuya JSON payload", exc_info=True) result = error_json(ERR_PAYLOAD) # Did we detect a device22 device? Return ERR_DEVTYPE error. if dev_type and dev_type != self.dev_type: - log.debug( + self.log.debug( "Device22 detected and updated (%s -> %s) - Update payload and try again", dev_type, self.dev_type, @@ -1109,7 +1118,7 @@ def _process_message( self, msg, dev_type=None, from_child=None, minresponse=28, if from_child and from_child is not True and from_child != found_child: # async update from different CID, try again - log.debug( 'Recieved async update for wrong CID %s while looking for CID %s, trying again', found_cid, want_cid ) + self.log.debug( 'Recieved async update for wrong CID %s while looking for CID %s, trying again', found_cid, want_cid ) if self.socketPersistent: # if persistent, save response until the next receive() call # otherwise, trash it @@ -1130,20 +1139,20 @@ def _process_message( self, msg, dev_type=None, from_child=None, minresponse=28, return self._process_response(result) def _decode_payload(self, payload): - log.debug("decode payload=%r", payload) + self.log.debug("decode payload=%r", payload) cipher = AESCipher(self.local_key) if self.version == 3.4: # 3.4 devices encrypt the version header in addition to the payload try: - log.debug("decrypting=%r", payload) + self.log.debug("decrypting=%r", payload) payload = cipher.decrypt(payload, False, decode_text=False) except: - log.debug("incomplete payload=%r (len:%d)", payload, len(payload), exc_info=True) + self.log.debug("incomplete payload=%r (len:%d)", payload, len(payload), exc_info=True) return error_json(ERR_PAYLOAD) - log.debug("decrypted 3.x payload=%r", payload) - log.debug("payload type = %s", type(payload)) + self.log.debug("decrypted 3.x payload=%r", payload) + self.log.debug("payload type = %s", type(payload)) if payload.startswith(PROTOCOL_VERSION_BYTES_31): # Received an encrypted payload @@ -1156,45 +1165,45 @@ def _decode_payload(self, payload): # Trim header for non-default device type if payload.startswith( self.version_bytes ): payload = payload[len(self.version_header) :] - log.debug("removing 3.x=%r", payload) + self.log.debug("removing 3.x=%r", payload) elif self.dev_type == "device22" and (len(payload) & 0x0F) != 0: payload = payload[len(self.version_header) :] - log.debug("removing device22 3.x header=%r", payload) + self.log.debug("removing device22 3.x header=%r", payload) if self.version < 3.4: try: - log.debug("decrypting=%r", payload) + self.log.debug("decrypting=%r", payload) payload = cipher.decrypt(payload, False) except: - log.debug("incomplete payload=%r (len:%d)", payload, len(payload), exc_info=True) + self.log.debug("incomplete payload=%r (len:%d)", payload, len(payload), exc_info=True) return error_json(ERR_PAYLOAD) - log.debug("decrypted 3.x payload=%r", payload) + self.log.debug("decrypted 3.x payload=%r", payload) # Try to detect if device22 found - log.debug("payload type = %s", type(payload)) + self.log.debug("payload type = %s", type(payload)) if not isinstance(payload, str): try: payload = payload.decode() except: - log.debug("payload was not string type and decoding failed") + self.log.debug("payload was not string type and decoding failed") return error_json(ERR_JSON, payload) if not self.disabledetect and "data unvalid" in payload: self.dev_type = "device22" # set at least one DPS self.dps_to_request = {"1": None} - log.debug( + self.log.debug( "'data unvalid' error detected: switching to dev_type %r", self.dev_type, ) return None elif not payload.startswith(b"{"): - log.debug("Unexpected payload=%r", payload) + self.log.debug("Unexpected payload=%r", payload) return error_json(ERR_PAYLOAD, payload) if not isinstance(payload, str): payload = payload.decode() - log.debug("decoded results=%r", payload) + self.log.debug("decoded results=%r", payload) try: json_payload = json.loads(payload) except: @@ -1231,38 +1240,38 @@ def _negotiate_session_key_generate_step_1( self ): def _negotiate_session_key_generate_step_3( self, rkey ): if not rkey or type(rkey) != TuyaMessage or len(rkey.payload) < 48: # error - log.debug("session key negotiation failed on step 1") + self.log.debug("session key negotiation failed on step 1") return False if rkey.cmd != SESS_KEY_NEG_RESP: - log.debug("session key negotiation step 2 returned wrong command: %d", rkey.cmd) + self.log.debug("session key negotiation step 2 returned wrong command: %d", rkey.cmd) return False payload = rkey.payload if self.version == 3.4: try: - log.debug("decrypting=%r", payload) + self.log.debug("decrypting=%r", payload) cipher = AESCipher(self.real_local_key) payload = cipher.decrypt(payload, False, decode_text=False) except: - log.debug("session key step 2 decrypt failed, payload=%r (len:%d)", payload, len(payload), exc_info=True) + self.log.debug("session key step 2 decrypt failed, payload=%r (len:%d)", payload, len(payload), exc_info=True) return False - log.debug("decrypted session key negotiation step 2 payload=%r", payload) - log.debug("payload type = %s len = %d", type(payload), len(payload)) + self.log.debug("decrypted session key negotiation step 2 payload=%r", payload) + self.log.debug("payload type = %s len = %d", type(payload), len(payload)) if len(payload) < 48: - log.debug("session key negotiation step 2 failed, too short response") + self.log.debug("session key negotiation step 2 failed, too short response") return False self.remote_nonce = payload[:16] hmac_check = hmac.new(self.local_key, self.local_nonce, sha256).digest() if hmac_check != payload[16:48]: - log.debug("session key negotiation step 2 failed HMAC check! wanted=%r but got=%r", binascii.hexlify(hmac_check), binascii.hexlify(payload[16:48])) + self.log.debug("session key negotiation step 2 failed HMAC check! wanted=%r but got=%r", binascii.hexlify(hmac_check), binascii.hexlify(payload[16:48])) return False - log.debug("session local nonce: %r remote nonce: %r", self.local_nonce, self.remote_nonce) + self.log.debug("session local nonce: %r remote nonce: %r", self.local_nonce, self.remote_nonce) rkey_hmac = hmac.new(self.local_key, self.remote_nonce, sha256).digest() return MessagePayload(SESS_KEY_NEG_FINISH, rkey_hmac) @@ -1273,17 +1282,17 @@ def _negotiate_session_key_generate_finalize( self ): self.local_key = ''.join(k) else: self.local_key = bytes( [ a^b for (a,b) in zip(self.local_nonce,self.remote_nonce) ] ) - log.debug("Session nonce XOR'd: %r", self.local_key) + self.log.debug("Session nonce XOR'd: %r", self.local_key) cipher = AESCipher(self.real_local_key) if self.version == 3.4: self.local_key = cipher.encrypt( self.local_key, False, pad=False ) else: iv = self.local_nonce[:12] - log.debug("Session IV: %r", iv) + self.log.debug("Session IV: %r", iv) self.local_key = cipher.encrypt( self.local_key, use_base64=False, pad=False, iv=iv )[12:28] - log.debug("Session key negotiate success! session key: %r", self.local_key) + self.log.debug("Session key negotiate success! session key: %r", self.local_key) return True # adds protocol header (if needed) and encrypts @@ -1301,7 +1310,7 @@ def _encode_message( self, msg ): if msg.cmd not in NO_PROTOCOL_HEADER_CMDS: # add the 3.x header payload = self.version_header + payload - log.debug('final payload: %r', payload) + self.log.debug('final payload: %r', payload) if self.version >= 3.5: iv = True @@ -1309,7 +1318,7 @@ def _encode_message( self, msg ): msg = TuyaMessage(self.seqno, msg.cmd, None, payload, 0, True, PREFIX_6699_VALUE, True) self.seqno += 1 # increase message sequence number data = pack_message(msg,hmac_key=self.local_key) - log.debug("payload encrypted=%r",binascii.hexlify(data)) + self.log.debug("payload encrypted=%r",binascii.hexlify(data)) return data payload = self.cipher.encrypt(payload, False) @@ -1344,12 +1353,12 @@ def _encode_message( self, msg ): msg = TuyaMessage(self.seqno, msg.cmd, 0, payload, 0, True, PREFIX_55AA_VALUE, False) self.seqno += 1 # increase message sequence number buffer = pack_message(msg,hmac_key=hmac_key) - log.debug("payload encrypted=%r",binascii.hexlify(buffer)) + self.log.debug("payload encrypted=%r",binascii.hexlify(buffer)) return buffer def _register_child(self, child): if child.id in self.children and child != self.children[child.id]: - log.debug('Replacing existing child %r!', child.id) + self.log.debug('Replacing existing child %r!', child.id) self.children[child.id] = child # disable device22 detection as gateways return "json obj data unvalid" when the gateway is polled without a cid self.disabledetect = True @@ -1372,16 +1381,16 @@ def send(self, payload): def status(self, nowait=False): """Return device status.""" query_type = DP_QUERY - log.debug("status() entry (dev_type is %s)", self.dev_type) + self.log.debug("status() entry (dev_type is %s)", self.dev_type) payload = self.generate_payload(query_type) data = self._send_receive(payload, 0, getresponse=(not nowait)) - log.debug("status() received data=%r", data) + self.log.debug("status() received data=%r", data) # Error handling if (not nowait) and data and "Err" in data: if data["Err"] == str(ERR_DEVTYPE): # Device22 detected and change - resend with new payload - log.debug("status() rebuilding payload for device22") + self.log.debug("status() rebuilding payload for device22") payload = self.generate_payload(query_type) data = self._send_receive(payload) @@ -1404,7 +1413,7 @@ def detect_available_dps(self): try: data = self.status() except Exception as ex: - log.exception("Failed to get status: %s", ex) + self.log.exception("Failed to get status: %s", ex) raise if data is not None and "dps" in data: self.dps_cache.update(data["dps"]) @@ -1412,7 +1421,7 @@ def detect_available_dps(self): if self.dev_type == "default": self.dps_to_request = self.dps_cache return self.dps_cache - log.debug("Detected dps: %s", self.dps_cache) + self.log.debug("Detected dps: %s", self.dps_cache) self.dps_to_request = self.dps_cache return self.dps_cache @@ -1471,6 +1480,14 @@ def set_retry(self, retry): def set_sendWait(self, s): self.sendWait = s + def set_debug(self, toggle=True, color=True): + if color: + self.log = log.getChild( '%s.%s%s%s' % (self.__class__.__name__, Fore.CYAN, self.id, Fore.RESET) ) + else: + self.log = log.getChild( '%s._%s_' % (self.__class__.__name__, self.id) ) + + self.log.setLevel(logging.DEBUG if toggle else logging.NOTSET) + def close(self): self.__del__() @@ -1569,7 +1586,7 @@ def generate_payload(self, command, data=None, gwId=None, devId=None, uid=None): # if spaces are not removed device does not respond! payload = payload.replace(" ", "") payload = payload.encode("utf-8") - log.debug("building command %s payload=%r", command, payload) + self.log.debug("building command %s payload=%r", command, payload) # create Tuya message packet return MessagePayload(command_override, payload) @@ -1594,7 +1611,7 @@ def set_status(self, on, switch=1, nowait=False): payload = self.generate_payload(CONTROL, {switch: on}) data = self._send_receive(payload, getresponse=(not nowait)) - log.debug("set_status received data=%r", data) + self.log.debug("set_status received data=%r", data) return data @@ -1606,7 +1623,7 @@ def product(self): # open device, send request, then close connection payload = self.generate_payload(AP_CONFIG) data = self._send_receive(payload, 0) - log.debug("product received data=%r", data) + self.log.debug("product received data=%r", data) return data def heartbeat(self, nowait=False): @@ -1619,7 +1636,7 @@ def heartbeat(self, nowait=False): # open device, send request, then close connection payload = self.generate_payload(HEART_BEAT) data = self._send_receive(payload, 0, getresponse=(not nowait)) - log.debug("heartbeat received data=%r", data) + self.log.debug("heartbeat received data=%r", data) return data def updatedps(self, index=None, nowait=False): @@ -1633,11 +1650,11 @@ def updatedps(self, index=None, nowait=False): if index is None: index = [1] - log.debug("updatedps() entry (dev_type is %s)", self.dev_type) + self.log.debug("updatedps() entry (dev_type is %s)", self.dev_type) # open device, send request, then close connection payload = self.generate_payload(UPDATEDPS, index) data = self._send_receive(payload, 0, getresponse=(not nowait)) - log.debug("updatedps received data=%r", data) + self.log.debug("updatedps received data=%r", data) return data def set_value(self, index, value, nowait=False): @@ -1700,13 +1717,13 @@ def set_timer(self, num_secs, dps_id=0, nowait=False): devices_numbers.sort() dps_id = devices_numbers[-1] else: - log.debug("set_timer received error=%r", status) + self.log.debug("set_timer received error=%r", status) return status payload = self.generate_payload(CONTROL, {dps_id: num_secs}) data = self._send_receive(payload, getresponse=(not nowait)) - log.debug("set_timer received data=%r", data) + self.log.debug("set_timer received data=%r", data) return data # Utility Functions diff --git a/tinytuya/scanner.py b/tinytuya/scanner.py index a14633e7..dab084f7 100644 --- a/tinytuya/scanner.py +++ b/tinytuya/scanner.py @@ -86,7 +86,7 @@ # Logging -log = logging.getLogger(__name__) +log = tinytuya.log.getChild('scanner') # Helper Functions def getmyIP(): @@ -524,7 +524,7 @@ def read_data( self ): if msg.cmd == tinytuya.SESS_KEY_NEG_RESP: if not self.v34_negotiate_sess_key_step_2( msg ): #if self.debug: - print('odata:', odata) + print('ForceScannedDevice: raw packet:', odata) self.timeout() return self.read = False @@ -840,7 +840,7 @@ def read_data( self ): if msg.cmd == tinytuya.SESS_KEY_NEG_RESP: if not self.v34_negotiate_sess_key_step_2( msg ): - print('odata:', odata) + print('PollDevice: raw packet:', odata) self.timeout() return self.read = False From ba3efadebbc8245b50337a1c6c1fa74db1fcada0 Mon Sep 17 00:00:00 2001 From: uzlonewolf Date: Mon, 20 Mar 2023 07:31:52 -0700 Subject: [PATCH 2/2] Update color formatting to use colorama more, and misc updates --- tinytuya/__main__.py | 13 +++---------- tinytuya/core.py | 31 ++++++++++++++++--------------- 2 files changed, 19 insertions(+), 25 deletions(-) diff --git a/tinytuya/__main__.py b/tinytuya/__main__.py index 4dd53fdd..f155d124 100644 --- a/tinytuya/__main__.py +++ b/tinytuya/__main__.py @@ -15,7 +15,10 @@ # Modules import sys + import tinytuya +from . import wizard +from . import scanner retries = None state = 0 @@ -67,16 +70,6 @@ force = force_list tinytuya.set_debug(debug, color) -#if debug: -# if color: -# logging.basicConfig( format="\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[39;2m%(message)s\x1b[0m", level=logging.DEBUG ) -# else: -# logging.basicConfig( level=logging.DEBUG ) - -if state == 1: - from . import wizard -else: - from . import scanner # State 0 = Run Network Scan if state == 0: diff --git a/tinytuya/core.py b/tinytuya/core.py index 43969c7a..57554400 100644 --- a/tinytuya/core.py +++ b/tinytuya/core.py @@ -336,8 +336,7 @@ def set_debug(toggle=True, color=True): log._tinytuya_use_color = color if color: - # \x1b[39;2m - fmt = "\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[31;1m%(message)s\x1b[0m" + fmt = Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL else: fmt = "%(levelname)s:%(name)s:%(message)s" @@ -345,6 +344,7 @@ def set_debug(toggle=True, color=True): log._tinytuya_created_formatter = True logging.basicConfig(format=fmt) else: #elif log._tinytuya_created_formatter: + # abuse log.root.handlers to overwrite the default formatter fmt = logging.Formatter(fmt) log.root.handlers[0].setFormatter(fmt) @@ -488,7 +488,9 @@ def parse_header(data): #seqno |= unknown << 32 total_length = payload_len + header_len + len(SUFFIX_6699_BIN) else: - raise DecodeError('Header prefix wrong! %08X is not %08X or %08X' % (prefix, PREFIX_55AA_VALUE, PREFIX_6699_VALUE)) + # Tuya protocol should include a header prefix 0x55AA (3.1, 3.2, 3.3, 3.4) or 0x6699 (3.5) + # (see https://github.com/jasonacox/tinytuya/discussions/260) + raise DecodeError('Unknown header prefix %08X - only %08X and %08X are handled' % (prefix, PREFIX_55AA_VALUE, PREFIX_6699_VALUE)) # sanity check. currently the max payload length is somewhere around 300 bytes if payload_len > 1000: @@ -1107,18 +1109,17 @@ def _process_message( self, msg, dev_type=None, from_child=None, minresponse=28, found_child = False if self.children: - found_cid = want_cid = None + found_cid = None if result and 'cid' in result: found_cid = result['cid'] for c in self.children: if self.children[c].cid == result['cid']: - want_cid = self.children[c].cid result['device'] = found_child = self.children[c] break if from_child and from_child is not True and from_child != found_child: # async update from different CID, try again - self.log.debug( 'Recieved async update for wrong CID %s while looking for CID %s, trying again', found_cid, want_cid ) + self.log.debug( 'Recieved async update for wrong CID %s while looking for CID %s, trying again', found_cid, from_child.cid ) if self.socketPersistent: # if persistent, save response until the next receive() call # otherwise, trash it @@ -1776,15 +1777,15 @@ def termcolor(color=True): bold = subbold = normal = dim = alert = alertdim = cyan = red = yellow = "" else: # Terminal Color Formatting - bold = "\033[0m\033[97m\033[1m" - subbold = "\033[0m\033[32m" - normal = "\033[97m\033[0m" - dim = "\033[0m\033[97m\033[2m" - alert = "\033[0m\033[91m\033[1m" - alertdim = "\033[0m\033[91m\033[2m" - cyan = "\033[0m\033[36m" - red = "\033[0m\033[31m" - yellow = "\033[0m\033[33m" + bold = Style.RESET_ALL + Fore.LIGHTWHITE_EX + Style.BRIGHT + subbold = Style.RESET_ALL + Fore.GREEN + normal = Style.RESET_ALL + dim = Style.RESET_ALL + Fore.LIGHTWHITE_EX + Style.DIM + alert = Style.RESET_ALL + Fore.LIGHTRED_EX + Style.BRIGHT + alertdim = Style.RESET_ALL + Fore.LIGHTRED_EX + Style.DIM + cyan = Style.RESET_ALL + Fore.CYAN + red = Style.RESET_ALL + Fore.RED + yellow = Style.RESET_ALL + Fore.YELLOW return bold,subbold,normal,dim,alert,alertdim,cyan,red,yellow