Let serve() wait for keep-alive-timeout seconds for new requests
[privoxy.git] / jcc.c
diff --git a/jcc.c b/jcc.c
index f2fa2cf..059e9e6 100644 (file)
--- a/jcc.c
+++ b/jcc.c
@@ -1,4 +1,4 @@
-const char jcc_rcs[] = "$Id: jcc.c,v 1.379 2012/07/23 12:39:12 fabiankeil Exp $";
+const char jcc_rcs[] = "$Id: jcc.c,v 1.397 2012/10/21 12:51:07 fabiankeil Exp $";
 /*********************************************************************
  *
  * File        :  $Source: /cvsroot/ijbswa/current/jcc.c,v $
@@ -6,7 +6,7 @@ const char jcc_rcs[] = "$Id: jcc.c,v 1.379 2012/07/23 12:39:12 fabiankeil Exp $"
  * Purpose     :  Main file.  Contains main() method, main loop, and
  *                the main connection-handling function.
  *
- * Copyright   :  Written by and Copyright (C) 2001-2010 the
+ * Copyright   :  Written by and Copyright (C) 2001-2012 the
  *                Privoxy team. http://www.privoxy.org/
  *
  *                Based on the Internet Junkbuster originally written
@@ -661,6 +661,34 @@ static const char *crunch_reason(const struct http_response *rsp)
 }
 
 
+/*********************************************************************
+ *
+ * Function    :  log_applied_actions
+ *
+ * Description :  Logs the applied actions if LOG_LEVEL_ACTIONS is
+ *                enabled.
+ *
+ * Parameters  :
+ *          1  :  actions = Current action spec to log
+ *
+ * Returns     :  Nothing.
+ *
+ *********************************************************************/
+static void log_applied_actions(const struct current_action_spec *actions)
+{
+   /*
+    * The conversion to text requires lots of memory allocations so
+    * we only do the conversion if the user is actually interested.
+    */
+   if (debug_level_is_enabled(LOG_LEVEL_ACTIONS))
+   {
+      char *actions_as_text = actions_to_line_of_text(actions);
+      log_error(LOG_LEVEL_ACTIONS, "%s", actions_as_text);
+      freez(actions_as_text);
+   }
+}
+
+
 /*********************************************************************
  *
  * Function    :  send_crunch_response
@@ -705,6 +733,7 @@ static void send_crunch_response(const struct client_state *csp, struct http_res
       status_code[3] = '\0';
 
       /* Log that the request was crunched and why. */
+      log_applied_actions(csp->action);
       log_error(LOG_LEVEL_CRUNCH, "%s: %s", crunch_reason(rsp), http->url);
       log_error(LOG_LEVEL_CLF, "%s - - [%T] \"%s\" %s %u",
          csp->ip_addr_str, http->ocmd, status_code, rsp->content_length);
@@ -1050,7 +1079,7 @@ void save_connection_destination(jb_socket sfd,
 static void verify_request_length(struct client_state *csp)
 {
    unsigned long long buffered_request_bytes =
-      (unsigned long long)(csp->iob->eod - csp->iob->cur);
+      (unsigned long long)(csp->client_iob->eod - csp->client_iob->cur);
 
    if ((csp->expected_client_content_length != 0)
       && (buffered_request_bytes != 0))
@@ -1064,8 +1093,8 @@ static void verify_request_length(struct client_state *csp)
       }
       else
       {
-         assert(csp->iob->eod > csp->iob->cur + csp->expected_client_content_length);
-         csp->iob->eod = csp->iob->cur + csp->expected_client_content_length;
+         assert(csp->client_iob->eod > csp->client_iob->cur + csp->expected_client_content_length);
+         csp->client_iob->eod = csp->client_iob->cur + csp->expected_client_content_length;
          log_error(LOG_LEVEL_CONNECT, "Reducing expected bytes to 0. "
             "Marking the server socket tainted after throwing %llu bytes away.",
             buffered_request_bytes - csp->expected_client_content_length);
@@ -1080,7 +1109,7 @@ static void verify_request_length(struct client_state *csp)
    }
 
    if (!(csp->flags & CSP_FLAG_CLIENT_REQUEST_COMPLETELY_READ)
-    && ((csp->iob->cur[0] != '\0') || (csp->expected_client_content_length != 0)))
+    && ((csp->client_iob->cur[0] != '\0') || (csp->expected_client_content_length != 0)))
    {
       csp->flags |= CSP_FLAG_SERVER_SOCKET_TAINTED;
       if (strcmpic(csp->http->gpc, "GET")
@@ -1102,8 +1131,8 @@ static void verify_request_length(struct client_state *csp)
             "Possible pipeline attempt detected. The connection will not "
             "be kept alive and we will only serve the first request.");
          /* Nuke the pipelined requests from orbit, just to be sure. */
-         csp->iob->buf[0] = '\0';
-         csp->iob->eod = csp->iob->cur = csp->iob->buf;
+         csp->client_iob->buf[0] = '\0';
+         csp->client_iob->eod = csp->client_iob->cur = csp->client_iob->buf;
       }
    }
    else
