Optimize logging, move useful stuff to INFO, leave DEBUG noisy.

pygatt/backends/backend.py

@@ -80,3 +80,7 @@ def add_descriptor(self, uuid, handle):
         Add a characteristic descriptor to the dictionary of descriptors.
         """
         self.descriptors[uuid] = handle
+
+    def __str__(self):
+        return "<%s uuid=%s handle=%d>" % (self.__class__.__name__,
+                                           self.uuid, self.handle)

pygatt/backends/bgapi/bgapi.py

@@ -5,7 +5,7 @@
 import serial
 import time
 import threading
-from binascii import hexlify
+from binascii import hexlify, unhexlify
 from uuid import UUID
 from enum import Enum
 from collections import defaultdict
@@ -32,6 +32,11 @@
                              'descriptor', 'characteristic'])
 
 
+def bgapi_address_to_hex(address):
+    address = hexlify(bytearray(list(reversed(address)))).upper()
+    return ':'.join(''.join(pair) for pair in zip(*[iter(address)] * 2))
+
+
 class AdvertisingAndScanInfo(object):
     """
     Holds the advertising and scan response packet data from a device at a given
@@ -132,7 +137,7 @@ def start(self):
         # TODO should disconnect from anything so we are in a clean slate
 
         # Stop any ongoing procedure
-        log.info("Stopping any outstanding GAP procedure")
+        log.debug("Stopping any outstanding GAP procedure")
         self.send_command(CommandBuilder.gap_end_procedure())
         try:
             self.expect(ResponsePacketType.gap_end_procedure)
@@ -190,7 +195,7 @@ def clear_bond(self, address=None):
               device.
         """
         # Find bonds
-        log.debug("Fetching existing bonds for devices")
+        log.info("Fetching existing bonds for devices")
         self._stored_bonds = []
         self.send_command(CommandBuilder.sm_get_bonds())
 
@@ -238,7 +243,7 @@ def scan(self, timeout=10, scan_interval=75, scan_window=50, active=True,
 
         self.expect(ResponsePacketType.gap_discover)
 
-        log.debug("Pausing for for %ds to allow scan to complete", timeout)
+        log.info("Pausing for for %ds to allow scan to complete", timeout)
         time.sleep(timeout)
 
         log.info("Stopping scan")
@@ -252,6 +257,7 @@ def scan(self, timeout=10, scan_interval=75, scan_window=50, active=True,
                 'name': info.name,
                 'rssi': info.rssi
             })
+        log.info("Discovered %d devices: %s", len(devices), devices)
         self._devices_discovered = {}
         return devices
 
@@ -273,13 +279,13 @@ def connect(self, address, timeout=5,
         Raises BGAPIError or NotConnectedError on failure.
         """
 
-        address_bytes = [int(b, 16) for b in address.split(":")]
+        address_bytes = bytearray(unhexlify(address.replace(":", "")))
         for device in self._connections.values():
-            if device._address == address_bytes:
+            if device._address == bgapi_address_to_hex(address_bytes):
                 return device
 
