Skip Menu |

This queue is for tickets about the Mail-IMAPClient CPAN distribution.

Report information
The Basics
Id: 53990
Status: rejected
Priority: 0/
Queue: Mail-IMAPClient

People
Owner: PLOBBES [...] cpan.org
Requestors: MARKLE [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: Normal
Broken in: 3.22
Fixed in: (no value)



Subject: connection closes while waiting for folder lock
Hi. I seem to have found a problem. Using dovecot 1.2.9 on CentOS 5.3 with Perl 5.8.8. I run `lockfile -ml` and then access my mail via IMAP with Thunderbird (Icedove). It sits there waiting while accessing the mail. When I run `lockfile -mu` on the server, Thunderbird continues fine and downloads the messages on the same connection. So, I do not think this is a problem with dovecot 1.2.9, though it might be, I will ask on the list. With Mail::IMAPClient, the same process fails. message_string() returns undef. body_string() completely borks. This used to work in my more complicated test scripts. So I don't know, maybe it is something that changed in dovecot or the dovecot options, but I'm having trouble figuring out what. Perl in CentOS often behaves strangely. I wrote a test script to demonstrate this, attached, as well as debug info. The test script only works in unix/linux with an imap server set to respect dotlock files. Does it happen for you? Thanks! --mark--
Subject: mail_imapclient_bug.t
#!/usr/bin/perl # this test demonstrates a bug in Mail::IMAPClient without use of any DeSpam modules use strict; use warnings FATAL => 'all'; use English '-no_match_vars'; use FindBin; my $imap_logfile = "/tmp/imap_debug.$FindBin::Script.log"; use Test::More; use YAML; use IO::File; #exit(0); $ENV{PATH} = '/sbin:/usr/sbin:/bin:/usr/bin'; use Mail::Sendmail; use Mail::IMAPClient; use User::pwent; use File::Slurp; use Term::ReadLine; use POSIX; #plan skip_all => 'Unimplemented'; plan tests => 6; my $pw = getpwuid($REAL_USER_ID); my $username = $pw->name; verify_continue(); my $inbox_file = "/var/spool/mail/$username"; diag("inbox: $inbox_file"); clear_mailbox($inbox_file); use Mail::Sendmail; sendmail( To => "$username\@localhost", From => "$username\@localhost", Subject => "test message", Message => "foobar\n", ) || die "cannot send test mail: $Mail::Sendmail::error\n"; do { diag("sleeping for delivery..."); sleep 2 } until -s $inbox_file; my $inbox = read_file($inbox_file) || die "could not read test mail: $OS_ERROR\n"; #diag($inbox); # here's how we check if the message is right: my $patmatch = qr{ ^ Subject: \s+ test \s+ message \r?\n .* ^ foobar \r?\n }mxs; ok( $inbox =~ $patmatch, 'test message arrived' ); # get imap connection, try to connect while inbox is not locked my $imap = get_mail_imapclient($username); # can we read the mail? $imap->select('INBOX'); my @msg_uids = $imap->messages(); diag("message uids in box: \n".Dump(\@msg_uids)); my $try_1 = $imap->message_string($msg_uids[0]); ok( $try_1 =~ $patmatch, 'try 1 matches message' ); $imap->close; $imap->logout; undef $imap; # lock inbox system("lockfile -ml") == 0 || die "cannot `lockfile -ml`: $OS_ERROR\n"; ok(-e "$inbox_file.lock", 'lockfile present after `lockfile -ml`'); # install a sig handler to remove it nicely if we bail: install_handler(); # while inbox is locked, try connection, setting alarm to remove lockfile. local $SIG{ALRM} = sub { system("lockfile -mu") == 0 || die "cannot `lockfile -mu`: $OS_ERROR\n"; ok(!-e "$inbox_file.lock", 'alarmsub lock gone after `lockfile -mu`'); }; diag("setting alarm to remove lockfile in 4 seconds..."); alarm 4; # get imap connection, try to connect while inbox is locked $imap = get_mail_imapclient($username); # can we read the mail? $imap->select('INBOX'); @msg_uids = $imap->messages(); diag("message uids in box: \n".Dump(\@msg_uids)); diag("when alarm is triggered, read should continue here."); diag("it does not, message_string is undefined and body_string causes error."); my $try_2 = $imap->message_string($msg_uids[0]); ok( $try_2 && $try_2 =~ $patmatch, 'try 2 matches message' ); my $body_try = $imap->body_string($msg_uids[0]); ok( $body_try && $body_try =~ m{ foobar }mxs, 'get something from body_string too' ); $imap->close; $imap->logout; undef $imap; exit(0); ##################### sub get_mail_imapclient { my ($username) = @_; diag("opening $imap_logfile"); my $imap = Mail::IMAPClient->new( Server => 'localhost', User => $username, Password => get_password(), Uid => 1, Debug => 1, Timeout => 60, Debug_fh => IO::File->new(">>$imap_logfile") || die "cannot open $imap_logfile: $OS_ERROR", ); return $imap; } my $password; sub get_password { my $term = Term::ReadLine->new($PROGRAM_NAME); my $attribs = $term->Attribs; $attribs->{redisplay_function} = $attribs->{shadow_redisplay}; ENTER_PASS: while (1) { last ENTER_PASS if $password; print "Enter password for this account:\n"; chomp( $password = $term->readline("password > ") ); } return $password; } sub verify_continue { print "# this will completely erase your account's mail. continue? [y/N] "; chomp(my $answ = <STDIN>); exit if !$answ || lc $answ ne 'y'; print "# no really, it will clear the inbox for user '$username' on this system.\n"; print "# continue? [y/N] "; chomp(my $answ2 = <STDIN>); exit if !$answ2 || lc $answ2 ne 'y'; return; } # install the sig handler AFTER getting the lock file sub unlock { my $signame = shift; warn "caught signal SIG$signame, exiting...\n" if $signame; system("lockfile -mu") == 0 || die "cannot `lockfile -mu`: $OS_ERROR\n"; } sub install_handler { my $sigset = POSIX::SigSet->new(); my $action = POSIX::SigAction->new( 'unlock', $sigset, &POSIX::SA_NODEFER, ); POSIX::sigaction($_, $action) for # see `man 7 signal` &POSIX::SIGHUP, # kill -1 &POSIX::SIGINT, # types ctl-c &POSIX::SIGQUIT, # types something (??) &POSIX::SIGKILL, # doesn't trap this one (-9) or output is lost &POSIX::SIGABRT, # (??) &POSIX::SIGPIPE, # broken pipe - bad rsync ipc? &POSIX::SIGTERM, # regular kill (-15) ; } sub clear_mailbox { my ($file) = @_; open my $fh, '>', $file || die "cannot clear $file: $OS_ERROR\n"; close $file; }
Subject: imap_debug.mail_imapclient_bug.t.log

Message body is not shown because it is too large.

son of a ... I guess I'll be changing my password. Mark
Looking at the log, I would argue this is a bug with the test program. It appears that a FETCH is attempted by the call to message_string in line 96 of mail_imapclient_bug.t: Sending: 5 UID FETCH 11 BODY[] Sent 23 bytes But that operation times out after 60 seconds (the Timeout value you specified). Resulting in the following error: ERROR: error waiting 60s for data from server: No such file or directory The test case code ignores the fact that an error has occurred and continues to try and do things with the IMAP connection that is no longer in a good state. Resulting in another error because of a call to body_string at line 98 of mail_imapclient_bug.t: ERROR: Error sending '6 UID FETCH 11 BODY[TEXT]': NO not connected That cycle continues until the end of the test is reached. If it worked before, it was perhaps because you were using an old version of the library that failed to honor Timeout. In 3.17(_01) we had these related changes (fix): - _read_more() improperly initialized vector causing select errors, thus timeouts were not working properly (now they work...) - *change default timeout 30s => 600s: 30s seems too short in practice I believe if you just use Timeout => 0 then you'll block until the lock is freed or some other error condition occurs. You could also use a large enough timeout that lets you avoid this as well but either way you will want to start checking for error conditions and handling them appropriately. I'll close this bug as rejected, but if you feel that I'm missing something please feel free to reopen and let me know.
On Mon Jan 25 23:21:22 2010, PLOBBES wrote: Show quoted text
> I'll close this bug as rejected, but if you feel that I'm missing > something please feel free to reopen and let me know.
Try running the script in a test account. While the file is locked with `lockfile -ml`, $imap connects, selects INBOX, and calls $imap->message_string() without any delay, and then hangs in that function. It only hangs for 4 seconds, the time set for the alarm. When the alarm goes off after 4 seconds, then the lockfile is removed and message_string() returns undef without error. If you omit message_string() and use body_string() instead, the same timing happens - body_string() call succeeds, hangs 4 seconds, the alarm removes the lockfile, but then it spits up that stack trace. So it seems like something else is wrong... it does not wait Timeout seconds. The comparison is to try the same thing manually with Thunderbird using IMAP - it opens the connection, and the progress bar sits there waiting, then you remove the lock on the server after waiting 5 seconds or so, and Thunderbird immediately continues from that point and downloads the messages.
Subject: Re: [rt.cpan.org #53990] connection closes while waiting for folder lock
Date: Tue, 26 Jan 2010 17:18:41 -0500
To: bug-Mail-IMAPClient [...] rt.cpan.org
From: Phil Pearl (Lobbes) <phil [...] perkpartners.com>
Hi Mark, This test case you provided is horribly broken, please read on... Mark Hedges via RT <bug-Mail-IMAPClient@rt.cpan.org> wrote: Show quoted text
> Queue: Mail-IMAPClient > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=53990 > > > On Mon Jan 25 23:21:22 2010, PLOBBES wrote:
> > I'll close this bug as rejected, but if you feel that I'm missing > > something please feel free to reopen and let me know.
> > Try running the script in a test account. > > While the file is locked with `lockfile -ml`, $imap connects, selects > INBOX, and calls $imap->message_string() without any delay, and then > hangs in that function. > > It only hangs for 4 seconds, the time set for the alarm. When the alarm > goes off after 4 seconds, then the lockfile is removed and > message_string() returns undef without error. > > If you omit message_string() and use body_string() instead, the same > timing happens - body_string() call succeeds, hangs 4 seconds, the alarm > removes the lockfile, but then it spits up that stack trace. > > So it seems like something else is wrong... it does not wait Timeout > seconds. > > The comparison is to try the same thing manually with Thunderbird using > IMAP - it opens the connection, and the progress bar sits there waiting, > then you remove the lock on the server after waiting 5 seconds or so, > and Thunderbird immediately continues from that point and downloads the > messages.
This test case is horribly broken because the SIGALRM interrupts the ongoing system call inside Mail::IMAPClient (a select) thus the Timeout does not come into play. The SIGALRM handler also trashes $! there by making the ERROR: ... more interesting (No such file vs Interrupted system call). At the moment I am of the opinion that proper signal handling (and/or proper coding) in cases like this is the responsibility of the caller. Feel free to try and convince me otherwise, I'm all ears. The code also fails to do error handling as required by Mail::IMAPClient. Unfortunately the API is old and has some rough edges and the documentation is probably far too wordy, but the following section should be of particular interest: http://search.cpan.org/dist/Mail-IMAPClient/lib/Mail/IMAPClient.pod#OBJECT_METHODS Here's the highlight: As a general rule, mailbox control methods return undef on failure and something besides undef when they succeed. This rule is modified in the case of methods that return search results. When called in a list context, searches that do not find matching results return an empty list. When called in a scalar context, searches with no hits return 'undef' instead of an array reference. If you want to know why you received no hits, you should check "LastError" or $@, which will be empty if the search was successful but had no matching results but populated with an error message if the search encountered a problem (such as invalid parameters). This was probably an unfortunate design decision by one of my predecessors. The reason being is that when calling a number of methods in list context when you hit an error many times you'll get a list that looks like this: ( undef ) So when you get that, you need to check if the first element of the list is undef and if it is, an error likely occured that you will need to handle that appropriately. In general, I recommend using scalar instead of list context that way you'll get an undef on error or an arrayref on success (typically). Regardless, if you choose to not check LastError / $@ then all the safeguards in the world will not help you, so please start checking these. Attached is what I would consider a more valid (but still not great) test case which works fine with 3.22 -- and probably with 3.21 and I would guess it is valid all the way back to 3.17 or so. In the future, I would also suggest that you try to pare down your test cases to the absolute minimum to avoid these types of problems. Sincerely, Phil

Message body is not shown because sender requested not to inline it.

Show quoted text
> This test case is horribly broken because the SIGALRM interrupts the > ongoing system call inside Mail::IMAPClient (a select) thus the > Timeout > does not come into play. The SIGALRM handler also trashes $! there by > making the ERROR: ... more interesting (No such file vs Interrupted > system call). > > Attached is what I would consider a more valid (but still not great) > test case which works fine with 3.22 -- and probably with 3.21 and I > would guess it is valid all the way back to 3.17 or so.
You are awesome! Thank you! It is strange that it appeared to work before, but I guess it was not working. Spawning a background process to remove the lock works, of course. I guess I thought alarm() did something way more complicated like ran the subref in a thread or something... when my original test started working way back when, I assumed I was doing the right thing. So, thank you for fixing whatever bug was fixed along the line that used to make this work! --mark--