Add debug logs for chats reading requests.

This commit is contained in:
John Preston 2020-05-12 16:18:19 +04:00
parent 2ede53e0ee
commit c478d96385
2 changed files with 68 additions and 0 deletions

View file

@ -66,23 +66,32 @@ void Histories::clearAll() {
}
void Histories::readInbox(not_null<History*> 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*> 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*> 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<crl::time>();
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*> 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<void()> finish) {
DEBUG_LOG(("Reading: sending request invoked with till %1."
).arg(tillId));
const auto finished = [=] {
const auto state = lookup(history);
Assert(state != nullptr);

View file

@ -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<int> 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<int> 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<int> History::countStillUnreadLocal(MsgId readTillId) const {
}
}
}
DEBUG_LOG(("Reading: check at end counted %1").arg(result));
return result;
}