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

improved logging

Browse source
This commit is contained in:
dj2ls 2022-01-04 14:45:30 +01:00
parent 6bcbfaf6ed
commit 16deb1df6d
2 changed files with 26 additions and 23 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

17
tnc/data_handler.py
View file

@ -193,13 +193,13 @@ def arq_data_received(data_in:bytes, bytes_per_frame:int, snr:int):
crc = checksum crc = checksum
''' '''
if rawdata["dt"] == "f": if rawdata["dt"] == "f":
#logging.debug("RECEIVED FILE --> MOVING DATA TO RX BUFFER") #structlog.get_logger("structlog").debug("RECEIVED FILE --> MOVING DATA TO RX BUFFER")
static.RX_BUFFER.append([static.DXCALLSIGN,static.DXGRID,int(time.time()), data_frame]) static.RX_BUFFER.append([static.DXCALLSIGN,static.DXGRID,int(time.time()), data_frame])
# if datatype is a file, we append to RX_MSG_BUFFER, which contains messages only # if datatype is a file, we append to RX_MSG_BUFFER, which contains messages only
if rawdata["dt"] == "m": if rawdata["dt"] == "m":
static.RX_MSG_BUFFER.append([static.DXCALLSIGN,static.DXGRID,int(time.time()), complete_data_frame]) static.RX_MSG_BUFFER.append([static.DXCALLSIGN,static.DXGRID,int(time.time()), complete_data_frame])
#logging.debug("RECEIVED MESSAGE --> MOVING DATA TO MESSAGE BUFFER") #structlog.get_logger("structlog").debug("RECEIVED MESSAGE --> MOVING DATA TO MESSAGE BUFFER")
# BUILDING ACK FRAME FOR DATA FRAME # BUILDING ACK FRAME FOR DATA FRAME
@ -283,8 +283,8 @@ def arq_transmit(data_out:bytes, mode:int, n_frames_per_burst:int):
bufferposition = 0 bufferposition = 0
# iterate through data out buffer # iterate through data out buffer
while bufferposition < len(data_out) and not DATA_FRAME_ACK_RECEIVED and static.ARQ_STATE: while bufferposition < len(data_out) and not DATA_FRAME_ACK_RECEIVED and static.ARQ_STATE:
print(DATA_FRAME_ACK_RECEIVED)
structlog.get_logger("structlog").debug("DATA_FRAME_ACK_RECEIVED", state=DATA_FRAME_ACK_RECEIVED)
# we have TX_N_MAX_RETRIES_PER_BURST attempts for sending a burst # we have TX_N_MAX_RETRIES_PER_BURST attempts for sending a burst
for TX_N_RETRIES_PER_BURST in range(0,TX_N_MAX_RETRIES_PER_BURST): for TX_N_RETRIES_PER_BURST in range(0,TX_N_MAX_RETRIES_PER_BURST):
@ -294,7 +294,8 @@ def arq_transmit(data_out:bytes, mode:int, n_frames_per_burst:int):
# force usage of selected mode # force usage of selected mode
if mode != 255: if mode != 255:
data_mode = mode data_mode = mode
print(f"selecting fixed mode {data_mode}") structlog.get_logger("structlog").debug("FIXED MODE", mode=data_mode)
else: else:
# at beginnign of transmission try fastest mode # at beginnign of transmission try fastest mode
if bufferposition == 0: if bufferposition == 0:
@ -302,12 +303,12 @@ def arq_transmit(data_out:bytes, mode:int, n_frames_per_burst:int):
# if we have a reduced SNR OR its the second attempt of sending data, select slower mode # if we have a reduced SNR OR its the second attempt of sending data, select slower mode
if BURST_ACK_SNR < 10 or TX_N_RETRIES_PER_BURST >= 2: if BURST_ACK_SNR < 10 or TX_N_RETRIES_PER_BURST >= 2:
data_mode = 12 data_mode = 12
print(f"selecting auto mode {data_mode}") structlog.get_logger("structlog").debug("AUTO MODE", mode=data_mode)
# if we have (again) a high SNR and our attmepts are 0, then switch back to a faster mode # if we have (again) a high SNR and our attmepts are 0, then switch back to a faster mode
if BURST_ACK_SNR < 20 and TX_N_RETRIES_PER_BURST == 0: if BURST_ACK_SNR < 20 and TX_N_RETRIES_PER_BURST == 0:
data_mode = 10 data_mode = 10
print(f"selecting auto mode {data_mode}") structlog.get_logger("structlog").debug("FIXED MODE", mode=data_mode)
# payload information # payload information
@ -374,7 +375,7 @@ def arq_transmit(data_out:bytes, mode:int, n_frames_per_burst:int):
# NEXT ATTEMPT # NEXT ATTEMPT
print(f"ATTEMPT {TX_N_RETRIES_PER_BURST}/{TX_N_MAX_RETRIES_PER_BURST}") structlog.get_logger("structlog").debug("ATTEMPT", retry=TX_N_RETRIES_PER_BURST, maxretries=TX_N_MAX_RETRIES_PER_BURST)
# update buffer position # update buffer position
bufferposition = bufferposition_end bufferposition = bufferposition_end
@ -428,7 +429,7 @@ def burst_ack_received(data_in:bytes):
BURST_ACK_RECEIVED = True # Force data loops of TNC to stop and continue with next frame BURST_ACK_RECEIVED = True # Force data loops of TNC to stop and continue with next frame
DATA_CHANNEL_LAST_RECEIVED = int(time.time()) # we need to update our timeout timestamp DATA_CHANNEL_LAST_RECEIVED = int(time.time()) # we need to update our timeout timestamp
BURST_ACK_SNR = int.from_bytes(bytes(data_in[3:4]), "big") BURST_ACK_SNR = int.from_bytes(bytes(data_in[3:4]), "big")
print(BURST_ACK_SNR)
def frame_ack_received(): def frame_ack_received():
global DATA_FRAME_ACK_RECEIVED global DATA_FRAME_ACK_RECEIVED

