From c478d963854a703b2466b76dd7af0e05706ef455 Mon Sep 17 00:00:00 2001 From: John Preston Date: Tue, 12 May 2020 16:18:19 +0400 Subject: [PATCH] Add debug logs for chats reading requests. --- Telegram/SourceFiles/data/data_histories.cpp | 50 ++++++++++++++++++++ Telegram/SourceFiles/history/history.cpp | 18 +++++++ 2 files changed, 68 insertions(+) diff --git a/Telegram/SourceFiles/data/data_histories.cpp b/Telegram/SourceFiles/data/data_histories.cpp index ee3da9421..a472fcb37 100644 --- a/Telegram/SourceFiles/data/data_histories.cpp +++ b/Telegram/SourceFiles/data/data_histories.cpp @@ -66,23 +66,32 @@ void Histories::clearAll() { } void Histories::readInbox(not_null history) { + DEBUG_LOG(("Reading: readInbox called.")); if (history->lastServerMessageKnown()) { const auto last = history->lastServerMessage(); + DEBUG_LOG(("Reading: last known, reading till %1." + ).arg(last ? last->id : 0)); readInboxTill(history, last ? last->id : 0); return; } else if (history->loadedAtBottom()) { if (const auto lastId = history->maxMsgId()) { + DEBUG_LOG(("Reading: loaded at bottom, maxMsgId %1." + ).arg(lastId)); readInboxTill(history, lastId); return; } else if (history->loadedAtTop()) { + DEBUG_LOG(("Reading: loaded at bottom, loaded at top.")); readInboxTill(history, 0); return; } + DEBUG_LOG(("Reading: loaded at bottom, but requesting entry.")); } requestDialogEntry(history, [=] { Expects(history->lastServerMessageKnown()); const auto last = history->lastServerMessage(); + DEBUG_LOG(("Reading: got entry, reading till %1." + ).arg(last ? last->id : 0)); readInboxTill(history, last ? last->id : 0); }); } @@ -135,10 +144,20 @@ void Histories::readInboxTill( bool force) { Expects(IsServerMsgId(tillId) || (!tillId && !force)); + DEBUG_LOG(("Reading: readInboxTill %1, force %2." + ).arg(tillId + ).arg(Logs::b(force))); + const auto syncGuard = gsl::finally([&] { + DEBUG_LOG(("Reading: in guard, unread %1." + ).arg(history->unreadCount())); if (history->unreadCount() > 0) { if (const auto last = history->lastServerMessage()) { + DEBUG_LOG(("Reading: checking last %1 and %2." + ).arg(last->id + ).arg(tillId)); if (last->id == tillId) { + DEBUG_LOG(("Reading: locally marked as read.")); history->setUnreadCount(0); history->updateChatListEntry(); } @@ -150,14 +169,21 @@ void Histories::readInboxTill( const auto needsRequest = history->readInboxTillNeedsRequest(tillId); if (!needsRequest && !force) { + DEBUG_LOG(("Reading: readInboxTill finish 1.")); return; } else if (!history->trackUnreadMessages()) { + DEBUG_LOG(("Reading: readInboxTill finish 2.")); return; } const auto maybeState = lookup(history); if (maybeState && maybeState->sentReadTill >= tillId) { + DEBUG_LOG(("Reading: readInboxTill finish 3 with %1." + ).arg(maybeState->sentReadTill)); return; } else if (maybeState && maybeState->willReadTill >= tillId) { + DEBUG_LOG(("Reading: readInboxTill finish 4 with %1 and force %2." + ).arg(maybeState->sentReadTill + ).arg(Logs::b(force))); if (force) { sendPendingReadInbox(history); } @@ -171,23 +197,35 @@ void Histories::readInboxTill( && stillUnread && history->unreadCountKnown() && *stillUnread == history->unreadCount()) { + DEBUG_LOG(("Reading: count didn't change so just update till %1" + ).arg(tillId)); history->setInboxReadTill(tillId); return; } auto &state = maybeState ? *maybeState : _states[history]; state.willReadTill = tillId; if (force || !stillUnread || !*stillUnread) { + DEBUG_LOG(("Reading: will read till %1 with still unread %2" + ).arg(tillId + ).arg(stillUnread.value_or(-666))); state.willReadWhen = 0; sendReadRequests(); if (!stillUnread) { return; } } else if (!state.willReadWhen) { + DEBUG_LOG(("Reading: will read till %1 with postponed").arg(tillId)); state.willReadWhen = crl::now() + kReadRequestTimeout; if (!_readRequestsTimer.isActive()) { _readRequestsTimer.callOnce(kReadRequestTimeout); } + } else { + DEBUG_LOG(("Reading: will read till %1 postponed already" + ).arg(tillId)); } + DEBUG_LOG(("Reading: marking now with till %1 and still %2" + ).arg(tillId + ).arg(*stillUnread)); history->setInboxReadTill(tillId); history->setUnreadCount(*stillUnread); history->updateChatListEntry(); @@ -399,6 +437,9 @@ void Histories::requestFakeChatListMessage( void Histories::sendPendingReadInbox(not_null history) { if (const auto state = lookup(history)) { + DEBUG_LOG(("Reading: send pending now with till %1 and when %2" + ).arg(state->willReadTill + ).arg(state->willReadWhen)); if (state->willReadTill && state->willReadWhen) { state->willReadWhen = 0; sendReadRequests(); @@ -407,6 +448,7 @@ void Histories::sendPendingReadInbox(not_null history) { } void Histories::sendReadRequests() { + DEBUG_LOG(("Reading: send requests with count %1.").arg(_states.size())); if (_states.empty()) { return; } @@ -414,10 +456,14 @@ void Histories::sendReadRequests() { auto next = std::optional(); for (auto &[history, state] : _states) { if (!state.willReadTill) { + DEBUG_LOG(("Reading: skipping zero till.")); continue; } else if (state.willReadWhen <= now) { + DEBUG_LOG(("Reading: sending with till %1." + ).arg(state.willReadTill)); sendReadRequest(history, state); } else if (!next || *next > state.willReadWhen) { + DEBUG_LOG(("Reading: scheduling for later send.")); next = state.willReadWhen; } } @@ -434,7 +480,11 @@ void Histories::sendReadRequest(not_null history, State &state) { const auto tillId = state.sentReadTill = base::take(state.willReadTill); state.willReadWhen = 0; state.sentReadDone = false; + DEBUG_LOG(("Reading: sending request now with till %1." + ).arg(tillId)); sendRequest(history, RequestType::ReadInbox, [=](Fn finish) { + DEBUG_LOG(("Reading: sending request invoked with till %1." + ).arg(tillId)); const auto finished = [=] { const auto state = lookup(history); Assert(state != nullptr); diff --git a/Telegram/SourceFiles/history/history.cpp b/Telegram/SourceFiles/history/history.cpp index ce51ea06a..9dc9d4056 100644 --- a/Telegram/SourceFiles/history/history.cpp +++ b/Telegram/SourceFiles/history/history.cpp @@ -1622,6 +1622,9 @@ bool History::readInboxTillNeedsRequest(MsgId tillId) { if (unreadMark()) { owner().histories().changeDialogUnreadMark(this, false); } + DEBUG_LOG(("Reading: readInboxTillNeedsRequest is_server %1, before %2." + ).arg(Logs::b(IsServerMsgId(tillId)) + ).arg(_inboxReadBefore.value_or(-666))); return IsServerMsgId(tillId) && (_inboxReadBefore.value_or(1) <= tillId); } @@ -1639,10 +1642,17 @@ bool History::unreadCountRefreshNeeded(MsgId readTillId) const { std::optional History::countStillUnreadLocal(MsgId readTillId) const { if (isEmpty() || !folderKnown()) { + DEBUG_LOG(("Reading: countStillUnreadLocal unknown %1 and %2." + ).arg(Logs::b(isEmpty()) + ).arg(Logs::b(folderKnown()))); return std::nullopt; } if (_inboxReadBefore) { const auto before = *_inboxReadBefore; + DEBUG_LOG(("Reading: check before %1 with min %2 and max %3." + ).arg(before + ).arg(minMsgId() + ).arg(maxMsgId())); if (minMsgId() <= before && maxMsgId() >= readTillId) { auto result = 0; for (const auto &block : blocks) { @@ -1658,12 +1668,19 @@ std::optional History::countStillUnreadLocal(MsgId readTillId) const { } } } + DEBUG_LOG(("Reading: check before result %1 with existing %2" + ).arg(result + ).arg(_unreadCount.value_or(-666))); if (_unreadCount) { return std::max(*_unreadCount - result, 0); } } } const auto minimalServerId = minMsgId(); + DEBUG_LOG(("Reading: check at end loaded from %1 loaded %2 - %3" + ).arg(minimalServerId + ).arg(Logs::b(loadedAtBottom()) + ).arg(Logs::b(loadedAtTop()))); if (!loadedAtBottom() || (!loadedAtTop() && !minimalServerId) || minimalServerId > readTillId) { @@ -1682,6 +1699,7 @@ std::optional History::countStillUnreadLocal(MsgId readTillId) const { } } } + DEBUG_LOG(("Reading: check at end counted %1").arg(result)); return result; }