Add MQTT logging for better understanding of what is going on (includes some flash status updates)

Add timestamps to log output and add extra line for readability before http client requests
Add start request logging for static files for better timing logging
Change action hook from tuya.device.dynamic.config.get to tuya.device.uuid.pskkey.get as it always comes later and starts the clock for flashing
add response for tuya.device.upgrade.status.update.json to hush default endpoint notice.

device-profiles/schema/tuya.device.upgrade.status.update.json

@@ -0,0 +1 @@
+{"t": 1640995200, "success": true}

src/cloudcutter/__main__.py

@@ -1,4 +1,5 @@
 import argparse
+import datetime
 import hmac
 import json
 import os
@@ -68,7 +69,7 @@ def __configure_ssid_on_device(ip: str, config: DeviceConfig, ssid: str, passwor
             print(parsed_data)
             sys.exit(80)
 
-        print(f"Device should be successfully onboarded on WiFi AP!")
+        print(f"Device should be successfully onboarded on WiFi AP!  Please allow up to 2 minutes for the device to connect to your specified network.")
         sys.exit(0)
     except Exception:
         print_exc()
@@ -80,11 +81,11 @@ def __trigger_firmware_update(config: DeviceConfig):
     local_key = config.get(DeviceConfig.LOCAL_KEY)
 
     mqtt.trigger_firmware_update(device_id=device_id, local_key=local_key, protocol="2.2", broker="127.0.0.1")
-    print("[MQTT Server] Firmware update messages triggered. Device will download and reset. Exiting in 30 seconds.")
-    tornado.ioloop.IOLoop.current().call_later(30.0, lambda: sys.exit(0))
+    print(f"[{datetime.datetime.now().time()} MQTT Sending] Triggering firmware update message. Device will download and reset. Exiting in 60 seconds.")
+    tornado.ioloop.IOLoop.current().call_later(60.0, lambda: sys.exit(0))
 
 
-def __configure_local_device_or_update_firmware(args, update_firmare: bool = False):
+def __configure_local_device_or_update_firmware(args, update_firmware: bool = False):
     if not os.path.exists(args.config):
         print(f"Configuration file {args.config} does not exist", file=sys.stderr)
         sys.exit(10)
@@ -96,21 +97,25 @@ def __configure_local_device_or_update_firmware(args, update_firmare: bool = Fal
     config = DeviceConfig.read(args.config)
     authkey, uuid = config.get_bytes(DeviceConfig.AUTH_KEY, default=DEFAULT_AUTH_KEY), config.get_bytes(DeviceConfig.UUID)
     context = PSKContext(authkey=authkey, uuid=uuid)
+    device_id, local_key = config.get(DeviceConfig.DEVICE_ID), config.get(DeviceConfig.LOCAL_KEY)
+    mqtt.mqtt_connect(device_id, local_key)
 
     with open(args.profile, "r") as f:
         combined = json.load(f)
         device = combined["device"]
 
-    def dynamic_config_endpoint_hook(handler, *_):
+    def pskkey_endpoint_hook(handler, *_):
         """
-        Hooks into an endpoint response for the dynamic config. Standard response should not be overwritten, but needs to
-        register a task to either changed device SSID or update firmware. Hence, return None.
+        Hooks into an endpoint response for the device uuid pskkey get, the apparent last call in standard activation,
+        and less likely to double-trigger in firmware updates (where dynamic config usually gets called twice).
+        Standard response should not be overwritten, but needs to register a task
+        to either change device SSID or update firmware. Hence, return None.
         """
 
         global dynamic_config_endpoint_hook_triggered
         if dynamic_config_endpoint_hook_triggered == False:
             dynamic_config_endpoint_hook_triggered = True
-            if update_firmare:
+            if update_firmware:
                 task_function = __trigger_firmware_update
                 task_args = (config, )
             else:
@@ -162,14 +167,14 @@ def __configure_local_device_or_update_firmware(args, update_firmare: bool = Fal
 
     response_transformers = __configure_local_device_response_transformers(config)
     endpoint_hooks = {
-        "tuya.device.dynamic.config.get": dynamic_config_endpoint_hook,
         "tuya.device.active": active_endpoint_hook,
+        "tuya.device.uuid.pskkey.get": pskkey_endpoint_hook,
     }
 
-    if update_firmare:
+    if update_firmware:
         endpoint_hooks.update({
+            "tuya.device.upgrade.get": upgrade_endpoint_hook,
             "tuya.device.upgrade.silent.get": upgrade_endpoint_hook,
-            "tuya.device.upgrade.get": upgrade_endpoint_hook
         })
 
     application = tornado.web.Application([
@@ -226,7 +231,7 @@ def __update_firmware(args):
         if error_code != 0:
             sys.exit(error_code)
 
-    __configure_local_device_or_update_firmware(args, update_firmare=True)
+    __configure_local_device_or_update_firmware(args, update_firmware=True)
 
 
 def __exploit_device(args):
@@ -248,7 +253,7 @@ def __exploit_device(args):
     output_path = os.path.join(output_dir, f"{device_uuid}.deviceconfig")
     device_config.write(output_path)
 
-    print(f"Exploit run, saved device config to!")
+    print("Exploit run, saved device config too!")
 
     # To communicate with external scripts
     print(f"output={output_path}")

src/cloudcutter/protocol/handlers.py

@@ -1,4 +1,5 @@
 import base64
+import datetime
 import json
 import os
 import time
@@ -13,19 +14,21 @@ from .transformers import ResponseTransformer
 
 
 def log_request(request, decrypted_response_body: str = None):
-    print(f'[Log (Client)] Request: {request}')
+    # print a blank line for easier reading
+    print("")
+    print(f'[{datetime.datetime.now().time()} Log (Client)] Request: {request}')
 
     if len(request.body) > 0:
-        print('[LOG (Client)] ==== Request body ===')
+        print(f'[{datetime.datetime.now().time()} LOG (Client)] ==== Request body ===')
         if (decrypted_response_body is not None):
             print(decrypted_response_body)
         else:
             print(request.body)
-        print('[LOG (Client)] ==== End request body ===')
+        print(f'[{datetime.datetime.now().time()} LOG (Client)] ==== End request body ===')
 
 
 def log_response(response):
-    print(f'[LOG (Server)] Response: ', response)
+    print(f'[{datetime.datetime.now().time()} LOG (Server)] Response: ', response)
 
 
 class TuyaHeadersHandler(tornado.web.RequestHandler):
@@ -77,10 +80,17 @@ class OldSDKGetURLHandler(TuyaHeadersHandler):
 
 
 class OTAFilesHandler(tornado.web.StaticFileHandler):
+    def prepare(self):
+        log_request(self.request, self.request.body)
+        range_value = self.request.headers.get("Range", "bytes 0-0")
+        # get_content_size() is not available in prepare without a lot of overriding work
+        # total = self.get_content_size()
+        log_response(range_value)
+
     def on_finish(self):
         range_value = self.request.headers.get("Range", "bytes 0-0")
         total = self.get_content_size()
-        print(f"[DEVICE OTA] Responding to device OTA HTTP request range: {range_value}/{total}")
+        print(f"[{datetime.datetime.now().time()} DEVICE OTA] Responding to device OTA HTTP request range: {range_value}/{total}")
 
 
 class DetachHandler(TuyaServerHandler):

src/cloudcutter/protocol/mqtt.py

@@ -7,16 +7,15 @@ Modified from tuya-convert for tuya-cloudcutter.
 """
 import base64
 import binascii
+import datetime
 import time
 from hashlib import md5
 
+import paho.mqtt.client as mqttClient
 import paho.mqtt.publish as publish
 from Cryptodome.Cipher import AES
 from Cryptodome.Util.Padding import pad, unpad
 
-# USAGE:
-# python3 mq_pub_15.py -i <deviceID> -p 2.2 -l 68e62d514b1033fa
-
 
 def encrypt(msg, key):
     return AES.new(key, AES.MODE_ECB).encrypt(pad(msg.encode(), block_size=16))
@@ -26,9 +25,12 @@ def decrypt(msg, key):
     return unpad(AES.new(key, AES.MODE_ECB).decrypt(msg), block_size=16).decode()
 
 
-def iot_dec(message, local_key):
-    message_clear = decrypt(base64.b64decode(message[19:]), local_key.encode())
-    print(message_clear)
+def iot_dec(message, local_key, protocol='2.2'):
+    if protocol == '2.1':
+        message_clear = decrypt(base64.b64decode(message[19:]), local_key.encode())
+    else:
+        message_clear = decrypt(message[15:], local_key.encode())
+
     return message_clear
 
 
@@ -48,14 +50,35 @@ def iot_enc(message, local_key, protocol):
     return messge_enc
 
 
+def mqtt_connect(device_id, local_key, broker="127.0.0.1", protocol="2.2"):
+    client = mqttClient.Client("CloudCutter")
+    client.device_id = device_id
+    client.local_key = local_key
+    client.protocol = protocol
+    client.connect(broker)
+    print(f"[{datetime.datetime.now().time()} MQTT] Connected")
+    client.on_message = on_message
+    # This is a private mqtt server, subscribe to all topics with "#"
+    client.subscribe("#")
+    client.loop_start()
+
+
+def on_message(client, userdata, message):
+    try:
+        if message.payload[:3] == bytes(client.protocol, 'utf-8'):
+            clean_payload = iot_dec(message.payload, client.local_key, client.protocol)
+        else:
+            clean_payload = message.payload.decode()
+        print(f"[{datetime.datetime.now().time()} MQTT Received] Topic: {message.topic} - Message: {clean_payload}")
+    except:
+        print(f"[{datetime.datetime.now().time()} MQTT Recieved] Unable to parse message: {message.payload}")
+
+
 def trigger_firmware_update(device_id, local_key, protocol="2.2", broker="127.0.0.1"):
     if protocol == "2.1":
-        message = '{"data":{"gwId":"%s"},"protocol":15,"s":%d,"t":%d}' % (
-            device_id, 1523715, time.time())
+        message = '{"data":{"gwId":"%s"},"protocol":15,"s":%d,"t":%d}' % device_id, 1523715, time.time()
     else:
-        message = (
-            '{"data":{"firmwareType":0},"protocol":15,"t":%d}' % time.time())
-    print("[MQTT Server] Sending firmware update message",
-          message, "using protocol", protocol)
-    m1 = iot_enc(message, local_key, protocol)
-    publish.single("smart/device/in/%s" % (device_id), m1, hostname=broker)
+        message = '{"data":{"firmwareType":0},"protocol":15,"t":%d}' % time.time()
+    print(f"[{datetime.datetime.now().time()} MQTT Sending] Sending firmware update message {message} using protocol {protocol}")
+    payload = iot_enc(message, local_key, protocol)
+    publish.single(f"smart/device/in/{device_id}", payload, hostname=broker)