Testsuite: make debug output for proxied TLS less indeterminate

6 files changed, 52 insertions, 43 deletions

diff --git a/src/src/deliver.c b/src/src/deliver.c
index 89ad7e5ea..295ae42c4 100644
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -8507,14 +8507,10 @@ if (cutthrough.fd >= 0 && cutthrough.callout_hold_only)
       goto fail;
 
     else if (pid == 0)		/* child: fork again to totally disconnect */
-      {
-      close(pfd[1]);
-      if ((pid = fork()))
-	_exit(pid < 0 ? EXIT_FAILURE : EXIT_SUCCESS);
-      smtp_proxy_tls(big_buffer, big_buffer_size, pfd[0], 5*60);
-      exim_exit(0, US"TLS proxy");
-      }
+      /* does not return */
+      smtp_proxy_tls(big_buffer, big_buffer_size, pfd, 5*60);
 
+    DEBUG(D_transport) debug_printf("proxy-proc inter-pid %d\n", pid);
     close(pfd[0]);
     waitpid(pid, NULL, 0);
     (void) close(channel_fd);	/* release the client socket */
diff --git a/src/src/functions.h b/src/src/functions.h
index 760a9f52b..1fe561f56 100644
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -412,7 +412,7 @@ extern void    smtp_get_cache(void);
 extern int     smtp_handle_acl_fail(int, int, uschar *, uschar *);
 extern void    smtp_log_no_mail(void);
 extern void    smtp_message_code(uschar **, int *, uschar **, uschar **, BOOL);
-extern void    smtp_proxy_tls(uschar *, size_t, int, int);
+extern void    smtp_proxy_tls(uschar *, size_t, int *, int);
 extern BOOL    smtp_read_response(smtp_inblock *, uschar *, int, int, int);
 extern void    smtp_respond(uschar *, int, BOOL, uschar *);
 extern void    smtp_notquit_exit(uschar *, uschar *, uschar *, ...);
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index ca06bf6bd..5f9d4313c 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -2580,29 +2580,37 @@ return 0;
 * Proxy TLS connection for another transport process *
 ******************************************************/
 /*
-Use the given buffer as a staging area, and select on both the given fd
-and the TLS'd client-fd for data to read (per the coding in ip_recv() and
-fd_ready() this is legitimate).  Do blocking full-size writes, and reads
-under a timeout.
+Close the unused end of the pipe, fork once more, then use the given buffer
+as a staging area, and select on both the given fd and the TLS'd client-fd for
+data to read (per the coding in ip_recv() and fd_ready() this is legitimate).
+Do blocking full-size writes, and reads under a timeout.  Once both input
+channels are closed, exit the process.
 
 Arguments:
   buf		space to use for buffering
   bufsiz	size of buffer
-  proxy_fd	comms to proxied process
+  pfd		pipe filedescriptor array; [0] is comms to proxied process
   timeout	per-read timeout, seconds
 */
 
 void
-smtp_proxy_tls(uschar * buf, size_t bsize, int proxy_fd, int timeout)
+smtp_proxy_tls(uschar * buf, size_t bsize, int * pfd, int timeout)
 {
 fd_set rfds, efds;
-int max_fd = MAX(proxy_fd, tls_out.active) + 1;
+int max_fd = MAX(pfd[0], tls_out.active) + 1;
 int rc, i, fd_bits, nbytes;
 
+close(pfd[1]);
+if ((rc = fork()))
+  {
+  DEBUG(D_transport) debug_printf("proxy-proc final-pid %d\n", rc);
+  _exit(rc < 0 ? EXIT_FAILURE : EXIT_SUCCESS);
+  }
+
 set_process_info("proxying TLS connection for continued transport");
 FD_ZERO(&rfds);
 FD_SET(tls_out.active, &rfds);
-FD_SET(proxy_fd, &rfds);
+FD_SET(pfd[0], &rfds);
 
 for (fd_bits = 3; fd_bits; )
   {
@@ -2624,17 +2632,17 @@ for (fd_bits = 3; fd_bits; )
     if (rc <= 0)
       {
       DEBUG(D_transport) if (rc == 0) debug_printf("%s: timed out\n", __FUNCTION__);
-      return;
+      goto done;
       }
 
-    if (FD_ISSET(tls_out.active, &efds) || FD_ISSET(proxy_fd, &efds))
+    if (FD_ISSET(tls_out.active, &efds) || FD_ISSET(pfd[0], &efds))
       {
       DEBUG(D_transport) debug_printf("select: exceptional cond on %s fd\n",
-	FD_ISSET(proxy_fd, &efds) ? "proxy" : "tls");
-      return;
+	FD_ISSET(pfd[0], &efds) ? "proxy" : "tls");
+      goto done;
       }
     }
