Bug #115726 for Mail-IMAPClient: "Use of uninitialized value in hash element" in fetch

Wed Jun 29 08:47:23 2016 mss [...] apache.org - Ticket created

Subject:

"Use of uninitialized value in hash element" in fetch_hash()

While checking the logs of an imapsync migration, I noticed an "Use of uninitialized value in hash element" every now and then. For example: Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: 13/29 [INBOX] -> [INBOX] Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: cache directory: /srv/imapsync/zmimapsync/spool/user@example.com/imapsync_cache/mail.example.com/user@example.com/z mmbx2.example.com/user@example.com/INBOX/INBOX Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: CACHE h1 h2: 9939 files Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: Use of uninitialized value in hash element at /usr/share/perl5/vendor_perl/Mail/IMAPClient.pm line 2245. Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: Use of uninitialized value in hash element at /usr/share/perl5/vendor_perl/Mail/IMAPClient.pm line 2245. Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: Use of uninitialized value in hash element at /usr/share/perl5/vendor_perl/Mail/IMAPClient.pm line 2245. Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: Use of uninitialized value in hash element at /usr/share/perl5/vendor_perl/Mail/IMAPClient.pm line 2245. Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: Use of uninitialized value in hash element at /usr/share/perl5/vendor_perl/Mail/IMAPClient.pm line 2245. Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: Use of uninitialized value in hash element at /usr/share/perl5/vendor_perl/Mail/IMAPClient.pm line 2245. Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: msg INBOX/387988 {44866} copied to INBOX/25523 0.04 msgs/s 1.519 KiB/s 2.729 MiB copied Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: msg INBOX/387989 {106653} copied to INBOX/25524 0.04 msgs/s 1.576 KiB/s 2.836 MiB copied Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: msg INBOX/387990 {17007} copied to INBOX/25525 0.04 msgs/s 1.591 KiB/s 2.863 MiB copied Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: msg INBOX/387992 {20508} copied to INBOX/25526 0.04 msgs/s 1.609 KiB/s 2.895 MiB copied Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: msg INBOX/387993 {50132} copied to INBOX/25527 0.04 msgs/s 1.635 KiB/s 2.949 MiB copied Jun 29 13:39:08 zmsync zmimapsync/user@example.com[19803]: msg INBOX/387994 {23833} copied to INBOX/25528 0.04 msgs/s 1.652 KiB/s 2.982 MiB copied The affected code is in fetch_hash: # NOTE: old code tried to remove any "unrequested" data in $entry # - UID is sometimes not explicitly requested, are there others? if ( $self->Uid ) { $uids->{ $entry->{UID} } = $entry; # <-- delete $entry->{UID} unless $asked_for_uid; } else { $uids->{$mid} = $entry; } So somehow every now and then $entry->{UID} is undef. Which should be impossible unless the magic regexp above fails. This is a migration from Exchange 2013 so maybe that one is misbehaving. I'll see if I can trigger the issue on a debug run but that's all I have right now.

Wed Jun 29 10:39:03 2016 mss [...] apache.org - Correspondence added

From:

mss [...] apache.org

I am able to reproduce the issue and ran imapsync with debugimap. Attached you can find the, I hope, relevant lines from the output.

Subject:

imapsync-115726.out

Download imapsync-115726.out
application/octet-stream 789.1k

Message body not shown because it is not plain text.

Wed Jun 29 12:22:16 2016 PLOBBES [...] cpan.org - Correspondence added

On Wed Jun 29 10:39:03 2016, mss@apache.org wrote: Show quoted text

> I am able to reproduce the issue and ran imapsync with debugimap. > Attached you can find the, I hope, relevant lines from the output.

Hi Malte, We send the request: Sending: 231 UID FETCH 235649,235652,235654,235659:235662,235665:235666,235669:235671,235673:235674,235720,235726:235727,235740,235742,235745,235750:235751,235755:235756,235760:235761,235763,235765,235770:235778,235783:235786,235790:235792,235800:235801,235804,235806,2358 09:235810,235812:235813,235815:235816,235823:235824,235828:235845,235847:235849,235851,235861,235863:235873,235878:235879,235881:235887,235894,235896:235897,235914,235919:235920,235922:235924,235927:235931,235933,235937,235945,235947,235952,235954:235957,235959:235961,235 966,235968:235969,235971:235972,235974:235987,236000,236005,236010:236012,236016,236018:236026,236028:236032,236040:236045,236047,236056,236059,236062,236072,236075:236086,236089:236094,236097:236100,236102:236103,236128:236130,236134,236136:236137,236139:236141,236146:23 6147,236149:236150,236152,236182,236226,236233,236244:236246,236249:236251,236253:236256,236258:236260,236262,236264:236280,236283:236284,236286:236289 (FLAGS INTERNALDATE RFC822.SIZE) Sent 993 bytes And the response comes back mostly as expected (by the code) with perhaps that the exception that we also get this as part of the response: Read: * 5629 FETCH (FLAGS (\Seen)) 231 OK FETCH completed. Now, I expect that all that happened here is that while the sync was occurring, the mailbox was being accessed by a client and that client made an update (read a message). We just happened to get an extra unsolicited (untagged) piece of info in that response to our FETCH. In theory that's a valid thing for the server to do. I'll probably just need to do a minor change to handle it (making sure we find a UID in responses, before trying to use the data in the response as if it was part of our FETCH data). If you disagree with what I'm saying or think I'm missing something, let me know! Phil

Wed Jun 29 12:22:17 2016 The RT System itself - Status changed from 'new' to 'open'

Wed Jun 29 12:22:22 2016 PLOBBES [...] cpan.org - Taken

Wed Jun 29 14:29:30 2016 mss [...] apache.org - Correspondence added

From:

mss [...] apache.org

Hi Phil, On Wed Jun 29 12:22:16 2016, PLOBBES wrote: Show quoted text

>[...] > And the response comes back mostly as expected (by the code) with > perhaps that the exception that we also get this as part of the > response: > > Read: * 5629 FETCH (FLAGS (\Seen)) > 231 OK FETCH completed. > > Now, I expect that all that happened here is that while the sync was > occurring, the mailbox was being accessed by a client and that client > made an update (read a message). We just happened to get an extra > unsolicited (untagged) piece of info in that response to our FETCH. > In theory that's a valid thing for the server to do. I'll probably > just need to do a minor change to handle it (making sure we find a UID > in responses, before trying to use the data in the response as if it > was part of our FETCH data). > > If you disagree with what I'm saying or think I'm missing something, > let me know!

That's probably what is happening here. I thought that the response to an UID FETCH always has to include the UID attribute but whatever Exchange does here has to be handled :-) The solution sounds right, too. Cheers, Malte

Thu Feb 02 19:56:05 2017 PLOBBES [...] cpan.org - Correspondence added

The following commit (for the next release) hopefully addresses the issue you ran into a while back: https://github.com/plobbes/mail-imapclient/commit/6b5374c0f69e9f438da3edcd44b78a240a28150a Thanks for taking the time to report this!

Thu Feb 02 19:56:06 2017 PLOBBES [...] cpan.org - Status changed from 'open' to 'patched'

Fri Feb 03 13:50:50 2017 PLOBBES [...] cpan.org - Fixed in 3.39 added

Fri Feb 03 13:50:50 2017 PLOBBES [...] cpan.org - Correspondence added

Closing as fixed as 3.39 is released.

Fri Feb 03 13:50:56 2017 PLOBBES [...] cpan.org - Status changed from 'patched' to 'resolved'

Bug #115726 for Mail-IMAPClient: "Use of uninitialized value in hash element" in fetch_hash()