@@ -1196,12 +1225,12 @@ static char *get_request_line(struct client_state *csp)
        * If there is no memory left for buffering the
        * request, there is nothing we can do but hang up
        */
-      if (add_to_iob(csp, buf, len))
+      if (add_to_iob(csp->client_iob, csp->config->buffer_limit, buf, len))
       {
          return NULL;
       }
 
-      request_line = get_header(csp->iob);
+      request_line = get_header(csp->client_iob);
 
    } while ((NULL != request_line) && ('\0' == *request_line));
 
@@ -1293,7 +1322,7 @@ static jb_err receive_client_request(struct client_state *csp)
    init_list(headers);
    for (;;)
    {
-      p = get_header(csp->iob);
+      p = get_header(csp->client_iob);
 
       if (p == NULL)
       {
@@ -1323,7 +1352,7 @@ static jb_err receive_client_request(struct client_state *csp)
             return JB_ERR_PARSE;
          }
 
-         if (add_to_iob(csp, buf, len))
+         if (add_to_iob(csp->client_iob, csp->config->buffer_limit, buf, len))
          {
             /*
              * If there is no memory left for buffering the
@@ -1425,6 +1454,12 @@ static jb_err parse_client_request(struct client_state *csp)
       /* Assume persistence until further notice */
       csp->flags |= CSP_FLAG_CLIENT_CONNECTION_KEEP_ALIVE;
    }
+
+   if (csp->http->ssl == 0)
+   {
+      csp->expected_client_content_length = get_expected_content_length(csp->headers);
+      verify_request_length(csp);
+   }
 #endif /* def FEATURE_CONNECTION_KEEP_ALIVE */
 
    err = sed(csp, FILTER_CLIENT_HEADERS);
@@ -1455,13 +1490,6 @@ static jb_err parse_client_request(struct client_state *csp)
       return JB_ERR_PARSE;
    }
 
-#ifdef FEATURE_CONNECTION_KEEP_ALIVE
-   if (csp->http->ssl == 0)
-   {
-      verify_request_length(csp);
-   }
-#endif /* def FEATURE_CONNECTION_KEEP_ALIVE */
-
    return JB_ERR_OK;
 
 }
@@ -1602,6 +1630,7 @@ static void chat(struct client_state *csp)
       return;
    }
 
+   log_applied_actions(csp->action);
    log_error(LOG_LEVEL_GPC, "%s%s", http->hostport, http->path);
 
    if (fwd->forward_host)
@@ -1673,6 +1702,7 @@ static void chat(struct client_state *csp)
 
    if (fwd->forward_host || (http->ssl == 0))
    {
+      int write_failure;
       hdr = list_to_text(csp->headers);
       if (hdr == NULL)
       {
@@ -1685,22 +1715,30 @@ static void chat(struct client_state *csp)
        * Write the client's (modified) header to the server
        * (along with anything else that may be in the buffer)
        */
-      if (write_socket(csp->server_connection.sfd, hdr, strlen(hdr))
-       || (flush_socket(csp->server_connection.sfd, csp->iob) <  0))
+      write_failure = 0 != write_socket(csp->server_connection.sfd, hdr, strlen(hdr));
+      freez(hdr);
+
+      if (write_failure)
       {
          log_error(LOG_LEVEL_CONNECT,
-            "write header to: %s failed: %E", http->hostport);
+            "Failed sending request headers to: %s: %E", http->hostport);
+      }
+      else if (flush_socket(csp->server_connection.sfd, csp->client_iob) <  0))
+      {
+         write_failure = 1;
+         log_error(LOG_LEVEL_CONNECT,
+            "Failed sending request body to: %s: %E", http->hostport);
+      }
 
