Improve mtproto connections logging.

Telegram/SourceFiles/mtproto/connection_abstract.cpp

@@ -16,6 +16,11 @@ https://github.com/telegramdesktop/tdesktop/blob/master/LEGAL
 
 namespace MTP {
 namespace details {
+namespace {
+
+std::atomic<int> GlobalConnectionCounter/* = 0*/;
+
+} // namespace
 
 ConnectionPointer::ConnectionPointer() = default;
 
@@ -158,7 +163,8 @@ std::optional<MTPResPQ> AbstractConnection::readPQFakeReply(
 AbstractConnection::AbstractConnection(
 	QThread *thread,
 	const ProxyData &proxy)
-: _proxy(proxy) {
+: _proxy(proxy)
+, _debugId(QString::number(++GlobalConnectionCounter)) {
 	moveToThread(thread);
 }
 
@@ -188,6 +194,24 @@ ConnectionPointer AbstractConnection::Create(
 	return result;
 }
 
+QString AbstractConnection::ProtocolDcDebugId(int16 protocolDcId) {
+	const auto postfix = (protocolDcId < 0) ? "_media" : "";
+	protocolDcId = (protocolDcId < 0) ? (-protocolDcId) : protocolDcId;
+	const auto prefix = (protocolDcId > kTestModeDcIdShift) ? "test_" : "";
+	protocolDcId = (protocolDcId > kTestModeDcIdShift)
+		? (protocolDcId - kTestModeDcIdShift)
+		: protocolDcId;
+	return prefix + QString::number(protocolDcId) + postfix;
+}
+
+void AbstractConnection::logInfo(const QString &message) {
+	DEBUG_LOG(("Connection %1 Info: ").arg(_debugId) + message);
+}
+
+void AbstractConnection::logError(const QString &message) {
+	DEBUG_LOG(("Connection %1 Error: ").arg(_debugId) + message);
+}
+
 uint32 AbstractConnection::extendedNotSecurePadding() const {
 	return uint32(base::RandomValue<uchar>() & 0x3F);
 }

Telegram/SourceFiles/mtproto/connection_abstract.h

@@ -24,6 +24,8 @@ struct ConnectionOptions;
 
 class AbstractConnection;
 
+inline constexpr auto kTestModeDcIdShift = 10000;
+
 class ConnectionPointer {
 public:
 	ConnectionPointer();
@@ -122,6 +124,13 @@ public:
 	[[nodiscard]] gsl::span<const mtpPrime> parseNotSecureResponse(
 		const mtpBuffer &buffer) const;
 
+	[[nodiscard]] static QString ProtocolDcDebugId(int16 protocolDcId);
+	[[nodiscard]] QString debugId() const {
+		return _debugId;
+	}
+	void logInfo(const QString &message);
+	void logError(const QString &message);
+
 	// Used to emit error(...) with no real code from the server.
 	static constexpr auto kErrorCodeOther = -499;
 
@@ -141,6 +150,8 @@ protected:
 	int _pingTime = 0;
 	ProxyData _proxy;
 
+	QString _debugId;
+
 	// first we always send fake MTPReq_pq to see if connection works at all
 	// we send them simultaneously through TCP/HTTP/IPv4/IPv6 to choose the working one
 	[[nodiscard]] mtpBuffer preparePQFake(const MTPint128 &nonce) const;
@@ -193,5 +204,8 @@ mtpBuffer AbstractConnection::prepareNotSecurePacket(
 	return result;
 }
 
+#define CONNECTION_LOG_INFO(x) if (Logs::DebugEnabled()) { logInfo(x); }
+#define CONNECTION_LOG_ERROR(x) if (Logs::DebugEnabled()) { logError(x); }
+
 } // namespace details
 } // namespace MTP

Telegram/SourceFiles/mtproto/connection_http.cpp

@@ -43,7 +43,7 @@ void HttpConnection::sendData(mtpBuffer &&buffer) {
 	request.setHeader(QNetworkRequest::ContentLengthHeader, QVariant(requestSize));
 	request.setHeader(QNetworkRequest::ContentTypeHeader, QVariant(qsl("application/x-www-form-urlencoded")));
 
-	TCP_LOG(("HTTP Info: sending %1 len request").arg(requestSize));
+	CONNECTION_LOG_INFO(u"Sending %1 len request."_q.arg(requestSize));
 	_requests.insert(_manager.post(request, QByteArray((const char*)(&buffer[2]), requestSize)));
 }
 
@@ -78,10 +78,12 @@ void HttpConnection::connectToServer(
 
 	auto buffer = preparePQFake(_checkNonce);
 
-	DEBUG_LOG(("HTTP Info: "
+	if (Logs::DebugEnabled()) {
-		"dc:%1 - Sending fake req_pq to '%2'"
+		_debugId = u"%1(dc:%2,%3)"_q
-		).arg(protocolDcId
+			.arg(_debugId.toInt())
-		).arg(url().toDisplayString()));
+			.arg(ProtocolDcDebugId(protocolDcId))
+			.arg(url().toDisplayString());
+	}
 
 	_pingTime = crl::now();
 	sendData(std::move(buffer));
@@ -89,12 +91,12 @@ void HttpConnection::connectToServer(
 
 mtpBuffer HttpConnection::handleResponse(QNetworkReply *reply) {
 	QByteArray response = reply->readAll();
-	TCP_LOG(("HTTP Info: read %1 bytes").arg(response.size()));
+	CONNECTION_LOG_INFO(u"Read %1 bytes."_q.arg(response.size()));
 
 	if (response.isEmpty()) return mtpBuffer();
 
 	if (response.size() & 0x03 || response.size() < 8) {
-		LOG(("HTTP Error: bad response size %1").arg(response.size()));
+		CONNECTION_LOG_ERROR(u"Bad response size %1."_q.arg(response.size()));
 		return mtpBuffer(1, -500);
 	}
 
@@ -104,31 +106,46 @@ mtpBuffer HttpConnection::handleResponse(QNetworkReply *reply) {
 	return data;
 }
 
-qint32 HttpConnection::handleError(QNetworkReply *reply) { // returnes "maybe bad key"
+// Returns "maybe bad key".
+qint32 HttpConnection::handleError(QNetworkReply *reply) {
 	auto result = qint32(kErrorCodeOther);
 
-	QVariant statusCode = reply->attribute(QNetworkRequest::HttpStatusCodeAttribute);
+	QVariant statusCode = reply->attribute(
+		QNetworkRequest::HttpStatusCodeAttribute);
 	if (statusCode.isValid()) {
 		int status = statusCode.toInt();
 		result = -status;
 	}
 
 	switch (reply->error()) {
-	case QNetworkReply::ConnectionRefusedError: LOG(("HTTP Error: connection refused - %1").arg(reply->errorString())); break;
+	case QNetworkReply::ConnectionRefusedError:
-	case QNetworkReply::RemoteHostClosedError: LOG(("HTTP Error: remote host closed - %1").arg(reply->errorString())); break;
+		CONNECTION_LOG_ERROR(u"Connection refused - %1."_q
-	case QNetworkReply::HostNotFoundError: LOG(("HTTP Error: host not found - %1").arg(reply->errorString())); break;
+			.arg(reply->errorString()));
-	case QNetworkReply::TimeoutError: LOG(("HTTP Error: timeout - %1").arg(reply->errorString())); break;
+		break;
-	case QNetworkReply::OperationCanceledError: LOG(("HTTP Error: cancelled - %1").arg(reply->errorString())); break;
+	case QNetworkReply::RemoteHostClosedError:
+		CONNECTION_LOG_ERROR(u"Remote host closed - %1."_q
+			.arg(reply->errorString()));
+		break;
+	case QNetworkReply::HostNotFoundError:
+		CONNECTION_LOG_ERROR(u"Host not found - %1."_q
+			.arg(reply->errorString()));
+		break;
+	case QNetworkReply::TimeoutError:
+		CONNECTION_LOG_ERROR(u"Timeout - %1."_q
+			.arg(reply->errorString()));
+		break;
+	case QNetworkReply::OperationCanceledError:
+		CONNECTION_LOG_ERROR(u"Cancelled - %1."_q
+			.arg(reply->errorString()));
+		break;
 	case QNetworkReply::SslHandshakeFailedError:
 	case QNetworkReply::TemporaryNetworkFailureError:
 	case QNetworkReply::NetworkSessionFailedError:
 	case QNetworkReply::BackgroundRequestNotAllowedError:
 	case QNetworkReply::UnknownNetworkError:
-		if (reply->error() == QNetworkReply::UnknownNetworkError) {
+		CONNECTION_LOG_ERROR(u"Network error %1 - %2."_q
-			DEBUG_LOG(("HTTP Error: network error %1 - %2").arg(reply->error()).arg(reply->errorString()));
+			.arg(reply->error())
-		} else {
+			.arg(reply->errorString()));
-			LOG(("HTTP Error: network error %1 - %2").arg(reply->error()).arg(reply->errorString()));
-		}
 		break;
 
 	// proxy errors (101-199):
@@ -137,7 +154,11 @@ qint32 HttpConnection::handleError(QNetworkReply *reply) { // returnes "maybe ba
 	case QNetworkReply::ProxyNotFoundError:
 	case QNetworkReply::ProxyTimeoutError:
 	case QNetworkReply::ProxyAuthenticationRequiredError:
-	case QNetworkReply::UnknownProxyError: LOG(("HTTP Error: proxy error %1 - %2").arg(reply->error()).arg(reply->errorString())); break;
+	case QNetworkReply::UnknownProxyError:
+		CONNECTION_LOG_ERROR(u"Proxy error %1 - %2."_q
+			.arg(reply->error())
+			.arg(reply->errorString()));
+		break;
 
 	// content errors (201-299):
 	case QNetworkReply::ContentAccessDenied:
@@ -145,14 +166,21 @@ qint32 HttpConnection::handleError(QNetworkReply *reply) { // returnes "maybe ba
 	case QNetworkReply::ContentNotFoundError:
 	case QNetworkReply::AuthenticationRequiredError:
 	case QNetworkReply::ContentReSendError:
-	case QNetworkReply::UnknownContentError: LOG(("HTTP Error: content error %1 - %2").arg(reply->error()).arg(reply->errorString())); break;
+	case QNetworkReply::UnknownContentError:
+		CONNECTION_LOG_ERROR(u"Content error %1 - %2."_q
+			.arg(reply->error())
+			.arg(reply->errorString()));
+		break;
 
 	// protocol errors
 	case QNetworkReply::ProtocolUnknownError:
 	case QNetworkReply::ProtocolInvalidOperationError:
-	case QNetworkReply::ProtocolFailure: LOG(("HTTP Error: protocol error %1 - %2").arg(reply->error()).arg(reply->errorString())); break;
+	case QNetworkReply::ProtocolFailure:
+		CONNECTION_LOG_ERROR(u"Protocol error %1 - %2."_q
+			.arg(reply->error())
+			.arg(reply->errorString()));
+		break;
 	};
-	TCP_LOG(("HTTP Error %1, restarting! - %2").arg(reply->error()).arg(reply->errorString()));
 
 	return result;
 }
@@ -178,20 +206,19 @@ void HttpConnection::requestFinished(QNetworkReply *reply) {
 			} else if (const auto res_pq = readPQFakeReply(data)) {
 				const auto &data = res_pq->c_resPQ();
 				if (data.vnonce() == _checkNonce) {
-					DEBUG_LOG(("Connection Info: "
+					CONNECTION_LOG_INFO(
-						"HTTP-transport to %1 connected by pq-response"
+						"HTTP-transport connected by pq-response.");
-						).arg(_address));
 					_status = Status::Ready;
 					_pingTime = crl::now() - _pingTime;
 					connected();
 				} else {
-					DEBUG_LOG(("Connection Error: "
+					CONNECTION_LOG_ERROR(
-						"Wrong nonce received in HTTP fake pq-responce"));
+						"Wrong nonce in HTTP fake pq-response.");
 					error(kErrorCodeOther);
 				}
 			} else {
-				DEBUG_LOG(("Connection Error: "
+				CONNECTION_LOG_ERROR(
-					"Could not parse HTTP fake pq-responce"));
+					"Could not parse HTTP fake pq-response.");
 				error(kErrorCodeOther);
 			}
 		}

Telegram/SourceFiles/mtproto/connection_http.h

@@ -40,8 +40,8 @@ public:
 	QString transport() const override;
 	QString tag() const override;
 
-	static mtpBuffer handleResponse(QNetworkReply *reply);
+	mtpBuffer handleResponse(QNetworkReply *reply);
-	static qint32 handleError(QNetworkReply *reply); // Returns error code.
+	qint32 handleError(QNetworkReply *reply); // Returns error code.
 
 private:
 	QUrl url() const;

Telegram/SourceFiles/mtproto/connection_resolving.cpp

@@ -72,12 +72,6 @@ void ResolvingConnection::setChild(ConnectionPointer &&child) {
 		&AbstractConnection::disconnected,
 		this,
 		&ResolvingConnection::handleDisconnected);
-	DEBUG_LOG(("Resolving Info: dc:%1 proxy '%2' got new child '%3'").arg(
-		QString::number(_protocolDcId),
-		_proxy.host + ':' + QString::number(_proxy.port),
-		(_ipIndex >= 0 && _ipIndex < _proxy.resolvedIPs.size())
-			? _proxy.resolvedIPs[_ipIndex]
-			: _proxy.host));
 	if (_protocolDcId) {
 		_child->connectToServer(
 			_address,
@@ -85,6 +79,8 @@ void ResolvingConnection::setChild(ConnectionPointer &&child) {
 			_protocolSecret,
 			_protocolDcId,
 			_protocolForFiles);
+		CONNECTION_LOG_INFO("Resolving connected a new child: "
+			+ _child->debugId());
 	}
 }
 
@@ -224,18 +220,13 @@ void ResolvingConnection::connectToServer(
 	_protocolSecret = protocolSecret;
 	_protocolDcId = protocolDcId;
 	_protocolForFiles = protocolForFiles;
-	DEBUG_LOG(("Resolving Info: dc:%1 proxy '%2' connects a child '%3'").arg(
+	_child->connectToServer(
-		QString::number(_protocolDcId),
-		_proxy.host +':' + QString::number(_proxy.port),
-		(_ipIndex >= 0 && _ipIndex < _proxy.resolvedIPs.size())
-			? _proxy.resolvedIPs[_ipIndex]
-			: _proxy.host));
-	return _child->connectToServer(
 		address,
 		port,
 		protocolSecret,
 		protocolDcId,
 		protocolForFiles);
+	CONNECTION_LOG_INFO("Resolving connected a child: " + _child->debugId());
 }
 
 bool ResolvingConnection::isConnected() const {

Telegram/SourceFiles/mtproto/connection_tcp.cpp

@@ -40,6 +40,8 @@ public:
 	virtual int readPacketLength(bytes::const_span bytes) const = 0;
 	virtual bytes::const_span readPacket(bytes::const_span bytes) const = 0;
 
+	virtual QString debugPostfix() const = 0;
+
 	virtual ~Protocol() = default;
 
 private:
@@ -60,6 +62,8 @@ public:
 	int readPacketLength(bytes::const_span bytes) const override;
 	bytes::const_span readPacket(bytes::const_span bytes) const override;
 
+	QString debugPostfix() const override;
+
 };
 
 uint32 TcpConnection::Protocol::Version0::id() const {
@@ -129,12 +133,18 @@ bytes::const_span TcpConnection::Protocol::Version0::readPacket(
 	return bytes.subspan(sizeLength, size - sizeLength);
 }
 
+QString TcpConnection::Protocol::Version0::debugPostfix() const {
+	return QString();
+}
+
 class TcpConnection::Protocol::Version1 : public Version0 {
 public:
 	explicit Version1(bytes::vector &&secret);
 
 	void prepareKey(bytes::span key, bytes::const_span source) override;
 
+	QString debugPostfix() const override;
+
 private:
 	bytes::vector _secret;
 
@@ -151,6 +161,10 @@ void TcpConnection::Protocol::Version1::prepareKey(
 	bytes::copy(key, openssl::Sha256(payload));
 }
 
+QString TcpConnection::Protocol::Version1::debugPostfix() const {
+	return u"_obf"_q;
+}
+
 class TcpConnection::Protocol::VersionD : public Version1 {
 public:
 	using Version1::Version1;
@@ -163,6 +177,8 @@ public:
 	int readPacketLength(bytes::const_span bytes) const override;
 	bytes::const_span readPacket(bytes::const_span bytes) const override;
 
+	QString debugPostfix() const override;
+
 };
 
 uint32 TcpConnection::Protocol::VersionD::id() const {
@@ -209,6 +225,10 @@ bytes::const_span TcpConnection::Protocol::VersionD::readPacket(
 	return bytes.subspan(sizeLength, size - sizeLength);
 }
 
+QString TcpConnection::Protocol::VersionD::debugPostfix() const {
+	return u"_dd"_q;
+}
+
 auto TcpConnection::Protocol::Create(bytes::const_span secret)
 -> std::unique_ptr<Protocol> {
 	// See also DcOptions::ValidateSecret.
@@ -269,7 +289,7 @@ void TcpConnection::socketRead() {
 	Expects(_leftBytes > 0 || !_usingLargeBuffer);
 
 	if (!_socket || !_socket->isConnected()) {
-		LOG(("MTP Error: Socket not connected in socketRead()"));
+		CONNECTION_LOG_ERROR("Socket not connected in socketRead()");
 		error(kErrorCodeOther);
 		return;
 	}
@@ -290,7 +310,7 @@ void TcpConnection::socketRead() {
 		if (readCount > 0) {
 			const auto read = free.subspan(0, readCount);
 			aesCtrEncrypt(read, _receiveKey, &_receiveState);
-			TCP_LOG(("TCP Info: read %1 bytes").arg(readCount));
+			CONNECTION_LOG_INFO(u"Read %1 bytes"_q.arg(readCount));
 
 			_readBytes += readCount;
 			if (_leftBytes > 0) {
@@ -306,9 +326,10 @@ void TcpConnection::socketRead() {
 					_largeBuffer.clear();
 					_offsetBytes = _readBytes = 0;
 				} else {
-					TCP_LOG(("TCP Info: not enough %1 for packet! read %2"
+					CONNECTION_LOG_INFO(
-						).arg(_leftBytes
+						u"Not enough %1 for packet! read %2"_q
-						).arg(_readBytes));
+						.arg(_leftBytes)
+						.arg(_readBytes));
 					receivedSome();
 				}
 			} else {
@@ -320,8 +341,9 @@ void TcpConnection::socketRead() {
 						// Not enough bytes yet.
 						break;
 					} else if (packetSize <= 0) {
-						LOG(("TCP Error: bad packet size in 4 bytes: %1"
+						CONNECTION_LOG_ERROR(
-							).arg(packetSize));
+							u"Bad packet size in 4 bytes: %1"_q
+							.arg(packetSize));
 						error(kErrorCodeOther);
 						return;
 					} else if (available.size() >= packetSize) {
@@ -342,22 +364,23 @@ void TcpConnection::socketRead() {
 						// If the next packet won't fit in the buffer.
 						ensureAvailableInBuffer(packetSize);
 
-						TCP_LOG(("TCP Info: not enough %1 for packet! "
+						CONNECTION_LOG_INFO(u"Not enough %1 for packet! "
-							"full size %2 read %3"
+							"full size %2 read %3"_q
-							).arg(_leftBytes
+							.arg(_leftBytes)
-							).arg(packetSize
+							.arg(packetSize)
-							).arg(available.size()));
+							.arg(available.size()));
 						receivedSome();
 						break;
 					}
 				}
 			}
 		} else if (readCount < 0) {
-			LOG(("TCP Error: socket read return %1").arg(readCount));
+			CONNECTION_LOG_ERROR(u"Socket read return %1."_q.arg(readCount));
 			error(kErrorCodeOther);
 			return;
 		} else {
-			TCP_LOG(("TCP Info: no bytes read, but bytes available was true..."));
+			CONNECTION_LOG_INFO(
+				"No bytes read, but bytes available was true...");
 			break;
 		}
 	} while (_socket
@@ -367,8 +390,7 @@ void TcpConnection::socketRead() {
 
 mtpBuffer TcpConnection::parsePacket(bytes::const_span bytes) {
 	const auto packet = _protocol->readPacket(bytes);
-	TCP_LOG(("TCP Info: packet received, size = %1"
+	CONNECTION_LOG_INFO(u"Packet received, size = %1."_q.arg(packet.size()));
-		).arg(packet.size()));
 	const auto ints = gsl::make_span(
 		reinterpret_cast<const mtpPrime*>(packet.data()),
 		packet.size() / sizeof(mtpPrime));
@@ -376,13 +398,8 @@ mtpBuffer TcpConnection::parsePacket(bytes::const_span bytes) {
 	if (ints.size() < 3) {
 		// nop or error or new quickack, latter is not yet supported.
 		if (ints[0] != 0) {
-			LOG(("TCP Error: "
+			CONNECTION_LOG_ERROR(u"Error packet received, code = %1"_q
-				"error packet received, endpoint: '%1:%2', "
+				.arg(ints[0]));
-				"protocolDcId: %3, code = %4"
-				).arg(_address.isEmpty() ? ("prx_" + _proxy.host) : _address
-				).arg(_address.isEmpty() ? _proxy.port : _port
-				).arg(_protocolDcId
-				).arg(ints[0]));
 		}
 		return mtpBuffer(1, ints[0]);
 	}
@@ -396,10 +413,7 @@ void TcpConnection::socketConnected() {
 
 	auto buffer = preparePQFake(_checkNonce);
 
-	DEBUG_LOG(("TCP Info: "
+	CONNECTION_LOG_INFO("Sending fake req_pq.");
-		"dc:%1 - Sending fake req_pq to '%2'"
-		).arg(_protocolDcId
-		).arg(_address + ':' + QString::number(_port)));
 
 	_pingTime = crl::now();
 	sendData(std::move(buffer));
@@ -423,7 +437,8 @@ void TcpConnection::sendData(mtpBuffer &&buffer) {
 
 	// buffer: 2 available int-s + data + available int.
 	const auto bytes = _protocol->finalizePacket(buffer);
-	TCP_LOG(("TCP Info: write packet %1 bytes").arg(bytes.size()));
+	CONNECTION_LOG_INFO(u"TCP Info: write packet %1 bytes."_q
+		.arg(bytes.size()));
 	aesCtrEncrypt(bytes, _sendKey, &_sendState);
 	_socket->write(connectionStartPrefix, bytes);
 }
@@ -506,20 +521,10 @@ void TcpConnection::connectToServer(
 		_address = _proxy.host;
 		_port = _proxy.port;
 		_protocol = Protocol::Create(secret);
-
-		DEBUG_LOG(("TCP Info: "
-			"dc:%1 - Connecting to proxy '%2'"
-			).arg(protocolDcId
-			).arg(_address + ':' + QString::number(_port)));
 	} else {
 		_address = address;
 		_port = port;
 		_protocol = Protocol::Create(secret);
-
-		DEBUG_LOG(("TCP Info: "
-			"dc:%1 - Connecting to '%2'"
-			).arg(protocolDcId
-			).arg(_address + ':' + QString::number(_port)));
 	}
 	_socket = AbstractSocket::Create(
 		thread(),
@@ -528,6 +533,18 @@ void TcpConnection::connectToServer(
 		protocolForFiles);
 	_protocolDcId = protocolDcId;
 
+	const auto postfix = _socket->debugPostfix();
+	_debugId = u"%1(dc:%2,%3%4:%5%6)"_q
+		.arg(_debugId.toInt())
+		.arg(ProtocolDcDebugId(_protocolDcId))
+		.arg((_proxy.type == ProxyData::Type::Mtproto) ? "mtproxy " : "")
+		.arg(_address)
+		.arg(_port)
+		.arg(postfix.isEmpty() ? _protocol->debugPostfix() : postfix);
+	_socket->setDebugId(_debugId);
+
+	CONNECTION_LOG_INFO("Connecting...");
+
 	_socket->connected(
 	) | rpl::start_with_next([=] {
 		socketConnected();
@@ -584,19 +601,18 @@ void TcpConnection::socketPacket(bytes::const_span bytes) {
 		if (const auto res_pq = readPQFakeReply(data)) {
 			const auto &data = res_pq->c_resPQ();
 			if (data.vnonce() == _checkNonce) {
-				DEBUG_LOG(("Connection Info: Valid pq response by TCP."));
+				CONNECTION_LOG_INFO("Valid pq response by TCP.");
 				_status = Status::Ready;
 				_connectedLifetime.destroy();
 				_pingTime = (crl::now() - _pingTime);
 				connected();
 			} else {
-				DEBUG_LOG(("Connection Error: "
+				CONNECTION_LOG_ERROR(
-					"Wrong nonce received in TCP fake pq-responce"));
+					"Wrong nonce received in TCP fake pq-responce");
 				error(kErrorCodeOther);
 			}
 		} else {
-			DEBUG_LOG(("Connection Error: "
+			CONNECTION_LOG_ERROR("Could not parse TCP fake pq-responce");
-				"Could not parse TCP fake pq-responce"));
 			error(kErrorCodeOther);
 		}
 	}

Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.cpp

@@ -28,4 +28,44 @@ std::unique_ptr<AbstractSocket> AbstractSocket::Create(
 	}
 }
 
+void AbstractSocket::logError(int errorCode, const QString &errorText) {
+	const auto log = [&](const QString &message) {
+		DEBUG_LOG(("Socket %1 Error: ").arg(_debugId) + message);
+	};
+	switch (errorCode) {
+	case QAbstractSocket::ConnectionRefusedError:
+		log(u"Socket connection refused - %1."_q.arg(errorText));
+		break;
+
+	case QAbstractSocket::RemoteHostClosedError:
+		log(u"Remote host closed socket connection - %1."_q.arg(errorText));
+		break;
+
+	case QAbstractSocket::HostNotFoundError:
+		log(u"Host not found - %1."_q.arg(errorText));
+		break;
+
+	case QAbstractSocket::SocketTimeoutError:
+		log(u"Socket timeout - %1."_q.arg(errorText));
+		break;
+
+	case QAbstractSocket::NetworkError: {
+		log(u"Network - %1."_q.arg(errorText));
+	} break;
+
+	case QAbstractSocket::ProxyAuthenticationRequiredError:
+	case QAbstractSocket::ProxyConnectionRefusedError:
+	case QAbstractSocket::ProxyConnectionClosedError:
+	case QAbstractSocket::ProxyConnectionTimeoutError:
+	case QAbstractSocket::ProxyNotFoundError:
+	case QAbstractSocket::ProxyProtocolError:
+		log(u"Proxy (%1) - %2."_q.arg(errorCode).arg(errorText));
+		break;
+
+	default:
+		log(u"Other (%1) - %2."_q.arg(errorCode).arg(errorText));
+		break;
+	}
+}
+
 } // namespace MTP::details

Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.h

@@ -20,6 +20,10 @@ public:
 		const QNetworkProxy &proxy,
 		bool protocolForFiles);
 
+	void setDebugId(const QString &id) {
+		_debugId = id;
+	}
+
 	explicit AbstractSocket(not_null<QThread*> thread) {
 		moveToThread(thread);
 	}
@@ -52,11 +56,15 @@ public:
 		bytes::const_span buffer) = 0;
 
 	virtual int32 debugState() = 0;
+	[[nodiscard]] virtual QString debugPostfix() const = 0;
 
 protected:
 	static const int kFilesSendBufferSize = 2 * 1024 * 1024;
 	static const int kFilesReceiveBufferSize = 2 * 1024 * 1024;
 
+	void logError(int errorCode, const QString &errorText);
+
+	QString _debugId;
 	rpl::event_stream<> _connected;
 	rpl::event_stream<> _disconnected;
 	rpl::event_stream<> _readyRead;

Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.cpp

@@ -114,50 +114,12 @@ int32 TcpSocket::debugState() {
 	return _socket.state();
 }
 
-void TcpSocket::LogError(int errorCode, const QString &errorText) {
+QString TcpSocket::debugPostfix() const {
-	switch (errorCode) {
+	return QString();
-	case QAbstractSocket::ConnectionRefusedError:
-		LOG(("TCP Error: socket connection refused - %1").arg(errorText));
-		break;
-
-	case QAbstractSocket::RemoteHostClosedError:
-		TCP_LOG(("TCP Info: remote host closed socket connection - %1"
-			).arg(errorText));
-		break;
-
-	case QAbstractSocket::HostNotFoundError:
-		LOG(("TCP Error: host not found - %1").arg(errorText));
-		break;
-
-	case QAbstractSocket::SocketTimeoutError:
-		LOG(("TCP Error: socket timeout - %1").arg(errorText));
-		break;
-
-	case QAbstractSocket::NetworkError: {
-		DEBUG_LOG(("TCP Error: network - %1").arg(errorText));
-	} break;
-
-	case QAbstractSocket::ProxyAuthenticationRequiredError:
-	case QAbstractSocket::ProxyConnectionRefusedError:
-	case QAbstractSocket::ProxyConnectionClosedError:
-	case QAbstractSocket::ProxyConnectionTimeoutError:
-	case QAbstractSocket::ProxyNotFoundError:
-	case QAbstractSocket::ProxyProtocolError:
-		LOG(("TCP Error: proxy (%1) - %2").arg(errorCode).arg(errorText));
-		break;
-
-	default:
-		LOG(("TCP Error: other (%1) - %2").arg(errorCode).arg(errorText));
-		break;
-	}
-
-	TCP_LOG(("TCP Error %1, restarting! - %2"
-		).arg(errorCode
-		).arg(errorText));
 }
 
 void TcpSocket::handleError(int errorCode) {
-	LogError(errorCode, _socket.errorString());
+	logError(errorCode, _socket.errorString());
 	_error.fire({});
 }
 

Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.h

@@ -27,8 +27,7 @@ public:
 	void write(bytes::const_span prefix, bytes::const_span buffer) override;
 
 	int32 debugState() override;
-
+	QString debugPostfix() const override;
-	static void LogError(int errorCode, const QString &errorText);
 
 private:
 	void handleError(int errorCode);

Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.cpp

@@ -505,7 +505,7 @@ void TlsSocket::plainConnected() {
 		domainFromSecret(),
 		keyFromSecret());
 	if (hello.data.isEmpty()) {
-		LOG(("TLS Error: Could not generate Client Hello!"));
+		logError(888, "Could not generate Client Hello.");
 		_state = State::Error;
 		_error.fire({});
 	} else {
@@ -563,7 +563,7 @@ void TlsSocket::checkHelloParts12(int parts1Size) {
 			- kLengthSize
 			- kServerHelloPart1.size();
 		if (!CheckPart(data.subspan(part1Offset), kServerHelloPart1)) {
-			LOG(("TLS Error: Bad Server Hello part1."));
+			logError(888, "Bad Server Hello part1.");
 			handleError();
 			return;
 		}
@@ -587,7 +587,7 @@ void TlsSocket::checkHelloParts34(int parts123Size) {
 			- kLengthSize
 			- kServerHelloPart3.size();
 		if (!CheckPart(data.subspan(part3Offset), kServerHelloPart3)) {
-			LOG(("TLS Error: Bad Server Hello part."));
+			logError(888, "Bad Server Hello part.");
 			handleError();
 			return;
 		}
@@ -611,7 +611,7 @@ void TlsSocket::checkHelloDigest() {
 	bytes::set_with_const(digest, bytes::type(0));
 	const auto check = openssl::HmacSha256(keyFromSecret(), fulldata);
 	if (bytes::compare(digestCopy, check) != 0) {
-		LOG(("TLS Error: Bad Server Hello digest."));
+		logError(888, "Bad Server Hello digest.");
 		handleError();
 		return;
 	}
@@ -649,7 +649,7 @@ bool TlsSocket::checkNextPacket() {
 			return true;
 		}
 		if (!CheckPart(incoming.subspan(offset), kServerHeader)) {
-			LOG(("TLS Error: Bad packet header."));
+			logError(888, "Bad packet header.");
 			return false;
 		}
 		const auto length = ReadPartLength(
@@ -773,12 +773,16 @@ int32 TlsSocket::debugState() {
 	return _socket.state();
 }
 
+QString TlsSocket::debugPostfix() const {
+	return u"_ee"_q;
+}
+
 void TlsSocket::handleError(int errorCode) {
 	if (_state != State::Connected) {
 		_syncTimeRequests.fire({});
 	}
 	if (errorCode) {
-		TcpSocket::LogError(errorCode, _socket.errorString());
+		logError(errorCode, _socket.errorString());
 	}
 	_state = State::Error;
 	_error.fire({});

Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.h

@@ -28,6 +28,7 @@ public:
 	void write(bytes::const_span prefix, bytes::const_span buffer) override;
 
 	int32 debugState() override;
+	QString debugPostfix() const override;
 
 private:
 	enum class State {

Telegram/SourceFiles/mtproto/session_private.cpp

@@ -39,7 +39,6 @@ constexpr auto kPingSendAfter = 30 * crl::time(1000);
 constexpr auto kPingSendAfterForce = 45 * crl::time(1000);
 constexpr auto kTemporaryExpiresIn = TimeId(86400);
 constexpr auto kBindKeyAdditionalExpiresTimeout = TimeId(30);
-constexpr auto kTestModeDcIdShift = 10000;
 constexpr auto kKeyOldEnoughForDestroy = 60 * crl::time(1000);
 constexpr auto kSentContainerLives = 600 * crl::time(1000);
 constexpr auto kFastRequestDuration = crl::time(500);
@@ -1252,14 +1251,10 @@ void SessionPrivate::handleReceived() {
 		auto ints = intsBuffer.constData();
 		if ((intsCount < kMinimalIntsCount) || (intsCount > kMaxMessageLength / kIntSize)) {
 			LOG(("TCP Error: bad message received, len %1").arg(intsCount * kIntSize));
-			TCP_LOG(("TCP Error: bad message %1").arg(Logs::mb(ints, intsCount * kIntSize).str()));
-
 			return restart();
 		}
 		if (_keyId != *(uint64*)ints) {
 			LOG(("TCP Error: bad auth_key_id %1 instead of %2 received").arg(_keyId).arg(*(uint64*)ints));
-			TCP_LOG(("TCP Error: bad message %1").arg(Logs::mb(ints, intsCount * kIntSize).str()));
-
 			return restart();
 		}
 
@@ -1297,8 +1292,6 @@ void SessionPrivate::handleReceived() {
 		constexpr auto kMsgKeyShift = 8U;
 		if (ConstTimeIsDifferent(&msgKey, sha256Buffer.data() + kMsgKeyShift, sizeof(msgKey))) {
 			LOG(("TCP Error: bad SHA256 hash after aesDecrypt in message"));
-			TCP_LOG(("TCP Error: bad message %1").arg(Logs::mb(encryptedInts, encryptedBytesCount).str()));
-
 			return restart();
 		}
 
@@ -1307,17 +1300,19 @@ void SessionPrivate::handleReceived() {
 			|| (paddingSize < kMinPaddingSize)
 			|| (paddingSize > kMaxPaddingSize)) {
 			LOG(("TCP Error: bad msg_len received %1, data size: %2").arg(messageLength).arg(encryptedBytesCount));
-			TCP_LOG(("TCP Error: bad message %1").arg(Logs::mb(encryptedInts, encryptedBytesCount).str()));
-
 			return restart();
 		}
 
-		TCP_LOG(("TCP Info: decrypted message %1,%2,%3 is %4 len").arg(msgId).arg(seqNo).arg(Logs::b(needAck)).arg(fullDataLength));
+		if (Logs::DebugEnabled()) {
+			_connection->logInfo(u"Decrypted message %1,%2,%3 is %4 len"_q
+				.arg(msgId)
+				.arg(seqNo)
+				.arg(Logs::b(needAck))
+				.arg(fullDataLength));
+		}
 
 		if (session != _sessionId) {
 			LOG(("MTP Error: bad server session received"));
-			TCP_LOG(("MTP Error: bad server session %1 instead of %2 in message received").arg(session).arg(_sessionId));
-
 			return restart();
 		}