[imp] [horde] Horde VFS on separate DB machine?

Fri Nov 23 17:46:07 UTC 2007

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.
>