+      if (write_failure)
+      {
          rsp = error_response(csp, "connect-failed");
          if (rsp)
          {
             send_crunch_response(csp, rsp);
          }
-
-         freez(hdr);
          return;
       }
-      freez(hdr);
    }
    else
    {
@@ -1714,7 +1752,7 @@ static void chat(struct client_state *csp)
       {
          return;
       }
-      IOB_RESET(csp);
+      IOB_RESET(csp->client_iob);
    }
 
    log_error(LOG_LEVEL_CONNECT, "to %s successful", http->hostport);
@@ -1938,7 +1976,6 @@ static void chat(struct client_state *csp)
          }
 #endif /* def FEATURE_CONNECTION_KEEP_ALIVE */
 
-         fflush(NULL);
          len = read_socket(csp->server_connection.sfd, buf, sizeof(buf) - 1);
 
          if (len < 0)
@@ -2115,7 +2152,7 @@ static void chat(struct client_state *csp)
                 * has been reached, switch to non-filtering mode, i.e. make & write the
                 * header, flush the iob and buf, and get out of the way.
                 */
-               if (add_to_iob(csp, buf, len))
+               if (add_to_iob(csp->iob, csp->config->buffer_limit, buf, len))
                {
                   size_t hdrlen;
                   long flushed;
@@ -2179,7 +2216,7 @@ static void chat(struct client_state *csp)
              * Buffer up the data we just read.  If that fails, there's
              * little we can do but send our static out-of-memory page.
              */
-            if (add_to_iob(csp, buf, len))
+            if (add_to_iob(csp->iob, csp->config->buffer_limit, buf, len))
             {
                log_error(LOG_LEVEL_ERROR, "Out of memory while looking for end of server headers.");
                rsp = cgi_error_memory();
@@ -2214,8 +2251,8 @@ static void chat(struct client_state *csp)
                    * we can parse the headers we just continue here.
                    */
                   log_error(LOG_LEVEL_CONNECT,
-                     "Continuing buffering headers. Bytes most recently read: %d.",
-                     len);
+                     "Continuing buffering server headers from socket %d. "
+                     "Bytes most recently read: %d.", csp->cfd, len);
                   continue;
                }
             }
@@ -2430,8 +2467,7 @@ static void prepare_csp_for_next_request(struct client_state *csp)
    csp->expected_content_length = 0;
    csp->expected_client_content_length = 0;
    list_remove_all(csp->headers);
-   freez(csp->iob->buf);
-   memset(csp->iob, 0, sizeof(csp->iob));
+   IOB_RESET(csp->iob);
    freez(csp->error_message);
    free_http_request(csp->http);
    destroy_list(csp->headers);
@@ -2477,11 +2513,14 @@ static void serve(struct client_state *csp)
    static int monitor_thread_running = 0;
 #endif /* def FEATURE_CONNECTION_SHARING */
    int continue_chatting = 0;