-        log.debug("Connecting to device at address %s (timeout %ds)",
-                  address, timeout)
+        log.info("Connecting to device at address %s (timeout %ds)",
+                 address, timeout)
         self.set_bondable(False)
         self.send_command(
             CommandBuilder.gap_connect_direct(
@@ -298,15 +304,15 @@ def connect(self, address, timeout=5,
             if self._connection_status_flag(
                     packet['flags'],
                     constants.connection_status_flag['connected']):
-                device = BGAPIBLEDevice(packet['address'],
+                device = BGAPIBLEDevice(bgapi_address_to_hex(packet['address']),
                                         packet['connection_handle'],
                                         self)
                 if self._connection_status_flag(
                         packet['flags'],
                         constants.connection_status_flag['encrypted']):
                     device.encrypted = True
                 self._connections[packet['connection_handle']] = device
-                log.debug("Connected to %s", address)
+                log.info("Connected to %s", address)
                 return device
         except ExpectedResponseTimeout:
             raise NotConnectedError()
@@ -330,7 +336,7 @@ def discover_characteristics(self, connection_handle):
                      char_uuid_str, char_obj.handle)
             for desc_uuid_str, desc_handle in (
                     char_obj.descriptors.iteritems()):
-                log.info("Characteristic descriptor 0x%s is handle %x",
+                log.info("Characteristic descriptor 0x%s is handle 0x%x",
                          desc_uuid_str, desc_handle)
         return self._characteristics[connection_handle]
 
@@ -411,8 +417,9 @@ def _scan_rsp_data(self, data):
                           'complete_list_128-bit_service_class_uuids'):
                         data_dict[field_name] = []
                         for i in range(0, len(field_value)/16):  # 16 bytes
-                            service_uuid = '0x'+hexlify(bytearray(list(reversed(
-                                field_value[i*16:i*16+16]))))
+                            service_uuid = (
+                                "0x%s" %
+                                bgapi_address_to_hex(field_value[i*16:i*16+16]))
                             data_dict[field_name].append(service_uuid)
                     else:
                         data_dict[field_name] = bytearray(field_value)
@@ -437,8 +444,8 @@ def expect_any(self, expected_packet_choices, timeout=None,
             not receiving withint the time limit.
         """
         timeout = timeout or 1
-        log.info("Expecting a response of one of %s within %fs",
-                 expected_packet_choices, timeout or 0)
+        log.debug("Expecting a response of one of %s within %fs",
+                  expected_packet_choices, timeout or 0)
 
         start_time = None
         if timeout is not None:
@@ -521,8 +528,8 @@ def _ble_evt_attclient_find_information_found(self, args):
         raw_uuid = bytearray(reversed(args['uuid']))
         uuid_type = self._get_uuid_type(raw_uuid)
         if uuid_type != UUIDType.custom:
-            uuid = uuid16_to_uuid(
-                int(hexlify(bytearray(reversed(args['uuid']))), 16))
+            uuid = uuid16_to_uuid(int(
+                bgapi_address_to_hex(args['uuid']).replace(':', ''), 16))
         else:
             uuid = UUID(hexlify(raw_uuid))
 
@@ -585,8 +592,7 @@ def _ble_evt_gap_scan_response(self, args):
         """
         # Parse packet
         packet_type = constants.scan_response_packet_type[args['packet_type']]
-        address = ":".join(list(reversed(
-            [format(b, '02x') for b in args['sender']])))
+        address = bgapi_address_to_hex(args['sender'])
         name, data_dict = self._scan_rsp_data(args['data'])
 
         # Store device information
@@ -601,9 +607,8 @@ def _ble_evt_gap_scan_response(self, args):
                 len(dev.packet_data[packet_type]) < len(data_dict)):
             dev.packet_data[packet_type] = data_dict
         dev.rssi = args['rssi']
-        log.info("Received a scan response from %s with rssi=%d dBM "
-                 "and data=%s",
-                 address, args['rssi'], data_dict)
+        log.debug("Received a scan response from %s with rssi=%d dBM "
+                  "and data=%s", address, args['rssi'], data_dict)
 
     def _ble_evt_sm_bond_status(self, args):
         """
@@ -637,4 +642,4 @@ def _ble_rsp_sm_get_bonds(self, args):
         args -- dictionary containing the number of stored bonds ('bonds'),
         """
         self._num_bonds = args['bonds']
-        log.info("num bonds = %d", args['bonds'])
+        log.debug("num bonds = %d", args['bonds'])

pygatt/backends/bgapi/device.py

@@ -38,7 +38,7 @@ def bond(self, permanent=False):
         # Set to bondable mode so bonds are store permanently
         if permanent:
             self._backend.set_bondable(True)
-        log.info("Bonding to %s", self._address)
+        log.debug("Bonding to %s", self._address)
         self._backend.send_command(
             CommandBuilder.sm_encrypt_start(
                 self._handle, constants.bonding['create_bonding']))
@@ -49,6 +49,7 @@ def bond(self, permanent=False):
              EventPacketType.sm_bonding_fail])
         if packet_type == EventPacketType.sm_bonding_fail:
             raise BGAPIError("Bonding failed")
+        log.info("Bonded to %s", self._address)
 
     @connection_required
     def get_rssi(self):
@@ -96,7 +97,6 @@ def char_write_handle(self, char_handle, value, wait_for_response=False):
 
         while True:
             value_list = [b for b in value]
-            log.info("attribute_write")
             self._backend.send_command(
                 CommandBuilder.attclient_attribute_write(
                     self._handle, char_handle, value_list))

pygatt/backends/bgapi/util.py

@@ -87,5 +87,5 @@ def find_usb_serial_devices(vendor_id=None, product_id=None):
                 devices.append(dev)
             elif dev.product_id == product_id and dev.vendor_id == vendor_id:
                 devices.append(dev)
-            log.info("USB device: %s", dev)
+            log.debug("USB device: %s", dev)
     return devices

pygatt/device.py

@@ -108,9 +108,6 @@ def subscribe(self, uuid, callback=None, indication=False):
         indication -- use indications (where each notificaiton is ACKd). This is
                       more reliable, but slower.
         """
-        log.info(
-            'Subscribing to uuid=%s with callback=%s and indication=%s',
-            uuid, callback, indication)
         # Expect notifications on the value handle...
         value_handle = self.get_handle(uuid)
 
@@ -136,7 +133,7 @@ def subscribe(self, uuid, callback=None, indication=False):
                     properties,
                     wait_for_response=False
                 )
-                log.debug("Subscribed to uuid=%s", uuid)
+                log.info("Subscribed to uuid=%s", uuid)
                 self._subscribed_handlers[value_handle] = properties
             else:
                 log.debug("Already subscribed to uuid=%s", uuid)