6.0.0-git
2019-03-18

[#12544] Activesync fails to sync inbox if sms upload from device
Summary Activesync fails to sync inbox if sms upload from device
Queue Synchronization
Queue Version Git master
Type Bug
State Resolved
Priority 2. Medium
Owners mrubinsk (at) horde (dot) org
Requester carlos.velasco (at) nimastelecom (dot) com
Created 2013-08-07 (2049 days ago)
Due
Updated 2013-08-12 (2044 days ago)
Assigned 2013-08-12 (2044 days ago)
Resolved 2013-08-12 (2044 days ago)
Milestone
Patch No

History
2013-08-12 21:23:42 Michael Rubinsky State ⇒ Resolved
 
2013-08-12 21:10:16 carlos (dot) velasco (at) nimastelecom (dot) com Comment #9 Reply to this comment
Yes, it seems working fine now
2013-08-12 18:31:22 Michael Rubinsky Comment #8
State ⇒ Feedback
Reply to this comment
Does this fix?
2013-08-12 18:30:23 Git Commit Comment #7 Reply to this comment
Changes have been made in Git (master):

commit e2232047c1152cd6ca10154cc4714689251fb82d
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Mon Aug 12 13:35:35 2013 -0400

     Bug: 12544 Output the CLASS_SMS value like Exchange does.

  .../lib/Horde/ActiveSync/Request/Sync.php          |    7 +++++++
  1 files changed, 7 insertions(+), 0 deletions(-)

http://git.horde.org/horde-git/-/commit/e2232047c1152cd6ca10154cc4714689251fb82d
2013-08-10 16:21:43 carlos (dot) velasco (at) nimastelecom (dot) com Comment #6
New Attachment: smshorde.txt Download
Reply to this comment
And the debugs in Horde.

2013-08-10 16:20:44 carlos (dot) velasco (at) nimastelecom (dot) com Comment #5
New Attachment: smsexchange.txt Download
Reply to this comment
Making more tests, it seems that *after* sms I got email dups in 
device. All new incoming mail is duplicated 3 times in the device.

Looking into debugs and traces I can't find why, it seems Horde is 
replying fine and device does not complain.

So I tested same issue against Exchange 2013. The only difference I 
*think* that could make a difference is a "Class" output in the 
exchange server reply.

             4 | Tag   | T   0    |   Known Tag 0x07           (.C) |   
         <Add>
             5 | Tag   | T   0    |   Known Tag 0x10           (.C) |   
           <Class>
             5 | Tag   | T   0    | STR_I (Inline string)           |   
           'SMS'
             5 | Tag   | T   0    | END (Known Tag 0x10)            |   
           </Class>

I'm uploading the Exchange server decodes of input and ouput packets 
of a SMS, and also uploading debugs of Horde with another SMS.

2013-08-08 03:33:54 Michael Rubinsky State ⇒ Resolved
 
2013-08-08 00:29:57 carlos (dot) velasco (at) nimastelecom (dot) com Comment #4 Reply to this comment
Does this fix?

None of my Android test devices seem to even support SMS sync at all...
I think so, in a quick test It does not give error and Return status is 1.

2013-08-08T01:36:16+02:00 DEBUG: [29141] I      <Add>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I       <FolderType>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         SMS
2013-08-08T01:36:16+02:00 DEBUG: [29141] I       </FolderType>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I       <ClientEntryId>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         SMS_1375918573071
2013-08-08T01:36:16+02:00 DEBUG: [29141] I       </ClientEntryId>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I       <Data>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        <POOMMAIL:To>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        </POOMMAIL:To>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        <POOMMAIL:From>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I          xxxxxxxxxx
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        </POOMMAIL:From>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        <POOMMAIL:DateReceived>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I          2013-08-07T23:36:13.000Z
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        </POOMMAIL:DateReceived>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        <POOMMAIL:Importance>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I          1
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        </POOMMAIL:Importance>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        <POOMMAIL:Read>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I          0
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        </POOMMAIL:Read>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        <AirSyncBase:Body>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         <AirSyncBase:Type>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I           1
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         </AirSyncBase:Type>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         
<AirSyncBase:EstimatedDataSize>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I           48
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         
</AirSyncBase:EstimatedDataSize>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         <AirSyncBase:Data>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I           xxxxxxxxxxxxxxxxxxxxxxxx.
2013-08-08T01:36:16+02:00 DEBUG: [29141] I         </AirSyncBase:Data>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I        </AirSyncBase:Body>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I       </Data>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I      </Add>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I     </Commands>
2013-08-08T01:36:16+02:00 INFO: [29141] Processed 1 incoming changes
2013-08-08T01:36:16+02:00 DEBUG: [29141] I    </Folder>
2013-08-08T01:36:16+02:00 INFO: [29141] Collection added to collection 
handler: collection: INBOX, synckey: 
{5202d35a-24d4-4bb9-a959-71d55570088c}5.
2013-08-08T01:36:16+02:00 DEBUG: [29141] I   </Folders>
2013-08-08T01:36:16+02:00 DEBUG: [29141] I  </Synchronize>
2013-08-08T01:36:16+02:00 INFO: Have syncable collections
2013-08-08T01:36:16+02:00 INFO: [29141] Replacing SYNC_CACHE entry for 
user xxxxxxxxxxxxxxxxxxxx and device xxxxxxxx
...
2013-08-08T01:36:16+02:00 INFO: All synckeys confirmed. Continuing with SYNC
2013-08-08T01:36:16+02:00 DEBUG: [29141] O  <Synchronize>
2013-08-08T01:36:16+02:00 DEBUG: [29141] O   <Status>
2013-08-08T01:36:16+02:00 DEBUG: [29141] O    1
2013-08-08T01:36:16+02:00 DEBUG: [29141] O   </Status>

2013-08-07 22:46:59 Michael Rubinsky Comment #3
Assigned to Michael Rubinsky
State ⇒ Feedback
Reply to this comment
Does this fix?

None of my Android test devices seem to even support SMS sync at all...
2013-08-07 22:45:49 Git Commit Comment #2 Reply to this comment
Changes have been made in Git (master):

commit e8206ea53cce2c052c267dd5f60e7c83383beef1
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Wed Aug 7 18:45:13 2013 -0400

     Parse incoming SMS messages, even if we ignore them.

     Bug: 12544

  framework/ActiveSync/lib/Horde/ActiveSync.php      |    1 +
  .../lib/Horde/ActiveSync/Connector/Importer.php    |   13 ++++++++++++-
  .../lib/Horde/ActiveSync/Request/Sync.php          |    8 +++++++-
  3 files changed, 20 insertions(+), 2 deletions(-)

http://git.horde.org/horde-git/-/commit/e8206ea53cce2c052c267dd5f60e7c83383beef1
2013-08-07 21:26:39 carlos (dot) velasco (at) nimastelecom (dot) com Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 2. Medium
Summary ⇒ Activesync fails to sync inbox if sms upload from device
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
New Attachment: sync_add_sms.txt Download
Reply to this comment
First of all, I really don't know if sms syncing works in horde, but 
it is activated by default in Android.

When device place SMS in Inbox it tries to upload it through 
ActiveSync. Horde fails with error "Unmatched end tag" and sends 
Status 4, this breaks the Email sync, no new mail is synced after this 
error.

Related somehow to Bug: 12281

AS logs:
2013-08-07T22:48:40+02:00 DEBUG: [483] I     <Commands>
2013-08-07T22:48:40+02:00 INFO: [483] Obtaining collection class of 
Email for collection id 6b55a45a
2013-08-07T22:48:40+02:00 INFO: [483] Initializing state for 
collection: INBOX, synckey: {52026a83-5f34-41de-96d2-6e395570088c}5
2013-08-07T22:48:40+02:00 INFO: [483] Loading state for synckey 
{52026a83-5f34-41de-96d2-6e395570088c}5
2013-08-07T22:48:40+02:00 DEBUG: [483] I      <Add>
2013-08-07T22:48:40+02:00 DEBUG: [483] I       <FolderType>
2013-08-07T22:48:40+02:00 DEBUG: [483] I         SMS
2013-08-07T22:48:40+02:00 DEBUG: [483] I       </FolderType>
2013-08-07T22:48:40+02:00 DEBUG: [483] I       <ClientEntryId>
2013-08-07T22:48:40+02:00 DEBUG: [483] I         SMS_1375894660369
2013-08-07T22:48:40+02:00 DEBUG: [483] I       </ClientEntryId>
2013-08-07T22:48:40+02:00 DEBUG: [483] I       <Data>
2013-08-07T22:48:40+02:00 DEBUG: [483] I        <POOMMAIL:To>
2013-08-07T22:48:40+02:00 ERR: [483] Unmatched end tag:
2013-08-07T22:48:40+02:00 ERR: Array
(
     [1] => 1
     [2] => POOMMAIL:To
     [4] => 1
)

2013-08-07T22:48:40+02:00 DEBUG: [483] O  <Synchronize>
2013-08-07T22:48:40+02:00 DEBUG: [483] O   <Status>
2013-08-07T22:48:40+02:00 DEBUG: [483] O    4
2013-08-07T22:48:40+02:00 DEBUG: [483] O   </Status>
2013-08-07T22:48:40+02:00 DEBUG: [483] O  </Synchronize>

The decoded TCP packet shows a "To" field empty:
             5 | Tag   | T   0    |   Known Tag 0x0C           (.C) |   
           <ClientId>
             5 | Tag   | T   0    | STR_I (Inline string)           |   
           'SMS_1375894660369'
             5 | Tag   | T   0    | END (Known Tag 0x0C)            |   
           </ClientId>
             5 | Tag   | T   0    |   Known Tag 0x1D           (.C) |   
           <ApplicationData>
               | Tag   | T -->  2 | SWITCH_PAGE (Tag code page)     |
             6 | Tag   | T   2    |   Known Tag 0x16           (.C) |   
             <To>
             6 | Tag   | T   2    | STR_I (Inline string)           |   
             ''
             6 | Tag   | T   2    | END (Known Tag 0x16)            |   
             </To>
             6 | Tag   | T   2    |   Known Tag 0x18           (.C) |   
             <From>
             6 | Tag   | T   2    | STR_I (Inline string)           |   
             '555555555'
             6 | Tag   | T   2    | END (Known Tag 0x18)            |   
             </From>

Uploading full decoded Sync request (some data changed for privacy).

Saved Queries