Add logging

This commit is contained in:
Lonami Exo 2018-07-26 01:35:00 +02:00
parent a3bd98d7a2
commit e66a547ca3
6 changed files with 114 additions and 16 deletions

View File

@ -142,7 +142,7 @@ public class Generator {
} }
writer.write("default:\n"); writer.write("default:\n");
writer.write("throw new ClassNotFoundException();\n"); writer.write("throw new ClassNotFoundException(Integer.toHexString(id));\n");
writer.write("}\n"); writer.write("}\n");
writer.write("}\n"); writer.write("}\n");
} }

View File

@ -0,0 +1,63 @@
package io.github.lonamiwebs.overgram.logging;
import java.io.PrintStream;
import java.util.IllegalFormatConversionException;
public class Log {
private static final int LEVEL;
private static final PrintStream OUTPUT;
// Level - Name
// 1 - debug
// 2 - info
// 3 - warning
// 4 - error/exception
// 5 - none
static {
LEVEL = 1;
OUTPUT = System.err;
}
public static void debug(final Object message, final Object... args) {
if (LEVEL <= 1 && OUTPUT != null) {
show(message, args);
}
}
public static void info(final Object message, final Object... args) {
if (LEVEL <= 2 && OUTPUT != null) {
show(message, args);
}
}
public static void warn(final Object message, final Object... args) {
if (LEVEL <= 3 && OUTPUT != null) {
show(message, args);
}
}
public static void error(final Object message, final Object... args) {
if (LEVEL <= 4 && OUTPUT != null) {
show(message, args);
}
}
public static void exception(final Throwable exception, final Object message, final Object... args) {
if (LEVEL <= 4 && OUTPUT != null) {
show(message, args);
exception.printStackTrace(OUTPUT);
}
}
private static void show(Object message, Object... args) {
if (args.length == 0) {
OUTPUT.println(message);
} else {
try {
OUTPUT.println(String.format(message.toString(), args));
} catch (IllegalFormatConversionException ignored) {
OUTPUT.println(message);
}
}
}
}

View File

@ -1,5 +1,6 @@
package io.github.lonamiwebs.overgram.network; package io.github.lonamiwebs.overgram.network;
import io.github.lonamiwebs.overgram.logging.Log;
import io.github.lonamiwebs.overgram.network.connection.Connection; import io.github.lonamiwebs.overgram.network.connection.Connection;
import io.github.lonamiwebs.overgram.tl.TLObject; import io.github.lonamiwebs.overgram.tl.TLObject;
import io.github.lonamiwebs.overgram.tl.TLRequest; import io.github.lonamiwebs.overgram.tl.TLRequest;
@ -26,6 +27,9 @@ public class MTProtoPlainSender {
final byte[] requestBytes = writer.toBytes(); final byte[] requestBytes = writer.toBytes();
writer.clear(); writer.clear();
Log.debug("Sending plain message %d of %d bytes %s",
msgId, requestBytes.length, request.getClass().getName());
writer.write(0L); writer.write(0L);
writer.write(msgId); writer.write(msgId);
writer.write(requestBytes.length); writer.write(requestBytes.length);
@ -52,6 +56,10 @@ public class MTProtoPlainSender {
assert length > 0; assert length > 0;
//noinspection unchecked //noinspection unchecked
return (T) reader.readTl(); final T result = (T) reader.readTl();
Log.debug("Received plain message %d of %d bytes %s",
serverMsgId, length, result.getClass().getName());
return result;
} }
} }

View File

