Thanks Daniel.
> On 17 Dec 2018, at 2:29 am, Daniel Miller <dmil...@amfes.com
> <mailto:dmil...@amfes.com>> wrote:
>
> As I don't use Mail.app (but do use Thunderbird and AquaMail on Android) my
> guess is different client configuration. But a couple possibilities:
>
> That shows me ASSP is connecting to Postfix via Postfix's listener on 10026.
> On 12/16/2018 4:38 AM, James Brown wrote:
>>
>> Hi Daniel, thanks again for your help. I’ve been trying to get this working
>> all weekend. Listening ports:
>>
>> $sudo lsof -i :10025
>> COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
>> perl 68782 root 18u IPv4 0x1117b83fd26dc88b 0t0 TCP
>> localhost:10025 (LISTEN)
>>
>> $ sudo lsof -i :10026
>> COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
>> master 89692 root 85u IPv4 0x1117b83fdbb9d20b 0t0 TCP
>> localhost:10026 (LISTEN)
>>
>> $ sudo lsof -i :465
>> COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
>> master 89692 root 102u IPv4 0x1117b83fab73ce8b 0t0 TCP *:urd
>> (LISTEN)
>>
>> If I try to send an email via Thunderbird I get:
>>
>> 2018-12-16 23:00:32.330688+1100 0x40dc66 Activity 0x49b2e0
>> 72070 0 smtpd: (libsystem_info.dylib) Retrieve User by Name
>> 2018-12-16 23:00:32.331438+1100 0x40dc66 Activity 0x49b2e1
>> 72070 0 smtpd: (libsystem_info.dylib) Retrieve User by Name
>> 2018-12-16 23:00:32.332155+1100 0x40dc66 Activity 0x49b2e2
>> 72070 0 smtpd: (libsystem_info.dylib) Retrieve Group by Name
>> 2018-12-16 23:00:32.342027+1100 0x40dc66 Activity 0x49b2e3
>> 72070 0 smtpd: (libsystem_info.dylib) Resolve user group list
>> 2018-12-16 23:00:32.344741+1100 0x40dc66 Info 0x0
>> 72070 0 smtpd: connect from localhost[127.0.0.1]
>> 2018-12-16 23:02:08.138177+1100 0x40d37c Info 0x0
>> 71932 0 smtpd: disconnect from localhost[127.0.0.1] ehlo=2 starttls=1
>> mail=1 rcpt=1 data=1 quit=1 commands=7
>> 2018-12-16 23:03:43.607388+1100 0x40dc66 Info 0x0
>> 72070 0 smtpd: lost connection after UNKNOWN from localhost[127.0.0.1]
>> 2018-12-16 23:03:43.607455+1100 0x40dc66 Info 0x0
>> 72070 0 smtpd: disconnect from localhost[127.0.0.1] unknown=0/3
>> commands=0/3
>>
>> Nothing in mail.log and nothing from ASSP in maillog.txt. I tried with
>> Microsoft Outlook for Mac and had the same situation.
> What is the above from if it's not from mail.log?
>
Running new version of macOS (Mojave) which has a different logging system. So
running this in Terminal to display Postscript log:
$ log stream --predicate '(process == "smtpd") || (process == "smtp") ||
(process == "master") || (senderImagePath CONTAINS "postfix")' -debug
Dovecot can log to mail.log OK, not sure why Postfix is different.
> You should increase the log settings in ASSP working through this. Set
> ConnectionLog to verbose for a start. If that doesn't show activity - next
> I'd try would be ValidateSenderLog to verbose.
>
ConnectionLog is already set to Diagnostic. ValidateSenderLog is already set to
Verbose.
>>
>> But using Mail.app again it works perfectly:
>>
>> 2018-12-16 22:56:56.338582+1100 0x40d362 Info 0x0
>> 71926 0 smtpd: connect from localhost[127.0.0.1]
>> 2018-12-16 22:56:56.578031+1100 0x40d362 Info 0x0
>> 71926 0 smtpd: Anonymous TLS connection established from
>> localhost[127.0.0.1]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384
>> (256/256 bits)
>> 2018-12-16 22:56:56.655063+1100 0x40d378 Default 0x0
>> 71931 0 trivial-rewrite: warning: database
>> /usr/local/etc/postfix/transport.db is older than source file
>> /usr/local/etc/postfix/transport
> Probably not the end of the world - but fix the easy stuff first. Looks like
> your /usr/local/etc/postfix/transport.db needs to be regenerated.
>> 2018-12-16 22:56:56.761289+1100 0x40d362 Activity 0x49ad34
>> 71926 0 smtpd: (libsystem_info.dylib) Retrieve service by name
>> 2018-12-16 22:56:57.304324+1100 0x40d37c Activity 0x49ad90
>> 71932 0 smtpd: (libsystem_info.dylib) Retrieve User by Name
>> 2018-12-16 22:56:57.305045+1100 0x40d37c Activity 0x49ad91
>> 71932 0 smtpd: (libsystem_info.dylib) Retrieve User by Name
>> 2018-12-16 22:56:57.305746+1100 0x40d37c Activity 0x49ad92
>> 71932 0 smtpd: (libsystem_info.dylib) Retrieve Group by Name
>> 2018-12-16 22:56:57.312412+1100 0x40d37c Activity 0x49ad93
>> 71932 0 smtpd: (libsystem_info.dylib) Resolve user group list
>> 2018-12-16 22:56:57.315379+1100 0x40d37c Info 0x0
>> 71932 0 smtpd: connect from localhost[127.0.0.1]
>> 2018-12-16 22:57:00.488720+1100 0x40d37c Info 0x0
>> 71932 0 smtpd: Anonymous TLS connection established from
>> localhost[127.0.0.1]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256
>> (128/128 bits)
>> 2018-12-16 22:57:01.263857+1100 0x40d362 Info 0x0
>> 71926 0 smtpd: NOQUEUE: client=localhost[127.0.0.1], sasl_method=PLAIN,
>> sasl_username=jlbr...@bordo.com.au
>> <mailto:sasl_username=jlbr...@bordo.com.au>
>> 2018-12-16 22:57:02.467839+1100 0x40d37c Activity 0x49ad94
>> 71932 0 smtpd: (libsystem_info.dylib) Retrieve service by name
>> 2018-12-16 22:57:02.548724+1100 0x40d37c Info 0x0
>> 71932 0 smtpd: 854ED8E602D: client=localhost[127.0.0.1]
>> 2018-12-16 22:57:06.622777+1100 0x40d3d8 Info 0x0
>> 71933 0 cleanup: 854ED8E602D:
>> message-id=<bf241d65-018c-458c-83bd-631f710b4...@bordo.com.au
>> <mailto:bf241d65-018c-458c-83bd-631f710b4...@bordo.com.au>>
>> 2018-12-16 22:57:06.623801+1100 0x40181f Info 0x0
>> 68623 0 qmgr: 854ED8E602D: from=<jlbr...@bordo.com.au
>> <mailto:jlbr...@bordo.com.au>>, size=1096, nrcpt=1 (queue active)
>> 2018-12-16 22:57:06.767183+1100 0x40d3eb Info 0x0
>> 71936 0 pipe: 854ED8E602D: to=<jlbr...@bordo.com.au
>> <mailto:jlbr...@bordo.com.au>>, relay=dovecot, delay=5.9,
>> delays=5.8/0.02/0/0.12, dsn=2.0.0, status=sent (delivered via dovecot
>> service (lda(jlbr...@bordo.com.au <mailto:jlbr...@bordo.com.au>,)Error:
>> net_connect_unix(/usr/local/var/run/dovecot/stats-writer) failed: P))
>> 2018-12-16 22:57:06.767634+1100 0x40181f Info 0x0
>> 68623 0 qmgr: 854ED8E602D: removed
>> 2018-12-16 22:57:07.341530+1100 0x40d362 Info 0x0
>> 71926 0 smtpd: proxy-accept: END-OF-MESSAGE: 250 2.0.0 Ok: queued as
>> 854ED8E602D; from=<jlbr...@bordo.com.au <mailto:jlbr...@bordo.com.au>>
>> to=<jlbr...@bordo.com.au <mailto:jlbr...@bordo.com.au>> proto=ESMTP
>> helo=<[127.0.0.1]> sasl_username=<jlbr...@bordo.com.au
>> <mailto:jlbr...@bordo.com.au>>
>> 2018-12-16 22:58:07.428262+1100 0x40d362 Info 0x0
>> 71926 0 smtpd: disconnect from localhost[127.0.0.1] ehlo=2 starttls=1
>> auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8
>>
>> And mail.log shows:
>>
>> Dec 16 22:57:06 lda(jlbr...@bordo.com.au
>> <mailto:jlbr...@bordo.com.au>)<71937><+K2AKZI9FlwBGQEAYBwt+A>: Info:
>> msgid=<bf241d65-018c-458c-83bd-631f710b4...@bordo.com.au
>> <mailto:bf241d65-018c-458c-83bd-631f710b4...@bordo.com.au>>: saved mail to
>> INBOX
> Try setting "smtpd_tls_loglevel = 2" in main.cf
>>
>> While ASSP shows:
>>
>> Dec-16-18 22:56:57 [Worker_1] Info: try to connect to server at
>> 127.0.0.1:10026
>> Dec-16-18 22:56:57 [Worker_1] Info: connected to server at 127.0.0.1:10026
>> Dec-16-18 22:56:57 [Worker_1] Connected: session:7FB6906A1160
>> 127.0.0.1:63176 > 127.0.0.1:10025 > 127.0.0.1:63178 > 127.0.0.1:10026 , 21-22
>> Dec-16-18 22:56:59 [Worker_1] 127.0.0.1 info: injected '250-STARTTLS' offer
>> in to EHLO reply
>> Dec-16-18 22:56:59 [Worker_1] 127.0.0.1 info: send '250-STARTTLS' - injected
>> for 127.0.0.1
>> Dec-16-18 22:56:59 [Worker_1] 127.0.0.1 info: removed '250-STARTTLS' - it
>> was already injected
>> Dec-16-18 22:57:00 [Worker_1] 127.0.0.1 info: injected STARTTLS request to
>> 127.0.0.1
> This tells me something is not right. If you used the directives I gave you
> - connections should be made via SSL and there would be no STARTTLS command
> issued. So I'm assuming you didn't exactly follow my config lines...or
> Mail.app isn't connecting to port 465. After you've enabled connection
> logging in ASSP things might be clearer.
>> I really don’t know why only Mail.app works.
> As a Thunderbird user I'm confident it's not a Thunderbird flaw - it's a
> PEBKAC issue. ;) I have more than a few myself.
>
I’m sure it is!
When I send from Thunderbird, Postfix says:
2018-12-17 10:42:27.126166+1100 0xbbbc Info 0x0
5686 0 smtpd: connect from localhost[127.0.0.1]
2018-12-17 10:44:07.838129+1100 0xbbbc Info 0x0
5686 0 smtpd: lost connection after UNKNOWN from localhost[127.0.0.1]
2018-12-17 10:44:07.838284+1100 0xbbbc Info 0x0
5686 0 smtpd: disconnect from localhost[127.0.0.1] unknown=0/3 commands=0/3
> After enabling more logging, if things don't resolve themselves share your
> new logs and also a full copy of assp.cfg and the result of "postconf -n”.
>
$ sudo postconf -n
broken_sasl_auth_clients = yes
command_directory = /usr/local/sbin
compatibility_level = 2
daemon_directory = /usr/local/libexec/postfix
data_directory = /var/lib/postfix
debug_peer_level = 7
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd
$daemon_directory/$process_name $process_id & sleep 5
default_process_limit = 100
disable_vrfy_command = yes
dovecot_destination_recipient_limit = 1
html_directory = no
inet_protocols = ipv4
mail_owner = _postfix
mailbox_size_limit = 102400000
mailq_path = /usr/local/bin/mailq
manpage_directory = /usr/local/man
message_size_limit = 102400000
meta_directory = /usr/local/etc/postfix
mydomain = bordo.com.au <http://bordo.com.au/>
myhostname = mail.bordo.com.au <http://mail.bordo.com.au/>
newaliases_path = /usr/local/bin/newaliases
queue_directory = /var/spool/postfix
readme_directory = no
sample_directory = /usr/local/etc/postfix
sendmail_path = /usr/local/sbin/sendmail
setgid_group = _postdrop
shlib_directory = no
smtpd_client_connection_count_limit = 100
smtpd_command_filter = pcre:/etc/postfix/command_filter.regex
smtpd_data_restrictions = reject_unauth_pipelining
smtpd_enforce_tls = no
smtpd_etrn_restrictions = reject
smtpd_helo_required = yes
smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated,
reject_unauth_pipelining, reject_unauth_destination, permit
smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated
defer_unauth_destination
smtpd_sasl_auth_enable = yes
smtpd_sasl_local_domain = $myhostname
smtpd_sasl_path = private/auth
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_tls_cert_file = /usr/local/etc/dovecot/mail.bordo.com.au.pem
smtpd_tls_key_file = /usr/local/etc/dovecot/mail.bordo.com.au.pem
smtpd_tls_loglevel = 2
smtpd_use_tls = yes
tls_random_source = dev:/dev/urandom
transport_maps = hash:/usr/local/etc/postfix/transport
unknown_local_recipient_reject_code = 550
vacation_destination_recipient_limit = 1
virtual_alias_maps = mysql:/usr/local/etc/postfix/mysql_virtual_alias_maps.cf
virtual_gid_maps = static:102
virtual_mailbox_base = /usr/local/virtual/
virtual_mailbox_domains =
mysql:/usr/local/etc/postfix/mysql_virtual_domains_maps.cf
virtual_mailbox_limit = 512000000
virtual_mailbox_maps =
mysql:/usr/local/etc/postfix/mysql_virtual_mailbox_maps.cf
virtual_minimum_uid = 102
virtual_transport = dovecot
virtual_uid_maps = static:102
I’m sure there’s a lot that could be improved with this!
master.cf (non-commented out stuff only):
pickup unix n - n 60 1 pickup
cleanup unix n - n - 0 cleanup
qmgr unix n - n 300 1 qmgr
tlsmgr unix - - n 1000? 1 tlsmgr
rewrite unix - - n - - trivial-rewrite
bounce unix - - n - 0 bounce
defer unix - - n - 0 bounce
trace unix - - n - 0 bounce
verify unix - - n - 1 verify
flush unix n - n 1000? 0 flush
proxymap unix - - n - - proxymap
proxywrite unix - - n - 1 proxymap
smtp unix - - n - - smtp
relay unix - - n - - smtp
-o syslog_name=postfix/$service_name
showq unix n - n - - showq
error unix - - n - - error
retry unix - - n - - error
discard unix - - n - - discard
local unix - n n - - local
virtual unix - n n - - virtual
lmtp unix - - n - - lmtp
anvil unix - - n - 1 anvil
scache unix - - n - 1 scache
127.0.0.1:10026 inet n - n - - smtpd
-o smtpd_sasl_auth_enable=yes
127.0.0.1:126 inet n - n - - smtpd
-o syslog_name=assptls
-o smtpd_tls_wrappermode=yes
-o smtpd_proxy_filter=
-o myhostname=mail.bordo.com.au <http://mail.bordo.com.au/>
465 inet n - n - 20 smtpd
-o smtpd_proxy_filter=127.0.0.1:10025
-o smtpd_client_connection_count_limit=100
proxywrite unix - - n - 1 proxymap
vacation unix - n n - - pipe
flags=DRhu user=_vacation argv=/var/spool/vacation/vacation.pl -f
${sender} -- ${recipient}
dovecot unix - n n - - pipe
flags=DRhu user=_vmail argv=/usr/local/libexec/dovecot/deliver -f ${sender}
-d ${recipient}
James._______________________________________________
Assp-test mailing list
Assp-test@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/assp-test
