#1860 Resolves USB transfer buffer submit errors and resubmit error tracking. Synchronizes the submit transfers method so that multi-threaded access doesn't cause accounting errors. Ignores LIBUSB_ERROR_BUSY when (re)submitting due to accounting errors. Comments out several P25 unrecognized messaging loggers. (#1950)

Co-authored-by: sheirerd <sheirerd@ainfosec.com>
This commit is contained in:
Denny Sheirer
2024-08-21 03:27:44 -04:00
committed by GitHub
parent 142dd9d579
commit c3487411fb
2 changed files with 44 additions and 32 deletions

View File

@@ -672,7 +672,7 @@ public class P25P1DecoderState extends DecoderState implements IChannelEventList
} }
break; break;
default: default:
mLog.debug("Unrecognized AMBTC Opcode: " + ambtc.getHeader().getOpcode().name()); // mLog.debug("Unrecognized AMBTC Opcode: " + ambtc.getHeader().getOpcode().name());
break; break;
} }
} }
@@ -1486,13 +1486,13 @@ public class P25P1DecoderState extends DecoderState implements IChannelEventList
case MOTOROLA_OSP_QUEUED_RESPONSE: case MOTOROLA_OSP_QUEUED_RESPONSE:
processTSBKQueuedResponse(tsbk); processTSBKQueuedResponse(tsbk);
default: default:
if(!tsbk.getOpcode().name().startsWith("ISP")) // if(!tsbk.getOpcode().name().startsWith("ISP"))
{ // {
LOGGING_SUPPRESSOR.info(tsbk.getOpcode().name() + tsbk.getMessage().toHexString(), // LOGGING_SUPPRESSOR.info(tsbk.getOpcode().name() + tsbk.getMessage().toHexString(),
1, "Unrecognized TSBK Opcode: " + tsbk.getOpcode().name() + // 1, "Unrecognized TSBK Opcode: " + tsbk.getOpcode().name() +
" VENDOR:" + tsbk.getVendor() + " OPCODE:" + tsbk.getOpcodeNumber() + // " VENDOR:" + tsbk.getVendor() + " OPCODE:" + tsbk.getOpcodeNumber() +
" MSG:" + tsbk.getMessage().toHexString()); // " MSG:" + tsbk.getMessage().toHexString());
} // }
break; break;
} }
} }
@@ -2164,10 +2164,10 @@ public class P25P1DecoderState extends DecoderState implements IChannelEventList
{ {
closeCurrentCallEvent(timestamp); closeCurrentCallEvent(timestamp);
} }
LOGGING_SUPPRESSOR.info(lcw.getVendor().toString() + lcw.getOpcodeNumber() + lcw.getMessage().toHexString(), // LOGGING_SUPPRESSOR.info(lcw.getVendor().toString() + lcw.getOpcodeNumber() + lcw.getMessage().toHexString(),
1, "Unrecognized LCW Opcode: " + lcw.getOpcode().name() + " VENDOR:" + lcw.getVendor() + // 1, "Unrecognized LCW Opcode: " + lcw.getOpcode().name() + " VENDOR:" + lcw.getVendor() +
" OPCODE:" + lcw.getOpcodeNumber() + " MSG:" + lcw.getMessage().toHexString() + // " OPCODE:" + lcw.getOpcodeNumber() + " MSG:" + lcw.getMessage().toHexString() +
" CHAN:" + getCurrentChannel() + " FREQ:" + getCurrentFrequency()); // " CHAN:" + getCurrentChannel() + " FREQ:" + getCurrentFrequency());
break; break;
} }
} }

View File

