# Postfix+tls+relay was working but now is broken

## darf

Hi all,

My setup was working just fine a month ago or so but all of a sudden its broken (see log below)

I can't figure out what the problem is, I'm not sure if I deleted a config file during an update or if my ISP changed something

on their server, I tried google for the error message and nothing turns up this time which is quite unusual OR its something

terribly simple that I just can't see it.

The error log:

```

Jun 14 13:33:20 reaver postfix/smtp[17455]: setting up TLS connection to smtphm.sympatico.ca

Jun 14 13:33:20 reaver postfix/smtp[17454]: Verified: subject_CN=smtphm.sympatico.ca, issuer=Entrust.net Secure Server Certification Authority

Jun 14 13:33:20 reaver postfix/smtp[17454]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)

Jun 14 13:33:21 reaver postfix/smtp[17454]: 2E64C258756: to=<darf@gameforce.ca>, orig_to=<root>, relay=smtphm.sympatico.ca[65.54.191.190]:25, delay=16400, del

ays=16389/0.04/11/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: another step is

 needed in authentication)

```

What the server says:

```

telnet smtphm.sympatico.ca 25                                                                                                                13:37

Trying 65.54.191.190...

Connected to smtphm.sympatico.ca.

Escape character is '^]'.

220 BAYC1-PASMTP06.CEZ.ICE Microsoft ESMTP MAIL Service, Version: 6.0.3790.2668 ready at  Thu, 14 Jun 2007 10:37:57 -0700

ehlo x

250-BAYC1-PASMTP06.CEZ.ICE Hello [69.156.60.31]

250-TURN

250-SIZE 35840000

250-ETRN

250-PIPELINING

250-DSN

250-ENHANCEDSTATUSCODES

250-8bitmime

250-BINARYMIME

250-CHUNKING

250-VRFY

250-TLS

250-STARTTLS

250 OK

quit

221 2.0.0 BAYC1-PASMTP06.CEZ.ICE Service closing transmission channel

Connection closed by foreign host.

```

My main.cf tls lines:

```

# client tls

smtp_use_tls = yes

smtp_sasl_auth_enable = yes

smtp_tls_CAfile = /etc/postfix/cacert.pem

tls_random_source = dev:/dev/urandom

smtp_sasl_password_maps = hash:/etc/postfix/saslpass

smtp_sasl_security_options = noanonymous

relayhost = smtphm.sympatico.ca

smtp_tls_loglevel = 1

```

Contents of /etc/postfix/saslpass: (I have used postmap on it)

```

# $Header: /var/cvsroot/gentoo-x86/mail-mta/postfix/files/smtp.pass,v 1.2 2004/07/18 03:26:56 dragonheart Exp $

#

# remotehost user:password

smtphm.sympatico.ca username@sympatico.ca:xxxxxx

```

The baffling part is the message "another step is needed in authentication" What step could it be?

Any guidance would be greately apreciated at this point.

Thanks!

----------

## steveb

 *darf wrote:*   

> 
> 
> ```
> 
> telnet smtphm.sympatico.ca 25                                                                                                                13:37
> ...

 

I don't see that server offering any authentication options. Where are the lines with:

```
250-AUTH DIGEST-MD5 CRAM-MD5 NTLM LOGIN PLAIN etc

250-AUTH=DIGEST-MD5 CRAM-MD5 NTLM LOGIN PLAIN etc
```

// SteveB

----------

## darf

 *steveb wrote:*   

> 
> 
> I don't see that server offering any authentication options. Where are the lines with:[code]250-AUTH DIGEST-MD5 CRAM-MD5 NTLM LOGIN PLAIN etc
> 
> // SteveB

 

I have no idea, does this mean they turned off authentication but still use tls?

0_o

----------

## steveb

 *darf wrote:*   

> I have no idea, does this mean they turned off authentication but still use tls?

 Yes. TLS != authentication.

Try to connect to port 587 instead of 25. Maybe they switched to the submission port for authentification? According to nmap the port is open.

// SteveB

----------

## elgato319

As you can see here:

```

Jun 14 13:33:20 reaver postfix/smtp[17454]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)

```

The server first builds up a tls connection and then does the authentification.

```

ays=16389/0.04/11/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: another step is

 needed in authentication) 

```

But it fails. Because it does the TLS thing first, you don't see the AUTH lines.

My guess is that your username/password have been disabled/altered on the other server.

You can use "net-mail/swaks" to test your authentification with tls to the other server

----------

## steveb

 *elgato319 wrote:*   

> As you can see here:
> 
> ```
> 
> Jun 14 13:33:20 reaver postfix/smtp[17454]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)
> ...

 right

 *elgato319 wrote:*   

> 
> 
> ```
> ays=16389/0.04/11/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: another step is
> 
> ...

 Because of the TLS connection the authorization fails? Because TLS? I never ever heard any thing like that before. According to your findings the server is not offering any auth stuff because you used first TLS? Where have you read this? Can you back up your claims?

 *elgato319 wrote:*   

> You can use "net-mail/swaks" to test your authentification with tls to the other server

 Cool. Did not know about that app. Thanx for that.

// SteveB

----------

## steveb

 *darf wrote:*   

> My main.cf tls lines:
> 
> ```
> # client tls
> 
> ...

 Can you change the relayhost line to be:

```
relayhost = securetls:[smtphm.sympatico.ca]
```

 *darf wrote:*   

> Contents of /etc/postfix/saslpass: (I have used postmap on it)
> 
> ```
> # $Header: /var/cvsroot/gentoo-x86/mail-mta/postfix/files/smtp.pass,v 1.2 2004/07/18 03:26:56 dragonheart Exp $
> 
> ...

 Can you change that as well to be:

```
[smtphm.sympatico.ca] username@sympatico.ca:xxxxxx
```

Did that helped? If not, then try changing this:

```
smtp_sasl_security_options = noanonymous
```

to this:

```
smtp_sasl_security_options =
```

If that as well did not help, then please add this to your main.cf:

```
debug_peer_list=smtphm.sympatico.ca

