>line took 620 seconds .... That's better than the 772seconds
This is caused by the performance improvement for large mails in this
version.
>I see a message which I assume is now expected: ( SIZE 15700413 byte >
neverQueueSize 12000000 byte)
This output was also seen in the old versions. Nothing new.
>I saw a X-ASSP-KEEP line in the header too. Don't know what that means.
Haven't seen that before.
This should have been there also in older versions. I've improved the code
there.
While assp receives the message in to the queue, there is no communication
with the SMTP backend server (MTA).
This can cause SMTP timeouts from this MTA. To prevent the timeout, assp
sends this 'dummy' header line to the MTA 15 seconds before a timeout
happens, to keep the connection alive.
>$main::neverQueueSize = 4194304; ... It took 327 seconds.
This looks OK for me. The read operation on your system for TLS requires
1.5 milliseconds - this is OK. (the rest see below)
>Removing the full message analysis seems like a shame especially since it
doesn't seem to even stutter if TLS is off.
This was the case all the time if '( SIZE 15700413 byte > neverQueueSize
12000000 byte)' was reached.
Nobody sends a 12MB SPAM. Analyzing 12MB or more for DKIM, Virus, OCR,
Razor, DCC ..... is an overkill.
answers:
1 - TLS requires high math operations to decrypt the content.
As long as there is no SSL-rehandshake requested by the sender, the
running code is the same for all connections.
Only the line
$hasread = $fh->sysread($SMTPbuf, $Con{$fh}->{RCVBUF});
calls the connection specific module (IO::Socket::INET, IO::Socket::INET6
or IO::Socket::SSL).
What ever time is taken there, we can't controll it. But the new debug
file shows - there is no TLS time issue.
2 - IO::Socket::SSL and Net::SSLeay
3 - Convert::Scalar->grow works together with the perl on my system
4 - IMHO a not correctly working Convert::Scalar at the used Perl version
/ OS (maloc and garbage collection)
what happens in Perl:
assume we store some byte (let's use the 1400 byte sent by google).
$buf = 'a' x 1400;
Perl will allocate ~1400 byte of memory for $buf and will write the 1400
byte in there.
Now we append additionally 1400 byte to $buf (as we do in assp queueing).
$buf = $buf . 'a' x 1400;
Perl will have a look in to the $buf memory area. If there is enought
space behind the still allocated memory, it will write the new 1400 byte
behind the existing. This will never be possible in the huge memory area
of assp with millions of memory changes per second. So what to do? Perl
will allocate a new area of 2800 byte, copies the existing content to
there and appends the new 1400 byte. After that, the old memory area is
marked for the Perl garbage collection to be freed up for any further
required memory.
This operation for the 1400...2800 byte is very fast because of the short
content.
But what if we still have 8MB in $buf and we add 1400 byte every some
milliseconds: alloc->copy->append,alloc->copy->append,alloc......
IMHO this happens on your system and it is done for the mail content to be
processed, the maillog-buffer and possibly for the crash-analyzer and
connection-timout-debug.
I know this behavior of Perl. To prevent this alloc->copy->append
mechanism, assp uses the 'grow' mechanism of the module Convert::Scalar.
This reduces the operation to a simple : append,append,append,ap......
If the sender announces the message size, assp grows the memory area for
all variables, that needs to grow to the message size.
If assp does not know the message size, MaxBytes are allocated and the
variables are growed by 1MB, every time the old limit is reached.
There are two option for the issue.
1. The Convert::Scalar->grow is not working.
2. Convert::Scalar->grow works, but Perl frees up the allocated unused
memory at any time.
Both we can't check at assp runtime.
>What is TLS doing that slows things down so much for GOOGLE mails only
(or at least only google that I've seen be slow)
I think, this (the only) is not right. The symptome is best shown in this
case.
1 - TLS takes much longer than plain.
2 - google uses high encryption algorythms.
3 - Large mails are sent from google.
4 - grow does not work
(4) is every time the case
all other points may be skipped by other senders : plain, or smaller mail,
or less encryption - and will lead in to more or less faster processing
The new debug log (just arrived) shows the reason for the slow down of the
speed.
Everything runs like expected - except the time required between
[Worker_1] <Maillog
and
[Worker_1] <whitebody
grows with the amount of the received data.
at Sep-26-16 22:37:58 it requires 6.7 milliseconds
at Sep-26-16 22:39:22 it requires 27.0 milliseconds
at Sep-26-16 22:41:11 it requires 43.8 milliseconds
The only growing variable between these two debug states is the maillog
buffer. All other code statements are looking very innocent in relation to
the issue.
The memory for the maillog buffer is pre-allocated at the same point in
time like the other growing variables.
It seems, that perl eliminates the pre-allocation for the maillog buffer
on your system in a very early processing state of a mail.
*******************************
Back to the 'TLS' relation. Forget it - this issue has totaly nothing to
do with TLS/SSL!
*******************************
If the sender announces the message size in the 'MAIL From: ...' , assp
allocates all memory (one time) after the DATA command was seen. Only if
the message gets larger than announced, additionally memory allocation is
done.
If there is no message size announcement, the allocation is done for
'MaxBytes' at the DATA state, again (1MB) if 'npSize' is reached and again
(1MB) for each received 1MB of data. So even if Perl has eliminated the
first allocation, the next allocation comes very early and seems to be
permanent on your system.
The problem is related to: large mails with message SIZE announcement in
MAIL FROM - than larger the mail, than bigger the problem
Now I know the reason and I think I'll find a solution for this problem.
So we wasted allot of time looking for a TLS/SSL issue - life is not easy.
:)
Thomas
ps:
>2_14315_5.020001_UAX#29_UAX#15_WordStem1.27 - required:
>2_14315_UAX#29_UAX#15_WordStem1.27
The perl version is no longer part of the DB version string. Ignore this
and run a rebuild.
Von: K Post <[email protected]>
An: ASSP development mailing list <[email protected]>
Datum: 27.09.2016 05:50
Betreff: Re: [Assp-test] Inbound TLS from gmail.com addresses /
servers
THANK YOU again for taking all the time on this. It's nuts that this only
seems to happen (to me and others reporting) with TLS on and mail sent
through google servers.
I've confirmed the version of Convert::Scalar to be 1.11
I'll get you a debug log privately, but here's what I'm seeing with the
latest version:
11mb attachment, tls on, newest version, but without
the $main::neverQueueSize = 4194304; line took 620 seconds. That's better
than the 772seconds that saw before I but still pretty terrible - and of
course, that's only one test.
I see a message which I assume is now expected:
message is too large ( SIZE 15700413 byte > neverQueueSize 12000000 byte)
to be queued for further internal processing! Skipping DKIM, Plugins and
charset conversion. for that message
I saw a X-ASSP-KEEP line in the header too. Don't know what that means.
Haven't seen that before.
Once I added the $main::neverQueueSize = 4194304; line to ASSP_Correct.pm,
speed improves for sure. It took 327 seconds. Still really slow
considering that without TLS it only takes 19 seconds.
Similar line noting the 4MB size limit
Removing the full message analysis seems like a shame especially since it
doesn't seem to even stutter if TLS is off.
especially since it
doesn't seem to even stutter if TLS is off.
So more questions for your consideration
1) What is TLS doing that slows things down so much for GOOGLE mails only
(or at least only google that I've seen be slow)
2) What encryption related modules need checking?
3) Why would things be fine on your old Windows 2003 rig, but clearly not
okay on my (presumably) faster machine
4) What is similar between my machine and the others who reported TLS
problems with Google. I know one at least was a Linux rig.
On Mon, Sep 26, 2016 at 4:02 AM, Thomas Eckardt
<[email protected]>
wrote:
> First, thank you for the debug file.
>
> There is one big problem. The debug file explains the general behavior
of
> the slowing down connection while the data size is growing.
> It not explains, why this should only happens at connections from
> gmail.com and only if TLS is used.
>
> looking at the following timeline - the *** lines are from me and are
> showing the count of read-socketcalls within this second
>
> ....
> Sep-23-16 21:14:37 [Worker_2] <wrote: IO::Socket::INET=GLOB(0x11c1e3bc)
> (6)<DATA[CR][LF]
> Sep-23-16 21:14:37 [Worker_2] <getheader
> Sep-23-16 21:14:38 [Worker_2] <getbody - done: maillength:77206
> Sep-23-16 21:14:39 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 164
> ...
> Sep-23-16 21:14:40 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 167
> ...
> Sep-23-16 21:14:41 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 108
> ...
> Sep-23-16 21:14:42 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 95
> ...
> Sep-23-16 21:14:43 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 82
> ...
> Sep-23-16 21:14:44 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 74
> ...
> Sep-23-16 21:15:09 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 43
> ...
> Sep-23-16 21:15:39 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 35
> ...
> Sep-23-16 21:16:39 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 21
> ...
> Sep-23-16 21:18:39 [Worker_2] <doing full
> ***socketcalls per second (each 1440 byte) 12
> ...
> Sep-23-16 21:22:41 msg79676-04975 209.85.223.177 <[email protected]>
to:
> testtls@[[ OUR DOMAIN ]].org info: message is too large ( >
neverQueueSize
> 12000000 byte) to be queued for further internal processing! Skipping
> DKMI, Plugins and charset conversion.
> ***socketcalls per second (each 1440 byte) 8
> ...
> Sep-23-16 21:22:45 [Worker_2] <wrote: IO::Socket::INET=GLOB(0x11c1e3bc)
> (1404)
> ***socketcalls per second (each 1440 byte) 150
> ...
> Sep-23-16 21:23:53 [Worker_2] <wrote: IO::Socket::INET=GLOB(0x11c1e3bc)
> (1404)
> ***socketcalls per second (each 1440 byte) 161
> ...
> Sep-23-16 21:23:53 [Worker_2] <wrote: IO::Socket::INET=GLOB(0x11c1e3bc)
> (1404)
> ***socketcalls per second (each 1440 byte) 161
> Sep-23-16 21:25:29 [Worker_2] <doing line <250 Queued (652.288
> seconds)[CR][LF]
> ....
>
> Until Sep-23-16 21:22:41 the mail is queued. While this is done, the
speed
> slows down with the growing data.
> After this timestamp, large (65 kB)data junks are sent to the MTA (small
> (1400 Byte) are received) and as the queued data are getting less, the
> speed grows.
> At Sep-23-16 21:22:45 the outqueue is empty and the data are sent as
they
> are received (1404 Byte each) with a normal speed.
>
> This behavior can't be explained with the usage of TLS, because the code
> behind is the same for all connections. The read data size for each read
> operation is always the same 1400 Byte.
> For me, the behavior can be exactly described with a not working Perl
> module 'Convert::Scalar' or a code operation, which is done over all the
> growing data after each read operation.
> The latter I can exclude. To make this 100% sure, I've made some small
> changes in the next release (will be published today).
>
> It is not possible to check, that 'Convert::Scalar' is working like
> expected for the 'grow' operation - even the module maintainer is not
able
> to do this in the installation test scripts.
> At least make sure that version 1.11 is installed.
>
> >Sep-23-16 21:14:37 [Worker_2] <allocate memory: header=15703707 ,
> maillogbuf=15703707 , outgoing=15703707
>
> shows, that the module is installed and called by assp.
>
> What are the options to solve the problem?
>
> 1. in any case - check that Convert::Scalar version 1.11 is installed
> 2. Try the new version of assp.pl - I'll publish today. It contains code
> changes to prevent this behavior, at least to indentify the reason
somehow
> better
> If the same behavior happens, please provide me the debug file
again.
>
> 3. if this does not help, add the following code line to the module
> 'assp/lib/CorrectASSPcfg.pm' in 'sub set { '
>
> $main::neverQueueSize = 4194304;
>
> This hidden value defines the maximum size of mail data, that should be
> queued for all full mail checks. If a mail is larger, queueing is
switched
> off - charset conversion, full DKIM checks, DKIM signing and all Plugins
> for full mail operations (level 2) will be skipped.
>
> 4194304 are 4MB - you may try any other value of your choice. Default
> value is 12000000.
> This solution will also work with the current code.
>
>
> Thomas
>
>
>
>
>
>
>
>
>
>
> Von: K Post <[email protected]>
> An: ASSP development mailing list <[email protected]>
> Datum: 24.09.2016 04:05
> Betreff: Re: [Assp-test] Inbound TLS from gmail.com addresses /
> servers
>
>
>
> in the debug that I'm about to send you, I'm seeing lines like:
> <left over <46 Byte>
> periodically in the file.
> Don't know if that's notable or not.
>
> On Fri, Sep 23, 2016 at 9:43 PM, K Post <[email protected]> wrote:
>
> > I'll get you a sample debug asap.
> >
> > FYI, I forgot to mention yesterday - I've noticed times (not always)
> when
> > watching the SMTP Connections Window with large test gmail emails
where
> a
> > message will start transferring and after some time (7-8 minutes,
maybe
> a
> > little less), that google will connect a second time and start
> transferring
> > the message again, even though the first one is still being received.
> >
> > The first message completed after say 12 minutes, and then 3-4 minutes
> > after that, the 2nd google connection disconnects and doesn't try
again
> > (nor should it).
> >
> > This does NOT happen every time, and I can't find find a reason why it
> > would do this on occasion for some but not other big messages.
> >
> >
> > On Fri, Sep 23, 2016 at 7:02 AM, Thomas Eckardt <
> > [email protected]> wrote:
> >
> >> Thank you Ken.
> >>
> >> Please would you send me the debug log for the large (15MB) TLS mail
as
> >> ZIP or make it available to me for download anywhere, if it is too
> large
> >> for SMTP.
> >>
> >> Thomas
> >>
> >>
> >
> ------------------------------------------------------------
> ------------------
> _______________________________________________
> Assp-test mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/assp-test
>
>
>
>
> DISCLAIMER:
> *******************************************************
> This email and any files transmitted with it may be confidential,
legally
> privileged and protected in law and are intended solely for the use of
the
>
> individual to whom it is addressed.
> This email was multiple times scanned for viruses. There should be no
> known virus in this email!
> *******************************************************
>
>
> ------------------------------------------------------------
> ------------------
>
> _______________________________________________
> Assp-test mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/assp-test
>
>
------------------------------------------------------------------------------
_______________________________________________
Assp-test mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/assp-test
DISCLAIMER:
*******************************************************
This email and any files transmitted with it may be confidential, legally
privileged and protected in law and are intended solely for the use of the
individual to whom it is addressed.
This email was multiple times scanned for viruses. There should be no
known virus in this email!
*******************************************************
------------------------------------------------------------------------------
_______________________________________________
Assp-test mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/assp-test
