Debugging SMTP connection problem

[Jeroen Oortwijn]

Hello,

I'm trying to set up the Email server on the GoCD server (http://localhost:8153/go/admin/config/server#!email-server), but I can't get it to work.

When I fill in all the details and click the Send Test Email button, after a while the following message appears:

There was an unknown error performing the operation. Possible reason (Not Acceptable)

In the server log (go-server.log) appears the following:

2020-08-27 16:51:18,460 ERROR [Thread-5048] GoSmtpMailSender:56 - Sending failed for email [Go Email Notification] to [gocd@***.**]

javax.mail.MessagingException: Exception reading response

at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:2460)

at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:2187)

at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:740)

at javax.mail.Service.connect(Service.java:366)

at com.thoughtworks.go.config.GoSmtpMailSender.send(GoSmtpMailSender.java:51)

at com.thoughtworks.go.config.BackgroundMailSender.lambda$send$0(BackgroundMailSender.java:48)

at java.base/java.lang.Thread.run(Unknown Source)

Caused by: java.net.SocketTimeoutException: Read timed out

at java.base/sun.nio.ch.NioSocketImpl.timedRead(Unknown Source)

at java.base/sun.nio.ch.NioSocketImpl.implRead(Unknown Source)

at java.base/sun.nio.ch.NioSocketImpl.read(Unknown Source)

at java.base/sun.nio.ch.NioSocketImpl$1.read(Unknown Source)

at java.base/java.net.Socket$SocketInputStream.read(Unknown Source)

at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:126)

at java.base/java.io.BufferedInputStream.fill(Unknown Source)

at java.base/java.io.BufferedInputStream.read(Unknown Source)

at com.sun.mail.util.LineInputStream.readLine(LineInputStream.java:106)

at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:2440)

... 6 common frames omitted

Above messages aren't really helpful in debugging the problem, so I want to view the SMTP log, but couldn't find it.

Is there a way to enable the SMTP log and where is it then located?

Kind regards,

Jeroen Oortwijn

[Ashwanth Kumar]

From the logs looks like the GoCD server is not able to connect to the SMTP server that's configured. May be check the firewall settings? 

The relevant section is the SocketTimeoutException from the logs. 

--
You received this message because you are subscribed to the Google Groups "go-cd" group.
To unsubscribe from this group and stop receiving emails from it, send an email to go-cd+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/83f969d6-72b9-4dbd-a46f-55ff0620041en%40googlegroups.com.

[Jeroen Oortwijn]

If I use SMTPS, I get a different error:

2020-08-27 18:42:10,370 ERROR [Thread-6531] GoSmtpMailSender:56 - Sending failed for email [Go Email Notification] to [gocd@***.**]

javax.mail.AuthenticationFailedException: 451 4.3.2 Internal server error

at com.sun.mail.smtp.SMTPTransport$Authenticator.authenticate(SMTPTransport.java:965)

at com.sun.mail.smtp.SMTPTransport.authenticate(SMTPTransport.java:876)

at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:780)

at javax.mail.Service.connect(Service.java:388)

at com.thoughtworks.go.config.GoSmtpMailSender.send(GoSmtpMailSender.java:51)

at com.thoughtworks.go.config.BackgroundMailSender.lambda$send$0(BackgroundMailSender.java:48)

at java.base/java.lang.Thread.run(Unknown Source)

[Jeroen Oortwijn]

I made a simple test application in C#:

namespace SMTP_send_email_test

{

    class Program

    {

        static void Main(string[] args)

        {

            var mimeMessage = new MimeKit.MimeMessage();

            mimeMessage.From.Add(new MimeKit.MailboxAddress("GoCD server", "gocd@***.**"));

            mimeMessage.To.Add(new MimeKit.MailboxAddress("GoCD server", "gocd@***.**"));

            mimeMessage.Subject = "Test message";

            mimeMessage.Body = new MimeKit.TextPart() { Text = "This is a test!" };

            using (var smtpClient = new MailKit.Net.Smtp.SmtpClient(new MailKit.ProtocolLogger("smtp.log")))

            {

                smtpClient.Connect("mail.antagonist.nl", 465, MailKit.Security.SecureSocketOptions.SslOnConnect);

                smtpClient.Authenticate("gocd@***.**", "********");

                smtpClient.Send(mimeMessage);

                smtpClient.Disconnect(true);

            }

        }

    }

}

