core: Silence auto-PINGs with invalid timestamps
authorShane Synan <digitalcircuit36939@gmail.com>
Mon, 18 Jun 2018 20:47:10 +0000 (15:47 -0500)
committerManuel Nickschas <sputnick@quassel-irc.org>
Mon, 18 Jun 2018 22:54:10 +0000 (00:54 +0200)
Track whether or not an automated ping reply is pending.  If so, and
if the network has not shown to reply to PING via quoting, silence
the response.

This fixes automated PING resulting in unsolicited PONG replies
spamming the server buffer for networks that don't quote PING in
PONG replies.  Manual PING still works in almost all cases, unless
the IRC server responds out-of-order.

Mark a network as sending valid PONG timestamps after the first one
is received, resetting on every connect (as each server may differ).

Simplify PONG silencing by using the EventManager::Silent flag,
remove redundant logic from EventStringifier.

Clean up private variable initialization.

src/core/corenetwork.cpp
src/core/corenetwork.h
src/core/coresessioneventprocessor.cpp
src/core/eventstringifier.cpp

index 575d20c..d3c4645 100644 (file)
@@ -44,9 +44,6 @@ CoreNetwork::CoreNetwork(const NetworkId &networkid, CoreSession *session)
     _previousConnectionAttemptFailed(false),
     _lastUsedServerIndex(0),
 
-    _lastPingTime(0),
-    _pingCount(0),
-    _sendPings(false),
     _requestedUserModes('-')
 {
     _autoReconnectTimer.setSingleShot(true);
@@ -253,6 +250,9 @@ void CoreNetwork::connectToIrc(bool reconnecting)
 
     enablePingTimeout();
 
+    // Reset tracking for valid timestamps in PONG replies
+    setPongTimestampValid(false);
+
     // Qt caches DNS entries for a minute, resulting in round-robin (e.g. for chat.freenode.net) not working if several users
     // connect at a similar time. QHostInfo::fromName(), however, always performs a fresh lookup, overwriting the cache entry.
     if (! server.useProxy) {
@@ -940,8 +940,12 @@ void CoreNetwork::sendPing()
         _lastPingTime = now;
         _pingCount++;
         // Don't send pings until the network is initialized
-        if(_sendPings)
+        if(_sendPings) {
+            // Mark as waiting for a reply
+            _pongReplyPending = true;
+            // Send default timestamp ping
             userInputHandler()->handlePing(BufferInfo(), QString());
+        }
     }
 }
 
@@ -952,6 +956,7 @@ void CoreNetwork::enablePingTimeout(bool enable)
         disablePingTimeout();
     else {
         resetPingTimeout();
+        resetPongReplyPending();
         if (networkConfig()->pingTimeoutEnabled())
             _pingTimer.start();
     }
@@ -963,6 +968,7 @@ void CoreNetwork::disablePingTimeout()
     _pingTimer.stop();
     _sendPings = false;
     resetPingTimeout();
+    resetPongReplyPending();
 }
 
 
@@ -972,6 +978,12 @@ void CoreNetwork::setPingInterval(int interval)
 }
 
 
+void CoreNetwork::setPongTimestampValid(bool validTimestamp)
+{
+    _pongTimestampValid = validTimestamp;
+}
+
+
 /******** Custom Rate Limiting ********/
 
 void CoreNetwork::updateRateLimiting(const bool forceUnlimited)
index 44dcd06..6ad77b6 100644 (file)
@@ -110,6 +110,25 @@ public:
      */
     inline bool disconnectExpected() const { return _disconnectExpected; }
 
+    /**
+     * Gets whether or not the server replies to automated PINGs with a valid timestamp
+     *
+     * Distinguishes between servers that reply by quoting the text sent, and those that respond
+     * with whatever they want.
+     *
+     * @return True if a valid timestamp has been received as a PONG, otherwise false.
+     */
+    inline bool isPongTimestampValid() const { return _pongTimestampValid; }
+
+    /**
+     * Gets whether or not an automated PING has been sent without any PONG received
+     *
+     * Reset whenever any PONG is received, not just the automated one sent.
+     *
+     * @return True if a PING has been sent without a PONG received, otherwise false.
+     */
+    inline bool isPongReplyPending() const { return _pongReplyPending; }
+
     QList<QList<QByteArray>> splitMessage(const QString &cmd, const QString &message, std::function<QList<QByteArray>(QString &)> cmdGenerator);
 
     // IRCv3 capability negotiation
@@ -190,6 +209,17 @@ public slots:
 
     void setPingInterval(int interval);
 
