Suppress HTTP input errors if there are too many of them; reduces log spam a fair...

diff --git a/httpinput.cpp b/httpinput.cpp
index 78e73a10eb9afeb5724ebbaa4efa6b0d9cb36f57..bf8a8b1dd22e609d6611193ae1cf327c96c3d758 100644 (file)
--- a/httpinput.cpp
+++ b/httpinput.cpp
@@ -50,13 +50,18 @@ HTTPInput::HTTPInput(const string &url, Input::Encoding encoding)
          url(url),
          encoding(encoding),
          has_metacube_header(false),
          url(url),
          encoding(encoding),
          has_metacube_header(false),

-         sock(-1)
+         sock(-1),
+         num_connection_attempts(0),
+         suppress_logging(false)

 {
        pthread_mutex_init(&stats_mutex, NULL);
        stats.url = url;
        stats.bytes_received = 0;
        stats.data_bytes_received = 0;
        stats.connect_time = -1;
 {
        pthread_mutex_init(&stats_mutex, NULL);
        stats.url = url;
        stats.bytes_received = 0;
        stats.data_bytes_received = 0;
        stats.connect_time = -1;

+
+       last_verbose_connection.tv_sec = -3600;
+       last_verbose_connection.tv_nsec = 0;

 }
 
 HTTPInput::HTTPInput(const InputProto &serialized)
 }
 
 HTTPInput::HTTPInput(const InputProto &serialized)


@@ -210,21 +215,27 @@ bool HTTPInput::parse_response(const string &request)
 {
        vector<string> lines = split_lines(response);
        if (lines.empty()) {
 {
        vector<string> lines = split_lines(response);
        if (lines.empty()) {

-               log(WARNING, "[%s] Empty HTTP response from input.", url.c_str());
+               if (!suppress_logging) {
+                       log(WARNING, "[%s] Empty HTTP response from input.", url.c_str());
+               }

                return false;
        }
 
        vector<string> first_line_tokens = split_tokens(lines[0]);
        if (first_line_tokens.size() < 2) {
                return false;
        }
 
        vector<string> first_line_tokens = split_tokens(lines[0]);
        if (first_line_tokens.size() < 2) {

-               log(WARNING, "[%s] Malformed response line '%s' from input.",
-                       url.c_str(), lines[0].c_str());
+               if (!suppress_logging) {
+                       log(WARNING, "[%s] Malformed response line '%s' from input.",
+                               url.c_str(), lines[0].c_str());
+               }

                return false;
        }
 
        int response = atoi(first_line_tokens[1].c_str());
        if (response != 200) {
                return false;
        }
 
        int response = atoi(first_line_tokens[1].c_str());
        if (response != 200) {

-               log(WARNING, "[%s] Non-200 response '%s' from input.",
-                       url.c_str(), lines[0].c_str());
+               if (!suppress_logging) {
+                       log(WARNING, "[%s] Non-200 response '%s' from input.",
+                               url.c_str(), lines[0].c_str());
+               }

                return false;
        }
 
                return false;
        }
 


@@ -296,7 +307,9 @@ void HTTPInput::do_work()
                        timespec elapsed = clock_diff(last_activity, now);
                        if (elapsed.tv_sec >= timeout_secs) {
                                // Timeout!
                        timespec elapsed = clock_diff(last_activity, now);
                        if (elapsed.tv_sec >= timeout_secs) {
                                // Timeout!

-                               log(ERROR, "[%s] Timeout after %d seconds, closing.", url.c_str(), elapsed.tv_sec);
+                               if (!suppress_logging) {
+                                       log(ERROR, "[%s] Timeout after %d seconds, closing.", url.c_str(), elapsed.tv_sec);
+                               }

                                state = CLOSING_SOCKET;
                                continue;
                        }
                                state = CLOSING_SOCKET;
                                continue;
                        }


@@ -331,7 +344,9 @@ void HTTPInput::do_work()
                        {
                                string protocol, user;  // Thrown away.
                                if (!parse_url(url, &protocol, &user, &host, &port, &path)) {
                        {
                                string protocol, user;  // Thrown away.
                                if (!parse_url(url, &protocol, &user, &host, &port, &path)) {

-                                       log(WARNING, "[%s] Failed to parse URL '%s'", url.c_str(), url.c_str());
+                                       if (!suppress_logging) {
+                                               log(WARNING, "[%s] Failed to parse URL '%s'", url.c_str(), url.c_str());
+                                       }

                                        break;
                                }
 
                                        break;
                                }
 


@@ -343,6 +358,24 @@ void HTTPInput::do_work()
                                }
                        }
 
                                }
                        }
 

