When users submit emails, there is a very high processing time reported by ASSP. The email is received by the other user long before ASSP has finished processing it and closed the connection. Eg this email which had an empty body:
ASSP log: May-28-19 16:29:29 [Worker_1] Connected: session:7FCFBFC71650 ::1:52271 > ::1:25 > 127.0.0.1:10026 May-28-19 16:29:29 [Worker_1] ::1 info: injected STARTTLS request to 127.0.0.1 May-28-19 16:29:29 [Worker_1] [TLS-out] ::1 info: authentication - plain is used May-28-19 16:29:29 [Worker_1] [TLS-out] ::1 info: authentication (PLAIN) realms - foruser:jlbr...@bordo.com.au, user:jlbr...@bordo.com.au May-28-19 16:29:30 id-24969-02905 [Worker_1] [TLS-out] ::1 <jlbr...@bordo.com.au> to: m...@mac.com [Plugin] calling plugin ASSP_AFC May-28-19 16:29:30 id-24969-02905 [Worker_1] [TLS-out] ::1 <jlbr...@bordo.com.au> to: m...@mac.com local (no bad attachments) May-28-19 16:29:30 id-24969-02905 [Worker_1] [TLS-out] [MessageOK] ::1 <jlbr...@bordo.com.au> to: m...@mac.com message ok [Test time 2] May-28-19 16:30:30 id-24969-02905 [Worker_1] [TLS-out] ::1 <jlbr...@bordo.com.au> to: m...@mac.com finished message - received DATA size: 1.12 kByte - sent DATA size: 832 Byte May-28-19 16:30:30 id-24969-02905 [Worker_1] [TLS-out] ::1 <jlbr...@bordo.com.au> to: m...@mac.com disconnected: session:7FCFBFC71650 ::1 - processing time 61 seconds Postfix log: 2019-05-28 16:29:29.543583+1000 localhost smtpd[41732]: connect from localhost[127.0.0.1] 2019-05-28 16:29:30.023590+1000 localhost smtpd[41732]: 059D818FD66F: client=localhost[127.0.0.1], sasl_method=PLAIN, sasl_username=jlbr...@bordo.com.au 2019-05-28 16:29:30.249955+1000 localhost cleanup[37257]: 059D818FD66F: message-id=<assp.005131ed3d.243e9444-83db-42ae-a040-de2386924...@bordo.com.au> 2019-05-28 16:29:30.251088+1000 localhost qmgr[50795]: 059D818FD66F: from=<jlbr...@bordo.com.au>, size=1056, nrcpt=1 (queue active) 2019-05-28 16:29:30.261214+1000 localhost smtp[42726]: (libsystem_info.dylib) Created Activity ID: 0x389ad0, Description: Retrieve User by Name 2019-05-28 16:29:30.261716+1000 localhost smtp[42726]: (libsystem_info.dylib) Created Activity ID: 0x389ad1, Description: Retrieve User by Name 2019-05-28 16:29:30.262061+1000 localhost smtp[42726]: (libsystem_info.dylib) Created Activity ID: 0x389ad2, Description: Retrieve Group by Name 2019-05-28 16:29:30.263229+1000 localhost smtp[42726]: (libsystem_info.dylib) Created Activity ID: 0x389ad3, Description: Resolve user group list 2019-05-28 16:29:30.263778+1000 localhost smtp[42726]: (libsystem_info.dylib) Created Activity ID: 0x389ad4, Description: Retrieve service by name 2019-05-28 16:29:31.077971+1000 localhost smtp[42726]: 059D818FD66F: to=<m...@mac.com>, relay=mx3.mail.icloud.com[17.142.163.15]:25, delay=1.2, delays=0.38/0.01/0.01/0.8, dsn=2.0.0, status=sent (250 OK id=1hVVc2-0007ya-0w) 2019-05-28 16:29:31.078637+1000 localhost qmgr[50795]: 059D818FD66F: removed Stunnel log: 2019.05.28 16:29:29 LOG5[1842]: Service [ssmtp465] accepted connection from ::ffff:192.168.1.10:61109 2019.05.28 16:29:29 LOG5[1842]: s_connect: connected ::1:25 2019.05.28 16:29:29 LOG5[1842]: Service [ssmtp465] connected remote server from ::1:52271 2019.05.28 16:30:30 LOG5[1842]: Connection closed: 324 byte(s) sent to TLS, 619 byte(s) sent to socket Stunnel config: [ssmtp465] client = no accept = 465 connect = localhost:25 options = NO_SSLv2 Notice that Postfix had received the submission, sent the email and removed it from its queue in 2 seconds. But there was a full minute between ASSP saying ‘message ok’ and it saying ‘finished message’ and disconnecting. Emails are received on port 25 (directly by ASSP) and processed without the delay. Any ideas what could be causing this? ASSP version 2.6.4 *SPAM-Evaporator* build 19115 Thanks, James. _______________________________________________ Assp-test mailing list Assp-test@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/assp-test
