Stopped getting emails? Super odd issue

technicks · October 19, 2019, 8:05am

So looks like my private email server hasn’t been receiving emails since Jul 11th.
Around this time i moved the server from one location to another and updated a bunch of IPs. May be related but i’m not sure. DNS config looks good, MX records show up properly from outside. SSL certificates are in place. Reverse address is good. Not sure what else to check.

Here’s what i can do, and what i can’t at the moment:

Note: Server is setup to automatically forward any message received to my gmail account.

Let’s assume i have me@domain1.com as my email with alias a@domain1.com to make it shorter.
I have also a 2nd domain, let’s assume admin@domain2.com is the email there. I can’t receive emails here either by the way, so this is common between all domains on the servers.

Sending email from a@domain1.com works fine.
Sending email from admin@domain2.com to a@domain1.com and to me@domain1.com triggers the emails to be forwarded to my gmail, so we know they are received internally, processed, but never get into the mailbox, even though the forwarding works fine
Sending email from my gmail to a@domain1.com and to me@domain1.com does NOT trigger emails to forwarded to gmail and also does not deliver anything to my mailbox.

Anyone got any goddamn idea what the hell is going on? I’m so confused i don’t know where to start. Checked mail logs, nothing unusual.

Here’s the log doing step #2 above after a restart (note - changed real info to the supposed data shown above for privacy reasons)