+   int config_file_change_detected = 0; /* Only used for debugging */
+
+   log_error(LOG_LEVEL_CONNECT, "Accepted connection from %s on socket %d",
+      csp->ip_addr_str, csp->cfd);
 
    do
    {
       unsigned int latency;
-      int config_file_change_detected = 0; /* Only used for debugging */
 
       chat(csp);
 
@@ -2495,27 +2534,40 @@ static void serve(struct client_state *csp)
       continue_chatting = (csp->config->feature_flags
          & RUNTIME_FEATURE_CONNECTION_KEEP_ALIVE)
          && !(csp->flags & CSP_FLAG_SERVER_SOCKET_TAINTED)
-         && ((csp->flags & CSP_FLAG_SERVER_CONNECTION_KEEP_ALIVE)
-             || (csp->flags & CSP_FLAG_CRUNCHED))
          && (csp->cfd != JB_INVALID_SOCKET)
          && ((csp->flags & CSP_FLAG_CLIENT_CONNECTION_KEEP_ALIVE)
              || (csp->config->feature_flags &
                 RUNTIME_FEATURE_CONNECTION_SHARING));
 
-      if (continue_chatting && !(csp->flags & CSP_FLAG_CRUNCHED))
+      if (!(csp->flags & CSP_FLAG_CRUNCHED)
+         && (csp->server_connection.sfd != JB_INVALID_SOCKET))
       {
-         continue_chatting = (csp->server_connection.sfd != JB_INVALID_SOCKET)
-            && socket_is_still_alive(csp->server_connection.sfd);
-         if (continue_chatting)
+         if (!(csp->flags & CSP_FLAG_SERVER_KEEP_ALIVE_TIMEOUT_SET))
          {
-            if (!(csp->flags & CSP_FLAG_SERVER_KEEP_ALIVE_TIMEOUT_SET))
+            csp->server_connection.keep_alive_timeout = csp->config->default_server_timeout;
+         }
+         if (!(csp->flags & CSP_FLAG_SERVER_CONNECTION_KEEP_ALIVE)
+            || (csp->flags & CSP_FLAG_SERVER_SOCKET_TAINTED)
+            || !socket_is_still_alive(csp->server_connection.sfd)
+            || !(latency < csp->server_connection.keep_alive_timeout))
+         {
+            log_error(LOG_LEVEL_CONNECT,
+               "Closing connection on server socket %d to %s: "
+               "keep-alive %u, tainted: %u, socket alive %u. %s timeout: %u.",
+               csp->server_connection.sfd, csp->server_connection.host,
+               0 != (csp->flags & CSP_FLAG_SERVER_CONNECTION_KEEP_ALIVE),
+               0 != (csp->flags & CSP_FLAG_SERVER_SOCKET_TAINTED),
+               socket_is_still_alive(csp->server_connection.sfd),
+               ((csp->flags & CSP_FLAG_SERVER_KEEP_ALIVE_TIMEOUT_SET) ?
+               "Specified" : "Assumed"), csp->server_connection.keep_alive_timeout);
+#ifdef FEATURE_CONNECTION_SHARING
+            if (csp->config->feature_flags & RUNTIME_FEATURE_CONNECTION_SHARING)
             {
-               csp->server_connection.keep_alive_timeout = csp->config->default_server_timeout;
-               log_error(LOG_LEVEL_CONNECT,
-                  "The server didn't specify how long the connection will stay open. "
-                  "Assumed timeout is: %u.", csp->server_connection.keep_alive_timeout);
+               forget_connection(csp->server_connection.sfd);
             }
-            continue_chatting = (latency < csp->server_connection.keep_alive_timeout);
+#endif /* def FEATURE_CONNECTION_SHARING */
+            close_socket(csp->server_connection.sfd);
+            mark_connection_closed(&csp->server_connection);
          }
       }
 
@@ -2527,13 +2579,10 @@ static void serve(struct client_state *csp)
 
       if (continue_chatting)
       {
-         unsigned int client_timeout = 1; /* XXX: Use something else here? */
-
          if (0 != (csp->flags & CSP_FLAG_CLIENT_CONNECTION_KEEP_ALIVE))
          {
             if (csp->server_connection.sfd != JB_INVALID_SOCKET)
             {
-               client_timeout = (unsigned)csp->server_connection.keep_alive_timeout - latency;
                log_error(LOG_LEVEL_CONNECT,
                   "Waiting for the next client request on socket %d. "
                   "Keeping the server socket %d to %s open.",
@@ -2547,7 +2596,7 @@ static void serve(struct client_state *csp)
             }
          }
          if ((csp->flags & CSP_FLAG_CLIENT_CONNECTION_KEEP_ALIVE)
-            && data_is_available(csp->cfd, (int)client_timeout)
+            && data_is_available(csp->cfd, (int)csp->config->keep_alive_timeout)
             && socket_is_still_alive(csp->cfd))
          {
             log_error(LOG_LEVEL_CONNECT,
@@ -2556,14 +2605,9 @@ static void serve(struct client_state *csp)
          }
          else
          {
-            if (0 != (csp->flags & CSP_FLAG_CLIENT_CONNECTION_KEEP_ALIVE))
-            {
-               log_error(LOG_LEVEL_CONNECT,
-                  "No additional client request received in time on socket %d.",
-                  csp->cfd);
-            }
 #ifdef FEATURE_CONNECTION_SHARING
             if ((csp->config->feature_flags & RUNTIME_FEATURE_CONNECTION_SHARING)
+               && (csp->server_connection.sfd != JB_INVALID_SOCKET)
                && (socket_is_still_alive(csp->server_connection.sfd)))
             {
                time_t time_open = time(NULL) - csp->server_connection.timestamp;
@@ -2575,7 +2619,7 @@ static void serve(struct client_state *csp)
 
                remember_connection(&csp->server_connection);
                csp->server_connection.sfd = JB_INVALID_SOCKET;
-               close_socket(csp->cfd);
+               drain_and_close_socket(csp->cfd);
                csp->cfd = JB_INVALID_SOCKET;
                privoxy_mutex_lock(&connection_reuse_mutex);
                if (!monitor_thread_running)
@@ -2595,15 +2639,13 @@ static void serve(struct client_state *csp)
       else if (csp->server_connection.sfd != JB_INVALID_SOCKET)
       {
          log_error(LOG_LEVEL_CONNECT,
-            "The connection on server socket %d to %s isn't reusable. Closing. "
-            "Server connection: keep-alive %u, tainted: %u, socket alive %u. "
-            "Client connection: socket alive: %u. Server timeout: %u. "
+            "Closing server socket %d connected to %s. Keep-alive %u. "
+            "Tainted: %u. Socket alive %u. Timeout: %u. "
             "Configuration file change detected: %u",
             csp->server_connection.sfd, csp->server_connection.host,
             0 != (csp->flags & CSP_FLAG_SERVER_CONNECTION_KEEP_ALIVE),
             0 != (csp->flags & CSP_FLAG_SERVER_SOCKET_TAINTED),
             socket_is_still_alive(csp->server_connection.sfd),
-            socket_is_still_alive(csp->cfd),
             csp->server_connection.keep_alive_timeout,
             config_file_change_detected);
       }
@@ -2630,7 +2672,13 @@ static void serve(struct client_state *csp)
 
    if (csp->cfd != JB_INVALID_SOCKET)
    {
-      close_socket(csp->cfd);
+      log_error(LOG_LEVEL_CONNECT, "Closing client socket %d. "
+         "Keep-alive: %u, Socket alive: %u. Data available: %u. "
+         "Configuration file change detected: %u.",
+         csp->cfd, 0 != (csp->flags & CSP_FLAG_CLIENT_CONNECTION_KEEP_ALIVE),
+         socket_is_still_alive(csp->cfd), data_is_available(csp->cfd, 0),
+         config_file_change_detected);
+      drain_and_close_socket(csp->cfd);
    }
 
    csp->flags &= ~CSP_FLAG_ACTIVE;
@@ -3032,12 +3080,7 @@ int main(int argc, char **argv)
       basedir = strdup_or_die(cwd);
       /* XXX: why + 5? */
       abs_file_size = strlen(cwd) + strlen(configfile) + 5;
-      abs_file = malloc(abs_file_size);
-      if (NULL == abs_file)
-      {
-         perror("malloc failed");
-         exit(1);
-      }
+      abs_file = malloc_or_die(abs_file_size);
       strlcpy(abs_file, basedir, abs_file_size);
       strlcat(abs_file, "/", abs_file_size);
       strlcat(abs_file, configfile, abs_file_size);
@@ -3526,12 +3569,6 @@ static void listen_loop(void)
          freez(csp_list);
          continue;
       }
-      else
-      {
-         log_error(LOG_LEVEL_CONNECT,
-            "accepted connection from %s on socket %d",
-            csp->ip_addr_str, csp->cfd);
-      }
 
       csp->flags |= CSP_FLAG_ACTIVE;
       csp->server_connection.sfd = JB_INVALID_SOCKET;