improved logging

now with colors and timestamps...
This commit is contained in:
DJ2LS 2021-02-10 19:43:59 +01:00 committed by GitHub
parent be7bc9744f
commit 63628f56d3
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
5 changed files with 113 additions and 75 deletions

79
arq.py
View file

@ -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

View file

@ -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

56
main.py
View file

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

View file

@ -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

View file

@ -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