+                       if (suppress_logging) {
+                               // See if there's more than one minute since last time we made a connection
+                               // with logging enabled. If so, turn it on again.
+                               timespec now;
+                               int err = clock_gettime(CLOCK_MONOTONIC_COARSE, &now);
+                               assert(err != -1);
+
+                               double elapsed = now.tv_sec - last_verbose_connection.tv_sec +
+                                       1e-9 * (now.tv_nsec - last_verbose_connection.tv_nsec);
+                               if (elapsed > 60.0) {
+                                       suppress_logging = false;
+                               }
+                       }
+                       if (!suppress_logging) {
+                               int err = clock_gettime(CLOCK_MONOTONIC_COARSE, &last_verbose_connection);
+                               assert(err != -1);
+                       }
+                       ++num_connection_attempts;

                        sock = lookup_and_connect(host, port);
                        if (sock != -1) {
                                // Yay, successful connect. Try to set it as nonblocking.
                        sock = lookup_and_connect(host, port);
                        if (sock != -1) {
                                // Yay, successful connect. Try to set it as nonblocking.


@@ -399,8 +432,10 @@ void HTTPInput::do_work()
 
                        if (ret == 0) {
                                // This really shouldn't happen...
 
                        if (ret == 0) {
                                // This really shouldn't happen...

-                               log(ERROR, "[%s] Socket unexpectedly closed while reading header",
-                                          url.c_str());
+                               if (!suppress_logging) {
+                                       log(ERROR, "[%s] Socket unexpectedly closed while reading header",
+                                                  url.c_str());
+                               }

                                state = CLOSING_SOCKET;
                                continue;
                        }
                                state = CLOSING_SOCKET;
                                continue;
                        }


@@ -408,7 +443,9 @@ void HTTPInput::do_work()
                        RequestParseStatus status = wait_for_double_newline(&response, buf, ret);
                        
                        if (status == RP_OUT_OF_SPACE) {
                        RequestParseStatus status = wait_for_double_newline(&response, buf, ret);
                        
                        if (status == RP_OUT_OF_SPACE) {

-                               log(WARNING, "[%s] Server sent overlong HTTP response!", url.c_str());
+                               if (!suppress_logging) {
+                                       log(WARNING, "[%s] Server sent overlong HTTP response!", url.c_str());
+                               }

                                state = CLOSING_SOCKET;
                                continue;
                        } else if (status == RP_NOT_FINISHED_YET) {
                                state = CLOSING_SOCKET;
                                continue;
                        } else if (status == RP_NOT_FINISHED_YET) {


@@ -435,13 +472,15 @@ void HTTPInput::do_work()
                                process_data(&extra_data[0], extra_data.size());
                        }
 
                                process_data(&extra_data[0], extra_data.size());
                        }
 

-                       if (encoding == Input::INPUT_ENCODING_RAW) {
-                               log(INFO, "[%s] Connected to '%s', receiving raw data.",
-                                          url.c_str(), url.c_str());
-                       } else {
-                               assert(encoding == Input::INPUT_ENCODING_METACUBE);
-                               log(INFO, "[%s] Connected to '%s', receiving data.",
-                                          url.c_str(), url.c_str());
+                       if (!suppress_logging) {
+                               if (encoding == Input::INPUT_ENCODING_RAW) {
+                                       log(INFO, "[%s] Connected to '%s', receiving raw data.",
+                                                  url.c_str(), url.c_str());
+                               } else {
+                                       assert(encoding == Input::INPUT_ENCODING_METACUBE);
+                                       log(INFO, "[%s] Connected to '%s', receiving data.",
+                                                  url.c_str(), url.c_str());
+                               }

                        }
                        state = RECEIVING_DATA;
                        break;
                        }
                        state = RECEIVING_DATA;
                        break;


@@ -462,12 +501,28 @@ void HTTPInput::do_work()
 
                        if (ret == 0) {
                                // This really shouldn't happen...
 
                        if (ret == 0) {
                                // This really shouldn't happen...

-                               log(ERROR, "[%s] Socket unexpectedly closed while reading data",
-                                          url.c_str());
+                               if (!suppress_logging) {
+                                       log(ERROR, "[%s] Socket unexpectedly closed while reading data",
+                                                  url.c_str());
+                               }

                                state = CLOSING_SOCKET;
                                continue;
                        }
 
                                state = CLOSING_SOCKET;
                                continue;
                        }
 

+                       num_connection_attempts = 0;  // Reset, since we have a successful read.
+                       if (suppress_logging) {
+                               // This was suppressed earlier, so print it out now.
+                               if (encoding == Input::INPUT_ENCODING_RAW) {
+                                       log(INFO, "[%s] Connected to '%s', receiving raw data.",
+                                                  url.c_str(), url.c_str());
+                               } else {
+                                       assert(encoding == Input::INPUT_ENCODING_METACUBE);
+                                       log(INFO, "[%s] Connected to '%s', receiving data.",
+                                                  url.c_str(), url.c_str());
+                               }
+                               suppress_logging = false;
+                       }
+

                        process_data(buf, ret);
                        break;
                }
                        process_data(buf, ret);
                        break;
                }


