First, I just want to thank you for your time Joe, This means a lot to me, I am very interested in making Virtualmin my goto platform as I progress into self hosting my clients. ( one day )
Second.
I want to provide as much as I can here so I’m going to show the whole process. I see there is some issues with dovecot right off the bat while it is running, they follow.
PRE SHUTDOWN OF DOVECOT
Active: active (running) since Wed 2016-12-21 08:40:45 UTC; 1 day 3h ago
Process: 877 ExecStartPre=/usr/libexec/dovecot/prestartscript (code=exited, st atus=0/SUCCESS)
Main PID: 887 (dovecot)
CGroup: /system.slice/dovecot.service
|-887 /usr/sbin/dovecot -F
|-890 dovecot/anvil
`-891 dovecot/log
Dec 21 07:31:15 dns dovecot[881]: master: Warning: Killed with signal 15 (by pid =8859 uid=0 code=kill)
Dec 21 08:40:44 dns systemd[1]: Starting Dovecot IMAP/POP3 email server…
Dec 21 08:40:45 dns systemd[1]: Started Dovecot IMAP/POP3 email server.
Dec 21 08:40:45 dns dovecot[887]: master: Dovecot v2.2.10 starting up for imap, pop3 (core dumps disabled)
Dec 21 15:38:50 dns dovecot[891]: pop3-login: Disconnected (no auth attempts in 1 secs): user=<>, rip=89.248.167.131, lip=216.158.230.167, session=<LGYQ8yxErgBZ +KeD>
Dec 22 02:41:59 dns dovecot[891]: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=141.212.122.96, lip=216.158.230.167, TLS, session=
Dec 22 05:04:02 dns dovecot[891]: pop3-login: Disconnected (no auth attempts in 2 secs): user=<>, rip=168.1.128.35, lip=MYSERVERIP, TLS handshaking: Disconn ected, session=
Dec 22 05:12:49 dns dovecot[891]: pop3-login: Disconnected (no auth attempts in 2 secs): user=<>, rip=168.1.128.59, lip=216.158.230.167, TLS handshaking: Discon nected, session=
Dec 22 09:02:42 dns dovecot[891]: imap-login: Disconnected (disconnected before auth was ready, waited 0 secs): user=<>, rip=141.212.122.32, lip=199.231.189.14, TLS handshaking: SSL_accept() failed: error:1408A0C1:SSL routines:SSL3_GET_CLIE NT_HELLO:no shared cipher, session=
Dec 22 09:55:55 dns dovecot[891]: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=89.248.172.16, lip=MYSERVERIP, session=<S1mMRjxEzABZ+K wQ>
NOTE:ONLY ONE of the IP Addresses above belong to my server and I have titled it “MYSERVERIP”
DOVECOT AFTER SHUTDOWN AND RESTART
Active: active (running) since Thu 2016-12-22 11:54:19 UTC; 20s ago
Process: 18287 ExecStartPre=/usr/libexec/dovecot/prestartscript (code=exited, status=0/SUCCESS)
Main PID: 18291 (dovecot)
CGroup: /system.slice/dovecot.service
|-18291 /usr/sbin/dovecot -F
|-18292 dovecot/anvil
|-18293 dovecot/log
`-18295 dovecot/config
Dec 22 11:54:19 dns systemd[1]: Starting Dovecot IMAP/POP3 email server…
Dec 22 11:54:19 dns systemd[1]: Started Dovecot IMAP/POP3 email server.
Dec 22 11:54:19 dns dovecot[18291]: master: Dovecot v2.2.10 starting up for imap, pop3 (core dumps disabled)
MAILLLOG IS EMPTY FOR ANY NEW ENTRYS FROM START AND STOP OF DOVECOT
But on another note, I do notice some new logs from the other day that may give some insight.
Dec 20 02:04:05 dns dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=17275, secured, session=<0WNrcw1EuAAAAAAAAAAAAAAAAAAAAAAB>
Dec 20 02:04:05 dns dovecot: imap: Error: user my.username: Mail access for users with UID 501 not permitted (see first_valid_uid in config file, uid from userdb lookup).
Dec 20 02:04:05 dns dovecot: imap: Error: Invalid user settings. Refer to server log for more information.
Dec 20 02:04:55 dns dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=17282, secured, session=
Dec 20 02:04:55 dns dovecot: imap: Error: user my.username: Mail access for users with UID 501 not permitted (see first_valid_uid in config file, uid from userdb lookup).
Dec 20 02:04:55 dns dovecot: imap: Error: Invalid user settings. Refer to server log for more information.
Dec 20 02:05:21 dns dovecot: imap-login: Disconnected (auth failed, 1 attempts in 4 secs): user=, method=PLAIN, rip=::1, lip=::1, secured, session=
Dec 20 02:06:34 dns dovecot: master: Fatal: Dovecot is already running with PID 8100 (read from /var/run/dovecot/master.pid)
Dec 20 02:07:56 dns postfix/postfix-script[17457]: fatal: the Postfix mail system is already running
Dec 20 02:10:04 dns dovecot: master: Fatal: Dovecot is already running with PID 8100 (read from /var/run/dovecot/master.pid)
Dec 20 02:33:12 dns postfix/smtpd[18902]: warning: hostname inspire.census.shodan.io does not resolve to address 71.6.146.186
Dec 20 02:33:12 dns postfix/smtpd[18902]: connect from unknown[71.6.146.186]
Dec 20 02:33:12 dns postfix/smtpd[18902]: lost connection after CONNECT from unknown[71.6.146.186]
NOTE: I am no longer getting the “dovecot is already running” error when I run systemctl status dovecot -l
but seeing this had me check postfix again, and sure enough, even though it was running the other day, It is not now. Some new info was provided when running systemctl status postfix -l
this time.
The other day, I sent an email from Webmin’s Read User Mail and it sent, then I tried to send back and nothing was received, but information about that sent email is in the Postfix status information now.
It looks to me like sending the email caused part of an issue that shut it down, maybe this will give some insight. I have changed the email address that I sent too in the logs to keep spambots from picking it up, in the logs I have changed the email to address to “remoteemail@gmail.com” for above noted purpose and email from my server to myemail@myserver.com.
I have not checked postfix since I sent the email and it worked, I am guessing according to the information below, it shut down right after sending.
ALSO: I got this kickback from gmail from the server when I sent an email to myserver.com
Technical details of temporary failure:
Google tried to deliver your message, but it was rejected by the server for the recipient domain myserver.com by mail.myserver.com. [123.45.67.89].
The error that the other server returned was:
451 4.3.5 Server configuration error
POSTFIX NEW STATUS AFTER EMAIL WAS SENT FROM WITHIN WEBMIN (Successfully)
- postfix.service - Postfix Mail Transport Agent
Loaded: loaded (/usr/lib/systemd/system/postfix.service; enabled; vendor preset: disabled)
Active: failed (Result: exit-code) since Wed 2016-12-21 08:44:35 UTC; 1 day 3h ago
Process: 1280 ExecStop=/usr/sbin/postfix stop (code=exited, status=1/FAILURE)
Process: 169 ExecStart=/usr/sbin/postfix start (code=exited, status=0/SUCCESS)
Process: 160 ExecStartPre=/usr/libexec/postfix/chroot-update (code=exited, status=0/SUCCESS)
Process: 117 ExecStartPre=/usr/libexec/postfix/aliasesdb (code=exited, status=0/SUCCESS)
Main PID: 597 (code=killed, signal=TERM)
Dec 21 08:43:35 dns postfix/pickup[618]: BE450E104F: uid=0 from=myemail@myserver.com
Dec 21 08:43:35 dns postfix/cleanup[1153]: BE450E104F: message-id=1482309815.1112@myserver.com
Dec 21 08:43:35 dns postfix/qmgr[619]: BE450E104F: from=myemail@myserver.com, size=621, nrcpt=1 (queue active)
Dec 21 08:44:11 dns postfix/smtp[1155]: connect to gmail-smtp-in.l.google.com[2607:f8b0:400d:c02::1a]:25: Connection timed out
Dec 21 08:44:11 dns postfix/smtp[1155]: BE450E104F: to=remoteemail@gmail.com, relay=gmail-smtp-in.l.google.com[74.125.22.27]:25, delay=36, delays=0.12/0.09/35/0.4, dsn=2.0.0, status=sent (250 2.0.0 OK 1482309852 z16si962002qtb.145 - gsmtp)
Dec 21 08:44:11 dns postfix/qmgr[619]: BE450E104F: removed
Dec 21 08:44:35 dns postfix/postfix-script[1293]: fatal: the Postfix mail system is not running
Dec 21 08:44:35 dns systemd[1]: postfix.service: control process exited, code=exited status=1
Dec 21 08:44:35 dns systemd[1]: Unit postfix.service entered failed state.
Dec 21 08:44:35 dns systemd[1]: postfix.service failed.
After looking at this I tried to do a systemctl start postfix
and of course it wouldn’t start, so I wanted to see what happened on a system reboot. So I did that.
After reboot, Postfix is running again, This is the new status of postfix after reboot, again it is showing the “postfix is already running” error and has cleared the issue with the mailsend.
AFTER A SYSTEM REBOOT
Active: active (running) since Thu 2016-12-22 12:16:48 UTC; 25s ago
Process: 165 ExecStart=/usr/sbin/postfix start (code=exited, status=0/SUCCESS)
Process: 157 ExecStartPre=/usr/libexec/postfix/chroot-update (code=exited, status=0/SUCCESS)
Process: 116 ExecStartPre=/usr/libexec/postfix/aliasesdb (code=exited, status=0/SUCCESS)
Main PID: 613 (master)
CGroup: /system.slice/postfix.service
|-613 /usr/libexec/postfix/master -w
|-628 pickup -l -t unix -u
`-629 qmgr -l -t unix -u
Dec 22 12:16:12 dns systemd[1]: Starting Postfix Mail Transport Agent…
Dec 22 12:16:12 dns postfix/postfix-script[18950]: fatal: the Postfix mail system is already running
Dec 22 12:16:12 dns systemd[1]: postfix.service: control process exited, code=exited status=1
Dec 22 12:16:12 dns systemd[1]: Failed to start Postfix Mail Transport Agent.
Dec 22 12:16:12 dns systemd[1]: Unit postfix.service entered failed state.
Dec 22 12:16:12 dns systemd[1]: postfix.service failed.
Dec 22 12:16:43 dns systemd[1]: Starting Postfix Mail Transport Agent…
Dec 22 12:16:47 dns postfix/postfix-script[599]: starting the Postfix mail system
Dec 22 12:16:48 dns postfix/master[613]: daemon started – version 2.10.1, configuration /etc/postfix
Dec 22 12:16:48 dns systemd[1]: Started Postfix Mail Transport Agent.
After system reboot, maillog is empty with no new entries still.
Now that I had it started again (not running right) but running, I figured I would send an email to my server before sending one outbound and see what happens. Results are nothing is delivered, as to be expected. Also, still nothing new in maillog.
But, Now that I sent an email to the server, there is another change to systemctl status postfix
and it reads as such.
POSTFIX NEW STATUS AFTER EMAIL WAS SENT FROM OUTSIDE SOURCE TO SERVER
Active: active (running) since Thu 2016-12-22 12:16:48 UTC; 11min ago
Process: 165 ExecStart=/usr/sbin/postfix start (code=exited, status=0/SUCCESS)
Process: 157 ExecStartPre=/usr/libexec/postfix/chroot-update (code=exited, status=0/SUCCESS)
Process: 116 ExecStartPre=/usr/libexec/postfix/aliasesdb (code=exited, status=0/SUCCESS)
Main PID: 613 (master)
CGroup: /system.slice/postfix.service
|- 613 /usr/libexec/postfix/master -w
|- 628 pickup -l -t unix -u
|- 629 qmgr -l -t unix -u
`-1333 anvil -l -t unix -u
Dec 22 12:16:48 dns postfix/master[613]: daemon started – version 2.10.1, configuration /etc/postfix
Dec 22 12:16:48 dns systemd[1]: Started Postfix Mail Transport Agent.
Dec 22 12:26:47 dns postfix/smtpd[1331]: connect from mail-qt0-f194.google.com[209.85.216.194]
Dec 22 12:26:47 dns postfix/smtpd[1331]: warning: unknown smtpd restriction: “=”
Dec 22 12:26:47 dns postfix/smtpd[1331]: NOQUEUE: reject: RCPT from mail-qt0-f194.google.com[209.85.216.194]: 451 4.3.5 Server configuration error; from=remoteemail@gmail.com to=myemail@myserver.com proto=ESMTP helo=<mail-qt0-f194.google.com>
Dec 22 12:26:47 dns postfix/cleanup[1335]: 9A49BE0090: message-id=20161222122647.9A49BE0090@dns.localdomain
Dec 22 12:26:47 dns postfix/qmgr[629]: 9A49BE0090: from=double-bounce@dns.localdomain, size=1029, nrcpt=1 (queue active)
Dec 22 12:26:47 dns postfix/smtpd[1331]: disconnect from mail-qt0-f194.google.com[209.85.216.194]
Dec 22 12:26:49 dns postfix/local[1336]: 9A49BE0090: to=root@dns.localdomain, orig_to=, relay=local, delay=1.6, delays=0.02/0.01/0/1.5, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)
Dec 22 12:26:49 dns postfix/qmgr[629]: 9A49BE0090: removed
NOTE: The line that says Dec 22 12:26:47 dns postfix/smtpd[1331]: warning: unknown smtpd restriction: “=”
tells me that my “fix” to postfix was an improper one and although I thought it got postfix running, It is not a permanent solution. So I will be removing that " = " from line “permit_sasl_authenticated,permit_mynetworks,reject_unauth_destination =” in postfix main.cf file as suggested by another, since it is not being recognized by postfix anyway.
Just to make sure line smtpd_recipient_restrictions = permit_mynetworks permit_sasl_authenticated reject_unauth_destination =
was the cause of the issued warning Dec 22 12:26:47 dns postfix/smtpd[1331]: warning: unknown smtpd restriction: “=”
I removed the = that I added to the end and rebooted the server, postfix was running again without that warning Dec 22 12:26:47 dns postfix/smtpd[1331]: warning: unknown smtpd restriction: “=”
this time and it rebooted and started just fine, But still had the other data left from the code post above regarding the inbound email.
But the rest of the information in regards to the email sent to my mail server may have some pertinent data for the problem at hand.
Hopefully this data helps.
Best Regards,
Kyle