debug_peer_level=3
```

And then post again the output of the conversation from your local Postfix with the SMTP of your ISP.

// SteveB

----------

## darf

First of all thank you for all the ideas and replies, you have no idea how much this thing is frustrating, or maybe you do  :Wink: 

Ok, for the 587 issue, I tried it and got the same exact results, both port 25 and 587 behave the same way.

The securetty:host line didnot work at all, in fact it broke the localhost from accepting any email with invalid transport errors

I changed the relayhost and the saslpass file to have brackets as well, result however still the same

So I turned on the debugging as suggested and saw a few things that may help,  The AUTH info is displayed on the second ehlo (why does it do it twice?)

Second thing I noticed is maps_find: smtp_sasl_passwd: smtphm.sympatico.ca: not found yet on the line imediately after that it finds it and authenticates me

So in essence, I see that my username password is correct, I do get authenticated however I am still missing something to complete the relay

```

Jun 15 09:37:59 reaver syslog-ng[10987]: syslog-ng version 1.6.11 starting

Jun 15 09:37:59 reaver syslog-ng[10987]: Changing permissions on special file /dev/tty12

Jun 15 09:38:09 reaver ddclient[10898]: WARNING:  caught SIGTERM; exiting

Jun 15 09:38:09 reaver postfix/pickup[10826]: 6628B25A0B7: uid=0 from=<root>

Jun 15 09:38:09 reaver postfix/cleanup[10873]: 6628B25A0B7: message-id=<20070615133809.6628B25A0B7@reaver.gameforce.ca>

Jun 15 09:38:09 reaver postfix/qmgr[10827]: 6628B25A0B7: from=<root@reaver.gameforce.ca>, size=424, nrcpt=1 (queue active)

Jun 15 09:38:09 reaver postfix/cleanup[10873]: 6951E25A0A9: message-id=<20070615133809.6628B25A0B7@reaver.gameforce.ca>

Jun 15 09:38:09 reaver postfix/qmgr[10827]: 6951E25A0A9: from=<root@reaver.gameforce.ca>, size=564, nrcpt=1 (queue active)

Jun 15 09:38:09 reaver postfix/local[10874]: 6628B25A0B7: to=<root@reaver.gameforce.ca>, orig_to=<root>, relay=local, delay=0.03, delays=0.02/0/0/0.01, dsn=2.

0.0, status=sent (forwarded as 6951E25A0A9)

Jun 15 09:38:09 reaver postfix/qmgr[10827]: 6628B25A0B7: removed

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 14 got 124

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 220 BAYC1-PASMTP02.CEZ.ICE Microsoft ESMTP MAIL Service, Version: 6.0.3790.2

668 ready at  Fri, 15 Ju

Jun 15 09:38:09 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: EHLO reaver.gameforce.ca

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 26

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 14 got 223

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-BAYC1-PASMTP02.CEZ.ICE Hello [69.156.60.31]

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-TURN

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-SIZE 35840000

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-ETRN

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-PIPELINING

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-DSN

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-ENHANCEDSTATUSCODES

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-8bitmime

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-BINARYMIME

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-CHUNKING

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-VRFY

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-TLS

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-STARTTLS

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK

Jun 15 09:38:09 reaver postfix/smtp[10829]: server features: 0x901f size 35840000

Jun 15 09:38:09 reaver postfix/smtp[10829]: Using ESMTP PIPELINING, TCP send buffer size is 4096

Jun 15 09:38:09 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: STARTTLS

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 10

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 14 got 29

Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 220 2.0.0 SMTP server ready

Jun 15 09:38:09 reaver postfix/smtp[10829]: setting up TLS connection to smtphm.sympatico.ca

Jun 15 09:38:09 reaver postfix/smtp[10829]: event_request_timer: reset 0x806fde6 0x80ab630 100

Jun 15 09:38:09 reaver postfix/smtp[10829]: send attr request = lookup

Jun 15 09:38:09 reaver postfix/smtp[10829]: send attr cache_type = smtp

Jun 15 09:38:09 reaver postfix/smtp[10829]: send attr cache_id = smtp:65.54.191.190:25:BAYC1-PASMTP02.CEZ.ICE

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_fflush_some: fd 9 flush 86

Jun 15 09:38:09 reaver postfix/smtp[10829]: private/tlsmgr: wanted attribute: status

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 9 got 28

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute name: status

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute value: 4294967294

Jun 15 09:38:09 reaver postfix/smtp[10829]: private/tlsmgr: wanted attribute: session

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute name: session

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute value: (end)

Jun 15 09:38:09 reaver postfix/smtp[10829]: private/tlsmgr: wanted attribute: (list terminator)

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute name: (end)

Jun 15 09:38:09 reaver postfix/smtp[10829]: event_request_timer: reset 0x806fde6 0x80ab630 100

Jun 15 09:38:09 reaver postfix/smtp[10829]: send attr request = seed

Jun 15 09:38:09 reaver postfix/smtp[10829]: send attr size = 32

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_fflush_some: fd 9 flush 22

Jun 15 09:38:09 reaver postfix/smtp[10829]: private/tlsmgr: wanted attribute: status

Jun 15 09:38:09 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 9 got 60

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute name: status

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute value: 0

Jun 15 09:38:09 reaver postfix/smtp[10829]: private/tlsmgr: wanted attribute: seed

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute name: seed

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute value: 4iOCNm54EnQcun6uxE1P4osoyuJWcgCza0TMCWb1M2Y=

Jun 15 09:38:09 reaver postfix/smtp[10829]: private/tlsmgr: wanted attribute: (list terminator)

Jun 15 09:38:09 reaver postfix/smtp[10829]: input attribute name: (end)

