From d097cc730a1ab358bad80338b30b49287d1274c3 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sat, 21 Oct 2017 18:36:31 +0100 Subject: [PATCH] Testsuite: make debug output for proxied TLS less indeterminate --- src/src/deliver.c | 10 ++---- src/src/functions.h | 2 +- src/src/transports/smtp.c | 72 ++++++++++++++++++++++----------------- test/runtest | 3 +- test/stderr/2035 | 4 ++- test/stderr/2135 | 4 ++- 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 ******** -- 2.25.1