General discussion on installation and configuration of SOGo

Text archives Help


Re: [SOGo] ActiveSync weirdness on 2.2.12a-1 and possibly other versions (bug???)


Chronological Thread 
  • From: Marcus Andree < >
  • To:
  • Subject: Re: [SOGo] ActiveSync weirdness on 2.2.12a-1 and possibly other versions (bug???)
  • Date: Mon, 22 Dec 2014 12:31:47 -0200

Hi, Thomas.

Thanks for your quick reply and for pointing me to the "ImapDebugEnabled" flag.

Here's the info you requested. The user in question has a plain new account. The older one was erased on Cyrus as a way to try to solve this issue. It has no IMAP subscriptions.

The single device listed corresponds to a Samsung TM-211 Tab 3 android tablet.

You can see the LIST "" "" command (IMAP command 5) clearly.
No e-mails are received on the tablet side and no email headers are seen travelling on the wire.

=========== sogo-tool
[root@t3v27i sogo]# sogo-tool -v manage-eas listdevices marcusmagalhaes
<0x0x1e714f8[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
<0x0x1e714f8[SOGoCache]> Using host(s) '127.0.0.1:11211' as server(s)
SEC1920C1536534C
[root@t3v27i sogo]# sogo-tool -v manage-eas listfolders marcusmagalhaes SEC1920C1536534C
<0x0xc7d568[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
<0x0xc7d568[SOGoCache]> Using host(s) '127.0.0.1:11211' as server(s)
Folder Key: SEC1920C1536534C+(null)
   Folder Name: Trash

   metadata Name: {displayName = Trash; }

Folder Key: SEC1920C1536534C+vevent/personal
   Folder Name: Calendário Pessoal

   metadata Name: {displayName = "Calend\U00E1rio Pessoal"; }

Folder Key: SEC1920C1536534C+vtodo/personal
   Folder Name: Calendário Pessoal

   metadata Name: {displayName = "Calend\U00E1rio Pessoal"; }

Folder Key: SEC1920C1536534C+vcard/personal
   Folder Name: Livro de Endereços Pessoais

   metadata Name: {DateCache = {}; SyncCache = {"FA2-5496F680-1-527CB300.vcf" = 1419179718; }; SyncKey = 1419179718; displayName = "Livro de Endere\U00E7os Pessoais"; }

==============================

sogo.log (with IMAP debug)

<after configuring a new exchange account on android>

2014-12-22 08:58:38.515 sogod[22869] WOCompoundElement: id logging is on.
Dec 22 08:58:38 sogod [22869]: |SOGo| request took 0.147720 seconds to execute
10.10.136.19 - - [22/Dec/2014:08:58:38 GMT] "GET /SOGo/so/ HTTP/1.1" 200 3967/0 0.150 11332 64% 640K
Dec 22 12:17:57 sogod [22869]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=OPTIONS&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:17:57.667 sogod[22869] ERROR(-[NGLdapSearchResultEnumerator nextObject]): does not support result references yet ..
2014-12-22 12:17:57.672 sogod[22869] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:17:57.698 sogod[22869] ERROR(-[NGLdapSearchResultEnumerator nextObject]): does not support result references yet ..
Dec 22 12:17:57 sogod [22869]: |SOGo| request took 0.069161 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:17:57 GMT] "OPTIONS /SOGo/Microsoft-Server-ActiveSync?Cmd=OPTIONS&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 0/0 0.124 - - 120K
Dec 22 12:17:57 sogod [22869]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:17:57.816 sogod[22869] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:17:57.921 sogod[22869] ERROR(-[NGLdapSearchResultEnumerator nextObject]): does not support result references yet ..
[0x7f5060c4b548]: 9 logout
S[0x7f5060d32b18]: * BYE LOGOUT received
S[0x7f5060d2ad68]: * OK IMAP4 ready
C[0x7f5060b948e8]: 1 login "marcusmagalhaes" "123Prodam"
S[0x7f5060d2ad68]: 1 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST X-REPLICATION URLAUTH URLAUTH=BINARY MUPDATE=mupdate://10.20.3.27/ LOGINDISABLED COMPRESS=DEFLATE IDLE] User logged in SESSIONID=<cyrus/frontend-23231-1419245917-1>
C[0x7f5060b948e8]: 2 capability
S[0x7f5060d2ad68]: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST X-REPLICATION URLAUTH URLAUTH=BINARY MUPDATE=mupdate://10.20.3.27/ LOGINDISABLED COMPRESS=DEFLATE IDLE
S[0x7f5060d2ad68]: 2 OK Completed
C[0x7f5060b948e8]: 3 ID ("x-originating-ip" "10.10.136.19")
S[0x7f5060d2ad68]: * ID NIL
S[0x7f5060d2ad68]: 3 OK Completed
C[0x7f5060b948e8]: 4 namespace
S[0x7f5060d2ad68]: * NAMESPACE (("" "/")) (("Outros Usu&AOE-rios/" "/")) (("Pastas P&APo-blicas/" "/"))
S[0x7f5060d2ad68]: 4 OK Completed
C[0x7f5060b948e8]: 5 LIST "" ""
S[0x7f5060d2ad68]: * LIST (\Noselect) "/" ""
S[0x7f5060d2ad68]: 5 OK Completed (0.000 secs)
C[0x7f5060b948e8]: 6 select "INBOX"
S[0x7f5060d2ad68]: * 31 EXISTS
S[0x7f5060d2ad68]: * 0 RECENT
S[0x7f5060d2ad68]: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
S[0x7f5060d2ad68]: * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok
S[0x7f5060d2ad68]: * OK [UNSEEN 1] Ok
S[0x7f5060d2ad68]: * OK [UIDVALIDITY 1419178472] Ok
S[0x7f5060d2ad68]: * OK [UIDNEXT 32] Ok
S[0x7f5060d2ad68]: * OK [HIGHESTMODSEQ 35] Ok
S[0x7f5060d2ad68]: * OK [URLMECH INTERNAL] Ok
S[0x7f5060d2ad68]: 6 OK [READ-WRITE] Completed
C[0x7f5060b948e8]: 7 expunge
S[0x7f5060d2ad68]: 7 OK Completed
C[0x7f5060b948e8]: 8 getquotaroot "INBOX"
S[0x7f5060d2ad68]: * QUOTAROOT INBOX
S[0x7f5060d2ad68]: 8 OK Completed
C[0x7f5060b948e8]: 9 logout
S[0x7f5060d2ad68]: * BYE LOGOUT received
S[0x7f5060d8c4f8]: * OK IMAP4 ready
C[0x7f5060d49d98]: 1 login "marcusmagalhaes" "123Prodam"
S[0x7f5060d8c4f8]: 1 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST X-REPLICATION URLAUTH URLAUTH=BINARY MUPDATE=mupdate://10.20.3.27/ LOGINDISABLED COMPRESS=DEFLATE IDLE] User logged in SESSIONID=<cyrus/frontend-25387-1419257878-1>
C[0x7f5060d49d98]: 2 capability
S[0x7f5060d8c4f8]: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST X-REPLICATION URLAUTH URLAUTH=BINARY MUPDATE=mupdate://10.20.3.27/ LOGINDISABLED COMPRESS=DEFLATE IDLE
S[0x7f5060d8c4f8]: 2 OK Completed
C[0x7f5060d49d98]: 3 ID ("x-originating-ip" "10.64.2.92")
S[0x7f5060d8c4f8]: * ID NIL
S[0x7f5060d8c4f8]: 3 OK Completed
C[0x7f5060d49d98]: 4 LIST "" ""
S[0x7f5060d8c4f8]: * LIST (\Noselect) "/" ""
S[0x7f5060d8c4f8]: 4 OK Completed (0.000 secs)
C[0x7f5060d49d98]: 5 LSUB "" "*"
S[0x7f5060d8c4f8]: 5 OK Completed (0.000 secs)
C[0x7f5060d49d98]: 6 namespace
S[0x7f5060d8c4f8]: * NAMESPACE (("" "/")) (("Outros Usu&AOE-rios/" "/")) (("Pastas P&APo-blicas/" "/"))
S[0x7f5060d8c4f8]: 6 OK Completed
C[0x7f5060d49d98]: 7 LSUB "" "Outros Usu&AOE-rios/*"
S[0x7f5060d8c4f8]: 7 OK Completed (0.000 secs)
C[0x7f5060d49d98]: 8 LSUB "" "Pastas P&APo-blicas/*"
S[0x7f5060d8c4f8]: 8 OK Completed (0.000 sDec 22 12:18:02 sogod [22869]: |SOGo| request took 4.966094 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:18:02 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 401/13 4.968 - - 448K


<now the tablet presents a screen where the user can set options such as sync periods and peak/off peak schedule>

Dec 22 12:19:54 sogod [22869]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=OPTIONS&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:19:54.656 sogod[22869] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
Dec 22 12:19:54 sogod [22869]: |SOGo| request took 0.005520 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:19:54 GMT] "OPTIONS /SOGo/Microsoft-Server-ActiveSync?Cmd=OPTIONS&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 0/0 0.008 - - 0
Dec 22 12:19:56 sogod [22869]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:19:56.747 sogod[22869] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
Dec 22 12:19:57 sogod [22869]: |SOGo| request took 0.510437 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:19:57 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 401/13 0.515 - - 0
Dec 22 12:19:59 sogod [22869]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Settings&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:19:59.304 sogod[22869] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
Dec 22 12:19:59 sogod [22869]: |SOGo| request took 0.003760 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:19:59 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Settings&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 19/131 0.006 - - 4K
Dec 22 12:20:00 sogod [22869]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:20:00.056 sogod[22869] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:20:00.426 sogod[22869] Sleeping 30 seconds while detecting changes...
Dec 22 12:20:00 sogod [22855]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:20:00.703 sogod[22855] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:20:00.747 sogod[22855] Change detected, we push the content.
Dec 22 12:20:00 sogod [22855]: |SOGo| request took 0.045837 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:20:00 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 50/35 0.049 - - 400K
Dec 22 12:20:00 sogod [22855]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:20:00.801 sogod[22855] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:20:00.806 sogod[22855] Change detected, we push the content.
Dec 22 12:20:00 sogod [22855]: |SOGo| request took 0.006656 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:20:00 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 54/36 0.008 - - 0
Dec 22 12:20:02 sogod [22855]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
2014-12-22 12:20:02.177 sogod[22855] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:20:02.184 sogod[22855] Change detected, we push the content.
Dec 22 12:20:02 sogod [22855]: |SOGo| request took 0.007611 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:20:02 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 53/35 0.010 - - 48K
Dec 22 12:20:02 sogod [22853]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
Dec 22 12:20:02 sogod [22855]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'2014-12-22 12:20:02.574 sogod[22853] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'

2014-12-22 12:20:02.575 sogod[22855] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:20:02.592 sogod[22855] Sleeping 30 seconds while detecting changes...
Dec 22 12:20:02 sogod [22853]: [WARN] <0x0x7f5060ba6788[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Dec 22 12:20:02 sogod [22853]: [WARN] <0x0x7f5060ba6788[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Dec 22 12:20:02 sogod [22853]: [WARN] <0x0x7f5060ba6788[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
2014-12-22 12:20:02.638 sogod[22853] Sleeping 30 seconds while detecting changes...
Dec 22 12:20:04 sogod [22860]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M'
Dec 22 12:20:04 sogod [22860]: <0x0x7f5060a29748[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Dec 22 12:20:04 sogod [22860]: <0x0x7f5060a29748[SOGoCache]> Using host(s) '127.0.0.1:11211' as server(s)
2014-12-22 12:20:04.820 sogod[22860] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='SAMSUNG-SM-T211M/100.40102'
2014-12-22 12:20:04.859 sogod[22860] Note(SoObject): SoDebugKeyLookup is enabled!
2014-12-22 12:20:04.859 sogod[22860] Note(SoObject): SoDebugBaseURL is enabled!
2014-12-22 12:20:04.859 sogod[22860] Note(SoObject): relative base URLs are enabled.
2014-12-22 12:20:04.953 sogod[22860] Note: Using UTF-8 as URL encoding in NGExtensions.
2014-12-22 12:20:05.050 sogod[22860] Change detected, we push the content.
Dec 22 12:20:05 sogod [22860]: |SOGo| request took 0.268662 seconds to execute
10.64.2.92 - - [22/Dec/2014:12:20:05 GMT] "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=marcusmagalhaes&DeviceId=SEC1920C1536534C&DeviceType=SAMSUNGSMT211M HTTP/1.1" 200 181/64 0.296 - - 4M



On Mon, Dec 22, 2014 at 5:25 AM, Thomas Fuehrer < > wrote:
Von: [mailto: ] Im Auftrag von Marcus Andree
Gesendet: Montag, 22. Dezember 2014 00:50
An:
Betreff: [SOGo] ActiveSync weirdness on 2.2.12a-1 and possibly other versions (bug???)

Hi, guys,
I've been tracking an issue with activesync and sogo on a demo project due to be ready in a week or so. Got a few virtual machines running Centos 6.5 x64. The complete setup is complex and includes:

Cyrus IMAP + Murder Aggregator (2 frontends, 2 backends and 2 mupdate's)
Apache
SOGo (first 2.2.9a, then 2.2.12a-1)
Win 2k8 + AD/LDAP (authentication)
SASL
Postfix
Nginx acting as IMAP proxy

Cyrus had to be upgraded to 2.4 in order to work properly with SOGo's activesync module. After some initial problems with no sufficient clients to test a single user (i.e., me), the number of workers was raised to a safe value (30).
Contact lists are sync'ing via ActiveSync, but had no luck so far with e-mails.
They simply refuse to synchronize.
When I was running 2.2.9a, was able to see the contents of all mail folders except INBOX (after a long time syncing, despite having only about 60 e-mail messages). The messages were sync' ing on mobile a Samsung TAB 3 and an iPad Mini.

Decided to upgrade from 2.2.9a to 2.2.12a-1, but no luck. After several hours trying to track the source of this problem, some tcpdump logs were set, after reversing imaps and https to imap and http. These logs were showing a "NO Mailbox does not exist"  between Cyrus and SOGo.

 These logs had also shown that SOGo was sending two unusual (wrong?) commands to Cyrus:
1) LIST "" ""
2) status "(null)" (UIDVALIDITY)

The command #2 above is, apparently, the source of the error message.
It _seems_ that the results of the first LIST command (nothing/null/no folders) are being used as (1) source of folders to sync and (2)  build the status command and this is causing the folders not to be sync'ed...

Can't say for sure if this error comes from my setup, so I'd appreciate if some SOGo guru with more-than-average knowledge about the source could check this...
Thanks.

================

Hi Marcus!

Please post an excerpt of sogo.log with ImapDebugEnabled set to YES  and the output of:

sogo-tool -v  manage-eas  listdevices <user-id>
sogo-tool -v  manage-eas  listfolders <user-id> <device-id>

Regards,
Thomas

--

https://inverse.ca/sogo/lists




Archive powered by MHonArc 2.6.18.

Top of page