Jun 15 09:38:10 reaver postfix/smtp[10829]: Verified: subject_CN=smtphm.sympatico.ca, issuer=Entrust.net Secure Server Certification Authority

Jun 15 09:38:10 reaver postfix/smtp[10829]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)

Jun 15 09:38:10 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: EHLO reaver.gameforce.ca

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 26

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 14 got 222

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-BAYC1-PASMTP02.CEZ.ICE Hello [69.156.60.31]

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-TURN

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-SIZE 35840000

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-ETRN

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-PIPELINING

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-DSN

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-ENHANCEDSTATUSCODES

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-8bitmime

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-BINARYMIME

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-CHUNKING

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-VRFY

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-AUTH LOGIN PLAIN <---- There is the Auth stuff

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK

Jun 15 09:38:10 reaver postfix/smtp[10829]: server features: 0x902f size 35840000

Jun 15 09:38:10 reaver postfix/smtp[10829]: Using ESMTP PIPELINING, TCP send buffer size is 4096

Jun 15 09:38:10 reaver postfix/smtp[10829]: maps_find: smtp_sasl_passwd: smtphm.sympatico.ca: not found <--- What is it looking for here?

Jun 15 09:38:10 reaver postfix/smtp[10829]: maps_find: smtp_sasl_passwd: hash:/etc/postfix/saslpass(0,lock|fold_fix): [smtphm.sympatico.ca] = username@sympatico.ca:xxxxxx

Jun 15 09:38:10 reaver postfix/smtp[10829]: smtp_sasl_passwd_lookup: host `smtphm.sympatico.ca' user `username@sympatico.ca' pass `xxxxxx'

Jun 15 09:38:10 reaver postfix/smtp[10829]: starting new SASL client

Jun 15 09:38:10 reaver postfix/smtp[10829]: smtp_sasl_authenticate: smtphm.sympatico.ca[65.54.191.190]: SASL mechanisms LOGIN PLAIN

Jun 15 09:38:10 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: AUTH LOGIN

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 12

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 14 got 19

Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 334 VXNlcm5hbWU6

Jun 15 09:38:10 reaver postfix/smtp[10829]: connect to subsystem private/defer

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr nrequest = 0

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr flags = 0

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr queue_id = 6951E25A0A9

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr original_recipient = root

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr recipient = otheruser@gameforce.ca

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr offset = 163

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr dsn_orig_rcpt =

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr notify_flags = 0

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr status = 4.7.0

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr diag_type = x-sasl

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr diag_text = another step is needed in authentication

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr mta_type =

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr mta_mname =

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr action = delayed

Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr reason = SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: a

nother step is needed in authentication

Jun 15 09:38:10 reaver postfix/smtp[10829]: private/defer socket: wanted attribute: status

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_fflush_some: fd 15 flush 393

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 15 got 10

Jun 15 09:38:10 reaver postfix/smtp[10829]: input attribute name: status

Jun 15 09:38:10 reaver postfix/smtp[10829]: input attribute value: 0

Jun 15 09:38:10 reaver postfix/smtp[10829]: private/defer socket: wanted attribute: (list terminator)

Jun 15 09:38:10 reaver postfix/smtp[10829]: input attribute name: (end)

Jun 15 09:38:10 reaver postfix/smtp[10829]: 6951E25A0A9: to=<otheruser@gameforce.ca>, orig_to=<root>, relay=smtphm.sympatico.ca[65.54.191.190]:25, delay=1.1, delay

s=0.01/0/1.1/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: another step is need

ed in authentication)

Jun 15 09:38:10 reaver postfix/smtp[10829]: flush_add: site gameforce.ca id 6951E25A0A9

Jun 15 09:38:10 reaver postfix/smtp[10829]: match_hostname: gameforce.ca ~? reaver.gameforce.ca

Jun 15 09:38:10 reaver postfix/smtp[10829]: match_hostname: gameforce.ca ~? localhost.gameforce.ca

Jun 15 09:38:10 reaver postfix/smtp[10829]: match_hostname: gameforce.ca ~? localhost

Jun 15 09:38:10 reaver postfix/smtp[10829]: match_list_match: gameforce.ca: no match

Jun 15 09:38:10 reaver postfix/smtp[10829]: flush_add: site gameforce.ca id 6951E25A0A9 status 4

Jun 15 09:38:10 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: QUIT

Jun 15 09:38:10 reaver postfix/smtp[10829]: name_mask: resource

Jun 15 09:38:10 reaver postfix/smtp[10829]: name_mask: software

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 6

Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 0

Jun 15 09:38:10 reaver postfix/smtp[10829]: disposing SASL state information

