dslreports logo
 
    All Forums Hot Topics Gallery
spc
uniqs
35

graysonf
MVM
join:1999-07-16
Fort Lauderdale, FL

graysonf to jimkyle

MVM

to jimkyle

Re: Postfix and Port 25

It looks like authentication is not working for some reason. Double check your gmail user/password credentials.

Another possibility is that your copy of Postfix wasn't compiled with the sasl and tls stuff included.

What OS are you running it on? Where did the postfix package come from?

Try telnetting to your Postfix box on port 25 and issue an

ehlo example.com

and see what's in the outputted capabilities list.

jimkyle
Btrieve Guy
Premium Member
join:2002-10-20
Oklahoma City, OK

jimkyle

Premium Member

To answer the questions in order, the user and password match those which get me into the webmail interface at gmail.com. The postfix server works properly with dovecot, using sasl, but I'm not sure the tls stuff is there. My o/s is Xubuntu 12.04.3 LTS with all updates installed, and the postfix package came from the Ubuntu repositories via Synaptic package manager.

I've found another puzzle in the fragment of debug log that I posted above: the AUTH line received from the gmail.com server doesn't list either SASL or TLS as an authentication method. Shouldn't it? Or is that implied by the other methods they do list? Obviously, I'm not at all familiar with the innards of the protocol although I've been using it for a dozen years. This is the first time I've needed to get this deep into it!

Here's the result of the telnet test:
jk@mehitabel:~$ telnet localhost 25
Trying 127.0.0.1...
Trying ::1...
telnet: Unable to connect to remote host: Network is unreachable
 

Very strange; "ifconfig -a" shows the "lo" interface up and running.

It's nearing midnight here in OKC so I'll be hitting the hay before much longer. I do appreciate all the help I'm getting here, and intend to stay with it until we find out what's going on. It might even help someone else in the future!
jimkyle

jimkyle to graysonf

Premium Member

to graysonf
I tried the test from another machine on my LAN and it worked. Here's the output:
jk@xubuntu2:~$ telnet mehitabel.mylan 25
Trying 192.168.0.2...
Connected to mehitabel.mylan.
Escape character is '^]'.
220 jimkyle.dns2go.com ESMTP Postfix (Ubuntu)
ehlo example.com
250-jimkyle.dns2go.com
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-STARTTLS
250-AUTH PLAIN
250-AUTH=PLAIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
quit
221 2.0.0 Bye
Connection closed by foreign host.
jk@xubuntu2:~$ 
 
Looks like it's advertising TLS capability. Still no indication where gmail is getting "jim@jimkyle.com" from, unless it's looking up my IP in some database at their end. Postfix certainly isn't sending it out so far as I can tell from the debug data.

leibold
MVM
join:2002-07-09
Sunnyvale, CA
Netgear CG3000DCR
ZyXEL P-663HN-51

leibold

MVM

In the debug output the lines with "<" show what postfix has received from the peer (gmail in this case) while the lines with ">" are what postfix is sending to the peer.

The command "MAIL" with the "FROM:" header line is sent from postfix to gmail. Presumably whatever mail client you used to generate this email message produced jim@jimkyle.com as the sender address.

jimkyle
Btrieve Guy
Premium Member
join:2002-10-20
Oklahoma City, OK

jimkyle

Premium Member

I simply used sendmail to generate the tests; never thought to check its configuration for "sender." However I don't think this is likely to be the root cause of the authentication failure.

I've been reading a couple of the many SASL how-to files and came across several points. First, the AUTH lines in the telnet test don't indicate any SASL capability, only showing PLAIN. Second, one of the how-tos on the postfix site itself says that the dovecot SASL capability does not support using it for what seems to be this case! Only the cyrus type provides the needed capability. If this is the problem, then how can I set up a local pop3 capability without using dovecot?

Seems as if the swamp is breeding alligators faster than we can knock them out!

Brano
I hate Vogons
MVM
join:2002-06-25
Burlington, ON

Brano

MVM

Try switching your sasl backend to cyrus and re-do the tests.

graysonf
MVM
join:1999-07-16
Fort Lauderdale, FL

graysonf to jimkyle

MVM

