Summary | Can't download attachments over ActiveSync |
Queue | Synchronization |
Queue Version | Git master |
Type | Bug |
State | Resolved |
Priority | 1. Low |
Owners | mrubinsk (at) horde (dot) org |
Requester | simon (at) simonandkate (dot) net |
Created | 07/23/2013 (4367 days ago) |
Due | |
Updated | 08/25/2013 (4334 days ago) |
Assigned | 08/16/2013 (4343 days ago) |
Resolved | 08/18/2013 (4341 days ago) |
Github Issue Link | |
Github Pull Request | |
Milestone | |
Patch | No |
Simon
State ⇒ Resolved
Good job !
Thanks
Thank you
commit b662b9311f20833b70308404d927e3b982385ca8
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Fri Aug 16 12:57:46 2013 -0400
Missing part of fix for
Bug: 12486framework/ActiveSync/lib/Horde/ActiveSync.php | 3 +++
1 files changed, 3 insertions(+), 0 deletions(-)
http://git.horde.org/horde-git/-/commit/b662b9311f20833b70308404d927e3b982385ca8
State ⇒ Feedback
commit 68a07bdfc1d0b073d25cf6e48286d75fba345917
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Fri Aug 16 12:48:44 2013 -0400
Bug: 12486Ensure the Content-Type header is sent before thebuffer is flushed.
framework/ActiveSync/lib/Horde/ActiveSync.php | 17 +++++++++++++++++
.../lib/Horde/ActiveSync/Request/GetAttachment.php | 5 +++++
.../Horde/ActiveSync/Request/ItemOperations.php | 1 +
3 files changed, 23 insertions(+), 0 deletions(-)
http://git.horde.org/horde-git/-/commit/68a07bdfc1d0b073d25cf6e48286d75fba345917
GETATTACHMENT requests. We'll have to do some clever dancing around
to get the proper content type from the attachment before the
request starts outputing to the client for those requests. For
requests other than GETATTACHMENT, your solution should work.
But, if you can fix it quickly, it's ok too :)
requests. We'll have to do some clever dancing around to get the
proper content type from the attachment before the request starts
outputing to the client for those requests. For requests other than
GETATTACHMENT, your solution should work.
we know for sure what the Content-Type is, which is why it is
currently sent after the request is processed.
multipart boolean...
matter what the webserver is, it matters what the webserver sends over
the wire.
we know for sure what the Content-Type is, which is why it is
currently sent after the request is processed.
fixes it.
Michael - I am surprised to learn that you run lighttpd - not because
there is anything wrong with it, but because you were very definite
about not being able to reproduce my issue which I stated was on an
Apache system.
Not expecting that devs replicate every setup (obviously practically
not feasible) - but knowing that you were on a different web server
may have changed the conversation about possible issue points.
Simon
New Attachment: 0001-Send-Content-Type-header-before-the-request-handle-t.patch
testing. I use lighttpd, not Apache, and it does not send a default
text/html content type, which is why I wasn't seeing this.
We will have to set the Content-Type earlier in the request in order
to work around this.
I agree with your solution and i'm waiting for test.
Thx
Ryu
State ⇒ Assigned
testing. I use lighttpd, not Apache, and it does not send a default
text/html content type, which is why I wasn't seeing this.
We will have to set the Content-Type earlier in the request in order
to work around this.
One of the things I tried early on was setting PHP output buffering to
ON (I think from memory default in php.ini is 4096):
From earlier message:
"If I turn php output buffering ON then the iPad instantly appears to
be downloading the attachment when tapped on, but it stops short of
the full size, and the attachment won't open (although it is
displaying as fully downloaded..."
That made the iOS devices' progress bar style indicator work, although
the resultant downloads were corrupted and incomplete.
Anyway, looks like we may be getting closer...
Php configuration in the php.ini (default_mimetype = "text/html")
It seems that this header problem already exists in 12.1. If you
attempt to download a big file (3MB) and you wire trace, you see that
the Content-type is :
Transfer-Encoding: chunked^M
Content-Type: text/html
But, the stream is well managed by iOS. Maybe because the
GetAttachment command want a raw format as result.
For the 14.1, the result must be a wbxml, so the client maybe try to
valid the format and fails...
That was my final test.
I think you have to force the Content-type header if the stream is
greater than the 1MB used in the output buffer before the flush, else
the result will change at each client implementation...
Thanks
Ryu
New Attachment: capture_image_getAttachment.dump
I finish new tests and all is clear for me, I think
This time, i was afraid than the content type was not sent because of
the ouput buffer. And it was the case.
You returns the Content-Type at the end of the method _handle()
(because you don't know if it is multipart or no) in
ActiveSync_Request_ItemOperations.php.
And so, in case of bigger files which are greater than 1MB, the fluh
send the first part of the stream withtout the valuable header...
I add a new dump from the GetAttachment command. In this case, the
content-type is image/jpeg. And all is good.
Then, I removed my previous patch with the output buffer size and
forced the header to Content-Type: application/vnd.ms-sync.wbxml
before to read the stream.
All was ok.
You're right with the buffer. Not needed to change it.
So, the questions are :
1. Why the content-type is sent with a bad value (text/html, see the
dump). My feeling is the Apache server which autodetects and adds a
type. (And fails with the binary of the wbxml and add text/html, but
success with the GetAttachment command).
2. Why the client makes a new call and breaks the connection after
retrieving the first part (1MB) of the file. Maybe it checks the
format, does not detect a valid HTML format and retry one more time.
I think I correctly sum up the problem.
I'm going to check if I can remove default Content-Type in apache.
What do you think about this deeper investigation ?
then? The buffer limit is present in ALL EAS requests.
the attachment in the stream. It doesn't add any wbxml or else around.
I think the problem is near this point.
In EAS 14.1, the data stream comes around tag and others informations...
Maybe in case or raw data, the client does not detect the flush...
the client, and continue processing - which includes sending the
remainder of the data when complete, this should not be seen as a
separate connection, or broken connection, or whatever the client is
seeing it as.
dump of the bad file, we can see that the content-type is not a EAS.
Transfer-Encoding: chunked
Content-Type: text/html
Maybe the headers are not sent when the php buffer is flushed and it
is the default content type which is sent... I have to check this
point. Maybe can you say more.
not stable. Now, I've retrieved some bigger files 3.5MB and all is ok.
output) without knowing how much total data is going to be sent. On
clients that have progress bars displayed during the sync, this
breaks things, so the data is "de-chunked" and sent along with the
content-length data. The limit is protection against keeping too
much data in memory at one time.
just remove the limit of the size.
I agree with this protection, but if my tests are valid, I think this
value should be a parameter with a higher default size (10MB ?) (My
Mail server accepts until 64MB...)
requests, but also why I am not seeing this regardless of the size
of the attachments I have. What clients does this happen with?
an old 4.2.1. But the problem exists with newest.
Have you test this issue with an Apple device ?
1) Why does it work correctly with the same size data in EAS 12.1
then? The buffer limit is present in ALL EAS requests.
2) If the buffer size is exceeded, PHP should flush the buffer to the
client, and continue processing - which includes sending the remainder
of the data when complete, this should not be seen as a separate
connection, or broken connection, or whatever the client is seeing it
as.
BUT, if you put this limit, it is not for nothing I think...
image is not retrieved or else... It is maybe my connection which is
very bad on my mobile now and I must test again with the WiFi.
use the same chunk size and send the same amount of data.
I would like to know the goal of the output buffer limit plz...
output) without knowing how much total data is going to be sent. On
clients that have progress bars displayed during the sync, this breaks
things, so the data is "de-chunked" and sent along with the
content-length data. The limit is protection against keeping too much
data in memory at one time.
I'm still wondering not only why this only happens with 14.x requests,
but also why I am not seeing this regardless of the size of the
attachments I have. What clients does this happen with?
Can you test too ?
Ryu
the use of fseek() and ftell() in
Horde_ActiveSync_Request_ItemOperations::_getDataSize(), as that is
really the only difference in what happens to the stream between
12.1 and 14.x requests.
After 2 days of remote debugging on my test environment (with vim :)
), I solved this bug.
As the ActiveSync message exceeds the size of the output buffer
defined in the method getReponse of the class Horde_Rpc_ActiveSync
(1MB), the transfer is splited in the Horde_ActiveSync_Wbxml_Encoder,
_outTermStr(). The client detects this as a problem and request again
the server.
I removed the limit for tests and all files can be downloaded !
BUT, if you put this limit, it is not for nothing I think...
BUT, after some tests, all my images are corrupted. The end of the
image is not retrieved or else... It is maybe my connection which is
very bad on my mobile now and I must test again with the WiFi.
I tell you later if it is ok.
I would like to know the goal of the output buffer limit plz...
Thx
Ryu
New Attachment: capture_image_ko.dump
on is a tcp trace (using something like wireshark).
I see the difference but I can explain. Maybe you will see better :)
Ryu
New Attachment: capture_image_ok.dump
on is a tcp trace (using something like wireshark).
I see the difference but I can explain. Maybe you will see better :)
Ryu
going on is a tcp trace (using something like wireshark).
I see the difference but I can explain. Maybe you will see better :)
Ryu
Thanks
the use of fseek() and ftell() in
Horde_ActiveSync_Request_ItemOperations::_getDataSize(), as that is
really the only difference in what happens to the stream between 12.1
and 14.x requests.
Assigned to Michael Rubinsky
State ⇒ Feedback
on is a tcp trace (using something like wireshark).
New Attachment: easTrace.txt
Many of my users told me about this problem but I thought it was a
problem of the sender... until I search yesterday and find your ticket.
I tried with a 3.5MB file. Same result.
I feel the file is sent to the mobile, but with a bad format or
else... Most strange is than the mobile does not refresh the amount
of data transfered.
I will try to dig again this day...
I add a trace of a good and a bad transfer. It seems that in case of
large image, the first attempt is cut by a new login attempt...
Ryu
- try a 3 or 4 MB attachment.
I haven't been able to test this further yet, and am running in 12.1
mode for compatibility sake. I run client -> reverse proxy -> host
with SSL each hop, so I am not sure that wiretracing will tell much
without disabling that, so I need to find some time to dig into this
further. Ryu - are you able to do any testing on yours?
Simon.
the wire, no other ideas.
same problem here.
2 simple tests :
- First, I do a photo on my iPhone (700ko real size). I send this
photo by mail to myself. I receive the mail and I can view the
attachment.
- Then, a new photo with my iPhone (855ko real size). I send it too.
But, this time, I can't download it.
My horde is configured with EAS 14.1. I check with 12.1 and all is ok.
When I check the file ActiveSync/Wbxml/Encoder.php, _outTermStr() and
I write the stream to a file, I can decode the photo from the base64
without problem.
But in the message sent to iPhone, it seems there is a problem...
I don't see any segfault...
My system is a Debian 7.1 with php 5.4.4
Do you have an idea to trace this problem deeper ?
Thanks
Ryu
it's just the ITEMOPERATION stream that has the issue.
can think of off hand is the use of fseek() and ftell() to re-position
the stream pointer while getting the size of the stream. There might
be some differences in how we ask for the data from the IMAP server,
but that would occur much earlier in the request.
reproduce it and no one else has reported this. Until somebody can
show evidence that it's something wrong with the code, I will continue
to think it's something with your php/apache/os/whatever. Again,
segfaults are NEVER the fault of userland PHP code.
You can look at a wiretrace to see exactly what is being sent over the
wire to see if there are any clues there...
just the ITEMOPERATION stream that has the issue.
I do miss the replied flags that 14.1 gives... I'll try it back on
14.1 over the weekend, and do some more digging.
Curious - are you still convinced that it's an issue with my php stack? :)
requesting the attachment data using a different commands. E.g.,
ITEMOPERATIONS vs GETATTACHMENT requests. Both are valid requests
under 12.1 and 14.1 but maybe the device favors one over the other in
different EAS versions. The former is a more involved request which,
among other things calculates the size of the stream using stream
commands such as fseek() and ftell() whereas the latter does not.
(combined php.ini and php.d):
curl.ini
dom.ini
fileinfo.ini
intl.ini
json.ini
ldap.ini
mbstring.ini
mcrypt.ini
mysql.ini
pdo.ini
pdo_mysql.ini
phar.ini
soap.ini
tidy.ini
wddx.ini
xmlreader.ini
xmlrpc.ini
xmlwriter.ini
xsl.ini
zip.ini
imagick.so
lzf.so
pam.so
ssh2.so
mongo.so
horde_lz4.so
geoip.so
Any more you think can go? The server only runs Horde, and I use
pdo-mysql database driver, and Shares driver is NG-SQL. The rest all
look needed...
successfully to AS devices.
No segfaults.
definitely wanted and useful...
I assume that the stream is handled differently in 14.1?
successfully to AS devices.
No segfaults.
3 years ago. Not sure if they would be compatible with the change from
5.2.x to 5.3.x without recompiling. Other than that, I would remove
the extensions that you don't use as a general rule. Unless you are
using apps other than Horde that use different databases there is no
reason to have pdo_mysql AND pdo_pgsql as well as mysqli and mysql.
Again, you may be using these elsewhere and that's fine. Also, Horde
doesn't use the imap extension so unless you need it elsewhere you can
disable it. Not sure if it's the cause of your problems, that's just
my practice.
extension=imagick.so
extension="lzf.so"
extension="memcache.so"
extension="pam.so"
extension="ssh2.so"
extension="mongo.so"
extension="horde_lz4.so"
extension=geoip.so
Horde doesn't run without lzf.so, I assume because compression is enabled.
With all of the others remarked out, the zend_mm_heap corrupted
messages disappear, but the segfaults remain, along with the "Cannot
download attachment". So one of the commented out modules is causing
the zend error but the segfault is being driven from elsewhere. I've
commented memcache out entirely as I don't use it any more, and I
suspect from reading that may have been the cause of the zend errors.
php.d directory loads:
-rw-r--r-- 1 root root 49 Jul 13 00:50 curl.ini
-rw-r--r-- 1 root root 47 Jul 13 00:50 dom.ini
-rw-r--r-- 1 root root 24 Jul 1 2010 facedetect.ini
-rw-r--r-- 1 root root 57 Jul 13 00:50 fileinfo.ini
-rw-r--r-- 1 root root 45 Jul 13 00:50 gd.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 imap.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 intl.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 json.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 ldap.ini
-rw-r--r-- 1 root root 23 Jul 1 2010 libpuzzle.ini
-rw-r--r-- 1 root root 57 Jul 13 00:50 mbstring.ini
-rw-r--r-- 1 root root 53 Jul 13 00:50 mcrypt.ini
-rw-r--r-- 1 root root 53 Jul 13 00:50 mysqli.ini
-rw-r--r-- 1 root root 51 Jul 13 00:50 mysql.ini
-rw-r--r-- 1 root root 47 Jul 13 00:50 pdo.ini
-rw-r--r-- 1 root root 59 Jul 13 00:50 pdo_mysql.ini
-rw-r--r-- 1 root root 59 Jul 13 00:50 pdo_pgsql.ini
-rw-r--r-- 1 root root 61 Jul 13 00:50 pdo_sqlite.ini
-rw-r--r-- 1 root root 51 Jul 13 00:50 pgsql.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 phar.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 soap.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 tidy.ini
-rw-r--r-- 1 root root 49 Jul 13 00:50 wddx.ini
-rw-r--r-- 1 root root 59 Jul 13 00:50 xmlreader.ini
-rw-r--r-- 1 root root 53 Jul 13 00:50 xmlrpc.ini
-rw-r--r-- 1 root root 59 Jul 13 00:50 xmlwriter.ini
-rw-r--r-- 1 root root 47 Jul 13 00:50 xsl.ini
-rw-r--r-- 1 root root 47 Jul 13 00:50 zip.ini
But I am uncertain which of those are not 'standard' - the same date
on most would lead me to believe that those have come from my upgrade
to 5.3.27...
Next step will be to try and get a core dump I guess, unless anything
looks odd from the above?
out about what is causing the segfault, then post back here.
the other concurrent PID was logged. It does look like the stream
processing completes for this request.
However, the timestamp for the segfault you are posting is BEFORE the
request for the attachment even hits the log, and is a different PID.
The process that is crashing is not the process that you show as a
successful request/response in the log.
So, according to the log, the stream is successfully sent out over the
PHP output stream (at least for the request you have shown). If the
device does not take it, either PHP dies while sending the output
buffer or perhaps there is something funky being sent over the wire.
Take a look at a wireshark/tcpdump to see what is actually being sent.
Also, my previous comments about PHP extensions/pecl modules still
holds true.
The errors still occur, I still cannot download large attachments
over ActiveSync, and I still get:
[Sat Jul 27 18:37:06 2013] [notice] child pid 13855 exit signal
Segmentation fault (11)
are caused by internal errors in PHP (or less likely, the webserver).
zend_mm_heap corrupted
buggy PHP module. Do you have APC or other opcode cache running? Try
disabling ALL non-essential php/pecl modules. If that doesn't work -
you could try using something like GDB to attach to the apache
process, wait for the crash, and see if you can get any meaningful
data out of the output.
(13939 is the PID to follow):
'[stream]' text is output to the logfile immediately before the stream
processing begins. Something is crashing immediately after '[stream]'
is output to the log, but before the closing Wbxml tag is output to
the log. The *only* thing that occurs between these two events is
stream processing.
Not what you want to hear, but something is broken/buggy on your
system. So far you are the only person reporting this, and no other
dev can reproduce it.
open an attachment on an email already on my wife's iPhone.
The errors still occur, I still cannot download large attachments over
ActiveSync, and I still get:
[Sat Jul 27 18:37:06 2013] [notice] child pid 13855 exit signal
Segmentation fault (11)
zend_mm_heap corrupted
zend_mm_heap corrupted
[Sat Jul 27 18:37:07 2013] [notice] caught SIGTERM, shutting down
The STREAM appears to work fine according to the AS device log (13939
is the PID to follow):
2013-07-27T08:37:12+00:00 INFO: [13939] Request being handled for
device: APPL79030TBFA4S Supporting protocol version: 14.1
2013-07-27T08:37:12+00:00 INFO: [APPL79030TBFA4S] Handling
ITEMOPERATIONS command.
2013-07-27T08:37:12+00:00 DEBUG: [13939] I <ItemOperations:ItemOperations>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I <ItemOperations:Fetch>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I <ItemOperations:Store>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I Mailbox
2013-07-27T08:37:12+00:00 DEBUG: [13939] I </ItemOperations:Store>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I <AirSyncBase:FileReference>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I INBOX:11687:2
2013-07-27T08:37:12+00:00 DEBUG: [13939] I </AirSyncBase:FileReference>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I </ItemOperations:Fetch>
2013-07-27T08:37:12+00:00 DEBUG: [13939] I </ItemOperations:ItemOperations>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:ItemOperations>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:Status>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O 1
2013-07-27T08:37:12+00:00 DEBUG: [13939] O </ItemOperations:Status>
2013-07-27T08:37:12+00:00 INFO: [13940] Request being handled for
device: APPL79030TBFA4S Supporting protocol version: 14.1
2013-07-27T08:37:12+00:00 INFO: [13940] Handling PING command received
at timestamp: 1374914232.
2013-07-27T08:37:12+00:00 INFO: [13940] Using cached heartbeat of 480
2013-07-27T08:37:12+00:00 INFO: [13940] Empty PING request.
2013-07-27T08:37:12+00:00 INFO: [13940] Loaded @Contacts@ from the cache.
2013-07-27T08:37:12+00:00 INFO: [13940] Loaded INBOX from the cache.
2013-07-27T08:37:12+00:00 INFO: [13940] Loaded @Calendar@ from the cache.
2013-07-27T08:37:12+00:00 INFO: [13940] Loaded @Tasks@ from the cache.
2013-07-27T08:37:12+00:00 INFO: Waiting for changes for 480 seconds
2013-07-27T08:37:12+00:00 INFO: [13940] Replacing SYNC_CACHE entry for
user katie and device APPL79030TBFA4S:
a:11:{s:18:"confirmed_synckeys";a:1:{s:41:"{51efbfcc-3b64-46cf-97cf-2456c0a801e6}121";b:1;}s:17:"lasthbsyncstarted";i:1374914232;s:17:"lastsyncendnormal";i:1374914222;s:9:"timestamp";s:10:"1374914232";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:74:{s:8:"fa71c9cd";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/Palm Details";}s:8:"f43b1ef6";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:20:"INBOX/Cabinet/Photos";}s:8:"eccbb3f9";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:18:"INBOX/Cabinet/Home";}s:8:"eb3b82e9";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:25:"INBOX/Cabinet/BKC Details";}s:8:"eade599f";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:22:"INBOX/Cabinet/Pictures";}s:8:"eaa6eca4";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/Jobs/Ansaldo";}s:8:"e909607f";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:11:"INBOX/Trash";}s:8:"e780cbd4";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Work Expenses";}s:8:"e5a53b78";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:34:"INBOX/Cabinet/Stepfamilies Details";}s:8:"e2d3c20f";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:32:"INBOX/Cabinet/Entertainment/Qtix";}s:8:"e1643e51";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:39:"INBOX/Cabinet/Jobs/Ansaldo/ASTS Details";}s:8:"e0f1eb03";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Footy Tipping";}s:8:"d102b3d3";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:28:"INBOX/Cabinet/Gaybee Details";}s:8:"c6289bb8";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Tower Details";}s:8:"bd29ff5a";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:33:"INBOX/Cabinet/Baby Shower Details";}s:8:"b9efdd34";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:19:"INBOX/Cabinet/Lotto";}s:8:"b842cd4a";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:36:"INBOX/Cabinet/Banking Details/Virgin";}s:8:"b3443027";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:18:"INBOX/Cabinet/Jobs";}s:8:"a994cd6f";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:29:"INBOX/Cabinet/Railway Details";}s:8:"a8795265";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:25:"INBOX/Cabinet/TPG Details";}s:8:"a73e2db2";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:37:"INBOX/Cabinet/RBWH Foundation Details";}s:8:"a6e7f28e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/ACSHS Details";}s:8:"a6d57ad0";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:19:"INBOX/Cabinet/12WBT";}s:8:"a1b8bef2";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:20:"INBOX/Cabinet/Virgin";}s:7:"@Tasks@";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:7:"@Tasks@";}s:7:"@Notes@";a:2:{s:5:"class";s:5:"Notes";s:8:"serverid";s:7:"@Notes@";}s:10:"@Contacts@";a:2:{s:5:"class";s:8:"Contacts";s:8:"serverid";s:10:"@Contacts@";}s:10:"@Calendar@";a:2:{s:5:"class";s:8:"Calendar";s:8:"serverid";s:10:"@Calendar@";}s:8:"9ff254cf";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Entertainment";}s:8:"9e01b742";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:33:"INBOX/Cabinet/Banking Details/ING";}s:8:"96689df9";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:38:"INBOX/Cabinet/PD & Application Details";}s:8:"9496b286";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/eBay Details";}s:8:"8d6597f1";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:25:"INBOX/Cabinet/MPC Details";}s:8:"8d1866fc";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:31:"INBOX/Cabinet/Primavera Details";}s:8:"8b69fd95";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Optus Details";}s:8:"717e2846";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX/Sent";}s:8:"8884e147";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX/Spam";}s:8:"829d5be6";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:34:"INBOX/Cabinet/Guthy-Renker Details";}s:8:"7f4b651b";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:28:"INBOX/Cabinet/PayPal Details";}s:8:"7f3bba4e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:48:"INBOX/Cabinet/Jobs/Joharko International Details";}s:8:"70de6c61";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/Gail Details";}s:8:"702ca60e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:13:"INBOX/Cabinet";}s:8:"6ef72b02";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:41:"INBOX/Cabinet/Jobs/Ansaldo/Security Issue";}s:8:"6a2a518c";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:29:"INBOX/Cabinet/FlyBuys Details";}s:8:"67b1aa6e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:31:"INBOX/Cabinet/Donna O D Details";}s:8:"646c0ad5";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:5:"INBOX";}s:8:"5ba39dc4";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:34:"INBOX/Cabinet/Football - U13B 2006";}s:8:"5b9de20a";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:31:"INBOX/Cabinet/Gantthead Details";}s:8:"58449e08";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:30:"INBOX/Cabinet/Passport Details";}s:8:"57d6ea97";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:33:"INBOX/Cabinet/Banking Details/NAB";}s:8:"5637a65a";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:33:"INBOX/Cabinet/Jokes & Funny Stuff";}s:8:"52391ed4";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:29:"INBOX/Cabinet/Aquenta Details";}s:8:"5131c455";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/ACSS Details";}s:8:"4e2ddaaf";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:54:"INBOX/Cabinet/Entertainment/Entertainment Book Details";}s:8:"4dbf75ac";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:50:"INBOX/Cabinet/Entertainment/Big Fish Games Details";}s:8:"4d442199";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Super Details";}s:8:"48843d3f";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/Home/The Gap";}s:8:"484ae3f5";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:18:"INBOX/Cabinet/Work";}s:8:"43864e2e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:49:"INBOX/Cabinet/Entertainment/Cinebuzz Club Details";}s:8:"3e8c2ce1";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Legal Details";}s:8:"3a068504";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:36:"INBOX/Cabinet/QT Social Club - MRTSC";}s:8:"34cdf8c2";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:24:"INBOX/Cabinet/QT Details";}s:8:"2a7e2894";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:26:"INBOX/Cabinet/Soccer - ACE";}s:8:"257d46a2";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:12:"INBOX/Drafts";}s:8:"24ecb703";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:29:"INBOX/Cabinet/Wedding Details";}s:8:"1c4f57f8";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:29:"INBOX/Cabinet/Contact Details";}s:8:"1ba254f6";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:39:"INBOX/Cabinet/Jobs/Leighton Contractors";}s:8:"180fd8fe";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:29:"INBOX/Cabinet/Banking Details";}s:8:"101fd644";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:50:"INBOX/Cabinet/Stepfamilies Details/Qld Association";}s:8:"0fb742bc";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:27:"INBOX/Cabinet/Home/Stafford";}s:8:"0668fc51";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:18:"INBOX/Cabinet/RACQ";}s:8:"05d9cf1c";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:31:"INBOX/Cabinet/Interlock Support";}s:8:"01d1de61";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:19:"INBOX/Cabinet/Saved";}s:8:"00cd127a";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:31:"INBOX/Cabinet/KrisFlyer
Details";}}s:9:"hierarchy";s:39:"{51eb85b8-8978-4cf5-940f-1a63c0a801e6}1";s:11:"collections";a:4:{s:10:"@Contacts@";a:12:{s:5:"class";s:8:"Contacts";s:10:"windowsize";s:2:"25";s:10:"filtertype";s:1:"0";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@Contacts@";s:11:"lastsynckey";s:40:"{51eb85c3-c3c8-42c8-aa84-1a63c0a801e6}22";s:8:"pingable";b:1;s:2:"id";s:10:"@Contacts@";}s:8:"646c0ad5";a:12:{s:5:"class";s:5:"Email";s:10:"windowsize";i:100;s:10:"filtertype";s:1:"3";s:10:"truncation";i:0;s:11:"mimesupport";s:1:"0";s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:5:"INBOX";s:11:"lastsynckey";s:41:"{51efbfcc-3b64-46cf-97cf-2456c0a801e6}121";s:8:"pingable";b:1;s:2:"id";s:8:"646c0ad5";}s:10:"@Calendar@";a:12:{s:5:"class";s:8:"Calendar";s:10:"wind
owsize";s:2:"25";s:10:"filtertype";s:1:"5";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@Calendar@";s:11:"lastsynckey";s:40:"{51eb85df-1578-4caa-ad28-1a60c0a801e6}18";s:8:"pingable";b:1;s:2:"id";s:10:"@Calendar@";}s:7:"@Tasks@";a:12:{s:5:"class";s:5:"Tasks";s:10:"windowsize";s:2:"25";s:10:"filtertype";s:1:"0";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:7:"@Tasks@";s:11:"lastsynckey";s:39:"{51eb85ec-ad08-404e-811d-1f2fc0a801e6}1";s:8:"pingable";b:1;s:2:"id";s:7:"@Tasks@";}}s:13:"pingheartbeat";b:0;s:14:"synckeycounter";a:4:{s:10:"@Contacts@";a:1:{s:40:"{51eb85c3-c3c8-42c8-aa84-1a63c0a801e6}22";i:0;}s:8:"646c0ad5";a:1:{s:41:"{51efbfcc-3b64-46cf-97cf-2456c0a801e6}120";i:1;}s:10:"@Calendar@";a:
1:{s:40:"{51eb85df-1578-4caa-ad28-1a60c0a801e6}17";i:1;}s:7:"@Tasks@";a:1:{s:39:"{51eb85ec-ad08-404e-811d-1f2fc0a801e6}1";i:0;}}}
2013-07-27T08:37:12+00:00 INFO: [13940] Initializing state for
collection: @Contacts@, synckey:
{51eb85c3-c3c8-42c8-aa84-1a63c0a801e6}22
2013-07-27T08:37:12+00:00 INFO: [13940] Loading state for synckey
{51eb85c3-c3c8-42c8-aa84-1a63c0a801e6}22
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:Response>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:Fetch>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:Status>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O 1
2013-07-27T08:37:12+00:00 DEBUG: [13939] O </ItemOperations:Status>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <AirSyncBase:FileReference>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O INBOX:11687:2
2013-07-27T08:37:12+00:00 DEBUG: [13939] O </AirSyncBase:FileReference>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:Properties>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <AirSyncBase:ContentType>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O image/jpeg
2013-07-27T08:37:12+00:00 DEBUG: [13939] O </AirSyncBase:ContentType>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O <ItemOperations:Data>
2013-07-27T08:37:12+00:00 DEBUG: [13939] O [STREAM]
2013-07-27T08:37:12+00:00 INFO: [13940] Using MODSEQ 2982 for @Contacts@.
2013-07-27T08:37:12+00:00 INFO: [13940] Initializing message diff
engine for @Contacts@ (@Contacts@)
2013-07-27T08:37:12+00:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 2982, 2982,
0, 1)
2013-07-27T08:37:12+00:00 INFO: [13940] Fetching changes for contacts
using MODSEQ.
2013-07-27T08:37:12+00:00 INFO: [13940] Found 0 message changes in @Contacts@.
2013-07-27T08:37:12+00:00 INFO: [13940] Initializing state for
collection: INBOX, synckey: {51efbfcc-3b64-46cf-97cf-2456c0a801e6}121
2013-07-27T08:37:12+00:00 INFO: [13940] Loading state for synckey
{51efbfcc-3b64-46cf-97cf-2456c0a801e6}121
2013-07-27T08:37:12+00:00 INFO: [13940] Initializing message diff
engine for 646c0ad5 (INBOX)
2013-07-27T08:37:12+00:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1374899886,
1374914232, 1374309432, 1)
2013-07-27T08:37:12+00:00 INFO: [13940] Found 0 message changes in 646c0ad5.
2013-07-27T08:37:12+00:00 INFO: [13940] Initializing state for
collection: @Calendar@, synckey:
{51eb85df-1578-4caa-ad28-1a60c0a801e6}18
2013-07-27T08:37:12+00:00 INFO: [13940] Loading state for synckey
{51eb85df-1578-4caa-ad28-1a60c0a801e6}18
2013-07-27T18:37:12+10:00 INFO: [13940] Using MODSEQ 3030 for @Calendar@.
2013-07-27T18:37:12+10:00 INFO: [13940] Initializing message diff
engine for @Calendar@ (@Calendar@)
2013-07-27T18:37:12+10:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 3030, 3030,
1372495032, 1)
2013-07-27T18:37:12+10:00 INFO: [13940] Fetching changes for calendar
using MODSEQ.
2013-07-27T18:37:12+10:00 INFO: [13940] Found 0 message changes in @Calendar@.
2013-07-27T18:37:12+10:00 INFO: [13940] Initializing state for
collection: @Tasks@, synckey: {51eb85ec-ad08-404e-811d-1f2fc0a801e6}1
2013-07-27T18:37:12+10:00 INFO: [13940] Loading state for synckey
{51eb85ec-ad08-404e-811d-1f2fc0a801e6}1
2013-07-27T18:37:12+10:00 INFO: [13940] Using MODSEQ 2696 for @Tasks@.
2013-07-27T18:37:12+10:00 INFO: [13940] Initializing message diff
engine for @Tasks@ (@Tasks@)
2013-07-27T18:37:12+10:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 0, 2696, 0, 1)
2013-07-27T18:37:12+10:00 INFO: [13940] Found 0 message changes in @Tasks@.
2013-07-27T18:37:12+10:00 INFO: [13940] Sleeping for 30 seconds.
2013-07-27T18:37:42+10:00 INFO: [13940] SyncCache collections refreshed.
2013-07-27T18:37:42+10:00 INFO: [13940] Refreshing @Contacts@ from the cache.
2013-07-27T18:37:42+10:00 INFO: [13940] Refreshing 646c0ad5 from the cache.
2013-07-27T18:37:42+10:00 INFO: [13940] Refreshing @Calendar@ from the cache.
2013-07-27T18:37:42+10:00 INFO: [13940] Refreshing @Tasks@ from the cache.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing state for
collection: @Contacts@, synckey:
{51eb85c3-c3c8-42c8-aa84-1a63c0a801e6}22
2013-07-27T18:37:42+10:00 INFO: [13940] Loading state for synckey
{51eb85c3-c3c8-42c8-aa84-1a63c0a801e6}22
2013-07-27T18:37:42+10:00 INFO: [13940] Using MODSEQ 2982 for @Contacts@.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing message diff
engine for @Contacts@ (@Contacts@)
2013-07-27T18:37:42+10:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 2982, 2982,
0, 1)
2013-07-27T18:37:42+10:00 INFO: [13940] Fetching changes for contacts
using MODSEQ.
2013-07-27T18:37:42+10:00 INFO: [13940] Found 0 message changes in @Contacts@.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing state for
collection: INBOX, synckey: {51efbfcc-3b64-46cf-97cf-2456c0a801e6}121
2013-07-27T18:37:42+10:00 INFO: [13940] Loading state for synckey
{51efbfcc-3b64-46cf-97cf-2456c0a801e6}121
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing message diff
engine for 646c0ad5 (INBOX)
2013-07-27T18:37:42+10:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1374899886,
1374914262, 1374309462, 1)
2013-07-27T18:37:42+10:00 INFO: [13940] Found 0 message changes in 646c0ad5.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing state for
collection: @Calendar@, synckey:
{51eb85df-1578-4caa-ad28-1a60c0a801e6}18
2013-07-27T18:37:42+10:00 INFO: [13940] Loading state for synckey
{51eb85df-1578-4caa-ad28-1a60c0a801e6}18
2013-07-27T18:37:42+10:00 INFO: [13940] Using MODSEQ 3030 for @Calendar@.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing message diff
engine for @Calendar@ (@Calendar@)
2013-07-27T18:37:42+10:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 3030, 3030,
1372495062, 1)
2013-07-27T18:37:42+10:00 INFO: [13940] Fetching changes for calendar
using MODSEQ.
2013-07-27T18:37:42+10:00 INFO: [13940] Found 0 message changes in @Calendar@.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing state for
collection: @Tasks@, synckey: {51eb85ec-ad08-404e-811d-1f2fc0a801e6}1
2013-07-27T18:37:42+10:00 INFO: [13940] Loading state for synckey
{51eb85ec-ad08-404e-811d-1f2fc0a801e6}1
2013-07-27T18:37:42+10:00 INFO: [13940] Using MODSEQ 2696 for @Tasks@.
2013-07-27T18:37:42+10:00 INFO: [13940] Initializing message diff
engine for @Tasks@ (@Tasks@)
2013-07-27T18:37:42+10:00 INFO: [13940]
Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 0, 2696, 0, 1)
2013-07-27T18:37:42+10:00 INFO: [13940] Found 0 message changes in @Tasks@.
2013-07-27T18:37:42+10:00 INFO: [13940] Sleeping for 30 seconds.
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:Data>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O <ItemOperations:Total>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O 2566611
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:Total>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O <ItemOperations:Range>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O 0-2566611
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:Range>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:Properties>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:Fetch>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:Response>
2013-07-27T08:38:12+00:00 DEBUG: [13939] O </ItemOperations:ItemOperations>
2013-07-27T08:38:12+00:00 INFO: [13939] User katie logged off
I haven't reset device AS partnerships or anything, just tried to open
an attachment on an email already on my wife's iPhone.
date - until this issue :) - there has been no compelling reason to do
so. The CentOS team assure their users that security vulnerabilities
are back-ported, which leaves functionality and / or bugs. I
understand the viewpoint expressed by Horde devs that they do not all
necessarily agree with that, and that is fine. Functionality has not
been an issue, the server only runs Horde, and it's been working fine
with no major issues, so (in my opinion) I have not yet needed to
upgrade. That has simplified the management of my (mostly)
original-CentOS-rpm server.
Now that it appears that I have run into a dead end that cannot be
resolved without upgrading I will absolutely look at doing it.
As always - thank you for your help Mike, it's appreciated.
PHP/Apache. PHP 5.3.3 is 3 years old. There were hundreds of bugs
fixed since then, and at least a dozen stream related fixes.
My guess is that it's a bug in PHP's stream filter handling but that's
just an educated guess. If you would rather poke around the code than
update PHP, you can look in
Horde_ActiveSync_Message_AirSyncBaseFileAttachment::_checkEncoding()
or Horde_ActiveSync_Wbxml_Encoder::_outTermStr()
The former adds a stream filter to encode the data to base64 as
required by the spec. The later is where the stream is ouput 8192
bytes at a time.
If you insist on not upgrading your 3 year old PHP you can read out
the stream into a string, convert it to base64 and return it from the
first method (though this will absolutely kill performance as the
entire attachment will be kept in memory, along with the larger base64
encoded version of it).
segfault remains, although obviously the zend_mm_corrupted message
disappears.
it. At the moment though (until now) I have no major functional
issues in Horde running 5.3.3, so have not had to...
to date from CentOS, which is 5.3.3.
If no other option I will look at one of the non-CentOS php upgrade
paths, but preference for managing this server would be to keep it
simple with CentOS packages. To date that has not been an issue, with
Horde working fine under 5.3.3.
it. At the moment though (until now) I have no major functional issues
in Horde running 5.3.3, so have not had to...
I have tried different sizes with pdfs.
* 740KB - succeeds. iOS automatically downloads it when you open the email.
* 785KB - fails. iOS tries to auto download, but it silently fails. No
Apache crash either. It appears to try a couple of times to get it too.
* 1000KB - fails, same as 785KB
* 1100KB - fails as per 1000KB, but added iOS "Cannot download
attachment". No Apache crash.
* 3.5MB - have to manually tap to attempt download on iOS. Apache
crashes, and I get "Cannot download attachment".
One interesting thing:
With the 785KB file, it tries TWICE, and the second one succeeds
according to AS (different PID):
2013-07-25T09:14:06+00:00 INFO: [APPLDLXFT5X3DFJ2] Handling
ITEMOPERATIONS command.
2013-07-25T09:14:06+00:00 DEBUG: [9302] I <ItemOperations:ItemOperations>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I <ItemOperations:Fetch>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I <ItemOperations:Store>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I Mailbox
2013-07-25T09:14:06+00:00 DEBUG: [9302] I </ItemOperations:Store>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I <AirSyncBase:FileReference>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I INBOX:51699:1.2
2013-07-25T09:14:06+00:00 DEBUG: [9302] I </AirSyncBase:FileReference>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I </ItemOperations:Fetch>
2013-07-25T09:14:06+00:00 DEBUG: [9302] I </ItemOperations:ItemOperations>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:ItemOperations>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:Status>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O 1
2013-07-25T09:14:06+00:00 DEBUG: [9302] O </ItemOperations:Status>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:Response>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:Fetch>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:Status>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O 1
2013-07-25T09:14:06+00:00 DEBUG: [9302] O </ItemOperations:Status>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <AirSyncBase:FileReference>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O INBOX:51699:1.2
2013-07-25T09:14:06+00:00 DEBUG: [9302] O </AirSyncBase:FileReference>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:Properties>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <AirSyncBase:ContentType>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O application/pdf
2013-07-25T09:14:06+00:00 DEBUG: [9302] O </AirSyncBase:ContentType>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O <ItemOperations:Data>
2013-07-25T09:14:06+00:00 DEBUG: [9302] O [STREAM]
2013-07-25T09:14:06+00:00 INFO: [10216]
Horde_Core_ActiveSync_Driver::authenticate() attempt for simon
2013-07-25T09:14:06+00:00 DEBUG: [10216] ITEMOPERATIONS request
received for user simon
2013-07-25T09:14:06+00:00 INFO: [10216] Device entry exists for
APPLDLXFT5X3DFJ2, updating userAgent and version.
2013-07-25T09:14:06+00:00 INFO: [10216] Request being handled for
device: APPLDLXFT5X3DFJ2 Supporting protocol version: 14.1
2013-07-25T09:14:06+00:00 INFO: [APPLDLXFT5X3DFJ2] Handling
ITEMOPERATIONS command.
2013-07-25T09:14:06+00:00 DEBUG: [10216] I <ItemOperations:ItemOperations>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I <ItemOperations:Fetch>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I <ItemOperations:Store>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I Mailbox
2013-07-25T09:14:06+00:00 DEBUG: [10216] I </ItemOperations:Store>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I <AirSyncBase:FileReference>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I INBOX:51699:1.2
2013-07-25T09:14:06+00:00 DEBUG: [10216] I </AirSyncBase:FileReference>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I </ItemOperations:Fetch>
2013-07-25T09:14:06+00:00 DEBUG: [10216] I </ItemOperations:ItemOperations>
2013-07-25T09:14:06+00:00 DEBUG: [10216] O <ItemOperations:ItemOperations>
2013-07-25T09:14:06+00:00 DEBUG: [10216] O <ItemOperations:Status>
2013-07-25T09:14:06+00:00 DEBUG: [10216] O 1
2013-07-25T09:14:06+00:00 DEBUG: [10216] O </ItemOperations:Status>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <ItemOperations:Response>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <ItemOperations:Fetch>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <ItemOperations:Status>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O 1
2013-07-25T09:14:07+00:00 DEBUG: [10216] O </ItemOperations:Status>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <AirSyncBase:FileReference>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O INBOX:51699:1.2
2013-07-25T09:14:07+00:00 DEBUG: [10216] O </AirSyncBase:FileReference>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <ItemOperations:Properties>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <AirSyncBase:ContentType>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O application/pdf
2013-07-25T09:14:07+00:00 DEBUG: [10216] O </AirSyncBase:ContentType>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O <ItemOperations:Data>
2013-07-25T09:14:07+00:00 DEBUG: [10216] O [STREAM]
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:Data>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O <ItemOperations:Total>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O 803031
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:Total>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O <ItemOperations:Range>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O 0-803031
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:Range>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:Properties>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:Fetch>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:Response>
2013-07-25T09:14:15+00:00 DEBUG: [10216] O </ItemOperations:ItemOperations>
But it appears the iPad is hanging on for the first one that fails.
If I turn php output buffering ON then the iPad instantly appears to
be downloading the attachment when tapped on, but it stops short of
the full size, and the attachment won't open (although it is
displaying as fully downloaded. E.g. AS device log for a 2MB pdf, only
one (apparently successful) STREAM:
2013-07-25T09:49:56+00:00 INFO: [APPLDLXFT5X3DFJ2] Handling
ITEMOPERATIONS command.
2013-07-25T09:49:56+00:00 DEBUG: [8373] I <ItemOperations:ItemOperations>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I <ItemOperations:Fetch>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I <ItemOperations:Store>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I Mailbox
2013-07-25T09:49:56+00:00 DEBUG: [8373] I </ItemOperations:Store>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I <AirSyncBase:FileReference>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I INBOX:51704:1.2
2013-07-25T09:49:56+00:00 DEBUG: [8373] I </AirSyncBase:FileReference>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I </ItemOperations:Fetch>
2013-07-25T09:49:56+00:00 DEBUG: [8373] I </ItemOperations:ItemOperations>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:ItemOperations>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Status>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O 1
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Status>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Response>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Fetch>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Status>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O 1
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Status>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <AirSyncBase:FileReference>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O INBOX:51704:1.2
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </AirSyncBase:FileReference>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Properties>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <AirSyncBase:ContentType>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O application/pdf
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </AirSyncBase:ContentType>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Data>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O [STREAM]
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Data>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Total>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O 2284370
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Total>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O <ItemOperations:Range>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O 0-2284370
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Range>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Properties>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Fetch>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:Response>
2013-07-25T09:49:56+00:00 DEBUG: [8373] O </ItemOperations:ItemOperations>
Says it's sent it all, but iPad shows this as an unopenable 694KB file.
devices now being on 14.1 instead of 12.1 that they are requested
differently?
version level in the config to 12.1.
There was a bug recently fixed that was causing attachments to ALWAYS
be truncated regardless of what the client requested. It's possible
you weren't hitting on your issue because the size was never larger
than 1MB.
Your logs show that a request for the data is successfully received,
parsed, the server successfully finds the requested data, prepares it
in the correct format and begins to stream it to the client. It's
after this last step that your server dies - during the operation that
reads a chunk of data from the attachment data stream and sends it
over the php output stream to the client. You can tell this because of
the "[stream]" value printed as the last successful log entry in each
request.
What version of PHP are you running?
client as part of the email sync are fine, it appears to be when a
larger attachment is not auto-downloaded as part of that original sync
and then subsequently requested that the problem occurs. I have sent
myself both a 2MB PDF and jpg, and they both do it.
This has definitely worked in the past, could it be due to the devices
now being on 14.1 instead of 12.1 that they are requested differently?
State ⇒ Not A Bug
New Attachment: error.txt
a few seconds it told me "cannot download attachment", and I
immediately copied the device's AS log file - and it's almost empty...
New Attachment: ipaderror.txt
This is a larger log from ActiveSync 2.5.5, another log to come from
after an update to 2.5.6
to say! Not git, but latest release.
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Type ⇒ Bug
Summary ⇒ Can't download attachments over ActiveSync
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
Downloading an image in an email on iPad / iPhone / S4 (fairly large,
2.5MB), causes httpd to segfault, and "Cannot download attachment" on
an iOS client, and "Load Failed!" on Android. I also tried to download
a pdf (900KB) and that didn't work, but no error returned on the client.
Apache log contains only this:
[Tue Jul 23 21:21:24 2013] [notice] child pid 2369 exit signal
Segmentation fault (11)
zend_mm_heap corrupted
[Tue Jul 23 21:21:24 2013] [notice] caught SIGTERM, shutting down
I'm attaching the client log from an empty log, attempt to download
the file, wait for the error, copy the log. You will see the request
for the image, and then a little later on the email to me saying that
Apache was being restarted after a segfault.
All four devices tested cannot download the image.
Any ideas what's going wrong here?