[horde] AS Mailbox not pushing new email

[Simon Wilson]

> Quoting Simon Wilson <simon at simonandkate.net>> AS 2.3.0
>> 
>> I had a meeting invitation sent to me, and it appeared in my Imp mailbox at
>> 11:49:23am.
>> 
>> My iOS devices are set to read Horde email over ActiveSync, and are set to
>> server push.
>> 
>> $conf[activesync][ping][heartbeatmax] is set to standard 2700, so at over
>> 2700 seconds worst-case scenarion it should have pushed, right?
>> 
>> It is now 3060 seconds later, and the push has not happened. Device has
>> been sync'ing as follows:
>> 
>> 2013-03-02T02:38:26+00:00 INFO: [6586] Horde_Core_ActiveSync_Driver::authenticate() attempt for simon
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] PING request received for user simon
>> 2013-03-02T02:38:26+00:00 DEBUG: [Appl79030T3BA4S] loadDeviceInfo: simon
>> 2013-03-02T02:38:26+00:00 INFO: Request being handled for device: Appl79030T3BA4S Supporting protocol version: 12.1
>> 2013-03-02T02:38:26+00:00 INFO: [6586] Handling PING command received at timestamp: 1362191906.
>> 2013-03-02T02:38:26+00:00 DEBUG: Reusing PING state: Array
>> (
>>    [@Contacts@] => Array
>>        (
>>            [class] => Contacts
>>            [windowsize] => 25
>>            [deletesasmoves] =>
>>            [filtertype] =>
>>            [truncation] => 0
>>            [rtftruncation] =>
>>            [mimesupport] => 0
>>            [mimetruncation] =>
>>            [conflict] => 1
>>            [bodyprefs] => Array
>>                (
>>                    [wanted] => 1
>>                    [1] => Array
>>                        (
>>                            [type] => 1
>>                            [truncationsize] => 32768
>>                        )
>> 
>>                )
>> 
>>            [lastsynckey] => {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>>            [pingable] => 1
>>            [id] => @Contacts@
>>            [synckey] => {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>>        )
>> 
>>    [@Tasks@] => Array
>>        (
>>            [class] => Tasks
>>            [windowsize] => 25
>>            [deletesasmoves] =>
>>            [filtertype] =>
>>            [truncation] => 0
>>            [rtftruncation] =>
>>            [mimesupport] =>
>>            [mimetruncation] =>
>>            [conflict] => 1
>>            [bodyprefs] => Array
>>                (
>>                    [wanted] => 1
>>                    [1] => Array
>>                        (
>>                            [type] => 1
>>                            [truncationsize] => 32768
>>                        )
>> 
>>                )
>> 
>>            [lastsynckey] => {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>>            [id] => @Tasks@
>>            [pingable] => 1
>>            [synckey] => {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>>        )
>> 
>>    [@Calendar@] => Array
>>        (
>>            [class] => Calendar
>>            [windowsize] => 25
>>            [deletesasmoves] =>
>>            [filtertype] => 4
>>            [truncation] => 0
>>            [rtftruncation] =>
>>            [mimesupport] =>
>>            [mimetruncation] =>
>>            [conflict] => 1
>>            [bodyprefs] => Array
>>                (
>>                    [wanted] => 1
>>                    [1] => Array
>>                        (
>>                            [type] => 1
>>                            [truncationsize] => 32768
>>                        )
>> 
>>                )
>> 
>>            [lastsynckey] => {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>>            [pingable] => 1
>>            [id] => @Calendar@
>>            [synckey] => {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>>        )
>> 
>> )
>> 
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Waiting for changes (heartbeat interval: 900)
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Initializing message diff engine for @Contacts@
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191906, 0, 1)
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Found 0 message changes in @Contacts at .
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Initializing message diff engine for @Tasks@
>> 2013-03-02T02:38:26+00:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191906, 0, 1)
>> 2013-03-02T12:38:26+10:00 DEBUG: [6586] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:38:26+10:00 DEBUG: [6586] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:38:26+10:00 DEBUG: [6586] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:38:26+10:00 DEBUG: [6586] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:38:26+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191906, 1360982306, 1)
>> 2013-03-02T12:38:26+10:00 DEBUG: [6586] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191933, 0, 1)
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191933, 0, 1)
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191933, 1360982333, 1)
>> 2013-03-02T12:38:53+10:00 DEBUG: [6589] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:38:56+10:00 DEBUG: [6586] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:38:56+10:00 DEBUG: [6586] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:38:56+10:00 DEBUG: [6586] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:38:56+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191936, 0, 1)
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191937, 0, 1)
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191937, 1360982337, 1)
>> 2013-03-02T12:38:57+10:00 DEBUG: [6586] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191963, 0, 1)
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191963, 0, 1)
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191963, 1360982363, 1)
>> 2013-03-02T12:39:23+10:00 DEBUG: [6589] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191967, 0, 1)
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191967, 0, 1)
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191967, 1360982367, 1)
>> 2013-03-02T12:39:27+10:00 DEBUG: [6586] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191993, 0, 1)
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191993, 0, 1)
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191993, 1360982393, 1)
>> 2013-03-02T12:39:53+10:00 DEBUG: [6589] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362191997, 0, 1)
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362191997, 0, 1)
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362191997, 1360982397, 1)
>> 2013-03-02T12:39:57+10:00 DEBUG: [6586] Found 0 message changes in @Calendar at .
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Initializing state for collection: @Contacts@, synckey: {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Loading state for synckey {5125e673-2ae8-4495-abe1-25bcc0a801e6}16
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Initializing message diff engine for @Contacts@
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1361438476, 1362192023, 0, 1)
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Found 0 message changes in @Contacts at .
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Initializing state for collection: @Tasks@, synckey: {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Loading state for synckey {5125e69b-fe7c-4f6f-bcab-22bfc0a801e6}4
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Initializing message diff engine for @Tasks@
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1361493185, 1362192023, 0, 1)
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Found 0 message changes in @Tasks at .
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Initializing state for collection: @Calendar@, synckey: {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Loading state for synckey {5125e694-0130-4f7f-8c10-25bfc0a801e6}34
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Initializing message diff engine for @Calendar@
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1362186939, 1362192023, 1360982423, 1)
>> 2013-03-02T12:40:23+10:00 DEBUG: [6589] Found 0 message changes in @Calendar at .
>> 
>> etc...
>> 
>> When I then go into Mail on the iPhone, it then prompts a full HUGE sync (the sync file for the next transaction is over 700KB - I will send to you directly if needed, but it contains a info I'd rather not post publicly).
>> 
>> So, push mail is not working for me, although apart from that I LOVE the new improvements to calendaring appointments and invites - Brilliant, thank you so much!
>> 
>> Simon
>> 
>> 
>> 
>> --
>> Simon Wilson
>> M: 0400 12 11 16
> Your device simply is not polling the INBOX. I've seen this happen sometime s on iOS. Usually it's from then user manually pressing refresh. It takes until the next full PING request to catch up.
> 
> mike
> Sent from mobile
> 
> Simon Wilson <simon at simonandkate.net> wrote:
> 

Thanks Michael. 

My MS exchange mailboxes push constantly.

This morning when I went into mail on the iPhone, there were no new mails in my horde AS inbox (and several in the other 2 Exchange boxes). Then it auto refreshed as it does when you go into it, and 10 emails appeared. That's 10 hours since I last touched the device. 

Simon.