@ -1,6 +1,7 @@
package io.github.lonamiwebs.overgram.network; package io.github.lonamiwebs.overgram.network;
import io.github.lonamiwebs.overgram.crypto.Authenticator; import io.github.lonamiwebs.overgram.crypto.Authenticator;
import io.github.lonamiwebs.overgram.logging.Log;
import io.github.lonamiwebs.overgram.network.connection.Connection; import io.github.lonamiwebs.overgram.network.connection.Connection;
import io.github.lonamiwebs.overgram.tl.*; import io.github.lonamiwebs.overgram.tl.*;
import io.github.lonamiwebs.overgram.utils.BinaryReader; import io.github.lonamiwebs.overgram.utils.BinaryReader;
@ -55,7 +56,8 @@ public class MTProtoSender {
connection.connect(ip, port); connection.connect(ip, port);
success = true; success = true;
break; break;
} catch (IOException ignored) { } catch (IOException e) {
Log.warn("Attempt %d failed connecting to %s:%d: %s", i + 1, ip, port, e);
} }
} }
if (!success) { if (!success) {
@ -70,7 +72,8 @@ public class MTProtoSender {
Authenticator.doAuthentication(plain, state); Authenticator.doAuthentication(plain, state);
success = true; success = true;
break; break;
} catch (SecurityException | IOException | ClassNotFoundException ignored) { } catch (SecurityException | IOException | ClassNotFoundException e) {
Log.warn("Attempt %d failed generating AuthKey: %s", i + 1, e);
} }
} }
@ -80,6 +83,7 @@ public class MTProtoSender {
} }
} }
Log.info("Sender connected to %s:%d. Starting send and receive threads", ip, port);
sendHandle = new Thread(this::sendLoop); sendHandle = new Thread(this::sendLoop);
sendHandle.setDaemon(true); sendHandle.setDaemon(true);
sendHandle.start(); sendHandle.start();
@ -102,9 +106,11 @@ public class MTProtoSender {
pendingAck.clear(); pendingAck.clear();
lastAck = null; lastAck = null;
stopHandles(); stopHandles();
Log.info("Sender disconnected from %s:%d", ip, port);
} }
private void stopHandles() { private void stopHandles() {
Log.info("Stopping send and receive threads");
if (sendHandle != null) { if (sendHandle != null) {
sendHandle.interrupt(); sendHandle.interrupt();
try { try {
@ -131,6 +137,7 @@ public class MTProtoSender {
} }
private void reconnect() { private void reconnect() {
Log.info("Starting automatic reconnection");
reconnecting = true; reconnecting = true;
stopHandles(); stopHandles();
connection.disconnect(); connection.disconnect();
@ -183,13 +190,16 @@ public class MTProtoSender {
return; return;
} }
Log.debug("Packing outgoing message %d: %s", message.id, message.object.getClass().getName());
final byte[] body = state.packMessage(message); final byte[] body = state.packMessage(message);
while (!message.future.isCancelled()) { while (!message.future.isCancelled()) {
try { try {
connection.send(body); connection.send(body);
Log.debug("Message %d sent", message.id);
break; break;
} catch (IOException ignored) { } catch (IOException e) {
// TODO e.g. on timeout retry (loop; not done yet) // TODO e.g. on timeout retry (loop; not done yet)
Log.warn("Failed to send message %d: %s", message.id, e);
try { try {
Thread.sleep(1000); Thread.sleep(1000);
doReconnect(); doReconnect();
@ -203,13 +213,14 @@ public class MTProtoSender {
} }
} }
private void recvLoop() { private void recvLoop() {
while (userConnected) { while (userConnected) {
final byte[] body; final byte[] body;
try { try {
Log.debug("Receiving items from the network...");
body = connection.recv(); body = connection.recv();
} catch (IOException ignored) { } catch (IOException e) {
Log.warn("Error while receiving items from the network: %s", e);
doReconnect(); doReconnect();
return; return;
} }
@ -217,15 +228,24 @@ public class MTProtoSender {
final TLMessage message; final TLMessage message;
try { try {
message = state.unpackMessage(body); message = state.unpackMessage(body);
} catch (ClassNotFoundException ignored) { } catch (ClassNotFoundException e) {
Log.exception(e, "Failed to unpack message");
continue; continue;
} }
try { try {
Log.debug("Processing incoming message %d: %s",
message.id, message.object.getClass().getName());
processMessage(message); processMessage(message);
} catch (ClassNotFoundException ignored) { } catch (ClassNotFoundException e) {
Log.warn("Class not found while processing %d: %s", message.id, e);
} catch (InterruptedException ignored) { } catch (InterruptedException ignored) {
Log.info("Interrupted while processing message %d, stopping read loop", message.id);
doDisconnect(); doDisconnect();
return; return;
} catch (Exception e) {
Log.exception(e, "Unhandled exception while processing %d", message.id);
} }
} }
} }
@ -265,11 +285,10 @@ public class MTProtoSender {
} }
} }
private void handleRpcResult(final TLMessage message) throws ClassNotFoundException { private void handleRpcResult(final TLMessage message) {
final RPCResult result = (RPCResult) message.object; final RPCResult result = (RPCResult) message.object;
final TLMessage replyMessage = pendingMessages.remove(result.reqMsgId); final TLMessage replyMessage = pendingMessages.remove(result.reqMsgId);
boolean ok = false;
try { try {
if (result.error != null) { if (result.error != null) {
replyMessage.future.completeExceptionally(new RPCError(result.error)); replyMessage.future.completeExceptionally(new RPCError(result.error));
@ -277,11 +296,11 @@ public class MTProtoSender {
final BinaryReader reader = new BinaryReader(ByteBuffer.wrap(result.result)); final BinaryReader reader = new BinaryReader(ByteBuffer.wrap(result.result));
replyMessage.future.complete(((TLRequest) replyMessage.object).readResult(reader)); replyMessage.future.complete(((TLRequest) replyMessage.object).readResult(reader));
} }
ok = true; } catch (Exception e) {
} finally { Log.exception(e, "Unhandled exception while receiving result for %d %s",
if (!ok) { replyMessage.id, replyMessage.object.getClass().getName());
replyMessage.future.completeExceptionally(new Exception());
} replyMessage.future.completeExceptionally(e);
} }
} }

View File

@ -2,6 +2,7 @@ package io.github.lonamiwebs.overgram.network;
import io.github.lonamiwebs.overgram.crypto.AES; import io.github.lonamiwebs.overgram.crypto.AES;
import io.github.lonamiwebs.overgram.crypto.AuthKey; import io.github.lonamiwebs.overgram.crypto.AuthKey;
import io.github.lonamiwebs.overgram.logging.Log;
import io.github.lonamiwebs.overgram.tl.TLMessage; import io.github.lonamiwebs.overgram.tl.TLMessage;
import io.github.lonamiwebs.overgram.tl.TLObject; import io.github.lonamiwebs.overgram.tl.TLObject;
import io.github.lonamiwebs.overgram.tl.TLRequest; import io.github.lonamiwebs.overgram.tl.TLRequest;
@ -135,6 +136,7 @@ public class MTProtoState {
final long correct = correctMsgId >> 32; final long correct = correctMsgId >> 32;
timeOffset = correct - now; timeOffset = correct - now;
lastMsgId = 0; lastMsgId = 0;
Log.info("New time offset %d", timeOffset);
} }
public void setTimeOffset(final long timeOffset) { public void setTimeOffset(final long timeOffset) {

View File

@ -1,5 +1,7 @@
package io.github.lonamiwebs.overgram.network; package io.github.lonamiwebs.overgram.network;
import io.github.lonamiwebs.overgram.logging.Log;
import java.io.IOException; import java.io.IOException;
import java.io.InputStream; import java.io.InputStream;
import java.io.OutputStream; import java.io.OutputStream;
@ -10,11 +12,13 @@ public class TcpClient {
private Socket socket; private Socket socket;
public void connect(final String ipAddress, final int port) throws IOException { public void connect(final String ipAddress, final int port) throws IOException {
Log.info("Connecting to %s:%d", ipAddress, port);
socket = new Socket(ipAddress, port); socket = new Socket(ipAddress, port);
} }
public void close() { public void close() {
try { try {
Log.info("Closing socket connection %s", socket.getRemoteSocketAddress());
socket.close(); socket.close();
} catch (IOException ignored) { } catch (IOException ignored) {
} }
@ -27,6 +31,7 @@ public class TcpClient {
int index = 0; int index = 0;
while (true) { while (true) {
final int count = in.read(result, index, result.length - index); final int count = in.read(result, index, result.length - index);
Log.debug("Read %d more bytes out of %d", count, result.length - index);
if (count == -1) { if (count == -1) {
throw new IOException("Connection closed"); throw new IOException("Connection closed");
} }
@ -40,6 +45,7 @@ public class TcpClient {
public void write(final byte[] bytes) throws IOException { public void write(final byte[] bytes) throws IOException {
final OutputStream out = socket.getOutputStream(); final OutputStream out = socket.getOutputStream();
Log.debug("Writing %d bytes", bytes.length);
out.write(bytes); out.write(bytes);
out.flush(); out.flush();
} }