```

----------

## elgato319

@steveb

 *Quote:*   

> 
> 
> Because of the TLS connection the authorization fails? Because TLS? I never ever heard any thing like that before. According to your findings the server is not offering any auth stuff because you used first TLS? Where have you read this? Can you back up your claims? 
> 
> 

 

what i meant was:

the server has 	possibly enabled "smtpd_tls_auth_only = yes" in it's config

this means the smtp-server only offers SMTP AUTH after the client has successfully established a TLS session

this way the client can use the unsecure AUTH LOGIN over a secured line

http://postfix.state-of-mind.de/patrick.koetter/smtpauth/postfix_tls_support.html

 *Quote:*   

> 
> 
> 15.8. Enabling Postfix to offer SMTP AUTH only when TLS is established
> 
> That leaves us with one major step to be done. We want to make sure that SMTP AUTH PLAIN will only be available to users who use TLS. So we advise Postfix to issue the SMTP AUTH command only when TLS has been established. This brings us back to the one line we had left commented out in main.cf when we added TLS support.
> ...

 

with swaks you can establish an tls connection and check if the username/password pair is still correct.  :Smile: 

----------

## elgato319

second post to clear thing up from the debug output above...

 *Quote:*   

> 
> 
> Jun 15 09:38:09 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: EHLO reaver.gameforce.ca 
> 
> 

 

be nice and do a ehlo

 *Quote:*   

> 
> 
> Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-STARTTLS
> 
> Jun 15 09:38:09 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK 
> ...

 

oh cool i can use tls to secure my connection, but no auth though... so lets do tls first

 *Quote:*   

> 
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: EHLO reaver.gameforce.ca 
> ...

 

at last i'm secured!! lets to the ehlo thing again and see if everything is still allright to send my email

 *Quote:*   

> 
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250-AUTH LOGIN PLAIN <---- There is the Auth stuff
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK 
> ...

 

yey! now that i'm secured over tls i can use AUTH

 *Quote:*   

> 
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: > smtphm.sympatico.ca[65.54.191.190]: AUTH LOGIN
> 
> 

 

ok lets do AUTH LOGIN

 *Quote:*   

> 
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_fflush_some: fd 14 flush 12
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: vstream_buf_get_ready: fd 14 got 19
> ...

 

the server sends me "Username:" base64 encoded

 *Quote:*   

> Jun 15 09:38:10 reaver postfix/smtp[10829]: send attr reason = SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: a
> 
> nother step is needed in authentication 

 

something goes horribly wrong, i didnt send the username and sasl whines about it, sorry i can't auth on this server  :Sad: 

----------------------------------

i think something goes wrong over here:

 *Quote:*   

> 
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: maps_find: smtp_sasl_passwd: smtphm.sympatico.ca: not found <--- What is it looking for here?
> 
> Jun 15 09:38:10 reaver postfix/smtp[10829]: maps_find: smtp_sasl_passwd: hash:/etc/postfix/saslpass(0,lock|fold_fix): [smtphm.sympatico.ca] = username@sympatico.ca:xxxxxx
> ...

 

could you please try swaks? giving it your username/password by hand

----------

## darf

Ok swaks worked fine (log below)

So theres two files I can think of 1 is the saslpass 

```

# remotehost user:password

[smtphm.sympatico.ca] username@sympatico.ca:xxxxxx

```

the other is /etc/sasl2/smtpd.conf which has these lines:

```

pwcheck_method:saslauthd

mech_list: plain login

```

swaks output

```

  :>  cat kernel.config | swaks -g -n -t otheruser@gameforce.ca -tlso -a -au username@sympatico.ca -ap xxxxxx -s smtphm.sympatico.ca                        10:19

=== Trying smtphm.sympatico.ca:25...

=== Connected to smtphm.sympatico.ca.

<-  220 BAYC1-PASMTP04.CEZ.ICE Microsoft ESMTP MAIL Service, Version: 6.0.3790.2668 ready at  Fri, 15 Jun 2007 07:19:58 -0700

 -> EHLO reaver.gameforce.ca

<-  250-BAYC1-PASMTP04.CEZ.ICE Hello [69.156.60.31]

<-  250-TURN

<-  250-SIZE 35840000

<-  250-ETRN

<-  250-PIPELINING

<-  250-DSN

<-  250-ENHANCEDSTATUSCODES

<-  250-8bitmime

<-  250-BINARYMIME

<-  250-CHUNKING

<-  250-VRFY

<-  250-TLS

<-  250-STARTTLS

<-  250 OK

 -> STARTTLS

<-  220 2.0.0 SMTP server ready

=== TLS started w/ cipher RC4-MD5

 ~> EHLO reaver.gameforce.ca

<~  250-BAYC1-PASMTP04.CEZ.ICE Hello [69.156.60.31]

<~  250-TURN

<~  250-SIZE 35840000

<~  250-ETRN

<~  250-PIPELINING

<~  250-DSN

<~  250-ENHANCEDSTATUSCODES

<~  250-8bitmime

<~  250-BINARYMIME

<~  250-CHUNKING

<~  250-VRFY

<~  250-AUTH LOGIN PLAIN

<~  250 OK

 ~> AUTH LOGIN

<~  334 VXNlcm5hbWU6

 ~> Z290bmlja0BzeW1wYXRpY28uY2E=

<~  334 UGFzc3dvcmQ6

 ~> dGh4MTEzOA==

<~  235 Authentication succeeded

 ~> MAIL FROM:<root@reaver.gameforce.ca>

<~  250 2.1.0 root@reaver.gameforce.ca....Sender OK

 ~> RCPT TO:<otheruser@gameforce.ca>

<~  250 2.1.5 otheruser@gameforce.ca

 ~> DATA

<~  354 Start mail input; end with <CRLF>.<CRLF>

 ~> 1785 lines sent

<~  250 2.6.0 <BAYC1-PASMTP04oe2U800027f81@BAYC1-PASMTP04.CEZ.ICE> Queued mail for delivery

 ~> QUIT

<~  221 2.0.0 BAYC1-PASMTP04.CEZ.ICE Service closing transmission channel

=== Connection closed with remote host.

```

Hwoever I connected directly to the server with swaks, I am thinking that there is something wrong with my postfix config since it seems that postfix is not giving the relay server what it wants, ideas? Here is my complete postconf -n:

```

alias_database = hash:/etc/mail/aliases

alias_maps = hash:/etc/mail/aliases

command_directory = /usr/sbin

config_directory = /etc/postfix

daemon_directory = /usr/lib/postfix

debug_peer_level = 3

debug_peer_list = smtphm.sympatico.ca

default_destination_concurrency_limit = 2

home_mailbox = .maildir/

local_destination_concurrency_limit = 2

mail_owner = postfix

manpage_directory = /usr/share/man

mydestination = $myhostname, localhost.$mydomain, localhost

mydomain = gameforce.ca

myhostname = reaver.gameforce.ca

mynetworks = 127.0.0.0/8 192.168.0.0/24

mynetworks_style = subnet

myorigin = $myhostname

