Help → POPfile stopped processing emails

POPfile stopped processing emails

I'm running two popfile installations, one on a Linux machine (NAS with Debian Etch) and one on a Windows Server 2012. The latter is processing an email accounbt on an Exchange Server (via the IMAP) and the Linux machine is processing an ordinary IMAP account.

So far things were running quite ok, but today both installations apparently stopped processing emails. I say apparently because I'm not sure what they are doing. They did not produce any error message in the log. The only reason I notice that they stopped doing what they were supposed to do is that I found emails in my inbox that weren't supposed to be there.

Here are the last few log entries from the Windows machine (logger level 0):

2014/9/17 14:05:39 2684: bayes: 540: Reclassification from news to cfp
2014/9/17 14:05:39 2684: history: 411: Change slot classification of 213 to cfp
2014/9/17 14:05:39 2684: imap: 765: Reclassified the message with UID 477 from bucket news to bucket cfp.
2014/9/17 17:35:46 2684: bayes: 540: Reclassification from later to inbox
2014/9/17 17:35:46 2684: history: 411: Change slot classification of 215 to inbox
2014/9/17 17:35:46 2684: bayes: 540: Reclassification from later to inbox
2014/9/17 17:35:46 2684: history: 411: Change slot classification of 214 to inbox
2014/9/17 17:35:46 2684: bayes: 540: Reclassification from later to inbox
2014/9/17 17:35:46 2684: history: 411: Change slot classification of 222 to inbox

And here the ones from the Linux machine (logger level 0):

2014/9/17 17:20:17 17894: bayes: 540: Reclassification from inbox to news
2014/9/17 17:20:17 17894: history: 411: Change slot classification of 112 to news
2014/9/17 17:20:17 17894: imap: 765: Reclassified the message with UID 2716 from bucket inbox to bucket news.
2014/9/17 17:36:30 17894: html: 333: HTTP error 404 returned
2014/9/17 17:40:37 17894: bayes: 540: Reclassification from inbox to news
2014/9/17 17:40:37 17894: history: 411: Change slot classification of 102 to news
2014/9/17 17:40:37 17894: bayes: 540: Reclassification from news to inbox
2014/9/17 17:40:37 17894: history: 411: Change slot classification of 100 to inbox
2014/9/17 17:40:37 17894: bayes: 540: Reclassification from news to inbox
2014/9/17 17:40:37 17894: history: 411: Change slot classification of 110 to inbox
2014/9/17 17:53:00 17894: imap: 700: Message was classified as news.
2014/9/17 17:53:00 17894: imap: 544: Found duplicate hash value: 8f136096eab468e6843e252a0a5f9179. Ignoring duplicate in folder +SaneNews.

It's now past 22:00 so there hasn't been any logged activity for more than four hours even though several emails arrived during that time (in both mail accounts).

I've now turned up the logger level to two but so far I haven't seen any additional information on the logs.

