Removed verbose logging that was added for debugging.

This commit is contained in:
akwizgran
2012-12-07 15:21:32 +00:00
parent c4bf931b80
commit 90978fa9c6
4 changed files with 16 additions and 92 deletions

View File

@@ -1,21 +1,15 @@
package net.sf.briar.plugins.modem; package net.sf.briar.plugins.modem;
import static java.util.logging.Level.INFO;
import java.io.IOException; import java.io.IOException;
import java.util.Comparator; import java.util.Comparator;
import java.util.Iterator; import java.util.Iterator;
import java.util.SortedSet; import java.util.SortedSet;
import java.util.TreeSet; import java.util.TreeSet;
import java.util.logging.Logger;
class Receiver implements ReadHandler { class Receiver implements ReadHandler {
static final int MAX_WINDOW_SIZE = 8 * Data.MAX_PAYLOAD_LENGTH; static final int MAX_WINDOW_SIZE = 8 * Data.MAX_PAYLOAD_LENGTH;
private static final Logger LOG =
Logger.getLogger(Receiver.class.getName());
private final Sender sender; private final Sender sender;
private final SortedSet<Data> dataFrames; // Locking: this private final SortedSet<Data> dataFrames; // Locking: this
@@ -33,24 +27,19 @@ class Receiver implements ReadHandler {
synchronized Data read() throws IOException, InterruptedException { synchronized Data read() throws IOException, InterruptedException {
while(valid) { while(valid) {
if(dataFrames.isEmpty()) { if(dataFrames.isEmpty()) {
if(LOG.isLoggable(INFO)) LOG.info("Waiting for a data frame"); // Wait for a data frame
wait(); wait();
} else { } else {
Data d = dataFrames.first(); Data d = dataFrames.first();
if(d.getSequenceNumber() == nextSequenceNumber) { if(d.getSequenceNumber() == nextSequenceNumber) {
if(LOG.isLoggable(INFO))
LOG.info("Reading #" + d.getSequenceNumber());
dataFrames.remove(d); dataFrames.remove(d);
// Update the window // Update the window
windowSize += d.getPayloadLength(); windowSize += d.getPayloadLength();
if(LOG.isLoggable(INFO))
LOG.info("Window at receiver " + windowSize);
sender.sendAck(0L, windowSize); sender.sendAck(0L, windowSize);
nextSequenceNumber++; nextSequenceNumber++;
return d; return d;
} else { } else {
if(LOG.isLoggable(INFO)) // Wait for the next in-order data frame
LOG.info("Waiting for #" + nextSequenceNumber);
wait(); wait();
} }
} }
@@ -76,62 +65,45 @@ class Receiver implements ReadHandler {
sender.handleAck(b); sender.handleAck(b);
break; break;
default: default:
if(LOG.isLoggable(INFO)) // Ignore unknown frame type
LOG.info("Ignoring unknown frame type: " + b[0]);
return; return;
} }
} }
private synchronized void handleData(byte[] b) throws IOException { private synchronized void handleData(byte[] b) throws IOException {
if(b.length < Data.MIN_LENGTH || b.length > Data.MAX_LENGTH) { if(b.length < Data.MIN_LENGTH || b.length > Data.MAX_LENGTH) {
if(LOG.isLoggable(INFO)) // Ignore data frame with invalid length
LOG.info("Ignoring data frame with invalid length");
return; return;
} }
Data d = new Data(b); Data d = new Data(b);
int payloadLength = d.getPayloadLength(); int payloadLength = d.getPayloadLength();
if(payloadLength > windowSize) { if(payloadLength > windowSize) return; // No space in the window
if(LOG.isLoggable(INFO)) LOG.info("No space in the window");
return;
}
if(d.getChecksum() != d.calculateChecksum()) { if(d.getChecksum() != d.calculateChecksum()) {
if(LOG.isLoggable(INFO)) // Ignore data frame with invalid checksum
LOG.info("Incorrect checksum on data frame");
return; return;
} }
long sequenceNumber = d.getSequenceNumber(); long sequenceNumber = d.getSequenceNumber();
if(sequenceNumber == 0L) { if(sequenceNumber == 0L) {
if(LOG.isLoggable(INFO)) LOG.info("Window probe"); // Window probe
} else if(sequenceNumber < nextSequenceNumber) { } else if(sequenceNumber < nextSequenceNumber) {
if(LOG.isLoggable(INFO)) LOG.info("Duplicate data frame"); // Duplicate data frame
} else if(d.isLastFrame()) { } else if(d.isLastFrame()) {
finalSequenceNumber = sequenceNumber; finalSequenceNumber = sequenceNumber;
// Remove any data frames with higher sequence numbers
Iterator<Data> it = dataFrames.iterator(); Iterator<Data> it = dataFrames.iterator();
while(it.hasNext()) { while(it.hasNext()) {
Data d1 = it.next(); Data d1 = it.next();
if(d1.getSequenceNumber() >= finalSequenceNumber) { if(d1.getSequenceNumber() >= finalSequenceNumber) it.remove();
if(LOG.isLoggable(INFO))
LOG.info("Received data frame after FIN");
it.remove();
}
} }
if(LOG.isLoggable(INFO)) LOG.info("Received #" + sequenceNumber);
if(dataFrames.add(d)) { if(dataFrames.add(d)) {
windowSize -= payloadLength; windowSize -= payloadLength;
if(LOG.isLoggable(INFO))
LOG.info("Window at receiver " + windowSize);
notifyAll(); notifyAll();
} }
} else if(sequenceNumber < finalSequenceNumber) { } else if(sequenceNumber < finalSequenceNumber) {
if(LOG.isLoggable(INFO)) LOG.info("Received #" + sequenceNumber);
if(dataFrames.add(d)) { if(dataFrames.add(d)) {
windowSize -= payloadLength; windowSize -= payloadLength;
if(LOG.isLoggable(INFO))
LOG.info("Window at receiver " + windowSize);
notifyAll(); notifyAll();
} }
} else {
if(LOG.isLoggable(INFO)) LOG.info("Received data frame after FIN");
} }
// Acknowledge the data frame even if it's a duplicate // Acknowledge the data frame even if it's a duplicate
sender.sendAck(sequenceNumber, windowSize); sender.sendAck(sequenceNumber, windowSize);

View File

@@ -1,6 +1,5 @@
package net.sf.briar.plugins.modem; package net.sf.briar.plugins.modem;
import static java.util.logging.Level.INFO;
import static java.util.logging.Level.WARNING; import static java.util.logging.Level.WARNING;
import java.io.IOException; import java.io.IOException;
@@ -44,15 +43,13 @@ class ReliabilityLayer implements ReadHandler, WriteHandler {
while(running) { while(running) {
byte[] b = writes.take(); byte[] b = writes.take();
if(b.length == 0) return; // Poison pill if(b.length == 0) return; // Poison pill
if(LOG.isLoggable(INFO))
LOG.info("Writing " + b.length + " bytes");
writeHandler.handleWrite(b); writeHandler.handleWrite(b);
} }
} catch(InterruptedException e) { } catch(InterruptedException e) {
if(LOG.isLoggable(WARNING)) if(LOG.isLoggable(WARNING))
LOG.warning("Interrupted while writing"); LOG.warning("Interrupted while writing");
running = false;
Thread.currentThread().interrupt(); Thread.currentThread().interrupt();
running = false;
} catch(IOException e) { } catch(IOException e) {
if(LOG.isLoggable(WARNING)) if(LOG.isLoggable(WARNING))
LOG.warning("Interrupted while writing"); LOG.warning("Interrupted while writing");
@@ -73,7 +70,6 @@ class ReliabilityLayer implements ReadHandler, WriteHandler {
} }
void stop() { void stop() {
if(LOG.isLoggable(INFO)) LOG.info("Stopping reliability layer");
running = false; running = false;
receiver.invalidate(); receiver.invalidate();
writes.add(new byte[0]); // Poison pill writes.add(new byte[0]); // Poison pill
@@ -82,14 +78,12 @@ class ReliabilityLayer implements ReadHandler, WriteHandler {
// The modem calls this method to pass data up to the SLIP decoder // The modem calls this method to pass data up to the SLIP decoder
public void handleRead(byte[] b) throws IOException { public void handleRead(byte[] b) throws IOException {
if(!running) throw new IOException("Connection closed"); if(!running) throw new IOException("Connection closed");
if(LOG.isLoggable(INFO)) LOG.info("Read " + b.length + " bytes");
decoder.handleRead(b); decoder.handleRead(b);
} }
// The SLIP encoder calls this method to pass data down to the modem // The SLIP encoder calls this method to pass data down to the modem
public void handleWrite(byte[] b) throws IOException { public void handleWrite(byte[] b) throws IOException {
if(!running) throw new IOException("Connection closed"); if(!running) throw new IOException("Connection closed");
if(LOG.isLoggable(INFO)) LOG.info("Queueing " + b.length + " bytes");
if(b.length > 0) writes.add(b); if(b.length > 0) writes.add(b);
} }
} }

View File

@@ -1,6 +1,5 @@
package net.sf.briar.plugins.modem; package net.sf.briar.plugins.modem;
import static java.util.logging.Level.INFO;
import static java.util.logging.Level.WARNING; import static java.util.logging.Level.WARNING;
import java.io.IOException; import java.io.IOException;
@@ -41,25 +40,17 @@ class Sender {
a.setSequenceNumber(sequenceNumber); a.setSequenceNumber(sequenceNumber);
a.setWindowSize(windowSize); a.setWindowSize(windowSize);
a.setChecksum(a.calculateChecksum()); a.setChecksum(a.calculateChecksum());
if(sequenceNumber == 0L) {
if(LOG.isLoggable(INFO)) LOG.info("Sending window update");
} else {
if(LOG.isLoggable(INFO))
LOG.info("Acknowledging #" + sequenceNumber);
}
writeHandler.handleWrite(a.getBuffer()); writeHandler.handleWrite(a.getBuffer());
} }
void handleAck(byte[] b) { void handleAck(byte[] b) {
if(b.length != Ack.LENGTH) { if(b.length != Ack.LENGTH) {
if(LOG.isLoggable(INFO)) // Ignore ack frame with invalid length
LOG.info("Ignoring ack frame with invalid length");
return; return;
} }
Ack a = new Ack(b); Ack a = new Ack(b);
if(a.getChecksum() != a.calculateChecksum()) { if(a.getChecksum() != a.calculateChecksum()) {
if(LOG.isLoggable(INFO)) // Ignore ack frame with invalid checksum
LOG.info("Incorrect checksum on ack frame");
return; return;
} }
long sequenceNumber = a.getSequenceNumber(); long sequenceNumber = a.getSequenceNumber();
@@ -72,8 +63,6 @@ class Sender {
for(int i = 0; it.hasNext(); i++) { for(int i = 0; it.hasNext(); i++) {
Outstanding o = it.next(); Outstanding o = it.next();
if(o.data.getSequenceNumber() == sequenceNumber) { if(o.data.getSequenceNumber() == sequenceNumber) {
if(LOG.isLoggable(INFO))
LOG.info("#" + sequenceNumber + " acknowledged");
it.remove(); it.remove();
outstandingBytes -= o.data.getPayloadLength(); outstandingBytes -= o.data.getPayloadLength();
foundIndex = i; foundIndex = i;
@@ -86,8 +75,6 @@ class Sender {
timeout = rtt + (rttVar << 2); timeout = rtt + (rttVar << 2);
if(timeout < MIN_TIMEOUT) timeout = MIN_TIMEOUT; if(timeout < MIN_TIMEOUT) timeout = MIN_TIMEOUT;
else if(timeout > MAX_TIMEOUT) timeout = MAX_TIMEOUT; else if(timeout > MAX_TIMEOUT) timeout = MAX_TIMEOUT;
if(LOG.isLoggable(INFO))
LOG.info("RTT " + rtt + ", timeout " + timeout);
} }
break; break;
} }
@@ -95,10 +82,6 @@ class Sender {
// If any older data frames are outstanding, retransmit the oldest // If any older data frames are outstanding, retransmit the oldest
if(foundIndex > 0) { if(foundIndex > 0) {
fastRetransmit = outstanding.poll(); fastRetransmit = outstanding.poll();
if(LOG.isLoggable(INFO)) {
LOG.info("Fast retransmitting #"
+ fastRetransmit.data.getSequenceNumber());
}
fastRetransmit.lastTransmitted = now; fastRetransmit.lastTransmitted = now;
fastRetransmit.retransmitted = true; fastRetransmit.retransmitted = true;
outstanding.add(fastRetransmit); outstanding.add(fastRetransmit);
@@ -108,7 +91,6 @@ class Sender {
int oldWindowSize = windowSize; int oldWindowSize = windowSize;
// Don't accept an unreasonably large window size // Don't accept an unreasonably large window size
windowSize = Math.min(a.getWindowSize(), Receiver.MAX_WINDOW_SIZE); windowSize = Math.min(a.getWindowSize(), Receiver.MAX_WINDOW_SIZE);
if(LOG.isLoggable(INFO)) LOG.info("Window at sender " + windowSize);
// If space has become available, notify any waiting writers // If space has become available, notify any waiting writers
if(windowSize > oldWindowSize || foundIndex != -1) notifyAll(); if(windowSize > oldWindowSize || foundIndex != -1) notifyAll();
} }
@@ -119,7 +101,7 @@ class Sender {
writeHandler.handleWrite(d.getBuffer()); writeHandler.handleWrite(d.getBuffer());
} catch(IOException e) { } catch(IOException e) {
// FIXME: Do something more meaningful // FIXME: Do something more meaningful
if(LOG.isLoggable(WARNING)) LOG.warning(e.toString()); if(LOG.isLoggable(WARNING)) LOG.log(WARNING, e.toString(), e);
} }
} }
} }
@@ -131,30 +113,21 @@ class Sender {
synchronized(this) { synchronized(this) {
if(outstanding.isEmpty()) { if(outstanding.isEmpty()) {
if(dataWaiting && now - lastWindowUpdateOrProbe > timeout) { if(dataWaiting && now - lastWindowUpdateOrProbe > timeout) {
if(LOG.isLoggable(INFO)) LOG.info("Sending window probe");
sendProbe = true; sendProbe = true;
timeout <<= 1; timeout <<= 1;
if(timeout > MAX_TIMEOUT) timeout = MAX_TIMEOUT; if(timeout > MAX_TIMEOUT) timeout = MAX_TIMEOUT;
if(LOG.isLoggable(INFO))
LOG.info("Increasing timeout to " + timeout);
} }
} else { } else {
Iterator<Outstanding> it = outstanding.iterator(); Iterator<Outstanding> it = outstanding.iterator();
while(it.hasNext()) { while(it.hasNext()) {
Outstanding o = it.next(); Outstanding o = it.next();
if(now - o.lastTransmitted > timeout) { if(now - o.lastTransmitted > timeout) {
if(LOG.isLoggable(INFO)) {
LOG.info("Retransmitting #"
+ o.data.getSequenceNumber());
}
it.remove(); it.remove();
if(retransmit == null) if(retransmit == null)
retransmit = new ArrayList<Outstanding>(); retransmit = new ArrayList<Outstanding>();
retransmit.add(o); retransmit.add(o);
timeout <<= 1; timeout <<= 1;
if(timeout > MAX_TIMEOUT) timeout = MAX_TIMEOUT; if(timeout > MAX_TIMEOUT) timeout = MAX_TIMEOUT;
if(LOG.isLoggable(INFO))
LOG.info("Increasing timeout to " + timeout);
} }
} }
if(retransmit != null) { if(retransmit != null) {
@@ -181,7 +154,7 @@ class Sender {
} }
} catch(IOException e) { } catch(IOException e) {
// FIXME: Do something more meaningful // FIXME: Do something more meaningful
if(LOG.isLoggable(WARNING)) LOG.warning(e.toString()); if(LOG.isLoggable(WARNING)) LOG.log(WARNING, e.toString(), e);
return; return;
} }
} }
@@ -189,9 +162,8 @@ class Sender {
void write(Data d) throws IOException, InterruptedException { void write(Data d) throws IOException, InterruptedException {
int payloadLength = d.getPayloadLength(); int payloadLength = d.getPayloadLength();
synchronized(this) { synchronized(this) {
// Wait for space in the window
while(outstandingBytes + payloadLength >= windowSize) { while(outstandingBytes + payloadLength >= windowSize) {
if(LOG.isLoggable(INFO))
LOG.info("Waiting for space in the window");
dataWaiting = true; dataWaiting = true;
wait(); wait();
} }
@@ -199,8 +171,6 @@ class Sender {
outstandingBytes += payloadLength; outstandingBytes += payloadLength;
dataWaiting = false; dataWaiting = false;
} }
if(LOG.isLoggable(INFO))
LOG.info("Transmitting #" + d.getSequenceNumber());
writeHandler.handleWrite(d.getBuffer()); writeHandler.handleWrite(d.getBuffer());
} }

View File

@@ -1,15 +1,9 @@
package net.sf.briar.plugins.modem; package net.sf.briar.plugins.modem;
import static java.util.logging.Level.INFO;
import java.io.IOException; import java.io.IOException;
import java.util.logging.Logger;
class SlipDecoder implements ReadHandler { class SlipDecoder implements ReadHandler {
private static final Logger LOG =
Logger.getLogger(SlipDecoder.class.getName());
// https://tools.ietf.org/html/rfc1055 // https://tools.ietf.org/html/rfc1055
private static final byte END = (byte) 192, ESC = (byte) 219; private static final byte END = (byte) 192, ESC = (byte) 219;
private static final byte TEND = (byte) 220, TESC = (byte) 221; private static final byte TEND = (byte) 220, TESC = (byte) 221;
@@ -32,8 +26,6 @@ class SlipDecoder implements ReadHandler {
reset(true); reset(true);
} else { } else {
if(decodedLength > 0) { if(decodedLength > 0) {
if(LOG.isLoggable(INFO))
LOG.info("Decoded " + decodedLength + " bytes");
byte[] decoded = new byte[decodedLength]; byte[] decoded = new byte[decodedLength];
System.arraycopy(buf, 0, decoded, 0, decodedLength); System.arraycopy(buf, 0, decoded, 0, decodedLength);
readHandler.handleRead(decoded); readHandler.handleRead(decoded);
@@ -74,10 +66,6 @@ class SlipDecoder implements ReadHandler {
} }
private void reset(boolean error) { private void reset(boolean error) {
if(error) {
if(LOG.isLoggable(INFO))
LOG.info("Decoding error after " + decodedLength + " bytes");
}
escape = false; escape = false;
decodedLength = 0; decodedLength = 0;
} }