queue_directory = /var/spool/postfix

readme_directory = /usr/share/doc/postfix-2.3.6/readme

relayhost = [smtphm.sympatico.ca]

smtp_sasl_auth_enable = yes

smtp_sasl_password_maps = hash:/etc/postfix/saslpass

smtp_sasl_security_options =

smtp_tls_CAfile = /etc/postfix/cacert.pem

smtp_tls_loglevel = 1

smtp_use_tls = yes

smtpd_tls_CAfile = /etc/ssl/postfix/demoCA/cacert.pem

smtpd_tls_ask_ccert = yes

smtpd_tls_auth_only = no

smtpd_tls_cert_file = /etc/ssl/postfix/newcert.pem

smtpd_tls_key_file = /etc/ssl/postfix/newkey.pem

smtpd_tls_loglevel = 3

smtpd_tls_received_header = yes

smtpd_tls_session_cache_timeout = 3600s

smtpd_use_tls = yes

tls_random_source = dev:/dev/urandom

```

Thanks

----------

## steveb

Looks to me like the remote SMTPD does not like the PLAIN mechanism. Try to use only the LOGIN mechanism:

```
smtp_sasl_mechanism_filter = login
```

Does that help?

----------

## darf

 *steveb wrote:*   

> Looks to me like the remote SMTPD does not like the PLAIN mechanism. Try to use only the LOGIN mechanism:
> 
> ```
> smtp_sasl_mechanism_filter = login
> ```
> ...

 

Doesn't do anything, it just looks like when the server asks postfix for the username postfix craps out or sends something that its not supposed to, as evidenced by this log snippet:

```

Jun 15 12:51:02 reaver postfix/smtp[15858]: smtp_sasl_authenticate: smtphm.sympatico.ca[65.54.191.190]: SASL mechanisms LOGIN

Jun 15 12:51:02 reaver postfix/smtp[15858]: > smtphm.sympatico.ca[65.54.191.190]: AUTH LOGIN

Jun 15 12:51:02 reaver postfix/smtp[15858]: vstream_fflush_some: fd 14 flush 12

Jun 15 12:51:03 reaver postfix/smtp[15858]: vstream_buf_get_ready: fd 14 got 19

Jun 15 12:51:03 reaver postfix/smtp[15858]: < smtphm.sympatico.ca[65.54.191.190]: 334 VXNlcm5hbWU6

Jun 15 12:51:03 reaver postfix/smtp[15858]: connect to subsystem private/defer

```

334 VXNlcm5hbWU6 = this is username in base64

then the next line postfix is defered, so it fails right there. Is there some way I can raise logging/debugging to see what happens at that point?

----------

## steveb

Just increase the debug_peer_level value (4 should be more then enough).

----------

## weedy

 *darf wrote:*   

> Hi all,
> 
> My setup was working just fine a month ago or so but all of a sudden its broken (see log below)
> 
> 

 What he said.

Config:

```
# postconf -n

alias_database = hash:/etc/mail/aliases

alias_maps = hash:/etc/mail/aliases

broken_sasl_auth_clients = yes

command_directory = /usr/sbin

config_directory = /etc/postfix

daemon_directory = /usr/lib/postfix

debug_peer_level = 4

debug_peer_list = smtphm.sympatico.ca

default_destination_concurrency_limit = 20

home_mailbox = .maildir/

html_directory = /usr/share/doc/postfix-2.4.3/html

local_destination_concurrency_limit = 2

mail_owner = postfix

mailq_path = /usr/bin/mailq

manpage_directory = /usr/share/man

mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain, mail.$mydomain, kamo-chan.$mydomain

mydomain = lan

myhostname = Suigintou.lan

mynetworks = 192.168.1.0/24, 127.0.0.0/8

mynetworks_style = subnet

myorigin = Suigintou.lan

newaliases_path = /usr/bin/newaliases

queue_directory = /var/spool/postfix

readme_directory = /usr/share/doc/postfix-2.4.3/readme

relayhost = smtphm.sympatico.ca

sendmail_path = /usr/sbin/sendmail

setgid_group = postdrop

smtp_sasl_auth_enable = yes

smtp_sasl_password_maps = hash:/etc/postfix/saslpass

smtp_sasl_security_options =

smtp_tls_CAfile = /etc/ssl/postfix/server.pem

smtp_tls_loglevel = 2

smtp_tls_note_starttls_offer = yes

smtp_use_tls = yes

smtpd_client_restrictions = permit_mynetworks, permit_sasl_authenticated, reject

smtpd_sasl_auth_enable = yes

smtpd_sasl_local_domain =

smtpd_sasl_security_options = noanonymous

smtpd_tls_CAfile = /etc/ssl/postfix/server.pem

smtpd_tls_auth_only = yes

smtpd_tls_cert_file = /etc/ssl/postfix/server.crt

smtpd_tls_key_file = /etc/ssl/postfix/server.key

smtpd_tls_loglevel = 3

smtpd_tls_received_header = yes

smtpd_tls_session_cache_timeout = 3600s

smtpd_use_tls = yes

tls_random_source = dev:/dev/urandom

unknown_local_recipient_reject_code = 450

```

Logs:

```
Aug  7 01:08:53 Suigintou postfix/postfix-script[20477]: refreshing the Postfix mail system

Aug  7 01:08:53 Suigintou postfix/master[18547]: reload configuration /etc/postfix

Aug  7 01:08:55 Suigintou postfix/qmgr[20481]: 4A18D2C028: from=<weedy@Suigintou.lan>, size=415, nrcpt=1 (queue active)

