mirror/python
1
0
Fork 0
mirror of https://github.com/meshtastic/python.git synced 2025-12-24 00:17:54 -05:00
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #812 from shukari/loggingHandler2

Browse Source 
Added Logging Handler Names & windows pytest support
This commit is contained in:
Ian McEwen
2025-09-18 09:26:55 -07:00
committed by GitHub
parent 47e5b04d3b 14ff3eb9c4
commit cfb23788e1
17 changed files with 310 additions and 275 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

45
meshtastic/__main__.py
View File

@@ -9,6 +9,7 @@ from typing import List, Optional, Union
from types import ModuleType
import argparse
argcomplete: Union[None, ModuleType] = None
try:
import argcomplete # type: ignore
@@ -62,12 +63,14 @@ except ImportError as e:
from meshtastic.protobuf import channel_pb2, config_pb2, portnums_pb2, mesh_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 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 +126,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 +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.")
@@ -608,7 +611,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)
@@ -1064,7 +1067,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)
@@ -1255,14 +1258,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)
@@ -1276,6 +1279,10 @@ def common():
format="%(levelname)s file:%(filename)s %(funcName)s line:%(lineno)s %(message)s",
)
# set all meshtastic loggers to DEBUG
if not (args.debug or args.listen) and args.debuglib:
logging.getLogger('meshtastic').setLevel(logging.DEBUG)
if len(sys.argv) == 1:
parser.print_help(sys.stderr)
meshtastic.util.our_exit("", 1)
@@ -1317,7 +1324,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)
@@ -1336,10 +1343,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")
@@ -1347,7 +1354,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)
@@ -1438,7 +1445,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)
@@ -2045,6 +2052,10 @@ def initParser():
"--debug", help="Show API library debug log messages", action="store_true"
)
group.add_argument(
"--debuglib", help="Show only API library debug log messages", action="store_true"
)
group.add_argument(
"--test",
help="Run stress test against all connected Meshtastic devices",

7
meshtastic/analysis/__main__.py
View File

@@ -2,6 +2,7 @@
import argparse
import logging
import os
from typing import cast, List
import dash_bootstrap_components as dbc # type: ignore[import-untyped]
@@ -143,8 +144,8 @@ def create_dash(slog_path: str) -> Dash:
"""
app = Dash(external_stylesheets=[dbc.themes.BOOTSTRAP])
dpwr = read_pandas(f"{slog_path}/power.feather")
dslog = read_pandas(f"{slog_path}/slog.feather")
dpwr = read_pandas(os.path.join(slog_path, "power.feather"))
dslog = read_pandas(os.path.join(slog_path, "slog.feather"))
pmon_raises = get_pmon_raises(dslog)
@@ -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 = os.path.join(root_dir(), "latest")
app = create_dash(slog_path=args.slog)
port = 8051

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)

104
meshtastic/mesh_interface.py
View File

@@ -17,6 +17,7 @@ from decimal import Decimal
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 @@ from meshtastic.util import (
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 @@ 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 +283,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 +306,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 +385,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 +540,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 +567,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 +594,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 +853,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 +976,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 +1000,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 +1055,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 +1145,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 +1203,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 +1220,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 +1267,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 +1290,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 +1321,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 +1336,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 +1451,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 +1485,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 +1541,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 +1555,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 +1579,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 +1611,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 +1628,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
@@ -65,7 +66,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
@@ -98,7 +99,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
@@ -107,7 +108,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":
@@ -234,7 +235,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:
@@ -247,7 +248,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
@@ -310,7 +311,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()
@@ -335,10 +336,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
@@ -421,7 +422,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
@@ -432,7 +433,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":
@@ -445,12 +446,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.module_available(mesh_pb2.EXTNOTIF_CONFIG):
logging.warning("External Notification module not present (excluded by firmware)")
return None
@@ -465,13 +466,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):
@@ -498,7 +499,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
@@ -508,7 +509,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":
@@ -521,14 +522,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.module_available(mesh_pb2.CANNEDMSG_CONFIG):
logging.warning("Canned Message module not present (excluded by firmware)")
return None
@@ -544,7 +545,7 @@ class Node:
while self.gotResponse is False:
time.sleep(0.1)
logging.debug(
logger.debug(
f"self.cannedPluginMessageMessages:{self.cannedPluginMessageMessages}"
)
@@ -552,7 +553,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):
@@ -579,7 +580,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
@@ -593,7 +594,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)
@@ -602,7 +603,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:
@@ -616,7 +617,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:
@@ -630,7 +631,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:
@@ -644,7 +645,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:
@@ -658,7 +659,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:
@@ -672,7 +673,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:
@@ -685,7 +686,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
@@ -698,10 +699,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:
@@ -805,7 +806,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:
@@ -846,7 +847,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
@@ -861,7 +862,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
@@ -893,7 +894,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":
@@ -905,30 +906,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
@@ -936,18 +937,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()
@@ -982,11 +983,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
@@ -1003,7 +1004,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:
@@ -1011,7 +1012,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 !
@@ -1032,7 +1033,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

34
meshtastic/serial_interface.py
View File

@@ -2,8 +2,9 @@
"""
# pylint: disable=R0917
import logging
import platform
import sys
import time
from io import TextIOWrapper
from typing import List, Optional
@@ -12,9 +13,7 @@ import serial # type: ignore[import-untyped]
import meshtastic.util
from meshtastic.stream_interface import StreamInterface
if platform.system() != "Windows":
import termios
logger = logging.getLogger(__name__)
class SerialInterface(StreamInterface):
"""Interface class for meshtastic devices over a serial link"""
@@ -33,7 +32,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,16 +43,11 @@ 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
if platform.system() != "Windows":
if sys.platform != "win32":
with open(self.devPath, encoding="utf8") as f:
attrs = termios.tcgetattr(f)
attrs[2] = attrs[2] & ~termios.HUPCL
termios.tcsetattr(f, termios.TCSAFLUSH, attrs)
f.close()
self._set_hupcl_with_termios(f)
time.sleep(0.1)
self.stream = serial.Serial(
@@ -66,6 +60,18 @@ class SerialInterface(StreamInterface):
self, debugOut=debugOut, noProto=noProto, connectNow=connectNow, noNodes=noNodes
)
def _set_hupcl_with_termios(self, f: TextIOWrapper):
"""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
"""
if sys.platform == "win32":
return
import termios # pylint: disable=C0415,E0401
attrs = termios.tcgetattr(f)
attrs[2] = attrs[2] & ~termios.HUPCL
termios.tcsetattr(f, termios.TCSAFLUSH, attrs)
def __repr__(self):
rep = f"SerialInterface(devPath={self.devPath!r}"
if hasattr(self, 'debugOut') and self.debugOut is not None:
@@ -84,5 +90,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)

