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

logging improvements

Browse source 
..and also a sample rate conversion test...
This commit is contained in:
DJ2LS 2021-11-19 14:52:58 +01:00
parent c64035c68e
commit 279fe7929f
3 changed files with 52 additions and 29 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

17
gui/preload-main.js
View file

@ -508,8 +508,8 @@ ipcRenderer.on('action-update-tnc-state', (event, arg) => {
type: 'linear',
position: 'bottom',
display: true,
min: -40,
max: 40,
min: -80,
max: 80,
ticks: {
display: false
}
@ -517,8 +517,8 @@ ipcRenderer.on('action-update-tnc-state', (event, arg) => {
y: {
display: true,
min: -40,
max: 40,
min: -80,
max: 80,
ticks: {
display: false,
}
@ -727,14 +727,17 @@ ipcRenderer.on('action-update-tnc-state', (event, arg) => {
var dataType = document.createElement("td");
var dataTypeText = document.createElement('span');
dataTypeText.innerText = arg.stations[i]['DATATYPE']
dataType.appendChild(dataTypeText);
if(arg.stations[i]['DATATYPE'] == 'DATA-CHANNEL'){
dataTypeText.innerText = 'DATA-C'
dataType.appendChild(dataTypeText);
}
if (dataTypeText.innerText == 'CQ CQ CQ') {
row.classList.add("table-success");
}
if (dataTypeText.innerText == 'DATA-CHANNEL') {
if (dataTypeText.innerText == 'DATA-C') {
row.classList.add("table-warning");
}

51
tnc/data_handler.py
View file

@ -147,6 +147,7 @@ def arq_data_received(data_in, bytes_per_frame):
# improve transfer rate
if static.RX_BURST_BUFFER.count(None) == 1 and RX_N_FRAMES_PER_DATA_FRAME != RX_N_FRAME_OF_DATA_FRAME : # count nones
logging.info("ARQ | TX | BURST ACK")
structlog.get_logger("structlog").info("[TNC] ARQ TX BURST ACK")
# BUILDING ACK FRAME FOR BURST -----------------------------------------------
ack_frame = bytearray(14)
@ -180,8 +181,7 @@ def arq_data_received(data_in, bytes_per_frame):
frame_number = frame_number.to_bytes(2, byteorder='big')
missing_frames += frame_number
logging.warning("ARQ | TX | RPT ARQ FRAMES [" + str(missing_frames) + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").warning("[TNC] ARQ RPT FRAMES", snr=static.SNR, frames=missing_frames)
# BUILDING RPT FRAME FOR BURST -----------------------------------------------
rpt_frame = bytearray(14)
rpt_frame[:1] = bytes([62])
@ -237,7 +237,7 @@ def arq_data_received(data_in, bytes_per_frame):
# IF THE FRAME PAYLOAD CRC IS EQUAL TO THE FRAME CRC WHICH IS KNOWN FROM THE HEADER --> SUCCESS
if frame_payload_crc == data_frame_crc:
static.INFO.append("ARQ;RECEIVING;SUCCESS")
logging.log(25, "ARQ | RX | DATA FRAME SUCESSFULLY RECEIVED! :-) ")
structlog.get_logger("structlog").info("[TNC] DATA FRAME SUCESSFULLY RECEIVED")
calculate_transfer_rate_rx(RX_N_FRAMES_PER_DATA_FRAME, RX_N_FRAME_OF_DATA_FRAME, RX_START_OF_TRANSMISSION, RX_PAYLOAD_PER_ARQ_FRAME)
# decode to utf-8 string
@ -263,8 +263,7 @@ def arq_data_received(data_in, bytes_per_frame):
ack_frame[2:3] = static.MYCALLSIGN_CRC8
# TRANSMIT ACK FRAME FOR BURST-----------------------------------------------
logging.info("ARQ | TX | ARQ DATA FRAME ACK [" + str(data_frame_crc.hex()) + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] ARQ DATA FRAME ACK", snr=static.SNR, crc=data_frame_crc.hex())
# since simultaneous decoding it seems, we don't have to wait anymore
# however, we will wait a little bit for easier ptt debugging
# possibly we can remove this later
@ -283,8 +282,7 @@ def arq_data_received(data_in, bytes_per_frame):
static.RX_BURST_BUFFER = []
static.RX_FRAME_BUFFER = []
logging.info("DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]<< >>[" + str(static.DXCALLSIGN, 'utf-8') + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]<< >>[" + str(static.DXCALLSIGN, 'utf-8') + "]", snr=static.SNR)
else:
structlog.get_logger("structlog").debug("[TNC] ARQ: ", ARQ_FRAME_BOF_RECEIVED=RX_FRAME_BOF_RECEIVED, ARQ_FRAME_EOF_RECEIVED=RX_FRAME_EOF_RECEIVED )
@ -361,8 +359,8 @@ def arq_transmit(data_out, mode, n_frames_per_burst):
TX_BUFFER = [data_out[i:i + TX_PAYLOAD_PER_ARQ_FRAME] for i in range(0, len(data_out), TX_PAYLOAD_PER_ARQ_FRAME)]
TX_BUFFER_SIZE = len(TX_BUFFER)
static.INFO.append("ARQ;TRANSMITTING")
logging.info("ARQ | TX | M:" + str(DATA_CHANNEL_MODE) + " | DATA FRAME --- BYTES: " + str(len(data_out)) + " ARQ FRAMES: " + str(TX_BUFFER_SIZE))
structlog.get_logger("structlog").info("[TNC] ARQ TX DATA", mode=DATA_CHANNEL_MODE, bytes=len(data_out), frames=TX_BUFFER_SIZE)
# ----------------------- THIS IS THE MAIN LOOP-----------------------------------------------------------------
@ -391,7 +389,12 @@ def arq_transmit(data_out, mode, n_frames_per_burst):
if TX_N_SENT_FRAMES + 1 <= TX_BUFFER_SIZE:
calculate_transfer_rate_tx(TX_N_SENT_FRAMES, TX_PAYLOAD_PER_ARQ_FRAME, TX_START_OF_TRANSMISSION, TX_BUFFER_SIZE)
logging.log(24, "ARQ | TX | M:" + str(DATA_CHANNEL_MODE) + " | F:[" + str(TX_N_SENT_FRAMES + 1) + "-" + str(TX_N_SENT_FRAMES + TX_N_FRAMES_PER_BURST) + "] | T:[" + str(TX_N_SENT_FRAMES) + "/" + str(TX_BUFFER_SIZE) + "] [" + str(int(static.ARQ_TRANSMISSION_PERCENT)).zfill(3) + "%] | A:[" + str(TX_N_RETRIES_PER_BURST + 1) + "/" + str(TX_N_MAX_RETRIES_PER_BURST) + "]")
frame_progress = str(TX_N_SENT_FRAMES + 1) + "-" + str(TX_N_SENT_FRAMES + TX_N_FRAMES_PER_BURST)
total_frame_progress = str(TX_N_SENT_FRAMES) + "/" + str(TX_BUFFER_SIZE)
transmission_percent = str(static.ARQ_TRANSMISSION_PERCENT).zfill(3)
transmission_attempts = str(TX_N_RETRIES_PER_BURST + 1) + "/" + str(TX_N_MAX_RETRIES_PER_BURST)
structlog.get_logger("structlog").info("[TNC] ARQ TX DATA", mode=DATA_CHANNEL_MODE, frames=frame_progress, percent=transmission_percent, frames_total=total_frame_progress, attempt=transmission_attempts)
# lets refresh all timers and ack states before sending a new frame
arq_reset_ack(False)
@ -679,7 +682,9 @@ async def arq_open_data_channel(mode):
for attempt in range(1,DATA_CHANNEL_MAX_RETRIES+1):
static.INFO.append("DATACHANNEL;OPENING")
logging.info("DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>> <<[" + str(static.DXCALLSIGN, 'utf-8') + "] A:[" + str(attempt) + "/" + str(DATA_CHANNEL_MAX_RETRIES) + "]")
attempt = str(attempt) + "/" + str(DATA_CHANNEL_MAX_RETRIES)
structlog.get_logger("structlog").info("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>> <<[" + str(static.DXCALLSIGN, 'utf-8') + "]", attempt=attempt)
while not modem.transmit_signalling(connection_frame, 1):
time.sleep(0.01)
@ -691,11 +696,11 @@ async def arq_open_data_channel(mode):
break
if DATA_CHANNEL_READY_FOR_DATA:
break
print("attempt:" + str(attempt) + "/" + str(DATA_CHANNEL_MAX_RETRIES))
if not DATA_CHANNEL_READY_FOR_DATA and attempt == DATA_CHANNEL_MAX_RETRIES:
static.INFO.append("DATACHANNEL;FAILED")
logging.info("DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>X<<[" + str(static.DXCALLSIGN, 'utf-8') + "]")
structlog.get_logger("structlog").warning("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>X<<[" + str(static.DXCALLSIGN, 'utf-8') + "]")
static.TNC_STATE = 'IDLE'
static.ARQ_STATE = 'IDLE'
sys.exit() # close thread and so connection attempts
@ -711,7 +716,8 @@ def arq_received_data_channel_opener(data_in):
static.DXCALLSIGN = bytes(data_in[3:9]).rstrip(b'\x00')
helpers.add_to_heard_stations(static.DXCALLSIGN,static.DXGRID, 'DATA-CHANNEL', static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
logging.info("DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>> <<[" + str(static.DXCALLSIGN, 'utf-8') + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>> <<[" + str(static.DXCALLSIGN, 'utf-8') + "]")
static.ARQ_STATE = 'DATA'
static.TNC_STATE = 'BUSY'
@ -729,8 +735,8 @@ def arq_received_data_channel_opener(data_in):
while not modem.transmit_signalling(connection_frame, 1):
time.sleep(0.01)
logging.info("DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>|<<[" + str(static.DXCALLSIGN, 'utf-8') + "] [M:"+str(mode)+"] SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>|<<[" + str(static.DXCALLSIGN, 'utf-8') + "]", snr=static.SNR, mode=mode)
static.CHANNEL_STATE = 'RECEIVING_DATA'
# and now we are going to "RECEIVING_DATA" mode....
@ -751,7 +757,7 @@ def arq_received_channel_is_open(data_in):
# we are doing a mode check here, but this doesn't seem to be necessary since we have simultaneous decoding
# we are forcing doing a transmission at the moment --> see else statement
if DATA_CHANNEL_MODE == int.from_bytes(bytes(data_in[12:13]), "big"):
logging.info("DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>|<<[" + str(static.DXCALLSIGN, 'utf-8') + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>|<<[" + str(static.DXCALLSIGN, 'utf-8') + "]", snr=static.SNR)
# wait a little bit so other station is ready ( PTT toggle )
print("wait.....")
@ -763,7 +769,7 @@ def arq_received_channel_is_open(data_in):
DATA_CHANNEL_READY_FOR_DATA = True
DATA_CHANNEL_LAST_RECEIVED = int(time.time())
else:
print("wrong mode received...")
structlog.get_logger("structlog").info("[TNC] DATA [" + str(static.MYCALLSIGN, 'utf-8') + "]>>|<<[" + str(static.DXCALLSIGN, 'utf-8') + "]", snr=static.SNR, info="wrong mode rcvd")
helpers.wait(0.5)
# as soon as we set ARQ_STATE to DATA, transmission starts
static.ARQ_STATE = 'DATA'
@ -779,8 +785,7 @@ def transmit_ping(callsign):
static.DXCALLSIGN_CRC8 = helpers.get_crc_8(static.DXCALLSIGN)
static.INFO.append("PING;SENDING")
logging.info("PING [" + str(static.MYCALLSIGN, 'utf-8') + "] >>> [" + str(static.DXCALLSIGN, 'utf-8') + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] PING REQ [" + str(static.MYCALLSIGN, 'utf-8') + "] >>> [" + str(static.DXCALLSIGN, 'utf-8') + "]" )
ping_frame = bytearray(14)
ping_frame[:1] = bytes([210])
@ -800,7 +805,8 @@ def received_ping(data_in, frequency_offset):
helpers.add_to_heard_stations(static.DXCALLSIGN,static.DXGRID, 'PING', static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
static.INFO.append("PING;RECEIVING")
logging.info("PING [" + str(static.MYCALLSIGN, 'utf-8') + "] <<< [" + str(static.DXCALLSIGN, 'utf-8') + "] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] PING REQ [" + str(static.MYCALLSIGN, 'utf-8') + "] <<< [" + str(static.DXCALLSIGN, 'utf-8') + "]", snr=static.SNR )
ping_frame = bytearray(14)
ping_frame[:1] = bytes([211])
@ -822,7 +828,8 @@ def received_ping_ack(data_in):
helpers.add_to_heard_stations(static.DXCALLSIGN,static.DXGRID, 'PING-ACK', static.SNR, static.FREQ_OFFSET, static.HAMLIB_FREQUENCY)
static.INFO.append("PING;RECEIVEDACK")
logging.info("PING [" + str(static.MYCALLSIGN, 'utf-8') + "] >|< [" + str(static.DXCALLSIGN, 'utf-8') + "]["+ str(static.DXGRID, 'utf-8') +"] [SNR:" + str(static.SNR) + "]")
structlog.get_logger("structlog").info("[TNC] PING ACK [" + str(static.MYCALLSIGN, 'utf-8') + "] >|< [" + str(static.DXCALLSIGN, 'utf-8') + "]", snr=static.SNR )
static.TNC_STATE = 'IDLE'
# ############################################################################################################
@ -850,7 +857,7 @@ def received_cq(data_in):
dxcallsign = bytes(data_in[2:8]).rstrip(b'\x00')
dxgrid = bytes(data_in[8:14]).rstrip(b'\x00')
static.INFO.append("CQ;RECEIVING")
logging.info("CQ RCVD [" + str(dxcallsign, 'utf-8') + "]["+ str(dxgrid, 'utf-8') +"] [SNR" + str(static.SNR) + "]")
structlog.get_logger("structlog").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)

13
tnc/modem.py
View file

@ -21,6 +21,10 @@ import static
import data_handler
import re
# option for testing miniaudio instead of audioop for sample rate conversion
#import miniaudio
####################################################
# https://stackoverflow.com/questions/7088672/pyaudio-working-but-spits-out-error-messages-each-time
# https://github.com/DJ2LS/FreeDATA/issues/22
@ -314,7 +318,14 @@ class RF():
self.streambuffer += bytes(mod_out_postamble)
converted_audio = audioop.ratecv(self.streambuffer, 2, 1, self.MODEM_SAMPLE_RATE, self.AUDIO_SAMPLE_RATE_TX, None)
#self.streambuffer = bytes(converted_audio[0])
#converted_audio_miniaudio = miniaudio.convert_frames(miniaudio.SampleFormat.SIGNED16, 1, 8000, bytes(self.streambuffer), miniaudio.SampleFormat.SIGNED16, 1, 48000)
self.streambuffer = bytes(converted_audio[0])
#self.streambuffer += bytes(converted_audio_miniaudio)
# append frame again with as much as in count defined
for i in range(1, count):
@ -505,6 +516,8 @@ class RF():
data_in = audioop.ratecv(data_in, 2, 1, self.AUDIO_SAMPLE_RATE_RX, self.MODEM_SAMPLE_RATE, None)
data_in = data_in[0] # .rstrip(b'\x00')
#data_in = miniaudio.convert_frames(miniaudio.SampleFormat.SIGNED16, 1, 48000, bytes(data_in), miniaudio.SampleFormat.SIGNED16, 1, 8000)
# we need to set nin * 2 beause of byte size in array handling
datac0_nin = self.c_lib.freedv_nin(datac0_freedv) * 2
datac1_nin = self.c_lib.freedv_nin(datac1_freedv) * 2