>> mydomain = myportaltech.com
>> myhostname = hostname
> Is this what postconf really returns or did you redact this?
Yes, I edited it. hostname was just the name of the host as
given by Unix command 'uname -n' or `hostname`
> I'm wondering why smtpd_recipient_restrictions didn't show here
Will check this out tomorrow.
Today, before I reverted back to the vanilla main.cf & master.cf
& before removing "-v" the smtpd line in master.cf ,
"ps -ef | grep postfix" showed the following 4 processes :
root 16571 1 0 Feb22 ? 00:00:00 /usr/libexec/postfix/master
postfix 16572 16571 0 Feb22 ? 00:00:00 qmgr -l -t fifo -u
postfix 22006 16571 0 11:02 ? 00:00:00 pickup -l -t fifo -u
postfix 22254 16571 0 11:32 ? 00:00:00 smtpd -n smtp -t inet
-u -o stress -v -o receive_override_options no_address_mappings
Is it expected to have master & smtpd processes running at the same?
Issuing /etc/init.d/postfix stop would stop all the above 4 processes &
"telnet localhost 25" won't respond after that.
Then I remove "-v" from smtpd in master.cf (& left behind "-D"), restarted
postfix & got the following latest maillog (I tested sending mails from my
Outlook/Exchange server in mds.com.sg domain (my postfix box is in
myportaltech.com domain). The following are the "strace -p pid" outputs:
Output of "strace -p pid_of_/usr/libexec/postfix/master" :
Process 22521 attached - interrupt to quit
alarm(333) = 297
time(NULL) = 1298432493
epoll_wait(13, {}, 100, 24000) = 0
time(NULL) = 1298432517
geteuid32() = 0
setresgid32(-1, 102, -1) = 0
setgroups32(1, [102]) = 0
setresuid32(-1, 102, -1) = 0
open("public/pickup", O_WRONLY|O_NONBLOCK) = 88
fstat64(88, {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
lstat64("public/pickup", {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
fcntl64(88, F_GETFL) = 0x801 (flags O_WRONLY|O_NONBLOCK)
fcntl64(88, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
poll([{fd=88, events=POLLOUT, revents=POLLOUT}], 1, 1000) = 1
write(88, "W", 1) = 1
close(88) = 0
getgid32() = 0
getuid32() = 0
geteuid32() = 102
setresuid32(-1, 0, -1) = 0
setgid32(0) = 0
setgroups32(1, [0]) = 0
setuid32(0) = 0
time([1298432517]) = 1298432517
alarm(333) = 309
time(NULL) = 1298432517
epoll_wait(13, {{EPOLLIN, {u32=17, u64=13806243738168590353}}}, 100, 60000) = 1
time(NULL) = 1298432517
read(17, "\373W\0\0\2\0\0\0\0\0\0\0", 12) = 12
alarm(333) = 333
time(NULL) = 1298432517
epoll_wait(13, {{EPOLLIN, {u32=17, u64=13806243738168590353}}}, 100, 60000) = 1
time(NULL) = 1298432517
read(17, "\373W\0\0\2\0\0\0\1\0\0\0", 12) = 12
alarm(333) = 333
time(NULL) = 1298432517
epoll_wait(13, {{EPOLLIN, {u32=12, u64=578268796096086028}}}, 100, 60000) = 1
time(NULL) = 1298432558
fork() = 22654
epoll_ctl(13, EPOLL_CTL_DEL, 12, {EPOLLIN, {u32=12, u64=17179869196}}) = 0
alarm(333) = 291
time(NULL) = 1298432558
epoll_wait(13, {{EPOLLIN, {u32=14, u64=13806243738168590350}}}, 100, 19000) = 1
time(NULL) = 1298432563
read(14, "~X\0\0\3\0\0\0\0\0\0\0", 12) = 12
epoll_ctl(13, EPOLL_CTL_ADD, 12, {EPOLLIN, {u32=12, u64=51539607564}}) = 0
alarm(333) = 328
time(NULL) = 1298432563
epoll_wait(13, {{EPOLLIN, {u32=14, u64=13806243738168590350}}}, 100, 14000) = 1
time(NULL) = 1298432563
read(14, "~X\0\0\3\0\0\0\1\0\0\0", 12) = 12
epoll_ctl(13, EPOLL_CTL_DEL, 12, {EPOLLIN, {u32=12, u64=51539607564}}) = 0
alarm(333) = 333
time(NULL) = 1298432563
epoll_wait(13, {}, 100, 14000) = 0
time(NULL) = 1298432577
geteuid32() = 0
setresgid32(-1, 102, -1) = 0
setgroups32(1, [102]) = 0
setresuid32(-1, 102, -1) = 0
open("public/pickup", O_WRONLY|O_NONBLOCK) = 88
fstat64(88, {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
lstat64("public/pickup", {st_mode=S_IFIFO|0622, st_size=0, ...}) = 0
fcntl64(88, F_GETFL) = 0x801 (flags O_WRONLY|O_NONBLOCK)
fcntl64(88, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
poll([{fd=88, events=POLLOUT, revents=POLLOUT}], 1, 1000) = 1
write(88, "W", 1) = 1
close(88) = 0
getgid32() = 0
getuid32() = 0
geteuid32() = 102
setresuid32(-1, 0, -1) = 0
setgid32(0) = 0
setgroups32(1, [0]) = 0
setuid32(0) = 0
time([1298432577]) = 1298432577
alarm(333) = 319
time(NULL) = 1298432577
epoll_wait(13, {{EPOLLIN, {u32=17, u64=13806243738168590353}}}, 100, 60000) = 1
time(NULL) = 1298432577
read(17, "\373W\0\0\2\0\0\0\0\0\0\0", 12) = 12
alarm(333) = 333
time(NULL) = 1298432577
epoll_wait(13, {{EPOLLIN, {u32=17, u64=13806243738168590353}}}, 100, 60000) = 1
time(NULL) = 1298432577
read(17, "\373W\0\0\2\0\0\0\1\0\0\0", 12) = 12
alarm(333) = 333
time(NULL) = 1298432577
epoll_wait(13, {}, 100, 60000) = 0
=====================================
Output of strace -p smtpd_pid :
Process 22654 attached - interrupt to quit
alarm(0) = 5974
flock(8, LOCK_EX) = 0
alarm(6000) = 0
time(NULL) = 1298432590
epoll_wait(9, {}, 100, 73000) = 0
time(NULL) = 1298432663
exit_group(0) = ?
Process 22654 detached
The following is the maillog indicating mail being sent from
gate1.mds.com.sg (this is the SMTP server of mds.com.sg domain,
possibly it's the Exchange server) :
Feb 23 11:45:28 hostname postfix/smtpd[22684]: public/cleanup socket:
wanted attribute: status
Feb 23 11:45:28 hostname postfix/smtpd[22684]: input attribute name: status
Feb 23 11:45:28 hostname postfix/smtpd[22684]: input attribute value: 0
Feb 23 11:45:28 hostname postfix/smtpd[22684]: public/cleanup socket:
wanted attribute: reason
Feb 23 11:45:28 hostname postfix/smtpd[22684]: input attribute name: reason
Feb 23 11:45:28 hostname postfix/smtpd[22684]: input attribute value: (end)
Feb 23 11:45:28 hostname postfix/smtpd[22684]: public/cleanup socket:
wanted attribute: (list terminator)
Feb 23 11:45:28 hostname postfix/smtpd[22684]: input attribute name: (end)
Feb 23 11:45:28 hostname postfix/smtpd[22684]: >
gate1.mds.com.sg[203.126.130.157]: 250 2.0.0 Ok: queued as 014F220008B
Feb 23 11:45:28 hostname postfix/qmgr[22522]: 014F220008B:
from=<prvs=028a5da91=pit...@mds.com.sg>, size=1908, nrcpt=2 (queue
active)
Feb 23 11:45:28 hostname postfix/smtpd[22680]: <
gate2.mds.com.sg[203.126.130.164]: QUIT
Feb 23 11:45:28 hostname postfix/smtpd[22680]: >
gate2.mds.com.sg[203.126.130.164]: 221 2.0.0 Bye
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_hostname:
gate2.mds.com.sg ~? 172.18.20.0/24
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_hostaddr:
203.126.130.164 ~? 172.18.20.0/24
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_hostname:
gate2.mds.com.sg ~? 127.0.0.0/8
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_hostaddr:
203.126.130.164 ~? 127.0.0.0/8
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_hostname:
gate2.mds.com.sg ~? 202.6.163.0/24
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_hostaddr:
203.126.130.164 ~? 202.6.163.0/24
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_list_match:
gate2.mds.com.sg: no match
Feb 23 11:45:28 hostname postfix/smtpd[22680]: match_list_match:
203.126.130.164: no match
Feb 23 11:45:28 hostname postfix/smtpd[22680]: send attr request = disconnect
Feb 23 11:45:28 hostname postfix/smtpd[22680]: send attr ident =
smtp:203.126.130.164
Feb 23 11:45:28 hostname postfix/smtpd[22680]: private/anvil: wanted
attribute: status
Feb 23 11:45:28 hostname postfix/smtpd[22680]: input attribute name: status
Feb 23 11:45:28 hostname postfix/smtpd[22680]: input attribute value: 0
Feb 23 11:45:28 hostname postfix/smtpd[22680]: private/anvil: wanted
attribute: (list terminator)
Feb 23 11:45:28 hostname postfix/smtpd[22680]: input attribute name: (end)
Feb 23 11:45:28 hostname postfix/smtpd[22680]: disconnect from
gate2.mds.com.sg[203.126.130.164]
Feb 23 11:45:33 hostname postfix/smtpd[22684]: <
gate1.mds.com.sg[203.126.130.157]: QUIT
Feb 23 11:45:33 hostname postfix/smtpd[22684]: >
gate1.mds.com.sg[203.126.130.157]: 221 2.0.0 Bye
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_hostname:
gate1.mds.com.sg ~? 172.18.20.0/24
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_hostaddr:
203.126.130.157 ~? 172.18.20.0/24
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_hostname:
gate1.mds.com.sg ~? 127.0.0.0/8
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_hostaddr:
203.126.130.157 ~? 127.0.0.0/8
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_hostname:
gate1.mds.com.sg ~? 202.6.163.0/24
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_hostaddr:
203.126.130.157 ~? 202.6.163.0/24
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_list_match:
gate1.mds.com.sg: no match
Feb 23 11:45:33 hostname postfix/smtpd[22684]: match_list_match:
203.126.130.157: no match
Feb 23 11:45:33 hostname postfix/smtpd[22684]: send attr request = disconnect
Feb 23 11:45:33 hostname postfix/smtpd[22684]: send attr ident =
smtp:203.126.130.157
Feb 23 11:45:33 hostname postfix/smtpd[22684]: private/anvil: wanted
attribute: status
Feb 23 11:45:33 hostname postfix/smtpd[22684]: input attribute name: status
Feb 23 11:45:33 hostname postfix/smtpd[22684]: input attribute value: 0
Feb 23 11:45:33 hostname postfix/smtpd[22684]: private/anvil: wanted
attribute: (list terminator)
Feb 23 11:45:33 hostname postfix/smtpd[22684]: input attribute name: (end)
Feb 23 11:45:33 hostname postfix/smtpd[22684]: disconnect from
gate1.mds.com.sg[203.126.130.157]
Feb 23 11:45:53 hostname postfix/smtp[22691]: connect to
smtp.portalcity-tech.com[202.6.163.31]:25: Connection timed out
Feb 23 11:45:53 hostname postfix/smtp[22691]: 04B9020008A:
to=<pit...@portalcity-tech.com>, relay=none, delay=30,
delays=0.21/0.01/30/0, dsn=4.4.1, status=deferred (connect to
smtp.portalcity-tech.com[202.6.163.31]:25: Connection timed out)
Feb 23 11:45:53 hostname postfix/smtp[22691]: 04B9020008A:
to=<r...@portalcity-tech.com>, relay=none, delay=30,
delays=0.21/0.01/30/0, dsn=4.4.1, status=deferred (connect to
smtp.portalcity-tech.com[202.6.163.31]:25: Connection timed out)
Feb 23 11:45:58 hostname postfix/smtp[22692]: connect to
smtp.portalcity-tech.com[202.6.163.31]:25: Connection timed out
Feb 23 11:45:58 hostname postfix/smtp[22692]: 014F220008B:
to=<pit...@portalcity-tech.com>, relay=none, delay=30,
delays=0.1/0.01/30/0, dsn=4.4.1, status=deferred (connect to
smtp.portalcity-tech.com[202.6.163.31]:25: Connection timed out)
Feb 23 11:45:58 hostname postfix/smtp[22692]: 014F220008B:
to=<r...@portalcity-tech.com>, relay=none, delay=30,
delays=0.1/0.01/30/0, dsn=4.4.1, status=deferred (connect to
smtp.portalcity-tech.com[202.6.163.31]:25: Connection timed out)
Feb 23 11:48:53 hostname postfix/anvil[22688]: statistics: max
connection rate 1/60s for (smtp:203.126.130.164) at Feb 23 11:45:22
Feb 23 11:48:53 hostname postfix/anvil[22688]: statistics: max
connection count 1 for (smtp:203.126.130.164) at Feb 23 11:45:22
Feb 23 11:48:53 hostname postfix/anvil[22688]: statistics: max cache
size 2 at Feb 23 11:45:27
Let me know if any other types of logging for smtpd/postfix that I may have
missed that will facilitate this troubleshooting.
Reverting to vanilla main.cf & master.cf was disastrous :
a certain file was locked & I can't start up postfix : didn't
get to capture the logs for vanilla setting
Sun