Any help to resolve this problem would be greatly appreciated.

  • Message #1951

    I'm still struggling with this, at least on the Windows machine. I have monitored the log for a while now, and from what I can tell, the problem is that POPFile is not seeing new mails coming in:

    This is an excerpt from the log (early this morning):

    2014/9/26 04:16:12 2684: imap: 504: Looking for new messages in folder INBOX.
    2014/9/26 04:16:12 2684: IMAP-Client: 334: << A152690 NOOP[0d][0a]
    2014/9/26 04:16:12 2684: IMAP-Client: 427: >> A152690 OK NOOP completed.[0d][0a]
    2014/9/26 04:16:12 2684: IMAP-Client: 334: << A152691 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
    2014/9/26 04:16:12 2684: IMAP-Client: 439: >> * STATUS INBOX (UIDNEXT 58751 UIDVALIDITY 4620) [0d][0a]
    2014/9/26 04:16:12 2684: IMAP-Client: 427: >> A152691 OK STATUS completed.[0d][0a]
    

    And this is one from a moment ago:

    2014/9/26 13:34:48 2684: imap: 504: Looking for new messages in folder INBOX.
    2014/9/26 13:34:48 2684: IMAP-Client: 334: << A172790 NOOP[0d][0a]
    2014/9/26 13:34:48 2684: IMAP-Client: 427: >> A172790 OK NOOP completed.[0d][0a]
    2014/9/26 13:34:48 2684: IMAP-Client: 334: << A172791 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
    2014/9/26 13:34:48 2684: IMAP-Client: 439: >> * STATUS INBOX (UIDNEXT 58751 UIDVALIDITY 4620) [0d][0a]
    2014/9/26 13:34:48 2684: IMAP-Client: 427: >> A172791 OK STATUS completed.[0d][0a]
    

    As we can see, the UIDNEXT has remained the same for hours, although several emails have arrived in that period.

    If I understand things correctly, this means that the problem is not with POPFile but with the mailserver, right? i.e. the mailserver is not returning a new UIDNEXT when even though it has received new mail.

    Since it is an Microsoft Exchange Server 2010 that we're dealing with here, I would not be surprised. It would not the first time that it has problems handling IMAP properly... :-(

    However, the thing is that at some unforeseable moments, the server does seem to produce a new UIDNEXT because emails do get processed sometimes. My current does not go back far enough to show a record of the last processed email (which was more than 24 hours ago), so I can't analyze what might have triggered that event (i.e. the correct processing). But I'll have a look once the congestion is released again.

    Hold on... (I'm typing this as I'm trying out stuff) ... I thing I figured out what triggers the processing of new mails: it's when I manually move an email into one of the buckets (doesn't work if I move it to any other folder (i.e. one that is not monitored by popfile). Once I move a message into one of the bucket-folders, Popfile does get an Updated UIDNEXT value for folder XYZ and processes the message. However, it concludes that Message is unknown and cannot be reclassified. and ignores the message. Which confirms that popfile was not able to see the message when it was still in the inbox.

    If my (amateurish) analysis is correct, what should I do? If not, what's wrong?

    • Message #1952

      OK, just a quick update with some additional information: I noticed that after popfile processed all the new mails that had arrived since yesterday morning (triggered by me moving an email manually, see previous post), popfile continued to process incoming mail correctly. And the reason for that seems to be that it does received new UIDNEXT values from the server.

      So what I don't understand is: why does moving a message from the inbox to a bucket folder cause the server to update the UIDNEXT value for the inbox but not when the message is moved to another folder (i.e. one not monitored by popfile)?

      Does it perhaps matter that the bucket folders are sub-folders within the inbox folder while the non-monitored folders are outside the inbox folder? Seems unlikely to me. Another possible (the only?) explanation might be that it is not the manual moving of a message that brings the server's UIDNEXT values back on track, but the subsequent processing of messages through popfile. But what exactly would that mean?

    • Message #2145

      I seem to have exactly the same problem, has a solution for this been found ?

      My company just switched to an Exchange server (Microsoft Exchange Server 2013 IMAP4). I managed to update the SSL definitions and got Popfile connected. However it will only classify the emails that had not been classified since the last run, but then on subsequent checks will not receive the information from the server that new mails has arrived. I have set the logging to 1 and here on example :

      2016/9/15 10:45:41 1500: imap: 504: Looking for new messages in folder INBOX.
      2016/9/15 10:45:41 1500: IMAP-Client: 340: << A00455 NOOP[0d][0a]
      2016/9/15 10:45:41 1500: IMAP-Client: 433: >> A00455 OK NOOP completed.[0d][0a]
      2016/9/15 10:45:41 1500: IMAP-Client: 340: << A00456 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
      2016/9/15 10:45:41 1500: IMAP-Client: 445: >> * STATUS INBOX (UIDNEXT 753 UIDVALIDITY 14) [0d][0a]
      2016/9/15 10:45:41 1500: IMAP-Client: 433: >> A00456 OK STATUS completed.[0d][0a]

      and I know that just before that new mail had arrived, so should have been picked up.
      When I shutdown and then restart, the unclassified emails are again picked up and classified.

      Probably some problem with the exchange server ?

      Any help would be welcome, I would really miss Popfile.

      Cheers
      Oliver

      • Message #2146

        I don't know much about the IMAP module.

        I think it might be worth setting the logger_level to 2 to see if this provides any more information about the responses from the IMAP server.

        Here is an example of the difference between logger_level 1 and 2 when POPFile checks the mailbox status on a POP3 server:

        logger_level 1

        pop3: 311: STAT[0d][0a]
        pop3: 311: +OK 0 0[0d][0a]
        pop3: 311: QUIT[0d][0a]
        pop3: 311: +OK[0d][0a]
        pop3: 682: POP3 proxy done
        

        logger_level 2

        pop3: 213: Command: --STAT--
        pop3: 311: STAT[0d][0a]
        pop3: 659: Read slurp data +OK 0 0[0d][0a]
        pop3: 311: +OK 0 0[0d][0a]
        pop3: 213: Command: --QUIT--
        pop3: 311: QUIT[0d][0a]
        pop3: 659: Read slurp data +OK[0d][0a]
        pop3: 311: +OK[0d][0a]
        mq: 380: post CMPLT (-3088)
        mq: 395: sending post CMPLT (-3088) to parent GLOB(0x4084c20)
        pop3: 682: POP3 proxy done
        

        Brian

        • Message #2147

          Thanks for the tip. I have set logging level to 2.

          Popfile stopped at 10:42 showing the arrival of new emails in the History tab
          Popfile is configured to update very 300 seconds.

          a new email arrived in my inbox at 11:09

          I'm copying below the Popfile updates for the INBOX at 11:04, 11:06, 11:11 & 11:16. They are all the same and even if I don't quite understand the messages, it seems that no new email was picked up ...
          Anybody any ideas on this ? Or ideas of what I could test to get better infos ?

          2016/9/16 11:04:04 6112: imap: 504: Looking for new messages in folder INBOX.
          2016/9/16 11:04:04 6112: IMAP-Client: 340: << A00357 NOOP[0d][0a]
          2016/9/16 11:04:04 6112: IMAP-Client: 659: Read slurp data A00357 OK NOOP completed.[0d][0a]
          2016/9/16 11:04:04 6112: IMAP-Client: 433: >> A00357 OK NOOP completed.[0d][0a]
          2016/9/16 11:04:04 6112: IMAP-Client: 340: << A00358 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
          2016/9/16 11:04:04 6112: IMAP-Client: 659: Read slurp data * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]A00358 OK STATUS completed.[0d][0a]
          2016/9/16 11:04:04 6112: IMAP-Client: 445: >> * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]
          2016/9/16 11:04:04 6112: IMAP-Client: 433: >> A00358 OK STATUS completed.[0d][0a]
          
          
          2016/9/16 11:06:04 6112: imap: 504: Looking for new messages in folder INBOX.
          2016/9/16 11:06:04 6112: IMAP-Client: 340: << A00365 NOOP[0d][0a]
          2016/9/16 11:06:04 6112: IMAP-Client: 659: Read slurp data A00365 OK NOOP completed.[0d][0a]
          2016/9/16 11:06:04 6112: IMAP-Client: 433: >> A00365 OK NOOP completed.[0d][0a]
          2016/9/16 11:06:04 6112: IMAP-Client: 340: << A00366 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
          2016/9/16 11:06:04 6112: IMAP-Client: 659: Read slurp data * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]A00366 OK STATUS completed.[0d][0a]
          2016/9/16 11:06:04 6112: IMAP-Client: 445: >> * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]
          2016/9/16 11:06:04 6112: IMAP-Client: 433: >> A00366 OK STATUS completed.[0d][0a]
          
          
          2016/9/16 11:11:04 6112: imap: 504: Looking for new messages in folder INBOX.
          2016/9/16 11:11:04 6112: IMAP-Client: 340: << A00373 NOOP[0d][0a]
          2016/9/16 11:11:04 6112: IMAP-Client: 659: Read slurp data A00373 OK NOOP completed.[0d][0a]
          2016/9/16 11:11:04 6112: IMAP-Client: 433: >> A00373 OK NOOP completed.[0d][0a]
          2016/9/16 11:11:04 6112: IMAP-Client: 340: << A00374 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
          2016/9/16 11:11:04 6112: IMAP-Client: 659: Read slurp data * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]A00374 OK STATUS completed.[0d][0a]
          2016/9/16 11:11:04 6112: IMAP-Client: 445: >> * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]
          2016/9/16 11:11:04 6112: IMAP-Client: 433: >> A00374 OK STATUS completed.[0d][0a]
          
          2016/9/16 11:16:04 6112: imap: 504: Looking for new messages in folder INBOX.
          2016/9/16 11:16:04 6112: IMAP-Client: 340: << A00381 NOOP[0d][0a]
          2016/9/16 11:16:04 6112: IMAP-Client: 659: Read slurp data A00381 OK NOOP completed.[0d][0a]
          2016/9/16 11:16:04 6112: IMAP-Client: 433: >> A00381 OK NOOP completed.[0d][0a]
          2016/9/16 11:16:04 6112: IMAP-Client: 340: << A00382 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
          2016/9/16 11:16:04 6112: IMAP-Client: 659: Read slurp data * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]A00382 OK STATUS completed.[0d][0a]
          2016/9/16 11:16:04 6112: IMAP-Client: 445: >> * STATUS INBOX (UIDNEXT 827 UIDVALIDITY 14) [0d][0a]
          2016/9/16 11:16:04 6112: IMAP-Client: 433: >> A00382 OK STATUS completed.[0d][0a]
          
          
          • Message #2148

            actually it seems that there is a whole bit of message missing : I have copied below the INBOX check from 10:36 : Popfile was still working correctly then : the first 8 lines are exactly the same as later on (I have marked them with a "*" ). However here are an additional 17 lines of messages, whihc include the lines "0 RECENT" and "292 EXISTS". 292 is the number of emails I have in my inbox. So it seems that the commands "SELECT "INBOX"" and then "Read slurp data * 292 EXISTS[0d][0a]* 0 RECENT[0d][0a]* FLAGS" do not work anymore.
            Actually I found that at the time when the last email was shown, a "1 RECENT" exists in the messages, but in the message block for "INBOX/Pourriel", which is a second watched folder, but which has basically never any messages in it.
            Since the switch to MS Exchange, all my bucket folders are at the second level, below the INBOX (Exchange supports folders in folders). Popfile did pick these up correctly, but perhaps the problem is somewhere in there ?
            I will delete the second watched folder and see if this changes anything.

            2016/9/16 10:36:03 6112:* imap: 504: Looking for new messages in folder INBOX.
            2016/9/16 10:36:03 6112:* IMAP-Client: 340: << A00234 NOOP[0d][0a]
            2016/9/16 10:36:03 6112:* IMAP-Client: 659: Read slurp data A00234 OK NOOP completed.[0d][0a]
            2016/9/16 10:36:03 6112:* IMAP-Client: 433: >> A00234 OK NOOP completed.[0d][0a]
            2016/9/16 10:36:03 6112:* IMAP-Client: 340: << A00235 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]
            2016/9/16 10:36:03 6112:* IMAP-Client: 659: Read slurp data * STATUS INBOX (UIDNEXT 826 UIDVALIDITY 14) [0d][0a]A00235 OK STATUS completed.[0d][0a]
            2016/9/16 10:36:03 6112:* IMAP-Client: 445: >> * STATUS INBOX (UIDNEXT 826 UIDVALIDITY 14) [0d][0a]
            2016/9/16 10:36:03 6112:* IMAP-Client: 433: >> A00235 OK STATUS completed.[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 340: << A00236 SELECT "INBOX"[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 659: Read slurp data * 292 EXISTS[0d][0a]* 0 RECENT[0d][0a]* FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)[0d][0a]* OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * 292 EXISTS[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * 0 RECENT[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 659: Read slurp data  Permanent flags[0d][0a]* OK [UNSEEN 1] Is the first unseen message[0d][0a]* OK [UIDVALIDITY 14] UIDVALIDITY value[0d][0a]* OK [UIDNEXT 826] The next unique identifier value[0d][0a]A00
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * OK [UNSEEN 1] Is the first unseen message[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * OK [UIDVALIDITY 14] UIDVALIDITY value[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * OK [UIDNEXT 826] The next unique identifier value[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 659: Read slurp data 236 OK [READ-WRITE] SELECT completed.[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 433: >> A00236 OK [READ-WRITE] SELECT completed.[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 662: Getting uids ge 825 in folder INBOX
            2016/9/16 10:36:03 6112: IMAP-Client: 340: << A00237 UID SEARCH UID 825:* UNDELETED[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 659: Read slurp data * SEARCH[0d][0a]A00237 OK SEARCH completed.[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 445: >> * SEARCH[0d][0a]
            2016/9/16 10:36:03 6112: IMAP-Client: 433: >> A00237 OK SEARCH completed.[0d][0a]
            
            • Message #2152

              I have removed the second watched folder and this has nothing changed : basically Popfile is just able to see the recent mails in the new mail folder (that is the ones that have not been classified yet) and from then on seems to not get the information from the exchange server that new mail has arrived.
              If have troubles interpreting the logging messages. If anybody can help me with that, and get some arguments what might be wrong (e.g. with the installatino fo the IMAP service of exchange), I could look further on forums with exchange specialists.
              Thanks in advance for any help

              Otherwise, a button "restart Popfile" could be a good workaraound ;-)

              Cheers

              Oliver

              • Message #2153

                Seemingly, it seems to be the following line that should look like this :

                5780: IMAP-Client: 659: Read slurp data * 1 RECENT[0d][0a]* 105 EXISTS[0d][0a]A00061 OK NOOP completed.[0d][0a]

                when an email arrives, and which looks like this :

                5780: IMAP-Client: 659: Read slurp data A00124 OK NOOP completed.[0d][0a]

                when an email has arrived, but it is not working.
                Is there anybody here with enough knowledge of IMAP servers to tell me what goes wrong here ?

                Thanks in advance

                Oliver

                • Message #2161

                  PopFile? seems to be working again properly !!! Seemingly no connection problems any more !!!

                  How did I do that ?

                  I stopped using Pmail to connect using the IMAP protocol to the Exchange server.
                  So it's seems that Pmail is messing something up at the server-side (I'm not a specialist, so semantic might be wrong here ;-), and then when PopFile? is connecting, it won't get the information that new mail has arrived ...

                  I'm sorry to have to let go Pmail, but I'm quite happy that PopFile? is still working fine

                  Cheers
                  Oliver

                  • Message #2163

                    no, finally not Pmails fault : it did work perfectly all day yesterday, doesn't today ...