And when run on the same PC as the GoCD server is running, it was able to send the mail (from smtp.log):

Connected to smtps://mail.antagonist.nl:465/

S: 220 smtp ESMTP ready

C: EHLO [10.0.2.15]

S: 250-smtp

S: 250 AUTH PLAIN LOGIN

C: AUTH PLAIN ****************

S: 235 2.0.0 OK

C: MAIL FROM:<gocd@***.**>

S: 250 OK

C: RCPT TO:<gocd@***.**>

S: 250 Accepted

C: DATA

S: 354 Enter message, ending with "." on a line by itself

C: From: GoCD server <gocd@***.**>

C: Date: Thu, 27 Aug 2020 18:37:21 +0200

C: Subject: Test message

C: Message-Id: <SP9BR6GPIBU4.QRAK6FVSVTCN2@***.**>

C: To: GoCD server <gocd@***.**>

C: MIME-Version: 1.0

C: Content-Type: text/plain; charset=utf-8

C: 

C: This is a test!

C: .

S: 250 OK id=1kBKts-00B44l-6x

C: QUIT

S: 221 s188.webhostingserver.nl closing connection

So it would be nice if I can see the SMTP log of the GOCD server, so I can further debug the issue.

[Ashwanth Kumar]

I'll probably wait for GoCD Developers to respond on the SMTP log. AFAIK there aren't any but there may be a flag to enable it. 

Based on the stack trace you shared earlier, it looks like there was an error with the credentials that was passed to GoCD.

javax.mail.AuthenticationFailedException: 451 4.3.2 Internal server error

Thanks,

--

You received this message because you are subscribed to the Google Groups "go-cd" group.
To unsubscribe from this group and stop receiving emails from it, send an email to go-cd+un...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/b398df0a-1372-435a-8e07-0fce9df130a0n%40googlegroups.com.

--

Ashwanth Kumar / ashwanthkumar.in

[Ketan Padegaonkar]

I don't believe there's a flag: but you may be able to set the system property `mail.debug` to true. Other system mail specific system properties are documented in this page.

- Ketan

To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/CAD9m7CxYB2XnKGD4nVXZPMN_yLj_GqZnarTiJbgchJizSFOB9w%40mail.gmail.com.

[Jeroen Oortwijn]

According to the FAQ (https://javaee.github.io/javamail/FAQ#debug), setting this system property causes the debug information to be printed to the console.

How do I then retrieve this information in case of the GoCD server, as there isn't any console?

- Jeroen

[Ketan Padegaonkar]

I forget the name of the log file (no longer on the gocd core team), but there's a wrapper output log or something.

- Ketan

To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/19516af7-56ff-481b-9842-b7c796c6629cn%40googlegroups.com.

[Jeroen Oortwijn]

Unfortunately, there's nothing interesting logged in go-server-wrapper.log.

- Jeroen

[Jeroen Oortwijn]

I decided to try the server on a fresh Ubuntu 20.04 installation, and there the test email works perfectly!

The following message appears:

Connection OK

And nothing get logged in the server log.

I can also see the message in the mail account.

I then decided to install the server on a clean Windows 10 (2004) installation, and there I also get the same error:

There was an unknown error performing the operation. Possible reason (Not Acceptable)

So it looks like sending mail messages (to this mail server) is broken on Windows 10, but works on Ubuntu 20.04.

I will file an issue on GitHub.

- Jeroen

[Jeroen Oortwijn]

The GitHub issue can be found at: https://github.com/gocd/gocd/issues/8513