Oct 19 03:26:36 server1 postfix/postfix-script[19478]: stopping the Postfix mail system
Oct 19 03:26:36 server1 postfix/master[9620]: terminating on signal 15
Oct 19 03:26:36 server1 postfix/postfix-script[19488]: fatal: the Postfix mail system is not running
Oct 19 03:26:36 server1 postfix/postqueue[19561]: warning: Mail system is down -- accessing queue directly
Oct 19 03:26:54 server1 postfix/postfix-script[19878]: starting the Postfix mail system
Oct 19 03:26:54 server1 postfix/master[19880]: daemon started -- version 2.10.1, configuration /etc/postfix
Oct 19 03:27:11 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=20206, session=<3u/4YD6VIoNJLEun>
Oct 19 03:27:11 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943
Oct 19 03:33:01 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=22145, session=
Oct 19 03:33:01 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943
Oct 19 03:36:06 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=24308, session=
Oct 19 03:36:06 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943
Oct 19 03:36:08 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=24355, session=
Oct 19 03:36:08 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943
Oct 19 03:37:28 server1 postfix/cleanup[25316]: warning: database /etc/postfix/generic.db is older than source file /etc/postfix/generic
Oct 19 03:37:28 server1 postfix/pickup[19881]: 5A6CE811290E: uid=0 from=
Oct 19 03:37:28 server1 postfix/cleanup[25316]: 5A6CE811290E: message-id=<1571470648.25308@domain1.com>
Oct 19 03:37:28 server1 postfix/qmgr[19882]: 5A6CE811290E: from=, size=559, nrcpt=1 (queue active)
Oct 19 03:37:28 server1 postfix/trivial-rewrite[25317]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains
Oct 19 03:37:28 server1 postfix/trivial-rewrite[25317]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains
Oct 19 03:37:31 server1 postfix/local[25318]: 5A6CE811290E: to=, orig_to=, relay=local, delay=3.2, delays=0.05/0.01/0/3.1, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)
Oct 19 03:37:31 server1 postfix/cleanup[25316]: 60B898124D19: message-id=<1571470648.25308@domain1.com>
Oct 19 03:37:31 server1 postfix/local[25318]: 5A6CE811290E: to=, orig_to=, relay=local, delay=3.2, delays=0.05/0.01/0/3.1, dsn=2.0.0, status=sent (forwarded as 60B898124D19)
Oct 19 03:37:31 server1 postfix/qmgr[19882]: 60B898124D19: from=, size=706, nrcpt=1 (queue active)
Oct 19 03:37:31 server1 postfix/qmgr[19882]: 5A6CE811290E: removed
Oct 19 03:37:31 server1 postfix/smtp[25395]: 60B898124D19: to=, orig_to=, relay=gmail-smtp-in.l.google.com[74.125.132.27]:25, delay=3.5, delays=3.1/0.01/0.19/0.21, dsn=2.0.0, status=sent (250 2.0.0 OK  1571470651 c4si2849970ilj.32 - gsmtp)
Oct 19 03:37:31 server1 postfix/qmgr[19882]: 60B898124D19: removed
Oct 19 03:37:55 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=25640, session=<95Vbhz6VWIRJLEun>
Oct 19 03:37:55 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943
Oct 19 03:40:48 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=27730, session=
Oct 19 03:40:48 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943
Oct 19 03:47:18 server1 postfix/cleanup[29306]: warning: database /etc/postfix/generic.db is older than source file /etc/postfix/generic
Oct 19 03:47:18 server1 postfix/pickup[19881]: 618108124D1A: uid=0 from=
Oct 19 03:47:18 server1 postfix/cleanup[29306]: 618108124D1A: message-id=<1571471238.29302@domain2.com>
Oct 19 03:47:18 server1 postfix/qmgr[19882]: 618108124D1A: from=, size=595, nrcpt=1 (queue active)
Oct 19 03:47:18 server1 postfix/trivial-rewrite[29307]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains
Oct 19 03:47:18 server1 postfix/trivial-rewrite[29307]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains
Oct 19 03:47:20 server1 postfix/local[29308]: 618108124D1A: to=, orig_to=, relay=local, delay=1.9, delays=0.04/0.01/0/1.9, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)
Oct 19 03:47:20 server1 postfix/cleanup[29306]: 69915815BD20: message-id=<1571471238.29302@domain2.com>
Oct 19 03:47:20 server1 postfix/qmgr[19882]: 69915815BD20: from=, size=742, nrcpt=1 (queue active)
Oct 19 03:47:20 server1 postfix/local[29308]: 618108124D1A: to=, orig_to=, relay=local, delay=2, delays=0.04/0.01/0/2, dsn=2.0.0, status=sent (forwarded as 69915815BD20)
Oct 19 03:47:20 server1 postfix/qmgr[19882]: 618108124D1A: removed
Oct 19 03:47:20 server1 postfix/smtp[29353]: 69915815BD20: to=, orig_to=, relay=gmail-smtp-in.l.google.com[74.125.132.26]:25, delay=2.5, delays=2/0.01/0.14/0.36, dsn=2.0.0, status=sent (250 2.0.0 OK  1571471240 a1si12452917ilp.82 - gsmtp)
Oct 19 03:47:20 server1 postfix/qmgr[19882]: 69915815BD20: removed
Oct 19 03:47:39 server1 postfix/pickup[19881]: 842E1815BD2C: uid=0 from=
Oct 19 03:47:39 server1 postfix/cleanup[29306]: 842E1815BD2C: message-id=<1571471259.29593@domain2.com>
Oct 19 03:47:39 server1 postfix/qmgr[19882]: 842E1815BD2C: from=, size=598, nrcpt=1 (queue active)
Oct 19 03:47:39 server1 postfix/trivial-rewrite[29307]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains
Oct 19 03:47:39 server1 postfix/trivial-rewrite[29307]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains
Oct 19 03:47:42 server1 postfix/local[29308]: 842E1815BD2C: to=, orig_to=, relay=local, delay=2.7, delays=0.03/0/0/2.7, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)
Oct 19 03:47:42 server1 postfix/cleanup[29306]: 8865A815BD2D: message-id=<1571471259.29593@domain2.com>
Oct 19 03:47:42 server1 postfix/local[29308]: 842E1815BD2C: to=, orig_to=, relay=local, delay=2.7, delays=0.03/0/0/2.7, dsn=2.0.0, status=sent (forwarded as 8865A815BD2D)
Oct 19 03:47:42 server1 postfix/qmgr[19882]: 8865A815BD2D: from=, size=745, nrcpt=1 (queue active)
Oct 19 03:47:42 server1 postfix/qmgr[19882]: 842E1815BD2C: removed
Oct 19 03:47:42 server1 postfix/smtp[29353]: 8865A815BD2D: to=, orig_to=, relay=gmail-smtp-in.l.google.com[74.125.132.26]:25, delay=3.1, delays=2.7/0/0.09/0.29, dsn=2.0.0, status=sent (250 2.0.0 OK  1571471262 u11si10789116iom.109 - gsmtp)
Oct 19 03:47:42 server1 postfix/qmgr[19882]: 8865A815BD2D: removed
Oct 19 03:48:01 server1 dovecot: pop3-login: Login: user=, method=PLAIN, rip=my.ip.address, lip=my.server.ip, mpid=29763, session=<+7KAqz6VwoVJLEun>
Oct 19 03:48:01 server1 dovecot: pop3(me@domain1.com): Disconnected: Logged out top=0/0, retr=0/0, del=0/7368, size=654099943

