Crash_Override/FreeDATA
1
0
Fork 0
mirror of https://github.com/DJ2LS/FreeDATA synced 2024-05-14 10:04:33 +02:00
Code Issues Packages Projects Releases Wiki Activity

Another round of formatting changes.

Browse source 
Implement class-level logging in places.
This commit is contained in:
Paul Kronenwetter 2022-05-27 22:17:15 -04:00
parent 08202bbaec
commit 2fa9aead44
10 changed files with 380 additions and 379 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

49
tnc/daemon.py
View file

@ -55,6 +55,8 @@ class DAEMON:
Daemon class Daemon class
""" """
log = structlog.get_logger("DAEMON")
def __init__(self): def __init__(self):
# load crc engine # load crc engine
self.crc_algorithm = crcengine.new("crc16-ccitt-false") # load crc8 library self.crc_algorithm = crcengine.new("crc16-ccitt-false") # load crc8 library
@ -73,12 +75,12 @@ class DAEMON:
""" """
Update audio devices and set to static Update audio devices and set to static
""" """
while 1: while True:
try: try:
if not static.TNCSTARTED: if not static.TNCSTARTED:
static.AUDIO_INPUT_DEVICES, static.AUDIO_OUTPUT_DEVICES = audio.get_audio_devices() static.AUDIO_INPUT_DEVICES, static.AUDIO_OUTPUT_DEVICES = audio.get_audio_devices()
except Exception as err1: except Exception as err1:
structlog.get_logger("structlog").error("[DMN] update_audio_devices: Exception gathering audio devices:", e=err1) self.log.error("[DMN] update_audio_devices: Exception gathering audio devices:", e=err1)
# print(e) # print(e)
time.sleep(1) time.sleep(1)
@ -86,7 +88,7 @@ class DAEMON:
""" """
Update serial devices and set to static Update serial devices and set to static
""" """
while 1: while True:
try: try:
serial_devices = [] serial_devices = []
ports = serial.tools.list_ports.comports() ports = serial.tools.list_ports.comports()
@ -101,14 +103,14 @@ class DAEMON:
static.SERIAL_DEVICES = serial_devices static.SERIAL_DEVICES = serial_devices
time.sleep(1) time.sleep(1)
except Exception as err1: except Exception as err1:
structlog.get_logger("structlog").error("[DMN] update_serial_devices: Exception gathering serial devices:", e=err1) self.log.error("[DMN] update_serial_devices: Exception gathering serial devices:", e=err1)
# print(e) # print(e)
def worker(self): def worker(self):
""" """
Worker to handle the received commands Worker to handle the received commands
""" """
while 1: while True:
try: try:
data = self.daemon_queue.get() data = self.daemon_queue.get()
@ -137,7 +139,7 @@ class DAEMON:
# data[23] respond_to_cq # data[23] respond_to_cq
if data[0] == "STARTTNC": if data[0] == "STARTTNC":
structlog.get_logger("structlog").warning("[DMN] Starting TNC", rig=data[5], port=data[6]) self.log.warning("[DMN] Starting TNC", rig=data[5], port=data[6])
# list of parameters, necessary for running subprocess command as a list # list of parameters, necessary for running subprocess command as a list
options = [] options = []
@ -231,13 +233,13 @@ class DAEMON:
command.append("freedata-tnc.exe") command.append("freedata-tnc.exe")
command += options command += options
p = subprocess.Popen(command) proc = subprocess.Popen(command)
atexit.register(p.kill) atexit.register(proc.kill)
structlog.get_logger("structlog").info("[DMN] TNC started", path="binary") self.log.info("[DMN] TNC started", path="binary")
except FileNotFoundError as err1: except FileNotFoundError as err1:
structlog.get_logger("structlog").error("[DMN] worker: Exception:", e=err1) self.log.error("[DMN] worker: Exception:", e=err1)
command = [] command = []
if sys.platform in ["linux", "darwin"]: if sys.platform in ["linux", "darwin"]:
command.append("python3") command.append("python3")
@ -246,18 +248,18 @@ class DAEMON:
command.append("main.py") command.append("main.py")
command += options command += options
p = subprocess.Popen(command) proc = subprocess.Popen(command)
atexit.register(p.kill) atexit.register(proc.kill)
structlog.get_logger("structlog").info("[DMN] TNC started", path="source") self.log.info("[DMN] TNC started", path="source")
static.TNCPROCESS = p # .pid static.TNCPROCESS = proc
static.TNCSTARTED = True static.TNCSTARTED = True
""" """
# WE HAVE THIS PART in SOCKET # WE HAVE THIS PART in SOCKET
if data[0] == "STOPTNC": if data[0] == "STOPTNC":
static.TNCPROCESS.kill() static.TNCPROCESS.kill()
structlog.get_logger("structlog").warning("[DMN] Stopping TNC") self.log.warning("[DMN] Stopping TNC")
#os.kill(static.TNCPROCESS, signal.SIGKILL) #os.kill(static.TNCPROCESS, signal.SIGKILL)
static.TNCSTARTED = False static.TNCSTARTED = False
""" """
@ -306,13 +308,13 @@ class DAEMON:
pttstate = hamlib.get_ptt() pttstate = hamlib.get_ptt()
if pttstate: if pttstate:
structlog.get_logger("structlog").info("[DMN] Hamlib PTT", status="SUCCESS") self.log.info("[DMN] Hamlib PTT", status="SUCCESS")
response = {"command": "test_hamlib", "result": "SUCCESS"} response = {"command": "test_hamlib", "result": "SUCCESS"}
elif not pttstate: elif not pttstate:
structlog.get_logger("structlog").warning("[DMN] Hamlib PTT", status="NO SUCCESS") self.log.warning("[DMN] Hamlib PTT", status="NO SUCCESS")
response = {"command": "test_hamlib", "result": "NOSUCCESS"} response = {"command": "test_hamlib", "result": "NOSUCCESS"}
else: else:
structlog.get_logger("structlog").error("[DMN] Hamlib PTT", status="FAILED") self.log.error("[DMN] Hamlib PTT", status="FAILED")
response = {"command": "test_hamlib", "result": "FAILED"} response = {"command": "test_hamlib", "result": "FAILED"}
hamlib.set_ptt(False) hamlib.set_ptt(False)
@ -322,10 +324,11 @@ class DAEMON:
sock.SOCKET_QUEUE.put(jsondata) sock.SOCKET_QUEUE.put(jsondata)
except Exception as err1: except Exception as err1:
structlog.get_logger("structlog").error("[DMN] worker: Exception: ", e=err1) self.log.error("[DMN] worker: Exception: ", e=err1)
if __name__ == "__main__": if __name__ == "__main__":
mainlog = structlog.get_logger(__file__)
# we need to run this on Windows for multiprocessing support # we need to run this on Windows for multiprocessing support
multiprocessing.freeze_support() multiprocessing.freeze_support()
@ -350,10 +353,10 @@ if __name__ == "__main__":
os.makedirs(logging_path) os.makedirs(logging_path)
log_handler.setup_logging(logging_path) log_handler.setup_logging(logging_path)
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error("[DMN] logger init error", exception=err) mainlog.error("[DMN] logger init error", exception=err)
try: try:
structlog.get_logger("structlog").info("[DMN] Starting TCP/IP socket", port=static.DAEMONPORT) mainlog.info("[DMN] Starting TCP/IP socket", port=static.DAEMONPORT)
# https://stackoverflow.com/a/16641793 # https://stackoverflow.com/a/16641793
socketserver.TCPServer.allow_reuse_address = True socketserver.TCPServer.allow_reuse_address = True
cmdserver = sock.ThreadedTCPServer((static.HOST, static.DAEMONPORT), sock.ThreadedTCPRequestHandler) cmdserver = sock.ThreadedTCPServer((static.HOST, static.DAEMONPORT), sock.ThreadedTCPRequestHandler)
@ -362,10 +365,10 @@ if __name__ == "__main__":
server_thread.start() server_thread.start()
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error("[DMN] Starting TCP/IP socket failed", port=static.DAEMONPORT, e=err) mainlog.error("[DMN] Starting TCP/IP socket failed", port=static.DAEMONPORT, e=err)
sys.exit(1) sys.exit(1)
daemon = DAEMON() daemon = DAEMON()
structlog.get_logger("structlog").info("[DMN] Starting FreeDATA Daemon", author="DJ2LS", year="2022", version=static.VERSION) mainlog.info("[DMN] Starting FreeDATA Daemon", author="DJ2LS", year="2022", version=static.VERSION)
while True: while True:
time.sleep(1) time.sleep(1)

395
tnc/data_handler.py
View file

