Postfix problem receiving email to relay


  • Service Provider

    I have a CentOS 7 box at a site simply being a mail relay. Has been working fine for the last year.

    Today it is not working right. It is accepting the incoming connection, but then nothing else. The sending devices are reporting a timeout.

    Here is the /var/log/maillog showing nothing helpful.

    Mar  7 09:21:33 relay01 postfix/smtpd[880]: connect from ljcm6040.domain.local[10.201.1.11]
    Mar  7 09:22:33 relay01 postfix/smtpd[880]: lost connection after CONNECT from ljcm6040.domain.local[10.201.1.11]
    Mar  7 09:22:33 relay01 postfix/smtpd[880]: disconnect from ljcm6040.domain.local[10.201.1.11]
    
    Mar  7 09:22:34 relay01 postfix/smtpd[880]: connect from ljcm6040.domain.local[10.201.1.11]
    Mar  7 09:23:34 relay01 postfix/smtpd[880]: warning: non-SMTP command from ljcm6040.domain.local[10.201.1.11]: Content-Type: text/plain;
    Mar  7 09:23:34 relay01 postfix/smtpd[880]: disconnect from ljcm6040.domain.local[10.201.1.11]
    
    Mar  7 09:23:58 relay01 postfix/smtpd[880]: connect from ljcm6040.domain.local[10.201.1.11]
    Mar  7 09:24:58 relay01 postfix/smtpd[880]: warning: non-SMTP command from ljcm6040.domain.local[10.201.1.11]: Content-Type: text/plain;
    Mar  7 09:24:58 relay01 postfix/smtpd[880]: disconnect from ljcm6040.domain.local[10.201.1.11]
    
    Mar  7 09:40:05 relay01 postfix/smtpd[10169]: connect from owncloud.domain.local[10.201.1.17]
    Mar  7 09:40:15 relay01 postfix/smtpd[10169]: lost connection after CONNECT from owncloud.domain.local[10.201.1.17]
    Mar  7 09:40:15 relay01 postfix/smtpd[10169]: disconnect from owncloud.domain.local[10.201.1.17]
    

  • Service Provider

    Any chance that you are experiencing packet loss or something like that?


  • Service Provider

    @scottalanmiller said in Postfix problem receiving email to relay:

    Any chance that you are experiencing packet loss or something like that?

    From the first one, which is a copier, yes. That is why I did a test send in owncloud. That is a VM on the same hypervisor..


  • Service Provider

    NIC on the fritz?


  • Service Provider

    @art_of_shred said in Postfix problem receiving email to relay:

    NIC on the fritz?

    VM to VM on the same HV would bypass that, even if the NIC caught fire and was in a pile of goo.


  • Service Provider

    Any clue of another log to look into? Server was rebooted, drive space is stupid extra. because when the VM was created, I apparently neglected to change the Hyper-V default of 127GB

    [[email protected] ~]# df -h
    Filesystem                       Size  Used Avail Use% Mounted on
    /dev/mapper/centos_relay01-root   50G  1.7G   49G   4% /
    devtmpfs                         229M     0  229M   0% /dev
    tmpfs                            240M     0  240M   0% /dev/shm
    tmpfs                            240M  4.3M  235M   2% /run
    tmpfs                            240M     0  240M   0% /sys/fs/cgroup
    /dev/sda2                        497M  280M  218M  57% /boot
    /dev/sda1                        200M  9.5M  191M   5% /boot/efi
    /dev/mapper/centos_relay01-home   76G   33M   76G   1% /home
    tmpfs                             48M     0   48M   0% /run/user/0
    

  • Service Provider

    maillog and messages should cover anything likely to have happened.

    No package updates?


  • Service Provider

    @scottalanmiller said in Postfix problem receiving email to relay:

    maillog and messages should cover anything likely to have happened.

    No package updates?

    nope.

    [[email protected] ~]# yum update
    Loaded plugins: fastestmirror
    Loading mirror speeds from cached hostfile
     * base: mirror.team-cymru.org
     * extras: mirror.compevo.com
     * updates: repos.lax.quadranet.com
    No packages marked for update
    

  • Service Provider

    @JaredBusch said in Postfix problem receiving email to relay:

    @scottalanmiller said in Postfix problem receiving email to relay:

    maillog and messages should cover anything likely to have happened.

    No package updates?

    nope.

    [[email protected] ~]# yum update
    Loaded plugins: fastestmirror
    Loading mirror speeds from cached hostfile
     * base: mirror.team-cymru.org
     * extras: mirror.compevo.com
     * updates: repos.lax.quadranet.com
    No packages marked for update
    

    Sorry, I meant historically, like yesterday before the issue came up. Check the yumlog.


  • Service Provider

    @scottalanmiller said in Postfix problem receiving email to relay:

    @JaredBusch said in Postfix problem receiving email to relay:

    @scottalanmiller said in Postfix problem receiving email to relay:

    maillog and messages should cover anything likely to have happened.

    No package updates?

    nope.

    [[email protected] ~]# yum update
    Loaded plugins: fastestmirror
    Loading mirror speeds from cached hostfile
     * base: mirror.team-cymru.org
     * extras: mirror.compevo.com
     * updates: repos.lax.quadranet.com
    No packages marked for update
    

    Sorry, I meant historically, like yesterday before the issue came up. Check the yumlog.

    March 4th was the last update.

    Mar 04 09:11:26 Updated: systemd-libs.x86_64 219-30.el7_3.7
    Mar 04 09:11:27 Updated: libgudev1.x86_64 219-30.el7_3.7
    Mar 04 09:11:27 Updated: audit-libs.x86_64 2.6.5-3.el7_3.1
    Mar 04 09:11:32 Updated: systemd.x86_64 219-30.el7_3.7
    Mar 04 09:11:32 Updated: systemd-sysv.x86_64 219-30.el7_3.7
    Mar 04 09:11:33 Updated: wpa_supplicant.x86_64 1:2.0-21.el7_3
    Mar 04 09:11:33 Updated: device-mapper-libs.x86_64 7:1.02.135-1.el7_3.3
    Mar 04 09:11:33 Updated: device-mapper.x86_64 7:1.02.135-1.el7_3.3
    Mar 04 09:11:33 Updated: device-mapper-event-libs.x86_64 7:1.02.135-1.el7_3.3
    Mar 04 09:11:33 Updated: NetworkManager-libnm.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:11:34 Updated: device-mapper-event.x86_64 7:1.02.135-1.el7_3.3
    Mar 04 09:11:34 Updated: lvm2-libs.x86_64 7:2.02.166-1.el7_3.3
    Mar 04 09:11:34 Updated: polkit.x86_64 0.112-11.el7_3
    Mar 04 09:11:36 Updated: NetworkManager.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:11:37 Updated: NetworkManager-wwan.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:11:38 Updated: kernel-tools-libs.x86_64 3.10.0-514.10.2.el7
    Mar 04 09:11:38 Updated: python-firewall.noarch 0.4.3.2-8.1.el7_3.2
    Mar 04 09:11:53 Updated: selinux-policy.noarch 3.13.1-102.el7_3.15
    Mar 04 09:11:53 Updated: firewalld-filesystem.noarch 0.4.3.2-8.1.el7_3.2
    Mar 04 09:11:54 Updated: firewalld.noarch 0.4.3.2-8.1.el7_3.2
    Mar 04 09:12:12 Updated: selinux-policy-targeted.noarch 3.13.1-102.el7_3.15
    Mar 04 09:12:14 Updated: kernel-tools.x86_64 3.10.0-514.10.2.el7
    Mar 04 09:12:14 Updated: NetworkManager-bluetooth.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:12:14 Updated: NetworkManager-wifi.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:12:14 Updated: NetworkManager-tui.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:12:14 Updated: NetworkManager-adsl.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:12:14 Updated: NetworkManager-team.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:12:16 Updated: lvm2.x86_64 7:2.02.166-1.el7_3.3
    Mar 04 09:12:16 Updated: audit.x86_64 2.6.5-3.el7_3.1
    Mar 04 09:12:17 Updated: microcode_ctl.x86_64 2:2.1-16.3.el7_3
    Mar 04 09:12:17 Updated: NetworkManager-glib.x86_64 1:1.4.0-17.el7_3
    Mar 04 09:12:18 Updated: python-perf.x86_64 3.10.0-514.10.2.el7
    Mar 04 09:12:29 Installed: kernel.x86_64 3.10.0-514.10.2.el7
    

  • Service Provider

    Looks like it started march 2

    Mar  1 08:44:04 relay01 postfix/smtpd[4139]: connect from ljcm6040.domain.local[10.201.1.11]
    Mar  1 08:44:05 relay01 postfix/smtpd[4139]: 04E9EC0C82C7: client=ljcm6040.domain.local[10.201.1.11]
    Mar  1 08:44:07 relay01 postfix/cleanup[4141]: 04E9EC0C82C7: message-id=<>
    Mar  1 08:44:08 relay01 postfix/qmgr[1710]: 04E9EC0C82C7: from=<[email protected]>, size=70941, nrcpt=1 (queue active)
    Mar  1 08:44:08 relay01 postfix/smtpd[4139]: disconnect from ljcm6040.domain.local[10.201.1.11]
    Mar  1 08:44:11 relay01 postfix/smtp[4142]: 04E9EC0C82C7: to=<[email protected]>, relay=domain-com.mail.protection.out$
    Mar  1 08:44:11 relay01 postfix/qmgr[1710]: 04E9EC0C82C7: removed
    Mar  1 16:13:58 relay01 postfix/postfix-script[1620]: starting the Postfix mail system
    Mar  1 16:13:58 relay01 postfix/master[1630]: daemon started -- version 2.10.1, configuration /etc/postfix
    Mar  2 07:11:11 relay01 postfix/smtpd[10917]: connect from nginx.domain.local[10.201.1.18]
    Mar  2 07:16:11 relay01 postfix/smtpd[10917]: timeout after CONNECT from nginx.domain.local[10.201.1.18]
    Mar  2 07:16:11 relay01 postfix/smtpd[10917]: disconnect from nginx.domain.local[10.201.1.18]
    

    The yum.log went from Feb 23 to March 4, so I would say nothing there.

    Feb 23 04:05:31 Installed: kernel.x86_64 3.10.0-514.6.2.el7
    Mar 04 09:11:26 Updated: systemd-libs.x86_64 219-30.el7_3.7
    

  • Service Provider

    Do you have any TLS here? Any cert expire?


  • Service Provider

    Not yet for postfix. That is on my to do list, https://mangolassi.it/topic/12545/how-do-i-setup-tls-on-a-postfix-relay



  • Maybe your firewall is blocking connection. Try to stop firewall and check if it works. Maybe you or somebody else changed some rules.


  • Service Provider

    The odd part is that the initial connection works, then it drops afterwards.


  • Service Provider

    @scottalanmiller said in Postfix problem receiving email to relay:

    The odd part is that the initial connection works, then it drops afterwards.

    right. that is what has me confused.


  • Service Provider

    @triple9 said in Postfix problem receiving email to relay:

    Maybe your firewall is blocking connection. Try to stop firewall and check if it works. Maybe you or somebody else changed some rules.

    No one else even knows how to handle this.

    Related note, I need to get more documentation in place.


  • Service Provider

    firewalld has port 25 allowed.

    [[email protected] ~]# firewall-cmd --list-all
    public (active)
      target: default
      icmp-block-inversion: no
      interfaces: eth0
      sources:
      services: dhcpv6-client ssh
      ports: 25/tcp
      protocols:
      masquerade: no
      forward-ports:
      sourceports:
      icmp-blocks:
      rich rules:
    

  • Service Provider

    Postfix config has not been touched since setup a year ago.

    [[email protected] ~]# ls -l /etc/postfix/main.cf
    -rw-r--r--. 1 root root 27281 Mar 14  2016 /etc/postfix/main.cf
    


  • Is there any filtering in postfix, like amavis, spamassassin?


  • Service Provider

    @triple9 said in Postfix problem receiving email to relay:

    Is there any filtering in postfix, like amavis, spamassassin?

    nope.


  • Service Provider

    And problem resolved.

    On the 1st, the damned DHCP lease had failed again due to the mysterious time drift issues I have been tracking down in another thread.

    But I needed this system up so I launched nmtui and set a static IP.... Wait for it.. to 10.201.1.12/32

    /fucking sigh....

    I also enabled the Time Synchronization in Hyper-V on March 1st. As soon as I fixed the /32, this morning, the Hyper-V integration started fixing the time every 5 seconds.. screw that. Turned it back off. I will count on chronyd it works well as long as the IP stays online.

    [[email protected] ~]# tail -f /var/log/messages
    Mar  7 11:18:33 relay01 systemd: Time has been changed
    Mar  7 11:18:38 relay01 systemd: Time has been changed
    Mar  7 11:18:43 relay01 systemd: Time has been changed
    Mar  7 11:18:48 relay01 systemd: Time has been changed
    Mar  7 11:18:53 relay01 systemd: Time has been changed
    Mar  7 11:18:58 relay01 systemd: Time has been changed
    Mar  7 11:19:03 relay01 systemd: Time has been changed
    Mar  7 11:19:08 relay01 systemd: Time has been changed
    Mar  7 11:19:13 relay01 systemd: Time has been changed
    Mar  7 11:19:18 relay01 systemd: Time has been changed
    

  • Service Provider

    Ah ha. DHCP strikes again :)


  • Service Provider

    @scottalanmiller said in Postfix problem receiving email to relay:

    Ah ha. DHCP strikes again :)

    I really want to figure out what is causing these VM's to do that. it is not normal.

    This problem was caused by me not being careful enough when I changed something to avoid the DHCP problem.


  • Service Provider

    And there goes a successful mail test.

    Mar  7 11:25:24 relay01 postfix/smtpd[2206]: connect from owncloud.domain.local[10.201.1.17]
    Mar  7 11:25:24 relay01 postfix/smtpd[2206]: CB2E6C0C82CB: client=owncloud.domain.local[10.201.1.17]
    Mar  7 11:25:24 relay01 postfix/cleanup[2208]: CB2E6C0C82CB: message-id=<[email protected]>
    Mar  7 11:25:24 relay01 postfix/qmgr[1665]: CB2E6C0C82CB: from=<[email protected]>, size=591, nrcpt=1 (queue active)
    Mar  7 11:25:24 relay01 postfix/smtpd[2206]: disconnect from owncloud.domain.local[10.201.1.17]
    Mar  7 11:25:26 relay01 postfix/smtp[2209]: CB2E6C0C82CB: to=<[email protected]>, relay=domain-com.mail.protection.outlook.com[216.32.181.170]:25, delay=2.1, delays=0.05/0/0.62/1.4, dsn=2.6.0, status=sent (250 2.6.0 <[email protected]> [InternalId=42704859829911, Hostname=SN1PR0201MB1854.namprd02.prod.outlook.com] 7564 bytes in 0.244, 30.254 KB/sec Queued mail for delivery)
    Mar  7 11:25:26 relay01 postfix/qmgr[1665]: CB2E6C0C82CB: removed
    

Log in to reply
 

Looks like your connection to MangoLassi was lost, please wait while we try to reconnect.