-  while (rc < 0 || !(FD_ISSET(tls_out.active, &rfds) || FD_ISSET(proxy_fd, &rfds)));
+  while (rc < 0 || !(FD_ISSET(tls_out.active, &rfds) || FD_ISSET(pfd[0], &rfds)));
 
   /* handle inbound data */
   if (FD_ISSET(tls_out.active, &rfds))
@@ -2642,20 +2650,20 @@ for (fd_bits = 3; fd_bits; )
       {
       fd_bits &= ~1;
       FD_CLR(tls_out.active, &rfds);
-      shutdown(proxy_fd, SHUT_WR);
+      shutdown(pfd[0], SHUT_WR);
       timeout = 5;
       }
     else
       {
       for (nbytes = 0; rc - nbytes > 0; nbytes += i)
-	if ((i = write(proxy_fd, buf + nbytes, rc - nbytes)) < 0) return;
+	if ((i = write(pfd[0], buf + nbytes, rc - nbytes)) < 0) goto done;
       }
   else if (fd_bits & 1)
     FD_SET(tls_out.active, &rfds);
 
   /* handle outbound data */
-  if (FD_ISSET(proxy_fd, &rfds))
-    if ((rc = read(proxy_fd, buf, bsize)) <= 0)
+  if (FD_ISSET(pfd[0], &rfds))
+    if ((rc = read(pfd[0], buf, bsize)) <= 0)
       {
       fd_bits = 0;
       tls_close(FALSE, TRUE);
@@ -2664,11 +2672,15 @@ for (fd_bits = 3; fd_bits; )
       {
       for (nbytes = 0; rc - nbytes > 0; nbytes += i)
 	if ((i = tls_write(FALSE, buf + nbytes, rc - nbytes, FALSE)) < 0)
-	  return;
+	  goto done;
       }
   else if (fd_bits & 2)
-    FD_SET(proxy_fd, &rfds);
+    FD_SET(pfd[0], &rfds);
   }
+
+done:
+  if (running_in_test_harness) millisleep(100);	/* let logging complete */
+  exim_exit(0, US"TLS proxy");
 }
 #endif
 
@@ -3485,7 +3497,8 @@ propagate it from the initial
 	{
         sx.send_quit = FALSE;
 
-	/* If TLS is still active, we need to proxy it for the transport we
+	/* We have passed the client socket to a fresh transport process.
+	If TLS is still active, we need to proxy it for the transport we
 	just passed the baton to.  Fork a child to to do it, and return to
 	get logging done asap.  Which way to place the work makes assumptions
 	about post-fork prioritisation which may not hold on all platforms. */
@@ -3493,10 +3506,16 @@ propagate it from the initial
 	if (tls_out.active >= 0)
 	  {
 	  int pid = fork();
+	  if (pid == 0)		/* child; fork again to disconnect totally */
+	    /* does not return */
+	    smtp_proxy_tls(sx.buffer, sizeof(sx.buffer), pfd,
+			    sx.ob->command_timeout);
+
 	  if (pid > 0)		/* parent */
 	    {
 	    DEBUG(D_transport) debug_printf("proxy-proc inter-pid %d\n", pid);
 	    close(pfd[0]);
+	    /* tidy the inter-proc to disconn the proxy proc */
 	    waitpid(pid, NULL, 0);
 	    tls_close(FALSE, FALSE);
 	    (void)close(sx.inblock.sock);
@@ -3504,18 +3523,7 @@ propagate it from the initial
 	    continue_hostname = NULL;
 	    return yield;
 	    }
-	  else if (pid == 0)	/* child; fork again to disconnect totally */
-	    {
-	    close(pfd[1]);
-	    if ((pid = fork()))
-	      {
-	      DEBUG(D_transport) debug_printf("proxy-prox final-pid %d\n", pid);
-	      _exit(pid < 0 ? EXIT_FAILURE : EXIT_SUCCESS);
-	      }
-	    smtp_proxy_tls(sx.buffer, sizeof(sx.buffer), pfd[0], sx.ob->command_timeout);
-	    if (running_in_test_harness) millisleep(100);	/* let logging complete */
-	    exim_exit(0, US"TLS proxy");
-	    }
+	  log_write(0, LOG_PANIC_DIE, "fork failed");
 	  }
 #endif
 	}