@@ -484,7 +539,15 @@ void HTTPInput::do_work()
                // or the connection just got closed.
                // The earlier steps have already given the error message, if any.
                if (state == NOT_CONNECTED && !should_stop()) {
                // or the connection just got closed.
                // The earlier steps have already given the error message, if any.
                if (state == NOT_CONNECTED && !should_stop()) {

-                       log(INFO, "[%s] Waiting 0.2 second and restarting...", url.c_str());
+                       if (!suppress_logging) {
+                               log(INFO, "[%s] Waiting 0.2 seconds and restarting...", url.c_str());
+                       }
+
+                       if (num_connection_attempts >= 3 && !suppress_logging) {
+                               log(INFO, "[%s] %d failed connection attempts, suppressing logging for one minute.",
+                                       url.c_str(), num_connection_attempts);
+                               suppress_logging = true;
+                       }

                        timespec timeout_ts;
                        timeout_ts.tv_sec = 0;
                        timeout_ts.tv_nsec = 200000000;
                        timespec timeout_ts;
                        timeout_ts.tv_sec = 0;
                        timeout_ts.tv_nsec = 200000000;

diff --git a/httpinput.h b/httpinput.h
index 823204d5b1cff4c264d348b70a731a93e29f1949..e7c447af52eb310da0d18b5a83cbc7272dfd5933 100644 (file)
--- a/httpinput.h
+++ b/httpinput.h
@@ -94,6 +94,17 @@ private:
 
        // The current statistics for this connection. Protected by <stats_mutex>.
        InputStats stats;
 
        // The current statistics for this connection. Protected by <stats_mutex>.
        InputStats stats;

+
+       // Number of (started) connection attempts since last data byte was successfully read.
+       unsigned num_connection_attempts;
+
+       // If set, don't log anything related to connections.
+       // (Only set if we've had enough unsuccessful connection attempts.)
+       bool suppress_logging;
+
+       // Last time we made a connection with logging enabled.
+       // (Initially at some point before the epoch.)
+       timespec last_verbose_connection;

 };
 
 #endif  // !defined(_HTTPINPUT_H)
 };
 
 #endif  // !defined(_HTTPINPUT_H)