Ticket #52 (assigned defect)

Opened 4 months ago

Last modified 3 weeks ago

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

Reported by: blueyed Assigned to: manni (accepted)
Priority: normal Milestone:
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.