@ -34,6 +34,7 @@ DATA_QUEUE_RECEIVED = queue.Queue()
class DATA: class DATA:
""" Terminal Node Controller for FreeDATA """ """ Terminal Node Controller for FreeDATA """
log = structlog.get_logger("DATA")
def __init__(self): def __init__(self):
self.mycallsign = static.MYCALLSIGN # initial call sign. Will be overwritten later self.mycallsign = static.MYCALLSIGN # initial call sign. Will be overwritten later
@ -104,7 +105,8 @@ class DATA:
daemon=True) daemon=True)
worker_thread_transmit.start() worker_thread_transmit.start()
worker_thread_receive = threading.Thread(target=self.worker_receive, name="worker thread receive", daemon=True) worker_thread_receive = threading.Thread(target=self.worker_receive, name="worker thread receive",
daemon=True)
worker_thread_receive.start() worker_thread_receive.start()
# START THE THREAD FOR THE TIMEOUT WATCHDOG # START THE THREAD FOR THE TIMEOUT WATCHDOG
@ -163,8 +165,7 @@ class DATA:
# [1] DX CALLSIGN # [1] DX CALLSIGN
self.send_test_frame() self.send_test_frame()
else: else:
structlog.get_logger("structlog").error("[TNC] worker_transmit: received invalid command:", data=data) self.log.error("[TNC] worker_transmit: received invalid command:", data=data)
# print(f"Invalid command: {data}")
def worker_receive(self): def worker_receive(self):
""" """ """ """
@ -186,8 +187,7 @@ class DATA:
Returns: Returns:
""" """
structlog.get_logger("structlog").debug("[TNC] process_data:", n_retries_per_burst=self.n_retries_per_burst) self.log.debug("[TNC] process_data:", n_retries_per_burst=self.n_retries_per_burst)
# print(f"self.n_retries_per_burst = {self.n_retries_per_burst}")
# forward data only if broadcast or we are the receiver # forward data only if broadcast or we are the receiver
# bytes_out[1:4] == callsign check for signalling frames, # bytes_out[1:4] == callsign check for signalling frames,
@ -207,111 +207,111 @@ class DATA:
# snr = self.calculate_snr(freedv) # snr = self.calculate_snr(freedv)
# we need to find a way of fixing this because after moving to class system this doesn't work anymore # we need to find a way of fixing this because after moving to class system this doesn't work anymore
snr = static.SNR snr = static.SNR
structlog.get_logger("structlog").debug("[TNC] RX SNR", snr=snr) self.log.debug("[TNC] RX SNR", snr=snr)
# send payload data to arq checker without CRC16 # send payload data to arq checker without CRC16
self.arq_data_received(bytes(bytes_out[:-2]), bytes_per_frame, snr, freedv) self.arq_data_received(bytes(bytes_out[:-2]), bytes_per_frame, snr, freedv)
# if we received the last frame of a burst or the last remaining rpt frame, do a modem unsync # if we received the last frame of a burst or the last remaining rpt frame, do a modem unsync
# if static.RX_BURST_BUFFER.count(None) <= 1 or (frame+1) == n_frames_per_burst: # if static.RX_BURST_BUFFER.count(None) <= 1 or (frame+1) == n_frames_per_burst:
# structlog.get_logger("structlog").debug(f"[TNC] LAST FRAME OF BURST --> UNSYNC {frame+1}/{n_frames_per_burst}") # self.log.debug(f"[TNC] LAST FRAME OF BURST --> UNSYNC {frame+1}/{n_frames_per_burst}")
# self.c_lib.freedv_set_sync(freedv, 0) # self.c_lib.freedv_set_sync(freedv, 0)
# BURST ACK # BURST ACK
elif frametype == 60: elif frametype == 60:
structlog.get_logger("structlog").debug("[TNC] ACK RECEIVED....") self.log.debug("[TNC] ACK RECEIVED....")
self.burst_ack_received(bytes_out[:-2]) self.burst_ack_received(bytes_out[:-2])
# FRAME ACK # FRAME ACK
elif frametype == 61: elif frametype == 61:
structlog.get_logger("structlog").debug("[TNC] FRAME ACK RECEIVED....") self.log.debug("[TNC] FRAME ACK RECEIVED....")
self.frame_ack_received() self.frame_ack_received()
# FRAME RPT # FRAME RPT
elif frametype == 62: elif frametype == 62:
structlog.get_logger("structlog").debug("[TNC] REPEAT REQUEST RECEIVED....") self.log.debug("[TNC] REPEAT REQUEST RECEIVED....")
self.burst_rpt_received(bytes_out[:-2]) self.burst_rpt_received(bytes_out[:-2])
# FRAME NACK # FRAME NACK
elif frametype == 63: elif frametype == 63:
structlog.get_logger("structlog").debug("[TNC] FRAME NACK RECEIVED....") self.log.debug("[TNC] FRAME NACK RECEIVED....")
self.frame_nack_received(bytes_out[:-2]) self.frame_nack_received(bytes_out[:-2])
# BURST NACK # BURST NACK
elif frametype == 64: elif frametype == 64:
structlog.get_logger("structlog").debug("[TNC] BURST NACK RECEIVED....") self.log.debug("[TNC] BURST NACK RECEIVED....")
self.burst_nack_received(bytes_out[:-2]) self.burst_nack_received(bytes_out[:-2])
# CQ FRAME # CQ FRAME
elif frametype == 200: elif frametype == 200:
structlog.get_logger("structlog").debug("[TNC] CQ RECEIVED....") self.log.debug("[TNC] CQ RECEIVED....")
self.received_cq(bytes_out[:-2]) self.received_cq(bytes_out[:-2])
# QRV FRAME # QRV FRAME
elif frametype == 201: elif frametype == 201:
structlog.get_logger("structlog").debug("[TNC] QRV RECEIVED....") self.log.debug("[TNC] QRV RECEIVED....")
self.received_qrv(bytes_out[:-2]) self.received_qrv(bytes_out[:-2])
# PING FRAME # PING FRAME
elif frametype == 210: elif frametype == 210:
structlog.get_logger("structlog").debug("[TNC] PING RECEIVED....") self.log.debug("[TNC] PING RECEIVED....")
self.received_ping(bytes_out[:-2]) self.received_ping(bytes_out[:-2])
# PING ACK # PING ACK
elif frametype == 211: elif frametype == 211:
structlog.get_logger("structlog").debug("[TNC] PING ACK RECEIVED....") self.log.debug("[TNC] PING ACK RECEIVED....")
self.received_ping_ack(bytes_out[:-2]) self.received_ping_ack(bytes_out[:-2])
# SESSION OPENER # SESSION OPENER
elif frametype == 221: elif frametype == 221:
structlog.get_logger("structlog").debug("[TNC] OPEN SESSION RECEIVED....") self.log.debug("[TNC] OPEN SESSION RECEIVED....")
self.received_session_opener(bytes_out[:-2]) self.received_session_opener(bytes_out[:-2])
# SESSION HEARTBEAT # SESSION HEARTBEAT
elif frametype == 222: elif frametype == 222:
structlog.get_logger("structlog").debug("[TNC] SESSION HEARTBEAT RECEIVED....") self.log.debug("[TNC] SESSION HEARTBEAT RECEIVED....")
self.received_session_heartbeat(bytes_out[:-2]) self.received_session_heartbeat(bytes_out[:-2])
# SESSION CLOSE # SESSION CLOSE
elif frametype == 223: elif frametype == 223:
structlog.get_logger("structlog").debug("[TNC] CLOSE ARQ SESSION RECEIVED....") self.log.debug("[TNC] CLOSE ARQ SESSION RECEIVED....")
self.received_session_close(bytes_out[:-2]) self.received_session_close(bytes_out[:-2])
# ARQ FILE TRANSFER RECEIVED! # ARQ FILE TRANSFER RECEIVED!
elif frametype in [225, 227]: elif frametype in [225, 227]:
structlog.get_logger("structlog").debug("[TNC] ARQ arq_received_data_channel_opener") self.log.debug("[TNC] ARQ arq_received_data_channel_opener")
self.arq_received_data_channel_opener(bytes_out[:-2]) self.arq_received_data_channel_opener(bytes_out[:-2])
# ARQ CHANNEL IS OPENED # ARQ CHANNEL IS OPENED
elif frametype in [226, 228]: elif frametype in [226, 228]:
structlog.get_logger("structlog").debug("[TNC] ARQ arq_received_channel_is_open") self.log.debug("[TNC] ARQ arq_received_channel_is_open")
self.arq_received_channel_is_open(bytes_out[:-2]) self.arq_received_channel_is_open(bytes_out[:-2])
# ARQ MANUAL MODE TRANSMISSION # ARQ MANUAL MODE TRANSMISSION
elif 230 <= frametype <= 240: elif 230 <= frametype <= 240:
structlog.get_logger("structlog").debug("[TNC] ARQ manual mode") self.log.debug("[TNC] ARQ manual mode")
self.arq_received_data_channel_opener(bytes_out[:-2]) self.arq_received_data_channel_opener(bytes_out[:-2])
# ARQ STOP TRANSMISSION # ARQ STOP TRANSMISSION
elif frametype == 249: elif frametype == 249:
structlog.get_logger("structlog").debug("[TNC] ARQ received stop transmission") self.log.debug("[TNC] ARQ received stop transmission")
self.received_stop_transmission() self.received_stop_transmission()
# this is outdated and we may remove it # this is outdated and we may remove it
elif frametype == 250: elif frametype == 250:
structlog.get_logger("structlog").debug("[TNC] BEACON RECEIVED") self.log.debug("[TNC] BEACON RECEIVED")
self.received_beacon(bytes_out[:-2]) self.received_beacon(bytes_out[:-2])
# TESTFRAMES # TESTFRAMES
elif frametype == 255: elif frametype == 255:
structlog.get_logger("structlog").debug("[TNC] TESTFRAME RECEIVED", frame=bytes_out[:]) self.log.debug("[TNC] TESTFRAME RECEIVED", frame=bytes_out[:])
# Unknown frame type # Unknown frame type
else: else:
structlog.get_logger("structlog").warning("[TNC] ARQ - other frame type", frametype=frametype) self.log.warning("[TNC] ARQ - other frame type", frametype=frametype)
else: else:
# for debugging purposes to receive all data # for debugging purposes to receive all data
structlog.get_logger("structlog").debug("[TNC] Unknown frame received", frame=bytes_out[:-2]) self.log.debug("[TNC] Unknown frame received", frame=bytes_out[:-2])
def enqueue_frame_for_tx(self, frame_to_tx: bytearray, c2_mode=14, copies=1, repeat_delay=0): def enqueue_frame_for_tx(self, frame_to_tx: bytearray, c2_mode=14, copies=1, repeat_delay=0):
""" """
@ -326,7 +326,7 @@ class DATA:
:param repeat_delay: Delay time before sending repeat frame, defaults to 0 :param repeat_delay: Delay time before sending repeat frame, defaults to 0
:type repeat_delay: int, optional :type repeat_delay: int, optional
""" """
structlog.get_logger("structlog").debug("[TNC] enqueue_frame_for_tx", c2_mode=c2_mode) self.log.debug("[TNC] enqueue_frame_for_tx", c2_mode=c2_mode)
if isinstance(c2_mode, str): if isinstance(c2_mode, str):
_mode = codec2.freedv_get_mode_value_by_name(c2_mode.lower()) _mode = codec2.freedv_get_mode_value_by_name(c2_mode.lower())
else: else:
@ -379,7 +379,7 @@ class DATA:
rpt_frame[4:7] = static.MYCALLSIGN_CRC rpt_frame[4:7] = static.MYCALLSIGN_CRC
rpt_frame[7:13] = missing_frames rpt_frame[7:13] = missing_frames
structlog.get_logger("structlog").info("[TNC] ARQ | RX | Requesting", frames=missing_frames) self.log.info("[TNC] ARQ | RX | Requesting", frames=missing_frames)
# Transmit frame # Transmit frame
self.enqueue_frame_for_tx(rpt_frame) self.enqueue_frame_for_tx(rpt_frame)
@ -464,10 +464,10 @@ class DATA:
# Append data to rx burst buffer # Append data to rx burst buffer
static.RX_BURST_BUFFER[RX_N_FRAME_OF_BURST] = data_in[8:] # [frame_type][n_frames_per_burst][CRC24][CRC24] static.RX_BURST_BUFFER[RX_N_FRAME_OF_BURST] = data_in[8:] # [frame_type][n_frames_per_burst][CRC24][CRC24]
structlog.get_logger("structlog").debug("[TNC] static.RX_BURST_BUFFER", buffer=static.RX_BURST_BUFFER) self.log.debug("[TNC] static.RX_BURST_BUFFER", buffer=static.RX_BURST_BUFFER)
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", snr, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL",
static.HAMLIB_FREQUENCY) snr, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
# Check if we received all frames in the burst by checking if burst buffer has no more "Nones" # Check if we received all frames in the burst by checking if burst buffer has no more "Nones"
# This is the ideal case because we received all data # This is the ideal case because we received all data
@ -482,7 +482,7 @@ class DATA:
# if frame buffer ends not with the current frame, we are going to append new data # if frame buffer ends not with the current frame, we are going to append new data
# if data already exists, we received the frame correctly, but the ACK frame didnt receive its destination (ISS) # if data already exists, we received the frame correctly, but the ACK frame didnt receive its destination (ISS)
if static.RX_FRAME_BUFFER.endswith(temp_burst_buffer): if static.RX_FRAME_BUFFER.endswith(temp_burst_buffer):
structlog.get_logger("structlog").info("[TNC] ARQ | RX | Frame already received - sending ACK again") self.log.info("[TNC] ARQ | RX | Frame already received - sending ACK again")
static.RX_BURST_BUFFER = [] static.RX_BURST_BUFFER = []
else: else:
@ -503,12 +503,12 @@ class DATA:
static.RX_FRAME_BUFFER = static.RX_FRAME_BUFFER[:search_position + get_position] static.RX_FRAME_BUFFER = static.RX_FRAME_BUFFER[:search_position + get_position]
static.RX_FRAME_BUFFER += temp_burst_buffer static.RX_FRAME_BUFFER += temp_burst_buffer
structlog.get_logger("structlog").warning("[TNC] ARQ | RX | replacing existing buffer data", self.log.warning("[TNC] ARQ | RX | replacing existing buffer data",
area=search_area, pos=get_position) area=search_area, pos=get_position)
# if we dont find data n this range, we really have new data and going to replace it # if we dont find data n this range, we really have new data and going to replace it
else: else:
static.RX_FRAME_BUFFER += temp_burst_buffer static.RX_FRAME_BUFFER += temp_burst_buffer
structlog.get_logger("structlog").debug("[TNC] ARQ | RX | appending data to buffer") self.log.debug("[TNC] ARQ | RX | appending data to buffer")
# lets check if we didnt receive a BOF and EOF yet to avoid sending ack frames if we already received all data # lets check if we didnt receive a BOF and EOF yet to avoid sending ack frames if we already received all data
if (not self.rx_frame_bof_received and if (not self.rx_frame_bof_received and
@ -527,7 +527,7 @@ class DATA:
self.set_listening_modes(self.mode_list[self.speed_level]) self.set_listening_modes(self.mode_list[self.speed_level])
# Create and send ACK frame # Create and send ACK frame
structlog.get_logger("structlog").info("[TNC] ARQ | RX | SENDING ACK") self.log.info("[TNC] ARQ | RX | SENDING ACK")
self.send_burst_ack_frame(snr) self.send_burst_ack_frame(snr)
# Reset n retries per burst counter # Reset n retries per burst counter
@ -541,15 +541,15 @@ class DATA:
# Check if we received last frame of burst - this is an indicator for missed frames. # Check if we received last frame of burst - this is an indicator for missed frames.
# With this way of doing this, we always MUST receive the last frame of a burst otherwise the entire # With this way of doing this, we always MUST receive the last frame of a burst otherwise the entire
# burst is lost # burst is lost
structlog.get_logger("structlog").debug("[TNC] all frames in burst received:", frame=RX_N_FRAME_OF_BURST, self.log.debug("[TNC] all frames in burst received:", frame=RX_N_FRAME_OF_BURST,
frames=RX_N_FRAMES_PER_BURST) frames=RX_N_FRAMES_PER_BURST)
self.send_retransmit_request_frame(freedv) self.send_retransmit_request_frame(freedv)
self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER)) self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER))
# Should never reach this point # Should never reach this point
else: else:
structlog.get_logger("structlog").error("[TNC] data_handler: Should not reach this point...", self.log.error("[TNC] data_handler: Should not reach this point...",
frame=RX_N_FRAME_OF_BURST, frames=RX_N_FRAMES_PER_BURST) frame=RX_N_FRAME_OF_BURST, frames=RX_N_FRAMES_PER_BURST)
# We have a BOF and EOF flag in our data. If we received both we received our frame. # We have a BOF and EOF flag in our data. If we received both we received our frame.
# In case of loosing data, but we received already a BOF and EOF we need to make sure, we # In case of loosing data, but we received already a BOF and EOF we need to make sure, we
@ -569,8 +569,8 @@ class DATA:
self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER)) self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER))
if bof_position >= 0 and eof_position > 0 and None not in static.RX_BURST_BUFFER: if bof_position >= 0 and eof_position > 0 and None not in static.RX_BURST_BUFFER:
structlog.get_logger("structlog").debug("[TNC] arq_data_received:", bof_position=bof_position, self.log.debug("[TNC] arq_data_received:", bof_position=bof_position,
eof_position=eof_position) eof_position=eof_position)
# print(f"bof_position {bof_position} / eof_position {eof_position}") # print(f"bof_position {bof_position} / eof_position {eof_position}")
self.rx_frame_bof_received = True self.rx_frame_bof_received = True
self.rx_frame_eof_received = True self.rx_frame_eof_received = True
@ -589,7 +589,7 @@ class DATA:
# Check if data_frame_crc is equal with received crc # Check if data_frame_crc is equal with received crc
if data_frame_crc == data_frame_crc_received: if data_frame_crc == data_frame_crc_received:
structlog.get_logger("structlog").info("[TNC] ARQ | RX | DATA FRAME SUCESSFULLY RECEIVED") self.log.info("[TNC] ARQ | RX | DATA FRAME SUCESSFULLY RECEIVED")
# Decompress the data frame # Decompress the data frame
data_frame_decompressed = zlib.decompress(data_frame) data_frame_decompressed = zlib.decompress(data_frame)
@ -611,31 +611,31 @@ class DATA:
base64_data = base64.b64encode(data_frame).decode("utf-8") base64_data = base64.b64encode(data_frame).decode("utf-8")
static.RX_BUFFER.append([uniqueid, timestamp, static.DXCALLSIGN, static.DXGRID, base64_data]) static.RX_BUFFER.append([uniqueid, timestamp, static.DXCALLSIGN, static.DXGRID, base64_data])
jsondata = {"arq": "received", "uuid": uniqueid, "timestamp": timestamp, jsondata = {"arq": "received", "uuid": uniqueid, "timestamp": timestamp,
"mycallsign": str(mycallsign, "utf-8"), "dxcallsign": str(static.DXCALLSIGN, "utf-8"), "mycallsign": str(mycallsign, "utf-8"),
"dxcallsign": str(static.DXCALLSIGN, "utf-8"),
"dxgrid": str(static.DXGRID, "utf-8"), "data": base64_data} "dxgrid": str(static.DXGRID, "utf-8"), "data": base64_data}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
structlog.get_logger("structlog").debug("[TNC] arq_data_received:", jsondata=jsondata) self.log.debug("[TNC] arq_data_received:", jsondata=jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
static.INFO.append("ARQ;RECEIVING;SUCCESS") static.INFO.append("ARQ;RECEIVING;SUCCESS")
structlog.get_logger("structlog").info("[TNC] ARQ | RX | SENDING DATA FRAME ACK", snr=snr, self.log.info("[TNC] ARQ | RX | SENDING DATA FRAME ACK", snr=snr,
crc=data_frame_crc.hex()) crc=data_frame_crc.hex())
self.send_data_ack_frame(snr) self.send_data_ack_frame(snr)
# update our statistics AFTER the frame ACK # update our statistics AFTER the frame ACK
self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER)) self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER))
structlog.get_logger("structlog").info("[TNC] | RX | DATACHANNEL [" + self.log.info("[TNC] | RX | DATACHANNEL [" + str(self.mycallsign, "utf-8") +
str(self.mycallsign, "utf-8") + "]<< >>[" + str( "]<< >>[" + str(static.DXCALLSIGN, "utf-8") + "]", snr=snr)
static.DXCALLSIGN, "utf-8") + "]", snr=snr)
else: else:
static.INFO.append("ARQ;RECEIVING;FAILED") static.INFO.append("ARQ;RECEIVING;FAILED")
structlog.get_logger("structlog").warning("[TNC] ARQ | RX | DATA FRAME NOT SUCESSFULLY RECEIVED!", self.log.warning("[TNC] ARQ | RX | DATA FRAME NOT SUCESSFULLY RECEIVED!",
e="wrong crc", expected=data_frame_crc, e="wrong crc", expected=data_frame_crc,
received=data_frame_crc_received, received=data_frame_crc_received,
overflows=static.BUFFER_OVERFLOW_COUNTER) overflows=static.BUFFER_OVERFLOW_COUNTER)
structlog.get_logger("structlog").info("[TNC] ARQ | RX | Sending NACK") self.log.info("[TNC] ARQ | RX | Sending NACK")
self.send_burst_nack_frame(snr) self.send_burst_nack_frame(snr)
# update session timeout # update session timeout
@ -684,7 +684,7 @@ class DATA:
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
structlog.get_logger("structlog").info("[TNC] | TX | DATACHANNEL", mode=mode, Bytes=static.TOTAL_BYTES) self.log.info("[TNC] | TX | DATACHANNEL", mode=mode, Bytes=static.TOTAL_BYTES)
# Compress data frame # Compress data frame
data_frame_compressed = zlib.compress(data_out) data_frame_compressed = zlib.compress(data_out)
@ -700,7 +700,7 @@ class DATA:
# Append a crc and the begin and end of file indicators # Append a crc and the begin and end of file indicators
frame_payload_crc = helpers.get_crc_32(data_out) frame_payload_crc = helpers.get_crc_32(data_out)
structlog.get_logger("structlog").debug("[TNC] frame payload CRC:", crc=frame_payload_crc) self.log.debug("[TNC] frame payload CRC:", crc=frame_payload_crc)
# data_out = self.data_frame_bof + frame_payload_crc + data_out + self.data_frame_eof # data_out = self.data_frame_bof + frame_payload_crc + data_out + self.data_frame_eof
data_out = self.data_frame_bof + frame_payload_crc + frame_total_size + compression_factor + data_out + self.data_frame_eof data_out = self.data_frame_bof + frame_payload_crc + frame_total_size + compression_factor + data_out + self.data_frame_eof
@ -718,7 +718,7 @@ class DATA:
# force usage of selected mode # force usage of selected mode
if mode != 255: if mode != 255:
data_mode = mode data_mode = mode
structlog.get_logger("structlog").debug("[TNC] FIXED MODE:", mode=data_mode) self.log.debug("[TNC] FIXED MODE:", mode=data_mode)
else: else:
# we are doing a modulo check of transmission retries of the actual burst # we are doing a modulo check of transmission retries of the actual burst
# every 2nd retry which fails, decreases speedlevel by 1. # every 2nd retry which fails, decreases speedlevel by 1.
@ -745,8 +745,8 @@ class DATA:
static.ARQ_SPEED_LEVEL = self.speed_level static.ARQ_SPEED_LEVEL = self.speed_level
data_mode = self.mode_list[self.speed_level] data_mode = self.mode_list[self.speed_level]
structlog.get_logger("structlog").debug("[TNC] Speed-level:", level=self.speed_level, self.log.debug("[TNC] Speed-level:", level=self.speed_level,
retry=self.tx_n_retry_of_burst, mode=data_mode) retry=self.tx_n_retry_of_burst, mode=data_mode)
# payload information # payload information
payload_per_frame = modem.get_bytes_per_frame(data_mode) - 2 payload_per_frame = modem.get_bytes_per_frame(data_mode) - 2
@ -784,9 +784,9 @@ class DATA:
# append frame to tempbuffer for transmission # append frame to tempbuffer for transmission
tempbuffer.append(frame) tempbuffer.append(frame)
structlog.get_logger("structlog").debug("[TNC] tempbuffer:", tempbuffer=tempbuffer) self.log.debug("[TNC] tempbuffer:", tempbuffer=tempbuffer)
structlog.get_logger("structlog").info("[TNC] ARQ | TX | FRAMES", mode=data_mode, self.log.info("[TNC] ARQ | TX | FRAMES", mode=data_mode,
fpb=TX_N_FRAMES_PER_BURST, retry=self.tx_n_retry_of_burst) fpb=TX_N_FRAMES_PER_BURST, retry=self.tx_n_retry_of_burst)
# we need to set our TRANSMITTING flag before we are adding an object the transmit queue # we need to set our TRANSMITTING flag before we are adding an object the transmit queue
# this is not that nice, we could improve this somehow # this is not that nice, we could improve this somehow
@ -833,9 +833,8 @@ class DATA:
self.calculate_transfer_rate_tx(tx_start_of_transmission, bufferposition_end, len(data_out)) self.calculate_transfer_rate_tx(tx_start_of_transmission, bufferposition_end, len(data_out))
# NEXT ATTEMPT # NEXT ATTEMPT
structlog.get_logger("structlog").debug("[TNC] ATTEMPT:", retry=self.tx_n_retry_of_burst, self.log.debug("[TNC] ATTEMPT:", retry=self.tx_n_retry_of_burst,
maxretries=TX_N_MAX_RETRIES_PER_BURST, maxretries=TX_N_MAX_RETRIES_PER_BURST, overflows=static.BUFFER_OVERFLOW_COUNTER)
overflows=static.BUFFER_OVERFLOW_COUNTER)
# update buffer position # update buffer position
bufferposition = bufferposition_end bufferposition = bufferposition_end
@ -844,7 +843,7 @@ class DATA:
self.calculate_transfer_rate_tx(tx_start_of_transmission, bufferposition_end, len(data_out)) self.calculate_transfer_rate_tx(tx_start_of_transmission, bufferposition_end, len(data_out))
jsondata = {"arq": "transmission", "status": "transmitting", "uuid": self.transmission_uuid, jsondata = {"arq": "transmission", "status": "transmitting", "uuid": self.transmission_uuid,
"percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE} "percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
@ -853,24 +852,24 @@ class DATA:
if self.data_frame_ack_received: if self.data_frame_ack_received:
static.INFO.append("ARQ;TRANSMITTING;SUCCESS") static.INFO.append("ARQ;TRANSMITTING;SUCCESS")
jsondata = {"arq": "transmission", "status": "success", "uuid": self.transmission_uuid, jsondata = {"arq": "transmission", "status": "success", "uuid": self.transmission_uuid,
"percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE} "percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
structlog.get_logger("structlog").info("[TNC] ARQ | TX | DATA TRANSMITTED!", self.log.info("[TNC] ARQ | TX | DATA TRANSMITTED!",
BytesPerMinute=static.ARQ_BYTES_PER_MINUTE, BytesPerMinute=static.ARQ_BYTES_PER_MINUTE, BitsPerSecond=static.ARQ_BITS_PER_SECOND,
BitsPerSecond=static.ARQ_BITS_PER_SECOND, overflows=static.BUFFER_OVERFLOW_COUNTER)
overflows=static.BUFFER_OVERFLOW_COUNTER)
else: else:
static.INFO.append("ARQ;TRANSMITTING;FAILED") static.INFO.append("ARQ;TRANSMITTING;FAILED")
jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid, jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid,
"percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE} "percent": static.ARQ_TRANSMISSION_PERCENT,
"bytesperminute": static.ARQ_BYTES_PER_MINUTE}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
structlog.get_logger("structlog").info("[TNC] ARQ | TX | TRANSMISSION FAILED OR TIME OUT!", self.log.info("[TNC] ARQ | TX | TRANSMISSION FAILED OR TIME OUT!",
overflows=static.BUFFER_OVERFLOW_COUNTER) overflows=static.BUFFER_OVERFLOW_COUNTER)
self.stop_transmission() self.stop_transmission()
# and last but not least doing a state cleanup # and last but not least doing a state cleanup
@ -905,8 +904,8 @@ class DATA:
self.burst_ack_snr = int.from_bytes(bytes(data_in[7:8]), "big") self.burst_ack_snr = int.from_bytes(bytes(data_in[7:8]), "big")
self.speed_level = int.from_bytes(bytes(data_in[8:9]), "big") self.speed_level = int.from_bytes(bytes(data_in[8:9]), "big")
static.ARQ_SPEED_LEVEL = self.speed_level static.ARQ_SPEED_LEVEL = self.speed_level
structlog.get_logger("structlog").debug("[TNC] burst_ack_received:", speed_level=self.speed_level) self.log.debug("[TNC] burst_ack_received:", speed_level=self.speed_level)
# print(self.speed_level)
# reset burst nack counter # reset burst nack counter
self.burst_nack_counter = 0 self.burst_nack_counter = 0
# reset n retries per burst counter # reset n retries per burst counter
@ -919,8 +918,6 @@ class DATA:
Args: Args:
data_in:bytes: data_in:bytes:
Returns:
""" """
# increase speed level if we received a burst ack # increase speed level if we received a burst ack
# self.speed_level += 1 # self.speed_level += 1
@ -937,8 +934,7 @@ class DATA:
self.speed_level = int.from_bytes(bytes(data_in[8:9]), "big") self.speed_level = int.from_bytes(bytes(data_in[8:9]), "big")
static.ARQ_SPEED_LEVEL = self.speed_level static.ARQ_SPEED_LEVEL = self.speed_level
self.burst_nack_counter += 1 self.burst_nack_counter += 1
structlog.get_logger("structlog").debug("[TNC] burst_nack_received:", speed_level=self.speed_level) self.log.debug("[TNC] burst_nack_received:", speed_level=self.speed_level)
# print(self.speed_level)
def frame_ack_received(self): def frame_ack_received(self):
""" """ """ """
@ -946,9 +942,11 @@ class DATA:
if static.ARQ_STATE: if static.ARQ_STATE:
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR,
static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
self.data_frame_ack_received = True # Force data loops of TNC to stop and continue with next frame # Force data loops of TNC to stop and continue with next frame
self.data_channel_last_received = int(time.time()) # we need to update our timeout timestamp self.data_frame_ack_received = True
self.arq_session_last_received = int(time.time()) # we need to update our timeout timestamp # Update timeout timestamps
self.data_channel_last_received = int(time.time())
self.arq_session_last_received = int(time.time())
def frame_nack_received(self, data_in: bytes): # pylint: disable=unused-argument def frame_nack_received(self, data_in: bytes): # pylint: disable=unused-argument
""" """
@ -959,8 +957,8 @@ class DATA:
Returns: Returns:
""" """
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL",
static.HAMLIB_FREQUENCY) static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
static.INFO.append("ARQ;TRANSMITTING;FAILED") static.INFO.append("ARQ;TRANSMITTING;FAILED")
jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid, jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid,
"percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE} "percent": static.ARQ_TRANSMISSION_PERCENT, "bytesperminute": static.ARQ_BYTES_PER_MINUTE}
@ -1010,8 +1008,9 @@ class DATA:
""" """
# TODO: we need to check this, maybe placing it to class init # TODO: we need to check this, maybe placing it to class init
self.datachannel_timeout = False self.datachannel_timeout = False
structlog.get_logger("structlog").info( self.log.info(
"[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] SESSION [" + str(self.mycallsign, "utf-8") +
"]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]",
state=static.ARQ_SESSION_STATE) state=static.ARQ_SESSION_STATE)
self.open_session(callsign) self.open_session(callsign)
@ -1049,10 +1048,10 @@ class DATA:
while not static.ARQ_SESSION: while not static.ARQ_SESSION:
time.sleep(0.01) time.sleep(0.01)
for attempt in range(1, self.session_connect_max_retries + 1): for attempt in range(1, self.session_connect_max_retries + 1):
structlog.get_logger("structlog").info( self.log.info(
"[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]>>?<<[" + str(static.DXCALLSIGN, "[TNC] SESSION [" + str(self.mycallsign, "utf-8") +
"utf-8") + "]", a=attempt, "]>>?<<[" + str(static.DXCALLSIGN, "utf-8") + "]",
state=static.ARQ_SESSION_STATE) a=attempt, state=static.ARQ_SESSION_STATE)
self.enqueue_frame_for_tx(connection_frame) self.enqueue_frame_for_tx(connection_frame)
@ -1089,10 +1088,11 @@ class DATA:
static.DXCALLSIGN_CRC = bytes(data_in[4:7]) static.DXCALLSIGN_CRC = bytes(data_in[4:7])
static.DXCALLSIGN = helpers.bytes_to_callsign(bytes(data_in[7:13])) static.DXCALLSIGN = helpers.bytes_to_callsign(bytes(data_in[7:13]))
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL",
static.HAMLIB_FREQUENCY) static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
structlog.get_logger("structlog").info( self.log.info(
"[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] SESSION [" + str(self.mycallsign, "utf-8") +
"]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]",
state=static.ARQ_SESSION_STATE) state=static.ARQ_SESSION_STATE)
static.ARQ_SESSION = True static.ARQ_SESSION = True
static.TNC_STATE = "BUSY" static.TNC_STATE = "BUSY"
@ -1102,10 +1102,11 @@ class DATA:
def close_session(self): def close_session(self):
""" Close the ARQ session """ """ Close the ARQ session """
static.ARQ_SESSION_STATE = "disconnecting" static.ARQ_SESSION_STATE = "disconnecting"
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL",
static.HAMLIB_FREQUENCY) static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
structlog.get_logger("structlog").info( self.log.info(
"[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]<<X>>[" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] SESSION [" + str(self.mycallsign, "utf-8") +
"]<<X>>[" + str(static.DXCALLSIGN, "utf-8") + "]",
state=static.ARQ_SESSION_STATE) state=static.ARQ_SESSION_STATE)
static.INFO.append("ARQ;SESSION;CLOSE") static.INFO.append("ARQ;SESSION;CLOSE")
self.IS_ARQ_SESSION_MASTER = False self.IS_ARQ_SESSION_MASTER = False
@ -1131,8 +1132,9 @@ class DATA:
static.ARQ_SESSION_STATE = "disconnected" static.ARQ_SESSION_STATE = "disconnected"
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR,
static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
structlog.get_logger("structlog").info( self.log.info(
"[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]<<X>>[" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] SESSION [" + str(self.mycallsign, "utf-8") +
"]<<X>>[" + str(static.DXCALLSIGN, "utf-8") + "]",
state=static.ARQ_SESSION_STATE) state=static.ARQ_SESSION_STATE)
static.INFO.append("ARQ;SESSION;CLOSE") static.INFO.append("ARQ;SESSION;CLOSE")
@ -1165,7 +1167,7 @@ class DATA:
# Accept session data if the DXCALLSIGN_CRC matches the station in static. # Accept session data if the DXCALLSIGN_CRC matches the station in static.
_valid_crc, _ = helpers.check_callsign(static.DXCALLSIGN, bytes(data_in[4:7])) _valid_crc, _ = helpers.check_callsign(static.DXCALLSIGN, bytes(data_in[4:7]))
if _valid_crc: if _valid_crc:
structlog.get_logger("structlog").debug("[TNC] Received session heartbeat") self.log.debug("[TNC] Received session heartbeat")
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "SESSION-HB", static.SNR, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "SESSION-HB", static.SNR,
static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
@ -1238,14 +1240,14 @@ class DATA:
if static.LOW_BANDWITH_MODE and mode == 255: if static.LOW_BANDWITH_MODE and mode == 255:
frametype = bytes([227]) frametype = bytes([227])
structlog.get_logger("structlog").debug("[TNC] Requesting low bandwidth mode") self.log.debug("[TNC] Requesting low bandwidth mode")
else: else:
frametype = bytes([225]) frametype = bytes([225])
structlog.get_logger("structlog").debug("[TNC] Requesting high bandwidth mode") self.log.debug("[TNC] Requesting high bandwidth mode")
if 230 <= mode <= 240: if 230 <= mode <= 240:
structlog.get_logger("structlog").debug("[TNC] Requesting manual mode --> not yet implemented ") self.log.debug("[TNC] Requesting manual mode --> not yet implemented ")
frametype = bytes([mode]) frametype = bytes([mode])
connection_frame = bytearray(14) connection_frame = bytearray(14)
@ -1259,9 +1261,9 @@ class DATA:
time.sleep(0.01) time.sleep(0.01)
for attempt in range(1, self.data_channel_max_retries + 1): for attempt in range(1, self.data_channel_max_retries + 1):
static.INFO.append("DATACHANNEL;OPENING") static.INFO.append("DATACHANNEL;OPENING")
structlog.get_logger("structlog").info( self.log.info(
"[TNC] ARQ | DATA | TX | [" + str(mycallsign, "utf-8") + "]>> <<[" + str(static.DXCALLSIGN, "[TNC] ARQ | DATA | TX | [" + str(mycallsign, "utf-8") +
"utf-8") + "]", "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]",
attempt=f"{str(attempt)}/{str(self.data_channel_max_retries)}") attempt=f"{str(attempt)}/{str(self.data_channel_max_retries)}")
self.enqueue_frame_for_tx(connection_frame) self.enqueue_frame_for_tx(connection_frame)
@ -1279,8 +1281,8 @@ class DATA:
if attempt == self.data_channel_max_retries: if attempt == self.data_channel_max_retries:
static.INFO.append("DATACHANNEL;FAILED") static.INFO.append("DATACHANNEL;FAILED")
structlog.get_logger("structlog").debug("[TNC] arq_open_data_channel:", self.log.debug("[TNC] arq_open_data_channel:",
transmission_uuid=self.transmission_uuid) transmission_uuid=self.transmission_uuid)
# print(self.transmission_uuid) # print(self.transmission_uuid)
jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid, jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid,
"percent": static.ARQ_TRANSMISSION_PERCENT, "percent": static.ARQ_TRANSMISSION_PERCENT,
@ -1288,9 +1290,10 @@ class DATA:
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
structlog.get_logger("structlog").warning( self.log.warning(
"[TNC] ARQ | TX | DATA [" + str(mycallsign, "utf-8") + "]>>X<<[" + str(static.DXCALLSIGN, "[TNC] ARQ | TX | DATA [" + str(mycallsign, "utf-8") +
"utf-8") + "]") "]>>X<<[" + str(static.DXCALLSIGN, "utf-8") + "]"
)
self.datachannel_timeout = True self.datachannel_timeout = True
if not TESTMODE: if not TESTMODE:
self.arq_cleanup() self.arq_cleanup()
@ -1307,8 +1310,6 @@ class DATA:
Args: Args:
data_in:bytes: data_in:bytes:
Returns:
""" """
self.arq_file_transfer = True self.arq_file_transfer = True
self.is_IRS = True self.is_IRS = True
@ -1330,14 +1331,13 @@ class DATA:
self.speed_level = len(self.mode_list) - 1 self.speed_level = len(self.mode_list) - 1
if 230 <= frametype <= 240: if 230 <= frametype <= 240:
structlog.get_logger("structlog").debug("[TNC] arq_received_data_channel_opener: manual mode request") self.log.debug("[TNC] arq_received_data_channel_opener: manual mode request")
# print("manual mode request")
# updated modes we are listening to # updated modes we are listening to
self.set_listening_modes(self.mode_list[self.speed_level]) self.set_listening_modes(self.mode_list[self.speed_level])
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL",
static.HAMLIB_FREQUENCY) static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
# check if callsign ssid override # check if callsign ssid override
valid, mycallsign = helpers.check_callsign(self.mycallsign, data_in[1:4]) valid, mycallsign = helpers.check_callsign(self.mycallsign, data_in[1:4])
@ -1347,8 +1347,9 @@ class DATA:
self.arq_cleanup() self.arq_cleanup()
return return
structlog.get_logger("structlog").info( self.log.info(
"[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") +
"]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]",
bandwith="wide") bandwith="wide")
static.ARQ_STATE = True static.ARQ_STATE = True
@ -1360,10 +1361,10 @@ class DATA:
# check if we are in low bandwith mode # check if we are in low bandwith mode
if static.LOW_BANDWITH_MODE or self.received_low_bandwith_mode: if static.LOW_BANDWITH_MODE or self.received_low_bandwith_mode:
frametype = bytes([228]) frametype = bytes([228])
structlog.get_logger("structlog").debug("[TNC] Responding with low bandwidth mode") self.log.debug("[TNC] Responding with low bandwidth mode")
else: else:
frametype = bytes([226]) frametype = bytes([226])
structlog.get_logger("structlog").debug("[TNC] Responding with high bandwidth mode") self.log.debug("[TNC] Responding with high bandwidth mode")
connection_frame = bytearray(14) connection_frame = bytearray(14)
connection_frame[:1] = frametype connection_frame[:1] = frametype
@ -1373,8 +1374,9 @@ class DATA:
self.enqueue_frame_for_tx(connection_frame) self.enqueue_frame_for_tx(connection_frame)
structlog.get_logger("structlog").info( self.log.info(
"[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") +
"]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]",
bandwith="wide", snr=static.SNR) bandwith="wide", snr=static.SNR)
# set start of transmission for our statistics # set start of transmission for our statistics
@ -1402,20 +1404,20 @@ class DATA:
self.mode_list = self.mode_list_low_bw self.mode_list = self.mode_list_low_bw
self.time_list = self.time_list_low_bw self.time_list = self.time_list_low_bw
self.speed_level = len(self.mode_list) - 1 self.speed_level = len(self.mode_list) - 1
structlog.get_logger("structlog").debug("[TNC] low bandwidth mode", modes=self.mode_list) self.log.debug("[TNC] low bandwidth mode", modes=self.mode_list)
else: else:
self.received_low_bandwith_mode = False self.received_low_bandwith_mode = False
self.mode_list = self.mode_list_high_bw self.mode_list = self.mode_list_high_bw
self.time_list = self.time_list_high_bw self.time_list = self.time_list_high_bw
self.speed_level = len(self.mode_list) - 1 self.speed_level = len(self.mode_list) - 1
structlog.get_logger("structlog").debug("[TNC] high bandwidth mode", modes=self.mode_list) self.log.debug("[TNC] high bandwidth mode", modes=self.mode_list)
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR,
static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
structlog.get_logger("structlog").info( self.log.info(
"[TNC] ARQ | DATA | TX | [" + str(self.mycallsign, "utf-8") + "]>>|<<[" + str(static.DXCALLSIGN, "[TNC] ARQ | DATA | TX | [" + str(self.mycallsign, "utf-8") +
"utf-8") + "]", "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]",
snr=static.SNR) snr=static.SNR)
# as soon as we set ARQ_STATE to DATA, transmission starts # as soon as we set ARQ_STATE to DATA, transmission starts
@ -1425,8 +1427,8 @@ class DATA:
static.TNC_STATE = "IDLE" static.TNC_STATE = "IDLE"
static.ARQ_STATE = False static.ARQ_STATE = False
static.INFO.append("PROTOCOL;VERSION_MISMATCH") static.INFO.append("PROTOCOL;VERSION_MISMATCH")
structlog.get_logger("structlog").warning("[TNC] protocol version mismatch:", received=protocol_version, self.log.warning("[TNC] protocol version mismatch:",
own=static.ARQ_PROTOCOL_VERSION) received=protocol_version, own=static.ARQ_PROTOCOL_VERSION)
self.arq_cleanup() self.arq_cleanup()
# ---------- PING # ---------- PING
@ -1443,8 +1445,9 @@ class DATA:
static.DXCALLSIGN_CRC = helpers.get_crc_24(static.DXCALLSIGN) static.DXCALLSIGN_CRC = helpers.get_crc_24(static.DXCALLSIGN)
static.INFO.append("PING;SENDING") static.INFO.append("PING;SENDING")
structlog.get_logger("structlog").info( self.log.info(
"[TNC] PING REQ [" + str(self.mycallsign, "utf-8") + "] >>> [" + str(static.DXCALLSIGN, "utf-8") + "]") "[TNC] PING REQ [" + str(self.mycallsign, "utf-8") +
"] >>> [" + str(static.DXCALLSIGN, "utf-8") + "]")
ping_frame = bytearray(14) ping_frame = bytearray(14)
ping_frame[:1] = bytes([210]) ping_frame[:1] = bytes([210])
@ -1452,7 +1455,7 @@ class DATA:
ping_frame[4:7] = static.MYCALLSIGN_CRC ping_frame[4:7] = static.MYCALLSIGN_CRC
ping_frame[7:13] = helpers.callsign_to_bytes(self.mycallsign) ping_frame[7:13] = helpers.callsign_to_bytes(self.mycallsign)
structlog.get_logger("structlog").info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) self.log.info("[TNC] ENABLE FSK", state=static.ENABLE_FSK)
if static.ENABLE_FSK: if static.ENABLE_FSK:
self.enqueue_frame_for_tx(ping_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) self.enqueue_frame_for_tx(ping_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0"))
else: else:
@ -1470,8 +1473,8 @@ class DATA:
""" """
static.DXCALLSIGN_CRC = bytes(data_in[4:7]) static.DXCALLSIGN_CRC = bytes(data_in[4:7])
static.DXCALLSIGN = helpers.bytes_to_callsign(bytes(data_in[7:13])) static.DXCALLSIGN = helpers.bytes_to_callsign(bytes(data_in[7:13]))
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING", static.SNR,
static.HAMLIB_FREQUENCY) static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
static.INFO.append("PING;RECEIVING") static.INFO.append("PING;RECEIVING")
@ -1479,12 +1482,12 @@ class DATA:
valid, mycallsign = helpers.check_callsign(self.mycallsign, data_in[1:4]) valid, mycallsign = helpers.check_callsign(self.mycallsign, data_in[1:4])
if not valid: if not valid:
# PING packet not for me. # PING packet not for me.
structlog.get_logger("structlog").debug("[TNC] received_ping: ping not for this station.") self.log.debug("[TNC] received_ping: ping not for this station.")
# print("ping not for me...")
return return
structlog.get_logger("structlog").info( self.log.info(
"[TNC] PING REQ [" + str(mycallsign, "utf-8") + "] <<< [" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] PING REQ [" + str(mycallsign, "utf-8") +
"] <<< [" + str(static.DXCALLSIGN, "utf-8") + "]",
snr=static.SNR) snr=static.SNR)
ping_frame = bytearray(14) ping_frame = bytearray(14)
@ -1493,7 +1496,7 @@ class DATA:
ping_frame[4:7] = static.MYCALLSIGN_CRC ping_frame[4:7] = static.MYCALLSIGN_CRC
ping_frame[7:13] = static.MYGRID ping_frame[7:13] = static.MYGRID
structlog.get_logger("structlog").info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) self.log.info("[TNC] ENABLE FSK", state=static.ENABLE_FSK)
if static.ENABLE_FSK: if static.ENABLE_FSK:
self.enqueue_frame_for_tx(ping_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) self.enqueue_frame_for_tx(ping_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0"))
else: else:
@ -1511,19 +1514,21 @@ class DATA:
static.DXCALLSIGN_CRC = bytes(data_in[4:7]) static.DXCALLSIGN_CRC = bytes(data_in[4:7])
static.DXGRID = bytes(data_in[7:13]).rstrip(b"\x00") static.DXGRID = bytes(data_in[7:13]).rstrip(b"\x00")
jsondata = {"type": "ping", "status": "ack", "uuid": str(uuid.uuid4()), "timestamp": int(time.time()), jsondata = {"type": "ping", "status": "ack", "uuid": str(uuid.uuid4()),
"mycallsign": str(self.mycallsign, "utf-8"), "dxcallsign": str(static.DXCALLSIGN, "utf-8"), "timestamp": int(time.time()), "mycallsign": str(self.mycallsign, "utf-8"),
"dxgrid": str(static.DXGRID, "utf-8"), "snr": str(static.SNR)} "dxcallsign": str(static.DXCALLSIGN, "utf-8"), "dxgrid": str(static.DXGRID, "utf-8"),
"snr": str(static.SNR)}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING-ACK", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING-ACK",
static.HAMLIB_FREQUENCY) static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
static.INFO.append("PING;RECEIVEDACK") static.INFO.append("PING;RECEIVEDACK")
structlog.get_logger("structlog").info( self.log.info(
"[TNC] PING ACK [" + str(self.mycallsign, "utf-8") + "] >|< [" + str(static.DXCALLSIGN, "utf-8") + "]", "[TNC] PING ACK [" + str(self.mycallsign, "utf-8") +
"] >|< [" + str(static.DXCALLSIGN, "utf-8") + "]",
snr=static.SNR) snr=static.SNR)
static.TNC_STATE = "IDLE" static.TNC_STATE = "IDLE"
@ -1531,7 +1536,7 @@ class DATA:
""" """
Force a stop of the running transmission Force a stop of the running transmission
""" """
structlog.get_logger("structlog").warning("[TNC] Stopping transmission!") self.log.warning("[TNC] Stopping transmission!")
stop_frame = bytearray(14) stop_frame = bytearray(14)
stop_frame[:1] = bytes([249]) stop_frame[:1] = bytes([249])
stop_frame[1:4] = static.DXCALLSIGN_CRC stop_frame[1:4] = static.DXCALLSIGN_CRC
@ -1549,7 +1554,7 @@ class DATA:
""" """
Received a transmission stop Received a transmission stop
""" """
structlog.get_logger("structlog").warning("[TNC] Stopping transmission!") self.log.warning("[TNC] Stopping transmission!")
static.TNC_STATE = "IDLE" static.TNC_STATE = "IDLE"
static.ARQ_STATE = False static.ARQ_STATE = False
static.INFO.append("TRANSMISSION;STOPPED") static.INFO.append("TRANSMISSION;STOPPED")
@ -1567,18 +1572,18 @@ class DATA:
""" """
try: try:
while 1: while True:
time.sleep(0.5) time.sleep(0.5)
while static.BEACON_STATE: while static.BEACON_STATE:
if not static.ARQ_SESSION and not self.arq_file_transfer and not static.BEACON_PAUSE: if not static.ARQ_SESSION and not self.arq_file_transfer and not static.BEACON_PAUSE:
static.INFO.append("BEACON;SENDING") static.INFO.append("BEACON;SENDING")
structlog.get_logger("structlog").info("[TNC] Sending beacon!", interval=self.beacon_interval) self.log.info("[TNC] Sending beacon!", interval=self.beacon_interval)
beacon_frame = bytearray(14) beacon_frame = bytearray(14)
beacon_frame[:1] = bytes([250]) beacon_frame[:1] = bytes([250])
beacon_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign) beacon_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign)
beacon_frame[9:13] = static.MYGRID[:4] beacon_frame[9:13] = static.MYGRID[:4]
structlog.get_logger("structlog").info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) self.log.info("[TNC] ENABLE FSK", state=static.ENABLE_FSK)
if static.ENABLE_FSK: if static.ENABLE_FSK:
self.enqueue_frame_for_tx(beacon_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) self.enqueue_frame_for_tx(beacon_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0"))
@ -1590,8 +1595,7 @@ class DATA:
time.sleep(0.01) time.sleep(0.01)
except Exception as err: except Exception as err:
structlog.get_logger("structlog").debug("[TNC] run_beacon: ", exception=err) self.log.debug("[TNC] run_beacon: ", exception=err)
# print(e)
def received_beacon(self, data_in: bytes): def received_beacon(self, data_in: bytes):
""" """
@ -1606,15 +1610,17 @@ class DATA:
dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7])) dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7]))
dxgrid = bytes(data_in[9:13]).rstrip(b"\x00") dxgrid = bytes(data_in[9:13]).rstrip(b"\x00")
jsondata = {"type": "beacon", "status": "received", "uuid": str(uuid.uuid4()), "timestamp": int(time.time()), jsondata = {"type": "beacon", "status": "received", "uuid": str(uuid.uuid4()),
"mycallsign": str(self.mycallsign, "utf-8"), "dxcallsign": str(dxcallsign, "utf-8"), "timestamp": int(time.time()), "mycallsign": str(self.mycallsign, "utf-8"),
"dxgrid": str(dxgrid, "utf-8"), "snr": str(static.SNR)} "dxcallsign": str(dxcallsign, "utf-8"), "dxgrid": str(dxgrid, "utf-8"),
"snr": str(static.SNR)}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
static.INFO.append("BEACON;RECEIVING") static.INFO.append("BEACON;RECEIVING")
structlog.get_logger("structlog").info( self.log.info(
"[TNC] BEACON RCVD [" + str(dxcallsign, "utf-8") + "][" + str(dxgrid, "utf-8") + "] ", snr=static.SNR) "[TNC] BEACON RCVD [" + str(dxcallsign, "utf-8") + "][" +
str(dxgrid, "utf-8") + "] ", snr=static.SNR)
helpers.add_to_heard_stations(dxcallsign, dxgrid, "BEACON", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(dxcallsign, dxgrid, "BEACON", static.SNR, static.FREQ_OFFSET,
static.HAMLIB_FREQUENCY) static.HAMLIB_FREQUENCY)
@ -1627,7 +1633,7 @@ class DATA:
Returns: Returns:
Nothing Nothing
""" """
structlog.get_logger("structlog").info("[TNC] CQ CQ CQ") self.log.info("[TNC] CQ CQ CQ")
static.INFO.append("CQ;SENDING") static.INFO.append("CQ;SENDING")
cq_frame = bytearray(14) cq_frame = bytearray(14)
@ -1635,8 +1641,8 @@ class DATA:
cq_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign) cq_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign)
cq_frame[7:11] = helpers.encode_grid(static.MYGRID.decode("utf-8")) cq_frame[7:11] = helpers.encode_grid(static.MYGRID.decode("utf-8"))
structlog.get_logger("structlog").info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) self.log.info("[TNC] ENABLE FSK", state=static.ENABLE_FSK)
structlog.get_logger("structlog").debug("[TNC] CQ Frame:", data=[cq_frame]) self.log.debug("[TNC] CQ Frame:", data=[cq_frame])
if static.ENABLE_FSK: if static.ENABLE_FSK:
self.enqueue_frame_for_tx(cq_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) self.enqueue_frame_for_tx(cq_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0"))
@ -1654,12 +1660,13 @@ class DATA:
""" """
# here we add the received station to the heard stations buffer # here we add the received station to the heard stations buffer
dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7])) dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7]))
structlog.get_logger("structlog").debug("[TNC] received_cq:", dxcallsign=dxcallsign) self.log.debug("[TNC] received_cq:", dxcallsign=dxcallsign)
# print(dxcallsign)
dxgrid = bytes(helpers.decode_grid(data_in[7:11]), "utf-8") dxgrid = bytes(helpers.decode_grid(data_in[7:11]), "utf-8")
static.INFO.append("CQ;RECEIVING") static.INFO.append("CQ;RECEIVING")
structlog.get_logger("structlog").info( self.log.info(
"[TNC] CQ RCVD [" + str(dxcallsign, "utf-8") + "][" + str(dxgrid, "utf-8") + "] ", snr=static.SNR) "[TNC] CQ RCVD [" + str(dxcallsign, "utf-8") + "][" +
str(dxgrid, "utf-8") + "] ", snr=static.SNR)
helpers.add_to_heard_stations(dxcallsign, dxgrid, "CQ CQ CQ", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(dxcallsign, dxgrid, "CQ CQ CQ", static.SNR, static.FREQ_OFFSET,
static.HAMLIB_FREQUENCY) static.HAMLIB_FREQUENCY)
@ -1681,14 +1688,14 @@ class DATA:
# in 0.5s increments. # in 0.5s increments.
helpers.wait(randrange(0, 20, 5) / 10.0) helpers.wait(randrange(0, 20, 5) / 10.0)
static.INFO.append("QRV;SENDING") static.INFO.append("QRV;SENDING")
structlog.get_logger("structlog").info("[TNC] Sending QRV!") self.log.info("[TNC] Sending QRV!")
qrv_frame = bytearray(14) qrv_frame = bytearray(14)
qrv_frame[:1] = bytes([201]) qrv_frame[:1] = bytes([201])
qrv_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign) qrv_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign)
qrv_frame[7:11] = helpers.encode_grid(static.MYGRID.decode("utf-8")) qrv_frame[7:11] = helpers.encode_grid(static.MYGRID.decode("utf-8"))
structlog.get_logger("structlog").info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) self.log.info("[TNC] ENABLE FSK", state=static.ENABLE_FSK)
if static.ENABLE_FSK: if static.ENABLE_FSK:
self.enqueue_frame_for_tx(qrv_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) self.enqueue_frame_for_tx(qrv_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0"))
@ -1708,15 +1715,17 @@ class DATA:
dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7])) dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7]))
dxgrid = bytes(helpers.decode_grid(data_in[7:11]), "utf-8") dxgrid = bytes(helpers.decode_grid(data_in[7:11]), "utf-8")
jsondata = {"type": "qrv", "status": "received", "uuid": str(uuid.uuid4()), "timestamp": int(time.time()), jsondata = {"type": "qrv", "status": "received", "uuid": str(uuid.uuid4()),
"mycallsign": str(self.mycallsign, "utf-8"), "dxcallsign": str(dxcallsign, "utf-8"), "timestamp": int(time.time()), "mycallsign": str(self.mycallsign, "utf-8"),
"dxgrid": str(dxgrid, "utf-8"), "snr": str(static.SNR)} "dxcallsign": str(dxcallsign, "utf-8"), "dxgrid": str(dxgrid, "utf-8"),
"snr": str(static.SNR)}
json_data_out = json.dumps(jsondata) json_data_out = json.dumps(jsondata)
sock.SOCKET_QUEUE.put(json_data_out) sock.SOCKET_QUEUE.put(json_data_out)
static.INFO.append("QRV;RECEIVING") static.INFO.append("QRV;RECEIVING")
structlog.get_logger("structlog").info( self.log.info(
"[TNC] QRV RCVD [" + str(dxcallsign, "utf-8") + "][" + str(dxgrid, "utf-8") + "] ", snr=static.SNR) "[TNC] QRV RCVD [" + str(dxcallsign, "utf-8") + "][" +
str(dxgrid, "utf-8") + "] ", snr=static.SNR)
helpers.add_to_heard_stations(dxcallsign, dxgrid, "QRV", static.SNR, static.FREQ_OFFSET, helpers.add_to_heard_stations(dxcallsign, dxgrid, "QRV", static.SNR, static.FREQ_OFFSET,
static.HAMLIB_FREQUENCY) static.HAMLIB_FREQUENCY)
@ -1749,7 +1758,7 @@ class DATA:
static.ARQ_BITS_PER_SECOND = 0 static.ARQ_BITS_PER_SECOND = 0
static.ARQ_BYTES_PER_MINUTE = 0 static.ARQ_BYTES_PER_MINUTE = 0
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error(f"[TNC] calculate_transfer_rate_rx: Exception: {err}") self.log.error(f"[TNC] calculate_transfer_rate_rx: Exception: {err}")
static.ARQ_TRANSMISSION_PERCENT = 0.0 static.ARQ_TRANSMISSION_PERCENT = 0.0
static.ARQ_BITS_PER_SECOND = 0 static.ARQ_BITS_PER_SECOND = 0
static.ARQ_BYTES_PER_MINUTE = 0 static.ARQ_BYTES_PER_MINUTE = 0
@ -1796,7 +1805,7 @@ class DATA:
static.ARQ_BYTES_PER_MINUTE = 0 static.ARQ_BYTES_PER_MINUTE = 0
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error(f"[TNC] calculate_transfer_rate_tx: Exception: {err}") self.log.error(f"[TNC] calculate_transfer_rate_tx: Exception: {err}")
static.ARQ_TRANSMISSION_PERCENT = 0.0 static.ARQ_TRANSMISSION_PERCENT = 0.0
static.ARQ_BITS_PER_SECOND = 0 static.ARQ_BITS_PER_SECOND = 0
static.ARQ_BYTES_PER_MINUTE = 0 static.ARQ_BYTES_PER_MINUTE = 0
@ -1810,7 +1819,7 @@ class DATA:
""" """
Cleanup funktion which clears all ARQ states Cleanup funktion which clears all ARQ states
""" """
structlog.get_logger("structlog").debug("[TNC] arq_cleanup") self.log.debug("[TNC] arq_cleanup")
self.received_mycall_crc = b"" self.received_mycall_crc = b""
@ -1881,18 +1890,18 @@ class DATA:
if mode_name == "datac1": if mode_name == "datac1":
modem.RECEIVE_DATAC1 = True modem.RECEIVE_DATAC1 = True
structlog.get_logger("structlog").debug("[TNC] Changing listening data mode", mode="datac1") self.log.debug("[TNC] Changing listening data mode", mode="datac1")
elif mode_name == "datac3": elif mode_name == "datac3":
modem.RECEIVE_DATAC3 = True modem.RECEIVE_DATAC3 = True
structlog.get_logger("structlog").debug("[TNC] Changing listening data mode", mode="datac3") self.log.debug("[TNC] Changing listening data mode", mode="datac3")
elif mode_name == "fsk_ldpc_1": elif mode_name == "fsk_ldpc_1":
modem.RECEIVE_FSK_LDPC_1 = True modem.RECEIVE_FSK_LDPC_1 = True
structlog.get_logger("structlog").debug("[TNC] Changing listening data mode", mode="fsk_ldpc_1") self.log.debug("[TNC] Changing listening data mode", mode="fsk_ldpc_1")
elif mode_name == "allmodes": elif mode_name == "allmodes":
modem.RECEIVE_DATAC1 = True modem.RECEIVE_DATAC1 = True
modem.RECEIVE_DATAC3 = True modem.RECEIVE_DATAC3 = True
modem.RECEIVE_FSK_LDPC_1 = True modem.RECEIVE_FSK_LDPC_1 = True
structlog.get_logger("structlog").debug("[TNC] Changing listening data mode", mode="datac1/datac3/fsk_ldpc") self.log.debug("[TNC] Changing listening data mode", mode="datac1/datac3/fsk_ldpc")
# ------------------------- WATCHDOG FUNCTIONS FOR TIMER # ------------------------- WATCHDOG FUNCTIONS FOR TIMER
def watchdog(self): def watchdog(self):
@ -1926,9 +1935,8 @@ class DATA:
# print((self.data_channel_last_received + self.time_list[self.speed_level])-time.time()) # print((self.data_channel_last_received + self.time_list[self.speed_level])-time.time())
pass pass
else: else:
structlog.get_logger("structlog").warning("[TNC] Frame timeout", attempt=self.n_retries_per_burst, self.log.warning("[TNC] Frame timeout", attempt=self.n_retries_per_burst,
max_attempts=self.rx_n_max_retries_per_burst, max_attempts=self.rx_n_max_retries_per_burst, speed_level=self.speed_level)
speed_level=self.speed_level)
self.frame_received_counter = 0 self.frame_received_counter = 0
self.burst_nack_counter += 1 self.burst_nack_counter += 1
if self.burst_nack_counter >= 2: if self.burst_nack_counter >= 2:
@ -1967,8 +1975,9 @@ class DATA:
# pass # pass
else: else:
self.data_channel_last_received = 0 self.data_channel_last_received = 0
structlog.get_logger("structlog").info( self.log.info(
"[TNC] DATA [" + str(self.mycallsign, "utf-8") + "]<<T>>[" + str(static.DXCALLSIGN, "utf-8") + "]") "[TNC] DATA [" + str(self.mycallsign, "utf-8") +
"]<<T>>[" + str(static.DXCALLSIGN, "utf-8") + "]")
static.INFO.append("ARQ;RECEIVING;FAILED") static.INFO.append("ARQ;RECEIVING;FAILED")
if not TESTMODE: if not TESTMODE:
self.arq_cleanup() self.arq_cleanup()
@ -1982,9 +1991,9 @@ class DATA:
if self.arq_session_last_received + self.arq_session_timeout > time.time(): if self.arq_session_last_received + self.arq_session_timeout > time.time():
time.sleep(0.01) time.sleep(0.01)
else: else:
structlog.get_logger("structlog").info( self.log.info(
"[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]<<T>>[" + str(static.DXCALLSIGN, "[TNC] SESSION [" + str(self.mycallsign, "utf-8") +
"utf-8") + "]") "]<<T>>[" + str(static.DXCALLSIGN, "utf-8") + "]")
static.INFO.append("ARQ;SESSION;TIMEOUT") static.INFO.append("ARQ;SESSION;TIMEOUT")
self.close_session() self.close_session()
@ -1992,7 +2001,7 @@ class DATA:
""" """
heartbeat thread which auto resumes the heartbeat signal within a arq session heartbeat thread which auto resumes the heartbeat signal within a arq session
""" """
while 1: while True:
time.sleep(0.01) time.sleep(0.01)
if static.ARQ_SESSION and self.IS_ARQ_SESSION_MASTER and static.ARQ_SESSION_STATE == "connected" and not self.arq_file_transfer: if static.ARQ_SESSION and self.IS_ARQ_SESSION_MASTER and static.ARQ_SESSION_STATE == "connected" and not self.arq_file_transfer:
time.sleep(1) time.sleep(1)