Aug  7 01:08:55 Suigintou postfix/smtp[20486]: initializing the client-side TLS engine

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 16 got 133

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 220 bayc1-pasmtp09.bayc1.hotmail.com Microsoft ESMTP MAIL Service, Version: 6.0.3790.2668 ready at

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: > smtphm.sympatico.ca[65.54.191.190]: EHLO Suigintou.lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 20

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 16 got 233

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-bayc1-pasmtp09.bayc1.hotmail.com Hello [65.92.119.68]

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-TURN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-SIZE 35840000

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-ETRN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-PIPELINING

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-DSN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-ENHANCEDSTATUSCODES

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-8bitmime

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-BINARYMIME

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-CHUNKING

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-VRFY

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-TLS

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-STARTTLS

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: server features: 0x901f size 35840000

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: Using ESMTP PIPELINING, TCP send buffer size is 4096

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: > smtphm.sympatico.ca[65.54.191.190]: STARTTLS

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 10

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 16 got 29

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 220 2.0.0 SMTP server ready

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: setting up TLS connection to smtphm.sympatico.ca

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: looking for session smtp:65.54.191.190:25:bayc1-pasmtp09.bayc1.hotmail.com in smtp cache

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: event_request_timer: reset 0x80029d59 0x80064fa0 5

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr request = lookup

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr cache_type = smtp

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr cache_id = smtp:65.54.191.190:25:bayc1-pasmtp09.bayc1.hotmail.com

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 9 flush 96

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 9 got 28

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/tlsmgr: wanted attribute: status

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: status

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute value: 4294967294

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/tlsmgr: wanted attribute: session

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: session

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute value: (end)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/tlsmgr: wanted attribute: (list terminator)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: (end)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: event_request_timer: reset 0x80029d59 0x80064fa0 5

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr request = seed

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr size = 32

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 9 flush 22

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 9 got 60

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/tlsmgr: wanted attribute: status

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: status

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute value: 0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/tlsmgr: wanted attribute: seed

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: seed

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute value: I7rzE7f6EfG200pTBO0hUBKMjhKbkzZ0CZj6LMJ9snc=

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/tlsmgr: wanted attribute: (list terminator)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: (end)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:before/connect initialization

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv2/v3 write client hello A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv2/v3 read server hello A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read server hello A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read server hello A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read server hello A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 read server hello A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: certificate verification depth=1 subject=/C=US/O=Entrust.net/OU=www.entrust.net/CPS incorp. by ref. (limits liab.)/OU=(c) 1999 Entrust.net Limited/CN=Entrust.net Secure Server Certification Authority

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: verify return: 1

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: certificate verification depth=0 subject=/C=CA/ST=Ontario/L=Toronto/O=Bell Canada/OU=Bell Sympatico/CN=smtphm.sympatico.ca

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: verify return: 1

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 read server certificate A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 read server done A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 write client key exchange A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 write change cipher spec A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 write finished A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 flush data

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read finished A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read finished A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read finished A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:error in SSLv3 read finished A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: SSL_connect:SSLv3 read finished A

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: Verified: subject_CN=smtphm.sympatico.ca, issuer=Entrust.net Secure Server Certification Authority

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: > smtphm.sympatico.ca[65.54.191.190]: EHLO Suigintou.lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 20

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 16 got 232

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-bayc1-pasmtp09.bayc1.hotmail.com Hello [65.92.119.68]

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-TURN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-SIZE 35840000

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-ETRN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-PIPELINING

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-DSN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-ENHANCEDSTATUSCODES

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-8bitmime

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-BINARYMIME

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-CHUNKING

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-VRFY

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250-AUTH LOGIN PLAIN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: server features: 0x902f size 35840000

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: Using ESMTP PIPELINING, TCP send buffer size is 4096

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: maps_find: smtp_sasl_passwd: hash:/etc/postfix/saslpass(0,lock|fold_fix): smtphm.sympatico.ca = NOU@sympatico.ca:OVER9000

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: smtp_sasl_passwd_lookup: host `smtphm.sympatico.ca' user `NOU@sympatico.ca' pass `OVER9000'

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: starting new SASL client

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: smtp_sasl_authenticate: smtphm.sympatico.ca[65.54.191.190]: SASL mechanisms LOGIN PLAIN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: > smtphm.sympatico.ca[65.54.191.190]: AUTH LOGIN

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 12

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 16 got 19

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: < smtphm.sympatico.ca[65.54.191.190]: 334 VXNlcm5hbWU6

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: connect to subsystem private/defer

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr nrequest = 0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr flags = 0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr queue_id = 4A18D2C028

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr original_recipient = weedy2887@MAHLAZAH.com

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr recipient = weedy2887@MAHLAZAH.com

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr offset = 191

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr dsn_orig_rcpt =

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr notify_flags = 0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr status = 4.7.0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr diag_type = x-sasl

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr diag_text = another step is needed in authentication

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr mta_type =

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr mta_mname =

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr action = delayed

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: send attr reason = SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: another step is needed in authentication

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 17 flush 409

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_buf_get_ready: fd 17 got 10

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/defer socket: wanted attribute: status

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: status

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute value: 0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: private/defer socket: wanted attribute: (list terminator)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: input attribute name: (end)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: 4A18D2C028: to=<weedy2887@MAHLAZAH.com>, relay=smtphm.sympatico.ca[65.54.191.190]:25, delay=2822, delays=2821/0.08/0.92/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtphm.sympatico.ca[65.54.191.190]: another step is needed in authentication)

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: flush_add: site MAHLAZAH.com id 4A18D2C028

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_hostname: MAHLAZAH.com ~? Suigintou.lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_hostname: MAHLAZAH.com ~? localhost.lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_hostname: MAHLAZAH.com ~? localhost

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_hostname: MAHLAZAH.com ~? lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_hostname: MAHLAZAH.com ~? mail.lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_hostname: MAHLAZAH.com ~? kamo-chan.lan

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: match_list_match: MAHLAZAH.com: no match

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: flush_add: site MAHLAZAH.com id 4A18D2C028 status 4

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: > smtphm.sympatico.ca[65.54.191.190]: QUIT

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: name_mask: resource

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: name_mask: software

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 6

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 0

