# HG changeset patch
# User Carl Byington <carl@five-ten-sg.com>
# Date 1474316102 25200
# Node ID ef5a6099cbe767a99af09fb9a2436dda4d80ac48
# Parent  68af9ca42eadd2f787328b93148241532afa50ed
enable smtp verify logging

diff -r 68af9ca42ead -r ef5a6099cbe7 src/context.cpp
--- a/src/context.cpp	Mon Sep 19 09:25:29 2016 -0700
+++ b/src/context.cpp	Mon Sep 19 13:15:02 2016 -0700
@@ -92,8 +92,8 @@
 
 int SMTP::writer() {
     #ifdef VERIFY_DEBUG
-        log("writer() sees buffer with %s", buffer);
-        log("writer() sees error %d", (int)error);
+        log("writer(%d) sees buffer with %s", buffer);
+        log("writer(%d) sees error %d", (int)error);
     #endif
     int rs = 0;
     if (!error) {
@@ -119,7 +119,7 @@
     // read some bytes terminated by lf or end of buffer.
     // we may have a multi line response or part thereof in the buffer.
     #ifdef VERIFY_DEBUG
-        log("reader() sees error %d", (int)error);
+        log("reader(%d) sees error %d", (int)error);
     #endif
     if (error) return 0;
     int len = maxlen-1; // room for null terminator
@@ -138,7 +138,7 @@
     }
     buffer[pending] = '\0';
     #ifdef VERIFY_DEBUG
-        log("reader() sees buffer with %s", buffer);
+        log("reader(%d) sees buffer with %s", buffer);
     #endif
     return pending;
 }
@@ -167,15 +167,15 @@
     while (true) {
         int r = read_line();
         #ifdef VERIFY_DEBUG
-            log("read_response() sees line with %s", buffer);
-            log("read_response() sees line length %d", r);
+            log("read_response(%d) sees line with %s", buffer);
+            log("read_response(%d) sees line length %d", r);
         #endif
         if (r == 0) return 0;   // failed to read any bytes
         if ((r > 4) && (buffer[3] == '-')) {
             flush_line(r);
             continue;
         }
-        log("read_response() sees line with %s", buffer);
+        log("verify::read_response(%d) sees line with %s", buffer);
         return atoi(buffer);
     }
     return 0;
@@ -250,14 +250,14 @@
 
 void SMTP::log(const char *m, int v) {
     char buf[maxlen];
-    snprintf(buf, maxlen, m, v);
+    snprintf(buf, maxlen, m, get_fd(), v);
     my_syslog(queueid, buf);
 }
 
 
 void SMTP::log(const char *m, const char *v) {
     char buf[maxlen];
-    snprintf(buf, maxlen, m, v);
+    snprintf(buf, maxlen, m, get_fd(), v);
     my_syslog(queueid, buf);
  }
 
@@ -296,7 +296,7 @@
         // avoid doing this work inside the mutex lock
         if (conn) {
             #ifdef VERIFY_DEBUG
-                conn->log("closer() closes ancient %d", conn->get_fd());
+                conn->log("closer(%d) closes ancient socket %s", "");
             #endif
             delete conn;
         }
@@ -307,13 +307,24 @@
 SMTP* VERIFY::get_connection(const char *queueid) {
     SMTP *conn = NULL;
     pthread_mutex_lock(&mutex);
-        if (!connections.empty()) {
+        while (!connections.empty()) {
             conn = connections.front();
+            time_t now = time(NULL);
+            if ((now - conn->get_stamp()) > maxsmtp_age) {
+                // this connection is ancient, remove it
+                conn->log("verify::get_connection(%d) closes ancient socket %s", "");
+                connections.pop_front();
+                delete conn;
+                conn = NULL;
+            }
+            else {
             conn->set_id(queueid);
             connections.pop_front();
             #ifdef VERIFY_DEBUG
-                conn->log("get_connection() %d from cache", conn->get_fd());
+                    conn->log("verify::get_connection(%d) from cache %s", "");
             #endif
+                break;
+            }
         }
     pthread_mutex_unlock(&mutex);
     if (conn) return conn;
@@ -341,13 +352,17 @@
         else last_err = time(NULL);
     }
     if (sock != NULL_SOCKET) {
+        struct timeval tv;
+        tv.tv_sec = 15;
+        tv.tv_usec = 0;
+        setsockopt(sock, SOL_SOCKET, SO_RCVTIMEO, (char *)&tv, sizeof(struct timeval));
         conn = new SMTP(sock);
         conn->set_id(queueid);
         #ifdef VERIFY_DEBUG
-            conn->log("get_connection() %d new socket", conn->get_fd());
+            conn->log("get_connection(%d) new socket %s", "");
         #endif
         int rc = conn->helo();
-        conn->log("verify::get_connection() helo sees %d", rc);
+        conn->log("verify::get_connection(%d) helo sees %d", rc);
         if (rc == 250) return conn;
         delete conn;
     }
@@ -358,14 +373,13 @@
 void VERIFY::put_connection(SMTP *conn) {
     if (conn->err()) {
         #ifdef VERIFY_DEBUG
-            conn->log("put_socket() %d with error, close it", conn->get_fd());
+            conn->log("put_socket(%d) with error %s", "");
         #endif
         delete conn;
-        last_err = time(NULL);
     }
     else {
         #ifdef VERIFY_DEBUG
-            conn->log("put_socket() %d", conn->get_fd());
+            conn->log("put_socket(%d) no error %s", "");
         #endif
         conn->now();
         pthread_mutex_lock(&mutex);
@@ -381,13 +395,13 @@
     if (!conn) return true;    // cannot verify right now, we have socket errors
     int rc;
     rc = conn->from(from);
-    conn->log("verify::ok() from sees %d", rc);
+    conn->log("verify::ok(%d) from sees %d", rc);
     if (rc != 250) {
         put_connection(conn);
         return (rc >= 500) ? false : true;
     }
     rc = conn->rcpt(to);
-    conn->log("verify::ok() rcpt sees %d", rc);
+    conn->log("verify::ok(%d) rcpt sees %d", rc);
     put_connection(conn);
     return (rc >= 500) ? false : true;
 }
diff -r 68af9ca42ead -r ef5a6099cbe7 src/includes.h
--- a/src/includes.h	Mon Sep 19 09:25:29 2016 -0700
+++ b/src/includes.h	Mon Sep 19 13:15:02 2016 -0700
@@ -8,7 +8,7 @@
 
 #define VERIFY_DEBUG   1
 #define RESOLVER_DEBUG 1
-#undef  VERIFY_DEBUG
+//#undef  VERIFY_DEBUG
 #undef	RESOLVER_DEBUG
 
 #ifdef HAVE_CONFIG_H