@@ -1,6 +1,6 @@
/* /*
* ***************************************************************************** * *****************************************************************************
* Copyright (C) 2014-2023 Dennis Sheirer * Copyright (C) 2014-2024 Dennis Sheirer
* *
* This program is free software: you can redistribute it and/or modify * This program is free software: you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by * it under the terms of the GNU General Public License as published by
@@ -588,9 +588,14 @@ public abstract class USBTunerController extends TunerController
/** /**
* (Re)Submits the transfer for stream processing * (Re)Submits the transfer for stream processing
*
* Note: synchronized used here because there can be multiple threads can invoke LibUsb.handleTimeoutEvents
* (scheduled thread pool and a dedicated shutdown thread) during tuner shutdown and this has caused transfer
* tracking issues.
*
* @param transfer to (re)submit * @param transfer to (re)submit
*/ */
private void submitTransfer(Transfer transfer) private synchronized void submitTransfer(Transfer transfer)
{ {
int status = LibUsb.submitTransfer(transfer); int status = LibUsb.submitTransfer(transfer);
@@ -616,35 +621,34 @@ public abstract class USBTunerController extends TunerController
mAvailableTransfers.size() + "]"); mAvailableTransfers.size() + "]");
} }
} }
else if(resubmitStatus == LibUsb.ERROR_BUSY)
{
//Ignore - this indicates the transfer was previously submitted and libusb is still working it.
}
else else
{ {
//Add it back to the queue to try again later.
mErrorTransfers.add(transfer); mErrorTransfers.add(transfer);
mTransferErrorCount++; mTransferErrorCount++;
//Only log this if more than half of the total transfer buffers are in error-holding
if(mErrorTransfers.size() >= (mAvailableTransfers.size() / 2))
{
mLog.error("Attempt to resubmit previous error USB transfer buffer failed with status [" +
LibUsb.errorName(resubmitStatus) + "] - this may be temporary and has happened [" +
mTransferErrorCount + "] times so far. Transfer buffer holding queue (error/total) [" +
mErrorTransfers.size() + "/" + mAvailableTransfers.size() + "]");
}
} }
} }
} }
else if(status == LibUsb.ERROR_BUSY)
{
//Ignore - this indicates the transfer was previously submitted and libusb is still working it. I'm not
//sure how this happens because we give libusb a transfer and it hands it back when it's full. If
//libusb is still working it, then why did it indicate the transfer was completed? So, we simply
//ignore this error code. Other libraries simply ignore the submit status code altogether.
}
else else
{ {
mLog.error("USB transfer [" + transfer + "] submit attempt failed with error [" + LibUsb.errorName(status) +
"] - adding to error queue to resubmit later - this may be a temporary USB issue and has happened [" +
mTransferErrorCount + "] time(s) so far. Current transfer error queue (error/total) [" +
mErrorTransfers.size() + "/" + mAvailableTransfers.size() + "]");
mErrorTransfers.add(transfer); mErrorTransfers.add(transfer);
mTransferErrorCount++; mTransferErrorCount++;
//Only log this if more than half of the total transfer buffers are in error-holding
if(mErrorTransfers.size() >= (mAvailableTransfers.size() / 2))
{
mLog.error("Attempt to submit USB transfer buffer failed with status [" +
LibUsb.errorName(status) + "] - this may be temporary and has happened [" +
mTransferErrorCount + "] time(s) so far. Transfer buffer holding queue (error/total) [" +
mErrorTransfers.size() + "/" + mAvailableTransfers.size() + "]");
}
} }
if(mErrorTransfers.size() >= mAvailableTransfers.size()) if(mErrorTransfers.size() >= mAvailableTransfers.size())
@@ -703,6 +707,14 @@ public abstract class USBTunerController extends TunerController
{ {
mInProgressTransfers.remove(transfer); mInProgressTransfers.remove(transfer);
if(mErrorTransfers.contains(transfer))
{
mLog.warn("USB transfer [" + transfer + "] that was being tracked as an error transfer, has just been " +
"delivered as completed with transfer status [" + LibUsb.errorName(transfer.status()) +
"] - removing it from the transfer error queue");
mErrorTransfers.remove(transfer);
}
switch(transfer.status()) switch(transfer.status())
{ {
case LibUsb.TRANSFER_COMPLETED: case LibUsb.TRANSFER_COMPLETED: