AnsweredAssumed Answered

Send Mail (SMTP) doesn't wait long enough for server response

Question asked by ehall on Feb 29, 2012
Latest reply on Apr 1, 2018 by user16691

Summary

Send Mail (SMTP) doesn't wait long enough for server response

Product

FileMaker Pro

Version

11.0v4

Operating system version

OS X 10.6.8 (Snow Leopard)

Description of the issue

When using the Send Mail script step to send email to an SMTP server, FileMaker sometimes returns a 1506 error, even though the email sent successfully.  This makes it impossible to handle errors, because we have no way of knowing whether a 1506 error is accurate or not.

Steps to reproduce the problem

Here is an example script that sends 20 emails to an SMTP server.  Try it on a slow SMTP server, or maybe try adding a large attachment.  If the server takes more than 5-10 seconds to process the email, FileMaker will return a 1506 error, even if the email is sent successfully.

I've attached a screenshot of the results from one test run.  Three of the illustrated attempts returned 1506 errors, even though two of those three were received successfully.

Set Error Capture [ On ]
Set Variable [ $max; Value:20 ] Loop
Set Variable [ $count; Value:$count + 1 ]
Set Variable [ $startTime; Value:Get ( CurrentTimeStamp ) ]
Send Mail [ Send via SMTP Server; To: "ehall@fantasyflightgames.com"; Subject: "Test email " & $count & " - " & Get(CurrentTimeStamp); Message: "Test email " & $count & " - " & Get(CurrentTimeStamp); Name: "FM Mail Test"; Email Address: "example@aaa.com"; SMTP Server: "mail.aaa.com"; Port: 25; Authentication Type: None ] [ No dialog ]
Set Variable [ $sendResults; Value:Let ( [ sendError = Get ( LastError ) ;
endTime = Get ( CurrentTimeStamp ) ; duration = endTime - $startTime ; logLine = sendError & " " & duration & "     " & $startTime & " " & endTime
];
$sendResults & logLine & ¶
)]
Exit Loop If [ $count ≥ $max ]

Expected result

FileMaker should not return an error if the email is sent successfully.  In this case, that may mean waiting longer for a response from the server.

Actual result

Occasional 1506 error, even if the email sends successfully.

Exact text of any error message(s) that appear

"Email(s) could not be sent successfully."

Configuration information

The SMTP server I'm connecting to runs OS X Server 10.6.8.  Here is a snippet from the /var/log/mail.log file that shows two example emails.  Both were sent successfully, but the first returned an error in FileMaker.

I attempted to remove identifying information from these logs.  Let me know if you need more information to research the issue.


## error 1506, but actually sent ok

Feb 29 13:57:23 edoras postfix/smtpd[79849]: 0E65138F6067: client=unknown[nn.nn.nn.nn]
Feb 29 13:57:23 edoras postfix/cleanup[77035]: 0E65138F6067: message-id=
Feb 29 13:57:50 edoras postfix/qmgr[42184]: 0E65138F6067: from=, size=159944, nrcpt=2 (queue active)
Feb 29 13:58:21 edoras postfix/smtp[77282]: 0E65138F6067: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=58, delays=28/0.08/0/31, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=79165-12, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as C628D38F60D8)
Feb 29 13:58:21 edoras postfix/smtp[77282]: 0E65138F6067: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=58, delays=28/0.08/0/31, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=79165-12, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as C628D38F60D8)
Feb 29 13:58:21 edoras postfix/qmgr[42184]: 0E65138F6067: removed

Feb 29 13:58:15 edoras postfix/smtpd[77822]: C628D38F60D8: client=localhost[127.0.0.1]
Feb 29 13:58:15 edoras postfix/cleanup[77696]: C628D38F60D8: message-id=
Feb 29 13:58:21 edoras postfix/qmgr[42184]: C628D38F60D8: from=, size=160316, nrcpt=2 (queue active)
Feb 29 13:58:25 edoras postfix/pipe[79251]: C628D38F60D8: to=, relay=dovecot, delay=9.5, delays=5.7/0.46/0/3.4, dsn=2.0.0, status=sent (delivered via dovecot service)
Feb 29 13:58:33 edoras postfix/smtp[79322]: C628D38F60D8: to=, relay=mail.bbb.com[mm.mm.mm.mm]:25, delay=18, delays=5.7/0.35/11/1.5, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 88D196DC120)
Feb 29 13:58:33 edoras postfix/qmgr[42184]: C628D38F60D8: removed


## no error, sent ok

Feb 29 14:03:34 edoras postfix/smtpd[80408]: BB92B38F6457: client=unknown[nn.nn.nn.nn]
Feb 29 14:03:34 edoras postfix/cleanup[80355]: BB92B38F6457: message-id=
Feb 29 14:03:36 edoras postfix/qmgr[42184]: BB92B38F6457: from=, size=159960, nrcpt=2 (queue active)
Feb 29 14:03:54 edoras postfix/smtp[80241]: BB92B38F6457: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=19, delays=1.8/0/0/18, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=79165-19, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 750E538F64AD)
Feb 29 14:03:54 edoras postfix/smtp[80241]: BB92B38F6457: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=19, delays=1.8/0/0/18, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=79165-19, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 750E538F64AD)
Feb 29 14:03:54 edoras postfix/qmgr[42184]: BB92B38F6457: removed

Feb 29 14:03:53 edoras postfix/smtpd[80308]: 750E538F64AD: client=localhost[127.0.0.1]
Feb 29 14:03:53 edoras postfix/cleanup[80429]: 750E538F64AD: message-id=
Feb 29 14:03:54 edoras postfix/qmgr[42184]: 750E538F64AD: from=, size=160332, nrcpt=2 (queue active)
Feb 29 14:03:55 edoras postfix/pipe[80152]: 750E538F64AD: to=, relay=dovecot, delay=2, delays=1/0.32/0/0.69, dsn=2.0.0, status=sent (delivered via dovecot service)
Feb 29 14:04:09 edoras postfix/smtp[80400]: 750E538F64AD: to=, relay=mail.bbb.com[mm.mm.mm.mm]:25, delay=17, delays=1/0/14/1.1, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 773AB84006)
Feb 29 14:04:09 edoras postfix/qmgr[42184]: 750E538F64AD: removed

script_output.png

Outcomes