39
meshtastic/slog/slog.py
View File

@@ -10,6 +10,7 @@ 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 +23,7 @@ from meshtastic.powermon import PowerMeter
from .arrow import FeatherWriter
logger = logging.getLogger(__name__)
def root_dir() -> str:
"""Return the root directory for slog files."""
@@ -29,9 +31,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, parents=True)
return str(dir_name)
@dataclass(init=False)
@@ -144,7 +146,7 @@ class StructuredLogger:
self.power_logger = power_logger
# Setup the arrow writer (and its schema)
self.writer = FeatherWriter(f"{dir_path}/slog")
self.writer = FeatherWriter(os.path.join(dir_path, "slog"))
all_fields = reduce(
(lambda x, y: x + y), map(lambda x: x.fields, log_defs.values())
)
@@ -164,7 +166,7 @@ class StructuredLogger:
self.raw_file: Optional[
io.TextIOWrapper
] = open( # pylint: disable=consider-using-with
f"{dir_path}/raw.txt", "w", encoding="utf8"
os.path.join(dir_path, "raw.txt"), "w", encoding="utf8"
)
# We need a closure here because the subscription API is very strict about exact arg matching
@@ -197,7 +199,7 @@ class StructuredLogger:
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 +221,9 @@ class StructuredLogger:
# 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,23 +258,28 @@ class LogSet:
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)
app_time_dir = Path(app_dir, datetime.now().strftime('%Y%m%d-%H%M%S'))
app_time_dir.mkdir(exist_ok=True)
dir_name = str(app_time_dir)
# 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
if not power_meter
else PowerLogger(power_meter, f"{self.dir_name}/power")
else PowerLogger(power_meter, os.path.join(self.dir_name, "power"))
)
self.slog_logger: Optional[StructuredLogger] = StructuredLogger(
@@ -286,7 +293,7 @@ class LogSet:
"""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

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()

47
meshtastic/tests/test_main.py
View File

@@ -35,7 +35,6 @@ from ..tcp_interface import TCPInterface
# from ..remote_hardware import onGPIOreceive
# from ..config_pb2 import Config
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
def test_main_init_parser_no_args(capsys):
@@ -758,12 +757,11 @@ def test_main_sendtext_with_invalid_channel_nine(caplog, capsys):
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_sendtext_with_dest(mock_findPorts, mock_serial, mocked_open, mock_get, mock_set, capsys, caplog, iface_with_nodes):
def test_main_sendtext_with_dest(mock_findPorts, mock_serial, mocked_open, mock_hupcl, capsys, caplog, iface_with_nodes):
"""Test --sendtext with --dest"""
sys.argv = ["", "--sendtext", "hello", "--dest", "foo"]
mt_config.args = sys.argv
@@ -957,12 +955,11 @@ def test_main_seturl(capsys):
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_set_valid(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_set_valid(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --set with valid field"""
sys.argv = ["", "--set", "network.wifi_ssid", "foo"]
mt_config.args = sys.argv
@@ -982,12 +979,11 @@ def test_main_set_valid(mocked_findports, mocked_serial, mocked_open, mocked_get
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_set_valid_wifi_psk(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_set_valid_wifi_psk(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --set with valid field"""
sys.argv = ["", "--set", "network.wifi_psk", "123456789"]
mt_config.args = sys.argv
@@ -1007,12 +1003,11 @@ def test_main_set_valid_wifi_psk(mocked_findports, mocked_serial, mocked_open, m
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_set_invalid_wifi_psk(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_set_invalid_wifi_psk(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --set with an invalid value (psk must be 8 or more characters)"""
sys.argv = ["", "--set", "network.wifi_psk", "1234567"]
mt_config.args = sys.argv
@@ -1035,12 +1030,11 @@ def test_main_set_invalid_wifi_psk(mocked_findports, mocked_serial, mocked_open,
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_set_valid_camel_case(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_set_valid_camel_case(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --set with valid field"""
sys.argv = ["", "--set", "network.wifi_ssid", "foo"]
mt_config.args = sys.argv
@@ -1061,12 +1055,11 @@ def test_main_set_valid_camel_case(mocked_findports, mocked_serial, mocked_open,
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_set_with_invalid(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_set_with_invalid(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --set with invalid field"""
sys.argv = ["", "--set", "foo", "foo"]
mt_config.args = sys.argv
@@ -1087,12 +1080,11 @@ def test_main_set_with_invalid(mocked_findports, mocked_serial, mocked_open, moc
# TODO: write some negative --configure tests
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_configure_with_snake_case(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_configure_with_snake_case(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --configure with valid file"""
sys.argv = ["", "--configure", "example_config.yaml"]
mt_config.args = sys.argv
@@ -1120,12 +1112,11 @@ def test_main_configure_with_snake_case(mocked_findports, mocked_serial, mocked_
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_main_configure_with_camel_case_keys(mocked_findports, mocked_serial, mocked_open, mocked_get, mocked_set, capsys):
def test_main_configure_with_camel_case_keys(mocked_findports, mocked_serial, mocked_open, mocked_hupcl, capsys):
"""Test --configure with valid file"""
sys.argv = ["", "--configure", "exampleConfig.yaml"]
mt_config.args = sys.argv
@@ -2722,16 +2713,16 @@ def test_tunnel_subnet_arg_with_no_devices(mock_platform_system, caplog, capsys)
assert err == ""
@pytest.mark.skipif(sys.platform == "win32", reason="on windows is no fcntl module")
@pytest.mark.unit
@pytest.mark.usefixtures("reset_mt_config")
@patch("platform.system")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_tunnel_tunnel_arg(
mocked_findPorts, mocked_serial, mocked_open, mock_get, mock_set, mock_platform_system, caplog, iface_with_nodes, capsys
mocked_findPorts, mocked_serial, mocked_open, mock_hupcl, mock_platform_system, caplog, iface_with_nodes, capsys
):
"""Test tunnel with tunnel arg (act like we are on a linux system)"""

22
meshtastic/tests/test_mesh_interface.py
View File

@@ -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 <class \'ValueError\'> 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

16
meshtastic/tests/test_serial_interface.py
View File

@@ -2,6 +2,7 @@
# pylint: disable=R0917
import re
import sys
from unittest.mock import mock_open, patch
import pytest
@@ -9,16 +10,14 @@ import pytest
from ..serial_interface import SerialInterface
from ..protobuf import config_pb2
@pytest.mark.unit
@patch("time.sleep")
@patch("termios.tcsetattr")
@patch("termios.tcgetattr")
@patch("meshtastic.serial_interface.SerialInterface._set_hupcl_with_termios")
@patch("builtins.open", new_callable=mock_open, read_data="data")
@patch("serial.Serial")
@patch("meshtastic.util.findPorts", return_value=["/dev/ttyUSBfake"])
def test_SerialInterface_single_port(
mocked_findPorts, mocked_serial, mocked_open, mock_get, mock_set, mock_sleep, capsys
mocked_findPorts, mocked_serial, mocked_open, mock_hupcl, mock_sleep, capsys
):
"""Test that we can instantiate a SerialInterface with a single port"""
iface = SerialInterface(noProto=True)
@@ -28,9 +27,12 @@ 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 on windows
if sys.platform != "win32":
mocked_open.assert_called()
mock_hupcl.assert_called()
mock_sleep.assert_called()
out, err = capsys.readouterr()
assert re.search(r"Nodes in mesh", out, re.MULTILINE)

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())