Fixes for stalling scenery downloads.

- handle closed connections equivalent to IDLE, for timeout purposes
- if the server closes the socket in WAITING_FOR_RESPONSE state, fail
  the first sent request when restoring.

Note this does not explain why the server sometimes closes the socket
in this way, but at least it now causes a detectable failure.

diff --git a/simgear/io/HTTPClient.cxx b/simgear/io/HTTPClient.cxx
index 302a01f0b3c0b384a287efa96953a2ada4fdb3ce..26ebcb66ebe86617f193f74b68aae113dad0f051 100644 (file)
--- a/simgear/io/HTTPClient.cxx
+++ b/simgear/io/HTTPClient.cxx
@@ -106,10 +106,11 @@ public:
 class Connection : public NetChat
 {
 public:
-    Connection(Client* pr) :
+    Connection(Client* pr, const std::string& conId) :
         client(pr),
         state(STATE_CLOSED),
-        port(DEFAULT_HTTP_PORT)
+        port(DEFAULT_HTTP_PORT),
+        connectionId(conId)
     {
     }
 
@@ -140,6 +141,11 @@ public:
     virtual void handleError(int error)
     {
         const char* errStr = strerror(error);
+        SG_LOG(SG_IO, SG_WARN, "HTTP Connection handleError:" << error << " ("
+               << errStr << ")");
+
+        debugDumpRequests();
+
         if (!activeRequest)
         {
         // connection level failure, eg name lookup or routing
@@ -168,6 +174,11 @@ public:
         state = STATE_SOCKET_ERROR;
     }
 
+    void handleTimeout()
+    {
+        handleError(ETIMEDOUT);
+    }
+
     virtual void handleClose()
     {
         NetChat::handleClose();
@@ -180,6 +191,13 @@ public:
             state =  STATE_CLOSED;
             responseComplete();
         } else {
+            if (state == STATE_WAITING_FOR_RESPONSE) {
+                assert(!sentRequests.empty());
+                sentRequests.front()->setFailure(500, "server closed connection unexpectedly");
+                // no active request, but don't restore the front sent one
+                sentRequests.erase(sentRequests.begin());
+            }
+
             if (activeRequest) {
                 activeRequest->setFailure(500, "server closed connection");
                 // remove the failed request from sentRequests, so it does
@@ -207,19 +225,6 @@ public:
       sentRequests.clear();
     }
 
-    void handleTimeout()
-    {
-        NetChat::handleError(ETIMEDOUT);
-        if (activeRequest) {
-            SG_LOG(SG_IO, SG_DEBUG, "HTTP socket timeout");
-            activeRequest->setFailure(ETIMEDOUT, "socket timeout");
-            activeRequest = NULL;
-            _contentDecoder.reset();
-        }
-
-        state = STATE_SOCKET_ERROR;
-    }
-
     void queueRequest(const Request_ptr& r)
     {
         queuedRequests.push_back(r);
@@ -356,9 +361,7 @@ public:
           }
         }
 
-      //   SG_LOG(SG_IO, SG_INFO, "did start request:" << r->url() <<
-      //       "\n\t @ " << reinterpret_cast<void*>(r.ptr()) <<
-      //      "\n\t on connection " << this);
+        SG_LOG(SG_IO, SG_DEBUG, "con:" << connectionId << " did start request:" << r->url());
       // successfully sent, remove from queue, and maybe send the next
       queuedRequests.pop_front();
       sentRequests.push_back(r);
@@ -423,21 +426,23 @@ public:
 
     bool hasIdleTimeout() const
     {
-        if (state != STATE_IDLE) {
+        if ((state != STATE_IDLE) && (state != STATE_CLOSED)) {
             return false;
         }
 
         assert(sentRequests.empty());
-        return idleTime.elapsedMSec() > 1000 * 10; // ten seconds
+        bool isTimedOut = (idleTime.elapsedMSec() > (1000 * 10)); // 10 seconds
+        return isTimedOut;
     }
 
     bool hasErrorTimeout() const
     {
-      if (state == STATE_IDLE) {
+      if ((state == STATE_IDLE) || (state == STATE_CLOSED)) {
         return false;
       }
 
-      return idleTime.elapsedMSec() > (1000 * 30); // 30 seconds
+        bool isTimedOut = (idleTime.elapsedMSec() > (1000 * 30)); // 30 seconds
+        return isTimedOut;
     }
 
     bool hasError() const
@@ -454,17 +459,37 @@ public:
     {
         return !queuedRequests.empty() || !sentRequests.empty();
     }
+
+    void debugDumpRequests() const
+    {
+        SG_LOG(SG_IO, SG_DEBUG, "requests for:" << host << ":" << port << " (conId=" << connectionId
+               << "; state=" << state << ")");
+        if (activeRequest) {
+            SG_LOG(SG_IO, SG_DEBUG, "\tactive:" << activeRequest->url());
+        } else {
+            SG_LOG(SG_IO, SG_DEBUG, "\tNo active request");
+        }
+
+        BOOST_FOREACH(Request_ptr req, sentRequests) {
+            SG_LOG(SG_IO, SG_DEBUG, "\tsent:" << req->url());
+        }
+
+        BOOST_FOREACH(Request_ptr req, queuedRequests) {
+            SG_LOG(SG_IO, SG_DEBUG, "\tqueued:" << req->url());
+        }
+    }
 private:
     bool connectToHost()
     {
         SG_LOG(SG_IO, SG_DEBUG, "HTTP connecting to " << host << ":" << port);
 
         if (!open()) {
-            SG_LOG(SG_ALL, SG_WARN, "HTTP::Connection: connectToHost: open() failed");
+            SG_LOG(SG_IO, SG_WARN, "HTTP::Connection: connectToHost: open() failed");
             return false;
         }
 
         if (connect(host.c_str(), port) != 0) {
+            SG_LOG(SG_IO, SG_WARN, "HTTP::Connection: connectToHost: connect() failed");
             return false;
         }
 
@@ -605,7 +630,6 @@ private:
 
     // notify request after we change state, so this connection is idle
     // if completion triggers other requests (which is likely)
-        //   SG_LOG(SG_IO, SG_INFO, "*** responseComplete:" << activeRequest->url());
         completedRequest->responseComplete();
         client->requestFinished(this);
 
@@ -639,6 +663,7 @@ private:
     RequestList sentRequests;
 
     ContentDecoder _contentDecoder;
+    std::string connectionId;
 };
 #endif // of !ENABLE_CURL
 
@@ -910,7 +935,7 @@ void Client::makeRequest(const Request_ptr& r)
 
     // allocate a new connection object
     if (!con) {
-        con = new Connection(this);
+        con = new Connection(this, connectionId);
         con->setServer(host, port);
         d->poller.addChannel(con);
         d->connections.insert(d->connections.end(),
@@ -1080,6 +1105,20 @@ size_t Client::requestHeaderCallback(char *rawBuffer, size_t size, size_t nitems
   return byteSize;
 }
 
+void Client::debugDumpRequests()
+{
+#if defined(ENABLE_CURL)
+
+#else
+    SG_LOG(SG_IO, SG_INFO, "== HTTP connection dump");
+    ConnectionDict::iterator it = d->connections.begin();
+    for (; it != d->connections.end(); ++it) {
+        it->second->debugDumpRequests();
+    }
+    SG_LOG(SG_IO, SG_INFO, "==");
+#endif
+}
+
 } // of namespace HTTP
 
 } // of namespace simgear

diff --git a/simgear/io/HTTPClient.hxx b/simgear/io/HTTPClient.hxx
index a9b2eee62e220c2a282a3dbeb8e64f600a67aa21..5c8d9f6f7269b23e4241c857b27d6d1a1818f995 100644 (file)
--- a/simgear/io/HTTPClient.hxx
+++ b/simgear/io/HTTPClient.hxx
@@ -98,6 +98,8 @@ public:
      * monitoring
      */
     uint64_t totalBytesDownloaded() const;
+
+    void debugDumpRequests();
 private:
     // libCurl callbacks
     static size_t requestWriteCallback(char *ptr, size_t size, size_t nmemb, void *userdata);

diff --git a/simgear/io/sg_netChannel.cxx b/simgear/io/sg_netChannel.cxx
index 1561e8de464bbbc83413915f1b53d82ec2367727..303e4ba5c9555ea69d269bb1093072b827a85a75 100644 (file)
--- a/simgear/io/sg_netChannel.cxx
+++ b/simgear/io/sg_netChannel.cxx
@@ -227,6 +227,13 @@ void NetChannel::handleAccept (void) {
 
 void NetChannel::handleError (int error)
 {
+    if (error == EINPROGRESS) {
+        // this shoudl never happen, because we should use isNonBlocking to check
+        // such error codes.
+        SG_LOG(SG_IO, SG_WARN, "Got EINPROGRESS at NetChannel::handleError: suggests broken logic somewhere else");
+        return; // not an actual error, don't warn
+    }
+
     // warn about address lookup failures seperately, don't warn again.
     // (and we (ab-)use ENOENT to mean 'name not found'.
     if (error != ENOENT) {

diff --git a/simgear/io/test_HTTP.cxx b/simgear/io/test_HTTP.cxx
index d7bd1280b6d8ff5d06d0bc5216c1b0c918d1f87f..8106914890a5f3cfe17e4e43791f20d0a6f6397d 100644 (file)
--- a/simgear/io/test_HTTP.cxx
+++ b/simgear/io/test_HTTP.cxx
@@ -293,6 +293,12 @@ public:
             d << contentStr;
             push(d.str().c_str());
             closeAfterSending();
+        } else if (path == "/test_abrupt_close") {
+            // simulate server doing socket close before sending any
+            // response - this used to cause a TerraSync failure since we
+            // would get stuck restarting the request
+            closeAfterSending();
+
         } else if (path == "/test_args") {
             if ((args["foo"] != "abc") || (args["bar"] != "1234") || (args["username"] != "johndoe")) {
                 sendErrorResponse(400, true, "bad arguments");
@@ -654,15 +660,25 @@ int main(int argc, char* argv[])
     }
     cout << "done3" << endl;
 // test connectToHost failure
-/*
+
     {
         TestRequest* tr = new TestRequest("http://not.found/something");
         HTTP::Request_ptr own(tr);
         cl.makeRequest(tr);
-        waitForFailed(tr);
-        COMPARE(tr->responseCode(), -1);
+        waitForFailed(&cl, tr);
+        COMPARE(tr->responseCode(), ENOENT);
+    }
+
+
+    // test server-side abrupt close
+    {
+        TestRequest* tr = new TestRequest("http://localhost:2000/test_abrupt_close");
+        HTTP::Request_ptr own(tr);
+        cl.makeRequest(tr);
+        waitForFailed(&cl, tr);
+        COMPARE(tr->responseCode(), 500);
     }
-    */
+
 // test proxy
     {
         cl.setProxy("localhost", 2000);