Topic: Email Broken

[jameswilson]

Applied updates to a 32bit sme 8 today and email is not functioning.
When connecting with thunderbird i get the error message

An error occured while sending mail. The mail server responded: Message denied temporarily.
Please check the message and try again.

This is on the internal lan

Server is in server / gateway mode.

Also smtp is down as well as no external email is arriving.
I noticed the weekend that i was getting sme8 admin messages about 11 emails going out in the last 5 mins, but couldnt see anything in the logs to suggest where they were originating from.

What logs should i be looking at to get to the bottom of it please?

[jameswilson]

its on at siaholdings.com
I have tried telnetting into smtp (25) and it just says

'220 sme-big.siaholdings.com ESMTP'

[guest22]

what does the command 'dmesg' say about booting the relevant services ?

[Daniel B.]

You should check SMTP logs

/var/log/qpsmtpd/current (for inbound email, and clients without auth or using TLS)
/var/log/sqpsmtpd/current (for client using SSL)

[jameswilson]

ty daniel.

ive been looking at all the logs to give me a clue. this was a working server. ive closed all ibays to be sure its not a php issue

[janet]

jameswilson

Send a message(s) locally and/or remotely & then check the log files mentioned around the time the message was sent.

Also check config settings
config show |more

scroll down (enter or space) to view mail settings, & I would also check RBL list settings.

You really need to find something more relevant/informative from the logs.

Did you do
signal-event post-upgrade
and
signal-event reboot
after the upgrade ?

Did the upgrade, reconfigure & reboot processes all run successfully & without apparent errors ?

Ultimately if you did a normal update process & the server is now problematic, then there could be a bug.
Upgrades are supposed to work correctly, so a better approach may be to lodge a bug (ie potential bug) at bugzilla.

[jameswilson]

i do think there is something being expolited, which is why i shut down all the i bays.

id agree i need find something in the logs, ive looked at them all for a clue which i can normally find.

what i dont get is why telnet on smtp doesnt give the expected response.

[CharlieBrady]

I have tried telnetting into smtp (25) and it just says

'220 sme-big.siaholdings.com ESMTP'

What do you expect to see? I don't see anything wrong with that.

[janet]

jameswilson

Perhaps you should answer the questions/follow advices that RequestedDeletion, daniel & myself have put to you, rather than (apparently) ignoring them.

Where is the evidence or proof you have been exploited, it's a guess.
Seems more likely to me that something went wrong during the upgrade, or maybe you had settings in place that were not previously saved correctly (eg as custom templates).
There are many possibilities, guessing is not a good approach, search for information that will provide clues, & keep searching until you find it.

You could also do an external port scan (grc.com) to see what is open, but nothing is yet pointing at that as the problem source, all suggestions are just "process of elimination" techniques at present.

I get the same telnet response so that's normal enough.

[CharlieBrady]

i do think there is something being expolited...

Why do you think that? What have you seen which makes you think that?

[jameswilson]

You should check SMTP logs

/var/log/qpsmtpd/current (for inbound email, and clients without auth or using TLS)
/var/log/sqpsmtpd/current (for client using SSL)

qpsmtpd current