2
tnc/main.py
View file

@ -150,5 +150,5 @@ if __name__ == "__main__":
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error("[TNC] Starting TCP/IP socket failed", port=static.PORT, e=err) structlog.get_logger("structlog").error("[TNC] Starting TCP/IP socket failed", port=static.PORT, e=err)
sys.exit(1) sys.exit(1)
while 1: while True:
time.sleep(1) time.sleep(1)

47
tnc/modem.py
View file

@ -44,6 +44,7 @@ RECEIVE_FSK_LDPC_1 = False
class RF: class RF:
""" """ """ """
log = structlog.get_logger("RF")
def __init__(self): def __init__(self):
@ -142,19 +143,19 @@ class RF:
device=(static.AUDIO_INPUT_DEVICE, static.AUDIO_OUTPUT_DEVICE), device=(static.AUDIO_INPUT_DEVICE, static.AUDIO_OUTPUT_DEVICE),
samplerate=self.AUDIO_SAMPLE_RATE_RX, blocksize=4800) samplerate=self.AUDIO_SAMPLE_RATE_RX, blocksize=4800)
atexit.register(self.stream.stop) atexit.register(self.stream.stop)
structlog.get_logger("structlog").info("[MDM] init: opened audio devices") self.log.info("[MDM] init: opened audio devices")
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error("[MDM] init: can't open audio device. Exit", e=err) self.log.error("[MDM] init: can't open audio device. Exit", e=err)
sys.exit(1) sys.exit(1)
try: try:
structlog.get_logger("structlog").debug("[MDM] init: starting pyaudio callback") self.log.debug("[MDM] init: starting pyaudio callback")
# self.audio_stream.start_stream() # self.audio_stream.start_stream()
self.stream.start() self.stream.start()
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error("[MDM] init: starting pyaudio callback failed", e=err) self.log.error("[MDM] init: starting pyaudio callback failed", e=err)
else: else:
# create a stream object for simulating audio stream # create a stream object for simulating audio stream
@ -169,7 +170,7 @@ class RF:
os.mkfifo(RXCHANNEL) os.mkfifo(RXCHANNEL)
os.mkfifo(TXCHANNEL) os.mkfifo(TXCHANNEL)
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error(f"[MDM] init:mkfifo: Exception: {err}") self.log.error(f"[MDM] init:mkfifo: Exception: {err}")
mkfifo_write_callback_thread = threading.Thread(target=self.mkfifo_write_callback, mkfifo_write_callback_thread = threading.Thread(target=self.mkfifo_write_callback,
name="MKFIFO WRITE CALLBACK THREAD", daemon=True) name="MKFIFO WRITE CALLBACK THREAD", daemon=True)
@ -233,7 +234,7 @@ class RF:
# -------------------------------------------------------------------------------------------------------- # --------------------------------------------------------------------------------------------------------
def mkfifo_read_callback(self): def mkfifo_read_callback(self):
while 1: while True:
time.sleep(0.01) time.sleep(0.01)
# -----read # -----read
data_in48k = bytes() data_in48k = bytes()
@ -257,7 +258,7 @@ class RF:
self.datac3_buffer.push(x) self.datac3_buffer.push(x)
def mkfifo_write_callback(self): def mkfifo_write_callback(self):
while 1: while True:
time.sleep(0.01) time.sleep(0.01)
# -----write # -----write
@ -283,8 +284,6 @@ class RF:
time: time:
status: status:
Returns:
Nothing
""" """
x = np.frombuffer(data_in48k, dtype=np.int16) x = np.frombuffer(data_in48k, dtype=np.int16)
x = self.resampler.resample48_to_8(x) x = self.resampler.resample48_to_8(x)
@ -333,7 +332,7 @@ class RF:
try: try:
outdata[:] = data_out48k[:frames] outdata[:] = data_out48k[:frames]
except IndexError as e: except IndexError as e:
structlog.get_logger("structlog").debug(f"[MDM] callback: IndexError: {e}") self.log.debug(f"[MDM] callback: IndexError: {e}")
# return (data_out48k, audio.pyaudio.paContinue) # return (data_out48k, audio.pyaudio.paContinue)
@ -347,10 +346,8 @@ class RF:
repeat_delay: repeat_delay:
frames: frames:
Returns:
""" """
structlog.get_logger("structlog").debug("[MDM] transmit", mode=mode) self.log.debug("[MDM] transmit", mode=mode)
static.TRANSMITTING = True static.TRANSMITTING = True
# Toggle ptt early to save some time and send ptt state via socket # Toggle ptt early to save some time and send ptt state via socket
static.PTT_STATE = self.hamlib.set_ptt(True) static.PTT_STATE = self.hamlib.set_ptt(True)
@ -384,7 +381,7 @@ class RF:
mod_out_silence = ctypes.create_string_buffer(data_delay * 2) mod_out_silence = ctypes.create_string_buffer(data_delay * 2)
txbuffer = bytes(mod_out_silence) txbuffer = bytes(mod_out_silence)
structlog.get_logger("structlog").debug("[MDM] TRANSMIT", mode=self.MODE, payload=payload_bytes_per_frame) self.log.debug("[MDM] TRANSMIT", mode=self.MODE, payload=payload_bytes_per_frame)
for _ in range(repeats): for _ in range(repeats):
# codec2 fsk preamble may be broken - at least it sounds like that so we are disabling it for testing # codec2 fsk preamble may be broken - at least it sounds like that so we are disabling it for testing
@ -440,7 +437,7 @@ class RF:
delta = chunk_length - len(c) delta = chunk_length - len(c)
delta_zeros = np.zeros(delta, dtype=np.int16) delta_zeros = np.zeros(delta, dtype=np.int16)
c = np.append(c, delta_zeros) c = np.append(c, delta_zeros)
# structlog.get_logger("structlog").debug("[MDM] mod out shorter than audio buffer", delta=delta) # self.log.debug("[MDM] mod out shorter than audio buffer", delta=delta)
self.modoutqueue.append(c) self.modoutqueue.append(c)
@ -556,7 +553,7 @@ class RF:
while True: while True:
data = self.modem_transmit_queue.get() data = self.modem_transmit_queue.get()
structlog.get_logger("structlog").debug("[MDM] worker_transmit", mode=data[0]) self.log.debug("[MDM] worker_transmit", mode=data[0])
self.transmit(mode=data[0], repeats=data[1], repeat_delay=data[2], frames=data[3]) self.transmit(mode=data[0], repeats=data[1], repeat_delay=data[2], frames=data[3])
# self.modem_transmit_queue.task_done() # self.modem_transmit_queue.task_done()
@ -577,8 +574,6 @@ class RF:
Args: Args:
freedv: freedv:
Returns:
""" """
modemStats = codec2.MODEMSTATS() modemStats = codec2.MODEMSTATS()
self.c_lib.freedv_get_modem_extended_stats.restype = None self.c_lib.freedv_get_modem_extended_stats.restype = None
@ -593,8 +588,6 @@ class RF:
Args: Args:
freedv: freedv:
Returns:
""" """
if not static.ENABLE_SCATTER: if not static.ENABLE_SCATTER:
return return
@ -629,8 +622,6 @@ class RF:
Args: Args:
freedv: freedv:
Returns:
""" """
try: try:
modem_stats_snr = ctypes.c_float() modem_stats_snr = ctypes.c_float()
@ -641,12 +632,12 @@ class RF:
modem_stats_sync = modem_stats_sync.value modem_stats_sync = modem_stats_sync.value
snr = round(modem_stats_snr, 1) snr = round(modem_stats_snr, 1)
structlog.get_logger("structlog").info("[MDM] calculate_snr: ", snr=snr) self.log.info("[MDM] calculate_snr: ", snr=snr)
# static.SNR = np.clip(snr, 0, 255) # limit to max value of 255 # static.SNR = np.clip(snr, 0, 255) # limit to max value of 255
static.SNR = np.clip(snr, -128, 128) # limit to max value of -128/128 as a possible fix of #188 static.SNR = np.clip(snr, -128, 128) # limit to max value of -128/128 as a possible fix of #188
return static.SNR return static.SNR
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error(f"[MDM] calculate_snr: Exception: {err}") self.log.error(f"[MDM] calculate_snr: Exception: {err}")
static.SNR = 0 static.SNR = 0
return static.SNR return static.SNR
@ -712,8 +703,8 @@ class RF:
static.FFT = dfftlist[:320] # 320 --> bandwidth 3000 static.FFT = dfftlist[:320] # 320 --> bandwidth 3000
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error(f"[MDM] calculate_fft: Exception: {err}") self.log.error(f"[MDM] calculate_fft: Exception: {err}")
structlog.get_logger("structlog").debug("[MDM] Setting fft=0") self.log.debug("[MDM] Setting fft=0")
# else 0 # else 0
static.FFT = [0] static.FFT = [0]
@ -723,8 +714,6 @@ class RF:
Args: Args:
n_frames_per_burst: n_frames_per_burst:
Returns:
""" """
codec2.api.freedv_set_frames_per_burst(self.datac1_freedv, n_frames_per_burst) codec2.api.freedv_set_frames_per_burst(self.datac1_freedv, n_frames_per_burst)
codec2.api.freedv_set_frames_per_burst(self.datac3_freedv, n_frames_per_burst) codec2.api.freedv_set_frames_per_burst(self.datac3_freedv, n_frames_per_burst)
@ -753,8 +742,6 @@ def get_bytes_per_frame(mode):
Args: Args:
mode: mode:
Returns:
""" """
freedv = open_codec2_instance(mode) freedv = open_codec2_instance(mode)