Dibs · October 19, 2019, 8:22am

A few things spring to mind:

Oct 19 03:26:36 server1 postfix/postfix-script[19488]: fatal: the Postfix mail system is not running

is a big flag. From Webmin - Server - Postfiox: check the status, start or stop\start if need be and check the system & mail logs at the time to see for errors.

From a command line type

postconf

to see your configuration and type

postconf -n

to see how it differs from a default setup. The following lines are not good


Oct 19 03:37:28 server1 postfix/cleanup[25316]: warning: database /etc/postfix/generic.db is older than source file /etc/postfix/generic
Oct 19 03:37:28 server1 postfix/trivial-rewrite[25317]: warning: do not list domain server1.mymainserver.com in BOTH mydestination and virtual_alias_domains

Those warnings should be dealt with. Given they are warnings - they shouldn’t stop Postfix from starting\running - however you could end up with weird\unpredictable behaviour, so I would recommend dealing with them

1st one - looks like you need to regen the associated hash file. 2nd one - it’s self explanatory. Once those issues are dealt with - Postfix should start\run better - if not - check the logs for additional errors and deal with them.

Then moving onto the mail:

remove the forwarding - it’s just complicating things for the moment.
test a sending of an email from a true external source (say your gmail account) or even by hand using Telnet or similar or from a website such as https://www.wormly.com/test-smtp-server to your email address me@domain1.com. Look in the logs for a “connect” at the time in question. You should expect around 5 -6 lines.
asumming the connect & associated lines are there - then put the forward back and test again - it should attempt to forward your message.

HIH

Dibs

technicks · October 21, 2019, 4:08pm

Thanks for the info!

I tried a few things and now it’s even more confusing.
May be a very odd mismatch of IP addresses, caused after moving server to another datacenter. Let me explain:

From outside, if i ping the server’s hostname (server1.myhostname.com) i get the NEW ip address (all good)
From the server itself, if i ping my hostname (same) i get the OLD ip address (wtf!?)

What gives? I am looking at network interfaces and i don’t see that old IP anywhere, and i have no idea how to update the hostname of the server to point to the actual IP of the server itself. I think this may be the issue. Pointers would be greatly appreciated.

Thanks!

technicks · October 21, 2019, 4:16pm

This was a dumb question - hosts file, duh. Let me see if that worked.

Dibs · October 21, 2019, 4:16pm

Anything odd in Host Addresses?

technicks · October 21, 2019, 4:21pm

It didn’t but doing a netstat -plnt | grep :25 still shows the old IP being listened on, not the new IP. Any idea where this can be changed!? I thought it was the hostname wrong but updating that (and i verified, it’s correct now) didn’t do the trick.

technicks · October 21, 2019, 4:24pm

Looks good, this is all that’s in there.

IP Address Enabled? Hostnames
127.0.0.1 Yes localhost , localhost.localdomain , localhost4 , localhost4.localdomain4
::1 Yes localhost , localhost.localdomain , localhost6 , localhost6.localdomain6
NEWIP Yes server1.myhost.com

Dibs · October 21, 2019, 4:25pm

When you moved data centers and IP - you did update your DNS records? For ALL hosts\domains?

technicks · October 21, 2019, 4:27pm

Yep, sure did, i can access everything very well. This is the only issue.

Dibs · October 21, 2019, 4:30pm

It isn’t really about whether you can access everything - you don’t have a DNS entry hanging about with the old IP? It’s happened to the best of us.

technicks · October 21, 2019, 4:34pm

I will re-check.
In the meantime i added to postfix config:
smtp_bind_address = newip
Restarted postfix, no change

Dibs · October 21, 2019, 4:35pm

In /etc/postfix/main.cf file what does inet_interfaces say?

technicks · October 21, 2019, 5:04pm

Checked every config file i can find and no luck, that IP doesn’t exist anywhere.
I’m running a grep -rlw “old ip address” / to see if it digs up anything. Though this may take a while as i probably should not have searched recursively from root lol

technicks · October 21, 2019, 7:47pm

So i got mad that i couldn’t find anything and literally re-installed postfix, re-did all config files, etc.
Whatever it was, it’s now fixed.

Thanks for the help, much appreciated, i learned a few things!

Dibs · October 21, 2019, 8:00pm

Glad you got it sorted. Be very careful with forwarding emails to Gmail. Forwarding isn’t ideal but a fairly good way to end up on an RBL or backscatterer.org unless you harden Postfix as best you can.

system · April 30, 2020, 5:39am