014-08-06 10:59:21.090004500 4303 250 <sales@secureitall.co.uk>, recipient ok
2014-08-06 10:59:21.090084500 4303 dispatching DATA
2014-08-06 10:59:21.090403500 4303 354 go ahead
2014-08-06 10:59:21.233053500 4297 250 <sales@secureitall.co.uk>, recipient ok
2014-08-06 10:59:21.233176500 4297 dispatching DATA
2014-08-06 10:59:21.233479500 4297 354 go ahead
2014-08-06 10:59:21.316847500 4303 spooling message to disk
2014-08-06 10:59:21.499826500 4297 spooling message to disk
2014-08-06 10:59:21.515024500 4303 bcc plugin (data_post): message copied to maillog
2014-08-06 10:59:21.626960500 4297 bcc plugin (data_post): message copied to maillog
2014-08-06 10:59:21.915707500 4335 check_earlytalker plugin (connect): remote host said nothing spontaneous, proceeding
2014-08-06 10:59:21.918963500 4335 220 sme-big.siaholdings.com ESMTP
2014-08-06 10:59:21.941185500 4335 dispatching EHLO mail.CompleteSecurityRecruitment.com
2014-08-06 10:59:21.942676500 4335 250-siaholdings.com Hi completesecurityrecruitment.com [81.138.18.245]
2014-08-06 10:59:21.942695500 4335 250-PIPELINING
2014-08-06 10:59:21.942702500 4335 250-8BITMIME
2014-08-06 10:59:21.942759500 4335 250-SIZE 15000000
2014-08-06 10:59:21.942760500 4335 250 STARTTLS
2014-08-06 10:59:21.964621500 4335 dispatching STARTTLS
2014-08-06 10:59:21.964731500 4335 220 Go ahead with TLS
2014-08-06 10:59:21.990331500 4361 Accepted connection 5/40 from 74.63.238.60 / server111.gangsa.in
2014-08-06 10:59:21.990447500 4361 Connection from server111.gangsa.in [74.63.238.60]
2014-08-06 10:59:21.992398500 4361 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:59:21.994920500 4361 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:59:22.006964500 4361 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:59:22.030421500 4335 tls plugin (unrecognized_command): TLS setup returning
2014-08-06 10:59:22.053879500 4335 dispatching EHLO mail.CompleteSecurityRecruitment.com
2014-08-06 10:59:22.054542500 4335 250-siaholdings.com Hi completesecurityrecruitment.com [81.138.18.245]
2014-08-06 10:59:22.054559500 4335 250-PIPELINING
2014-08-06 10:59:22.054571500 4335 250-8BITMIME
2014-08-06 10:59:22.054630500 4335 250-SIZE 15000000
2014-08-06 10:59:22.054632500 4335 250 AUTH PLAIN LOGIN
2014-08-06 10:59:22.078091500 4335 dispatching MAIL FROM:<L.Feltham@CompleteSecurityRecruitment.com> SIZE=217756
2014-08-06 10:59:22.078210500 4335 full from_parameter: FROM:<L.Feltham@CompleteSecurityRecruitment.com> SIZE=217756
2014-08-06 10:59:22.213119500 4335 getting mail from <L.Feltham@CompleteSecurityRecruitment.com>
2014-08-06 10:59:22.213165500 4335 250 <L.Feltham@CompleteSecurityRecruitment.com>, sender OK - how exciting to get mail from you!
2014-08-06 10:59:22.213345500 4335 dispatching RCPT TO:<anne@secureitall.co.uk>
2014-08-06 10:59:22.241489500 4292 spamassassin plugin (data_post): check_spam: No, hits=1.1, required=5.0, tests=DKIM_SIGNED,DKIM_VALID,HTML_MESSAGE,RCVD_IN_DNSWL_NONE,SPF_HELO_PASS,SPF_PASS,URIBL_GREY
2014-08-06 10:59:22.241677500 4292 virus::clamav plugin (data_post): Changing permissions on file to permit scanner access
2014-08-06 10:59:22.243006500 4292 virus::clamav plugin (data_post): clamscan results: ERROR: Can't connect to clamd: No such file or directory
2014-08-06 10:59:22.243007500 4292 virus::clamav plugin (data_post): ClamAV error: /usr/bin/clamdscan --stdout  --config-file=/etc/clamd.conf --no-summary /var/spool/qpsmtpd/1407319160:4292:0 2>&1: 2
2014-08-06 10:59:22.243008500
2014-08-06 10:59:22.243298500 4292 logging::logterse plugin (deny): ` 46.236.37.52   relay-13-52.msgfocus.com   relay-13-52.msgfocus.com   <mail.nrcmlorzhjdegr@email.suttons.co.uk>   <anne@secureitall.co.uk>,Mail::Address=ARRAY(0xa48aad8)   virus::clamav   902      msg denied before queued
2014-08-06 10:59:22.243398500 4292 452 Message denied temporarily
2014-08-06 10:59:22.261956500 4292 dispatching RSET
2014-08-06 10:59:22.262069500 4292 250 OK
2014-08-06 10:59:22.281108500 4292 dispatching MAIL FROM:<mail.nrcmloqgjvfeuo@email.suttons.co.uk> BODY=8BITMIME
2014-08-06 10:59:22.281221500 4292 full from_parameter: FROM:<mail.nrcmloqgjvfeuo@email.suttons.co.uk> BODY=8BITMIME
2014-08-06 10:59:22.295700500 4292 getting mail from <mail.nrcmloqgjvfeuo@email.suttons.co.uk>
2014-08-06 10:59:22.295701500 4292 250 <mail.nrcmloqgjvfeuo@email.suttons.co.uk>, sender OK - how exciting to get mail from you!
2014-08-06 10:59:22.295767500 4292 dispatching RCPT TO:<anne@secureitall.co.uk>
2014-08-06 10:59:22.387254500 4335 250 <anne@secureitall.co.uk>, recipient ok
2014-08-06 10:59:22.468992500 4335 dispatching DATA
2014-08-06 10:59:22.469370500 4335 354 go ahead
2014-08-06 10:59:22.486706500 4292 250 <anne@secureitall.co.uk>, recipient ok
2014-08-06 10:59:22.486805500 4292 dispatching DATA
2014-08-06 10:59:22.487012500 4292 354 go ahead
2014-08-06 10:59:22.527218500 4292 spooling message to disk
2014-08-06 10:59:22.543475500 4335 spooling message to disk
2014-08-06 10:59:22.587578500 4292 bcc plugin (data_post): message copied to maillog

sqpsmtpd log

2014-08-06 09:49:39.515980500 31331 Accepted connection 0/10 from 212.32.55.213 / Unknown
2014-08-06 09:49:39.516097500 31331 Connection from Unknown [212.32.55.213]
2014-08-06 09:49:39.518062500 31331 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 09:49:39.520650500 31331 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 09:49:39.526866500 31331 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 09:49:39.636873500 31331 tls plugin (connect): Connected via SMTPS
2014-08-06 09:49:39.700203500 31331 check_earlytalker plugin (connect): remote host started talking before we said hello [212.32.55.213]
2014-08-06 09:49:39.700423500 31331 logging::logterse plugin (deny): ` 212.32.55.213   Unknown            check_earlytalker   902   Connecting host started transmitting before SMTP greeting   msg denied before queued
2014-08-06 09:49:39.700518500 31331 450 Connecting host started transmitting before SMTP greeting
2014-08-06 09:49:39.701364500 31331 click, disconnecting
2014-08-06 09:49:40.121428500 4270 cleaning up after 31331
2014-08-06 09:49:40.129815500 31337 Accepted connection 1/10 from 212.32.55.213 / Unknown
2014-08-06 09:49:40.129930500 31337 Connection from Unknown [212.32.55.213]
2014-08-06 09:49:40.131883500 31337 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 09:49:40.134481500 31337 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 09:49:40.144093500 31337 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 09:49:40.255194500 31337 tls plugin (connect): Connected via SMTPS
2014-08-06 09:49:40.319808500 31337 check_earlytalker plugin (connect): remote host started talking before we said hello [212.32.55.213]
2014-08-06 09:49:40.320060500 31337 logging::logterse plugin (deny): ` 212.32.55.213   Unknown            check_earlytalker   902   Connecting host started transmitting before SMTP greeting   msg denied before queued
2014-08-06 09:49:40.320165500 31337 450 Connecting host started transmitting before SMTP greeting
2014-08-06 09:49:40.321039500 31337 click, disconnecting
2014-08-06 09:49:41.124350500 4270 cleaning up after 31337
2014-08-06 10:19:13.065970500 14985 Accepted connection 0/10 from 212.32.55.213 / Unknown
2014-08-06 10:19:13.066086500 14985 Connection from Unknown [212.32.55.213]
2014-08-06 10:19:13.068040500 14985 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:19:13.070622500 14985 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:19:13.077692500 14985 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:19:13.187710500 14985 tls plugin (connect): Connected via SMTPS
2014-08-06 10:19:13.527252500 14985 check_earlytalker plugin (connect): remote host started talking before we said hello [212.32.55.213]
2014-08-06 10:19:13.527471500 14985 logging::logterse plugin (deny): ` 212.32.55.213   Unknown            check_earlytalker   902   Connecting host started transmitting before SMTP greeting   msg denied before queued
2014-08-06 10:19:13.527566500 14985 450 Connecting host started transmitting before SMTP greeting
2014-08-06 10:19:13.528406500 14985 click, disconnecting
2014-08-06 10:19:13.705966500 4270 cleaning up after 14985
2014-08-06 10:19:13.715588500 14991 Accepted connection 1/10 from 212.32.55.213 / Unknown
2014-08-06 10:19:13.715775500 14991 Connection from Unknown [212.32.55.213]
2014-08-06 10:19:13.716650500 14991 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:19:13.717805500 14991 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:19:13.721892500 14991 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:19:13.829304500 14991 tls plugin (connect): Connected via SMTPS
2014-08-06 10:19:13.907888500 14991 check_earlytalker plugin (connect): remote host started talking before we said hello [212.32.55.213]
2014-08-06 10:19:13.908040500 14991 logging::logterse plugin (deny): ` 212.32.55.213   Unknown            check_earlytalker   902   Connecting host started transmitting before SMTP greeting   msg denied before queued
2014-08-06 10:19:13.908115500 14991 450 Connecting host started transmitting before SMTP greeting
2014-08-06 10:19:13.908549500 14991 click, disconnecting
2014-08-06 10:19:14.705830500 4270 cleaning up after 14991
2014-08-06 10:53:32.723421500 752 Accepted connection 0/10 from 212.32.55.213 / Unknown
2014-08-06 10:53:32.723530500 752 Connection from Unknown [212.32.55.213]
2014-08-06 10:53:32.725530500 752 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:53:32.728129500 752 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:53:32.737781500 752 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:53:32.852669500 752 tls plugin (connect): Connected via SMTPS
2014-08-06 10:53:32.918866500 752 check_earlytalker plugin (connect): remote host started talking before we said hello [212.32.55.213]
2014-08-06 10:53:32.919093500 752 logging::logterse plugin (deny): ` 212.32.55.213   Unknown            check_earlytalker   902   Connecting host started transmitting before SMTP greeting   msg denied before queued
2014-08-06 10:53:32.919192500 752 450 Connecting host started transmitting before SMTP greeting
2014-08-06 10:53:32.920056500 752 click, disconnecting
2014-08-06 10:53:32.986212500 4270 cleaning up after 752
2014-08-06 10:53:32.995825500 760 Accepted connection 1/10 from 212.32.55.213 / Unknown
2014-08-06 10:53:32.995934500 760 Connection from Unknown [212.32.55.213]
2014-08-06 10:53:32.997893500 760 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:53:33.000463500 760 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:53:33.007637500 760 tls plugin (init): ciphers: HIGH:!SSLv2:!ADH:!aNULL:!MD5:!RC4
2014-08-06 10:53:33.117932500 760 tls plugin (connect): Connected via SMTPS
2014-08-06 10:53:33.237032500 760 check_earlytalker plugin (connect): remote host started talking before we said hello [212.32.55.213]
2014-08-06 10:53:33.237222500 760 logging::logterse plugin (deny): ` 212.32.55.213   Unknown            check_earlytalker   902   Connecting host started transmitting before SMTP greeting   msg denied before queued
2014-08-06 10:53:33.237316500 760 450 Connecting host started transmitting before SMTP greeting
2014-08-06 10:53:33.238134500 760 click, disconnecting
2014-08-06 10:53:33.985856500 4270 cleaning up after 760

[jameswilson]

Why do you think that? What have you seen which makes you think that?

I was getting emails from sme8admin that the server had sent x emails in the last 5 mins. Friday night when noone was in work

[jameswilson]

jameswilson

Perhaps you should answer the questions/follow advices that RequestedDeletion, daniel & myself have put to you, rather than (apparently) ignoring them.

Where is the evidence or proof you have been exploited, it's a guess.
Seems more likely to me that something went wrong during the upgrade, or maybe you had settings in place that were not previously saved correctly (eg as custom templates).
There are many possibilities, guessing is not a good approach, search for information that will provide clues, & keep searching until you find it.

You could also do an external port scan (grc.com) to see what is open, but nothing is yet pointing at that as the problem source, all suggestions are just "process of elimination" techniques at present.

I get the same telnet response so that's normal enough.

Janet
My appologies im not ignoring it i will provide all response now

[jameswilson]

jameswilson

Send a message(s) locally and/or remotely & then check the log files mentioned around the time the message was sent.

Also check config settings
config show |more

scroll down (enter or space) to view mail settings, & I would also check RBL list settings.

You really need to find something more relevant/informative from the logs.

Did you do
signal-event post-upgrade
and
signal-event reboot
after the upgrade ?

Did the upgrade, reconfigure & reboot processes all run successfully & without apparent errors ?

Ultimately if you did a normal update process & the server is now problematic, then there could be a bug.
Upgrades are supposed to work correctly, so a better approach may be to lodge a bug (ie potential bug) at bugzilla.

On sending locally (can only loginto webmail local smtp does not work) horde gives an smtp error of 452.
Which log am i looking at for the time error etc info?

Yes the upgrade and reconfigure did appear normal

[Daniel B.]

Your log snippets show nothing wrong, and no connection attempt from the local network, nor the webmail. Please, check your logs at the time you try to send an email (either with thunderbird or the webmail)