2
tnc/rigctld.py
View file

@ -8,8 +8,6 @@ import logging
import socket import socket
import time import time
import log_handler
import static
import structlog import structlog
# set global hamlib version # set global hamlib version

2
tnc/rigdummy.py
View file

@ -1,7 +1,5 @@
#!/usr/bin/env python3 #!/usr/bin/env python3
import structlog
hamlib_version = 0 hamlib_version = 0

89
tnc/sock.py
View file

@ -38,6 +38,8 @@ DAEMON_QUEUE = queue.Queue()
CONNECTED_CLIENTS = set() CONNECTED_CLIENTS = set()
CLOSE_SIGNAL = False CLOSE_SIGNAL = False
log = structlog.get_logger("sock")
class ThreadedTCPServer(socketserver.ThreadingMixIn, socketserver.TCPServer): class ThreadedTCPServer(socketserver.ThreadingMixIn, socketserver.TCPServer):
""" """
@ -82,8 +84,7 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler):
try: try:
client.send(sock_data) client.send(sock_data)
except Exception as err: except Exception as err:
# print("connection lost...") log.info("[SCK] Connection lost", e=err)
structlog.get_logger("structlog").info("[SCK] Connection lost", e=err)
self.connection_alive = False self.connection_alive = False
# we want to transmit scatter data only once to reduce network traffic # we want to transmit scatter data only once to reduce network traffic
@ -131,8 +132,8 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler):
# finally delete our rx buffer to be ready for new commands # finally delete our rx buffer to be ready for new commands
data = bytes() data = bytes()
except Exception as err: except Exception as err:
structlog.get_logger("structlog").info("[SCK] Connection closed", ip=self.client_address[0], log.info("[SCK] Connection closed", ip=self.client_address[0],
port=self.client_address[1], e=err) port=self.client_address[1], e=err)
self.connection_alive = False self.connection_alive = False
def handle(self): def handle(self):
@ -141,12 +142,14 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler):
""" """
CONNECTED_CLIENTS.add(self.request) CONNECTED_CLIENTS.add(self.request)
structlog.get_logger("structlog").debug("[SCK] Client connected", ip=self.client_address[0], log.debug("[SCK] Client connected", ip=self.client_address[0],
port=self.client_address[1]) port=self.client_address[1])
self.connection_alive = True self.connection_alive = True
self.sendThread = threading.Thread(target=self.send_to_client, args=[], daemon=True).start() self.send_thread = threading.Thread(target=self.send_to_client, args=[], daemon=True)
self.receiveThread = threading.Thread(target=self.receive_from_client, args=[], daemon=True).start() self.send_thread.start()
self.receive_thread = threading.Thread(target=self.receive_from_client, args=[], daemon=True)
self.receive_thread.start()
# keep connection alive until we close it # keep connection alive until we close it
while self.connection_alive and not CLOSE_SIGNAL: while self.connection_alive and not CLOSE_SIGNAL:
@ -154,13 +157,13 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler):
def finish(self): def finish(self):
""" """ """ """
structlog.get_logger("structlog").warning("[SCK] Closing client socket", ip=self.client_address[0], log.warning("[SCK] Closing client socket", ip=self.client_address[0],
port=self.client_address[1]) port=self.client_address[1])
try: try:
CONNECTED_CLIENTS.remove(self.request) CONNECTED_CLIENTS.remove(self.request)
except Exception as err: except Exception as err:
structlog.get_logger("structlog").warning("[SCK] client connection already removed from client list", log.warning("[SCK] client connection already removed from client list",
client=self.request, e=err) client=self.request, e=err)
def process_tnc_commands(data): def process_tnc_commands(data):
@ -177,7 +180,7 @@ def process_tnc_commands(data):
try: try:
# convert data to json object # convert data to json object
received_json = json.loads(data) received_json = json.loads(data)
structlog.get_logger("structlog").debug("[SCK] CMD", command=received_json) log.debug("[SCK] CMD", command=received_json)
# SET TX AUDIO LEVEL ----------------------------------------------------- # SET TX AUDIO LEVEL -----------------------------------------------------
if received_json["type"] == "set" and received_json["command"] == "tx_audio_level": if received_json["type"] == "set" and received_json["command"] == "tx_audio_level":
try: try:
@ -186,7 +189,7 @@ def process_tnc_commands(data):
except Exception as err: except Exception as err:
command_response("tx_audio_level", False) command_response("tx_audio_level", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# TRANSMIT SINE WAVE ----------------------------------------------------- # TRANSMIT SINE WAVE -----------------------------------------------------
if received_json["type"] == "set" and received_json["command"] == "send_test_frame": if received_json["type"] == "set" and received_json["command"] == "send_test_frame":
@ -195,7 +198,7 @@ def process_tnc_commands(data):
command_response("send_test_frame", True) command_response("send_test_frame", True)
except Exception as err: except Exception as err:
command_response("send_test_frame", False) command_response("send_test_frame", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# CQ CQ CQ ----------------------------------------------------- # CQ CQ CQ -----------------------------------------------------
if received_json["command"] == "cqcqcq": if received_json["command"] == "cqcqcq":
@ -205,7 +208,7 @@ def process_tnc_commands(data):
except Exception as err: except Exception as err:
command_response("cqcqcq", False) command_response("cqcqcq", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# START_BEACON ----------------------------------------------------- # START_BEACON -----------------------------------------------------
if received_json["command"] == "start_beacon": if received_json["command"] == "start_beacon":
@ -216,18 +219,18 @@ def process_tnc_commands(data):
command_response("start_beacon", True) command_response("start_beacon", True)
except Exception as err: except Exception as err:
command_response("start_beacon", False) command_response("start_beacon", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# STOP_BEACON ----------------------------------------------------- # STOP_BEACON -----------------------------------------------------
if received_json["command"] == "stop_beacon": if received_json["command"] == "stop_beacon":
try: try:
structlog.get_logger("structlog").warning("[TNC] Stopping beacon!") log.warning("[TNC] Stopping beacon!")
static.BEACON_STATE = False static.BEACON_STATE = False
data_handler.DATA_QUEUE_TRANSMIT.put(["BEACON", None, False]) data_handler.DATA_QUEUE_TRANSMIT.put(["BEACON", None, False])
command_response("stop_beacon", True) command_response("stop_beacon", True)
except Exception as err: except Exception as err:
command_response("stop_beacon", False) command_response("stop_beacon", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# PING ---------------------------------------------------------- # PING ----------------------------------------------------------
if received_json["type"] == "ping" and received_json["command"] == "ping": if received_json["type"] == "ping" and received_json["command"] == "ping":
@ -245,7 +248,7 @@ def process_tnc_commands(data):
command_response("ping", True) command_response("ping", True)
except Exception as err: except Exception as err:
command_response("ping", False) command_response("ping", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# CONNECT ---------------------------------------------------------- # CONNECT ----------------------------------------------------------
if received_json["type"] == "arq" and received_json["command"] == "connect": if received_json["type"] == "arq" and received_json["command"] == "connect":
@ -267,7 +270,7 @@ def process_tnc_commands(data):
command_response("connect", True) command_response("connect", True)
except Exception as err: except Exception as err:
command_response("connect", False) command_response("connect", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# DISCONNECT ---------------------------------------------------------- # DISCONNECT ----------------------------------------------------------
if received_json["type"] == "arq" and received_json["command"] == "disconnect": if received_json["type"] == "arq" and received_json["command"] == "disconnect":
@ -277,7 +280,7 @@ def process_tnc_commands(data):
command_response("disconnect", True) command_response("disconnect", True)
except Exception as err: except Exception as err:
command_response("disconnect", False) command_response("disconnect", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# TRANSMIT RAW DATA ------------------------------------------- # TRANSMIT RAW DATA -------------------------------------------
if received_json["type"] == "arq" and received_json["command"] == "send_raw": if received_json["type"] == "arq" and received_json["command"] == "send_raw":
@ -321,20 +324,20 @@ def process_tnc_commands(data):
raise TypeError raise TypeError
except Exception as err: except Exception as err:
command_response("send_raw", False) command_response("send_raw", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# STOP TRANSMISSION ---------------------------------------------------------- # STOP TRANSMISSION ----------------------------------------------------------
if received_json["type"] == "arq" and received_json["command"] == "stop_transmission": if received_json["type"] == "arq" and received_json["command"] == "stop_transmission":
try: try:
if static.TNC_STATE == "BUSY" or static.ARQ_STATE: if static.TNC_STATE == "BUSY" or static.ARQ_STATE:
data_handler.DATA_QUEUE_TRANSMIT.put(["STOP"]) data_handler.DATA_QUEUE_TRANSMIT.put(["STOP"])
structlog.get_logger("structlog").warning("[TNC] Stopping transmission!") log.warning("[TNC] Stopping transmission!")
static.TNC_STATE = "IDLE" static.TNC_STATE = "IDLE"
static.ARQ_STATE = False static.ARQ_STATE = False
command_response("stop_transmission", True) command_response("stop_transmission", True)
except Exception as err: except Exception as err:
command_response("stop_transmission", False) command_response("stop_transmission", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
if received_json["type"] == "get" and received_json["command"] == "rx_buffer": if received_json["type"] == "get" and received_json["command"] == "rx_buffer":
try: try:
@ -358,7 +361,7 @@ def process_tnc_commands(data):
except Exception as err: except Exception as err:
command_response("rx_buffer", False) command_response("rx_buffer", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
if received_json["type"] == "set" and received_json["command"] == "del_rx_buffer": if received_json["type"] == "set" and received_json["command"] == "del_rx_buffer":
try: try:
@ -366,11 +369,11 @@ def process_tnc_commands(data):
command_response("del_rx_buffer", True) command_response("del_rx_buffer", True)
except Exception as err: except Exception as err:
command_response("del_rx_buffer", False) command_response("del_rx_buffer", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
# exception, if JSON can't be decoded # exception, if JSON can't be decoded
except Exception as err: except Exception as err:
structlog.get_logger("structlog").error("[TNC] JSON decoding error", e=err) log.error("[TNC] JSON decoding error", e=err)
def send_tnc_state(): def send_tnc_state():
@ -424,6 +427,8 @@ def send_tnc_state():
return json.dumps(output) return json.dumps(output)
# This has apparently been taken out of a class, but is never called because
# the `self.request.sendall` call is a syntax error as `self` is undefined.
def process_daemon_commands(data): def process_daemon_commands(data):
""" """
process daemon commands process daemon commands
@ -436,25 +441,25 @@ def process_daemon_commands(data):
""" """
# convert data to json object # convert data to json object
received_json = json.loads(data) received_json = json.loads(data)
structlog.get_logger("structlog").debug("[SCK] CMD", command=received_json) log.debug("[SCK] CMD", command=received_json)
if received_json["type"] == "set" and received_json["command"] == "mycallsign": if received_json["type"] == "set" and received_json["command"] == "mycallsign":
try: try:
callsign = received_json["parameter"] callsign = received_json["parameter"]
if bytes(callsign, "utf-8") == b"": if bytes(callsign, "utf-8") == b"":
self.request.sendall(b"INVALID CALLSIGN") self.request.sendall(b"INVALID CALLSIGN")
structlog.get_logger("structlog").warning("[DMN] SET MYCALL FAILED", call=static.MYCALLSIGN, log.warning("[DMN] SET MYCALL FAILED", call=static.MYCALLSIGN,
crc=static.MYCALLSIGN_CRC) crc=static.MYCALLSIGN_CRC)
else: else:
static.MYCALLSIGN = bytes(callsign, "utf-8") static.MYCALLSIGN = bytes(callsign, "utf-8")
static.MYCALLSIGN_CRC = helpers.get_crc_24(static.MYCALLSIGN) static.MYCALLSIGN_CRC = helpers.get_crc_24(static.MYCALLSIGN)
command_response("mycallsign", True) command_response("mycallsign", True)
structlog.get_logger("structlog").info("[DMN] SET MYCALL", call=static.MYCALLSIGN, log.info("[DMN] SET MYCALL", call=static.MYCALLSIGN,
crc=static.MYCALLSIGN_CRC) crc=static.MYCALLSIGN_CRC)
except Exception as err: except Exception as err:
command_response("mycallsign", False) command_response("mycallsign", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
if received_json["type"] == "set" and received_json["command"] == "mygrid": if received_json["type"] == "set" and received_json["command"] == "mygrid":
try: try:
@ -464,11 +469,11 @@ def process_daemon_commands(data):
self.request.sendall(b"INVALID GRID") self.request.sendall(b"INVALID GRID")
else: else:
static.MYGRID = bytes(mygrid, "utf-8") static.MYGRID = bytes(mygrid, "utf-8")
structlog.get_logger("structlog").info("[SCK] SET MYGRID", grid=static.MYGRID) log.info("[SCK] SET MYGRID", grid=static.MYGRID)
command_response("mygrid", True) command_response("mygrid", True)
except Exception as err: except Exception as err:
command_response("mygrid", False) command_response("mygrid", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
if received_json["type"] == "set" and received_json["command"] == "start_tnc" and not static.TNCSTARTED: if received_json["type"] == "set" and received_json["command"] == "start_tnc" and not static.TNCSTARTED:
try: try:
@ -498,7 +503,7 @@ def process_daemon_commands(data):
# print some debugging parameters # print some debugging parameters
for item in received_json["parameter"][0]: for item in received_json["parameter"][0]:
structlog.get_logger("structlog").debug(f"[DMN] TNC Startup Config : {item}", value=received_json["parameter"][0][item]) log.debug(f"[DMN] TNC Startup Config : {item}", value=received_json["parameter"][0][item])
DAEMON_QUEUE.put(["STARTTNC", DAEMON_QUEUE.put(["STARTTNC",
mycall, mycall,
@ -529,7 +534,7 @@ def process_daemon_commands(data):
except Exception as err: except Exception as err:
command_response("start_tnc", False) command_response("start_tnc", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
if received_json["type"] == "get" and received_json["command"] == "test_hamlib": if received_json["type"] == "get" and received_json["command"] == "test_hamlib":
try: try:
@ -561,7 +566,7 @@ def process_daemon_commands(data):
command_response("test_hamlib", True) command_response("test_hamlib", True)
except Exception as err: except Exception as err:
command_response("test_hamlib", False) command_response("test_hamlib", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
if received_json["type"] == "set" and received_json["command"] == "stop_tnc": if received_json["type"] == "set" and received_json["command"] == "stop_tnc":
try: try:
@ -569,12 +574,12 @@ def process_daemon_commands(data):
# unregister process from atexit to avoid process zombies # unregister process from atexit to avoid process zombies
atexit.unregister(static.TNCPROCESS.kill) atexit.unregister(static.TNCPROCESS.kill)
structlog.get_logger("structlog").warning("[DMN] Stopping TNC") log.warning("[DMN] Stopping TNC")
static.TNCSTARTED = False static.TNCSTARTED = False
command_response("stop_tnc", True) command_response("stop_tnc", True)
except Exception as err: except Exception as err:
command_response("stop_tnc", False) command_response("stop_tnc", False)
structlog.get_logger("structlog").warning("[SCK] command execution error", e=err, command=received_json) log.warning("[SCK] command execution error", e=err, command=received_json)
def send_daemon_state(): def send_daemon_state():
@ -605,7 +610,7 @@ def send_daemon_state():
return json.dumps(output) return json.dumps(output)
except Exception as err: except Exception as err:
structlog.get_logger("structlog").warning("[SCK] error", e=err) log.warning("[SCK] error", e=err)
return None return None

147
tnc/static.py
View file

@ -8,115 +8,118 @@ Here we are saving application wide variables and stats, which have to be access
Not nice, suggestions are appreciated :-) Not nice, suggestions are appreciated :-)
""" """
import subprocess
VERSION = "0.4.0-alpha" VERSION = "0.4.0-alpha"
# DAEMON # DAEMON
DAEMONPORT = 3001 DAEMONPORT: int = 3001
TNCSTARTED = False TNCSTARTED: bool = False
TNCPROCESS = 0 TNCPROCESS: subprocess.Popen
# Operator Defaults # Operator Defaults
MYCALLSIGN = b"AA0AA" MYCALLSIGN: bytes = b"AA0AA"
MYCALLSIGN_CRC = b"A" MYCALLSIGN_CRC: bytes = b"A"
DXCALLSIGN = b"AA0AA" DXCALLSIGN: bytes = b"AA0AA"
DXCALLSIGN_CRC = b"A" DXCALLSIGN_CRC: bytes = b"A"
MYGRID = b"" MYGRID: bytes = b""
DXGRID = b"" DXGRID: bytes = b""
SSID_LIST = [] # ssid list we are responding to SSID_LIST: list = [] # ssid list we are responding to
LOW_BANDWITH_MODE = False LOW_BANDWITH_MODE: bool = False
# --------------------------------- # ---------------------------------
# Server Defaults # Server Defaults
HOST = "0.0.0.0" HOST: str = "0.0.0.0"
PORT = 3000 PORT: int = 3000
SOCKET_TIMEOUT = 1 # seconds SOCKET_TIMEOUT: int = 1 # seconds
# --------------------------------- # ---------------------------------
SERIAL_DEVICES = [] SERIAL_DEVICES: list = []
# --------------------------------- # ---------------------------------
PTT_STATE = False PTT_STATE: bool = False
TRANSMITTING = False TRANSMITTING: bool = False
HAMLIB_VERSION = "0" HAMLIB_VERSION: str = "0"
HAMLIB_PTT_TYPE = "RTS" HAMLIB_PTT_TYPE: str = "RTS"
HAMLIB_DEVICE_NAME = "RIG_MODEL_DUMMY_NOVFO" HAMLIB_DEVICE_NAME: str = "RIG_MODEL_DUMMY_NOVFO"
HAMLIB_DEVICE_PORT = "/dev/ttyUSB0" HAMLIB_DEVICE_PORT: str = "/dev/ttyUSB0"
HAMLIB_SERIAL_SPEED = "9600" HAMLIB_SERIAL_SPEED: str = "9600"
HAMLIB_PTT_PORT = "/dev/ttyUSB0" HAMLIB_PTT_PORT: str = "/dev/ttyUSB0"
HAMLIB_STOP_BITS = "1" HAMLIB_STOP_BITS: str = "1"
HAMLIB_DATA_BITS = "8" HAMLIB_DATA_BITS: str = "8"
HAMLIB_HANDSHAKE = "None" HAMLIB_HANDSHAKE: str = "None"
HAMLIB_RADIOCONTROL = "direct" HAMLIB_RADIOCONTROL: str = "direct"
HAMLIB_RIGCTLD_IP = "127.0.0.1" HAMLIB_RIGCTLD_IP: str = "127.0.0.1"
HAMLIB_RIGCTLD_PORT = "4532" HAMLIB_RIGCTLD_PORT: str = "4532"
HAMLIB_FREQUENCY = 0 HAMLIB_FREQUENCY: int = 0
HAMLIB_MODE = "" HAMLIB_MODE: str = ""
HAMLIB_BANDWITH = 0 HAMLIB_BANDWITH: int = 0
# ------------------------- # -------------------------
# FreeDV Defaults # FreeDV Defaults
SNR = 0 SNR: float = 0
FREQ_OFFSET = 0 FREQ_OFFSET: float = 0
SCATTER = [] SCATTER: list = []
ENABLE_SCATTER = False ENABLE_SCATTER: bool = False
ENABLE_FSK = False ENABLE_FSK: bool = False
RESPOND_TO_CQ = False RESPOND_TO_CQ: bool = False
# --------------------------------- # ---------------------------------
# Audio Defaults # Audio Defaults
TX_AUDIO_LEVEL = 50 TX_AUDIO_LEVEL: int = 50
AUDIO_INPUT_DEVICES = [] AUDIO_INPUT_DEVICES: list = []
AUDIO_OUTPUT_DEVICES = [] AUDIO_OUTPUT_DEVICES: list = []
AUDIO_INPUT_DEVICE = -2 AUDIO_INPUT_DEVICE: int = -2
AUDIO_OUTPUT_DEVICE = -2 AUDIO_OUTPUT_DEVICE: int = -2
BUFFER_OVERFLOW_COUNTER = [0, 0, 0, 0, 0] BUFFER_OVERFLOW_COUNTER: list = [0, 0, 0, 0, 0]
AUDIO_RMS = 0 AUDIO_RMS: int = 0
FFT = [0] FFT: list = [0]
ENABLE_FFT = False ENABLE_FFT: bool = False
CHANNEL_BUSY = None CHANNEL_BUSY: bool = False
# ARQ PROTOCOL VERSION # ARQ PROTOCOL VERSION
ARQ_PROTOCOL_VERSION = 1 ARQ_PROTOCOL_VERSION: int = 1
# ARQ statistics # ARQ statistics
ARQ_BYTES_PER_MINUTE_BURST = 0 ARQ_BYTES_PER_MINUTE_BURST: int = 0
ARQ_BYTES_PER_MINUTE = 0 ARQ_BYTES_PER_MINUTE: int = 0
ARQ_BITS_PER_SECOND_BURST = 0 ARQ_BITS_PER_SECOND_BURST: int = 0
ARQ_BITS_PER_SECOND = 0 ARQ_BITS_PER_SECOND: int = 0
ARQ_COMPRESSION_FACTOR = 0 ARQ_COMPRESSION_FACTOR: int = 0
ARQ_TRANSMISSION_PERCENT = 0 ARQ_TRANSMISSION_PERCENT: int = 0
ARQ_SPEED_LEVEL = 0 ARQ_SPEED_LEVEL: int = 0
TOTAL_BYTES = 0 TOTAL_BYTES: int = 0
# CHANNEL_STATE = 'RECEIVING_SIGNALLING' # CHANNEL_STATE = 'RECEIVING_SIGNALLING'
TNC_STATE = "IDLE" TNC_STATE: str = "IDLE"
ARQ_STATE = False ARQ_STATE: bool = False
ARQ_SESSION = False ARQ_SESSION: bool = False
ARQ_SESSION_STATE = "disconnected" # disconnected, connecting, connected, disconnecting, failed # disconnected, connecting, connected, disconnecting, failed
ARQ_SESSION_STATE: str = "disconnected"
# BEACON STATE # BEACON STATE
BEACON_STATE = False BEACON_STATE: bool = False
BEACON_PAUSE = False BEACON_PAUSE: bool = False
# ------- RX BUFFER # ------- RX BUFFER
RX_BUFFER = [] RX_BUFFER: list = []
RX_MSG_BUFFER = [] RX_MSG_BUFFER: list = []
RX_BURST_BUFFER = [] RX_BURST_BUFFER: list = []
RX_FRAME_BUFFER = b"" RX_FRAME_BUFFER: bytes = b""
# RX_BUFFER_SIZE = 0 # RX_BUFFER_SIZE: int = 0
# ------- HEARD STATIONS BUFFER # ------- HEARD STATIONS BUFFER
HEARD_STATIONS = [] HEARD_STATIONS: list = []
# ------- INFO MESSAGE BUFFER # ------- INFO MESSAGE BUFFER
INFO = [] INFO: list = []
# ------- CODEC2 SETTINGS # ------- CODEC2 SETTINGS
TUNING_RANGE_FMIN = -50.0 TUNING_RANGE_FMIN: float = -50.0
TUNING_RANGE_FMAX = 50.0 TUNING_RANGE_FMAX: float = 50.0

12
tools/list_audio_devices.py
View file

@ -6,12 +6,14 @@ import pyaudio
def list_audio_devices(): def list_audio_devices():
p = pyaudio.PyAudio() p = pyaudio.PyAudio()
devices = []
print("--------------------------------------------------------------------") print("--------------------------------------------------------------------")
for x in range(0, p.get_device_count()): devices = [
devices.append(f"{x} - {p.get_device_info_by_index(x)['name']}") f"{x} - {p.get_device_info_by_index(x)['name']}"
for x in range(p.get_device_count())
]
for line in devices: for line in devices:
print(line) print(line)
list_audio_devices() list_audio_devices()

14
tools/socketclient.py
View file

@ -6,10 +6,9 @@ Created on Fri Dec 11 21:53:35 2020
@author: parallels @author: parallels
""" """
import socket
import sys
import argparse import argparse
import random import random
import socket
def create_string(length): def create_string(length):
@ -24,14 +23,14 @@ def create_string(length):
random_integer = random_integer - 32 if flip_bit == 1 else random_integer random_integer = random_integer - 32 if flip_bit == 1 else random_integer
# Keep appending random characters using chr(x) # Keep appending random characters using chr(x)
random_string += (chr(random_integer)) random_string += (chr(random_integer))
print("STR:" + str(random_string)) print(f"STR: {random_string!s}")
return random_string return random_string
# --------------------------------------------GET PARAMETER INPUTS # --------------------------------------------GET PARAMETER INPUTS
parser = argparse.ArgumentParser(description='Simons TEST TNC') parser = argparse.ArgumentParser(description='Simons TEST TNC')
parser.add_argument('--port', dest="socket_port", default=9000, help="Set the port, the socket is listening on.", type=int) parser.add_argument('--port', dest="socket_port", default=9000, help="Set the port, the socket is listening on.", type=int)
# parser.add_argument('--data', dest="data", default=False, help="data", type=str) # parser.add_argument('--data', dest="data", default=False, help="data", type=str)
parser.add_argument('--random', dest="datalength", default=False, help="data", type=int) parser.add_argument('--random', dest="datalength", default=False, help="data", type=int)
@ -52,7 +51,4 @@ with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock:
# Receive data from the server and shut down # Receive data from the server and shut down
received = str(sock.recv(1024), "utf-8") received = str(sock.recv(1024), "utf-8")
print("Sent: {}".format(data)) print(f"Sent: {data}")