Aug  7 01:08:56 Suigintou postfix/smtp[20486]: disposing SASL state information
```

Help would be awesome. Thanks.

----------

## elgato319

TLS seems to work fine.

 *Quote:*   

> 
> 
> Aug  7 01:08:56 Suigintou postfix/smtp[20486]: > smtphm.sympatico.ca[65.54.191.190]: AUTH LOGIN
> 
> Aug  7 01:08:56 Suigintou postfix/smtp[20486]: vstream_fflush_some: fd 16 flush 12
> ...

 

The client sends: AUTH LOGIN

and the server answers with: "Username:"

But the Client never sends it.

Try using "swaks" as stated above to further examain the problem.

----------

## weedy

```
cat kernelupdate.sh | swaks -g -n -t weedy2887@MAHLAZAH.com -tlso -a -au NOU@sympatico.ca -ap OVER9000 -s smtphm.sympatico.ca

=== Trying smtphm.sympatico.ca:25...

=== Connected to smtphm.sympatico.ca.

<-  220 bayc1-pasmtp06.bayc1.hotmail.com Microsoft ESMTP MAIL Service, Version: 6.0.3790.2668 ready at  Wed, 8 Aug 2007 11:40:40 -0700

 -> EHLO Suigintou.lan

<-  250-bayc1-pasmtp06.bayc1.hotmail.com Hello [65.92.119.68]

<-  250-TURN

<-  250-SIZE 35840000

<-  250-ETRN

<-  250-PIPELINING

<-  250-DSN

<-  250-ENHANCEDSTATUSCODES

<-  250-8bitmime

<-  250-BINARYMIME

<-  250-CHUNKING

<-  250-VRFY

<-  250-TLS

<-  250-STARTTLS

<-  250 OK

 -> STARTTLS

<-  220 2.0.0 SMTP server ready

=== TLS started w/ cipher RC4-MD5

 ~> EHLO Suigintou.lan

<~  250-bayc1-pasmtp06.bayc1.hotmail.com Hello [65.92.119.68]

<~  250-TURN

<~  250-SIZE 35840000

<~  250-ETRN

<~  250-PIPELINING

<~  250-DSN

<~  250-ENHANCEDSTATUSCODES

<~  250-8bitmime

<~  250-BINARYMIME

<~  250-CHUNKING

<~  250-VRFY

<~  250-AUTH LOGIN PLAIN

<~  250 OK

 ~> AUTH LOGIN

<~  334 VXNlcm5hbWU6

 ~> d2VlZHlAc3ltcGF0aWNvLmNh

<~  334 UGFzc3dvcmQ6

 ~> aXNoY2FiaWJlbA==

<~  235 Authentication succeeded

 ~> MAIL FROM:<root@Suigintou.lan>

<~  250 2.1.0 root@Suigintou.lan....Sender OK

 ~> RCPT TO:<weedy2887@MAHLAZAH.com>

<~  250 2.1.5 weedy2887@MAHLAZAH.com

 ~> DATA

<~  354 Start mail input; end with <CRLF>.<CRLF>

 ~> 47 lines sent

<~  250 2.6.0 <BAYC1-PASMTP06ds7b80000816f@bayc1-pasmtp06.bayc1.hotmail.com> Queued mail for delivery

 ~> QUIT

<~  221 2.0.0 bayc1-pasmtp06.bayc1.hotmail.com Service closing transmission channel

=== Connection closed with remote host.

```

----------

## weedy

I fixed it with:

smtp_sasl_mechanism_filter = plain

Are they any real down sides to forcing plain login? how come swaks works with login?

```
Aug  8 15:06:25 Suigintou postfix/postfix-script[32268]: refreshing the Postfix mail system

Aug  8 15:06:25 Suigintou postfix/master[4437]: reload configuration /etc/postfix

Aug  8 15:11:01 Suigintou postfix/pickup[32272]: 063B62B1F2: uid=1000 from=<weedy>

Aug  8 15:11:01 Suigintou postfix/cleanup[32372]: 063B62B1F2: message-id=<20070808191100.GA32367@Suigintou.lan>