32
tnc/modem.py
View file

@ -288,7 +288,9 @@ class RF():
# if data is shorter than the expcected audio frames per buffer we need to append 0 # if data is shorter than the expcected audio frames per buffer we need to append 0
# to prevent the callback from stucking/crashing # to prevent the callback from stucking/crashing
if len(c) < self.AUDIO_FRAMES_PER_BUFFER_RX*2: if len(c) < self.AUDIO_FRAMES_PER_BUFFER_RX*2:
c += bytes(self.AUDIO_FRAMES_PER_BUFFER_RX*2 - len(c)) delta = bytes(self.AUDIO_FRAMES_PER_BUFFER_RX*2 - len(c))
c += delta
structlog.get_logger("structlog").debug("[TNC] mod out shorter than audio buffer", delta=len(delta))
self.modoutqueue.put(c) self.modoutqueue.put(c)
# maybe we need to toggle PTT before craeting modulation because of queue processing # maybe we need to toggle PTT before craeting modulation because of queue processing
@ -302,10 +304,10 @@ class RF():
def audio(self): def audio(self):
try: try:
print(f"starting pyaudio callback", file=sys.stderr) structlog.get_logger("structlog").debug("[TNC] starting pyaudio callback")
self.audio_stream.start_stream() self.audio_stream.start_stream()
except Exception as e: except Exception as e:
print(f"pyAudio error: {e}", file=sys.stderr) structlog.get_logger("structlog").error("[TNC] starting pyaudio callback failed", e=e)
while self.audio_stream.is_active(): while self.audio_stream.is_active():
@ -377,45 +379,45 @@ class RF():
# get snr of received data # get snr of received data
snr = self.calculate_snr(freedv) snr = self.calculate_snr(freedv)
print(f"SNR - {snr}") structlog.get_logger("structlog").debug("[TNC] RX SNR", snr=snr)
# send payload data to arq checker without CRC16 # send payload data to arq checker without CRC16
data_handler.arq_data_received(bytes(bytes_out[:-2]), bytes_per_frame, snr) data_handler.arq_data_received(bytes(bytes_out[:-2]), bytes_per_frame, snr)
# if we received the last frame of a burst or the last remaining rpt frame, do a modem unsync # if we received the last frame of a burst or the last remaining rpt frame, do a modem unsync
if static.RX_BURST_BUFFER.count(None) <= 1 or (frame+1) == n_frames_per_burst: if static.RX_BURST_BUFFER.count(None) <= 1 or (frame+1) == n_frames_per_burst:
logging.debug(f"LAST FRAME OF BURST --> UNSYNC {frame+1}/{n_frames_per_burst}") structlog.get_logger("structlog").debug(f"LAST FRAME OF BURST --> UNSYNC {frame+1}/{n_frames_per_burst}")
self.c_lib.freedv_set_sync(freedv, 0) self.c_lib.freedv_set_sync(freedv, 0)
# BURST ACK # BURST ACK
elif frametype == 60: elif frametype == 60:
logging.debug("ACK RECEIVED....") structlog.get_logger("structlog").debug("ACK RECEIVED....")
data_handler.burst_ack_received(bytes_out[:-2]) data_handler.burst_ack_received(bytes_out[:-2])
# FRAME ACK # FRAME ACK
elif frametype == 61: elif frametype == 61:
logging.debug("FRAME ACK RECEIVED....") structlog.get_logger("structlog").debug("FRAME ACK RECEIVED....")
data_handler.frame_ack_received() data_handler.frame_ack_received()
# FRAME RPT # FRAME RPT
elif frametype == 62: elif frametype == 62:
logging.debug("REPEAT REQUEST RECEIVED....") structlog.get_logger("structlog").debug("REPEAT REQUEST RECEIVED....")
data_handler.burst_rpt_received(bytes_out[:-2]) data_handler.burst_rpt_received(bytes_out[:-2])
# FRAME NACK # FRAME NACK
elif frametype == 63: elif frametype == 63:
logging.debug("FRAME NOT ACK RECEIVED....") structlog.get_logger("structlog").debug("FRAME NOT ACK RECEIVED....")
data_handler.frame_nack_received(bytes_out[:-2]) data_handler.frame_nack_received(bytes_out[:-2])
# CQ FRAME # CQ FRAME
elif frametype == 200: elif frametype == 200:
logging.debug("CQ RECEIVED....") structlog.get_logger("structlog").debug("CQ RECEIVED....")
data_handler.received_cq(bytes_out[:-2]) data_handler.received_cq(bytes_out[:-2])
# PING FRAME # PING FRAME
elif frametype == 210: elif frametype == 210:
logging.debug("PING RECEIVED....") structlog.get_logger("structlog").debug("PING RECEIVED....")
frequency_offset = self.get_frequency_offset(freedv) frequency_offset = self.get_frequency_offset(freedv)
#print("Freq-Offset: " + str(frequency_offset)) #print("Freq-Offset: " + str(frequency_offset))
data_handler.received_ping(bytes_out[:-2], frequency_offset) data_handler.received_ping(bytes_out[:-2], frequency_offset)
@ -423,7 +425,7 @@ class RF():
# PING ACK # PING ACK
elif frametype == 211: elif frametype == 211:
logging.debug("PING ACK RECEIVED....") structlog.get_logger("structlog").debug("PING ACK RECEIVED....")
# early detection of frequency offset # early detection of frequency offset
#frequency_offset = int.from_bytes(bytes(bytes_out[9:11]), "big", signed=True) #frequency_offset = int.from_bytes(bytes(bytes_out[9:11]), "big", signed=True)
#print("Freq-Offset: " + str(frequency_offset)) #print("Freq-Offset: " + str(frequency_offset))
@ -438,18 +440,18 @@ class RF():
# ARQ FILE TRANSFER RECEIVED! # ARQ FILE TRANSFER RECEIVED!
elif frametype == 225: elif frametype == 225:
logging.debug("ARQ arq_received_data_channel_opener") structlog.get_logger("structlog").debug("ARQ arq_received_data_channel_opener")
data_handler.arq_received_data_channel_opener(bytes_out[:-2]) data_handler.arq_received_data_channel_opener(bytes_out[:-2])
# ARQ CHANNEL IS OPENED # ARQ CHANNEL IS OPENED
elif frametype == 226: elif frametype == 226:
logging.debug("ARQ arq_received_channel_is_open") structlog.get_logger("structlog").debug("ARQ arq_received_channel_is_open")
data_handler.arq_received_channel_is_open(bytes_out[:-2]) data_handler.arq_received_channel_is_open(bytes_out[:-2])
# ARQ CONNECT ACK / KEEP ALIVE # ARQ CONNECT ACK / KEEP ALIVE
# this is outdated and we may remove it # this is outdated and we may remove it
elif frametype == 230: elif frametype == 230:
logging.debug("BEACON RECEIVED") structlog.get_logger("structlog").debug("BEACON RECEIVED")
data_handler.received_beacon(bytes_out[:-2]) data_handler.received_beacon(bytes_out[:-2])
# TESTFRAMES # TESTFRAMES