diff --git a/tnc/daemon.py b/tnc/daemon.py index 5b751e75..63551b81 100755 --- a/tnc/daemon.py +++ b/tnc/daemon.py @@ -55,6 +55,8 @@ class DAEMON: Daemon class """ + log = structlog.get_logger("DAEMON") + def __init__(self): # load crc engine self.crc_algorithm = crcengine.new("crc16-ccitt-false") # load crc8 library @@ -73,12 +75,12 @@ class DAEMON: """ Update audio devices and set to static """ - while 1: + while True: try: if not static.TNCSTARTED: static.AUDIO_INPUT_DEVICES, static.AUDIO_OUTPUT_DEVICES = audio.get_audio_devices() 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) time.sleep(1) @@ -86,7 +88,7 @@ class DAEMON: """ Update serial devices and set to static """ - while 1: + while True: try: serial_devices = [] ports = serial.tools.list_ports.comports() @@ -101,14 +103,14 @@ class DAEMON: static.SERIAL_DEVICES = serial_devices time.sleep(1) 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) def worker(self): """ Worker to handle the received commands """ - while 1: + while True: try: data = self.daemon_queue.get() @@ -137,7 +139,7 @@ class DAEMON: # data[23] respond_to_cq 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 options = [] @@ -231,13 +233,13 @@ class DAEMON: command.append("freedata-tnc.exe") 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: - structlog.get_logger("structlog").error("[DMN] worker: Exception:", e=err1) + self.log.error("[DMN] worker: Exception:", e=err1) command = [] if sys.platform in ["linux", "darwin"]: command.append("python3") @@ -246,18 +248,18 @@ class DAEMON: command.append("main.py") command += options - p = subprocess.Popen(command) - atexit.register(p.kill) + proc = subprocess.Popen(command) + 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 """ # WE HAVE THIS PART in SOCKET if data[0] == "STOPTNC": static.TNCPROCESS.kill() - structlog.get_logger("structlog").warning("[DMN] Stopping TNC") + self.log.warning("[DMN] Stopping TNC") #os.kill(static.TNCPROCESS, signal.SIGKILL) static.TNCSTARTED = False """ @@ -306,13 +308,13 @@ class DAEMON: pttstate = hamlib.get_ptt() 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"} 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"} 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"} hamlib.set_ptt(False) @@ -322,10 +324,11 @@ class DAEMON: sock.SOCKET_QUEUE.put(jsondata) 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__": + mainlog = structlog.get_logger(__file__) # we need to run this on Windows for multiprocessing support multiprocessing.freeze_support() @@ -350,10 +353,10 @@ if __name__ == "__main__": os.makedirs(logging_path) log_handler.setup_logging(logging_path) except Exception as err: - structlog.get_logger("structlog").error("[DMN] logger init error", exception=err) + mainlog.error("[DMN] logger init error", exception=err) 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 socketserver.TCPServer.allow_reuse_address = True cmdserver = sock.ThreadedTCPServer((static.HOST, static.DAEMONPORT), sock.ThreadedTCPRequestHandler) @@ -362,10 +365,10 @@ if __name__ == "__main__": server_thread.start() 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) 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: time.sleep(1) diff --git a/tnc/data_handler.py b/tnc/data_handler.py index eb6b8591..d4e37bea 100644 --- a/tnc/data_handler.py +++ b/tnc/data_handler.py @@ -34,6 +34,7 @@ DATA_QUEUE_RECEIVED = queue.Queue() class DATA: """ Terminal Node Controller for FreeDATA """ + log = structlog.get_logger("DATA") def __init__(self): self.mycallsign = static.MYCALLSIGN # initial call sign. Will be overwritten later @@ -104,7 +105,8 @@ class DATA: daemon=True) 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() # START THE THREAD FOR THE TIMEOUT WATCHDOG @@ -163,8 +165,7 @@ class DATA: # [1] DX CALLSIGN self.send_test_frame() else: - structlog.get_logger("structlog").error("[TNC] worker_transmit: received invalid command:", data=data) - # print(f"Invalid command: {data}") + self.log.error("[TNC] worker_transmit: received invalid command:", data=data) def worker_receive(self): """ """ @@ -186,8 +187,7 @@ class DATA: Returns: """ - structlog.get_logger("structlog").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}") + self.log.debug("[TNC] process_data:", n_retries_per_burst=self.n_retries_per_burst) # forward data only if broadcast or we are the receiver # bytes_out[1:4] == callsign check for signalling frames, @@ -207,111 +207,111 @@ class DATA: # 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 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 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 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) # BURST ACK elif frametype == 60: - structlog.get_logger("structlog").debug("[TNC] ACK RECEIVED....") + self.log.debug("[TNC] ACK RECEIVED....") self.burst_ack_received(bytes_out[:-2]) # FRAME ACK elif frametype == 61: - structlog.get_logger("structlog").debug("[TNC] FRAME ACK RECEIVED....") + self.log.debug("[TNC] FRAME ACK RECEIVED....") self.frame_ack_received() # FRAME RPT 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]) # FRAME NACK 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]) # BURST NACK 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]) # CQ FRAME elif frametype == 200: - structlog.get_logger("structlog").debug("[TNC] CQ RECEIVED....") + self.log.debug("[TNC] CQ RECEIVED....") self.received_cq(bytes_out[:-2]) # QRV FRAME elif frametype == 201: - structlog.get_logger("structlog").debug("[TNC] QRV RECEIVED....") + self.log.debug("[TNC] QRV RECEIVED....") self.received_qrv(bytes_out[:-2]) # PING FRAME elif frametype == 210: - structlog.get_logger("structlog").debug("[TNC] PING RECEIVED....") + self.log.debug("[TNC] PING RECEIVED....") self.received_ping(bytes_out[:-2]) # PING ACK 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]) # SESSION OPENER 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]) # SESSION HEARTBEAT 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]) # SESSION CLOSE 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]) # ARQ FILE TRANSFER RECEIVED! 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]) # ARQ CHANNEL IS OPENED 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]) # ARQ MANUAL MODE TRANSMISSION 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]) # ARQ STOP TRANSMISSION 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() # this is outdated and we may remove it elif frametype == 250: - structlog.get_logger("structlog").debug("[TNC] BEACON RECEIVED") + self.log.debug("[TNC] BEACON RECEIVED") self.received_beacon(bytes_out[:-2]) # TESTFRAMES 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 else: - structlog.get_logger("structlog").warning("[TNC] ARQ - other frame type", frametype=frametype) + self.log.warning("[TNC] ARQ - other frame type", frametype=frametype) else: # 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): """ @@ -326,7 +326,7 @@ class DATA: :param repeat_delay: Delay time before sending repeat frame, defaults to 0 :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): _mode = codec2.freedv_get_mode_value_by_name(c2_mode.lower()) else: @@ -379,7 +379,7 @@ class DATA: rpt_frame[4:7] = static.MYCALLSIGN_CRC 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 self.enqueue_frame_for_tx(rpt_frame) @@ -464,10 +464,10 @@ class DATA: # 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] - 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, - static.HAMLIB_FREQUENCY) + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", + 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" # 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 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): - 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 = [] else: @@ -503,12 +503,12 @@ class DATA: static.RX_FRAME_BUFFER = static.RX_FRAME_BUFFER[:search_position + get_position] static.RX_FRAME_BUFFER += temp_burst_buffer - structlog.get_logger("structlog").warning("[TNC] ARQ | RX | replacing existing buffer data", - area=search_area, pos=get_position) + self.log.warning("[TNC] ARQ | RX | replacing existing buffer data", + area=search_area, pos=get_position) # if we dont find data n this range, we really have new data and going to replace it else: 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 if (not self.rx_frame_bof_received and @@ -527,7 +527,7 @@ class DATA: self.set_listening_modes(self.mode_list[self.speed_level]) # 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) # 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. # With this way of doing this, we always MUST receive the last frame of a burst otherwise the entire # burst is lost - structlog.get_logger("structlog").debug("[TNC] all frames in burst received:", frame=RX_N_FRAME_OF_BURST, - frames=RX_N_FRAMES_PER_BURST) + self.log.debug("[TNC] all frames in burst received:", frame=RX_N_FRAME_OF_BURST, + frames=RX_N_FRAMES_PER_BURST) self.send_retransmit_request_frame(freedv) self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER)) # Should never reach this point else: - structlog.get_logger("structlog").error("[TNC] data_handler: Should not reach this point...", - frame=RX_N_FRAME_OF_BURST, frames=RX_N_FRAMES_PER_BURST) + self.log.error("[TNC] data_handler: Should not reach this point...", + 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. # 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)) 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, - eof_position=eof_position) + self.log.debug("[TNC] arq_data_received:", 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_eof_received = True @@ -589,7 +589,7 @@ class DATA: # Check if data_frame_crc is equal with received crc 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 data_frame_decompressed = zlib.decompress(data_frame) @@ -611,31 +611,31 @@ class DATA: base64_data = base64.b64encode(data_frame).decode("utf-8") static.RX_BUFFER.append([uniqueid, timestamp, static.DXCALLSIGN, static.DXGRID, base64_data]) 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} 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) static.INFO.append("ARQ;RECEIVING;SUCCESS") - structlog.get_logger("structlog").info("[TNC] ARQ | RX | SENDING DATA FRAME ACK", snr=snr, - crc=data_frame_crc.hex()) + self.log.info("[TNC] ARQ | RX | SENDING DATA FRAME ACK", snr=snr, + crc=data_frame_crc.hex()) self.send_data_ack_frame(snr) # update our statistics AFTER the frame ACK self.calculate_transfer_rate_rx(self.rx_start_of_transmission, len(static.RX_FRAME_BUFFER)) - structlog.get_logger("structlog").info("[TNC] | RX | DATACHANNEL [" + - str(self.mycallsign, "utf-8") + "]<< >>[" + str( - static.DXCALLSIGN, "utf-8") + "]", snr=snr) + self.log.info("[TNC] | RX | DATACHANNEL [" + str(self.mycallsign, "utf-8") + + "]<< >>[" + str(static.DXCALLSIGN, "utf-8") + "]", snr=snr) else: static.INFO.append("ARQ;RECEIVING;FAILED") - structlog.get_logger("structlog").warning("[TNC] ARQ | RX | DATA FRAME NOT SUCESSFULLY RECEIVED!", - e="wrong crc", expected=data_frame_crc, - received=data_frame_crc_received, - overflows=static.BUFFER_OVERFLOW_COUNTER) + self.log.warning("[TNC] ARQ | RX | DATA FRAME NOT SUCESSFULLY RECEIVED!", + e="wrong crc", expected=data_frame_crc, + received=data_frame_crc_received, + 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) # update session timeout @@ -684,7 +684,7 @@ class DATA: json_data_out = json.dumps(jsondata) 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 data_frame_compressed = zlib.compress(data_out) @@ -700,7 +700,7 @@ class DATA: # Append a crc and the begin and end of file indicators 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 + frame_total_size + compression_factor + data_out + self.data_frame_eof @@ -718,7 +718,7 @@ class DATA: # force usage of selected mode if mode != 255: data_mode = mode - structlog.get_logger("structlog").debug("[TNC] FIXED MODE:", mode=data_mode) + self.log.debug("[TNC] FIXED MODE:", mode=data_mode) else: # we are doing a modulo check of transmission retries of the actual burst # every 2nd retry which fails, decreases speedlevel by 1. @@ -745,8 +745,8 @@ class DATA: static.ARQ_SPEED_LEVEL = self.speed_level data_mode = self.mode_list[self.speed_level] - structlog.get_logger("structlog").debug("[TNC] Speed-level:", level=self.speed_level, - retry=self.tx_n_retry_of_burst, mode=data_mode) + self.log.debug("[TNC] Speed-level:", level=self.speed_level, + retry=self.tx_n_retry_of_burst, mode=data_mode) # payload information payload_per_frame = modem.get_bytes_per_frame(data_mode) - 2 @@ -784,9 +784,9 @@ class DATA: # append frame to tempbuffer for transmission tempbuffer.append(frame) - structlog.get_logger("structlog").debug("[TNC] tempbuffer:", tempbuffer=tempbuffer) - structlog.get_logger("structlog").info("[TNC] ARQ | TX | FRAMES", mode=data_mode, - fpb=TX_N_FRAMES_PER_BURST, retry=self.tx_n_retry_of_burst) + self.log.debug("[TNC] tempbuffer:", tempbuffer=tempbuffer) + self.log.info("[TNC] ARQ | TX | FRAMES", mode=data_mode, + 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 # 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)) # NEXT ATTEMPT - structlog.get_logger("structlog").debug("[TNC] ATTEMPT:", retry=self.tx_n_retry_of_burst, - maxretries=TX_N_MAX_RETRIES_PER_BURST, - overflows=static.BUFFER_OVERFLOW_COUNTER) + self.log.debug("[TNC] ATTEMPT:", retry=self.tx_n_retry_of_burst, + maxretries=TX_N_MAX_RETRIES_PER_BURST, overflows=static.BUFFER_OVERFLOW_COUNTER) # update buffer position bufferposition = bufferposition_end @@ -844,7 +843,7 @@ class DATA: self.calculate_transfer_rate_tx(tx_start_of_transmission, bufferposition_end, len(data_out)) 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) sock.SOCKET_QUEUE.put(json_data_out) @@ -853,24 +852,24 @@ class DATA: if self.data_frame_ack_received: static.INFO.append("ARQ;TRANSMITTING;SUCCESS") 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) sock.SOCKET_QUEUE.put(json_data_out) - structlog.get_logger("structlog").info("[TNC] ARQ | TX | DATA TRANSMITTED!", - BytesPerMinute=static.ARQ_BYTES_PER_MINUTE, - BitsPerSecond=static.ARQ_BITS_PER_SECOND, - overflows=static.BUFFER_OVERFLOW_COUNTER) + self.log.info("[TNC] ARQ | TX | DATA TRANSMITTED!", + BytesPerMinute=static.ARQ_BYTES_PER_MINUTE, BitsPerSecond=static.ARQ_BITS_PER_SECOND, + overflows=static.BUFFER_OVERFLOW_COUNTER) else: static.INFO.append("ARQ;TRANSMITTING;FAILED") 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) sock.SOCKET_QUEUE.put(json_data_out) - structlog.get_logger("structlog").info("[TNC] ARQ | TX | TRANSMISSION FAILED OR TIME OUT!", - overflows=static.BUFFER_OVERFLOW_COUNTER) + self.log.info("[TNC] ARQ | TX | TRANSMISSION FAILED OR TIME OUT!", + overflows=static.BUFFER_OVERFLOW_COUNTER) self.stop_transmission() # 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.speed_level = int.from_bytes(bytes(data_in[8:9]), "big") static.ARQ_SPEED_LEVEL = self.speed_level - structlog.get_logger("structlog").debug("[TNC] burst_ack_received:", speed_level=self.speed_level) - # print(self.speed_level) + self.log.debug("[TNC] burst_ack_received:", speed_level=self.speed_level) + # reset burst nack counter self.burst_nack_counter = 0 # reset n retries per burst counter @@ -919,8 +918,6 @@ class DATA: Args: data_in:bytes: - Returns: - """ # increase speed level if we received a burst ack # self.speed_level += 1 @@ -937,8 +934,7 @@ class DATA: self.speed_level = int.from_bytes(bytes(data_in[8:9]), "big") static.ARQ_SPEED_LEVEL = self.speed_level self.burst_nack_counter += 1 - structlog.get_logger("structlog").debug("[TNC] burst_nack_received:", speed_level=self.speed_level) - # print(self.speed_level) + self.log.debug("[TNC] burst_nack_received:", speed_level=self.speed_level) def frame_ack_received(self): """ """ @@ -946,9 +942,11 @@ class DATA: if static.ARQ_STATE: helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) - self.data_frame_ack_received = True # 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.arq_session_last_received = int(time.time()) # we need to update our timeout timestamp + # Force data loops of TNC to stop and continue with next frame + self.data_frame_ack_received = True + # 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 """ @@ -959,8 +957,8 @@ class DATA: Returns: """ - helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, - static.HAMLIB_FREQUENCY) + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", + static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.INFO.append("ARQ;TRANSMITTING;FAILED") jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid, "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 self.datachannel_timeout = False - structlog.get_logger("structlog").info( - "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", + self.log.info( + "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", state=static.ARQ_SESSION_STATE) self.open_session(callsign) @@ -1049,10 +1048,10 @@ class DATA: while not static.ARQ_SESSION: time.sleep(0.01) for attempt in range(1, self.session_connect_max_retries + 1): - structlog.get_logger("structlog").info( - "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]>>?<<[" + str(static.DXCALLSIGN, - "utf-8") + "]", a=attempt, - state=static.ARQ_SESSION_STATE) + self.log.info( + "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + + "]>>?<<[" + str(static.DXCALLSIGN, "utf-8") + "]", + a=attempt, state=static.ARQ_SESSION_STATE) self.enqueue_frame_for_tx(connection_frame) @@ -1089,10 +1088,11 @@ class DATA: static.DXCALLSIGN_CRC = bytes(data_in[4:7]) 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, - static.HAMLIB_FREQUENCY) - structlog.get_logger("structlog").info( - "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", + static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) + self.log.info( + "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", state=static.ARQ_SESSION_STATE) static.ARQ_SESSION = True static.TNC_STATE = "BUSY" @@ -1102,10 +1102,11 @@ class DATA: def close_session(self): """ Close the ARQ session """ static.ARQ_SESSION_STATE = "disconnecting" - helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, - static.HAMLIB_FREQUENCY) - structlog.get_logger("structlog").info( - "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]", + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", + static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) + self.log.info( + "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]", state=static.ARQ_SESSION_STATE) static.INFO.append("ARQ;SESSION;CLOSE") self.IS_ARQ_SESSION_MASTER = False @@ -1131,8 +1132,9 @@ class DATA: static.ARQ_SESSION_STATE = "disconnected" helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) - structlog.get_logger("structlog").info( - "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]", + self.log.info( + "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]", state=static.ARQ_SESSION_STATE) static.INFO.append("ARQ;SESSION;CLOSE") @@ -1165,7 +1167,7 @@ class DATA: # Accept session data if the DXCALLSIGN_CRC matches the station in static. _valid_crc, _ = helpers.check_callsign(static.DXCALLSIGN, bytes(data_in[4:7])) 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, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) @@ -1238,14 +1240,14 @@ class DATA: if static.LOW_BANDWITH_MODE and mode == 255: frametype = bytes([227]) - structlog.get_logger("structlog").debug("[TNC] Requesting low bandwidth mode") + self.log.debug("[TNC] Requesting low bandwidth mode") else: 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: - 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]) connection_frame = bytearray(14) @@ -1259,9 +1261,9 @@ class DATA: time.sleep(0.01) for attempt in range(1, self.data_channel_max_retries + 1): static.INFO.append("DATACHANNEL;OPENING") - structlog.get_logger("structlog").info( - "[TNC] ARQ | DATA | TX | [" + str(mycallsign, "utf-8") + "]>> <<[" + str(static.DXCALLSIGN, - "utf-8") + "]", + self.log.info( + "[TNC] ARQ | DATA | TX | [" + str(mycallsign, "utf-8") + + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", attempt=f"{str(attempt)}/{str(self.data_channel_max_retries)}") self.enqueue_frame_for_tx(connection_frame) @@ -1279,8 +1281,8 @@ class DATA: if attempt == self.data_channel_max_retries: static.INFO.append("DATACHANNEL;FAILED") - structlog.get_logger("structlog").debug("[TNC] arq_open_data_channel:", - transmission_uuid=self.transmission_uuid) + self.log.debug("[TNC] arq_open_data_channel:", + transmission_uuid=self.transmission_uuid) # print(self.transmission_uuid) jsondata = {"arq": "transmission", "status": "failed", "uuid": self.transmission_uuid, "percent": static.ARQ_TRANSMISSION_PERCENT, @@ -1288,9 +1290,10 @@ class DATA: json_data_out = json.dumps(jsondata) sock.SOCKET_QUEUE.put(json_data_out) - structlog.get_logger("structlog").warning( - "[TNC] ARQ | TX | DATA [" + str(mycallsign, "utf-8") + "]>>X<<[" + str(static.DXCALLSIGN, - "utf-8") + "]") + self.log.warning( + "[TNC] ARQ | TX | DATA [" + str(mycallsign, "utf-8") + + "]>>X<<[" + str(static.DXCALLSIGN, "utf-8") + "]" + ) self.datachannel_timeout = True if not TESTMODE: self.arq_cleanup() @@ -1307,8 +1310,6 @@ class DATA: Args: data_in:bytes: - Returns: - """ self.arq_file_transfer = True self.is_IRS = True @@ -1330,14 +1331,13 @@ class DATA: self.speed_level = len(self.mode_list) - 1 if 230 <= frametype <= 240: - structlog.get_logger("structlog").debug("[TNC] arq_received_data_channel_opener: manual mode request") - # print("manual mode request") + self.log.debug("[TNC] arq_received_data_channel_opener: manual mode request") # updated modes we are listening to 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, - static.HAMLIB_FREQUENCY) + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "DATA-CHANNEL", + static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) # check if callsign ssid override valid, mycallsign = helpers.check_callsign(self.mycallsign, data_in[1:4]) @@ -1347,8 +1347,9 @@ class DATA: self.arq_cleanup() return - structlog.get_logger("structlog").info( - "[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", + self.log.info( + "[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") + + "]>> <<[" + str(static.DXCALLSIGN, "utf-8") + "]", bandwith="wide") static.ARQ_STATE = True @@ -1360,10 +1361,10 @@ class DATA: # check if we are in low bandwith mode if static.LOW_BANDWITH_MODE or self.received_low_bandwith_mode: frametype = bytes([228]) - structlog.get_logger("structlog").debug("[TNC] Responding with low bandwidth mode") + self.log.debug("[TNC] Responding with low bandwidth mode") else: 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[:1] = frametype @@ -1373,8 +1374,9 @@ class DATA: self.enqueue_frame_for_tx(connection_frame) - structlog.get_logger("structlog").info( - "[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", + self.log.info( + "[TNC] ARQ | DATA | RX | [" + str(mycallsign, "utf-8") + + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", bandwith="wide", snr=static.SNR) # set start of transmission for our statistics @@ -1402,20 +1404,20 @@ class DATA: self.mode_list = self.mode_list_low_bw self.time_list = self.time_list_low_bw 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: self.received_low_bandwith_mode = False self.mode_list = self.mode_list_high_bw self.time_list = self.time_list_high_bw 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, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) - structlog.get_logger("structlog").info( - "[TNC] ARQ | DATA | TX | [" + str(self.mycallsign, "utf-8") + "]>>|<<[" + str(static.DXCALLSIGN, - "utf-8") + "]", + self.log.info( + "[TNC] ARQ | DATA | TX | [" + str(self.mycallsign, "utf-8") + + "]>>|<<[" + str(static.DXCALLSIGN, "utf-8") + "]", snr=static.SNR) # as soon as we set ARQ_STATE to DATA, transmission starts @@ -1425,8 +1427,8 @@ class DATA: static.TNC_STATE = "IDLE" static.ARQ_STATE = False static.INFO.append("PROTOCOL;VERSION_MISMATCH") - structlog.get_logger("structlog").warning("[TNC] protocol version mismatch:", received=protocol_version, - own=static.ARQ_PROTOCOL_VERSION) + self.log.warning("[TNC] protocol version mismatch:", + received=protocol_version, own=static.ARQ_PROTOCOL_VERSION) self.arq_cleanup() # ---------- PING @@ -1443,8 +1445,9 @@ class DATA: static.DXCALLSIGN_CRC = helpers.get_crc_24(static.DXCALLSIGN) static.INFO.append("PING;SENDING") - structlog.get_logger("structlog").info( - "[TNC] PING REQ [" + str(self.mycallsign, "utf-8") + "] >>> [" + str(static.DXCALLSIGN, "utf-8") + "]") + self.log.info( + "[TNC] PING REQ [" + str(self.mycallsign, "utf-8") + + "] >>> [" + str(static.DXCALLSIGN, "utf-8") + "]") ping_frame = bytearray(14) ping_frame[:1] = bytes([210]) @@ -1452,7 +1455,7 @@ class DATA: ping_frame[4:7] = static.MYCALLSIGN_CRC 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: self.enqueue_frame_for_tx(ping_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) else: @@ -1470,8 +1473,8 @@ class DATA: """ static.DXCALLSIGN_CRC = bytes(data_in[4:7]) 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, - static.HAMLIB_FREQUENCY) + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING", static.SNR, + static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.INFO.append("PING;RECEIVING") @@ -1479,12 +1482,12 @@ class DATA: valid, mycallsign = helpers.check_callsign(self.mycallsign, data_in[1:4]) if not valid: # PING packet not for me. - structlog.get_logger("structlog").debug("[TNC] received_ping: ping not for this station.") - # print("ping not for me...") + self.log.debug("[TNC] received_ping: ping not for this station.") return - structlog.get_logger("structlog").info( - "[TNC] PING REQ [" + str(mycallsign, "utf-8") + "] <<< [" + str(static.DXCALLSIGN, "utf-8") + "]", + self.log.info( + "[TNC] PING REQ [" + str(mycallsign, "utf-8") + + "] <<< [" + str(static.DXCALLSIGN, "utf-8") + "]", snr=static.SNR) ping_frame = bytearray(14) @@ -1493,7 +1496,7 @@ class DATA: ping_frame[4:7] = static.MYCALLSIGN_CRC 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: self.enqueue_frame_for_tx(ping_frame, c2_mode=codec2.freedv_get_mode_value_by_name("FSK_LDPC_0")) else: @@ -1511,19 +1514,21 @@ class DATA: static.DXCALLSIGN_CRC = bytes(data_in[4:7]) static.DXGRID = bytes(data_in[7:13]).rstrip(b"\x00") - jsondata = {"type": "ping", "status": "ack", "uuid": str(uuid.uuid4()), "timestamp": int(time.time()), - "mycallsign": str(self.mycallsign, "utf-8"), "dxcallsign": str(static.DXCALLSIGN, "utf-8"), - "dxgrid": str(static.DXGRID, "utf-8"), "snr": str(static.SNR)} + jsondata = {"type": "ping", "status": "ack", "uuid": str(uuid.uuid4()), + "timestamp": int(time.time()), "mycallsign": str(self.mycallsign, "utf-8"), + "dxcallsign": str(static.DXCALLSIGN, "utf-8"), "dxgrid": str(static.DXGRID, "utf-8"), + "snr": str(static.SNR)} json_data_out = json.dumps(jsondata) sock.SOCKET_QUEUE.put(json_data_out) - helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING-ACK", static.SNR, static.FREQ_OFFSET, - static.HAMLIB_FREQUENCY) + helpers.add_to_heard_stations(static.DXCALLSIGN, static.DXGRID, "PING-ACK", + static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY) static.INFO.append("PING;RECEIVEDACK") - structlog.get_logger("structlog").info( - "[TNC] PING ACK [" + str(self.mycallsign, "utf-8") + "] >|< [" + str(static.DXCALLSIGN, "utf-8") + "]", + self.log.info( + "[TNC] PING ACK [" + str(self.mycallsign, "utf-8") + + "] >|< [" + str(static.DXCALLSIGN, "utf-8") + "]", snr=static.SNR) static.TNC_STATE = "IDLE" @@ -1531,7 +1536,7 @@ class DATA: """ 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[:1] = bytes([249]) stop_frame[1:4] = static.DXCALLSIGN_CRC @@ -1549,7 +1554,7 @@ class DATA: """ Received a transmission stop """ - structlog.get_logger("structlog").warning("[TNC] Stopping transmission!") + self.log.warning("[TNC] Stopping transmission!") static.TNC_STATE = "IDLE" static.ARQ_STATE = False static.INFO.append("TRANSMISSION;STOPPED") @@ -1567,18 +1572,18 @@ class DATA: """ try: - while 1: + while True: time.sleep(0.5) while static.BEACON_STATE: if not static.ARQ_SESSION and not self.arq_file_transfer and not static.BEACON_PAUSE: 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[:1] = bytes([250]) beacon_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign) 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: 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) except Exception as err: - structlog.get_logger("structlog").debug("[TNC] run_beacon: ", exception=err) - # print(e) + self.log.debug("[TNC] run_beacon: ", exception=err) def received_beacon(self, data_in: bytes): """ @@ -1606,15 +1610,17 @@ class DATA: dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7])) dxgrid = bytes(data_in[9:13]).rstrip(b"\x00") - jsondata = {"type": "beacon", "status": "received", "uuid": str(uuid.uuid4()), "timestamp": int(time.time()), - "mycallsign": str(self.mycallsign, "utf-8"), "dxcallsign": str(dxcallsign, "utf-8"), - "dxgrid": str(dxgrid, "utf-8"), "snr": str(static.SNR)} + jsondata = {"type": "beacon", "status": "received", "uuid": str(uuid.uuid4()), + "timestamp": int(time.time()), "mycallsign": str(self.mycallsign, "utf-8"), + "dxcallsign": str(dxcallsign, "utf-8"), "dxgrid": str(dxgrid, "utf-8"), + "snr": str(static.SNR)} json_data_out = json.dumps(jsondata) sock.SOCKET_QUEUE.put(json_data_out) static.INFO.append("BEACON;RECEIVING") - structlog.get_logger("structlog").info( - "[TNC] BEACON RCVD [" + str(dxcallsign, "utf-8") + "][" + str(dxgrid, "utf-8") + "] ", snr=static.SNR) + self.log.info( + "[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, static.HAMLIB_FREQUENCY) @@ -1627,7 +1633,7 @@ class DATA: Returns: Nothing """ - structlog.get_logger("structlog").info("[TNC] CQ CQ CQ") + self.log.info("[TNC] CQ CQ CQ") static.INFO.append("CQ;SENDING") cq_frame = bytearray(14) @@ -1635,8 +1641,8 @@ class DATA: cq_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign) cq_frame[7:11] = helpers.encode_grid(static.MYGRID.decode("utf-8")) - structlog.get_logger("structlog").info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) - structlog.get_logger("structlog").debug("[TNC] CQ Frame:", data=[cq_frame]) + self.log.info("[TNC] ENABLE FSK", state=static.ENABLE_FSK) + self.log.debug("[TNC] CQ Frame:", data=[cq_frame]) if static.ENABLE_FSK: 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 dxcallsign = helpers.bytes_to_callsign(bytes(data_in[1:7])) - structlog.get_logger("structlog").debug("[TNC] received_cq:", dxcallsign=dxcallsign) - # print(dxcallsign) + self.log.debug("[TNC] received_cq:", dxcallsign=dxcallsign) + dxgrid = bytes(helpers.decode_grid(data_in[7:11]), "utf-8") static.INFO.append("CQ;RECEIVING") - structlog.get_logger("structlog").info( - "[TNC] CQ RCVD [" + str(dxcallsign, "utf-8") + "][" + str(dxgrid, "utf-8") + "] ", snr=static.SNR) + self.log.info( + "[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, static.HAMLIB_FREQUENCY) @@ -1681,14 +1688,14 @@ class DATA: # in 0.5s increments. helpers.wait(randrange(0, 20, 5) / 10.0) 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[:1] = bytes([201]) qrv_frame[1:7] = helpers.callsign_to_bytes(self.mycallsign) 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: 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])) dxgrid = bytes(helpers.decode_grid(data_in[7:11]), "utf-8") - jsondata = {"type": "qrv", "status": "received", "uuid": str(uuid.uuid4()), "timestamp": int(time.time()), - "mycallsign": str(self.mycallsign, "utf-8"), "dxcallsign": str(dxcallsign, "utf-8"), - "dxgrid": str(dxgrid, "utf-8"), "snr": str(static.SNR)} + jsondata = {"type": "qrv", "status": "received", "uuid": str(uuid.uuid4()), + "timestamp": int(time.time()), "mycallsign": str(self.mycallsign, "utf-8"), + "dxcallsign": str(dxcallsign, "utf-8"), "dxgrid": str(dxgrid, "utf-8"), + "snr": str(static.SNR)} json_data_out = json.dumps(jsondata) sock.SOCKET_QUEUE.put(json_data_out) static.INFO.append("QRV;RECEIVING") - structlog.get_logger("structlog").info( - "[TNC] QRV RCVD [" + str(dxcallsign, "utf-8") + "][" + str(dxgrid, "utf-8") + "] ", snr=static.SNR) + self.log.info( + "[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, static.HAMLIB_FREQUENCY) @@ -1749,7 +1758,7 @@ class DATA: static.ARQ_BITS_PER_SECOND = 0 static.ARQ_BYTES_PER_MINUTE = 0 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_BITS_PER_SECOND = 0 static.ARQ_BYTES_PER_MINUTE = 0 @@ -1796,7 +1805,7 @@ class DATA: static.ARQ_BYTES_PER_MINUTE = 0 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_BITS_PER_SECOND = 0 static.ARQ_BYTES_PER_MINUTE = 0 @@ -1810,7 +1819,7 @@ class DATA: """ 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"" @@ -1881,18 +1890,18 @@ class DATA: if mode_name == "datac1": 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": 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": 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": modem.RECEIVE_DATAC1 = True modem.RECEIVE_DATAC3 = 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 def watchdog(self): @@ -1926,9 +1935,8 @@ class DATA: # print((self.data_channel_last_received + self.time_list[self.speed_level])-time.time()) pass else: - structlog.get_logger("structlog").warning("[TNC] Frame timeout", attempt=self.n_retries_per_burst, - max_attempts=self.rx_n_max_retries_per_burst, - speed_level=self.speed_level) + self.log.warning("[TNC] Frame timeout", attempt=self.n_retries_per_burst, + max_attempts=self.rx_n_max_retries_per_burst, speed_level=self.speed_level) self.frame_received_counter = 0 self.burst_nack_counter += 1 if self.burst_nack_counter >= 2: @@ -1967,8 +1975,9 @@ class DATA: # pass else: self.data_channel_last_received = 0 - structlog.get_logger("structlog").info( - "[TNC] DATA [" + str(self.mycallsign, "utf-8") + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]") + self.log.info( + "[TNC] DATA [" + str(self.mycallsign, "utf-8") + + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]") static.INFO.append("ARQ;RECEIVING;FAILED") if not TESTMODE: self.arq_cleanup() @@ -1982,9 +1991,9 @@ class DATA: if self.arq_session_last_received + self.arq_session_timeout > time.time(): time.sleep(0.01) else: - structlog.get_logger("structlog").info( - "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + "]<>[" + str(static.DXCALLSIGN, - "utf-8") + "]") + self.log.info( + "[TNC] SESSION [" + str(self.mycallsign, "utf-8") + + "]<>[" + str(static.DXCALLSIGN, "utf-8") + "]") static.INFO.append("ARQ;SESSION;TIMEOUT") self.close_session() @@ -1992,7 +2001,7 @@ class DATA: """ heartbeat thread which auto resumes the heartbeat signal within a arq session """ - while 1: + while True: 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: time.sleep(1) diff --git a/tnc/main.py b/tnc/main.py index 3f076fdf..a3acb0d1 100755 --- a/tnc/main.py +++ b/tnc/main.py @@ -150,5 +150,5 @@ if __name__ == "__main__": except Exception as err: structlog.get_logger("structlog").error("[TNC] Starting TCP/IP socket failed", port=static.PORT, e=err) sys.exit(1) - while 1: + while True: time.sleep(1) diff --git a/tnc/modem.py b/tnc/modem.py index f3b0bf2d..52aad102 100644 --- a/tnc/modem.py +++ b/tnc/modem.py @@ -44,6 +44,7 @@ RECEIVE_FSK_LDPC_1 = False class RF: """ """ + log = structlog.get_logger("RF") def __init__(self): @@ -142,19 +143,19 @@ class RF: device=(static.AUDIO_INPUT_DEVICE, static.AUDIO_OUTPUT_DEVICE), samplerate=self.AUDIO_SAMPLE_RATE_RX, blocksize=4800) 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: - 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) 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.stream.start() 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: # create a stream object for simulating audio stream @@ -169,7 +170,7 @@ class RF: os.mkfifo(RXCHANNEL) os.mkfifo(TXCHANNEL) 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, name="MKFIFO WRITE CALLBACK THREAD", daemon=True) @@ -233,7 +234,7 @@ class RF: # -------------------------------------------------------------------------------------------------------- def mkfifo_read_callback(self): - while 1: + while True: time.sleep(0.01) # -----read data_in48k = bytes() @@ -257,7 +258,7 @@ class RF: self.datac3_buffer.push(x) def mkfifo_write_callback(self): - while 1: + while True: time.sleep(0.01) # -----write @@ -283,8 +284,6 @@ class RF: time: status: - Returns: - Nothing """ x = np.frombuffer(data_in48k, dtype=np.int16) x = self.resampler.resample48_to_8(x) @@ -333,7 +332,7 @@ class RF: try: outdata[:] = data_out48k[:frames] 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) @@ -347,10 +346,8 @@ class RF: repeat_delay: frames: - Returns: - """ - structlog.get_logger("structlog").debug("[MDM] transmit", mode=mode) + self.log.debug("[MDM] transmit", mode=mode) static.TRANSMITTING = True # Toggle ptt early to save some time and send ptt state via socket static.PTT_STATE = self.hamlib.set_ptt(True) @@ -384,7 +381,7 @@ class RF: mod_out_silence = ctypes.create_string_buffer(data_delay * 2) 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): # 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_zeros = np.zeros(delta, dtype=np.int16) 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) @@ -556,7 +553,7 @@ class RF: while True: 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.modem_transmit_queue.task_done() @@ -577,8 +574,6 @@ class RF: Args: freedv: - Returns: - """ modemStats = codec2.MODEMSTATS() self.c_lib.freedv_get_modem_extended_stats.restype = None @@ -593,8 +588,6 @@ class RF: Args: freedv: - Returns: - """ if not static.ENABLE_SCATTER: return @@ -629,8 +622,6 @@ class RF: Args: freedv: - Returns: - """ try: modem_stats_snr = ctypes.c_float() @@ -641,12 +632,12 @@ class RF: modem_stats_sync = modem_stats_sync.value 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, -128, 128) # limit to max value of -128/128 as a possible fix of #188 return static.SNR 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 return static.SNR @@ -712,8 +703,8 @@ class RF: static.FFT = dfftlist[:320] # 320 --> bandwidth 3000 except Exception as err: - structlog.get_logger("structlog").error(f"[MDM] calculate_fft: Exception: {err}") - structlog.get_logger("structlog").debug("[MDM] Setting fft=0") + self.log.error(f"[MDM] calculate_fft: Exception: {err}") + self.log.debug("[MDM] Setting fft=0") # else 0 static.FFT = [0] @@ -723,8 +714,6 @@ class RF: Args: 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.datac3_freedv, n_frames_per_burst) @@ -753,8 +742,6 @@ def get_bytes_per_frame(mode): Args: mode: - Returns: - """ freedv = open_codec2_instance(mode) diff --git a/tnc/rigctld.py b/tnc/rigctld.py index 34c02806..46b4c142 100644 --- a/tnc/rigctld.py +++ b/tnc/rigctld.py @@ -8,8 +8,6 @@ import logging import socket import time -import log_handler -import static import structlog # set global hamlib version diff --git a/tnc/rigdummy.py b/tnc/rigdummy.py index ccd3012f..35b98b3f 100644 --- a/tnc/rigdummy.py +++ b/tnc/rigdummy.py @@ -1,7 +1,5 @@ #!/usr/bin/env python3 -import structlog - hamlib_version = 0 diff --git a/tnc/sock.py b/tnc/sock.py index e241bd7c..94cf1c8f 100644 --- a/tnc/sock.py +++ b/tnc/sock.py @@ -38,6 +38,8 @@ DAEMON_QUEUE = queue.Queue() CONNECTED_CLIENTS = set() CLOSE_SIGNAL = False +log = structlog.get_logger("sock") + class ThreadedTCPServer(socketserver.ThreadingMixIn, socketserver.TCPServer): """ @@ -82,8 +84,7 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler): try: client.send(sock_data) except Exception as err: - # print("connection lost...") - structlog.get_logger("structlog").info("[SCK] Connection lost", e=err) + log.info("[SCK] Connection lost", e=err) self.connection_alive = False # 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 data = bytes() except Exception as err: - structlog.get_logger("structlog").info("[SCK] Connection closed", ip=self.client_address[0], - port=self.client_address[1], e=err) + log.info("[SCK] Connection closed", ip=self.client_address[0], + port=self.client_address[1], e=err) self.connection_alive = False def handle(self): @@ -141,12 +142,14 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler): """ CONNECTED_CLIENTS.add(self.request) - structlog.get_logger("structlog").debug("[SCK] Client connected", ip=self.client_address[0], - port=self.client_address[1]) + log.debug("[SCK] Client connected", ip=self.client_address[0], + port=self.client_address[1]) self.connection_alive = True - self.sendThread = threading.Thread(target=self.send_to_client, args=[], daemon=True).start() - self.receiveThread = threading.Thread(target=self.receive_from_client, args=[], daemon=True).start() + self.send_thread = threading.Thread(target=self.send_to_client, args=[], daemon=True) + 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 while self.connection_alive and not CLOSE_SIGNAL: @@ -154,13 +157,13 @@ class ThreadedTCPRequestHandler(socketserver.StreamRequestHandler): def finish(self): """ """ - structlog.get_logger("structlog").warning("[SCK] Closing client socket", ip=self.client_address[0], - port=self.client_address[1]) + log.warning("[SCK] Closing client socket", ip=self.client_address[0], + port=self.client_address[1]) try: CONNECTED_CLIENTS.remove(self.request) except Exception as err: - structlog.get_logger("structlog").warning("[SCK] client connection already removed from client list", - client=self.request, e=err) + log.warning("[SCK] client connection already removed from client list", + client=self.request, e=err) def process_tnc_commands(data): @@ -177,7 +180,7 @@ def process_tnc_commands(data): try: # convert data to json object 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 ----------------------------------------------------- if received_json["type"] == "set" and received_json["command"] == "tx_audio_level": try: @@ -186,7 +189,7 @@ def process_tnc_commands(data): except Exception as err: 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 ----------------------------------------------------- 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) except Exception as err: 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 ----------------------------------------------------- if received_json["command"] == "cqcqcq": @@ -205,7 +208,7 @@ def process_tnc_commands(data): except Exception as err: 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 ----------------------------------------------------- if received_json["command"] == "start_beacon": @@ -216,18 +219,18 @@ def process_tnc_commands(data): command_response("start_beacon", True) except Exception as err: 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 ----------------------------------------------------- if received_json["command"] == "stop_beacon": try: - structlog.get_logger("structlog").warning("[TNC] Stopping beacon!") + log.warning("[TNC] Stopping beacon!") static.BEACON_STATE = False data_handler.DATA_QUEUE_TRANSMIT.put(["BEACON", None, False]) command_response("stop_beacon", True) except Exception as err: 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 ---------------------------------------------------------- if received_json["type"] == "ping" and received_json["command"] == "ping": @@ -245,7 +248,7 @@ def process_tnc_commands(data): command_response("ping", True) except Exception as err: 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 ---------------------------------------------------------- if received_json["type"] == "arq" and received_json["command"] == "connect": @@ -267,7 +270,7 @@ def process_tnc_commands(data): command_response("connect", True) except Exception as err: 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 ---------------------------------------------------------- if received_json["type"] == "arq" and received_json["command"] == "disconnect": @@ -277,7 +280,7 @@ def process_tnc_commands(data): command_response("disconnect", True) except Exception as err: 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 ------------------------------------------- if received_json["type"] == "arq" and received_json["command"] == "send_raw": @@ -321,20 +324,20 @@ def process_tnc_commands(data): raise TypeError except Exception as err: 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 ---------------------------------------------------------- if received_json["type"] == "arq" and received_json["command"] == "stop_transmission": try: if static.TNC_STATE == "BUSY" or static.ARQ_STATE: 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.ARQ_STATE = False command_response("stop_transmission", True) except Exception as err: 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": try: @@ -358,7 +361,7 @@ def process_tnc_commands(data): except Exception as err: 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": try: @@ -366,11 +369,11 @@ def process_tnc_commands(data): command_response("del_rx_buffer", True) except Exception as err: 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 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(): @@ -424,6 +427,8 @@ def send_tnc_state(): 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): """ process daemon commands @@ -436,25 +441,25 @@ def process_daemon_commands(data): """ # convert data to json object 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": try: callsign = received_json["parameter"] if bytes(callsign, "utf-8") == b"": self.request.sendall(b"INVALID CALLSIGN") - structlog.get_logger("structlog").warning("[DMN] SET MYCALL FAILED", call=static.MYCALLSIGN, - crc=static.MYCALLSIGN_CRC) + log.warning("[DMN] SET MYCALL FAILED", call=static.MYCALLSIGN, + crc=static.MYCALLSIGN_CRC) else: static.MYCALLSIGN = bytes(callsign, "utf-8") static.MYCALLSIGN_CRC = helpers.get_crc_24(static.MYCALLSIGN) command_response("mycallsign", True) - structlog.get_logger("structlog").info("[DMN] SET MYCALL", call=static.MYCALLSIGN, - crc=static.MYCALLSIGN_CRC) + log.info("[DMN] SET MYCALL", call=static.MYCALLSIGN, + crc=static.MYCALLSIGN_CRC) except Exception as err: 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": try: @@ -464,11 +469,11 @@ def process_daemon_commands(data): self.request.sendall(b"INVALID GRID") else: 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) except Exception as err: 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: try: @@ -498,7 +503,7 @@ def process_daemon_commands(data): # print some debugging parameters 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", mycall, @@ -529,7 +534,7 @@ def process_daemon_commands(data): except Exception as err: 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": try: @@ -561,7 +566,7 @@ def process_daemon_commands(data): command_response("test_hamlib", True) except Exception as err: 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": try: @@ -569,12 +574,12 @@ def process_daemon_commands(data): # unregister process from atexit to avoid process zombies atexit.unregister(static.TNCPROCESS.kill) - structlog.get_logger("structlog").warning("[DMN] Stopping TNC") + log.warning("[DMN] Stopping TNC") static.TNCSTARTED = False command_response("stop_tnc", True) except Exception as err: 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(): @@ -605,7 +610,7 @@ def send_daemon_state(): return json.dumps(output) except Exception as err: - structlog.get_logger("structlog").warning("[SCK] error", e=err) + log.warning("[SCK] error", e=err) return None diff --git a/tnc/static.py b/tnc/static.py index aef93c35..10a17a50 100644 --- a/tnc/static.py +++ b/tnc/static.py @@ -8,115 +8,118 @@ Here we are saving application wide variables and stats, which have to be access Not nice, suggestions are appreciated :-) """ +import subprocess + VERSION = "0.4.0-alpha" # DAEMON -DAEMONPORT = 3001 -TNCSTARTED = False -TNCPROCESS = 0 +DAEMONPORT: int = 3001 +TNCSTARTED: bool = False +TNCPROCESS: subprocess.Popen # Operator Defaults -MYCALLSIGN = b"AA0AA" -MYCALLSIGN_CRC = b"A" +MYCALLSIGN: bytes = b"AA0AA" +MYCALLSIGN_CRC: bytes = b"A" -DXCALLSIGN = b"AA0AA" -DXCALLSIGN_CRC = b"A" +DXCALLSIGN: bytes = b"AA0AA" +DXCALLSIGN_CRC: bytes = b"A" -MYGRID = b"" -DXGRID = b"" +MYGRID: bytes = 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 -HOST = "0.0.0.0" -PORT = 3000 -SOCKET_TIMEOUT = 1 # seconds +HOST: str = "0.0.0.0" +PORT: int = 3000 +SOCKET_TIMEOUT: int = 1 # seconds # --------------------------------- -SERIAL_DEVICES = [] +SERIAL_DEVICES: list = [] # --------------------------------- -PTT_STATE = False -TRANSMITTING = False +PTT_STATE: bool = False +TRANSMITTING: bool = False -HAMLIB_VERSION = "0" -HAMLIB_PTT_TYPE = "RTS" -HAMLIB_DEVICE_NAME = "RIG_MODEL_DUMMY_NOVFO" -HAMLIB_DEVICE_PORT = "/dev/ttyUSB0" -HAMLIB_SERIAL_SPEED = "9600" -HAMLIB_PTT_PORT = "/dev/ttyUSB0" -HAMLIB_STOP_BITS = "1" -HAMLIB_DATA_BITS = "8" -HAMLIB_HANDSHAKE = "None" -HAMLIB_RADIOCONTROL = "direct" -HAMLIB_RIGCTLD_IP = "127.0.0.1" -HAMLIB_RIGCTLD_PORT = "4532" +HAMLIB_VERSION: str = "0" +HAMLIB_PTT_TYPE: str = "RTS" +HAMLIB_DEVICE_NAME: str = "RIG_MODEL_DUMMY_NOVFO" +HAMLIB_DEVICE_PORT: str = "/dev/ttyUSB0" +HAMLIB_SERIAL_SPEED: str = "9600" +HAMLIB_PTT_PORT: str = "/dev/ttyUSB0" +HAMLIB_STOP_BITS: str = "1" +HAMLIB_DATA_BITS: str = "8" +HAMLIB_HANDSHAKE: str = "None" +HAMLIB_RADIOCONTROL: str = "direct" +HAMLIB_RIGCTLD_IP: str = "127.0.0.1" +HAMLIB_RIGCTLD_PORT: str = "4532" -HAMLIB_FREQUENCY = 0 -HAMLIB_MODE = "" -HAMLIB_BANDWITH = 0 +HAMLIB_FREQUENCY: int = 0 +HAMLIB_MODE: str = "" +HAMLIB_BANDWITH: int = 0 # ------------------------- # FreeDV Defaults -SNR = 0 -FREQ_OFFSET = 0 -SCATTER = [] -ENABLE_SCATTER = False -ENABLE_FSK = False -RESPOND_TO_CQ = False +SNR: float = 0 +FREQ_OFFSET: float = 0 +SCATTER: list = [] +ENABLE_SCATTER: bool = False +ENABLE_FSK: bool = False +RESPOND_TO_CQ: bool = False # --------------------------------- # Audio Defaults -TX_AUDIO_LEVEL = 50 -AUDIO_INPUT_DEVICES = [] -AUDIO_OUTPUT_DEVICES = [] -AUDIO_INPUT_DEVICE = -2 -AUDIO_OUTPUT_DEVICE = -2 -BUFFER_OVERFLOW_COUNTER = [0, 0, 0, 0, 0] +TX_AUDIO_LEVEL: int = 50 +AUDIO_INPUT_DEVICES: list = [] +AUDIO_OUTPUT_DEVICES: list = [] +AUDIO_INPUT_DEVICE: int = -2 +AUDIO_OUTPUT_DEVICE: int = -2 +BUFFER_OVERFLOW_COUNTER: list = [0, 0, 0, 0, 0] -AUDIO_RMS = 0 -FFT = [0] -ENABLE_FFT = False -CHANNEL_BUSY = None +AUDIO_RMS: int = 0 +FFT: list = [0] +ENABLE_FFT: bool = False +CHANNEL_BUSY: bool = False # ARQ PROTOCOL VERSION -ARQ_PROTOCOL_VERSION = 1 +ARQ_PROTOCOL_VERSION: int = 1 # ARQ statistics -ARQ_BYTES_PER_MINUTE_BURST = 0 -ARQ_BYTES_PER_MINUTE = 0 -ARQ_BITS_PER_SECOND_BURST = 0 -ARQ_BITS_PER_SECOND = 0 -ARQ_COMPRESSION_FACTOR = 0 -ARQ_TRANSMISSION_PERCENT = 0 -ARQ_SPEED_LEVEL = 0 -TOTAL_BYTES = 0 +ARQ_BYTES_PER_MINUTE_BURST: int = 0 +ARQ_BYTES_PER_MINUTE: int = 0 +ARQ_BITS_PER_SECOND_BURST: int = 0 +ARQ_BITS_PER_SECOND: int = 0 +ARQ_COMPRESSION_FACTOR: int = 0 +ARQ_TRANSMISSION_PERCENT: int = 0 +ARQ_SPEED_LEVEL: int = 0 +TOTAL_BYTES: int = 0 # CHANNEL_STATE = 'RECEIVING_SIGNALLING' -TNC_STATE = "IDLE" -ARQ_STATE = False -ARQ_SESSION = False -ARQ_SESSION_STATE = "disconnected" # disconnected, connecting, connected, disconnecting, failed +TNC_STATE: str = "IDLE" +ARQ_STATE: bool = False +ARQ_SESSION: bool = False +# disconnected, connecting, connected, disconnecting, failed +ARQ_SESSION_STATE: str = "disconnected" # BEACON STATE -BEACON_STATE = False -BEACON_PAUSE = False +BEACON_STATE: bool = False +BEACON_PAUSE: bool = False # ------- RX BUFFER -RX_BUFFER = [] -RX_MSG_BUFFER = [] -RX_BURST_BUFFER = [] -RX_FRAME_BUFFER = b"" -# RX_BUFFER_SIZE = 0 +RX_BUFFER: list = [] +RX_MSG_BUFFER: list = [] +RX_BURST_BUFFER: list = [] +RX_FRAME_BUFFER: bytes = b"" +# RX_BUFFER_SIZE: int = 0 # ------- HEARD STATIONS BUFFER -HEARD_STATIONS = [] +HEARD_STATIONS: list = [] # ------- INFO MESSAGE BUFFER -INFO = [] +INFO: list = [] # ------- CODEC2 SETTINGS -TUNING_RANGE_FMIN = -50.0 -TUNING_RANGE_FMAX = 50.0 +TUNING_RANGE_FMIN: float = -50.0 +TUNING_RANGE_FMAX: float = 50.0 diff --git a/tools/list_audio_devices.py b/tools/list_audio_devices.py index 8b869b4c..8ee31fa2 100755 --- a/tools/list_audio_devices.py +++ b/tools/list_audio_devices.py @@ -6,12 +6,14 @@ import pyaudio def list_audio_devices(): p = pyaudio.PyAudio() - devices = [] print("--------------------------------------------------------------------") - for x in range(0, p.get_device_count()): - devices.append(f"{x} - {p.get_device_info_by_index(x)['name']}") - + devices = [ + f"{x} - {p.get_device_info_by_index(x)['name']}" + for x in range(p.get_device_count()) + ] + for line in devices: - print(line) + print(line) + list_audio_devices() diff --git a/tools/socketclient.py b/tools/socketclient.py index 753ce568..9e667b77 100644 --- a/tools/socketclient.py +++ b/tools/socketclient.py @@ -6,10 +6,9 @@ Created on Fri Dec 11 21:53:35 2020 @author: parallels """ -import socket -import sys import argparse import random +import socket def create_string(length): @@ -24,14 +23,14 @@ def create_string(length): random_integer = random_integer - 32 if flip_bit == 1 else random_integer # Keep appending random characters using chr(x) random_string += (chr(random_integer)) - print("STR:" + str(random_string)) - + print(f"STR: {random_string!s}") + return random_string # --------------------------------------------GET PARAMETER INPUTS 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('--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 received = str(sock.recv(1024), "utf-8") -print("Sent: {}".format(data)) - - - +print(f"Sent: {data}")