]> git.ipfire.org Git - thirdparty/squid.git/commitdiff
Bug 3319: Inconsistencies in error messages pt2
authorAmos Jeffries <squid3@treenet.co.nz>
Fri, 2 Sep 2011 12:35:57 +0000 (00:35 +1200)
committerAmos Jeffries <squid3@treenet.co.nz>
Fri, 2 Sep 2011 12:35:57 +0000 (00:35 +1200)
15 files changed:
src/auth/basic/UserRequest.cc
src/client_side_request.cc
src/comm/ModDevPoll.cc
src/comm/ModEpoll.cc
src/comm/ModKqueue.cc
src/comm/ModPoll.cc
src/comm/ModSelect.cc
src/comm/ModSelectWin32.cc
src/filemap.cc
src/ftp.cc
src/helper.cc
src/htcp.cc
src/ipcache.cc
src/peer_digest.cc
src/ssl/support.cc

index bad3a2b16bec5534c5125516a0525bc4f3c072f4..bdad04209377738c4e278386ea3146e9d0cc188a 100644 (file)
@@ -140,7 +140,7 @@ AuthBasicUserRequest::HandleReply(void *data, char *reply)
     BasicAuthQueueNode *tmpnode;
     char *t = NULL;
     void *cbdata;
-    debugs(29, 9, HERE << "{" << (reply ? reply : "<NULL>") << "}");
+    debugs(29, 5, HERE << "{" << (reply ? reply : "<NULL>") << "}");
 
     if (reply) {
         if ((t = strchr(reply, ' ')))
index 08a38ad3a574c28ffc99194a4e238886c43e9dfe..f81481c74f5f244ebf4d0146d75e68968ec5ddb3 100644 (file)
@@ -873,7 +873,7 @@ clientRedirectAccessCheckDone(allow_t answer, void *data)
 void
 ClientRequestContext::clientRedirectStart()
 {
-    debugs(33, 5, "clientRedirectStart: '" << http->uri << "'");
+    debugs(33, 5, HERE << "'" << http->uri << "'");
 
     if (Config.accessList.redirector) {
         acl_checklist = clientAclChecklistCreate(Config.accessList.redirector, http);
index 614ac85416621af334c6e356cbc5e963f759c34b..8db2585e74d40c90411cecac4509d2038e695f42 100644 (file)
@@ -247,13 +247,9 @@ void
 Comm::SetSelect(int fd, unsigned int type, PF * handler, void *client_data, time_t timeout)
 {
     assert(fd >= 0);
-    debugs(
-        5,
-        DEBUG_DEVPOLL ? 0 : 8,
-        HERE << "FD " << fd << ",type=" << type
-        << ",handler=" << handler << ",client_data=" << client_data
-        << ",timeout=" << timeout << ")"
-    );
+    debugs(5, 5, HERE << "FD " << fd << ", type=" << type <<
+           ", handler=" << handler << ", client_data=" << client_data <<
+           ", timeout=" << timeout);
 
     /* POLLIN/POLLOUT are defined in <sys/poll.h> */
     fde *F = &fd_table[fd];
index af9790ace8f6ad382b7d12e9435203a527a40ab0..f19df2f2c7dfa9d20bb6e0f16db27348b4dc8d9e 100644 (file)
@@ -132,7 +132,7 @@ Comm::SetSelect(int fd, unsigned int type, PF * handler, void *client_data, time
 
     struct epoll_event ev;
     assert(fd >= 0);
-    debugs(5, DEBUG_EPOLL ? 0 : 8, HERE << "FD " << fd << ", type=" << type <<
+    debugs(5, 5, HERE << "FD " << fd << ", type=" << type <<
            ", handler=" << handler << ", client_data=" << client_data <<
            ", timeout=" << timeout);
 
index 3364853d343ac2e140b873d94d57b2d89b05c404..de3616cf173925762f7800672dd84c994587520a 100644 (file)
@@ -194,6 +194,9 @@ Comm::SetSelect(int fd, unsigned int type, PF * handler, void *client_data, time
     fde *F = &fd_table[fd];
     assert(fd >= 0);
     assert(F->flags.open);
+    debugs(5, 5, HERE << "FD " << fd << ", type=" << type <<
+           ", handler=" << handler << ", client_data=" << client_data <<
+           ", timeout=" << timeout);
 
     if (type & COMM_SELECT_READ) {
         kq_update_events(fd, EVFILT_READ, handler);
index 0d80fb47138f8088850798db6a9f3ac3ef3fd687..cbb00bc971a9f25b7aaae83b74bff944c0783f1a 100644 (file)
@@ -144,7 +144,9 @@ Comm::SetSelect(int fd, unsigned int type, PF * handler, void *client_data, time
     fde *F = &fd_table[fd];
     assert(fd >= 0);
     assert(F->flags.open);
-    debugs(5, 5, "commSetSelect: FD " << fd << " type " << type);
+    debugs(5, 5, HERE << "FD " << fd << ", type=" << type <<
+           ", handler=" << handler << ", client_data=" << client_data <<
+           ", timeout=" << timeout);
 
     if (type & COMM_SELECT_READ) {
         F->read_handler = handler;
@@ -513,7 +515,7 @@ Comm::DoSelect(int msec)
             }
 
             if (revents & (POLLWRNORM | POLLOUT | POLLHUP | POLLERR)) {
-                debugs(5, 5, "comm_poll: FD " << fd << " ready for writing");
+                debugs(5, 6, "comm_poll: FD " << fd << " ready for writing");
 
                 if ((hdl = F->write_handler)) {
                     PROF_start(comm_write_handler);
index d7c773393cde4bdfb0ce2a6a6447c600bfab13b9..d18feef2a765d036cf2cb6dc43eaaa6fe4307d72 100644 (file)
@@ -139,7 +139,9 @@ Comm::SetSelect(int fd, unsigned int type, PF * handler, void *client_data, time
     fde *F = &fd_table[fd];
     assert(fd >= 0);
     assert(F->flags.open);
-    debugs(5, 5, HERE << "FD " << fd << " type " << type);
+    debugs(5, 5, HERE << "FD " << fd << ", type=" << type <<
+           ", handler=" << handler << ", client_data=" << client_data <<
+           ", timeout=" << timeout);
 
     if (type & COMM_SELECT_READ) {
         F->read_handler = handler;
@@ -585,7 +587,7 @@ Comm::DoSelect(int msec)
                 }
 
                 F = &fd_table[fd];
-                debugs(5, 5, "comm_select: FD " << fd << " ready for writing");
+                debugs(5, 6, "comm_select: FD " << fd << " ready for writing");
 
                 if ((hdl = F->write_handler)) {
                     F->write_handler = NULL;
index 2e190904fa8c38e42f746081d3c89f9a2bb2ddd5..4763437949691d921f49a3389e699d21d33012c7 100644 (file)
@@ -138,7 +138,9 @@ Comm::SetSelect(int fd, unsigned int type, PF * handler, void *client_data, time
     fde *F = &fd_table[fd];
     assert(fd >= 0);
     assert(F->flags.open);
-    debugs(5, 5, "commSetSelect: FD " << fd << " type " << type);
+    debugs(5, 5, HERE << "FD " << fd << ", type=" << type <<
+           ", handler=" << handler << ", client_data=" << client_data <<
+           ", timeout=" << timeout);
 
     if (type & COMM_SELECT_READ) {
         F->read_handler = handler;
@@ -608,7 +610,7 @@ Comm::DoSelect(int msec)
             }
 
             F = &fd_table[fd];
-            debugs(5, 5, "comm_select: FD " << fd << " ready for writing");
+            debugs(5, 6, "comm_select: FD " << fd << " ready for writing");
 
             if ((hdl = F->write_handler)) {
                 F->write_handler = NULL;
index d6d41ad1c937e003af614f5cd852c65ad528a0ca..10bcb0091f28d10fd6dc483a0d1d1be4fa6b7984 100644 (file)
@@ -76,6 +76,7 @@ file_map_grow(fileMap * fm)
     assert(fm->max_n_files <= (1 << 24));      /* swap_filen is 25 bits, signed */
     fm->nwords = fm->max_n_files >> LONG_BIT_SHIFT;
     debugs(8, 3, "file_map_grow: creating space for " << fm->max_n_files << " files");
+    debugs(8, 5, "--> " << fm->nwords << " words of " << sizeof(*fm->file_map) << " bytes each");
     fm->file_map = (unsigned long *)xcalloc(fm->nwords, sizeof(*fm->file_map));
     debugs(8, 3, "copying " << old_sz << " old bytes");
     memcpy(fm->file_map, old_map, old_sz);
index 150c4edaad3b801e73bf21ca287b6696b3f608be..2e34f30cec908e8da31e30e7a74068344ce3fdcc 100644 (file)
@@ -3232,7 +3232,7 @@ ftpReadRetr(FtpStateData * ftpState)
 
     if (code == 125 || (code == 150 && Comm::IsConnOpen(ftpState->data.conn))) {
         /* Begin data transfer */
-        debugs(9, 3, HERE << "reading data channel");
+        debugs(9, 3, HERE << "begin data transfer from " << ftpState->data.conn->remote << " (" << ftpState->data.conn->local << ")");
         ftpState->switchTimeoutToDataChannel();
         ftpState->maybeReadVirginBody();
         ftpState->state = READING_DATA;
index ae56fe7cb268db89433d813429a0d810ccfcc075..6a1ce2aca4036e186507b478535e7ddb11c00814 100644 (file)
@@ -1093,6 +1093,7 @@ GetFirstAvailable(helper * hlp)
     dlink_node *n;
     helper_server *srv;
     helper_server *selected = NULL;
+    debugs(84, 5, "GetFirstAvailable: Running servers " << hlp->childs.n_running);
 
     if (hlp->childs.n_running == 0)
         return NULL;
@@ -1119,12 +1120,17 @@ GetFirstAvailable(helper * hlp)
     }
 
     /* Check for overload */
-    if (!selected)
+    if (!selected) {
+        debugs(84, 5, "GetFirstAvailable: None available.");
         return NULL;
+    }
 
-    if (selected->stats.pending >= (hlp->childs.concurrency ? hlp->childs.concurrency : 1))
+    if (selected->stats.pending >= (hlp->childs.concurrency ? hlp->childs.concurrency : 1)) {
+        debugs(84, 3, "GetFirstAvailable: Least-loaded helper is overloaded!");
         return NULL;
+    }
 
+    debugs(84, 5, "GetFirstAvailable: returning srv-" << selected->index);
     return selected;
 }
 
index 5c5fbd90dddb3d1b3b3ed005863ab7a95620b0e9..1e2d0a6cd9fb23a24eccffd1cadd93e66b4638bc 100644 (file)
@@ -1171,7 +1171,6 @@ htcpHandleTstResponse(htcpDataHeader * hdr, char *buf, int sz, Ip::Address &from
 }
 
 static void
-
 htcpHandleTstRequest(htcpDataHeader * dhdr, char *buf, int sz, Ip::Address &from)
 {
     /* buf should be a SPECIFIER */
@@ -1193,27 +1192,27 @@ htcpHandleTstRequest(htcpDataHeader * dhdr, char *buf, int sz, Ip::Address &from
     s->setDataHeader(dhdr);
 
     if (NULL == s) {
-        debugs(31, 2, "htcpHandleTstRequest: htcpUnpackSpecifier failed");
+        debugs(31, 3, "htcpHandleTstRequest: htcpUnpackSpecifier failed");
         htcpLogHtcp(from, dhdr->opcode, LOG_UDP_INVALID, dash_str);
         return;
     }
 
     if (!s->request) {
-        debugs(31, 2, "htcpHandleTstRequest: failed to parse request");
+        debugs(31, 3, "htcpHandleTstRequest: failed to parse request");
         htcpLogHtcp(from, dhdr->opcode, LOG_UDP_INVALID, dash_str);
         htcpFreeSpecifier(s);
         return;
     }
 
     if (!htcpAccessAllowed(Config.accessList.htcp, s, from)) {
-        debugs(31, 2, "htcpHandleTstRequest: Access denied");
+        debugs(31, 3, "htcpHandleTstRequest: Access denied");
         htcpLogHtcp(from, dhdr->opcode, LOG_UDP_DENIED, s->uri);
         htcpFreeSpecifier(s);
         return;
     }
 
-    debugs(31, 3, "htcpHandleTstRequest: " << s->method << " " << s->uri << " " << s->version);
-    debugs(31, 3, "htcpHandleTstRequest: " << s->req_hdrs);
+    debugs(31, 2, "HTCP TST request: " << s->method << " " << s->uri << " " << s->version);
+    debugs(31, 2, "HTCP TST headers: " << s->req_hdrs);
     s->checkHit();
 }
 
@@ -1251,7 +1250,7 @@ htcpHandleClr(htcpDataHeader * hdr, char *buf, int sz, Ip::Address &from)
     htcpSpecifier *s;
     /* buf[0/1] is reserved and reason */
     int reason = buf[1] << 4;
-    debugs(31, 3, "htcpHandleClr: reason=" << reason);
+    debugs(31, 2, "HTCP CLR reason: " << reason);
     buf += 2;
     sz -= 2;
 
@@ -1272,21 +1271,21 @@ htcpHandleClr(htcpDataHeader * hdr, char *buf, int sz, Ip::Address &from)
     }
 
     if (!s->request) {
-        debugs(31, 2, "htcpHandleTstRequest: failed to parse request");
+        debugs(31, 3, "htcpHandleTstRequest: failed to parse request");
         htcpLogHtcp(from, hdr->opcode, LOG_UDP_INVALID, dash_str);
         htcpFreeSpecifier(s);
         return;
     }
 
     if (!htcpAccessAllowed(Config.accessList.htcp_clr, s, from)) {
-        debugs(31, 2, "htcpHandleClr: Access denied");
+        debugs(31, 3, "htcpHandleClr: Access denied");
         htcpLogHtcp(from, hdr->opcode, LOG_UDP_DENIED, s->uri);
         htcpFreeSpecifier(s);
         return;
     }
 
-    debugs(31, 5, "htcpHandleClr: " << s->method << " " << s->uri << " " << s->version);
-    debugs(31, 5, "htcpHandleClr: request headers: " << s->req_hdrs);
+    debugs(31, 2, "HTCP CLR request: " << s->method << " " << s->uri << " " << s->version);
+    debugs(31, 2, "HTCP CLR headers: " << s->req_hdrs);
 
     /* Release objects from cache
      * analog to clientPurgeRequest in client_side.c
index ed538e6465aedbb145b8b70b63803507b4c6566b..ce69f12572916029d318bda0b03384fb11d154ea 100644 (file)
@@ -487,6 +487,7 @@ ipcacheParse(ipcache_entry *i, rfc1035_rr * answers, int nr, const char *error_m
         return -1;
     }
 
+    debugs(14, 3, "ipcacheParse: " << nr << " answers for '" << name << "'");
     assert(answers);
 
     for (k = 0; k < nr; k++) {
index 84089c1b5742270de33570512f2a773ab41edc7f..3ddf4df286d27e41a214ab57316873a97f206a9c 100644 (file)
@@ -917,7 +917,7 @@ peerDigestFetchFinish(DigestFetchState * fetch, int err)
     assert(fetch->entry && fetch->request);
 
     if (fetch->old_entry) {
-        debugs(72, 2, "peerDigestFetchFinish: deleting old entry");
+        debugs(72, 3, "peerDigestFetchFinish: deleting old entry");
         storeUnregister(fetch->old_sc, fetch->old_entry, fetch);
         fetch->old_entry->releaseRequest();
         fetch->old_entry->unlock();
index 17191716c00ab695e54683c5243620d0d4326a5e..cfdb05b85114681bf179d830afe1c30da76ea40c 100644 (file)
@@ -654,7 +654,7 @@ sslCreateServerContext(const char *certfile, const char *keyfile, int version, c
         debugs(83, 5, "Using SSLv2.");
         method = SSLv2_server_method();
 #else
-        debugs(83, 1, "SSLv2 is not available in this Proxy.");
+        debugs(83, DBG_IMPORTANT, "SSLv2 is not available in this Proxy.");
         return NULL;
 #endif
         break;
@@ -711,31 +711,33 @@ sslCreateServerContext(const char *certfile, const char *keyfile, int version, c
         }
     }
 
-    debugs(83, 1, "Using certificate in " << certfile);
+    debugs(83, DBG_IMPORTANT, "Using certificate in " << certfile);
 
     if (!SSL_CTX_use_certificate_chain_file(sslContext, certfile)) {
         ssl_error = ERR_get_error();
-        debugs(83, 0, "Failed to acquire SSL certificate '" << certfile << "': " << ERR_error_string(ssl_error, NULL)  );
-        goto error;
+        debugs(83, DBG_CRITICAL, "ERROR: Failed to acquire SSL certificate '" << certfile << "': " << ERR_error_string(ssl_error, NULL));
+        SSL_CTX_free(sslContext);
+        return NULL;
     }
 
-    debugs(83, 1, "Using private key in " << keyfile);
+    debugs(83, DBG_IMPORTANT, "Using private key in " << keyfile);
     ssl_ask_password(sslContext, keyfile);
 
     if (!SSL_CTX_use_PrivateKey_file(sslContext, keyfile, SSL_FILETYPE_PEM)) {
         ssl_error = ERR_get_error();
-        debugs(83, 0, "Failed to acquire SSL private key '" << keyfile << "': " << ERR_error_string(ssl_error, NULL)  );
-        goto error;
+        debugs(83, DBG_CRITICAL, "ERROR: Failed to acquire SSL private key '" << keyfile << "': " << ERR_error_string(ssl_error, NULL));
+        SSL_CTX_free(sslContext);
+        return NULL;
     }
 
     debugs(83, 5, "Comparing private and public SSL keys.");
 
     if (!SSL_CTX_check_private_key(sslContext)) {
         ssl_error = ERR_get_error();
-        debugs(83, 0, "SSL private key '" <<
-               certfile << "' does not match public key '" <<
-               keyfile << "': " << ERR_error_string(ssl_error, NULL)  );
-        goto error;
+        debugs(83, DBG_CRITICAL, "ERROR: SSL private key '" << certfile << "' does not match public key '" <<
+               keyfile << "': " << ERR_error_string(ssl_error, NULL));
+        SSL_CTX_free(sslContext);
+        return NULL;
     }
 
     debugs(83, 9, "Setting RSA key generation callback.");
@@ -745,15 +747,13 @@ sslCreateServerContext(const char *certfile, const char *keyfile, int version, c
 
     if ((CAfile || CApath) && !SSL_CTX_load_verify_locations(sslContext, CAfile, CApath)) {
         ssl_error = ERR_get_error();
-        debugs(83, 1, "Error setting CA certificate locations: " << ERR_error_string(ssl_error, NULL)  );
-        debugs(83, 1, "continuing anyway..." );
+        debugs(83, DBG_IMPORTANT, "WARNING: Ignoring error setting CA certificate locations: " << ERR_error_string(ssl_error, NULL));
     }
 
     if (!(fl & SSL_FLAG_NO_DEFAULT_CA) &&
             !SSL_CTX_set_default_verify_paths(sslContext)) {
         ssl_error = ERR_get_error();
-        debugs(83, 1, "Error setting default CA certificate location: " << ERR_error_string(ssl_error, NULL)  );
-        debugs(83, 1, "continuing anyway..." );
+        debugs(83, DBG_IMPORTANT, "WARNING: Ignoring error setting default CA certificate location: " << ERR_error_string(ssl_error, NULL));
     }
 
     if (clientCA) {
@@ -762,8 +762,9 @@ sslCreateServerContext(const char *certfile, const char *keyfile, int version, c
         cert_names = SSL_load_client_CA_file(clientCA);
 
         if (cert_names == NULL) {
-            debugs(83, 1, "Error loading the client CA certificates from '" << clientCA << "\': " << ERR_error_string(ERR_get_error(),NULL)  );
-            goto error;
+            debugs(83, DBG_IMPORTANT, "ERROR: loading the client CA certificates from '" << clientCA << "\': " << ERR_error_string(ERR_get_error(),NULL));
+            SSL_CTX_free(sslContext);
+            return NULL;
         }
 
         ERR_clear_error();
@@ -806,10 +807,10 @@ sslCreateServerContext(const char *certfile, const char *keyfile, int version, c
         }
 
         if (!dh)
-            debugs(83, 1, "WARNING: Failed to read DH parameters '" << dhfile << "'");
+            debugs(83, DBG_IMPORTANT, "WARNING: Failed to read DH parameters '" << dhfile << "'");
         else if (dh && DH_check(dh, &codes) == 0) {
             if (codes) {
-                debugs(83, 1, "WARNING: Failed to verify DH parameters '" << dhfile  << "' (" << std::hex << codes  << ")");
+                debugs(83, DBG_IMPORTANT, "WARNING: Failed to verify DH parameters '" << dhfile  << "' (" << std::hex << codes  << ")");
                 DH_free(dh);
                 dh = NULL;
             }
@@ -823,11 +824,6 @@ sslCreateServerContext(const char *certfile, const char *keyfile, int version, c
         SSL_CTX_set_ex_data(sslContext, ssl_ctx_ex_index_dont_verify_domain, (void *) -1);
 
     return sslContext;
-
-error:
-    SSL_CTX_free(sslContext);
-
-    return NULL;
 }
 
 SSL_CTX *
@@ -857,7 +853,7 @@ sslCreateClientContext(const char *certfile, const char *keyfile, int version, c
         debugs(83, 5, "Using SSLv2.");
         method = SSLv2_client_method();
 #else
-        debugs(83, 1, "SSLv2 is not available in this Proxy.");
+        debugs(83, DBG_IMPORTANT, "SSLv2 is not available in this Proxy.");
         return NULL;
 #endif
         break;
@@ -931,7 +927,7 @@ sslCreateClientContext(const char *certfile, const char *keyfile, int version, c
     SSL_CTX_set_tmp_rsa_callback(sslContext, ssl_temp_rsa_cb);
 
     if (fl & SSL_FLAG_DONT_VERIFY_PEER) {
-        debugs(83, 1, "NOTICE: Peer certificates are not verified for validity!");
+        debugs(83, 2, "NOTICE: Peer certificates are not verified for validity!");
         SSL_CTX_set_verify(sslContext, SSL_VERIFY_NONE, NULL);
     } else {
         debugs(83, 9, "Setting certificate verification callback.");
@@ -942,8 +938,7 @@ sslCreateClientContext(const char *certfile, const char *keyfile, int version, c
 
     if ((CAfile || CApath) && !SSL_CTX_load_verify_locations(sslContext, CAfile, CApath)) {
         ssl_error = ERR_get_error();
-        debugs(83, 1, "Error setting CA certificate locations: " << ERR_error_string(ssl_error, NULL));
-        debugs(83, 1, "continuing anyway..." );
+        debugs(83, DBG_IMPORTANT, "WARNING: Ignoring error setting CA certificate locations: " << ERR_error_string(ssl_error, NULL));
     }
 
     if (CRLfile) {
@@ -962,8 +957,7 @@ sslCreateClientContext(const char *certfile, const char *keyfile, int version, c
     if (!(fl & SSL_FLAG_NO_DEFAULT_CA) &&
             !SSL_CTX_set_default_verify_paths(sslContext)) {
         ssl_error = ERR_get_error();
-        debugs(83, 1, "Error setting default CA certificate location: " << ERR_error_string(ssl_error, NULL)  );
-        debugs(83, 1, "continuing anyway...");
+        debugs(83, DBG_IMPORTANT, "WARNING: Ignoring error setting default CA certificate location: " << ERR_error_string(ssl_error, NULL));
     }
 
     return sslContext;