diff --git a/meshtastic/__init__.py b/meshtastic/__init__.py index 7573e8b0..34cc7318 100644 --- a/meshtastic/__init__.py +++ b/meshtastic/__init__.py @@ -129,6 +129,7 @@ def onConnection(interface, topic=pub.AUTO_TOPIC): # called when we (re)connect publishingThread = DeferredExecution("publishing") +logger = logging.getLogger(__name__) class ResponseHandler(NamedTuple): """A pending response callback, waiting for a response to one of our messages""" @@ -160,31 +161,31 @@ def _onTextReceive(iface, asDict): # # Usually btw this problem is caused by apps sending binary data but setting the payload type to # text. - logging.debug(f"in _onTextReceive() asDict:{asDict}") + logger.debug(f"in _onTextReceive() asDict:{asDict}") try: asBytes = asDict["decoded"]["payload"] asDict["decoded"]["text"] = asBytes.decode("utf-8") except Exception as ex: - logging.error(f"Malformatted utf8 in text message: {ex}") + logger.error(f"Malformatted utf8 in text message: {ex}") _receiveInfoUpdate(iface, asDict) def _onPositionReceive(iface, asDict): """Special auto parsing for received messages""" - logging.debug(f"in _onPositionReceive() asDict:{asDict}") + logger.debug(f"in _onPositionReceive() asDict:{asDict}") if "decoded" in asDict: if "position" in asDict["decoded"] and "from" in asDict: p = asDict["decoded"]["position"] - logging.debug(f"p:{p}") + logger.debug(f"p:{p}") p = iface._fixupPosition(p) - logging.debug(f"after fixup p:{p}") + logger.debug(f"after fixup p:{p}") # update node DB as needed iface._getOrCreateByNum(asDict["from"])["position"] = p def _onNodeInfoReceive(iface, asDict): """Special auto parsing for received messages""" - logging.debug(f"in _onNodeInfoReceive() asDict:{asDict}") + logger.debug(f"in _onNodeInfoReceive() asDict:{asDict}") if "decoded" in asDict: if "user" in asDict["decoded"] and "from" in asDict: p = asDict["decoded"]["user"] @@ -198,7 +199,7 @@ def _onNodeInfoReceive(iface, asDict): def _onTelemetryReceive(iface, asDict): """Automatically update device metrics on received packets""" - logging.debug(f"in _onTelemetryReceive() asDict:{asDict}") + logger.debug(f"in _onTelemetryReceive() asDict:{asDict}") if "from" not in asDict: return @@ -222,7 +223,7 @@ def _onTelemetryReceive(iface, asDict): updateObj = telemetry.get(toUpdate) newMetrics = node.get(toUpdate, {}) newMetrics.update(updateObj) - logging.debug(f"updating {toUpdate} metrics for {asDict['from']} to {newMetrics}") + logger.debug(f"updating {toUpdate} metrics for {asDict['from']} to {newMetrics}") node[toUpdate] = newMetrics def _receiveInfoUpdate(iface, asDict): @@ -234,7 +235,7 @@ def _receiveInfoUpdate(iface, asDict): def _onAdminReceive(iface, asDict): """Special auto parsing for received messages""" - logging.debug(f"in _onAdminReceive() asDict:{asDict}") + logger.debug(f"in _onAdminReceive() asDict:{asDict}") if "decoded" in asDict and "from" in asDict and "admin" in asDict["decoded"]: adminMessage = asDict["decoded"]["admin"]["raw"] iface._getOrCreateByNum(asDict["from"])["adminSessionPassKey"] = adminMessage.session_passkey diff --git a/meshtastic/__main__.py b/meshtastic/__main__.py index a5d7c85f..3025bde1 100644 --- a/meshtastic/__main__.py +++ b/meshtastic/__main__.py @@ -9,6 +9,7 @@ from types import ModuleType import argparse + argcomplete: Union[None, ModuleType] = None try: import argcomplete # type: ignore @@ -62,12 +63,14 @@ from meshtastic.protobuf import channel_pb2, config_pb2, portnums_pb2 from meshtastic.version import get_active_version +logger = logging.getLogger(__name__) + def onReceive(packet, interface) -> None: """Callback invoked when a packet arrives""" args = mt_config.args try: d = packet.get("decoded") - logging.debug(f"in onReceive() d:{d}") + logger.debug(f"in onReceive() d:{d}") # Exit once we receive a reply if ( @@ -101,7 +104,7 @@ def onConnection(interface, topic=pub.AUTO_TOPIC) -> None: # pylint: disable=W0 def checkChannel(interface: MeshInterface, channelIndex: int) -> bool: """Given an interface and channel index, return True if that channel is non-disabled on the local node""" ch = interface.localNode.getChannelByChannelIndex(channelIndex) - logging.debug(f"ch:{ch}") + logger.debug(f"ch:{ch}") return ch and ch.role != channel_pb2.Channel.Role.DISABLED @@ -114,7 +117,7 @@ def _printSetting(config_type, uni_name, pref_value, repeated): else: pref_value = meshtastic.util.toStr(pref_value) print(f"{str(config_type.name)}.{uni_name}: {str(pref_value)}") - logging.debug(f"{str(config_type.name)}.{uni_name}: {str(pref_value)}") + logger.debug(f"{str(config_type.name)}.{uni_name}: {str(pref_value)}") name = splitCompoundName(comp_name) wholeField = name[0] == name[1] # We want the whole field @@ -123,8 +126,8 @@ def _printSetting(config_type, uni_name, pref_value, repeated): # Note: protobufs has the keys in snake_case, so snake internally snake_name = meshtastic.util.camel_to_snake(name[1]) uni_name = camel_name if mt_config.camel_case else snake_name - logging.debug(f"snake_name:{snake_name} camel_name:{camel_name}") - logging.debug(f"use camel:{mt_config.camel_case}") + logger.debug(f"snake_name:{snake_name} camel_name:{camel_name}") + logger.debug(f"use camel:{mt_config.camel_case}") # First validate the input localConfig = node.localConfig @@ -198,8 +201,8 @@ def setPref(config, comp_name, raw_val) -> bool: snake_name = meshtastic.util.camel_to_snake(name[-1]) camel_name = meshtastic.util.snake_to_camel(name[-1]) uni_name = camel_name if mt_config.camel_case else snake_name - logging.debug(f"snake_name:{snake_name}") - logging.debug(f"camel_name:{camel_name}") + logger.debug(f"snake_name:{snake_name}") + logger.debug(f"camel_name:{camel_name}") objDesc = config.DESCRIPTOR config_part = config @@ -223,7 +226,7 @@ def setPref(config, comp_name, raw_val) -> bool: val = meshtastic.util.fromStr(raw_val) else: val = raw_val - logging.debug(f"valStr:{raw_val} val:{val}") + logger.debug(f"valStr:{raw_val} val:{val}") if snake_name == "wifi_psk" and len(str(raw_val)) < 8: print("Warning: network.wifi_psk must be 8 or more characters.") @@ -603,7 +606,7 @@ def onConnected(interface): time.sleep(1) if interface.gotResponse: break - logging.debug(f"end of gpio_rd") + logger.debug(f"end of gpio_rd") if args.gpio_watch: bitmask = int(args.gpio_watch, 16) @@ -1059,7 +1062,7 @@ def setSimpleConfig(modem_preset): # Even if others said we could close, stay open if the user asked for a tunnel closeNow = False if interface.noProto: - logging.warning(f"Not starting Tunnel - disabled by noProto") + logger.warning(f"Not starting Tunnel - disabled by noProto") else: if args.tunnel_net: tunnel.Tunnel(interface, subnet=args.tunnel_net) @@ -1250,14 +1253,14 @@ def create_power_meter(): meter = SimPowerSupply() if meter and v: - logging.info(f"Setting power supply to {v} volts") + logger.info(f"Setting power supply to {v} volts") meter.v = v meter.powerOn() if args.power_wait: input("Powered on, press enter to continue...") else: - logging.info("Powered-on, waiting for device to boot") + logger.info("Powered-on, waiting for device to boot") time.sleep(5) @@ -1312,7 +1315,7 @@ def common(): args.seriallog = "none" # assume no debug output in this case if args.deprecated is not None: - logging.error( + logger.error( "This option has been deprecated, see help below for the correct replacement..." ) parser.print_help(sys.stderr) @@ -1331,10 +1334,10 @@ def common(): logfile = sys.stdout elif args.seriallog == "none": args.seriallog = None - logging.debug("Not logging serial output") + logger.debug("Not logging serial output") logfile = None else: - logging.info(f"Logging serial output to {args.seriallog}") + logger.info(f"Logging serial output to {args.seriallog}") # Note: using "line buffering" # pylint: disable=R1732 logfile = open(args.seriallog, "w+", buffering=1, encoding="utf8") @@ -1342,7 +1345,7 @@ def common(): subscribe() if args.ble_scan: - logging.debug("BLE scan starting") + logger.debug("BLE scan starting") for x in BLEInterface.scan(): print(f"Found: name='{x.name}' address='{x.address}'") meshtastic.util.our_exit("BLE scan finished", 0) @@ -1433,7 +1436,7 @@ def common(): while True: time.sleep(1000) except KeyboardInterrupt: - logging.info("Exiting due to keyboard interrupt") + logger.info("Exiting due to keyboard interrupt") # don't call exit, background threads might be running still # sys.exit(0) diff --git a/meshtastic/analysis/__main__.py b/meshtastic/analysis/__main__.py index 50505a6c..34cf39e4 100644 --- a/meshtastic/analysis/__main__.py +++ b/meshtastic/analysis/__main__.py @@ -2,6 +2,7 @@ import argparse import logging +from pathlib import Path from typing import cast, List import dash_bootstrap_components as dbc # type: ignore[import-untyped] @@ -190,7 +191,7 @@ def main(): parser = create_argparser() args = parser.parse_args() if not args.slog: - args.slog = f"{root_dir()}/latest" + args.slog = str(Path(root_dir(), "latest")) app = create_dash(slog_path=args.slog) port = 8051 diff --git a/meshtastic/ble_interface.py b/meshtastic/ble_interface.py index 71b957f2..e65d3396 100644 --- a/meshtastic/ble_interface.py +++ b/meshtastic/ble_interface.py @@ -23,6 +23,7 @@ FROMNUM_UUID = "ed9da18c-a800-4f66-a670-aa7547e34453" LEGACY_LOGRADIO_UUID = "6c6fd238-78fa-436b-aacf-15c5be1ef2e2" LOGRADIO_UUID = "5a3d6e49-06e6-4423-9944-e9de8cdf9547" +logger = logging.getLogger(__name__) class BLEInterface(MeshInterface): @@ -44,19 +45,19 @@ def __init__( self.should_read = False - logging.debug("Threads starting") + logger.debug("Threads starting") self._want_receive = True self._receiveThread: Optional[Thread] = Thread( target=self._receiveFromRadioImpl, name="BLEReceive", daemon=True ) self._receiveThread.start() - logging.debug("Threads running") + logger.debug("Threads running") self.client: Optional[BLEClient] = None try: - logging.debug(f"BLE connecting to: {address if address else 'any'}") + logger.debug(f"BLE connecting to: {address if address else 'any'}") self.client = self.connect(address) - logging.debug("BLE connected") + logger.debug("BLE connected") except BLEInterface.BLEError as e: self.close() raise e @@ -69,13 +70,13 @@ def __init__( if self.client.has_characteristic(LOGRADIO_UUID): self.client.start_notify(LOGRADIO_UUID, self.log_radio_handler) - logging.debug("Mesh configure starting") + logger.debug("Mesh configure starting") self._startConfig() if not self.noProto: self._waitConnected(timeout=60.0) self.waitForConfig() - logging.debug("Register FROMNUM notify callback") + logger.debug("Register FROMNUM notify callback") self.client.start_notify(FROMNUM_UUID, self.from_num_handler) # We MUST run atexit (if we can) because otherwise (at least on linux) the BLE device is not disconnected @@ -99,7 +100,7 @@ def from_num_handler(self, _, b: bytes) -> None: # pylint: disable=C0116 Note: this method does not need to be async because it is just setting a bool. """ from_num = struct.unpack(" List[BLEDevice]: """Scan for available BLE devices.""" with BLEClient() as client: - logging.info("Scanning for BLE devices (takes 10 seconds)...") + logger.info("Scanning for BLE devices (takes 10 seconds)...") response = client.discover( timeout=10, return_adv=True, service_uuids=[SERVICE_UUID] ) @@ -186,19 +187,19 @@ def _receiveFromRadioImpl(self) -> None: retries: int = 0 while self._want_receive: if self.client is None: - logging.debug(f"BLE client is None, shutting down") + logger.debug(f"BLE client is None, shutting down") self._want_receive = False continue try: b = bytes(self.client.read_gatt_char(FROMRADIO_UUID)) except BleakDBusError as e: # Device disconnected probably, so end our read loop immediately - logging.debug(f"Device disconnected, shutting down {e}") + logger.debug(f"Device disconnected, shutting down {e}") self._want_receive = False except BleakError as e: # We were definitely disconnected if "Not connected" in str(e): - logging.debug(f"Device disconnected, shutting down {e}") + logger.debug(f"Device disconnected, shutting down {e}") self._want_receive = False else: raise BLEInterface.BLEError("Error reading BLE") from e @@ -208,7 +209,7 @@ def _receiveFromRadioImpl(self) -> None: retries += 1 continue break - logging.debug(f"FROMRADIO read: {b.hex()}") + logger.debug(f"FROMRADIO read: {b.hex()}") self._handleFromRadio(b) else: time.sleep(0.01) @@ -216,7 +217,7 @@ def _receiveFromRadioImpl(self) -> None: def _sendToRadioImpl(self, toRadio) -> None: b: bytes = toRadio.SerializeToString() if b and self.client: # we silently ignore writes while we are shutting down - logging.debug(f"TORADIO write: {b.hex()}") + logger.debug(f"TORADIO write: {b.hex()}") try: self.client.write_gatt_char( TORADIO_UUID, b, response=True @@ -234,7 +235,7 @@ def close(self) -> None: try: MeshInterface.close(self) except Exception as e: - logging.error(f"Error closing mesh interface: {e}") + logger.error(f"Error closing mesh interface: {e}") if self._want_receive: self._want_receive = False # Tell the thread we want it to stop @@ -263,7 +264,7 @@ def __init__(self, address=None, **kwargs) -> None: self._eventThread.start() if not address: - logging.debug("No address provided - only discover method will work.") + logger.debug("No address provided - only discover method will work.") return self.bleak_client = BleakClient(address, **kwargs) diff --git a/meshtastic/mesh_interface.py b/meshtastic/mesh_interface.py index 50ff0d8c..4ec9b80d 100644 --- a/meshtastic/mesh_interface.py +++ b/meshtastic/mesh_interface.py @@ -17,6 +17,7 @@ from typing import Any, Callable, Dict, List, Optional, Union import google.protobuf.json_format + try: import print_color # type: ignore[import-untyped] except ImportError as e: @@ -46,6 +47,7 @@ stripnl, ) +logger = logging.getLogger(__name__) def _timeago(delta_secs: int) -> str: """Convert a number of seconds in the past into a short, friendly string @@ -149,11 +151,11 @@ def __enter__(self): def __exit__(self, exc_type, exc_value, trace): if exc_type is not None and exc_value is not None: - logging.error( + logger.error( f"An exception of type {exc_type} with value {exc_value} has occurred" ) if trace is not None: - logging.error(f"Traceback: {trace}") + logger.error(f"Traceback:\n{''.join(traceback.format_tb(trace))}") self.close() @staticmethod @@ -281,7 +283,7 @@ def getTimeAgo(ts) -> Optional[str]: def getNestedValue(node_dict: Dict[str, Any], key_path: str) -> Any: if key_path.index(".") < 0: - logging.debug("getNestedValue was called without a nested path.") + logger.debug("getNestedValue was called without a nested path.") return None keys = key_path.split(".") value: Optional[Union[str, dict]] = node_dict @@ -304,7 +306,7 @@ def getNestedValue(node_dict: Dict[str, Any], key_path: str) -> Any: rows: List[Dict[str, Any]] = [] if self.nodesByNum: - logging.debug(f"self.nodes:{self.nodes}") + logger.debug(f"self.nodes:{self.nodes}") for node in self.nodesByNum.values(): if not includeSelf and node["num"] == self.localNode.nodeNum: continue @@ -383,7 +385,7 @@ def getNode( n = meshtastic.node.Node(self, nodeId, timeout=timeout) # Only request device settings and channel info when necessary if requestChannels: - logging.debug("About to requestChannels") + logger.debug("About to requestChannels") n.requestChannels() retries_left = requestChannelAttempts last_index: int = 0 @@ -538,11 +540,11 @@ def sendData( """ if getattr(data, "SerializeToString", None): - logging.debug(f"Serializing protobuf as data: {stripnl(data)}") + logger.debug(f"Serializing protobuf as data: {stripnl(data)}") data = data.SerializeToString() - logging.debug(f"len(data): {len(data)}") - logging.debug( + logger.debug(f"len(data): {len(data)}") + logger.debug( f"mesh_pb2.Constants.DATA_PAYLOAD_LEN: {mesh_pb2.Constants.DATA_PAYLOAD_LEN}" ) if len(data) > mesh_pb2.Constants.DATA_PAYLOAD_LEN: @@ -565,7 +567,7 @@ def sendData( meshPacket.priority = priority if onResponse is not None: - logging.debug(f"Setting a response handler for requestId {meshPacket.id}") + logger.debug(f"Setting a response handler for requestId {meshPacket.id}") self._addResponseHandler(meshPacket.id, onResponse, ackPermitted=onResponseAckPermitted) p = self._sendPacket(meshPacket, destinationId, wantAck=wantAck, hopLimit=hopLimit, pkiEncrypted=pkiEncrypted, publicKey=publicKey) return p @@ -592,15 +594,15 @@ def sendPosition( p = mesh_pb2.Position() if latitude != 0.0: p.latitude_i = int(latitude / 1e-7) - logging.debug(f"p.latitude_i:{p.latitude_i}") + logger.debug(f"p.latitude_i:{p.latitude_i}") if longitude != 0.0: p.longitude_i = int(longitude / 1e-7) - logging.debug(f"p.longitude_i:{p.longitude_i}") + logger.debug(f"p.longitude_i:{p.longitude_i}") if altitude != 0: p.altitude = int(altitude) - logging.debug(f"p.altitude:{p.altitude}") + logger.debug(f"p.altitude:{p.altitude}") if wantResponse: onResponse = self.onResponsePosition @@ -851,15 +853,15 @@ def sendWaypoint( # same algorithm as https://github.com/meshtastic/js/blob/715e35d2374276a43ffa93c628e3710875d43907/src/meshDevice.ts#L791 seed = secrets.randbits(32) w.id = math.floor(seed * math.pow(2, -32) * 1e9) - logging.debug(f"w.id:{w.id}") + logger.debug(f"w.id:{w.id}") else: w.id = waypoint_id if latitude != 0.0: w.latitude_i = int(latitude * 1e7) - logging.debug(f"w.latitude_i:{w.latitude_i}") + logger.debug(f"w.latitude_i:{w.latitude_i}") if longitude != 0.0: w.longitude_i = int(longitude * 1e7) - logging.debug(f"w.longitude_i:{w.longitude_i}") + logger.debug(f"w.longitude_i:{w.longitude_i}") if wantResponse: onResponse = self.onResponseWaypoint @@ -974,7 +976,7 @@ def _sendPacket( else: nodeNum = node["num"] else: - logging.warning("Warning: There were no self.nodes.") + logger.warning("Warning: There were no self.nodes.") meshPacket.to = nodeNum meshPacket.want_ack = wantAck @@ -998,11 +1000,11 @@ def _sendPacket( toRadio.packet.CopyFrom(meshPacket) if self.noProto: - logging.warning( + logger.warning( "Not sending packet because protocol use is disabled by noProto" ) else: - logging.debug(f"Sending packet: {stripnl(meshPacket)}") + logger.debug(f"Sending packet: {stripnl(meshPacket)}") self._sendToRadio(toRadio) return meshPacket @@ -1053,7 +1055,7 @@ def getMyNodeInfo(self) -> Optional[Dict]: """Get info about my node.""" if self.myInfo is None or self.nodesByNum is None: return None - logging.debug(f"self.nodesByNum:{self.nodesByNum}") + logger.debug(f"self.nodesByNum:{self.nodesByNum}") return self.nodesByNum.get(self.myInfo.my_node_num) def getMyUser(self): @@ -1143,7 +1145,7 @@ def _startHeartbeat(self): def callback(): self.heartbeatTimer = None interval = 300 - logging.debug(f"Sending heartbeat, interval {interval} seconds") + logger.debug(f"Sending heartbeat, interval {interval} seconds") self.heartbeatTimer = threading.Timer(interval, callback) self.heartbeatTimer.start() self.sendHeartbeat() @@ -1201,11 +1203,11 @@ def _queueClaim(self) -> None: def _sendToRadio(self, toRadio: mesh_pb2.ToRadio) -> None: """Send a ToRadio protobuf to the device""" if self.noProto: - logging.warning( + logger.warning( "Not sending packet because protocol use is disabled by noProto" ) else: - # logging.debug(f"Sending toRadio: {stripnl(toRadio)}") + # logger.debug(f"Sending toRadio: {stripnl(toRadio)}") if not toRadio.HasField("packet"): # not a meshpacket -- send immediately, give queue a chance, @@ -1218,38 +1220,38 @@ def _sendToRadio(self, toRadio: mesh_pb2.ToRadio) -> None: resentQueue = collections.OrderedDict() while self.queue: - # logging.warn("queue: " + " ".join(f'{k:08x}' for k in self.queue)) + # logger.warn("queue: " + " ".join(f'{k:08x}' for k in self.queue)) while not self._queueHasFreeSpace(): - logging.debug("Waiting for free space in TX Queue") + logger.debug("Waiting for free space in TX Queue") time.sleep(0.5) try: toResend = self.queue.popitem(last=False) except KeyError: break packetId, packet = toResend - # logging.warn(f"packet: {packetId:08x} {packet}") + # logger.warn(f"packet: {packetId:08x} {packet}") resentQueue[packetId] = packet if packet is False: continue self._queueClaim() if packet != toRadio: - logging.debug(f"Resending packet ID {packetId:08x} {packet}") + logger.debug(f"Resending packet ID {packetId:08x} {packet}") self._sendToRadioImpl(packet) - # logging.warn("resentQueue: " + " ".join(f'{k:08x}' for k in resentQueue)) + # logger.warn("resentQueue: " + " ".join(f'{k:08x}' for k in resentQueue)) for packetId, packet in resentQueue.items(): if ( self.queue.pop(packetId, False) is False ): # Packet got acked under us - logging.debug(f"packet {packetId:08x} got acked under us") + logger.debug(f"packet {packetId:08x} got acked under us") continue if packet: self.queue[packetId] = packet - # logging.warn("queue + resentQueue: " + " ".join(f'{k:08x}' for k in self.queue)) + # logger.warn("queue + resentQueue: " + " ".join(f'{k:08x}' for k in self.queue)) def _sendToRadioImpl(self, toRadio: mesh_pb2.ToRadio) -> None: """Send a ToRadio protobuf to the device""" - logging.error(f"Subclass must provide toradio: {toRadio}") + logger.error(f"Subclass must provide toradio: {toRadio}") def _handleConfigComplete(self) -> None: """ @@ -1265,22 +1267,22 @@ def _handleConfigComplete(self) -> None: def _handleQueueStatusFromRadio(self, queueStatus) -> None: self.queueStatus = queueStatus - logging.debug( + logger.debug( f"TX QUEUE free {queueStatus.free} of {queueStatus.maxlen}, res = {queueStatus.res}, id = {queueStatus.mesh_packet_id:08x} " ) if queueStatus.res: return - # logging.warn("queue: " + " ".join(f'{k:08x}' for k in self.queue)) + # logger.warn("queue: " + " ".join(f'{k:08x}' for k in self.queue)) justQueued = self.queue.pop(queueStatus.mesh_packet_id, None) if justQueued is None and queueStatus.mesh_packet_id != 0: self.queue[queueStatus.mesh_packet_id] = False - logging.debug( + logger.debug( f"Reply for unexpected packet ID {queueStatus.mesh_packet_id:08x}" ) - # logging.warn("queue: " + " ".join(f'{k:08x}' for k in self.queue)) + # logger.warn("queue: " + " ".join(f'{k:08x}' for k in self.queue)) def _handleFromRadio(self, fromRadioBytes): """ @@ -1288,30 +1290,30 @@ def _handleFromRadio(self, fromRadioBytes): Called by subclasses.""" fromRadio = mesh_pb2.FromRadio() - logging.debug( + logger.debug( f"in mesh_interface.py _handleFromRadio() fromRadioBytes: {fromRadioBytes}" ) try: fromRadio.ParseFromString(fromRadioBytes) except Exception as ex: - logging.error( + logger.error( f"Error while parsing FromRadio bytes:{fromRadioBytes} {ex}" ) traceback.print_exc() raise ex asDict = google.protobuf.json_format.MessageToDict(fromRadio) - logging.debug(f"Received from radio: {fromRadio}") + logger.debug(f"Received from radio: {fromRadio}") if fromRadio.HasField("my_info"): self.myInfo = fromRadio.my_info self.localNode.nodeNum = self.myInfo.my_node_num - logging.debug(f"Received myinfo: {stripnl(fromRadio.my_info)}") + logger.debug(f"Received myinfo: {stripnl(fromRadio.my_info)}") elif fromRadio.HasField("metadata"): self.metadata = fromRadio.metadata - logging.debug(f"Received device metadata: {stripnl(fromRadio.metadata)}") + logger.debug(f"Received device metadata: {stripnl(fromRadio.metadata)}") elif fromRadio.HasField("node_info"): - logging.debug(f"Received nodeinfo: {asDict['nodeInfo']}") + logger.debug(f"Received nodeinfo: {asDict['nodeInfo']}") node = self._getOrCreateByNum(asDict["nodeInfo"]["num"]) node.update(asDict["nodeInfo"]) @@ -1319,7 +1321,7 @@ def _handleFromRadio(self, fromRadioBytes): newpos = self._fixupPosition(node["position"]) node["position"] = newpos except: - logging.debug("Node without position") + logger.debug("Node without position") # no longer necessary since we're mutating directly in nodesByNum via _getOrCreateByNum # self.nodesByNum[node["num"]] = node @@ -1334,7 +1336,7 @@ def _handleFromRadio(self, fromRadioBytes): elif fromRadio.config_complete_id == self.configId: # we ignore the config_complete_id, it is unneeded for our # stream API fromRadio.config_complete_id - logging.debug(f"Config complete ID {self.configId}") + logger.debug(f"Config complete ID {self.configId}") self._handleConfigComplete() elif fromRadio.HasField("channel"): self._handleChannel(fromRadio.channel) @@ -1449,7 +1451,7 @@ def _handleFromRadio(self, fromRadioBytes): ) else: - logging.debug("Unexpected FromRadio payload") + logger.debug("Unexpected FromRadio payload") def _fixupPosition(self, position: Dict) -> Dict: """Convert integer lat/lon into floats @@ -1483,7 +1485,7 @@ def _nodeNumToId(self, num: int, isDest = True) -> Optional[str]: try: return self.nodesByNum[num]["user"]["id"] # type: ignore[index] except: - logging.debug(f"Node {num} not found for fromId") + logger.debug(f"Node {num} not found for fromId") return None def _getOrCreateByNum(self, nodeNum): @@ -1539,7 +1541,7 @@ def _handlePacketFromRadio(self, meshPacket, hack=False): # from might be missing if the nodenum was zero. if not hack and "from" not in asDict: asDict["from"] = 0 - logging.error( + logger.error( f"Device returned a packet we sent, ignoring: {stripnl(asDict)}" ) print( @@ -1553,11 +1555,11 @@ def _handlePacketFromRadio(self, meshPacket, hack=False): try: asDict["fromId"] = self._nodeNumToId(asDict["from"], False) except Exception as ex: - logging.warning(f"Not populating fromId {ex}") + logger.warning(f"Not populating fromId {ex}") try: asDict["toId"] = self._nodeNumToId(asDict["to"]) except Exception as ex: - logging.warning(f"Not populating toId {ex}") + logger.warning(f"Not populating toId {ex}") # We could provide our objects as DotMaps - which work with . notation or as dictionaries # asObj = DotMap(asDict) @@ -1577,7 +1579,7 @@ def _handlePacketFromRadio(self, meshPacket, hack=False): # it to prevent confusion if "portnum" not in decoded: decoded["portnum"] = portnum - logging.warning(f"portnum was not in decoded. Setting to:{portnum}") + logger.warning(f"portnum was not in decoded. Setting to:{portnum}") else: portnum = decoded["portnum"] @@ -1609,7 +1611,7 @@ def _handlePacketFromRadio(self, meshPacket, hack=False): # Is this message in response to a request, if so, look for a handler requestId = decoded.get("requestId") if requestId is not None: - logging.debug(f"Got a response for requestId {requestId}") + logger.debug(f"Got a response for requestId {requestId}") # We ignore ACK packets unless the callback is named `onAckNak` # or the handler is set as ackPermitted, but send NAKs and # other, data-containing responses to the handlers @@ -1626,12 +1628,12 @@ def _handlePacketFromRadio(self, meshPacket, hack=False): or handler.ackPermitted ): handler = self.responseHandlers.pop(requestId, None) - logging.debug( + logger.debug( f"Calling response handler for requestId {requestId}" ) handler.callback(asDict) - logging.debug(f"Publishing {topic}: packet={stripnl(asDict)} ") + logger.debug(f"Publishing {topic}: packet={stripnl(asDict)} ") publishingThread.queueWork( lambda: pub.sendMessage(topic, packet=asDict, interface=self) ) diff --git a/meshtastic/node.py b/meshtastic/node.py index e6bd3ca6..a6507632 100644 --- a/meshtastic/node.py +++ b/meshtastic/node.py @@ -18,6 +18,7 @@ message_to_json, ) +logger = logging.getLogger(__name__) class Node: """A model of a (local or remote) node in the mesh @@ -55,7 +56,7 @@ def showChannels(self): """Show human readable description of our channels.""" print("Channels:") if self.channels: - logging.debug(f"self.channels:{self.channels}") + logger.debug(f"self.channels:{self.channels}") for c in self.channels: cStr = message_to_json(c.settings) # don't show disabled channels @@ -88,7 +89,7 @@ def setChannels(self, channels): def requestChannels(self, startingIndex: int = 0): """Send regular MeshPackets to ask channels.""" - logging.debug(f"requestChannels for nodeNum:{self.nodeNum}") + logger.debug(f"requestChannels for nodeNum:{self.nodeNum}") # only initialize if we're starting out fresh if startingIndex == 0: self.channels = None @@ -97,7 +98,7 @@ def requestChannels(self, startingIndex: int = 0): def onResponseRequestSettings(self, p): """Handle the response packets for requesting settings _requestSettings()""" - logging.debug(f"onResponseRequestSetting() p:{p}") + logger.debug(f"onResponseRequestSetting() p:{p}") config_values = None if "routing" in p["decoded"]: if p["decoded"]["routing"]["errorReason"] != "NONE": @@ -224,7 +225,7 @@ def writeConfig(self, config_name): else: our_exit(f"Error: No valid config with name {config_name}") - logging.debug(f"Wrote: {config_name}") + logger.debug(f"Wrote: {config_name}") if self == self.iface.localNode: onResponse = None else: @@ -237,7 +238,7 @@ def writeChannel(self, channelIndex, adminIndex=0): p = admin_pb2.AdminMessage() p.set_channel.CopyFrom(self.channels[channelIndex]) self._sendAdmin(p, adminIndex=adminIndex) - logging.debug(f"Wrote channel {channelIndex}") + logger.debug(f"Wrote channel {channelIndex}") def getChannelByChannelIndex(self, channelIndex): """Get channel by channelIndex @@ -300,7 +301,7 @@ def _getAdminChannelIndex(self): def setOwner(self, long_name: Optional[str]=None, short_name: Optional[str]=None, is_licensed: bool=False, is_unmessagable: Optional[bool]=None): """Set device owner name""" - logging.debug(f"in setOwner nodeNum:{self.nodeNum}") + logger.debug(f"in setOwner nodeNum:{self.nodeNum}") self.ensureSessionKey() p = admin_pb2.AdminMessage() @@ -325,10 +326,10 @@ def setOwner(self, long_name: Optional[str]=None, short_name: Optional[str]=None p.set_owner.is_unmessagable = is_unmessagable # Note: These debug lines are used in unit tests - logging.debug(f"p.set_owner.long_name:{p.set_owner.long_name}:") - logging.debug(f"p.set_owner.short_name:{p.set_owner.short_name}:") - logging.debug(f"p.set_owner.is_licensed:{p.set_owner.is_licensed}") - logging.debug(f"p.set_owner.is_unmessagable:{p.set_owner.is_unmessagable}:") + logger.debug(f"p.set_owner.long_name:{p.set_owner.long_name}:") + logger.debug(f"p.set_owner.short_name:{p.set_owner.short_name}:") + logger.debug(f"p.set_owner.is_licensed:{p.set_owner.is_licensed}") + logger.debug(f"p.set_owner.is_unmessagable:{p.set_owner.is_unmessagable}:") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: onResponse = None @@ -411,7 +412,7 @@ def setURL(self, url: str, addOnly: bool = False): ch.index = i ch.settings.CopyFrom(chs) self.channels[ch.index] = ch - logging.debug(f"Channel i:{i} ch:{ch}") + logger.debug(f"Channel i:{i} ch:{ch}") self.writeChannel(ch.index) i = i + 1 @@ -422,7 +423,7 @@ def setURL(self, url: str, addOnly: bool = False): def onResponseRequestRingtone(self, p): """Handle the response packet for requesting ringtone part 1""" - logging.debug(f"onResponseRequestRingtone() p:{p}") + logger.debug(f"onResponseRequestRingtone() p:{p}") errorFound = False if "routing" in p["decoded"]: if p["decoded"]["routing"]["errorReason"] != "NONE": @@ -435,12 +436,12 @@ def onResponseRequestRingtone(self, p): self.ringtonePart = p["decoded"]["admin"][ "raw" ].get_ringtone_response - logging.debug(f"self.ringtonePart:{self.ringtonePart}") + logger.debug(f"self.ringtonePart:{self.ringtonePart}") self.gotResponse = True def get_ringtone(self): """Get the ringtone. Concatenate all pieces together and return a single string.""" - logging.debug(f"in get_ringtone()") + logger.debug(f"in get_ringtone()") if not self.ringtone: p1 = admin_pb2.AdminMessage() p1.get_ringtone_request = True @@ -451,13 +452,13 @@ def get_ringtone(self): while self.gotResponse is False: time.sleep(0.1) - logging.debug(f"self.ringtone:{self.ringtone}") + logger.debug(f"self.ringtone:{self.ringtone}") self.ringtone = "" if self.ringtonePart: self.ringtone += self.ringtonePart - logging.debug(f"ringtone:{self.ringtone}") + logger.debug(f"ringtone:{self.ringtone}") return self.ringtone def set_ringtone(self, ringtone): @@ -481,7 +482,7 @@ def set_ringtone(self, ringtone): if i == 0: p.set_ringtone_message = chunk - logging.debug(f"Setting ringtone '{chunk}' part {i+1}") + logger.debug(f"Setting ringtone '{chunk}' part {i+1}") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: onResponse = None @@ -491,7 +492,7 @@ def set_ringtone(self, ringtone): def onResponseRequestCannedMessagePluginMessageMessages(self, p): """Handle the response packet for requesting canned message plugin message part 1""" - logging.debug(f"onResponseRequestCannedMessagePluginMessageMessages() p:{p}") + logger.debug(f"onResponseRequestCannedMessagePluginMessageMessages() p:{p}") errorFound = False if "routing" in p["decoded"]: if p["decoded"]["routing"]["errorReason"] != "NONE": @@ -504,14 +505,14 @@ def onResponseRequestCannedMessagePluginMessageMessages(self, p): self.cannedPluginMessageMessages = p["decoded"]["admin"][ "raw" ].get_canned_message_module_messages_response - logging.debug( + logger.debug( f"self.cannedPluginMessageMessages:{self.cannedPluginMessageMessages}" ) self.gotResponse = True def get_canned_message(self): """Get the canned message string. Concatenate all pieces together and return a single string.""" - logging.debug(f"in get_canned_message()") + logger.debug(f"in get_canned_message()") if not self.cannedPluginMessage: p1 = admin_pb2.AdminMessage() p1.get_canned_message_module_messages_request = True @@ -524,7 +525,7 @@ def get_canned_message(self): while self.gotResponse is False: time.sleep(0.1) - logging.debug( + logger.debug( f"self.cannedPluginMessageMessages:{self.cannedPluginMessageMessages}" ) @@ -532,7 +533,7 @@ def get_canned_message(self): if self.cannedPluginMessageMessages: self.cannedPluginMessage += self.cannedPluginMessageMessages - logging.debug(f"canned_plugin_message:{self.cannedPluginMessage}") + logger.debug(f"canned_plugin_message:{self.cannedPluginMessage}") return self.cannedPluginMessage def set_canned_message(self, message): @@ -556,7 +557,7 @@ def set_canned_message(self, message): if i == 0: p.set_canned_message_module_messages = chunk - logging.debug(f"Setting canned message '{chunk}' part {i+1}") + logger.debug(f"Setting canned message '{chunk}' part {i+1}") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: onResponse = None @@ -570,7 +571,7 @@ def exitSimulator(self): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.exit_simulator = True - logging.debug("in exitSimulator()") + logger.debug("in exitSimulator()") return self._sendAdmin(p) @@ -579,7 +580,7 @@ def reboot(self, secs: int = 10): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.reboot_seconds = secs - logging.info(f"Telling node to reboot in {secs} seconds") + logger.info(f"Telling node to reboot in {secs} seconds") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -593,7 +594,7 @@ def beginSettingsTransaction(self): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.begin_edit_settings = True - logging.info(f"Telling open a transaction to edit settings") + logger.info(f"Telling open a transaction to edit settings") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -607,7 +608,7 @@ def commitSettingsTransaction(self): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.commit_edit_settings = True - logging.info(f"Telling node to commit open transaction for editing settings") + logger.info(f"Telling node to commit open transaction for editing settings") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -621,7 +622,7 @@ def rebootOTA(self, secs: int = 10): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.reboot_ota_seconds = secs - logging.info(f"Telling node to reboot to OTA in {secs} seconds") + logger.info(f"Telling node to reboot to OTA in {secs} seconds") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -635,7 +636,7 @@ def enterDFUMode(self): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.enter_dfu_mode_request = True - logging.info(f"Telling node to enable DFU mode") + logger.info(f"Telling node to enable DFU mode") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -649,7 +650,7 @@ def shutdown(self, secs: int = 10): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.shutdown_seconds = secs - logging.info(f"Telling node to shutdown in {secs} seconds") + logger.info(f"Telling node to shutdown in {secs} seconds") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -662,7 +663,7 @@ def getMetadata(self): """Get the node's metadata.""" p = admin_pb2.AdminMessage() p.get_device_metadata_request = True - logging.info(f"Requesting device metadata") + logger.info(f"Requesting device metadata") self._sendAdmin( p, wantResponse=True, onResponse=self.onRequestGetMetadata @@ -675,10 +676,10 @@ def factoryReset(self, full: bool = False): p = admin_pb2.AdminMessage() if full: p.factory_reset_device = True - logging.info(f"Telling node to factory reset (full device reset)") + logger.info(f"Telling node to factory reset (full device reset)") else: p.factory_reset_config = True - logging.info(f"Telling node to factory reset (config reset)") + logger.info(f"Telling node to factory reset (config reset)") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -782,7 +783,7 @@ def resetNodeDb(self): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.nodedb_reset = True - logging.info(f"Telling node to reset the NodeDB") + logger.info(f"Telling node to reset the NodeDB") # If sending to a remote node, wait for ACK/NAK if self == self.iface.localNode: @@ -823,7 +824,7 @@ def removeFixedPosition(self): self.ensureSessionKey() p = admin_pb2.AdminMessage() p.remove_fixed_position = True - logging.info(f"Telling node to remove fixed position") + logger.info(f"Telling node to remove fixed position") if self == self.iface.localNode: onResponse = None @@ -838,7 +839,7 @@ def setTime(self, timeSec: int = 0): timeSec = int(time.time()) p = admin_pb2.AdminMessage() p.set_time_only = timeSec - logging.info(f"Setting node time to {timeSec}") + logger.info(f"Setting node time to {timeSec}") if self == self.iface.localNode: onResponse = None @@ -870,7 +871,7 @@ def _fillChannels(self): def onRequestGetMetadata(self, p): """Handle the response packet for requesting device metadata getMetadata()""" - logging.debug(f"onRequestGetMetadata() p:{p}") + logger.debug(f"onRequestGetMetadata() p:{p}") if "routing" in p["decoded"]: if p["decoded"]["routing"]["errorReason"] != "NONE": @@ -882,30 +883,30 @@ def onRequestGetMetadata(self, p): portnums_pb2.PortNum.ROUTING_APP ): if p["decoded"]["routing"]["errorReason"] != "NONE": - logging.warning( + logger.warning( f'Metadata request failed, error reason: {p["decoded"]["routing"]["errorReason"]}' ) self._timeout.expireTime = time.time() # Do not wait any longer return # Don't try to parse this routing message - logging.debug(f"Retrying metadata request.") + logger.debug(f"Retrying metadata request.") self.getMetadata() return c = p["decoded"]["admin"]["raw"].get_device_metadata_response self._timeout.reset() # We made forward progress - logging.debug(f"Received metadata {stripnl(c)}") + logger.debug(f"Received metadata {stripnl(c)}") print(f"\nfirmware_version: {c.firmware_version}") print(f"device_state_version: {c.device_state_version}") def onResponseRequestChannel(self, p): """Handle the response packet for requesting a channel _requestChannel()""" - logging.debug(f"onResponseRequestChannel() p:{p}") + logger.debug(f"onResponseRequestChannel() p:{p}") if p["decoded"]["portnum"] == portnums_pb2.PortNum.Name( portnums_pb2.PortNum.ROUTING_APP ): if p["decoded"]["routing"]["errorReason"] != "NONE": - logging.warning( + logger.warning( f'Channel request failed, error reason: {p["decoded"]["routing"]["errorReason"]}' ) self._timeout.expireTime = time.time() # Do not wait any longer @@ -913,18 +914,18 @@ def onResponseRequestChannel(self, p): lastTried = 0 if len(self.partialChannels) > 0: lastTried = self.partialChannels[-1].index - logging.debug(f"Retrying previous channel request.") + logger.debug(f"Retrying previous channel request.") self._requestChannel(lastTried) return c = p["decoded"]["admin"]["raw"].get_channel_response self.partialChannels.append(c) self._timeout.reset() # We made forward progress - logging.debug(f"Received channel {stripnl(c)}") + logger.debug(f"Received channel {stripnl(c)}") index = c.index if index >= 8 - 1: - logging.debug("Finished downloading channels") + logger.debug("Finished downloading channels") self.channels = self.partialChannels self._fixupChannels() @@ -959,11 +960,11 @@ def _requestChannel(self, channelNum: int): print( f"Requesting channel {channelNum} info from remote node (this could take a while)" ) - logging.debug( + logger.debug( f"Requesting channel {channelNum} info from remote node (this could take a while)" ) else: - logging.debug(f"Requesting channel {channelNum}") + logger.debug(f"Requesting channel {channelNum}") return self._sendAdmin( p, wantResponse=True, onResponse=self.onResponseRequestChannel @@ -980,7 +981,7 @@ def _sendAdmin( """Send an admin message to the specified node (or the local node if destNodeNum is zero)""" if self.noProto: - logging.warning( + logger.warning( f"Not sending packet because protocol use is disabled by noProto" ) else: @@ -988,7 +989,7 @@ def _sendAdmin( adminIndex == 0 ): # unless a special channel index was used, we want to use the admin index adminIndex = self.iface.localNode._getAdminChannelIndex() - logging.debug(f"adminIndex:{adminIndex}") + logger.debug(f"adminIndex:{adminIndex}") if isinstance(self.nodeNum, int): nodeid = self.nodeNum else: # assume string starting with ! @@ -1009,7 +1010,7 @@ def _sendAdmin( def ensureSessionKey(self): """If our entry in iface.nodesByNum doesn't already have an adminSessionPassKey, make a request to get one""" if self.noProto: - logging.warning( + logger.warning( f"Not ensuring session key, because protocol use is disabled by noProto" ) else: diff --git a/meshtastic/remote_hardware.py b/meshtastic/remote_hardware.py index c3d873a2..41534a02 100644 --- a/meshtastic/remote_hardware.py +++ b/meshtastic/remote_hardware.py @@ -7,10 +7,11 @@ from meshtastic.protobuf import portnums_pb2, remote_hardware_pb2 from meshtastic.util import our_exit +logger = logging.getLogger(__name__) def onGPIOreceive(packet, interface) -> None: """Callback for received GPIO responses""" - logging.debug(f"packet:{packet} interface:{interface}") + logger.debug(f"packet:{packet} interface:{interface}") gpioValue = 0 hw = packet["decoded"]["remotehw"] if "gpioValue" in hw: @@ -76,7 +77,7 @@ def writeGPIOs(self, nodeid, mask, vals): Write the specified vals bits to the device GPIOs. Only bits in mask that are 1 will be changed """ - logging.debug(f"writeGPIOs nodeid:{nodeid} mask:{mask} vals:{vals}") + logger.debug(f"writeGPIOs nodeid:{nodeid} mask:{mask} vals:{vals}") r = remote_hardware_pb2.HardwareMessage() r.type = remote_hardware_pb2.HardwareMessage.Type.WRITE_GPIOS r.gpio_mask = mask @@ -85,7 +86,7 @@ def writeGPIOs(self, nodeid, mask, vals): def readGPIOs(self, nodeid, mask, onResponse=None): """Read the specified bits from GPIO inputs on the device""" - logging.debug(f"readGPIOs nodeid:{nodeid} mask:{mask}") + logger.debug(f"readGPIOs nodeid:{nodeid} mask:{mask}") r = remote_hardware_pb2.HardwareMessage() r.type = remote_hardware_pb2.HardwareMessage.Type.READ_GPIOS r.gpio_mask = mask @@ -93,7 +94,7 @@ def readGPIOs(self, nodeid, mask, onResponse=None): def watchGPIOs(self, nodeid, mask): """Watch the specified bits from GPIO inputs on the device for changes""" - logging.debug(f"watchGPIOs nodeid:{nodeid} mask:{mask}") + logger.debug(f"watchGPIOs nodeid:{nodeid} mask:{mask}") r = remote_hardware_pb2.HardwareMessage() r.type = remote_hardware_pb2.HardwareMessage.Type.WATCH_GPIOS r.gpio_mask = mask diff --git a/meshtastic/serial_interface.py b/meshtastic/serial_interface.py index 7594ddf9..9f99a173 100644 --- a/meshtastic/serial_interface.py +++ b/meshtastic/serial_interface.py @@ -12,6 +12,8 @@ import meshtastic.util from meshtastic.stream_interface import StreamInterface +logger = logging.getLogger(__name__) + if platform.system() != "Windows": import termios @@ -33,7 +35,7 @@ def __init__(self, devPath: Optional[str]=None, debugOut=None, noProto: bool=Fal if self.devPath is None: ports: List[str] = meshtastic.util.findPorts(True) - logging.debug(f"ports:{ports}") + logger.debug(f"ports:{ports}") if len(ports) == 0: print("No Serial Meshtastic device detected, attempting TCP connection on localhost.") return @@ -44,7 +46,7 @@ def __init__(self, devPath: Optional[str]=None, debugOut=None, noProto: bool=Fal else: self.devPath = ports[0] - logging.debug(f"Connecting to {self.devPath}") + logger.debug(f"Connecting to {self.devPath}") # first we need to set the HUPCL so the device will not reboot based on RTS and/or DTR # see https://github.com/pyserial/pyserial/issues/124 @@ -84,5 +86,5 @@ def close(self) -> None: time.sleep(0.1) self.stream.flush() time.sleep(0.1) - logging.debug("Closing Serial stream") + logger.debug("Closing Serial stream") StreamInterface.close(self) diff --git a/meshtastic/slog/slog.py b/meshtastic/slog/slog.py index 6b09e4b7..f91f0667 100644 --- a/meshtastic/slog/slog.py +++ b/meshtastic/slog/slog.py @@ -3,13 +3,13 @@ import atexit import io import logging -import os import re import threading import time from dataclasses import dataclass from datetime import datetime from functools import reduce +from pathlib import Path from typing import Optional, List, Tuple import parse # type: ignore[import-untyped] @@ -22,6 +22,7 @@ from .arrow import FeatherWriter +logger = logging.getLogger(__name__) def root_dir() -> str: """Return the root directory for slog files.""" @@ -29,9 +30,9 @@ def root_dir() -> str: app_name = "meshtastic" app_author = "meshtastic" app_dir = platformdirs.user_data_dir(app_name, app_author) - dir_name = f"{app_dir}/slogs" - os.makedirs(dir_name, exist_ok=True) - return dir_name + dir_name = Path(app_dir, "slogs") + dir_name.mkdir(exist_ok=True) + return str(dir_name) @dataclass(init=False) @@ -197,7 +198,7 @@ def _onLogMessage(self, line: str) -> None: if m: src = m.group(1) args = m.group(2) - logging.debug(f"SLog {src}, args: {args}") + logger.debug(f"SLog {src}, args: {args}") d = log_defs.get(src) if d: @@ -219,9 +220,9 @@ def _onLogMessage(self, line: str) -> None: # If the last field is an empty string, remove it del di[last_field[0]] else: - logging.warning(f"Failed to parse slog {line} with {d.format}") + logger.warning(f"Failed to parse slog {line} with {d.format}") else: - logging.warning(f"Unknown Structured Log: {line}") + logger.warning(f"Unknown Structured Log: {line}") # Store our structured log record if di or self.include_raw: @@ -256,18 +257,22 @@ def __init__( if not dir_name: app_dir = root_dir() - dir_name = f"{app_dir}/{datetime.now().strftime('%Y%m%d-%H%M%S')}" - os.makedirs(dir_name, exist_ok=True) + dir_name = Path(app_dir, datetime.now().strftime('%Y%m%d-%H%M%S')) + dir_name.mkdir(exist_ok=True) # Also make a 'latest' directory that always points to the most recent logs + latest_dir = Path(app_dir, "latest") + latest_dir.unlink(missing_ok=True) + # symlink might fail on some platforms, if it does fail silently - if os.path.exists(f"{app_dir}/latest"): - os.unlink(f"{app_dir}/latest") - os.symlink(dir_name, f"{app_dir}/latest", target_is_directory=True) + try: + latest_dir.symlink_to(dir_name, target_is_directory=True) + except OSError: + pass self.dir_name = dir_name - logging.info(f"Writing slogs to {dir_name}") + logger.info(f"Writing slogs to {dir_name}") self.power_logger: Optional[PowerLogger] = ( None @@ -286,7 +291,7 @@ def close(self) -> None: """Close the log set.""" if self.slog_logger: - logging.info(f"Closing slogs in {self.dir_name}") + logger.info(f"Closing slogs in {self.dir_name}") atexit.unregister( self.atexit_handler ) # docs say it will silently ignore if not found diff --git a/meshtastic/stream_interface.py b/meshtastic/stream_interface.py index c1fecab2..a45c0676 100644 --- a/meshtastic/stream_interface.py +++ b/meshtastic/stream_interface.py @@ -17,6 +17,7 @@ START2 = 0xC3 HEADER_LEN = 4 MAX_TO_FROM_RADIO_SIZE = 512 +logger = logging.getLogger(__name__) class StreamInterface(MeshInterface): @@ -82,7 +83,7 @@ def _disconnected(self) -> None: """We override the superclass implementation to close our port""" MeshInterface._disconnected(self) - logging.debug("Closing our port") + logger.debug("Closing our port") # pylint: disable=E0203 if not self.stream is None: # pylint: disable=E0203 @@ -111,17 +112,17 @@ def _readBytes(self, length) -> Optional[bytes]: def _sendToRadioImpl(self, toRadio) -> None: """Send a ToRadio protobuf to the device""" - logging.debug(f"Sending: {stripnl(toRadio)}") + logger.debug(f"Sending: {stripnl(toRadio)}") b: bytes = toRadio.SerializeToString() bufLen: int = len(b) # We convert into a string, because the TCP code doesn't work with byte arrays header: bytes = bytes([START1, START2, (bufLen >> 8) & 0xFF, bufLen & 0xFF]) - logging.debug(f"sending header:{header!r} b:{b!r}") + logger.debug(f"sending header:{header!r} b:{b!r}") self._writeBytes(header + b) def close(self) -> None: """Close a connection to the device""" - logging.debug("Closing stream") + logger.debug("Closing stream") MeshInterface.close(self) # pyserial cancel_read doesn't seem to work, therefore we ask the # reader thread to close things for us @@ -148,18 +149,18 @@ def _handleLogByte(self, b): def __reader(self) -> None: """The reader thread that reads bytes from our stream""" - logging.debug("in __reader()") + logger.debug("in __reader()") empty = bytes() try: while not self._wantExit: - # logging.debug("reading character") + # logger.debug("reading character") b: Optional[bytes] = self._readBytes(1) - # logging.debug("In reader loop") - # logging.debug(f"read returned {b}") + # logger.debug("In reader loop") + # logger.debug(f"read returned {b}") if b is not None and len(cast(bytes, b)) > 0: c: int = b[0] - # logging.debug(f'c:{c}') + # logger.debug(f'c:{c}') ptr: int = len(self._rxBuf) # Assume we want to append this byte, fixme use bytearray instead @@ -176,7 +177,7 @@ def __reader(self) -> None: if c != START2: self._rxBuf = empty # failed to find start2 elif ptr >= HEADER_LEN - 1: # we've at least got a header - # logging.debug('at least we received a header') + # logger.debug('at least we received a header') # big endian length follows header packetlen = (self._rxBuf[2] << 8) + self._rxBuf[3] @@ -192,32 +193,32 @@ def __reader(self) -> None: try: self._handleFromRadio(self._rxBuf[HEADER_LEN:]) except Exception as ex: - logging.error( + logger.error( f"Error while handling message from radio {ex}" ) traceback.print_exc() self._rxBuf = empty else: - # logging.debug(f"timeout") + # logger.debug(f"timeout") pass except serial.SerialException as ex: if ( not self._wantExit ): # We might intentionally get an exception during shutdown - logging.warning( + logger.warning( f"Meshtastic serial port disconnected, disconnecting... {ex}" ) except OSError as ex: if ( not self._wantExit ): # We might intentionally get an exception during shutdown - logging.error( + logger.error( f"Unexpected OSError, terminating meshtastic reader... {ex}" ) except Exception as ex: - logging.error( + logger.error( f"Unexpected exception, terminating meshtastic reader... {ex}" ) finally: - logging.debug("reader is exiting") + logger.debug("reader is exiting") self._disconnected() diff --git a/meshtastic/tcp_interface.py b/meshtastic/tcp_interface.py index 4263da37..a324b900 100644 --- a/meshtastic/tcp_interface.py +++ b/meshtastic/tcp_interface.py @@ -10,6 +10,7 @@ from meshtastic.stream_interface import StreamInterface DEFAULT_TCP_PORT = 4403 +logger = logging.getLogger(__name__) class TCPInterface(StreamInterface): """Interface class for meshtastic devices over a TCP link""" @@ -67,13 +68,13 @@ def _socket_shutdown(self) -> None: def myConnect(self) -> None: """Connect to socket""" - logging.debug(f"Connecting to {self.hostname}") # type: ignore[str-bytes-safe] + logger.debug(f"Connecting to {self.hostname}") # type: ignore[str-bytes-safe] server_address = (self.hostname, self.portNumber) self.socket = socket.create_connection(server_address) def close(self) -> None: """Close a connection to the device""" - logging.debug("Closing TCP stream") + logger.debug("Closing TCP stream") super().close() # Sometimes the socket read might be blocked in the reader thread. # Therefore we force the shutdown by closing the socket here @@ -97,7 +98,7 @@ def _readBytes(self, length) -> Optional[bytes]: # empty byte indicates a disconnected socket, # we need to handle it to avoid an infinite loop reading from null socket if data == b'': - logging.debug("dead socket, re-connecting") + logger.debug("dead socket, re-connecting") # cleanup and reconnect socket without breaking reader thread with contextlib.suppress(Exception): self._socket_shutdown() diff --git a/meshtastic/test.py b/meshtastic/test.py index 96d6c094..9c9d62a6 100644 --- a/meshtastic/test.py +++ b/meshtastic/test.py @@ -29,6 +29,7 @@ sendingInterface = None +logger = logging.getLogger(__name__) def onReceive(packet, interface) -> None: """Callback invoked when a packet arrives""" @@ -79,7 +80,7 @@ def testSend( else: toNode = toInterface.myInfo.my_node_num - logging.debug(f"Sending test wantAck={wantAck} packet from {fromNode} to {toNode}") + logger.debug(f"Sending test wantAck={wantAck} packet from {fromNode} to {toNode}") # pylint: disable=W0603 global sendingInterface sendingInterface = fromInterface @@ -98,7 +99,7 @@ def testSend( def runTests(numTests: int=50, wantAck: bool=False, maxFailures: int=0) -> bool: """Run the tests.""" - logging.info(f"Running {numTests} tests with wantAck={wantAck}") + logger.info(f"Running {numTests} tests with wantAck={wantAck}") numFail: int = 0 numSuccess: int = 0 for _ in range(numTests): @@ -112,26 +113,26 @@ def runTests(numTests: int=50, wantAck: bool=False, maxFailures: int=0) -> bool: ) if not success: numFail = numFail + 1 - logging.error( + logger.error( f"Test {testNumber} failed, expected packet not received ({numFail} failures so far)" ) else: numSuccess = numSuccess + 1 - logging.info( + logger.info( f"Test {testNumber} succeeded {numSuccess} successes {numFail} failures so far" ) time.sleep(1) if numFail > maxFailures: - logging.error("Too many failures! Test failed!") + logger.error("Too many failures! Test failed!") return False return True def testThread(numTests=50) -> bool: """Test thread""" - logging.info("Found devices, starting tests...") + logger.info("Found devices, starting tests...") result: bool = runTests(numTests, wantAck=True) if result: # Run another test @@ -148,7 +149,7 @@ def onConnection(topic=pub.AUTO_TOPIC) -> None: def openDebugLog(portName) -> io.TextIOWrapper: """Open the debug log file""" debugname = "log" + portName.replace("/", "_") - logging.info(f"Writing serial debugging to {debugname}") + logger.info(f"Writing serial debugging to {debugname}") return open(debugname, "w+", buffering=1, encoding="utf8") @@ -177,7 +178,7 @@ def testAll(numTests: int=5) -> bool: ) ) - logging.info("Ports opened, starting test") + logger.info("Ports opened, starting test") result: bool = testThread(numTests) for i in interfaces: @@ -196,14 +197,14 @@ def testSimulator() -> None: python3 -c 'from meshtastic.test import testSimulator; testSimulator()' """ logging.basicConfig(level=logging.DEBUG) - logging.info("Connecting to simulator on localhost!") + logger.info("Connecting to simulator on localhost!") try: iface: meshtastic.tcp_interface.TCPInterface = TCPInterface("localhost") iface.showInfo() iface.localNode.showInfo() iface.localNode.exitSimulator() iface.close() - logging.info("Integration test successful!") + logger.info("Integration test successful!") except: print("Error while testing simulator:", sys.exc_info()[0]) traceback.print_exc() diff --git a/meshtastic/tests/test_main.py b/meshtastic/tests/test_main.py index 1e24dc2d..2a7048c0 100644 --- a/meshtastic/tests/test_main.py +++ b/meshtastic/tests/test_main.py @@ -6,6 +6,7 @@ import platform import re import sys +import types from unittest.mock import mock_open, MagicMock, patch import pytest @@ -35,6 +36,12 @@ # from ..remote_hardware import onGPIOreceive # from ..config_pb2 import Config +# create a fake termios for Wwindows, otherwise errors will occur +if sys.platform == "win32": + fake_termios = types.ModuleType("termios") + fake_termios.tcgetattr = lambda fd: None + fake_termios.tcsetattr = lambda fd, when, settings: None + sys.modules["termios"] = fake_termios @pytest.mark.unit @pytest.mark.usefixtures("reset_mt_config") @@ -2722,6 +2729,7 @@ def test_tunnel_subnet_arg_with_no_devices(mock_platform_system, caplog, capsys) assert err == "" +@pytest.mark.skipif(sys.platform == "win32", reason="Linux is forced in test and no termios") @pytest.mark.unit @pytest.mark.usefixtures("reset_mt_config") @patch("platform.system") diff --git a/meshtastic/tests/test_mesh_interface.py b/meshtastic/tests/test_mesh_interface.py index c561ab20..8d53628f 100644 --- a/meshtastic/tests/test_mesh_interface.py +++ b/meshtastic/tests/test_mesh_interface.py @@ -672,15 +672,21 @@ def test_getOrCreateByNum(iface_with_nodes): @pytest.mark.unit def test_exit_with_exception(caplog): """Test __exit__()""" - iface = MeshInterface(noProto=True) with caplog.at_level(logging.ERROR): - iface.__exit__("foo", "bar", "baz") - assert re.search( - r"An exception of type foo with value bar has occurred", - caplog.text, - re.MULTILINE, - ) - assert re.search(r"Traceback: baz", caplog.text, re.MULTILINE) + try: + with MeshInterface(noProto=True): + raise ValueError("Something went wrong") + except: + assert re.search( + r"An exception of type with value Something went wrong has occurred", + caplog.text, + re.MULTILINE, + ) + assert re.search( + r"Traceback:\n.*in test_exit_with_exception\n {4}raise ValueError\(\"Something went wrong\"\)", + caplog.text, + re.MULTILINE + ) @pytest.mark.unit diff --git a/meshtastic/tests/test_serial_interface.py b/meshtastic/tests/test_serial_interface.py index 26faf082..29683d7c 100644 --- a/meshtastic/tests/test_serial_interface.py +++ b/meshtastic/tests/test_serial_interface.py @@ -1,4 +1,5 @@ """Meshtastic unit tests for serial_interface.py""" +import platform # pylint: disable=R0917 import re @@ -28,9 +29,13 @@ def test_SerialInterface_single_port( iface.close() mocked_findPorts.assert_called() mocked_serial.assert_called() - mocked_open.assert_called() - mock_get.assert_called() - mock_set.assert_called() + + # doesn't get called in SerialInterface.__init__ on windows + if platform.system() != "Windows": + mocked_open.assert_called() + mock_get.assert_called() + mock_set.assert_called() + mock_sleep.assert_called() out, err = capsys.readouterr() assert re.search(r"Nodes in mesh", out, re.MULTILINE) diff --git a/meshtastic/tunnel.py b/meshtastic/tunnel.py index d1294f30..46e3a2e0 100644 --- a/meshtastic/tunnel.py +++ b/meshtastic/tunnel.py @@ -26,10 +26,11 @@ from meshtastic import mt_config from meshtastic.util import ipstr, readnet_u16 +logger = logging.getLogger(__name__) def onTunnelReceive(packet, interface): # pylint: disable=W0613 """Callback for received tunneled messages from mesh.""" - logging.debug(f"in onTunnelReceive()") + logger.debug(f"in onTunnelReceive()") tunnelInstance = mt_config.tunnelInstance tunnelInstance.onReceive(packet) @@ -92,7 +93,7 @@ def __init__(self, iface, subnet: str="10.115", netmask: str="255.255.0.0") -> N self.LOG_TRACE = 5 # TODO: check if root? - logging.info( + logger.info( "Starting IP to mesh tunnel (you must be root for this *pre-alpha* " "feature to work). Mesh members:" ) @@ -104,13 +105,13 @@ def __init__(self, iface, subnet: str="10.115", netmask: str="255.255.0.0") -> N for node in self.iface.nodes.values(): nodeId = node["user"]["id"] ip = self._nodeNumToIp(node["num"]) - logging.info(f"Node { nodeId } has IP address { ip }") + logger.info(f"Node { nodeId } has IP address { ip }") - logging.debug("creating TUN device with MTU=200") + logger.debug("creating TUN device with MTU=200") # FIXME - figure out real max MTU, it should be 240 - the overhead bytes for SubPacket and Data self.tun = None if self.iface.noProto: - logging.warning( + logger.warning( f"Not creating a TapDevice() because it is disabled by noProto" ) else: @@ -120,11 +121,11 @@ def __init__(self, iface, subnet: str="10.115", netmask: str="255.255.0.0") -> N self._rxThread = None if self.iface.noProto: - logging.warning( + logger.warning( f"Not starting TUN reader because it is disabled by noProto" ) else: - logging.debug(f"starting TUN reader, our IP address is {myAddr}") + logger.debug(f"starting TUN reader, our IP address is {myAddr}") self._rxThread = threading.Thread( target=self.__tunReader, args=(), daemon=True ) @@ -134,9 +135,9 @@ def onReceive(self, packet): """onReceive""" p = packet["decoded"]["payload"] if packet["from"] == self.iface.myInfo.my_node_num: - logging.debug("Ignoring message we sent") + logger.debug("Ignoring message we sent") else: - logging.debug(f"Received mesh tunnel message type={type(p)} len={len(p)}") + logger.debug(f"Received mesh tunnel message type={type(p)} len={len(p)}") # we don't really need to check for filtering here (sender should have checked), # but this provides useful debug printing on types of packets received if not self.iface.noProto: @@ -152,7 +153,7 @@ def _shouldFilterPacket(self, p): ignore = False # Assume we will be forwarding the packet if protocol in self.protocolBlacklist: ignore = True - logging.log( + logger.log( self.LOG_TRACE, f"Ignoring blacklisted protocol 0x{protocol:02x}" ) elif protocol == 0x01: # ICMP @@ -160,7 +161,7 @@ def _shouldFilterPacket(self, p): icmpCode = p[21] checksum = p[22:24] # pylint: disable=line-too-long - logging.debug( + logger.debug( f"forwarding ICMP message src={ipstr(srcaddr)}, dest={ipstr(destAddr)}, type={icmpType}, code={icmpCode}, checksum={checksum}" ) # reply to pings (swap src and dest but keep rest of packet unchanged) @@ -171,19 +172,19 @@ def _shouldFilterPacket(self, p): destport = readnet_u16(p, subheader + 2) if destport in self.udpBlacklist: ignore = True - logging.log(self.LOG_TRACE, f"ignoring blacklisted UDP port {destport}") + logger.log(self.LOG_TRACE, f"ignoring blacklisted UDP port {destport}") else: - logging.debug(f"forwarding udp srcport={srcport}, destport={destport}") + logger.debug(f"forwarding udp srcport={srcport}, destport={destport}") elif protocol == 0x06: # TCP srcport = readnet_u16(p, subheader) destport = readnet_u16(p, subheader + 2) if destport in self.tcpBlacklist: ignore = True - logging.log(self.LOG_TRACE, f"ignoring blacklisted TCP port {destport}") + logger.log(self.LOG_TRACE, f"ignoring blacklisted TCP port {destport}") else: - logging.debug(f"forwarding tcp srcport={srcport}, destport={destport}") + logger.debug(f"forwarding tcp srcport={srcport}, destport={destport}") else: - logging.warning( + logger.warning( f"forwarding unexpected protocol 0x{protocol:02x}, " "src={ipstr(srcaddr)}, dest={ipstr(destAddr)}" ) @@ -192,10 +193,10 @@ def _shouldFilterPacket(self, p): def __tunReader(self): tap = self.tun - logging.debug("TUN reader running") + logger.debug("TUN reader running") while True: p = tap.read() - # logging.debug(f"IP packet received on TUN interface, type={type(p)}") + # logger.debug(f"IP packet received on TUN interface, type={type(p)}") destAddr = p[16:20] if not self._shouldFilterPacket(p): @@ -210,7 +211,7 @@ def _ipToNodeId(self, ipAddr): for node in self.iface.nodes.values(): nodeNum = node["num"] & 0xFFFF - # logging.debug(f"Considering nodenum 0x{nodeNum:x} for ipBits 0x{ipBits:x}") + # logger.debug(f"Considering nodenum 0x{nodeNum:x} for ipBits 0x{ipBits:x}") if (nodeNum) == ipBits: return node["user"]["id"] return None @@ -222,12 +223,12 @@ def sendPacket(self, destAddr, p): """Forward the provided IP packet into the mesh""" nodeId = self._ipToNodeId(destAddr) if nodeId is not None: - logging.debug( + logger.debug( f"Forwarding packet bytelen={len(p)} dest={ipstr(destAddr)}, destNode={nodeId}" ) self.iface.sendData(p, nodeId, portnums_pb2.IP_TUNNEL_APP, wantAck=False) else: - logging.warning( + logger.warning( f"Dropping packet because no node found for destIP={ipstr(destAddr)}" ) diff --git a/meshtastic/util.py b/meshtastic/util.py index 3d76e591..243dfe93 100644 --- a/meshtastic/util.py +++ b/meshtastic/util.py @@ -38,6 +38,7 @@ 0x303a Heltec tracker""" whitelistVids = dict.fromkeys([0x239a, 0x303a]) +logger = logging.getLogger(__name__) def quoteBooleans(a_string: str) -> str: """Quote booleans @@ -141,7 +142,7 @@ def catchAndIgnore(reason: str, closure) -> None: try: closure() except BaseException as ex: - logging.error(f"Exception thrown in {reason}: {ex}") + logger.error(f"Exception thrown in {reason}: {ex}") def findPorts(eliminate_duplicates: bool=False) -> List[str]: @@ -307,7 +308,7 @@ def _run(self) -> None: o = self.queue.get() o() except: - logging.error( + logger.error( f"Unexpected error in deferred execution {sys.exc_info()[0]}" ) print(traceback.format_exc())