Browse Source

Added some logging

Paul-Louis Ageneau 5 years ago
parent
commit
ebd21a016b
5 changed files with 68 additions and 26 deletions
  1. 4 4
      src/dtlstransport.cpp
  2. 1 0
      src/sctptransport.cpp
  3. 32 11
      src/tcptransport.cpp
  4. 18 11
      src/tlstransport.cpp
  5. 13 0
      src/wstransport.cpp

+ 4 - 4
src/dtlstransport.cpp

@@ -178,7 +178,7 @@ void DtlsTransport::runRecvLoop() {
 
 	// Receive loop
 	try {
-		PLOG_INFO << "DTLS handshake done";
+		PLOG_INFO << "DTLS handshake finished";
 		changeState(State::Connected);
 
 		const size_t bufferSize = maxMtu;
@@ -213,7 +213,7 @@ void DtlsTransport::runRecvLoop() {
 
 	gnutls_bye(mSession, GNUTLS_SHUT_RDWR);
 
-	PLOG_INFO << "DTLS disconnected";
+	PLOG_INFO << "DTLS closed";
 	changeState(State::Disconnected);
 	recv(nullptr);
 }
@@ -484,7 +484,7 @@ void DtlsTransport::runRecvLoop() {
 						// MTU See https://tools.ietf.org/html/rfc8261#section-5
 						SSL_set_mtu(mSsl, maxMtu + 1);
 
-						PLOG_INFO << "DTLS handshake done";
+						PLOG_INFO << "DTLS handshake finished";
 						changeState(State::Connected);
 					}
 				} else {
@@ -530,7 +530,7 @@ void DtlsTransport::runRecvLoop() {
 	}
 
 	if (state() == State::Connected) {
-		PLOG_INFO << "DTLS disconnected";
+		PLOG_INFO << "DTLS closed";
 		changeState(State::Disconnected);
 		recv(nullptr);
 	} else {

+ 1 - 0
src/sctptransport.cpp

@@ -233,6 +233,7 @@ void SctpTransport::shutdown() {
 
 bool SctpTransport::send(message_ptr message) {
 	std::lock_guard lock(mSendMutex);
+
 	if (!message)
 		return mSendQueue.empty();
 

+ 32 - 11
src/tcptransport.cpp

@@ -31,28 +31,34 @@ TcpTransport::TcpTransport(const string &hostname, const string &service, state_
 	mThread = std::thread(&TcpTransport::runLoop, this);
 }
 
-TcpTransport::~TcpTransport() { stop(); }
+TcpTransport::~TcpTransport() {
+	stop();
+	if (mInterruptSock != INVALID_SOCKET)
+		::closesocket(mInterruptSock);
+}
 
 bool TcpTransport::stop() {
 	if (!Transport::stop())
 		return false;
 
+	PLOG_DEBUG << "Waiting TCP recv thread";
 	close();
 	mThread.join();
 	return true;
 }
 
-bool TcpTransport::send(message_ptr message) { return outgoing(message); }
+bool TcpTransport::send(message_ptr message) {
+	if (!message)
+		return mSendQueue.empty();
 
-void TcpTransport::incoming(message_ptr message) { recv(message); }
+	PLOG_VERBOSE << "Send size=" << (message ? message->size() : 0);
 
-bool TcpTransport::outgoing(message_ptr message) {
-	if (mSock == INVALID_SOCKET)
-		throw std::runtime_error("Not connected");
+	return outgoing(message);
+}
 
-	if (!message)
-		return mSendQueue.empty();
+void TcpTransport::incoming(message_ptr message) { recv(message); }
 
+bool TcpTransport::outgoing(message_ptr message) {
 	// If nothing is pending, try to send directly
 	// It's safe because if the queue is empty, the thread is not sending
 	if (mSendQueue.empty() && trySendMessage(message))
@@ -64,6 +70,8 @@ bool TcpTransport::outgoing(message_ptr message) {
 }
 
 void TcpTransport::connect(const string &hostname, const string &service) {
+	PLOG_DEBUG << "Connecting to " << hostname << ":" << service;
+
 	struct addrinfo hints = {};
 	hints.ai_family = AF_UNSPEC;
 	hints.ai_socktype = SOCK_STREAM;
@@ -89,6 +97,8 @@ void TcpTransport::connect(const string &hostname, const string &service) {
 
 void TcpTransport::connect(const sockaddr *addr, socklen_t addrlen) {
 	try {
+		PLOG_DEBUG << "Creating TCP socket";
+
 		// Create socket
 		mSock = ::socket(addr->sa_family, SOCK_STREAM, IPPROTO_TCP);
 		if (mSock == INVALID_SOCKET)
@@ -98,6 +108,15 @@ void TcpTransport::connect(const sockaddr *addr, socklen_t addrlen) {
 		if (::ioctlsocket(mSock, FIONBIO, &b) < 0)
 			throw std::runtime_error("Failed to set socket non-blocking mode");
 
+		IF_PLOG(plog::debug) {
+			char node[MAX_NUMERICNODE_LEN];
+			char serv[MAX_NUMERICSERV_LEN];
+			if (getnameinfo(addr, addrlen, node, MAX_NUMERICNODE_LEN, serv, MAX_NUMERICSERV_LEN,
+			                NI_NUMERICHOST | NI_NUMERICSERV) == 0) {
+				PLOG_DEBUG << "Trying address " << node << ":" << serv;
+			}
+		}
+
 		// Initiate connection
 		::connect(mSock, addr, addrlen);
 
@@ -126,6 +145,7 @@ void TcpTransport::connect(const sockaddr *addr, socklen_t addrlen) {
 
 void TcpTransport::close() {
 	if (mSock != INVALID_SOCKET) {
+		PLOG_DEBUG << "Closing TCP socket";
 		::closesocket(mSock);
 		mSock = INVALID_SOCKET;
 	}
@@ -166,10 +186,9 @@ bool TcpTransport::trySendMessage(message_ptr &message) {
 void TcpTransport::runLoop() {
 	const size_t bufferSize = 4096;
 
-	changeState(State::Connecting);
-
 	// Connect
 	try {
+		changeState(State::Connecting);
 		connect(mHostname, mService);
 
 	} catch (const std::exception &e) {
@@ -178,10 +197,12 @@ void TcpTransport::runLoop() {
 		return;
 	}
 
-	changeState(State::Connected);
 
 	// Receive loop
 	try {
+		PLOG_INFO << "TCP connected";
+		changeState(State::Connected);
+
 		while (true) {
 			fd_set readfds, writefds;
 			int n = prepareSelect(readfds, writefds);

+ 18 - 11
src/tlstransport.cpp

@@ -111,6 +111,8 @@ bool TlsTransport::send(message_ptr message) {
 	if (!message)
 		return false;
 
+	PLOG_VERBOSE << "Send size=" << message->size();
+
 	ssize_t ret;
 	do {
 		ret = gnutls_record_send(mSession, message->data(), message->size());
@@ -128,11 +130,12 @@ void TlsTransport::incoming(message_ptr message) {
 
 void TlsTransport::runRecvLoop() {
 	const size_t bufferSize = 4096;
-
-	changeState(State::Connecting);
+	char buffer[bufferSize];
 
 	// Handshake loop
 	try {
+		changeState(State::Connecting);
+
 		int ret;
 		do {
 			ret = gnutls_handshake(mSession);
@@ -145,12 +148,12 @@ void TlsTransport::runRecvLoop() {
 		return;
 	}
 
-	changeState(State::Connected);
-
 	// Receive loop
 	try {
+		PLOG_INFO << "TLS handshake finished";
+		changeState(State::Connected);
+
 		while (true) {
-			char buffer[bufferSize];
 			ssize_t ret;
 			do {
 				ret = gnutls_record_recv(mSession, buffer, bufferSize);
@@ -178,7 +181,7 @@ void TlsTransport::runRecvLoop() {
 
 	gnutls_bye(mSession, GNUTLS_SHUT_RDWR);
 
-	PLOG_INFO << "TLS disconnected";
+	PLOG_INFO << "TLS closed";
 	changeState(State::Disconnected);
 	recv(nullptr);
 }
@@ -366,8 +369,10 @@ void TlsTransport::incoming(message_ptr message) {
 void TlsTransport::runRecvLoop() {
 	const size_t bufferSize = 4096;
 	byte buffer[bufferSize];
-	bool initFinished = false;
+
 	try {
+		changeState(State::Connecting);
+
 		SSL_do_handshake(mSsl);
 		while (int len = BIO_read(mOutBio, buffer, bufferSize))
 			outgoing(make_message(buffer, buffer + len));
@@ -388,8 +393,10 @@ void TlsTransport::runRecvLoop() {
 			while (int len = BIO_read(mOutBio, buffer, bufferSize))
 				outgoing(make_message(buffer, buffer + len));
 
-			if (!initFinished && SSL_is_init_finished(mSsl))
-				initFinished = true;
+			if (state() == State::Connecting && SSL_is_init_finished(mSsl)) {
+				PLOG_INFO << "TLS handshake finished";
+				changeState(State::Connected);
+			}
 
 			if (decrypted)
 				recv(decrypted);
@@ -398,8 +405,8 @@ void TlsTransport::runRecvLoop() {
 		PLOG_ERROR << "TLS recv: " << e.what();
 	}
 
-	if (initFinished) {
-		PLOG_INFO << "TLS disconnected";
+	if (state() == State::Connected) {
+		PLOG_INFO << "TLS closed";
 		recv(nullptr);
 	} else {
 		PLOG_ERROR << "TLS handshake failed";

+ 13 - 0
src/wstransport.cpp

@@ -86,6 +86,8 @@ bool WsTransport::send(mutable_message_ptr message) {
 	if (!message || state() != State::Connected)
 		return false;
 
+	PLOG_VERBOSE << "Send size=" << message->size();
+
 	return sendFrame({message->type == Message::String ? TEXT_FRAME : BINARY_FRAME, message->data(),
 	                  message->size(), true, true});
 }
@@ -97,6 +99,7 @@ void WsTransport::incoming(message_ptr message) {
 		if (state() == State::Connecting) {
 			if (size_t len = readHttpResponse(mBuffer.data(), mBuffer.size())) {
 				mBuffer.erase(mBuffer.begin(), mBuffer.begin() + len);
+				PLOG_INFO << "WebSocket open";
 				changeState(State::Connected);
 			}
 		}
@@ -110,6 +113,14 @@ void WsTransport::incoming(message_ptr message) {
 		}
 	} catch (const std::exception &e) {
 		PLOG_ERROR << e.what();
+	}
+
+	if (state() == State::Connected) {
+		PLOG_INFO << "WebSocket disconnected";
+		changeState(State::Disconnected);
+		recv(nullptr);
+	} else {
+		PLOG_ERROR << "WebSocket handshake failed";
 		changeState(State::Failed);
 	}
 }
@@ -117,6 +128,7 @@ void WsTransport::incoming(message_ptr message) {
 void WsTransport::close() {
 	if (state() == State::Connected) {
 		sendFrame({CLOSE, NULL, 0, true, true});
+		PLOG_INFO << "WebSocket closing";
 		changeState(State::Completed);
 	}
 }
@@ -309,6 +321,7 @@ void WsTransport::recvFrame(const Frame &frame) {
 	}
 	case CLOSE: {
 		close();
+		PLOG_INFO << "WebSocket closed";
 		changeState(State::Disconnected);
 		break;
 	}