diff --git a/arq.py b/arq.py index ef60befd..92490a2d 100644 --- a/arq.py +++ b/arq.py @@ -14,7 +14,10 @@ from random import randrange import static import modem import helpers -import main +#import main + + + modem = modem.RF() @@ -22,12 +25,7 @@ modem = modem.RF() static.ARQ_PAYLOAD_PER_FRAME = static.FREEDV_DATA_PAYLOAD_PER_FRAME - 3 #6?! static.ARQ_ACK_PAYLOAD_PER_FRAME = 14 - 2# -#def arq_ack_timeout(): -# static.ARQ_ACK_TIMEOUT = 1 -#def arq_rpt_timeout(): -# static.ARQ_RPT_TIMEOUT = True - def data_received(data_in): @@ -122,7 +120,7 @@ def data_received(data_in): frame_number = burstnumber.to_bytes(2, byteorder='big') missing_frames += frame_number - logging.info("ARQ | TX | RPT ARQ FRAMES [" + str(missing_frames) + "]") + logging.warning("ARQ | TX | RPT ARQ FRAMES [" + str(missing_frames) + "]") #BUILDING RPT FRAME FOR BURST ----------------------------------------------- rpt_payload = missing_frames @@ -180,7 +178,7 @@ def data_received(data_in): ack_frame = b'='+ ack_payload + bytes(static.FRAME_CRC) # < = 61 #TRANSMIT ACK FRAME FOR BURST----------------------------------------------- - time.sleep(3) #0.5 + time.sleep(1) #0.5 logging.info("ARQ | TX | ARQ DATA FRAME ACK [" + str(static.FRAME_CRC.hex()) +"]") modem.transmit_arq_ack(ack_frame) @@ -197,7 +195,7 @@ def data_received(data_in): #print("----------------------------------------------------------------") else: - logging.info("ARQ | RX | DATA FRAME NOT SUCESSFULLY RECEIVED!") + logging.error("ARQ | RX | DATA FRAME NOT SUCESSFULLY RECEIVED!") @@ -273,7 +271,7 @@ def transmit(data_out): #static.ARQ_RX_ACK_TIMEOUT = False - logging.info("ARQ | RX | WAITING FOR BURST ACK") + logging.debug("ARQ | RX | WAITING FOR BURST ACK") static.ARQ_STATE = 'RECEIVING_SIGNALLING' helpers.arq_reset_timeout(False) @@ -282,22 +280,22 @@ def transmit(data_out): acktimer = threading.Timer(static.ARQ_RX_ACK_TIMEOUT_SECONDS, helpers.arq_ack_timeout) acktimer.start() - print(".............................") - print("static.ARQ_STATE " + str(static.ARQ_STATE)) - print("static.ARQ_FRAME_ACK_RECEIVED " + str(static.ARQ_FRAME_ACK_RECEIVED)) - print("static.ARQ_ACK_RECEIVED " + str(static.ARQ_ACK_RECEIVED)) - print("static.ARQ_RX_ACK_TIMEOUT " + str(static.ARQ_RX_ACK_TIMEOUT)) - print("static.ARQ_RPT_RECEIVED " + str(static.ARQ_RPT_RECEIVED)) - print(".............................") + logging.debug(".............................") + logging.debug("static.ARQ_STATE " + str(static.ARQ_STATE)) + logging.debug("static.ARQ_FRAME_ACK_RECEIVED " + str(static.ARQ_FRAME_ACK_RECEIVED)) + logging.debug("static.ARQ_ACK_RECEIVED " + str(static.ARQ_ACK_RECEIVED)) + logging.debug("static.ARQ_RX_ACK_TIMEOUT " + str(static.ARQ_RX_ACK_TIMEOUT)) + logging.debug("static.ARQ_RPT_RECEIVED " + str(static.ARQ_RPT_RECEIVED)) + logging.debug(".............................") # --------------------------- WHILE TIMEOUT NOT REACHED AND NO ACK RECEIVED --> LISTEN while static.ARQ_ACK_RECEIVED != True and static.ARQ_RPT_RECEIVED != True and static.ARQ_FRAME_ACK_RECEIVED != True and static.ARQ_RX_FRAME_TIMEOUT != True and static.ARQ_RX_ACK_TIMEOUT != True: time.sleep(0.01) # lets reduce CPU load a little bit - print(static.ARQ_STATE) + logging.debug(static.ARQ_STATE) if static.ARQ_RPT_RECEIVED == True: - logging.info("ARQ | RX | REQUEST FOR REPEATING FRAMES: " + str(static.ARQ_RPT_FRAMES)) + logging.warning("ARQ | RX | REQUEST FOR REPEATING FRAMES: " + str(static.ARQ_RPT_FRAMES)) logging.info("ARQ | TX | SENDING REQUESTED FRAMES: " + str(static.ARQ_RPT_FRAMES)) TRANSMIT_ARQ_BURST_THREAD = threading.Thread(target=modem.transmit_arq_burst, name="TRANSMIT_ARQ_BURST") @@ -318,7 +316,7 @@ def transmit(data_out): while static.ARQ_ACK_RECEIVED == False and static.ARQ_FRAME_ACK_RECEIVED == False and static.ARQ_RX_RPT_TIMEOUT == False: time.sleep(0.01) # lets reduce CPU load a little bit - print(static.ARQ_STATE) + logging.debug(static.ARQ_STATE) if static.ARQ_ACK_RECEIVED == True: @@ -328,7 +326,8 @@ def transmit(data_out): static.ARQ_RPT_FRAMES = [] if static.ARQ_RX_RPT_TIMEOUT == True and static.ARQ_ACK_RECEIVED == False: - print("Burst lost....") + + logging.error("ARQ | Burst lost....") helpers.arq_reset_ack(False) static.ARQ_RPT_FRAMES = [] @@ -336,7 +335,7 @@ def transmit(data_out): #-------------------------------------------------------------------------------------------------------------- elif static.ARQ_ACK_RECEIVED == 0 and static.ARQ_RX_ACK_TIMEOUT == 1: - logging.info("ARQ | RX | ACK TIMEOUT - AND NO ACK!") + logging.warning("ARQ | RX | ACK TIMEOUT - AND NO ACK!") pass #no break here so we can continue with the next try of repeating the burst #--------------- BREAK LOOP IF ACK HAS BEEN RECEIVED @@ -348,30 +347,30 @@ def transmit(data_out): #--------------- BREAK LOOP IF FRAME ACK HAS BEEN RECEIVED EARLIER AS EXPECTED elif static.ARQ_FRAME_ACK_RECEIVED == True: - print("----------------------------------------------------------") + logging.info("----------------------------------------------------------") logging.info("ARQ | RX | EARLY FRAME ACK RECEIVED - STOPPING TX") #static.ARQ_N_SENT_FRAMES = #static.TX_BUFFER_SIZE static.ARQ_N_SENT_FRAMES = static.ARQ_N_SENT_FRAMES + static.ARQ_TX_N_FRAMES_PER_BURST break else: - print("------------------------------->NO RULE MATCHED!") + logging.debug("------------------------------->NO RULE MATCHED!") break #--------------------------------WAITING AREA FOR FRAME ACKs - print("static.ARQ_N_SENT_FRAMES " + str(static.ARQ_N_SENT_FRAMES)) - print("static.TX_BUFFER_SIZE " + str(static.TX_BUFFER_SIZE)) - print("static.TX_N_RETRIES " + str(static.TX_N_RETRIES)) - print("static.TX_N_MAX_RETRIES " + str(static.TX_N_MAX_RETRIES)) + logging.debug("static.ARQ_N_SENT_FRAMES " + str(static.ARQ_N_SENT_FRAMES)) + logging.debug("static.TX_BUFFER_SIZE " + str(static.TX_BUFFER_SIZE)) + logging.debug("static.TX_N_RETRIES " + str(static.TX_N_RETRIES)) + logging.debug("static.TX_N_MAX_RETRIES " + str(static.TX_N_MAX_RETRIES)) - print("static.ARQ_STATE " + str(static.ARQ_STATE)) - print("static.ARQ_FRAME_ACK_RECEIVED " + str(static.ARQ_FRAME_ACK_RECEIVED)) - print("static.ARQ_RX_FRAME_TIMEOUT " + str(static.ARQ_RX_FRAME_TIMEOUT)) - print("static.ARQ_ACK_RECEIVED " + str(static.ARQ_ACK_RECEIVED)) - print("static.ARQ_RX_ACK_TIMEOUT " + str(static.ARQ_RX_ACK_TIMEOUT)) - print("static.ARQ_RPT_RECEIVED " + str(static.ARQ_RPT_RECEIVED)) + logging.debug("static.ARQ_STATE " + str(static.ARQ_STATE)) + logging.debug("static.ARQ_FRAME_ACK_RECEIVED " + str(static.ARQ_FRAME_ACK_RECEIVED)) + logging.debug("static.ARQ_RX_FRAME_TIMEOUT " + str(static.ARQ_RX_FRAME_TIMEOUT)) + logging.debug("static.ARQ_ACK_RECEIVED " + str(static.ARQ_ACK_RECEIVED)) + logging.debug("static.ARQ_RX_ACK_TIMEOUT " + str(static.ARQ_RX_ACK_TIMEOUT)) + logging.debug("static.ARQ_RPT_RECEIVED " + str(static.ARQ_RPT_RECEIVED)) frametimer = threading.Timer(static.ARQ_RX_FRAME_TIMEOUT_SECONDS, helpers.arq_frame_timeout) @@ -382,13 +381,13 @@ def transmit(data_out): while static.ARQ_FRAME_ACK_RECEIVED == False and static.ARQ_RX_FRAME_TIMEOUT == False and static.ARQ_N_SENT_FRAMES == static.TX_BUFFER_SIZE: time.sleep(0.01) # lets reduce CPU load a little bit #print(static.ARQ_STATE) - print("WAITING FOR FRAME ACK") + logging.debug("WAITING FOR FRAME ACK") # ----------- if no ACK received and out of retries.....stop frame sending if static.ARQ_ACK_RECEIVED == False and static.ARQ_FRAME_ACK_RECEIVED == False and static.ARQ_RX_ACK_TIMEOUT == True: - logging.info("ARQ | TX | NO BURST OR FRAME ACK RECEIVED | DATA SHOULD BE RESEND!") + logging.error("ARQ | TX | NO BURST OR FRAME ACK RECEIVED | DATA SHOULD BE RESEND!") break #-------------------------BREAK TX BUFFER LOOP IF ALL PACKETS HAVE BEEN SENT AND WE GOT A FRAME ACK @@ -397,7 +396,7 @@ def transmit(data_out): break else: - print("NO MATCHING RULE AT THE END") + logging.debug("NO MATCHING RULE AT THE END") # IF TX BUFFER IS EMPTY / ALL FRAMES HAVE BEEN SENT --> HERE WE COULD ADD AN static.VAR for IDLE STATE @@ -421,7 +420,7 @@ def get_n_frames_per_burst(): def burst_ack_received(): - logging.info("ARQ | RX | BURST ACK RCVD!") + #logging.info("ARQ | RX | BURST ACK RCVD!") #static.ARQ_RX_ACK_TIMEOUT = True #Force timer to stop waiting static.ARQ_ACK_RECEIVED = True #Force data loops of TNC to stop and continue with next frame @@ -432,7 +431,7 @@ def burst_ack_received(): def frame_ack_received(): - logging.info("ARQ | RX | FRAME ACK RCVD!") + #logging.info("ARQ | RX | FRAME ACK RCVD!") #static.ARQ_RX_ACK_TIMEOUT = True #Force timer to stop waiting static.ARQ_FRAME_ACK_RECEIVED = True #Force data loops of TNC to stop and continue with next frame @@ -443,7 +442,7 @@ def frame_ack_received(): def burst_rpt_received(data_in): - logging.info("ARQ | RX | BURST RPT RCVD!") + #logging.info("ARQ | RX | BURST RPT RCVD!") #static.ARQ_RX_ACK_TIMEOUT = False #Force timer to stop waiting #static.ARQ_ACK_RECEIVED = False #Force data loops of TNC to stop and continue with next frame diff --git a/helpers.py b/helpers.py index d2b2d1e3..10447e46 100644 --- a/helpers.py +++ b/helpers.py @@ -9,12 +9,14 @@ Created on Fri Dec 25 21:25:14 2020 import time import threading import logging +from colorlog import ColoredFormatter import crcengine import static - + + def get_crc_8(data): crc_algorithm = crcengine.new('crc8-ccitt') #load crc8 library @@ -32,29 +34,29 @@ def get_crc_16(data): def arq_ack_timeout(): if static.ARQ_STATE == 'RECEIVING_SIGNALLING': static.ARQ_RX_ACK_TIMEOUT = True - print("ARQ_RX_ACK_TIMEOUT") + logging.debug("ARQ_RX_ACK_TIMEOUT") def arq_rpt_timeout(): if static.ARQ_STATE == 'RECEIVING_SIGNALLING': static.ARQ_RX_RPT_TIMEOUT = True - print("ARQ_RX_RPT_TIMEOUT") + logging.debug("ARQ_RX_RPT_TIMEOUT") def arq_frame_timeout(): if static.ARQ_STATE == 'RECEIVING_SIGNALLING': static.ARQ_RX_FRAME_TIMEOUT = True - print("ARQ_RX_FRAME_TIMEOUT") + logging.debug("ARQ_RX_FRAME_TIMEOUT") def arq_reset_timeout(state): - print(state) + static.ARQ_RX_ACK_TIMEOUT = state static.ARQ_RX_FRAME_TIMEOUT = state static.ARQ_RX_RPT_TIMEOUT = state def arq_reset_ack(state): - print(state) + static.ARQ_ACK_RECEIVED = state static.ARQ_RPT_RECEIVED = state static.ARQ_FRAME_ACK_RECEIVED = state @@ -66,6 +68,6 @@ def arq_reset_frame_machine(): static.ARQ_N_SENT_FRAMES = 0 static.ARQ_TX_N_FRAMES_PER_BURST = 0 - + diff --git a/main.py b/main.py index 8fdc7b28..e86710f6 100644 --- a/main.py +++ b/main.py @@ -11,8 +11,10 @@ import socketserver import argparse import logging + #import tnc import static +import helpers @@ -21,32 +23,68 @@ import static if __name__ == '__main__': + + + + static.MYCALLSIGN = b'DJ2LS' + static.MYCALLSIGN_CRC8 = helpers.get_crc_8(static.MYCALLSIGN) + + static.DXCALLSIGN = b'DH3WO' + static.DXCALLSIGN_CRC8 = helpers.get_crc_8(static.DXCALLSIGN) + + print("MYCALLSIGN " + str(static.MYCALLSIGN)) + print("MYCALLSIGN_CRC8 " + str(static.MYCALLSIGN_CRC8)) + + print("DXCALLSIGN " + str(static.DXCALLSIGN)) + print("DXCALLSIGN_CRC8 " + str(static.DXCALLSIGN_CRC8)) + + + #--------------------------------------------GET PARAMETER INPUTS parser = argparse.ArgumentParser(description='Simons TEST TNC') parser.add_argument('--rx', dest="audio_input_device", default=0, help="sound card for listening.", type=int) parser.add_argument('--tx', dest="audio_output_device", default=0, help="sound card for transmitting.", type=int) parser.add_argument('--port', dest="socket_port", default=3000, help="Set the port, the socket is listening on.", type=int) - + parser.add_argument('--mode', dest="freedv_data_mode", default=12, help="Set the mode.", type=int) + args = parser.parse_args() - + + + + static.FREEDV_DATA_MODE = args.freedv_data_mode static.AUDIO_INPUT_DEVICE = args.audio_input_device static.AUDIO_OUTPUT_DEVICE = args.audio_output_device static.PORT = args.socket_port import tnc # we need to wait until we got all parameters from argparse - #-------------------------------------------- DEFINE LOGGER - logger = logging.getLogger() - logger.setLevel("INFO") #DEBUG>INFO>WARNING>ERROR>CRITICAL + #-------------------------------------------- DEFINE LOGGING + logging.basicConfig(format='%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s', datefmt='%H:%M:%S', level=logging.INFO) + #logging.addLevelName(logging.INFO, "\033[1;37m%s\033[1;0m" % 'SUCCESS') - - - #--------------------------------------------START SERVER - logging.info("STARTING TCP/IP SOCKET ON PORT " + str(static.PORT)) + logging.addLevelName( logging.DEBUG, "\033[1;37m%s\033[1;0m" % logging.getLevelName(logging.DEBUG)) + logging.addLevelName( logging.INFO, "\033[1;32m%s\033[1;0m" % logging.getLevelName(logging.INFO)) + logging.addLevelName( logging.WARNING, "\033[1;33m%s\033[1;0m" % logging.getLevelName(logging.WARNING)) + logging.addLevelName( logging.ERROR, "\033[1;31m%s\033[1;0m" % logging.getLevelName(logging.ERROR)) + logging.addLevelName( logging.CRITICAL, "\033[1;41m%s\033[1;0m" % logging.getLevelName(logging.CRITICAL)) + + + # https://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output + #'DEBUG' : 37, # white + #'INFO' : 36, # cyan + #'WARNING' : 33, # yellow + #'ERROR' : 31, # red + #'CRITICAL': 41, # white on red bg + + + #--------------------------------------------START CMD SERVER + logging.info("SRV | STARTING TCP/IP SOCKET ON PORT " + str(static.PORT)) try: socketserver.TCPServer.allow_reuse_address = True #https://stackoverflow.com/a/16641793 server = socketserver.TCPServer((static.HOST, static.PORT), tnc.TCPRequestHandler) server.serve_forever() finally: server.server_close() + + diff --git a/modem.py b/modem.py index 71191378..6a9dd11c 100644 --- a/modem.py +++ b/modem.py @@ -92,13 +92,12 @@ class RF(): # -------------- transmit audio twice - print("SEND SIGNALLING FRAME...................................") - print(ack_buffer) - self.stream_tx.write(bytes(txbuffer)) - print("........................................................") + logging.debug("SEND SIGNALLING FRAME " + str(ack_buffer)) self.stream_tx.write(bytes(txbuffer)) - print("...................................DONE!") + self.stream_tx.write(bytes(txbuffer)) + + static.ARQ_STATE = 'RECEIVING_DATA' #-------------------------------------------------------------------------------------------------------- @@ -248,7 +247,7 @@ class RF(): self.c_lib.freedv_rawdatarx.argtype = [ctypes.POINTER(ctypes.c_ubyte), data_bytes_out, data_in] # check if really neccessary nbytes = self.c_lib.freedv_rawdatarx(freedv_data, data_bytes_out, data_in) # demodulate audio - print(self.c_lib.freedv_get_rx_status(freedv_data)) + logging.debug(self.c_lib.freedv_get_rx_status(freedv_data)) #-------------STUCK IN SYNC DETECTOR @@ -267,7 +266,7 @@ class RF(): if stuck_in_sync_counter >= 66 and stuck_in_sync_10_counter >= 2: - logging.warning("modem stuck in sync") + logging.critical("modem stuck in sync") self.c_lib.freedv_set_sync(freedv_data, 0) #FORCE UNSYNC stuck_in_sync_counter = 0 stuck_in_sync_10_counter = 0 @@ -293,19 +292,19 @@ class RF(): #print("static.ARQ_RX_BURST_BUFFER.count(None) " + str(static.ARQ_RX_BURST_BUFFER.count(None))) if static.ARQ_RX_BURST_BUFFER.count(None) <= 1: - print("FULL BURST BUFFER ---> UNSYNC") + logging.debug("FULL BURST BUFFER ---> UNSYNC") self.c_lib.freedv_set_sync(freedv_data, 0) else: - print("---------------------------SIMULATED MISSING FRAME") + logging.critical("---------------------------SIMULATED MISSING FRAME") force = True else: - print("MODE: " + str(data_mode) + " DATA: " + str(bytes(data_bytes_out))) + logging.info("MODE: " + str(data_mode) + " DATA: " + str(bytes(data_bytes_out))) # DO UNSYNC AFTER LAST BURST by checking the frame numbers agains the total frames per burst if frame == n_frames_per_burst: - print("LAST FRAME ---> UNSYNC") + logging.debug("LAST FRAME ---> UNSYNC") self.c_lib.freedv_set_sync(freedv_data, 0) #FORCE UNSYNC @@ -330,25 +329,25 @@ class RF(): # BURST ACK if frametype == 60: - print("ACK RECEIVED....") + logging.debug("ACK RECEIVED....") arq.burst_ack_received() # FRAME ACK elif frametype == 61: - print("FRAME ACK RECEIVED....") + logging.debug("FRAME ACK RECEIVED....") arq.frame_ack_received() # FRAME RPT elif frametype == 62: - print("REPEAT REQUEST RECEIVED....") + logging.debug("REPEAT REQUEST RECEIVED....") arq.burst_rpt_received(signalling_bytes_out[:-2]) else: - print("OTHER FRAME: " + str(signalling_bytes_out[:-2])) + logging.debug("OTHER FRAME: " + str(signalling_bytes_out[:-2])) rxstatus = self.c_lib.freedv_get_rx_status(freedv_signalling) - print("ACK-" + str(rxstatus)) + logging.debug("ACK-" + str(rxstatus)) #print(rxstatus) if nbytes == static.FREEDV_SIGNALLING_BYTES_PER_FRAME or rxstatus == 10: self.c_lib.freedv_set_sync(freedv_signalling, 0) #FORCE UNSYNC diff --git a/static.py b/static.py index 0eb4d840..4fa71047 100644 --- a/static.py +++ b/static.py @@ -85,16 +85,16 @@ ARQ_ACK_PAYLOAD_PER_FRAME = 0 # PAYLOAD per ACK frame ARQ_ACK_RECEIVED = False # set to 1 if ACK received ARQ_RX_ACK_TIMEOUT = False # set to 1 if timeut reached -ARQ_RX_ACK_TIMEOUT_SECONDS = 4.0 #timeout for waiting for ACK frames +ARQ_RX_ACK_TIMEOUT_SECONDS = 5.0 #timeout for waiting for ACK frames ARQ_FRAME_ACK_RECEIVED = False # set to 1 if FRAME ACK received ARQ_RX_FRAME_TIMEOUT = False -ARQ_RX_FRAME_TIMEOUT_SECONDS = 4.0 +ARQ_RX_FRAME_TIMEOUT_SECONDS = 5.0 ARQ_RX_RPT_TIMEOUT = False -ARQ_RX_RPT_TIMEOUT_SECONDS = 4.0 +ARQ_RX_RPT_TIMEOUT_SECONDS = 5.0 ARQ_RPT_RECEIVED = False #indicate if RPT frame has been received ARQ_RPT_FRAMES = [] #buffer for frames which are requested to repeat