natpmp: fix out-of-order responses bug

This patch fixes a few issues with the way libnatpmp was used in DHTNet.
The two most important ones are the following:

1) Each call to sendnewportmapping is now followed by a call to
   readResponse. This is important because libnatpmp expects the
   response to each request to be read before another request is sent;
   skipping a request can cause the responses to later requests to be
   incorrect.

2) All requests are now sent from the Asio thread. This wasn't the case
   before, and as a result the responses to requests made from different
   threads would sometimes get mixed up (e.g. if thread 1 sends request
   A and thread 2 sends request B, then thread 1 could end up reading
   the response to request B).

The other (minor) issues are:

3) The readResponse function would return the NATPMP_ERR_SOCKETERROR
   error code when the MAX_READ_RETRIES limit was hit instead of
   NATPMP_TRYAGAIN, which made this case look identical to a poll error
   in the logs. The function would also sleep unnecessarily after the
   last iteration when the limit was reached.

4) The sendMappingRequest function tried to make up to MAX_READ_RETRIES
   calls to readResponse when it detected that it had gotten a response
   of the wrong type, but this doesn't work because libnatpmp doesn't
   allow reading multiple responses in a row and will simply return a
   NATPMP_ERR_NOPENDINGREQ error for each call after the first one.

GitLab: #33
Change-Id: If8f0824eef1de601411c9e70bd33df46230a24f8
diff --git a/src/upnp/protocol/natpmp/nat_pmp.cpp b/src/upnp/protocol/natpmp/nat_pmp.cpp
index 9005ee4..60d6bf5 100644
--- a/src/upnp/protocol/natpmp/nat_pmp.cpp
+++ b/src/upnp/protocol/natpmp/nat_pmp.cpp
@@ -262,56 +262,74 @@
 void
 NatPmp::requestMappingAdd(const Mapping& mapping)
 {
-    Mapping map(mapping);
-    assert(map.getIgd());
-    auto err = addPortMapping(map);
-    if (err < 0) {
-        if (logger_) logger_->warn("NAT-PMP: Request for mapping {} on {} failed with error {:d}: {}",
-                  map.toString(),
-                  igd_->toString(),
-                  err,
-                  getNatPmpErrorStr(err));
+    // libnatpmp isn't thread-safe, so we use Asio here to make
+    // sure that all requests are sent from the same thread.
+    ioContext->post([w = weak(), mapping] {
+        auto sthis = w.lock();
+        if (!sthis)
+            return;
+        Mapping map(mapping);
+        assert(map.getIgd());
+        auto err = sthis->addPortMapping(map);
+        if (err < 0) {
+            if (sthis->logger_)
+                sthis->logger_->warn("NAT-PMP: Request for mapping {} on {} failed with error {:d}: {}",
+                                     map.toString(),
+                                     sthis->igd_->toString(),
+                                     err,
+                                     sthis->getNatPmpErrorStr(err));
 
-        if (isErrorFatal(err)) {
-            // Fatal error, increment the counter.
-            incrementErrorsCounter(igd_);
+            if (sthis->isErrorFatal(err)) {
+                // Fatal error, increment the counter.
+                sthis->incrementErrorsCounter(sthis->igd_);
+            }
+            // Notify the listener.
+            sthis->processMappingRequestFailed(std::move(map));
+        } else {
+            if (sthis->logger_)
+                sthis->logger_->debug("NAT-PMP: Request for mapping {:s} on {:s} succeeded",
+                                      map.toString(),
+                                      sthis->igd_->toString());
+            // Notify the listener.
+            sthis->processMappingAdded(std::move(map));
         }
-        // Notify the listener.
-        processMappingRequestFailed(std::move(map));
-    } else {
-        if (logger_) logger_->debug("NAT-PMP: Request for mapping {:s} on {:s} succeeded",
-                 map.toString(),
-                 igd_->toString());
-        // Notify the listener.
-        processMappingAdded(std::move(map));
-    }
+    });
 }
 
 void
 NatPmp::requestMappingRenew(const Mapping& mapping)
 {
-    Mapping map(mapping);
-    auto err = addPortMapping(map);
-    if (err < 0) {
-        if (logger_) logger_->warn("NAT-PMP: Renewal request for mapping {} on {} failed with error {:d}: {}",
-                  map.toString(),
-                  igd_->toString(),
-                  err,
-                  getNatPmpErrorStr(err));
-        // Notify the listener.
-        processMappingRequestFailed(std::move(map));
+    // libnatpmp isn't thread-safe, so we use Asio here to make
+    // sure that all requests are sent from the same thread.
+    ioContext->post([w = weak(), mapping] {
+        auto sthis = w.lock();
+        if (!sthis)
+            return;
+        Mapping map(mapping);
+        auto err = sthis->addPortMapping(map);
+        if (err < 0) {
+            if (sthis->logger_)
+                sthis->logger_->warn("NAT-PMP: Renewal request for mapping {} on {} failed with error {:d}: {}",
+                                     map.toString(),
+                                     sthis->igd_->toString(),
+                                     err,
+                                     sthis->getNatPmpErrorStr(err));
+            // Notify the listener.
+            sthis->processMappingRequestFailed(std::move(map));
 
-        if (isErrorFatal(err)) {
-            // Fatal error, increment the counter.
-            incrementErrorsCounter(igd_);
+            if (sthis->isErrorFatal(err)) {
+                // Fatal error, increment the counter.
+                sthis->incrementErrorsCounter(sthis->igd_);
+            }
+        } else {
+            if (sthis->logger_)
+                sthis->logger_->debug("NAT-PMP: Renewal request for mapping {} on {} succeeded",
+                                      map.toString(),
+                                      sthis->igd_->toString());
+            // Notify the listener.
+            sthis->processMappingRenewed(map);
         }
-    } else {
-        if (logger_) logger_->debug("NAT-PMP: Renewal request for mapping {} on {} succeeded",
-                 map.toString(),
-                 igd_->toString());
-        // Notify the listener.
-        processMappingRenewed(map);
-    }
+    });
 }
 
 int
@@ -321,11 +339,6 @@
     unsigned readRetriesCounter = 0;
 
     while (true) {
-        if (readRetriesCounter++ > MAX_READ_RETRIES) {
-            err = NATPMP_ERR_SOCKETERROR;
-            break;
-        }
-
         struct pollfd fds;
         fds.fd = handle.s;
         fds.events = POLLIN;
@@ -345,7 +358,7 @@
         // Read the data.
         err = readnatpmpresponseorretry(&handle, &response);
 
-        if (err == NATPMP_TRYAGAIN) {
+        if (err == NATPMP_TRYAGAIN && readRetriesCounter++ < MAX_READ_RETRIES) {
             std::this_thread::sleep_for(std::chrono::milliseconds(TIMEOUT_BEFORE_READ_RETRY));
         } else {
             break;
@@ -372,48 +385,87 @@
         return err;
     }
 
-    unsigned readRetriesCounter = 0;
+    // Read the response
+    natpmpresp_t response;
+    err = readResponse(natpmpHdl_, response);
 
-    while (readRetriesCounter++ < MAX_READ_RETRIES) {
-        // Read the response
-        natpmpresp_t response;
-        err = readResponse(natpmpHdl_, response);
-
-        if (err < 0) {
-            if (logger_) logger_->warn("NAT-PMP: Read response on IGD {} failed with error {}",
-                      igd_->toString(),
-                      getNatPmpErrorStr(err));
-        } else if (response.type != NATPMP_RESPTYPE_TCPPORTMAPPING
-                   and response.type != NATPMP_RESPTYPE_UDPPORTMAPPING) {
-            if (logger_) logger_->error("NAT-PMP: Unexpected response type ({:d}) for mapping {} from IGD {}.",
-                     response.type,
-                     mapping.toString(),
-                     igd_->toString());
-            // Try to read again.
-            continue;
-        }
-
-        uint16_t newExternalPort = response.pnu.newportmapping.mappedpublicport;
-        uint32_t newLifetime = response.pnu.newportmapping.lifetime;
-        if (lifetime > 0) {
-            // We requested the creation/renewal of a mapping and didn't get an error, so at this point
-            // newExternalPort and newLifetime should both be nonzero. However, that's not always the case
-            // in practice (presumably because some routers don't implement NAT-PMP correctly).
-            if (newExternalPort == 0 || newLifetime == 0) {
-                if (logger_) logger_->warn("NAT-PMP: mapping request returned without error but the response"
-                                           " contains invalid data (external port: {}, lifetime: {})",
-                                           newExternalPort,
-                                           newLifetime);
-                err = NATPMP_ERR_INVALIDARGS;
-            } else {
-                lifetime = newLifetime;
-                mapping.setExternalPort(newExternalPort);
-            }
-        }
-       break;
+    if (err < 0) {
+        if (logger_) logger_->warn("NAT-PMP: Read response on IGD {} failed with error {}",
+                  igd_->toString(),
+                  getNatPmpErrorStr(err));
+        return err;
     }
 
-    return err;
+    // Even if readResponse returned without error, there is no guarantee that the
+    // response we read is for the mapping we just requested. libnatpmp expects that
+    // after each call to sendnewportmappingrequest, readnatpmpresponseorretry will
+    // be called "as long as it returns NATPMP_TRYAGAIN". Failure to do so (whether
+    // it's because of a bug as in https://git.jami.net/savoirfairelinux/dhtnet/-/issues/33,
+    // or simply because readResponse gave up after MAX_READ_RETRIES attempts) can
+    // result in us reading the response to a previous request.
+    bool responseValid = true;
+
+    if (response.type == NATPMP_RESPTYPE_PUBLICADDRESS) {
+        responseValid = false;
+        if (logger_)
+            logger_->error("NAT-PMP: unexpected response to request for mapping {} from IGD {} [type: PUBLICADDRESS]",
+                           mapping.toString(),
+                           igd_->toString());
+    } else {
+        // There are only three possible response types in libnatpmp. If it's not
+        // PUBLICADDRESS, then it's either UDPPORTMAPPING or TCPPORTMAPPING.
+        uint16_t expectedType = mapping.getType() == PortType::UDP ? NATPMP_RESPTYPE_UDPPORTMAPPING
+                                                                   : NATPMP_RESPTYPE_TCPPORTMAPPING;
+        uint16_t expectedPrivatePort = mapping.getInternalPort();
+        // If the response we got was actually for the mapping we requested, then both the
+        // type and the internal port (called "private port" by libnatpmp) should match.
+        // The other parameters, including the external port, are allowed to differ (see
+        // section 3.3 of the NAT-PMP RFC: https://datatracker.ietf.org/doc/html/rfc6886).
+        if (response.type != expectedType ||
+            response.pnu.newportmapping.privateport != expectedPrivatePort) {
+            responseValid = false;
+            if (logger_)
+                logger_->error("NAT-PMP: unexpected response to request for mapping {} from IGD {}"
+                               " [type={}, resultcode={}, privateport={}, mappedpublicport={}, lifetime={}]",
+                               mapping.toString(),
+                               igd_->toString(),
+                               response.type == NATPMP_RESPTYPE_UDPPORTMAPPING ? "UDP" : "TCP",
+                               response.resultcode,
+                               response.pnu.newportmapping.privateport,
+                               response.pnu.newportmapping.mappedpublicport,
+                               response.pnu.newportmapping.lifetime);
+        }
+    }
+
+    if (!responseValid) {
+        // Unfortunately, libnatpmp only allows reading one response per request sent; calling
+        // readResponse again at this point would result in a NATPMP_ERR_NOPENDINGREQ error.
+        // Since we can't know whether the mapping was actually created or not, we return an
+        // error to ensure the caller won't attempt to use a port mapping that doesn't exist.
+        return NATPMP_ERR_INVALIDARGS;
+    }
+
+    uint16_t newExternalPort = response.pnu.newportmapping.mappedpublicport;
+    uint32_t newLifetime = response.pnu.newportmapping.lifetime;
+    if (lifetime > 0) {
+        // We requested the creation/renewal of a mapping and didn't get an error, so at this point
+        // newExternalPort and newLifetime should both be nonzero.
+        if (newExternalPort == 0 || newLifetime == 0) {
+            if (logger_) logger_->error("NAT-PMP: response from IGD {} to request for mapping {}"
+                                        " indicates that the mapping was deleted [external port: {}, lifetime: {}]",
+                                        igd_->toString(),
+                                        mapping.toString(),
+                                        newExternalPort,
+                                        newLifetime);
+            return NATPMP_ERR_INVALIDARGS;
+        }
+    }
+
+    // We need to set the mapping's lifetime and external port here because NAT-PMP
+    // doesn't guarantee that the values returned by the IGD are those we requested.
+    lifetime = newLifetime;
+    mapping.setExternalPort(newExternalPort);
+    return 0;
 }
 
 int
@@ -549,18 +601,33 @@
 void
 NatPmp::removeAllMappings()
 {
-    if (logger_) logger_->warn("NAT-PMP: Send request to close all existing mappings to IGD {}",
+    if (logger_) logger_->debug("NAT-PMP: Send request to close all existing mappings to IGD {}",
               igd_->toString().c_str());
 
+    // NOTE: libnatpmp assumes that the response to each request will be read (see
+    // https://git.jami.net/savoirfairelinux/dhtnet/-/issues/33 for more details), so
+    // it's important that we call readResponse after each call to sendnewportmappingrequest
+    // below, even if we don't actually look at the content of the responses.
+    natpmpresp_t response;
     int err = sendnewportmappingrequest(&natpmpHdl_, NATPMP_PROTOCOL_TCP, 0, 0, 0);
     if (err < 0) {
         if (logger_) logger_->warn("NAT-PMP: Send close all TCP mappings request failed with error {}",
                   getNatPmpErrorStr(err));
+    } else {
+        err = readResponse(natpmpHdl_, response);
+        if (err < 0 && logger_)
+            logger_->warn("NAT-PMP: Failed to read response to TCP mappings deletion request: {}",
+                          getNatPmpErrorStr(err));
     }
     err = sendnewportmappingrequest(&natpmpHdl_, NATPMP_PROTOCOL_UDP, 0, 0, 0);
     if (err < 0) {
         if (logger_) logger_->warn("NAT-PMP: Send close all UDP mappings request failed with error {}",
                   getNatPmpErrorStr(err));
+    } else {
+        err = readResponse(natpmpHdl_, response);
+        if (err < 0 && logger_)
+            logger_->warn("NAT-PMP: Failed to read response to UDP mappings deletion request: {}",
+                          getNatPmpErrorStr(err));
     }
 }