+    /**
+     * Sets whether or not the IRC server has replied to PING with a valid timestamp
+     *
+     * This allows determining whether or not an IRC server responds to PING with a PONG that quotes
+     * what was sent, or if it does something else (and therefore PONGs should be more aggressively
+     * hidden).
+     *
+     * @param timestampValid If true, a valid timestamp has been received via PONG reply
+     */
+    void setPongTimestampValid(bool validTimestamp);
+
     void connectToIrc(bool reconnecting = false);
     /**
      * Disconnect from the IRC server.
@@ -372,6 +402,11 @@ public slots:
 
     inline void resetPingTimeout() { _pingCount = 0; }
 
+    /**
+     * Marks the network as no longer having a pending reply to an automated PING
+     */
+    inline void resetPongReplyPending() { _pongReplyPending = false; }
+
     inline void displayMsg(Message::Type msgType, BufferInfo::Type bufferType, const QString &target, const QString &text, const QString &sender = "", Message::Flags flags = Message::None)
     {
         emit displayMsg(networkId(), msgType, bufferType, target, text, sender, flags);
@@ -478,9 +513,13 @@ private:
     int _lastUsedServerIndex;
 
     QTimer _pingTimer;
-    qint64 _lastPingTime;
-    uint _pingCount;
-    bool _sendPings;
+    qint64 _lastPingTime = 0;          ///< Unix time of most recently sent automatic ping
+    uint _pingCount = 0;               ///< Unacknowledged automatic pings
+    bool _sendPings = false;           ///< If true, pings should be periodically sent to server
+    bool _pongTimestampValid = false;  ///< If true, IRC server responds to PING by quoting in PONG
+    // This tracks whether or not a server responds to PING with a PONG of what was sent, or if it
+    // does something else.  If false, PING reply hiding should be more aggressive.
+    bool _pongReplyPending = false;    ///< If true, at least one PING sent without a PONG reply
 
     QStringList _autoWhoQueue;
     QHash<QString, int> _autoWhoPending;
index c4c01e5..eb2ec0e 100644 (file)
@@ -661,12 +661,46 @@ void CoreSessionEventProcessor::processIrcEventPong(IrcEvent *e)
     // Attempt to parse the timestamp
     QTime sendTime = QTime::fromString(timestamp, "hh:mm:ss.zzz");
     if (sendTime.isValid()) {
+        // Mark IRC server as sending valid ping replies
+        if (!coreNetwork(e)->isPongTimestampValid()) {
+            coreNetwork(e)->setPongTimestampValid(true);
+            // Add a message the first time it happens
+            qDebug().nospace() << "Received PONG with valid timestamp, marking pong replies on "
+                                  "network "
+                               << "\"" << qPrintable(e->network()->networkName()) << "\" (ID: "
+                               << qPrintable(QString::number(e->network()->networkId().toInt()))
+                               << ") as usable for latency measurement";
+        }
+        // Remove pending flag
+        coreNetwork(e)->resetPongReplyPending();
+
+        // Don't show this in the UI
+        e->setFlag(EventManager::Silent);
+        // TODO:  To allow for a user-sent /ping (without arguments, so default timestamp is used),
+        // this could track how many automated PINGs have been sent by the core and subtract one
+        // each time, only marking the PING as silent if there's pending automated pong replies.
+        // However, that's a behavior change which warrants further testing.  For now, take the
+        // simpler, previous approach that errs on the side of silencing too much.
+
         // Calculate latency from time difference, divided by 2 to account for round-trip time
         e->network()->setLatency(sendTime.msecsTo(QTime::currentTime()) / 2);
-    } else {
-        // Just in case it's a wonky server, log a debug message to make this easier to track down
-        qDebug() << "Received valid PONG with invalid timestamp, parameters are" << e->params();
+    } else if (coreNetwork(e)->isPongReplyPending() && !coreNetwork(e)->isPongTimestampValid()) {
+        // There's an auto-PING reply pending and we've not yet received a PONG reply with a valid
+        // timestamp.  It's possible this server will never respond with a valid timestamp, and thus
+        // any automated PINGs will result in unwanted spamming of the server buffer.
+
+        // Don't show this in the UI
+        e->setFlag(EventManager::Silent);
+        // Remove pending flag
+        coreNetwork(e)->resetPongReplyPending();
+
+        // Log a message
+        qDebug().nospace() << "Received PONG with invalid timestamp from network "
+                           << "\"" << qPrintable(e->network()->networkName()) << "\" (ID: "
+                           << qPrintable(QString::number(e->network()->networkId().toInt()))
+                           << "), silencing, parameters are " << e->params();
     }
+    // else: We're not expecting a PONG reply and timestamp is not valid, assume it's from the user
 }
 
 
index b4ba3ad..c7da8d7 100644 (file)
@@ -365,29 +365,11 @@ void EventStringifier::processIrcEventPart(IrcEvent *e)
 
 void EventStringifier::processIrcEventPong(IrcEvent *e)
 {
-    // Some IRC servers respond with only one parameter, others respond with two, with the latter
-    // being the text sent.  Handle both situations.
-    QString timestamp;
-    if (e->params().count() < 2) {
-        // Only one parameter received
-        // :localhost PONG 02:43:49.565
-        timestamp = e->params().at(0);
-    } else {
-        // Two parameters received, pick the second
-        // :localhost PONG localhost :02:43:49.565
-        timestamp = e->params().at(1);
-    }
+    // CoreSessionEventProcessor will flag automated PONG replies as EventManager::Silent.  There's
+    // no need to handle that specially here.
 
-    // Attempt to parse the timestamp
-    QTime sendTime = QTime::fromString(timestamp, "hh:mm:ss.zzz");
-    if (!sendTime.isValid()) {
-        // No valid timestamp found, this is most likely a user-specified PING message.
-        //
-        // Or the IRC server is returning whatever it feels like to PING messages, in which case..
-        // sorry.  Increase the ping timeout delay in Quassel to as high as possible, and go
-        // encourage your IRC server developer to fix their stuff.
-        displayMsg(e, Message::Server, "PONG " + e->params().join(" "), e->prefix());
-    }
+    // Format the PONG reply for display
+    displayMsg(e, Message::Server, "PONG " + e->params().join(" "), e->prefix());
 }