diff --git a/test/runtest b/test/runtest
index 8f5d393bb..5fbf1d3fe 100755
--- a/test/runtest
+++ b/test/runtest
@@ -925,9 +925,10 @@ RESET_AFTER_EXTRA_LINE_READ:
 
     s/^Exim version .*/Exim version x.yz ..../;
 
-    # Debugging lines for Exim terminations
+    # Debugging lines for Exim terminations and process-generation
 
     s/(?<=^>>>>>>>>>>>>>>>> Exim pid=)\d+(?= terminating)/pppp/;
+    s/^(proxy-proc \w{5}-pid) \d+$/$1 pppp/;
 
     # IP address lookups use gethostbyname() when IPv6 is not supported,
     # and gethostbyname2() or getipnodebyname() when it is.
diff --git a/test/stderr/2035 b/test/stderr/2035
index 3b6cb2824..80c2476d8 100644
--- a/test/stderr/2035
+++ b/test/stderr/2035
@@ -36,6 +36,8 @@ LOG: MAIN
 LOG: smtp_connection MAIN
   SMTP connection from CALLER closed by QUIT
 >>>>>>>>>>>>>>>> Exim pid=pppp (msg setup toplevel) terminating with rc=0 >>>>>>>>>>>>>>>>
+proxy-proc inter-pid pppp
+proxy-proc final-pid pppp
 Exim version x.yz ....
 configuration file is TESTSUITE/test-config
 trusted user
@@ -64,11 +66,11 @@ ok=1 send_quit=1 send_rset=0 continue_more=0 yield=0 first_address is NULL
 cmd buf flush ddd bytes
   SMTP(close)>>
 Leaving t1 transport
->>>>>>>>>>>>>>>> Exim pid=pppp (TLS proxy) terminating with rc=0 >>>>>>>>>>>>>>>>
 LOG: MAIN
   => userb@test.ex R=client T=t1 H=127.0.0.1 [127.0.0.1]:1225 X=TLS1.x:xxxxRSA_AES_256_CBC_SHAnnn:256 CV=no C="250 OK id=10HmaY-0005vi-00"
 LOG: MAIN
   Completed
 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
+>>>>>>>>>>>>>>>> Exim pid=pppp (TLS proxy) terminating with rc=0 >>>>>>>>>>>>>>>>
 
 ******** SERVER ********
diff --git a/test/stderr/2135 b/test/stderr/2135
index 32e0d013e..e7e1c3f65 100644
--- a/test/stderr/2135
+++ b/test/stderr/2135
@@ -36,6 +36,8 @@ LOG: MAIN
 LOG: smtp_connection MAIN
   SMTP connection from CALLER closed by QUIT
 >>>>>>>>>>>>>>>> Exim pid=pppp (msg setup toplevel) terminating with rc=0 >>>>>>>>>>>>>>>>
+proxy-proc inter-pid pppp
+proxy-proc final-pid pppp
 Exim version x.yz ....
 configuration file is TESTSUITE/test-config
 trusted user
@@ -64,11 +66,11 @@ ok=1 send_quit=1 send_rset=0 continue_more=0 yield=0 first_address is NULL
 cmd buf flush ddd bytes
   SMTP(close)>>
 Leaving t1 transport
->>>>>>>>>>>>>>>> Exim pid=pppp (TLS proxy) terminating with rc=0 >>>>>>>>>>>>>>>>
 LOG: MAIN
   => userb@test.ex R=client T=t1 H=127.0.0.1 [127.0.0.1]:1225 X=TLSv1:AES256-SHA:256 CV=no C="250 OK id=10HmaY-0005vi-00"
 LOG: MAIN
   Completed
 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
+>>>>>>>>>>>>>>>> Exim pid=pppp (TLS proxy) terminating with rc=0 >>>>>>>>>>>>>>>>
 
 ******** SERVER ********