[horde] Attachments failing. Someone please advise.

Mon Nov 26 17:38:50 UTC 2007

Okay here's our setup:

20x horde machines:

	OpenBSD 4.1 (i386)
	Horde: 3.1.4
	Imp: H3 (4.1.4)
	Turba: H3 (2.1.4)
	PHP Version: 4.4.1

4x Session Machines:
	OpenBSD 4.1 (AMD64)
	memcached 1.1.12

Database:
	OpenBSD 4.1 (i386)
	MySQL 14.12 Distrib 5.0.33

Round Robin Clustering via PF and CARP

shared NFS volume for uploaded attachments.

So, as Babita mentioned before, we're getting a lot of attachment  
failures.  They just don't show up in the received message all,  
despite Imp saying everything worked fine when sending.  When you  
check the sent mail folder, sure enough there's no attachment (and it  
hasn't been "stripped" - there's no notice in the retained sent  
message).

Having traced through the code as best as I can I haven't been able to  
isolate exactly where it's failing.  So I'm not sure if it's a bug or  
if it's in a misconfiguration or setup problem.

We noticed that when we reboot the test machine, the problem went  
away.  We speculated that it might be some PEAR/PHP nonsense and it  
was actually the act of restarting apache that was solving the problem  
rather than the complete reboot.  We were wrong.  So, thinking that a  
reboot would at least be a bandaid solution to get us through end-of- 
semester we set up the horde machines to reboot once a week on  
saturday morning.  Unfortunately that turned out to be completely  
ineffective and we arrived this morning with 28 complaints about  
attachments.  We suspect that some of them saw the notice we put up  
about the issue and, having never looked in their sent mail folder  
before, saw that the attachments were getting stripped but not  
realizing that it's the default behavior.  But I'm sure some of them  
are seeing the same problem as before, where the attachments aren't  
stripped... they were never attached in the first place.  We're also  
not sure why the reboot seemed to fix the problem, though we  
collectively sent only about 60 or 80 messages while testing it the  
last time so it may not have been enough... however when it was  
failing regularly you could count on at least a 1 in 10 failure rate.

I have no idea what role the session handler has on attachments, but  
since we reboot the 4 memcached servers every monday morning I'm  
watching to see what happens (we haven't had any further complaints  
today yet).

Anyway... if any of the Imp developers or Horde team have any idea  
where we can look further to see why this is happening and stop it,  
I'd greatly appreciate it.  This is the worst possible time of year to  
have this happen, since students are relying on being able to submit  
homework, projects, and the like for final grading.  We need to get  
this fixed so the students will have a robust and reliable service and  
at this point I can't say that they do.

Kevin

On Nov 23, 2007, at 10:46 AM, Kevin Konowalec wrote:

> 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 src at twc1 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 src at twc1 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 src at twc1 HORDE[30381]: [imp] In addPart for  
> testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 13:07:11 src at twc1 HORDE[30381]: [imp] testuser sent message  
> to webadmin at ualberta.ca [on line 1141 of "/var/www/horde/imp/ 
> compose.php"]
>
>
> Message with attachment:
>
> Nov 20 13:09:05 src at twc1 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 src at twc1 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 src at twc1 HORDE[13673]: [imp] In addPart for  
> testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 13:09:05 src at twc1 HORDE[13673]: [imp] In buildAllAttachments  
> for testuser. [on line 748 of "/var/www/horde/imp/lib/Compose.php"]
> Nov 20 13:09:05 src at twc1 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 src at twc1 HORDE[13673]: [imp] In addPart for  
> testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 13:09:05 src at twc1 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 src at twc1 HORDE[13673]: [imp] In addPart for  
> testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 13:09:06 src at twc1 HORDE[13673]: [imp] testuser sent message  
> to webadmin at ualberta.ca [on line 1141 of "/var/www/horde/imp/ 
> compose.php"]
>
>
> Message that had an attachment but never gets attached:
>
> Nov 20 12:44:07 src at twc1 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 src at twc1 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 src at twc1 HORDE[31693]: [imp] In addPart for  
> testuser. [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 12:44:08 src at twc1 HORDE[31693]: [imp] testuser sent message  
> to webadmin at ualberta.ca [on line 1140 of "/var/www/horde/imp/ 
> compose.php"]
> Nov 20 12:44:08 src at twc1 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 src at twc1 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 src at twc1 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 src at twc1 HORDE[3941]: [imp] In addPart for testuser.  
> [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 15:35:40 src at twc1 HORDE[3941]: [imp] In buildAllAttachments  
> for testuser. [on line 756 of "/var/www/horde/imp/lib/Compose.php"]
> Nov 20 15:35:40 src at twc1 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 src at twc1 HORDE[3941]: [imp] In addPart for testuser.  
> [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 15:35:40 src at twc1 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 src at twc1 HORDE[3941]: [imp] In addPart for testuser.  
> [on line 577 of "/var/www/horde/lib/Horde/MIME/Part.php"]
> Nov 20 15:35:41 src at twc1 HORDE[3941]: [imp] testuser sent message to  
> webadmin <webadmin at ualberta.ca> [on line 1155 of "/var/www/horde/imp/ 
> compose.php"]
> Nov 20 15:35:41 src at twc1 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 src at twc1 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: Graeme.Wood at ed.ac.uk 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.
>>
>