to jimkyle
said by jimkyle:

Here's the result of the telnet test:

jk@mehitabel:~$ telnet localhost 25
Trying 127.0.0.1...
Trying ::1...
telnet: Unable to connect to remote host: Network is unreachable
 

Very strange; "ifconfig -a" shows the "lo" interface up and running.

It's not enough that lo is up. Postfix needs to be bound to it also. You probably restricted Postfix from binding to all interfaces, and specified only your ethernet adapter.

jimkyle
Btrieve Guy
Premium Member
join:2002-10-20
Oklahoma City, OK

jimkyle

Premium Member

said by graysonf:

You probably restricted Postfix from binding to all interfaces, and specified only your ethernet adapter.

Nope; I have interfaces=all in main.cf. It might be something in my iptables rules however...

Since I can telnet in from the other box in my office I'll leave this problem for the moment and concentrate on getting SASL working (or trying another off-site mail server instead of gmail). Right now the dovecot-vs-cyrus SASL type looks most promising...

graysonf
MVM
join:1999-07-16
Fort Lauderdale, FL

graysonf

MVM

You should verify how your copy of Postfix was compiled. Many of the options are not in the default configuration and must be enabled at build time. If you refer to such options in your Postfix configuration and the capabilities are not present in the compiled code, you may or may not see errors in the logs.

Brano
I hate Vogons
MVM
join:2002-06-25
Burlington, ON

Brano to jimkyle

MVM

to jimkyle
You can always find every default config option with postconf -d and current option with just postconf.

jimkyle
Btrieve Guy
Premium Member
join:2002-10-20
Oklahoma City, OK

jimkyle to Brano

Premium Member

to Brano
said by Brano:

Try switching your sasl backend to cyrus and re-do the tests.

Did this and the telnet responses did show SASL methods afterward, but the test message log results did not change. The gmail server still says authentication failed just as before.

I've commented out the debug entries from mail.cf while I mull these findings. It looks more and more like a catch-22 situation. Dovecot still does work even though I changed the SASL type to cyrus, but it may still be interfering with things. I'm considering totally removing it and also all its associated lines in main.cf, but that will cripple my daily checks of logwatch by removing the local POP3 delivery capability...

Thanks much for all the help!

graysonf
MVM
join:1999-07-16
Fort Lauderdale, FL

graysonf

MVM

Maybe you can try talking to smtp.gmail.com on port 465, the SSL/TSL port rather than the submission port 587.

Brano
I hate Vogons
MVM
join:2002-06-25
Burlington, ON

Brano to jimkyle

MVM

to jimkyle
Can you post one full log with log level 2 and tls log level 1? ... pretty much same type of log as I posted

jimkyle
Btrieve Guy
Premium Member
join:2002-10-20
Oklahoma City, OK

jimkyle

Premium Member

What should I remove to sanitize it? I definitely don't want any passwords to be exposed...

And will the two lines you had me add earlier provide the TLS log level also? I don't recall seeing any of that earlier...
jimkyle

jimkyle to Brano

Premium Member

to Brano
said by Brano:

Can you post one full log with log level 2 and tls log level 1? ... pretty much same type of log as I posted

Here's the entire mail log for the earlier test, after changing the SASL type to cyrus. I've removed the "attr value" data for all the places that appear to be uuencoded, in case any of them were the user/password strings, and also removed all of the dovecot entries.

The first few lines report the telnet-via-LAN test from "xubuntu2.mylan" before trying a message to gmail.

The final two lines, noting reload events, are from my removal of the logging options from main.cf.

