mirror/python
1
0
Fork 0
mirror of https://github.com/meshtastic/python.git synced 2026-01-13 10:17:55 -05:00
Code Issues Packages Projects Releases Wiki Activity

Added Logging Handler Names

Browse Source
This commit is contained in:
shukari
2025-08-06 18:21:32 +02:00
parent c60b5d4b05
commit db1891b651
12 changed files with 220 additions and 202 deletions
Download Patch File Download Diff File Expand all files Collapse all files

19
meshtastic/__init__.py
View File

@@ -129,6 +129,7 @@ NODELESS_WANT_CONFIG_ID = 69420
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

38
meshtastic/__main__.py
View File

@@ -9,6 +9,10 @@ from typing import List, Optional, Union
from types import ModuleType
import argparse
import logging
logger = logging.getLogger(__name__)
argcomplete: Union[None, ModuleType] = None
try:
import argcomplete # type: ignore
@@ -67,7 +71,7 @@ def onReceive(packet, interface) -> None:
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 +105,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 +118,7 @@ def getPref(node, comp_name) -> bool:
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 +127,8 @@ def getPref(node, comp_name) -> bool:
# 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 +202,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 +227,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 +607,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 +1063,7 @@ def onConnected(interface):
# 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 +1254,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 +1316,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 +1335,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 +1346,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 +1437,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)

33
meshtastic/ble_interface.py
View File

