This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

User portal missing some spam shown in mail manager

I am trying to resolve an issue with antispam.

Most spam messages sent to an account, say "xyz", are listed in the user portal when user xyz logs in; but not all of them. 

In other words, I can see some messages in the mail manager that are addressed to user xyz, but they just won't show up in xyz's user portal. These messages are classified as spam, i.e., they were not flagged as viruses. So I don't understand why they don't show up like the others.

These odd messages also cannot be released, and they are not included in the quarantine report.

I have re-entered the e-mail password and other settings in the user portal, just to be safe, but that was not the reason.

Any ideas?


This thread was automatically locked due to age.
  • Version of UTM?  POP3 or SMTP Proxy?  Lines from the relevant log file for one such message?

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • Version of UTM?  POP3 or SMTP Proxy?  Lines from the relevant log file for one such message?

    Cheers - Bob


    Oops, yes, forgot the crucial details...

    UTM 9.201-23
    POP3 Proxy

    In terms of the logs, logged on as user yyyyyyyyyy.
    Deleted all spam there.
    Logged in as admin and went to Mail Manager
    Saw spam for user yyyyyyyyyy not seen in the user portal.
    Tried to release, but to no effect.
    Finally, deleted the spam.

     aua[15987]: id="3004" severity="info" sys="System" sub="auth" name="Authentication successful" srcip="***.***.***.***" user="yyyyyyyyyy" caller="portal" engine="local"
     confd[3358]: I main::top-level:652() => id="310a" severity="info" sys="System" sub="confd" name="object changed" class="aaa" type="user" ref="REF_AaaUseConcernedc" objname="yyyyyyyyyy" user="system" srcip="127.0.0.1" sid="SswvyEcgzUwHxNekJxKl" facility="system" client="aua.bin" pid="15988" oldattr_lastauth_time="1399430753" attr_lastauth_time="1399601189"
     confd[3358]: I main::top-level:749() => id="310n" severity="info" sys="System" sub="confd" name="applied changes" user="system" srcip="127.0.0.1" sid="SswvyEcgzUwHxNekJxKl" facility="system" client="aua.bin" pid="15988" version="15" storage="/cfg"
     middleware[3916]: T main::top-level:260() => ending cycle 12, caught 1 signals, 1 children still running
     middleware[3916]: T main::top-level:213() => starting cycle 13, caught 1 signals
     smtpd[4615]: MASTER[4615]: (Re-)loading configuration from Confd
     middleware[3916]: T core::Config::Changed:134() => configversion=15
     middleware[3916]: T core::Config::Changed:144() => nodes=0 objects=1 triggers=0
     middleware[3916]: T core::Config::load:269() => modules=1,1
     smtpd[4615]: MASTER[4615]: Past 08:00:00, QR status one set to 'sent'
     smtpd[4615]: MASTER[4615]: Past 16:00:00, QR status two set to 'sent'
     middleware[3916]: T modules::ipset:[:D]eleteUnused:320() => auto#=2/682 confd#=1/341
     middleware[3916]: T main::top-level:271() => cycle 13 waiting for 1 children
     exim-in[5120]: 2014-05-08 19:06:30 pid 5120: SIGHUP received: re-exec daemon
     exim-in[5120]: 2014-05-08 19:06:30 exim 4.76 daemon started: pid=5120, no queue runs, listening for SMTP on port 25 (IPv4) port 587 (IPv4) and for SMTPS on port 465 (IPv4)
     httpd: ***.***.***.*** - - [08/May/2014:19:06:29 -0700] "POST /index.plx?app=eup&func=login HTTP/1.1" 200 701
     httpd: ***.***.***.*** - - [08/May/2014:19:06:31 -0700] "POST /index.plx?app=eup&func=mainmenu HTTP/1.1" 200 357
     httpd: ***.***.***.*** - - [08/May/2014:19:06:31 -0700] "POST /index.plx?app=eup&func=welcome HTTP/1.1" 200 961
     httpd: ***.***.***.*** - - [08/May/2014:19:06:33 -0700] "POST /index.plx?app=eup&func=pop3_quarantine HTTP/1.1" 200 461
     httpd: ***.***.***.*** - - [08/May/2014:19:06:37 -0700] "POST /index.plx?app=eup&func=pop3_action HTTP/1.1" 200 136
     httpd: ***.***.***.*** - - [08/May/2014:19:06:37 -0700] "POST /index.plx?app=eup&func=pop3_quarantine HTTP/1.1" 200 249
     httpd: ***.***.***.*** - - [08/May/2014:19:06:39 -0700] "POST /index.plx?app=eup&func=logout HTTP/1.1" 200 59
     httpd: ***.***.***.*** - - [08/May/2014:19:06:39 -0700] "POST /index.plx?app=eup&func=login HTTP/1.1" 200 96
     httpd: ***.***.***.*** - - [08/May/2014:19:06:43 -0700] "POST /qm/index.plx?app=qm&func=logout HTTP/1.1" 200 30
     httpd: ***.***.***.*** - - [08/May/2014:19:06:43 -0700] "POST /webadmin.plx HTTP/1.1" 200 950
     httpd: ***.***.***.*** - - [08/May/2014:19:06:45 -0700] "GET /qm/ HTTP/1.1" 200 9625
     httpd: ***.***.***.*** - - [08/May/2014:19:06:45 -0700] "POST /qm/index.plx?app=qm&func=login HTTP/1.1" 200 78
     httpd: ***.***.***.*** - - [08/May/2014:19:06:45 -0700] "POST /qm/index.plx?app=qm&func=mainmenu HTTP/1.1" 200 212
     httpd: ***.***.***.*** - - [08/May/2014:19:06:45 -0700] "POST /qm/index.plx?app=qm&func=smtp_quarantine HTTP/1.1" 200 276
     httpd: ***.***.***.*** - - [08/May/2014:19:06:50 -0700] "POST /qm/index.plx?app=qm&func=pop3_quarantine HTTP/1.1" 200 372
     exim-out[16054]: 2014-05-08 19:07:00 Start queue run: pid=16054
     exim-out[16054]: 2014-05-08 19:07:00 End queue run: pid=16054
     httpd: ***.***.***.*** - - [08/May/2014:19:07:08 -0700] "POST /qm/index.plx?app=qm&func=pop3_action HTTP/1.1" 200 110
     httpd: ***.***.***.*** - - [08/May/2014:19:07:08 -0700] "POST /qm/index.plx?app=qm&func=pop3_quarantine HTTP/1.1" 200 403
     httpd: ***.***.***.*** - - [08/May/2014:19:07:45 -0700] "POST /qm/index.plx?app=qm&func=pop3_action HTTP/1.1" 200 142
     httpd: ***.***.***.*** - - [08/May/2014:19:07:53 -0700] "POST /qm/index.plx?app=qm&func=pop3_action HTTP/1.1" 200 111
     httpd: ***.***.***.*** - - [08/May/2014:19:07:53 -0700] "POST /qm/index.plx?app=qm&func=pop3_quarantine HTTP/1.1" 200 227
     exim-out[16132]: 2014-05-08 19:08:00 Start queue run: pid=16132
     exim-out[16132]: 2014-05-08 19:08:00 End queue run: pid=16132
     httpd: ***.***.***.*** - - [08/May/2014:19:08:20 -0700] "POST /qm/index.plx?app=qm&func=logout HTTP/1.1" 200 30
     httpd: ***.***.***.*** - - [08/May/2014:19:08:22 -0700] "GET /qm/ HTTP/1.1" 200 9625
     httpd: ***.***.***.*** - - [08/May/2014:19:08:23 -0700] "POST /qm/index.plx?app=qm&func=login HTTP/1.1" 200 78
     httpd: ***.***.***.*** - - [08/May/2014:19:08:23 -0700] "POST /qm/index.plx?app=qm&func=mainmenu HTTP/1.1" 200 212
     httpd: ***.***.***.*** - - [08/May/2014:19:08:23 -0700] "POST /qm/index.plx?app=qm&func=smtp_quarantine HTTP/1.1" 200 276
     httpd: ***.***.***.*** - - [08/May/2014:19:08:24 -0700] "POST /qm/index.plx?app=qm&func=pop3_quarantine HTTP/1.1" 200 194
     httpd: ***.***.***.*** - - [08/May/2014:19:08:26 -0700] "POST /qm/index.plx?app=qm&func=logout HTTP/1.1" 200 30
     exim-out[16210]: 2014-05-08 19:09:00 Start queue run: pid=16210
     exim-out[16285]: 2014-05-08 19:10:00 Start queue run: pid=16285
     /usr/sbin/cron[16303]: (root) CMD (   /usr/local/bin/reporter/system-reporter.pl)
     /usr/sbin/cron[16302]: (root) CMD (/var/mdw/scripts/pmx-blocklist-update)
  • Sorry, I just now got back to this.

    How about the lines from the POP3 logfile for when a spam was downloaded from the server by the UTM?

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • Sorry, I just now got back to this.

    How about the lines from the POP3 logfile for when a spam was downloaded from the server by the UTM?

    Cheers - Bob


    Thanks for asking.

    This is interesting.  All the affected e-mails are both passed and quarantined (sample below). 

    They are not included in the quarantine report, but rather are sent separately under the "E-mail blocked" cover.

    [from, to, subject, size, srcip are the same; dstip differ]

    May 31 13:11:27 pop3proxy[11465]: id="1100" severity="info" sys="SecureMail" sub="pop3" name="email passed" from="[redacted]" to="[redacted]" subject="[redacted]" size="18878" srcip="zz.240.9.43" dstip="xx.yy.128.135" uid="47221.X1WM6g8fbIXxW2ukt2OsuyqFb3U=" ident="0/11465-1-1401567087"
    May 31 13:34:48 pop3proxy[13748]: id="1101" severity="info" sys="SecureMail" sub="pop3" name="email quarantined" from="[redacted]" to="[redacted]" subject="[redacted]" size="18878" srcip="zz.240.9.43" dstip="xx.yy.136.144" uid="47221.X1WM6g8fbIXxW2ukt2OsuyqFb3U=" ident="0/13748-1-1401568487" reason="as"
  • Does this just happen with a single user?  Does this work correctly for everyone else?  

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • Does this just happen with a single user?  Does this work correctly for everyone else?  

    Cheers - Bob


    It affects all users at one point or another during the day.
  • And, it's not from just one POP3 server?

    I'm a bit confused that there were only two lines in the POP3 log during that 23-minute period.

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • And, it's not from just one POP3 server?

    I'm a bit confused that there were only two lines in the POP3 log during that 23-minute period.

    Cheers - Bob


    Oops again. I looked at an archived version on a different server. The following is directly from the UTM.

    The pop3 server has the same DNS name but resolves to different IPs.

    Thanks for taking the time!

    2014:05:31-13:11:27 TheWiredGateway pop3proxy[11465]: Prefetch for account 3: Successfully logged in on POP3 server xx.yy.128.135
    2014:05:31-13:11:28 TheWiredGateway pop3proxy[11465]: id="1100" severity="info" sys="SecureMail" sub="pop3" name="email passed" from="ggg" to="eee" subject="hhh?" size="18878" srcip="zz.240.9.43" dstip="xx.yy.128.135" uid="47221.X1WM6g8fbIXxW2ukt2OsuyqFb3U=" ident="0/11465-1-1401567087"
    2014:05:31-13:11:28 TheWiredGateway pop3proxy[11465]: Prefetch for account 3 finished (fetched=1, deleted=0, not_on_server=1)

    2014:05:31-13:26:29 TheWiredGateway pop3proxy[12966]: Prefetch for account 3: Successfully logged in on POP3 server xx.yy.128.135
    2014:05:31-13:26:29 TheWiredGateway pop3proxy[12966]: Prefetch for account 3 finished (fetched=0, deleted=0, not_on_server=1)

    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13743]: Accepted client connection from iii for xx.yy.136.144
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13746]: Accepted client connection from iii for xx.yy.136.144
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13747]: Accepted client connection from iii for xx.yy.136.144
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13745]: Accepted client connection from iii for xx.yy.136.144
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13748]: Accepted client connection from iii for xx.yy.136.144
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13743]: aaa logged in
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13746]: bbb logged in
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13745]: ddd logged in
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13748]: eee logged in
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13747]: fff logged in
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13743]: Client iii logged out (account=0, deleted=0)
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13745]: Client iii logged out (account=0, deleted=0)
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13746]: Client iii logged out (account=0, deleted=0)
    2014:05:31-13:34:47 TheWiredGateway pop3proxy[13747]: Client iii logged out (account=0, deleted=0)
    2014:05:31-13:34:48 TheWiredGateway pop3proxy[13748]: id="1101" severity="info" sys="SecureMail" sub="pop3" name="email quarantined" from="ggg" to="eee" subject="hhh?" size="18878" srcip="zz.240.9.43" dstip="xx.yy.136.144" uid="47221.X1WM6g8fbIXxW2ukt2OsuyqFb3U=" ident="0/13748-1-1401568487" reason="as"
    2014:05:31-13:34:48 TheWiredGateway pop3proxy[13748]: Client iii logged out (account=0, deleted=0)