Ticket #52 (assigned defect)

Opened 4 years ago

Last modified 1 year ago

POPFile hanging in endless loop (after "NOOP failed"?)

Reported by: blueyed Assigned to: manni (accepted)
Priority: normal Milestone: 1.0.1
Component: IMAP Version: 0.22.4
Severity: critical Keywords:
Cc:

Description

I've just had POPFile hanging and using all available CPU.

When I've attached strace to the process, it showed only the following lines: 

write(6, "\27\3\1\0PuRT9\tR\36\216s\223\320\30\316\265<\222\324\3633\34\22\37\347\274#-b\23)\25\21Vf\31\330L1\360\21q?\262?x\227\3303Q\325\363\24o*\200\24\244\352\367\250\332lM\354V\306\31.\311\240\31\30\17\3069W\210\23\313\220.", 85) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---

The last log entry from POPFile is: 

2008/5/18 16:11:03 2531: IMAP-Client: 450: Got unsolicited BYE response from server while reading response for NOOP.
2008/5/18 16:11:03 2531: IMAP-Client: 484: !!! Server said something unexpected !!!
2008/5/18 16:11:03 2531: IMAP-Client: 227: NOOP failed (return value -2)

The call to noop appears to have been done in IMAP::scan_folder (Services/IMAP.pm): 

    # Do a NOOP first. Certain implementations won't tell us about
    # new messages while we are connected and selected otherwise:
    if ( ! $imap->noop() ) {
        # Now what?
    }

It seems like this code should return from the function in case of error.

This has happened with POPFile 1.0.1RC1.

Change History

05/19/08 02:03:53 changed by blueyed

The same thing happened again, when I've restarted Dovecot, apparently during the POPFile run. This is the log excerpt with log_level=2: 

[...]
2008/5/19 00:54:02 7253: imap: 501: Looking for new messages in folder XXX.
2008/5/19 00:54:02 7253: IMAP-Client: 333: << A01742 NOOP[0d][0a]
2008/5/19 00:54:02 7253: IMAP-Client: 658: Read slurp data A01742 OK NOOP completed.[0d][0a]
2008/5/19 00:54:02 7253: IMAP-Client: 426: >> A01742 OK NOOP completed.[0d][0a]
2008/5/19 00:54:02 7253: IMAP-Client: 333: << A01743 STATUS "XXX" (UIDNEXT UIDVALIDITY)[0d][0a]
2008/5/19 00:54:02 7253: IMAP-Client: 658: Read slurp data * STATUS "XXX" (UIDNEXT 5748 UIDVALIDITY 1184109158)[0d][0a]A01743 OK Status completed.[0d][0a]
2008/5/19 00:54:02 7253: IMAP-Client: 438: >> * STATUS "XXX" (UIDNEXT 5748 UIDVALIDITY 1184109158)[0d][0a]
2008/5/19 00:54:02 7253: IMAP-Client: 426: >> A01743 OK Status completed.[0d][0a]
2008/5/19 00:56:02 7253: imap: 501: Looking for new messages in folder YYY.
2008/5/19 00:56:02 7253: IMAP-Client: 333: << A01744 NOOP[0d][0a]
2008/5/19 00:56:02 7253: IMAP-Client: 658: Read slurp data * BYE Server shutting down.[0d][0a]
2008/5/19 00:56:02 7253: IMAP-Client: 438: >> * BYE Server shutting down.[0d][0a]
2008/5/19 00:56:02 7253: IMAP-Client: 450: Got unsolicited BYE response from server while reading response for NOOP.
2008/5/19 00:56:02 7253: IMAP-Client: 484: !!! Server said something unexpected !!!
2008/5/19 00:56:02 7253: IMAP-Client: 227: NOOP failed (return value -2)

08/15/08 08:43:36 changed by manni

  • status changed from new to assigned.

Seems like an error in the code for get_response in Client.pm.

Unsolicited BYE responses should trigger an exception. But I have to take a closer look.

05/17/09 17:23:29 changed by manni

  • milestone set to 1.0.1.

05/21/09 21:01:33 changed by junkmail

My Dovecot 1.0.5 popfile process just quits running every so often with the following log entry:

IMAP-Client: 451: Got unsolicited BYE response from server while reading response for NOOP. IMAP-Client: 485: !!! Server said something unexpected !!! IMAP-Client: 228: NOOP failed (return value -2) IMAP-Client: 985: Lost connection while I tried to say 'A00049 STATUS "INBOX" (UIDNEXT UIDVALIDITY)[0d][0a]'.

I'll be glad when this is resolved. Meanwhile, I suppose I can monitor it with a cron script and restart whenever it quits.

09/08/10 22:27:47 changed by stephenk

Is this a difficult ticket to fix? Here I am with popfile 1.1.1 and it the code still hasn't been changed!

Unlike junkmail above, I don't yet have the linux foo to monitor a log file and restart with this.

The strange thing is that I was on windows before with the same mail server (zimbra) and had no issues...