@@ -23,6 +23,7 @@ FROMRADIO_UUID = "2c55e69e-4993-11ed-b878-0242ac120002"
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 @@ class BLEInterface(MeshInterface):
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 @@ class BLEInterface(MeshInterface):
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 @@ class BLEInterface(MeshInterface):
Note: this method does not need to be async because it is just setting a bool.
"""
from_num = struct.unpack("<I", bytes(b))[0]
logging.debug(f"FROMNUM notify: {from_num}")
logger.debug(f"FROMNUM notify: {from_num}")
self.should_read = True
async def log_radio_handler(self, _, b): # pylint: disable=C0116
@@ -114,7 +115,7 @@ class BLEInterface(MeshInterface):
)
self._handleLogLine(message)
except google.protobuf.message.DecodeError:
logging.warning("Malformed LogRecord received. Skipping.")
logger.warning("Malformed LogRecord received. Skipping.")
async def legacy_log_radio_handler(self, _, b): # pylint: disable=C0116
log_radio = b.decode("utf-8").replace("\n", "")
@@ -124,7 +125,7 @@ class BLEInterface(MeshInterface):
def scan() -> 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 @@ class BLEInterface(MeshInterface):
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 @@ class BLEInterface(MeshInterface):
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 @@ class BLEInterface(MeshInterface):
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 @@ class BLEInterface(MeshInterface):
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 @@ class BLEClient:
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)

105
meshtastic/mesh_interface.py
View File

@@ -17,6 +17,9 @@ from decimal import Decimal
from typing import Any, Callable, Dict, List, Optional, Union
import google.protobuf.json_format
logger = logging.getLogger(__name__)
try:
import print_color # type: ignore[import-untyped]
except ImportError as e:
@@ -149,11 +152,11 @@ class MeshInterface: # pylint: disable=R0902
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 +284,7 @@ class MeshInterface: # pylint: disable=R0902
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 +307,7 @@ class MeshInterface: # pylint: disable=R0902
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 +386,7 @@ class MeshInterface: # pylint: disable=R0902
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 +541,11 @@ class MeshInterface: # pylint: disable=R0902
"""
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 +568,7 @@ class MeshInterface: # pylint: disable=R0902
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 +595,15 @@ class MeshInterface: # pylint: disable=R0902
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 +854,15 @@ class MeshInterface: # pylint: disable=R0902
# 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 +977,7 @@ class MeshInterface: # pylint: disable=R0902
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 +1001,11 @@ class MeshInterface: # pylint: disable=R0902
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 +1056,7 @@ class MeshInterface: # pylint: disable=R0902
"""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 +1146,7 @@ class MeshInterface: # pylint: disable=R0902
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 +1204,11 @@ class MeshInterface: # pylint: disable=R0902
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 +1221,38 @@ class MeshInterface: # pylint: disable=R0902
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 +1268,22 @@ class MeshInterface: # pylint: disable=R0902
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 +1291,30 @@ class MeshInterface: # pylint: disable=R0902
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 +1322,7 @@ class MeshInterface: # pylint: disable=R0902
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 +1337,7 @@ class MeshInterface: # pylint: disable=R0902
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 +1452,7 @@ class MeshInterface: # pylint: disable=R0902
)
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 +1486,7 @@ class MeshInterface: # pylint: disable=R0902
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 +1542,7 @@ class MeshInterface: # pylint: disable=R0902
# 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 +1556,11 @@ class MeshInterface: # pylint: disable=R0902
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 +1580,7 @@ class MeshInterface: # pylint: disable=R0902
# 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 +1612,7 @@ class MeshInterface: # pylint: disable=R0902
# 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 +1629,12 @@ class MeshInterface: # pylint: disable=R0902
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)
)

101
meshtastic/node.py
View File

@@ -18,6 +18,7 @@ from meshtastic.util import (
message_to_json,
)
logger = logging.getLogger(__name__)
class Node:
"""A model of a (local or remote) node in the mesh
@@ -55,7 +56,7 @@ class Node:
"""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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
while self.gotResponse is False:
time.sleep(0.1)
logging.debug(
logger.debug(
f"self.cannedPluginMessageMessages:{self.cannedPluginMessageMessages}"
)
@@ -532,7 +533,7 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
"""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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
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 @@ class Node:
"""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 @@ class Node:
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 @@ class Node:
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:

9
meshtastic/remote_hardware.py
View File

@@ -7,10 +7,11 @@ from pubsub import pub # type: ignore[import-untyped]
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 @@ class RemoteHardwareClient:
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 @@ class RemoteHardwareClient:
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 @@ class RemoteHardwareClient:
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

8
meshtastic/serial_interface.py
View File

@@ -12,6 +12,8 @@ import serial # type: ignore[import-untyped]
import meshtastic.util
from meshtastic.stream_interface import StreamInterface
logger = logging.getLogger(__name__)
if platform.system() != "Windows":
import termios
@@ -33,7 +35,7 @@ class SerialInterface(StreamInterface):
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 @@ class SerialInterface(StreamInterface):
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 @@ class SerialInterface(StreamInterface):
time.sleep(0.1)
self.stream.flush()
time.sleep(0.1)
logging.debug("Closing Serial stream")
logger.debug("Closing Serial stream")
StreamInterface.close(self)

33
meshtastic/stream_interface.py
View File

@@ -17,6 +17,7 @@ START1 = 0x94
START2 = 0xC3
HEADER_LEN = 4
MAX_TO_FROM_RADIO_SIZE = 512
logger = logging.getLogger(__name__)
class StreamInterface(MeshInterface):
@@ -82,7 +83,7 @@ class StreamInterface(MeshInterface):
"""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 @@ class StreamInterface(MeshInterface):
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 @@ class StreamInterface(MeshInterface):
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 @@ class StreamInterface(MeshInterface):
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 @@ class StreamInterface(MeshInterface):
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()

7
meshtastic/tcp_interface.py
View File

@@ -10,6 +10,7 @@ from typing import Optional
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 @@ class TCPInterface(StreamInterface):
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 @@ class TCPInterface(StreamInterface):
# 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()

21
meshtastic/test.py
View File

@@ -29,6 +29,7 @@ testNumber: int = 0
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()

43
meshtastic/tunnel.py
View File

@@ -26,10 +26,11 @@ from meshtastic.protobuf import portnums_pb2
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 @@ class Tunnel:
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 @@ class Tunnel:
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 @@ class Tunnel:
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 @@ class Tunnel:
"""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 @@ class Tunnel:
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 @@ class Tunnel:
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 @@ class Tunnel:
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 @@ class Tunnel:
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 @@ class Tunnel:
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 @@ class Tunnel:
"""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)}"
)

5
meshtastic/util.py
View File

@@ -38,6 +38,7 @@ blacklistVids: Dict = dict.fromkeys([0x1366, 0x0483, 0x1915, 0x0925, 0x04b4])
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 @@ class DeferredExecution:
o = self.queue.get()
o()
except:
logging.error(
logger.error(
f"Unexpected error in deferred execution {sys.exc_info()[0]}"
)
print(traceback.format_exc())