We use the smtpmail.p procedure from FFW to send all of our emails. These emails can be generated from a hard client or through webspeed from our website.
When triggering this code from the hard client the email sends instantly but when it is triggered through webspeed it seems to take 6-8 seconds for the code in smtpmail.p to fully execute. I have attached both socketmail logs which shows that it took ~7 seconds to fully execute from the website but instantly from the hard client.
Has anyone come across this issue before? Ideally we would like the website to match the speed of the hard client.
Thanks in advance for any insights.
This is being used to email a OTP code to an input email address and we would ideally like this to be as fast as possible. The below are my log files from both tests.
This is the log when running through our client front-end.
15/11/22 10:45:46
************** ****** New Group ******* ************
Socket email started
15/11/2022 10:45:46.673+00:00
Input Parameters
EmailFrom = ***
EmailReplyTo =
EmailTo = ***
EmailCC =
Attachments =
LocalFiles =
Subject = Email Test
Body = a
MIMEHeader = type=text/plain:charset=UTF-8
LocalHostName = localhost
Delivery Receipt = no
Read Receipt = no
Importance = 0
DoAuth = no
AuthType = Postfix
User =
Password = <Hidden>
15/11/22 10:45:46 opening socket
15/11/22 10:45:46 SOCKET Connection Established.
15/11/22 10:45:46 Number of lines: 2
str:220 *** ESMTP Postfix (Ubuntu)
15/11/22 10:45:46 Parse Line:1
Line:220 *** ESMTP Postfix (Ubuntu)
15/11/22 10:45:46 Begin read state 1
RESP:220 *** ESMTP Postfix (Ubuntu)
15/11/22 10:45:46 1 220 HELO
15/11/22 10:45:46 newstate: 5 - Sending: HELO localhost
15/11/22 10:45:46 newstate - before 0 16 0
15/11/22 10:45:46 newstate - after 16 16 16
15/11/22 10:45:46 END READ state 5
15/11/22 10:45:46 Number of lines: 2
str:250 ***
15/11/22 10:45:46 Parse Line:1
Line:250 ***
15/11/22 10:45:46 Begin read state 5
RESP:250 ***
15/11/22 10:45:46 5 250 Mail From
15/11/22 10:45:46 newstate: 6 - Sending: MAIL From: <***>
15/11/22 10:45:46 newstate - before 0 40 16
15/11/22 10:45:46 newstate - after 40 40 40
15/11/22 10:45:46 Recipient Cnt: 1
15/11/22 10:45:46 END READ state 6
15/11/22 10:45:46 Number of lines: 2
str:250 2.1.0 Ok
15/11/22 10:45:46 Parse Line:1
Line:250 2.1.0 Ok
15/11/22 10:45:46 Begin read state 6
RESP:250 2.1.0 Ok
15/11/22 10:45:46 6 250 Mail TO/CC 1 of (To:1 *** cc:0)
15/11/22 10:45:46 1 Email TO ***
15/11/22 10:45:46 newstate: 7 - Sending: RCPT TO: <***>
15/11/22 10:45:46 newstate - before 0 38 40
15/11/22 10:45:46 newstate - after 38 38 38
15/11/22 10:45:46 END READ state 7
15/11/22 10:45:46 Number of lines: 2
str:250 2.1.5 Ok
15/11/22 10:45:46 Parse Line:1
Line:250 2.1.5 Ok
15/11/22 10:45:46 Begin read state 7
RESP:250 2.1.5 Ok
15/11/22 10:45:46 7 250 Data
15/11/22 10:45:46 newstate: 8 - Sending: DATA
15/11/22 10:45:46 newstate - before 0 7 38
15/11/22 10:45:46 newstate - after 7 7 7
15/11/22 10:45:46 END READ state 8
15/11/22 10:45:46 Number of lines: 2
str:354 End data with <CR><LF>.<CR><LF>
15/11/22 10:45:46 Parse Line:1
Line:354 End data with <CR><LF>.<CR><LF>
15/11/22 10:45:46 Begin read state 8
RESP:354 End data with <CR><LF>.<CR><LF>
15/11/22 10:45:46 8 354 build HEADER/SEND data
15/11/22 10:45:46 writedata chomp NULL data 0
15/11/22 10:45:46 writedata - before 0 339 7
15/11/22 10:45:46 writedata - IN 0 339 7
15/11/22 10:45:46 writedata = after 339 339 339
15/11/22 10:45:46 writedata chomp NULL data 0
15/11/22 10:45:46 writedata - before 0 93 339
15/11/22 10:45:46 writedata - IN 0 93 339
15/11/22 10:45:46 writedata = after 93 93 93
15/11/22 10:45:46 writedata chomp NULL data 0
15/11/22 10:45:46 writedata - before 0 5 93
15/11/22 10:45:46 writedata - IN 0 5 93
15/11/22 10:45:46 writedata = after 5 5 5
15/11/22 10:45:46 newstate: 9 - Sending: .
15/11/22 10:45:46 newstate - before 0 3 5
15/11/22 10:45:46 newstate - after 3 3 3
15/11/22 10:45:46 END READ state 9
15/11/22 10:45:46 Number of lines: 2
str:250 2.0.0 Ok: queued as BEC08407C9
15/11/22 10:45:46 Parse Line:1
Line:250 2.0.0 Ok: queued as BEC08407C9
15/11/22 10:45:46 Begin read state 9
RESP:250 2.0.0 Ok: queued as BEC08407C9
15/11/22 10:45:46 9 250 SEND QUIT
15/11/22 10:45:46 newstate: 10 - Sending: QUIT
15/11/22 10:45:46 newstate - before 0 6 3
15/11/22 10:45:46 newstate - after 6 6 6
15/11/22 10:45:46 END READ state 10
15/11/22 10:45:46 END SMTP SESSION
and this is how it looks when being executed through the website and webspeed.
15/11/22 10:43:56
************** ****** New Group ******* ************
Socket email started
15/11/2022 10:43:56.933+00:00
Input Parameters
EmailFrom = ***
EmailReplyTo =
EmailTo = ***
EmailCC =
Attachments =
LocalFiles =
Subject = Email Test
Body = a
MIMEHeader = type=text/plain:charset=UTF-8
LocalHostName = localhost
Delivery Receipt = no
Read Receipt = no
Importance = 0
DoAuth = no
AuthType = Postfix
User =
Password = <Hidden>
15/11/22 10:43:56 opening socket
15/11/22 10:43:56 SOCKET Connection Established.
15/11/22 10:43:56 END READ state 1
15/11/22 10:43:57 Number of lines: 2
str:220 *** ESMTP Postfix (Ubuntu)
15/11/22 10:43:57 Parse Line:1
Line:220 *** ESMTP Postfix (Ubuntu)
15/11/22 10:43:57 Begin read state 1
RESP:220 *** ESMTP Postfix (Ubuntu)
15/11/22 10:43:57 1 220 HELO
15/11/22 10:43:57 newstate: 5 - Sending: HELO localhost
15/11/22 10:43:57 newstate - before 0 16 0
15/11/22 10:43:57 newstate - after 16 16 16
15/11/22 10:43:57 END READ state 5
15/11/22 10:43:58 Number of lines: 2
str:250 ***
15/11/22 10:43:58 Parse Line:1
Line:250 ***
15/11/22 10:43:58 Begin read state 5
RESP:250 ***
15/11/22 10:43:58 5 250 Mail From
15/11/22 10:43:58 newstate: 6 - Sending: MAIL From: <***>
15/11/22 10:43:58 newstate - before 0 40 16
15/11/22 10:43:58 newstate - after 40 40 40
15/11/22 10:43:58 Recipient Cnt: 1
15/11/22 10:43:58 END READ state 6
15/11/22 10:43:59 Number of lines: 2
str:250 2.1.0 Ok
15/11/22 10:43:59 Parse Line:1
Line:250 2.1.0 Ok
15/11/22 10:43:59 Begin read state 6
RESP:250 2.1.0 Ok
15/11/22 10:43:59 6 250 Mail TO/CC 1 of (To:1 *** cc:0)
15/11/22 10:43:59 1 Email TO ***
15/11/22 10:43:59 newstate: 7 - Sending: RCPT TO: <***>
15/11/22 10:43:59 newstate - before 0 38 40
15/11/22 10:43:59 newstate - after 38 38 38
15/11/22 10:43:59 END READ state 7
15/11/22 10:44:00 Number of lines: 2
str:250 2.1.5 Ok
15/11/22 10:44:00 Parse Line:1
Line:250 2.1.5 Ok
15/11/22 10:44:00 Begin read state 7
RESP:250 2.1.5 Ok
15/11/22 10:44:00 7 250 Data
15/11/22 10:44:00 newstate: 8 - Sending: DATA
15/11/22 10:44:00 newstate - before 0 7 38
15/11/22 10:44:00 newstate - after 7 7 7
15/11/22 10:44:00 END READ state 8
15/11/22 10:44:01 Number of lines: 2
str:354 End data with <CR><LF>.<CR><LF>
15/11/22 10:44:01 Parse Line:1
Line:354 End data with <CR><LF>.<CR><LF>
15/11/22 10:44:01 Begin read state 8
RESP:354 End data with <CR><LF>.<CR><LF>
15/11/22 10:44:01 8 354 build HEADER/SEND data
15/11/22 10:44:01 writedata chomp NULL data 0
15/11/22 10:44:01 writedata - before 0 324 7
15/11/22 10:44:01 writedata - IN 0 324 7
15/11/22 10:44:01 writedata = after 324 324 324
15/11/22 10:44:01 writedata chomp NULL data 0
15/11/22 10:44:01 writedata - before 0 93 324
15/11/22 10:44:01 writedata - IN 0 93 324
15/11/22 10:44:01 writedata = after 93 93 93
15/11/22 10:44:01 writedata chomp NULL data 0
15/11/22 10:44:01 writedata - before 0 4 93
15/11/22 10:44:01 writedata - IN 0 4 93
15/11/22 10:44:01 writedata = after 4 4 4
15/11/22 10:44:01 newstate: 9 - Sending: .
15/11/22 10:44:01 newstate - before 0 3 4
15/11/22 10:44:01 newstate - after 3 3 3
15/11/22 10:44:01 END READ state 9
15/11/22 10:44:03 Number of lines: 2
str:250 2.0.0 Ok: queued as F1A8A407C9
15/11/22 10:44:03 Parse Line:1
Line:250 2.0.0 Ok: queued as F1A8A407C9
15/11/22 10:44:03 Begin read state 9
RESP:250 2.0.0 Ok: queued as F1A8A407C9
15/11/22 10:44:03 9 250 SEND QUIT
15/11/22 10:44:03 newstate: 10 - Sending: QUIT
15/11/22 10:44:03 newstate - before 0 6 3
15/11/22 10:44:03 newstate - after 6 6 6
15/11/22 10:44:03 END READ state 10
15/11/22 10:44:03 END SMTP SESSION
The most recent version of FreeFrameWork that I can find is on sourceforge. This contains the following code for the loop, which also explains why this is running slowly under WebSpeed, which is running in batch mode:
IF NOT THIS-PROCEDURE:PERSISTENT AND
NOT SESSION:BATCH-MODE THEN WAIT-FOR CLOSE OF THIS-PROCEDURE.
ELSE IF SESSION:BATCH-MODE THEN DO:
/*********************************************************
9/19/2001 by Paul Keary
Progress will not wait-for input on a Socket while running in
batch mode. Simon Prinsloo [[email protected]] proposed this
simple code to workaround this problem.
******************************************************/
start-etime = ETIME.
DO WHILE sending:
PROCESS EVENTS.
PAUSE 1.
/* Build in timer in case sending is never set to NO
this will terminate the program after 60 seconds
start-Etime will be reset by WriteData each time there
is activity on the socket to allow for long transmissions */
IF start-etime + 60000 < ETIME THEN DO:
sending = NO.
RUN Cleanup.
END.
END.
END.
There is always a 1 second delay per event. Depending on your version of OpenEdge you can replace this with something like:
start-etime = ETIME.
DO WHILE sending:
PROCESS EVENTS.
WAIT-FOR READ-RESPONSE OF hsocket PAUSE 1.
IF ETIME - start-etime > 60000 THEN DO:
sending = FALSE.
MESSAGE "Connection Timed out.".
END.
END.
This will immediately act on a response on the socket instead of always waiting 1 second.