If you need more let me know and I'll put those options back and try again.
Nov 10 09:47:21 mehitabel postfix/master[10337]: reload -- version 2.9.6, configuration /etc/postfix
Nov 10 09:48:38 mehitabel postfix/smtpd[17622]: connect from xubuntu2[192.168.0.5]
Nov 10 09:49:09 mehitabel postfix/smtpd[17622]: disconnect from xubuntu2[192.168.0.5]
Nov 10 09:49:58 mehitabel postfix/pickup[17616]: 548E1100031: uid=1000 from=<jk>
Nov 10 09:49:58 mehitabel postfix/cleanup[17690]: 548E1100031: message-id=<20131110154958.548E1100031@jimkyle.dns2go.com>
Nov 10 09:49:58 mehitabel postfix/qmgr[17615]: 548E1100031: from=<jim@jimkyle.com>, size=329, nrcpt=1 (queue active)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 220 mx.google.com ESMTP 9sm31797088yhe.21 - gsmtp
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: EHLO jimkyle.dns2go.com
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-mx.google.com at your service, [162.227.43.138]
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-SIZE 35882577
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-8BITMIME
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-STARTTLS
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-ENHANCEDSTATUSCODES
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250 CHUNKING
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: server features: 0x101b size 35882577
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: STARTTLS
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 220 2.0.0 Ready to start TLS
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr request = lookup
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr cache_type = smtp
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr cache_id = smtp:173.194.64.108:587:mx.google.com&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439567
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: status
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute value: 4294967295
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: session
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: session
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute value: (end)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: (list terminator)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr request = seed
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr size = 32
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: status
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute value: 0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: seed
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: seed
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute value: xxx--removed--xxx
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: (list terminator)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr request = update
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr cache_type = smtp
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr cache_id = smtp:173.194.64.108:587:mx.google.com&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439567
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr session = [data 1433 bytes]
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: status
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute value: 0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: (list terminator)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: EHLO jimkyle.dns2go.com
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-mx.google.com at your service, [162.227.43.138]
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-SIZE 35882577
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-8BITMIME
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-AUTH LOGIN PLAIN XOAUTH XOAUTH2 PLAIN-CLIENTTOKEN
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-ENHANCEDSTATUSCODES
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250 CHUNKING
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: server features: 0x100b size 35882577
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: MAIL FROM:<jim@jimkyle.com> SIZE=329
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 530-5.5.1 Authentication Required. Learn more at
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 9sm31797088yhe.21 - gsmtp
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: connect to subsystem private/bounce
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr nrequest = 0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr flags = 0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr queue_id = 548E1100031
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr original_recipient = test5@jimkyle.com
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr recipient = test5@jimkyle.com
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr offset = 193
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr dsn_orig_rcpt = 
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr notify_flags = 0
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr status = 5.5.1
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr diag_type = smtp
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr diag_text = 530-5.5.1 Authentication Required. Learn more at 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 9sm31797088yhe.21 - gsmtp
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr mta_type = dns
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr mta_mname = smtp.gmail.com
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr action = failed
Nov 10 09:49:58 mehitabel postfix/smtp[17692]: send attr reason = host smtp.gmail.com[173.194.64.108] said: 530-5.5.1 Authentication Required. Learn more at 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 9sm31797088yhe.21 - gsmtp (in reply to MAIL FROM command)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/bounce socket: wanted attribute: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute value: 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/bounce socket: wanted attribute: (list terminator)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: 548E1100031: to=<test5@jimkyle.com>, relay=smtp.gmail.com[173.194.64.108]:587, delay=0.68, delays=0.1/0.01/0.52/0.05, dsn=5.5.1, status=bounced (host smtp.gmail.com[173.194.64.108] said: 530-5.5.1 Authentication Required. Learn more at 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 9sm31797088yhe.21 - gsmtp (in reply to MAIL FROM command))
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: RSET
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=20 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250 2.1.5 Flushed 9sm31797088yhe.21 - gsmtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: QUIT
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: name_mask: resource
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: name_mask: software
Nov 10 09:49:59 mehitabel postfix/cleanup[17690]: 1C633100032: message-id=<20131110154959.1C633100032@jimkyle.dns2go.com>
Nov 10 09:49:59 mehitabel postfix/bounce[17693]: 548E1100031: sender non-delivery notification: 1C633100032
Nov 10 09:49:59 mehitabel postfix/qmgr[17615]: 1C633100032: from=<>, size=2432, nrcpt=1 (queue active)
Nov 10 09:49:59 mehitabel postfix/qmgr[17615]: 548E1100031: removed
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 220 mx.google.com ESMTP c44sm31800301yho.20 - gsmtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: EHLO jimkyle.dns2go.com
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-mx.google.com at your service, [162.227.43.138]
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-SIZE 35882577
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-8BITMIME
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-STARTTLS
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-ENHANCEDSTATUSCODES
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250 CHUNKING
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: server features: 0x101b size 35882577
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: STARTTLS
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 220 2.0.0 Ready to start TLS
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr request = lookup
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr cache_type = smtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr cache_id = smtp:173.194.64.108:587:mx.google.com&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439567
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute value: 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: session
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: session
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute value: xxx--removed--xxx
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: (list terminator)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr request = seed
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr size = 32
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute value: 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: seed
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: seed
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute value: xxx--removed--xxx
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/tlsmgr: wanted attribute: (list terminator)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: EHLO jimkyle.dns2go.com
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-mx.google.com at your service, [162.227.43.138]
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-SIZE 35882577
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-8BITMIME
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-AUTH LOGIN PLAIN XOAUTH XOAUTH2 PLAIN-CLIENTTOKEN
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250-ENHANCEDSTATUSCODES
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250 CHUNKING
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: server features: 0x100b size 35882577
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: MAIL FROM:<> SIZE=2432
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 530-5.5.1 Authentication Required. Learn more at
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 c44sm31800301yho.20 - gsmtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: connect to subsystem private/bounce
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr nrequest = 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr flags = 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr queue_id = 1C633100032
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr original_recipient = jim@jimkyle.com
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr recipient = jim@jimkyle.com
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr offset = 184
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr dsn_orig_rcpt = 
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr notify_flags = 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr status = 5.5.1
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr diag_type = smtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr diag_text = 530-5.5.1 Authentication Required. Learn more at 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 c44sm31800301yho.20 - gsmtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr mta_type = dns
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr mta_mname = smtp.gmail.com
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr action = failed
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: send attr reason = host smtp.gmail.com[173.194.64.108] said: 530-5.5.1 Authentication Required. Learn more at 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 c44sm31800301yho.20 - gsmtp (in reply to MAIL FROM command)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/bounce socket: wanted attribute: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: status
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute value: 0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: private/bounce socket: wanted attribute: (list terminator)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: input attribute name: (end)
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: 1C633100032: to=<jim@jimkyle.com>, relay=smtp.gmail.com[173.194.64.108]:587, delay=0.47, delays=0.04/0/0.39/0.05, dsn=5.5.1, status=bounced (host smtp.gmail.com[173.194.64.108] said: 530-5.5.1 Authentication Required. Learn more at 530 5.5.1 http://support.google.com/mail/bin/answer.py?answer=14257 c44sm31800301yho.20 - gsmtp (in reply to MAIL FROM command))
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: RSET
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: smtp_stream_setup: maxtime=20 enable_deadline=0
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: < smtp.gmail.com[173.194.64.108]:587: 250 2.1.5 Flushed c44sm31800301yho.20 - gsmtp
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: > smtp.gmail.com[173.194.64.108]:587: QUIT
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: name_mask: resource
Nov 10 09:49:59 mehitabel postfix/smtp[17692]: name_mask: software
Nov 10 09:49:59 mehitabel postfix/qmgr[17615]: 1C633100032: removed
Nov 10 09:54:07 mehitabel postfix/master[10337]: reload -- version 2.9.6, configuration /etc/postfix
Nov 10 09:58:14 mehitabel postfix/master[10337]: reload -- version 2.9.6, configuration /etc/postfix
 

Brano
I hate Vogons
MVM
join:2002-06-25
Burlington, ON

Brano

MVM

How are you testing this? Is this manual through telnet or using some mail client?
Seems the AUTH command is never being issued by the client for some reason.

jimkyle
Btrieve Guy
Premium Member
join:2002-10-20
Oklahoma City, OK

jimkyle

Premium Member

I'm using the command line with "jk@mehitabel:~$ echo "Test mail from postfix" | mail -s "Test Postfix" test5@jimkyle.com" with the "5" of "test5" changed from time to time to make searching the log easier...

I had to contact AT&T's on-line chat to get some help with the TV side of the new system, and they indicate that I might be able to get port 25 unblocked -- but now I'm pretty determined to see this through since we've all put so much effort into it...