That's not QUITE the problem we're having but it's similar. When the attachments fail to attach in our scenario it looks like there wasn't even an attempt to add something. No zero-length files. No "attachment stripped" message. No nothing. I thought NFS may have been the problem so I unmounted it and just used the local file system to test on... same problem. And the annoying thing is that it happens only about 10% of the time so it's MUCH harder to diagnose.
So I went into the code and added a bunch of debug statements to see how Imp progresses through and constructs the message. Here's what I get: Message without any attachments: Nov 20 13:07:10 [EMAIL PROTECTED] HORDE[30381]: [imp] testuser attempting to send message. Adding 0 attachments [on line 302 of "/var/www/horde/ imp/compose.php"] Nov 20 13:07:10 [EMAIL PROTECTED] HORDE[30381]: [imp] Creating base MIME message for sending for testuser. [on line 328 of "/var/www/horde/imp/ compose.php"] Nov 20 13:07:10 [EMAIL PROTECTED] HORDE[30381]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 13:07:11 [EMAIL PROTECTED] HORDE[30381]: [imp] testuser sent message to [EMAIL PROTECTED] [on line 1141 of "/var/www/horde/imp/compose.php"] Message with attachment: Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] testuser attempting to send message. Adding 1 attachments [on line 302 of "/var/www/horde/ imp/compose.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] About to build mixed MIME part of message for testuser. [on line 310 of "/var/www/horde/imp/ compose.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] In buildAllAttachments for testuser. [on line 748 of "/var/www/horde/imp/lib/Compose.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] In buildAllAttachments for testuser - Filename for upload is munkie.jpg. [on line 759 of "/ var/www/horde/imp/lib/Compose.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] Creating base MIME message for sending for testuser. [on line 328 of "/var/www/horde/imp/ compose.php"] Nov 20 13:09:05 [EMAIL PROTECTED] HORDE[13673]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 13:09:06 [EMAIL PROTECTED] HORDE[13673]: [imp] testuser sent message to [EMAIL PROTECTED] [on line 1141 of "/var/www/horde/imp/compose.php"] Message that had an attachment but never gets attached: Nov 20 12:44:07 [EMAIL PROTECTED] HORDE[31693]: [imp] testuser attempting to send message. Adding 0 attachments [on line 302 of "/var/www/horde/imp/ compose.php"] Nov 20 12:44:07 [EMAIL PROTECTED] HORDE[31693]: [imp] Creating base MIME message for sending for testuser. [on line 327 of "/var/www/horde/imp/ compose.php"] Nov 20 12:44:07 [EMAIL PROTECTED] HORDE[31693]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 12:44:08 [EMAIL PROTECTED] HORDE[31693]: [imp] testuser sent message to [EMAIL PROTECTED] [on line 1140 of "/var/www/horde/imp/compose.php"] Nov 20 12:44:08 [EMAIL PROTECTED] HORDE[31693]: PHP Warning: array_values(): The argument should be an array in /var/www/horde/imp/lib/Compose.php on line 658 This case is almost identical to the message with no attachment with the exception of the warning. Turned out line 658 is in a function called "deleteAttachment". I looked a bit more at that, thinking that might be a clue... but adding more debug statements gives me this: (this is an example of another successful attach and send) Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] testuser attempting to send message. Adding 1 attachments [on line 302 of "/var/www/horde/ imp/compose.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] About to build mixed MIME part of message for testuser. [on line 310 of "/var/www/horde/imp/ compose.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] In buildAllAttachments for testuser. [on line 756 of "/var/www/horde/imp/lib/Compose.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] In buildAllAttachments for testuser - Filename for upload is 2006198979200376518_rs.jpg. [on line 767 of "/var/www/horde/imp/lib/Compose.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] Creating base MIME message for sending for testuser. [on line 328 of "/var/www/horde/imp/ compose.php"] Nov 20 15:35:40 [EMAIL PROTECTED] HORDE[3941]: [imp] In addPart for testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"] Nov 20 15:35:41 [EMAIL PROTECTED] HORDE[3941]: [imp] testuser sent message to webadmin <[EMAIL PROTECTED]> [on line 1155 of "/var/www/horde/imp/ compose.php"] Nov 20 15:35:41 [EMAIL PROTECTED] HORDE[3941]: [imp] testuser is in deleteAllAttachments for some reason. [on line 673 of "/var/www/horde/ imp/lib/Compose.php"] Nov 20 15:35:41 [EMAIL PROTECTED] HORDE[3941]: [imp] Now testuser is in deleteAttachment. [on line 627 of "/var/www/horde/imp/lib/Compose.php"] Given that the warning is after all of the above it suggests that it's basically a cleanup routine (though the 3000+ messages in my shared NFS volume suggests it's not cleaning up after itself properly...). So I'm totally at a loss as to where the problem could be. I'm hoping someone on the IMP team can at the very least point out where I can go in and add more debug statements to try and narrow this down. I'm getting worried since this is the busiest time of the year for Imp usage on our campus. The last thing we need is to be blamed when students try to email their assignments or whatever for their final marks and it doesn't attach. That's 50,000+ potentially pissed students. So hopefully with the help of the Imp team we can identify the problem quickly. On Nov 23, 2007, at 4:44 AM, Graeme Wood wrote: > I've also got a problem with some attachments not being uploaded and > then appearing as zero length when the messages are sent. It > doesn't make any difference whether it is a clustered service or > not, as we have both one service made up of multiple web front-ends > and one which is a single web front-end. I also am using just the > file system to store uploaded files, but there is no NFS. The > behaviour looks like either a failure in PHP to create the temporary > filename or a race condition which means that the filename isn't > there when the compose.php looks for it. We get errors logged in the > apache logs to say that the temporary file doesn't exist. > > I'm not sure when this problem first started occuring as we have > only in the last few months started getting reports about this. > > I'm running Horde 3.1.3, IMP 4.1.3 and PHP 4.4.7. > > On Thu, 22 Nov 2007, Kevin Konowalec wrote: > >> Horde 3.1.5 >> IMP 4.1.5 >> PHP 4.4.1 >> Clustered environment all sharing common NFS space for uploaded >> files. >> >> >> I was wondering if it was possible to separate the VFS DB from the >> regular SQL backend? We're trying to do some testing to see why >> attachments are randomly failing and want to be able to use the >> production database for preferences and address book but want to >> shift >> the VFS storage to a second non-production database box for test >> purposes. Is that doable? If so, how? >> >> We're trying to test if the problem we're having with attachments >> randomly not being sent (though having been successfully uploaded to >> the server) is related to not using VFS at all (simply storing the >> uploaded files on a shared NFS volume). >> >> >> > > -- > Graeme Wood, Unix Section of the IT Infrastructure Division, > Information Services, The University of Edinburgh > Email: [EMAIL PROTECTED] Phone: +44 131 650 5003 Fax: +44 131 650 > 6552 > > The University of Edinburgh is a charitable body, > registered in Scotland, with registration number SC005336. > -- IMP mailing list - Join the hunt: http://horde.org/bounties/#imp Frequently Asked Questions: http://horde.org/faq/ To unsubscribe, mail: [EMAIL PROTECTED]