Aug  8 15:11:01 Suigintou postfix/qmgr[32273]: 063B62B1F2: from=<weedy@Suigintou.lan>, size=426, nrcpt=1 (queue active)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: initializing the client-side TLS engine

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 133

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 220 bayc1-pasmtp12.bayc1.hotmail.com Microsoft ESMTP MAIL Service, Version: 6.0.3790.2668 ready at

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: EHLO Suigintou.lan

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 16 flush 20

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 233

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-bayc1-pasmtp12.bayc1.hotmail.com Hello [65.92.119.68]

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-TURN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-SIZE 35840000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-ETRN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-PIPELINING

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-DSN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-ENHANCEDSTATUSCODES

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-8bitmime

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-BINARYMIME

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-CHUNKING

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-VRFY

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-TLS

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-STARTTLS

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: server features: 0x901f size 35840000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: Using ESMTP PIPELINING, TCP send buffer size is 4096

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: STARTTLS

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 16 flush 10

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 29

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 220 2.0.0 SMTP server ready

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: setting up TLS connection to smtphm.sympatico.ca

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: looking for session smtp:65.54.191.190:25:bayc1-pasmtp12.bayc1.hotmail.com in smtp cache

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: event_request_timer: reset 0x80029d59 0x800650c0 5

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: send attr request = lookup

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: send attr cache_type = smtp

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: send attr cache_id = smtp:65.54.191.190:25:bayc1-pasmtp12.bayc1.hotmail.com

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 9 flush 96

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 9 got 28

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: private/tlsmgr: wanted attribute: status

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute name: status

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute value: 4294967294

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: private/tlsmgr: wanted attribute: session

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute name: session

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute value: (end)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: private/tlsmgr: wanted attribute: (list terminator)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute name: (end)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: event_request_timer: reset 0x80029d59 0x800650c0 5

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: send attr request = seed

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: send attr size = 32

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 9 flush 22

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 9 got 60

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: private/tlsmgr: wanted attribute: status

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute name: status

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute value: 0

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: private/tlsmgr: wanted attribute: seed

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute name: seed

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute value: ardp6C/wUTf7Ynxy/WtP5XFHhaZsIfOxbhFnm2eWh44=

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: private/tlsmgr: wanted attribute: (list terminator)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: input attribute name: (end)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:before/connect initialization

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv2/v3 write client hello A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv2/v3 read server hello A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read server hello A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read server hello A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read server hello A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 read server hello A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: certificate verification depth=1 subject=/C=US/O=Entrust.net/OU=www.entrust.net/CPS incorp. by ref. (limits liab.)/OU=(c) 1999 Entrust.net Limited/CN=Entrust.net Secure Server Certification Authority

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: verify return: 1

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: certificate verification depth=0 subject=/C=CA/ST=Ontario/L=Toronto/O=Bell Canada/OU=Bell Sympatico/CN=smtphm.sympatico.ca

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: verify return: 1

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 read server certificate A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 read server done A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 write client key exchange A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 write change cipher spec A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 write finished A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 flush data

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read finished A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read finished A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read finished A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:error in SSLv3 read finished A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: SSL_connect:SSLv3 read finished A

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: Verified: subject_CN=smtphm.sympatico.ca, issuer=Entrust.net Secure Server Certification Authority

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: TLS connection established to smtphm.sympatico.ca: TLSv1 with cipher RC4-MD5 (128/128 bits)

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: EHLO Suigintou.lan

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 16 flush 20

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 232

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-bayc1-pasmtp12.bayc1.hotmail.com Hello [65.92.119.68]

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-TURN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-SIZE 35840000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-ETRN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-PIPELINING

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-DSN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-ENHANCEDSTATUSCODES

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-8bitmime

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-BINARYMIME

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-CHUNKING

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-VRFY

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250-AUTH LOGIN PLAIN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250 OK

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: match_string: LOGIN ~? plain

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: match_list_match: LOGIN: no match

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: match_string: PLAIN ~? plain

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: server features: 0x902f size 35840000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: Using ESMTP PIPELINING, TCP send buffer size is 4096

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: maps_find: smtp_sasl_passwd: hash:/etc/postfix/saslpass(0,lock|fold_fix): smtphm.sympatico.ca = NOU@sympatico.ca:OVER9000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: smtp_sasl_passwd_lookup: host `smtphm.sympatico.ca' user `NOU@sympatico.ca' pass `OVER9000'

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: starting new SASL client

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: name_mask: noanonymous

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: smtp_sasl_authenticate: smtphm.sympatico.ca[65.54.191.190]: SASL mechanisms PLAIN

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: xsasl_cyrus_client_get_user: NOU@sympatico.ca

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: xsasl_cyrus_client_get_user: NOU@sympatico.ca

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: xsasl_cyrus_client_get_passwd: OVER9000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: xsasl_cyrus_client_first: uncoded initial reply: NOU@sympatico.ca\0NOU@sympatico.ca\0OVER9000

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: AUTH PLAIN d2VlZHlAc3ltcGF0aWNvLmNhAHdlZWR5QHN5bXBhdGljby5jYQBpc2hjYWJpYmVs

Aug  8 15:11:01 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 16 flush 77

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 31

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 235 Authentication succeeded

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: MAIL FROM:<weedy@Suigintou.lan> SIZE=426 AUTH=<>

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: RCPT TO:<weedy2887@MAHLAZAH.com> ORCPT=rfc822;weedy2887@MAHLAZAH.com

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: DATA

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 16 flush 120

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 44

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250 2.1.0 weedy@Suigintou.lan....Sender OK

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 32

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250 2.1.5 weedy2887@MAHLAZAH.com

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 46

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 354 Start mail input; end with <CRLF>.<CRLF>

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 15 got 430

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 54 data Received:

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 53 data ?id 063B62

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 36 data Date: Wed,

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 25 data From: weed

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 23 data To: weedy2

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 16 data Subject: t

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 50 data Message-ID

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 17 data MIME-Versi

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 42 data Content-Ty

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 27 data Content-Di

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 36 data User-Agent

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 0 data

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 19 data I think I

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type N len 0 data

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_get: type X len 0 data

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: .

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: > smtphm.sympatico.ca[65.54.191.190]: QUIT

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 16 flush 435

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_buf_get_ready: fd 16 got 76

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: < smtphm.sympatico.ca[65.54.191.190]: 250 2.6.0  <20070808191100.GA32367@Suigintou.lan> Queued mail for delivery

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: 063B62B1F2: to=<weedy2887@MAHLAZAH.com>, relay=smtphm.sympatico.ca[65.54.191.190]:25, delay=1.6, delays=0.05/0.06/1/0.45, dsn=2.6.0, status=sent (250 2.6.0  <20070808191100.GA32367@Suigintou.lan> Queued mail for delivery)

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: rec_put_type: 68 at 191

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: vstream_fflush_some: fd 15 flush 1

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: name_mask: resource

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: name_mask: software

Aug  8 15:11:02 Suigintou postfix/smtp[32374]: disposing SASL state information

Aug  8 15:11:02 Suigintou postfix/qmgr[32273]: 063B62B1F2: removed
```

----------

## elgato319

 *Quote:*   

> 
> 
> Are they any real down sides to forcing plain login? how come swaks works with login? 
> 
> 

 

auth login and auth plain are basicly the same, even uses the same "encryption" base64.

if used with tls it should be safe

i have no idea why auth login works with swaks and not with the other smtp server

----------

## weedy

its postfix

----------

