From 8658dba97ad48687a0c871863c32c94551abed38 Mon Sep 17 00:00:00 2001 From: John Preston Date: Mon, 7 Feb 2022 14:24:02 +0300 Subject: [PATCH] Improve mtproto connections logging. --- .../mtproto/connection_abstract.cpp | 26 ++++- .../SourceFiles/mtproto/connection_abstract.h | 14 +++ .../SourceFiles/mtproto/connection_http.cpp | 87 +++++++++------ .../SourceFiles/mtproto/connection_http.h | 4 +- .../mtproto/connection_resolving.cpp | 17 +-- .../SourceFiles/mtproto/connection_tcp.cpp | 102 ++++++++++-------- .../details/mtproto_abstract_socket.cpp | 40 +++++++ .../mtproto/details/mtproto_abstract_socket.h | 8 ++ .../mtproto/details/mtproto_tcp_socket.cpp | 44 +------- .../mtproto/details/mtproto_tcp_socket.h | 3 +- .../mtproto/details/mtproto_tls_socket.cpp | 16 +-- .../mtproto/details/mtproto_tls_socket.h | 1 + .../SourceFiles/mtproto/session_private.cpp | 19 ++-- 13 files changed, 231 insertions(+), 150 deletions(-) diff --git a/Telegram/SourceFiles/mtproto/connection_abstract.cpp b/Telegram/SourceFiles/mtproto/connection_abstract.cpp index 8cb8fd80a..a9323633f 100644 --- a/Telegram/SourceFiles/mtproto/connection_abstract.cpp +++ b/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 GlobalConnectionCounter/* = 0*/; + +} // namespace ConnectionPointer::ConnectionPointer() = default; @@ -158,7 +163,8 @@ std::optional 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() & 0x3F); } diff --git a/Telegram/SourceFiles/mtproto/connection_abstract.h b/Telegram/SourceFiles/mtproto/connection_abstract.h index a262206bc..71172df45 100644 --- a/Telegram/SourceFiles/mtproto/connection_abstract.h +++ b/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 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 diff --git a/Telegram/SourceFiles/mtproto/connection_http.cpp b/Telegram/SourceFiles/mtproto/connection_http.cpp index 6c369d735..3e7e04d87 100644 --- a/Telegram/SourceFiles/mtproto/connection_http.cpp +++ b/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: " - "dc:%1 - Sending fake req_pq to '%2'" - ).arg(protocolDcId - ).arg(url().toDisplayString())); + if (Logs::DebugEnabled()) { + _debugId = u"%1(dc:%2,%3)"_q + .arg(_debugId.toInt()) + .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::RemoteHostClosedError: LOG(("HTTP Error: remote host closed - %1").arg(reply->errorString())); break; - case QNetworkReply::HostNotFoundError: LOG(("HTTP Error: host not found - %1").arg(reply->errorString())); break; - case QNetworkReply::TimeoutError: LOG(("HTTP Error: timeout - %1").arg(reply->errorString())); break; - case QNetworkReply::OperationCanceledError: LOG(("HTTP Error: cancelled - %1").arg(reply->errorString())); break; + case QNetworkReply::ConnectionRefusedError: + CONNECTION_LOG_ERROR(u"Connection refused - %1."_q + .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) { - DEBUG_LOG(("HTTP Error: network error %1 - %2").arg(reply->error()).arg(reply->errorString())); - } else { - LOG(("HTTP Error: network error %1 - %2").arg(reply->error()).arg(reply->errorString())); - } + CONNECTION_LOG_ERROR(u"Network error %1 - %2."_q + .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: " - "HTTP-transport to %1 connected by pq-response" - ).arg(_address)); + CONNECTION_LOG_INFO( + "HTTP-transport connected by pq-response."); _status = Status::Ready; _pingTime = crl::now() - _pingTime; connected(); } else { - DEBUG_LOG(("Connection Error: " - "Wrong nonce received in HTTP fake pq-responce")); + CONNECTION_LOG_ERROR( + "Wrong nonce in HTTP fake pq-response."); error(kErrorCodeOther); } } else { - DEBUG_LOG(("Connection Error: " - "Could not parse HTTP fake pq-responce")); + CONNECTION_LOG_ERROR( + "Could not parse HTTP fake pq-response."); error(kErrorCodeOther); } } diff --git a/Telegram/SourceFiles/mtproto/connection_http.h b/Telegram/SourceFiles/mtproto/connection_http.h index bbc7a44a7..53a909f93 100644 --- a/Telegram/SourceFiles/mtproto/connection_http.h +++ b/Telegram/SourceFiles/mtproto/connection_http.h @@ -40,8 +40,8 @@ public: QString transport() const override; QString tag() const override; - static mtpBuffer handleResponse(QNetworkReply *reply); - static qint32 handleError(QNetworkReply *reply); // Returns error code. + mtpBuffer handleResponse(QNetworkReply *reply); + qint32 handleError(QNetworkReply *reply); // Returns error code. private: QUrl url() const; diff --git a/Telegram/SourceFiles/mtproto/connection_resolving.cpp b/Telegram/SourceFiles/mtproto/connection_resolving.cpp index ae4b6f9e5..571e14eb3 100644 --- a/Telegram/SourceFiles/mtproto/connection_resolving.cpp +++ b/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( - QString::number(_protocolDcId), - _proxy.host +':' + QString::number(_proxy.port), - (_ipIndex >= 0 && _ipIndex < _proxy.resolvedIPs.size()) - ? _proxy.resolvedIPs[_ipIndex] - : _proxy.host)); - return _child->connectToServer( + _child->connectToServer( address, port, protocolSecret, protocolDcId, protocolForFiles); + CONNECTION_LOG_INFO("Resolving connected a child: " + _child->debugId()); } bool ResolvingConnection::isConnected() const { diff --git a/Telegram/SourceFiles/mtproto/connection_tcp.cpp b/Telegram/SourceFiles/mtproto/connection_tcp.cpp index 6c8fbf4a8..d50234127 100644 --- a/Telegram/SourceFiles/mtproto/connection_tcp.cpp +++ b/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 { // 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" - ).arg(_leftBytes - ).arg(_readBytes)); + CONNECTION_LOG_INFO( + u"Not enough %1 for packet! read %2"_q + .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" - ).arg(packetSize)); + CONNECTION_LOG_ERROR( + 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! " - "full size %2 read %3" - ).arg(_leftBytes - ).arg(packetSize - ).arg(available.size())); + CONNECTION_LOG_INFO(u"Not enough %1 for packet! " + "full size %2 read %3"_q + .arg(_leftBytes) + .arg(packetSize) + .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" - ).arg(packet.size())); + CONNECTION_LOG_INFO(u"Packet received, size = %1."_q.arg(packet.size())); const auto ints = gsl::make_span( reinterpret_cast(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: " - "error packet received, endpoint: '%1:%2', " - "protocolDcId: %3, code = %4" - ).arg(_address.isEmpty() ? ("prx_" + _proxy.host) : _address - ).arg(_address.isEmpty() ? _proxy.port : _port - ).arg(_protocolDcId - ).arg(ints[0])); + CONNECTION_LOG_ERROR(u"Error packet received, code = %1"_q + .arg(ints[0])); } return mtpBuffer(1, ints[0]); } @@ -396,10 +413,7 @@ void TcpConnection::socketConnected() { auto buffer = preparePQFake(_checkNonce); - DEBUG_LOG(("TCP Info: " - "dc:%1 - Sending fake req_pq to '%2'" - ).arg(_protocolDcId - ).arg(_address + ':' + QString::number(_port))); + CONNECTION_LOG_INFO("Sending fake req_pq."); _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: " - "Wrong nonce received in TCP fake pq-responce")); + CONNECTION_LOG_ERROR( + "Wrong nonce received in TCP fake pq-responce"); error(kErrorCodeOther); } } else { - DEBUG_LOG(("Connection Error: " - "Could not parse TCP fake pq-responce")); + CONNECTION_LOG_ERROR("Could not parse TCP fake pq-responce"); error(kErrorCodeOther); } } diff --git a/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.cpp b/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.cpp index 055b5c256..653033365 100644 --- a/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.cpp +++ b/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.cpp @@ -28,4 +28,44 @@ std::unique_ptr 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 diff --git a/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.h b/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.h index ce1431fff..4283a353d 100644 --- a/Telegram/SourceFiles/mtproto/details/mtproto_abstract_socket.h +++ b/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 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; diff --git a/Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.cpp b/Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.cpp index c5ca5b749..5eb98bacb 100644 --- a/Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.cpp +++ b/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) { - switch (errorCode) { - 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)); +QString TcpSocket::debugPostfix() const { + return QString(); } void TcpSocket::handleError(int errorCode) { - LogError(errorCode, _socket.errorString()); + logError(errorCode, _socket.errorString()); _error.fire({}); } diff --git a/Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.h b/Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.h index 28e3c4665..453e2eaac 100644 --- a/Telegram/SourceFiles/mtproto/details/mtproto_tcp_socket.h +++ b/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; - - static void LogError(int errorCode, const QString &errorText); + QString debugPostfix() const override; private: void handleError(int errorCode); diff --git a/Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.cpp b/Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.cpp index b74d44869..166ce8702 100644 --- a/Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.cpp +++ b/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({}); diff --git a/Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.h b/Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.h index 4bced8d75..c97b1d7e8 100644 --- a/Telegram/SourceFiles/mtproto/details/mtproto_tls_socket.h +++ b/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 { diff --git a/Telegram/SourceFiles/mtproto/session_private.cpp b/Telegram/SourceFiles/mtproto/session_private.cpp index ca46f113e..fe60be4a3 100644 --- a/Telegram/SourceFiles/mtproto/session_private.cpp +++ b/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(); }