Erreur "SyncStorage WARN - SyncKey not found" et perte synchro android

psyray · October 5, 2015, 1:12pm

Bonjour,

J’ai monté un serveur BM 3.0.24 sur Debian Jessie 64 (VM KVM, 1socket/8cores avec 8G de RAM et 100Go de disque sur du SAN-iSCSI HA, LAN 1Go).
Ce serveur sert de serveur mail pour ma société (SSII) ainsi que pour nos clients (~120 comptes mail)
Niveau unité, les clients se servent uniquement de la partie email, donc ~ 120 unités
Pour l’instant je suis le seul à me servir de la fonctionnalité EAS car je n’arrive pas à la faire fonctionner de manière convenable du fait de ce problème.
Je ne la propose donc pas encore à mes clients, mais j’aimerai le faire assez rapidement.

Pour installer le serveur j’ai suivi la procédure d’install de blue-mind et respecté tous les pré-requis (locale, hostname).
J’ai migré tous les emails de notre ancien serveur (Postfix + Dovecot) vers BM en utilisant l’API de BM (et un script python) pour créer les comptes et en utilisant imapsync pour le contenu des boîtes.

Tout fonctionne très bien sauf la partie EAS, qui ne fonctionne qu’à moitié (sur Android 5.1 en tout cas).

J’ai essayé avec la synchro Exchange de base fourni avec Android 5.1 et le client Mail de base aussi.
Config OK, les emails, contacts et adresses se synchronise correctement, mais, pour une raison qui m’échappe, la synchro se perd puis une full sync est de nouveau initiée.
Le résultat est :

Dans l’agenda, les agendas EAS s’affichent puis ne s’affichent plus, puis s’affichent …
Dans les contacts idem
Et les emails, ils sont sans cesse en train de se re-synchroniser.

J’ai essayé avec le client exchange Nine, idem, MailWise idem …

Les erreurs qui remontent au niveau du serveur lors d’une perte de synchro sont les suivantes (j’ai remplacé l’email par no@email.com) :

2015-10-05 12:22:09,759 n.b.e.i.SyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 12:22:09,760 n.b.e.s.j.SyncStorage WARN - SyncKey not found: b45172d1-cf65-4247-a428-f7a5ce63e065
2015-10-05 12:22:09,761 n.b.e.i.SyncHandler ERROR - Collection with id[24119] can not be found.
net.bluemind.eas.exception.CollectionNotFoundException: Collection with id[24119] can not be found.
	at net.bluemind.eas.storage.jdbc.SyncStorage.getCollectionPath(SyncStorage.java:461) ~[na:na]
	at net.bluemind.eas.state.StateMachine.getSyncState(StateMachine.java:83) ~[net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.impl.SyncHandler.processCollection(SyncHandler.java:573) ~[net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.impl.SyncHandler.process(SyncHandler.java:123) ~[net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.impl.WbxmlRequestHandler.process(WbxmlRequestHandler.java:107) [net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.ActiveSyncServlet.processActiveSyncMethod(ActiveSyncServlet.java:357) [net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.ActiveSyncServlet.service(ActiveSyncServlet.java:231) [net.bluemind.eas_1.0.0.b13439.jar:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) [javax.servlet_2.5.0.v201103041518.jar:na]
	at org.eclipse.equinox.http.registry.internal.ServletManager$ServletWrapper.service(ServletManager.java:180) [org.eclipse.equinox.http.registry_1.1.100.v20110502.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61) [org.eclipse.equinox.http.servlet_1.1.200.v20110502.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:126) [org.eclipse.equinox.http.servlet_1.1.200.v20110502.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:60) [org.eclipse.equinox.http.servlet_1.1.200.v20110502.jar:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) [javax.servlet_2.5.0.v201103041518.jar:na]
	at org.eclipse.equinox.http.jetty.internal.HttpServerManager$InternalHttpServiceServlet.service(HttpServerManager.java:317) [org.eclipse.equinox.http.jetty_2.0.100.v20110502.jar:na]
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:390) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.Server.handle(Server.java:326) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:939) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582) [org.mortbay.jetty.util_6.1.23.v201012071420.jar:na]
2015-10-05 12:22:09,761 n.b.e.i.SyncHandler ERROR - Error response for requestId: 8567
2015-10-05 12:22:09,761 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Status>8</Status>
</Sync>

2015-10-05 12:22:10,218 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 12:22:10,218 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: FolderSync
2015-10-05 12:22:10,218 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 12:22:10,219 n.b.e.i.FolderSyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><FolderSync>
<SyncKey>df797f18-55c5-4ac3-a283-3aa31a8b89cd</SyncKey>
</FolderSync>

2015-10-05 12:22:10,219 n.b.e.i.FolderSyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 12:22:10,219 n.b.e.i.FolderSyncHandler ERROR - SyncState is not valid. Send Invalid SyncKey to device Mailwise1932040915120121009, key: df797f18-55c5-4ac3-a283-3aa31a8b89cd, Data Type:FOLDER
2015-10-05 12:22:10,220 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><FolderSync>
<Status>9</Status>
</FolderSync>

2015-10-05 12:22:10,408 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 12:22:10,408 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: Sync
2015-10-05 12:22:10,408 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 12:22:10,410 n.b.e.i.SyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>c72f732f-9868-41dd-a574-63bfea6b21e6</SyncKey>
<CollectionId>24136</CollectionId>
<DeletesAsMoves>1</DeletesAsMoves>
<GetChanges/>
<WindowSize>5</WindowSize>
<Options>
<FilterType>0</FilterType>
<BodyPreference>
<Type>4</Type>
<TruncationSize>20000</TruncationSize>
</BodyPreference>
<MIMESupport>2</MIMESupport>
</Options>
</Collection>
</Collections>
</Sync>

2015-10-05 12:22:10,410 n.b.e.i.SyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 12:22:10,410 n.b.e.s.j.SyncStorage WARN - SyncKey not found: c72f732f-9868-41dd-a574-63bfea6b21e6
2015-10-05 12:22:10,411 n.b.e.i.SyncHandler ERROR - Collection with id[24136] can not be found.
net.bluemind.eas.exception.CollectionNotFoundException: Collection with id[24136] can not be found.
	at net.bluemind.eas.storage.jdbc.SyncStorage.getCollectionPath(SyncStorage.java:461) ~[na:na]
	at net.bluemind.eas.state.StateMachine.getSyncState(StateMachine.java:83) ~[net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.impl.SyncHandler.processCollection(SyncHandler.java:573) ~[net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.impl.SyncHandler.process(SyncHandler.java:123) ~[net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.impl.WbxmlRequestHandler.process(WbxmlRequestHandler.java:107) [net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.ActiveSyncServlet.processActiveSyncMethod(ActiveSyncServlet.java:357) [net.bluemind.eas_1.0.0.b13439.jar:na]
	at net.bluemind.eas.ActiveSyncServlet.service(ActiveSyncServlet.java:231) [net.bluemind.eas_1.0.0.b13439.jar:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) [javax.servlet_2.5.0.v201103041518.jar:na]
	at org.eclipse.equinox.http.registry.internal.ServletManager$ServletWrapper.service(ServletManager.java:180) [org.eclipse.equinox.http.registry_1.1.100.v20110502.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61) [org.eclipse.equinox.http.servlet_1.1.200.v20110502.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:126) [org.eclipse.equinox.http.servlet_1.1.200.v20110502.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:60) [org.eclipse.equinox.http.servlet_1.1.200.v20110502.jar:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) [javax.servlet_2.5.0.v201103041518.jar:na]
	at org.eclipse.equinox.http.jetty.internal.HttpServerManager$InternalHttpServiceServlet.service(HttpServerManager.java:317) [org.eclipse.equinox.http.jetty_2.0.100.v20110502.jar:na]
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:390) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.Server.handle(Server.java:326) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:939) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) [org.mortbay.jetty.server_6.1.23.v201012071420.jar:na]
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582) [org.mortbay.jetty.util_6.1.23.v201012071420.jar:na]
2015-10-05 12:22:10,412 n.b.e.i.SyncHandler ERROR - Error response for requestId: 8569
2015-10-05 12:22:10,412 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Status>8</Status>
</Sync>

2015-10-05 12:22:11,041 n.b.e.ActiveSyncServlet INFO - q: null pending: false resumed: false m: OPTIONS num:8571
2015-10-05 12:22:11,188 n.b.e.ActiveSyncServlet INFO - q: Cmd=FolderSync&User=no%40email.com&DeviceId=Mailwise1932040915120121009&DeviceType=Android pending: false resumed: false m: POST num:8572
2015-10-05 12:22:11,216 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 12:22:11,217 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: FolderSync
2015-10-05 12:22:11,217 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 12:22:11,218 n.b.e.i.FolderSyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><FolderSync>
<SyncKey>0</SyncKey>
</FolderSync>

2015-10-05 12:22:11,218 n.b.e.i.FolderSyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 12:22:11,218 n.b.e.b.b.BMBackend INFO - [no@email.com] resetForFullSync devId: 'no@email.com::Mailwise1932040915120121009'
2015-10-05 12:22:11,222 n.b.e.s.j.SyncStorage INFO - mappings & states cleared for full sync of device no@email.com::Mailwise1932040915120121009. 173 sent items, 15 sync state, 173 sync mail, 55 folder mapping
2015-10-05 12:22:11,223 n.b.p.x.i.ConnectionPool INFO - already closed.
2015-10-05 12:22:11,573 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><FolderSync>
<Status>1</Status>
<SyncKey>d2e4e554-cc77-4695-9296-2556f88c2a8b</SyncKey>
<Changes>
<Count>179</Count>
<Add>
<ServerId>24353</ServerId>
<ParentId>0</ParentId>
<DisplayName>User name</DisplayName>
<Type>8</Type>
</Add>
<Add>
<ServerId>24354</ServerId>
<ParentId>0</ParentId>
<DisplayName>Boîte de réception</DisplayName>
<Type>2</Type>
</Add>
<Add>
<ServerId>24355</ServerId>
<ParentId>0</ParentId>
<DisplayName>Archives</DisplayName>
<Type>12</Type>
</Add>
<Add>
<ServerId>24356</ServerId>
<ParentId>24355</ParentId>
<DisplayName>2012</DisplayName>
<Type>12</Type>
</Add>
<Add>
<ServerId>24357</ServerId>
<ParentId>0</ParentId>
<DisplayName>Brouillon</DisplayName>
<Type>12</Type>
</Add>

J’ai redémarré le serveur, même problème.

Je n’arrive donc pas à avoir une synchro EAS stable.

Lorsque cela se passe bien j’ai ce log là

2015-10-05 13:02:39,340 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 13:02:39,340 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: FolderSync
2015-10-05 13:02:39,340 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 13:02:39,341 n.b.e.i.FolderSyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><FolderSync>
<SyncKey>16f0e817-8bba-428e-9203-2405ae6635ba</SyncKey>
</FolderSync>

2015-10-05 13:02:39,341 n.b.e.i.FolderSyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 13:02:39,431 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><FolderSync>
<Status>1</Status>
<SyncKey>445c6812-61b0-4aa7-9ab9-306d0518ef21</SyncKey>
<Changes>
<Count>0</Count>
</Changes>
</FolderSync>

2015-10-05 13:02:39,442 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 13:02:39,442 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: Sync
2015-10-05 13:02:39,442 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 13:02:39,443 n.b.e.i.SyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>718732af-64f8-41f8-859a-82f5094211fa</SyncKey>
<CollectionId>24598</CollectionId>
<DeletesAsMoves>1</DeletesAsMoves>
<GetChanges/>
<WindowSize>5</WindowSize>
<Options>
<FilterType>0</FilterType>
<BodyPreference>
<Type>4</Type>
<TruncationSize>20000</TruncationSize>
</BodyPreference>
<MIMESupport>2</MIMESupport>
</Options>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:39,443 n.b.e.i.SyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 13:02:39,444 n.b.e.b.b.m.MailBackend INFO - Collection: bm:\\no@email.com\email\INBOX
2015-10-05 13:02:39,478 n.b.e.b.b.m.EmailCacheStorage INFO - Device wants mail delivered after or re-flagged after 2015-10-05 12:39:21.0 UNFILTERED
2015-10-05 13:02:39,479 n.b.e.b.b.m.EmailCacheStorage INFO - changes: received: 0 flag: 0 removed: 0
2015-10-05 13:02:39,479 n.b.e.b.b.m.EmailCacheStorage INFO - [no@email.com]: collectionId [24598] 0 changes found. (17ms (loadCache: 2ms, imap: 13ms (1009 mails), updCache: 1ms, computeChanges: 1ms))
2015-10-05 13:02:39,482 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:39,482 n.b.e.b.b.m.MailBackend INFO - pre-marked some items (0) we will never send to the device
2015-10-05 13:02:39,482 n.b.e.b.b.ContentsExporter INFO - Get changed from 2015-10-05 12:39:21.0 on collectionId:24598, type: EMAIL
2015-10-05 13:02:39,482 n.b.e.i.SyncHandler INFO - WindowSize is 5. Send 0 change(s)
2015-10-05 13:02:39,483 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>ea42b93c-5db3-470f-8117-a6a0709252de</SyncKey>
<CollectionId>24598</CollectionId>
<Status>1</Status>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:39,486 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:39,820 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 13:02:39,820 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: Sync
2015-10-05 13:02:39,820 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 13:02:39,821 n.b.e.i.SyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>7b61d547-bda6-4da4-a59d-8d4bb840ac5b</SyncKey>
<CollectionId>24615</CollectionId>
<DeletesAsMoves>1</DeletesAsMoves>
<GetChanges/>
<WindowSize>5</WindowSize>
<Options>
<FilterType>0</FilterType>
<BodyPreference>
<Type>4</Type>
<TruncationSize>20000</TruncationSize>
</BodyPreference>
<MIMESupport>2</MIMESupport>
</Options>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:39,821 n.b.e.i.SyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 13:02:39,823 n.b.e.b.b.m.MailBackend INFO - Collection: bm:\\no@email.com\email\Sent
2015-10-05 13:02:39,855 n.b.e.b.b.m.EmailCacheStorage INFO - Device wants mail delivered after or re-flagged after 2015-10-04 12:56:02.914 UNFILTERED
2015-10-05 13:02:39,856 n.b.e.b.b.m.EmailCacheStorage INFO - changes: received: 0 flag: 0 removed: 0
2015-10-05 13:02:39,856 n.b.e.b.b.m.EmailCacheStorage INFO - [no@email.com]: collectionId [24615] 0 changes found. (12ms (loadCache: 1ms, imap: 10ms (750 mails), updCache: 0ms, computeChanges: 1ms))
2015-10-05 13:02:39,862 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:39,862 n.b.e.b.b.m.MailBackend INFO - pre-marked some items (0) we will never send to the device
2015-10-05 13:02:39,862 n.b.e.b.b.ContentsExporter INFO - Get changed from 2015-10-04 12:56:02.914 on collectionId:24615, type: EMAIL
2015-10-05 13:02:39,862 n.b.e.i.SyncHandler INFO - WindowSize is 5. Send 0 change(s)
2015-10-05 13:02:39,863 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>066350b2-267e-4973-8f3a-663ee5ea9ebd</SyncKey>
<CollectionId>24615</CollectionId>
<Status>1</Status>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:39,866 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:40,264 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 13:02:40,264 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: Sync
2015-10-05 13:02:40,264 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 13:02:40,265 n.b.e.i.SyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>ea42b93c-5db3-470f-8117-a6a0709252de</SyncKey>
<CollectionId>24598</CollectionId>
<DeletesAsMoves>1</DeletesAsMoves>
<GetChanges/>
<WindowSize>5</WindowSize>
<Options>
<FilterType>0</FilterType>
<BodyPreference>
<Type>4</Type>
<TruncationSize>20000</TruncationSize>
</BodyPreference>
<MIMESupport>2</MIMESupport>
</Options>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:40,265 n.b.e.i.SyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 13:02:40,266 n.b.e.b.b.m.MailBackend INFO - Collection: bm:\\no@email.com\email\INBOX
2015-10-05 13:02:40,301 n.b.e.b.b.m.EmailCacheStorage INFO - Device wants mail delivered after or re-flagged after 2015-10-05 12:39:21.0 UNFILTERED
2015-10-05 13:02:40,303 n.b.e.b.b.m.EmailCacheStorage INFO - changes: received: 0 flag: 0 removed: 0
2015-10-05 13:02:40,303 n.b.e.b.b.m.EmailCacheStorage INFO - [no@email.com]: collectionId [24598] 0 changes found. (18ms (loadCache: 2ms, imap: 14ms (1009 mails), updCache: 0ms, computeChanges: 2ms))
2015-10-05 13:02:40,306 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:40,306 n.b.e.b.b.m.MailBackend INFO - pre-marked some items (0) we will never send to the device
2015-10-05 13:02:40,306 n.b.e.b.b.ContentsExporter INFO - Get changed from 2015-10-05 12:39:21.0 on collectionId:24598, type: EMAIL
2015-10-05 13:02:40,306 n.b.e.i.SyncHandler INFO - WindowSize is 5. Send 0 change(s)
2015-10-05 13:02:40,307 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>02fa70da-0734-4bf1-bd06-fa944b7a0973</SyncKey>
<CollectionId>24598</CollectionId>
<Status>1</Status>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:40,310 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:40,408 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: 325481902
2015-10-05 13:02:40,408 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: Sync
2015-10-05 13:02:40,408 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 13:02:40,409 n.b.e.i.SyncHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>066350b2-267e-4973-8f3a-663ee5ea9ebd</SyncKey>
<CollectionId>24615</CollectionId>
<DeletesAsMoves>1</DeletesAsMoves>
<GetChanges/>
<WindowSize>5</WindowSize>
<Options>
<FilterType>0</FilterType>
<BodyPreference>
<Type>4</Type>
<TruncationSize>20000</TruncationSize>
</BodyPreference>
<MIMESupport>2</MIMESupport>
</Options>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:40,409 n.b.e.i.SyncHandler INFO - process(no@email.com / Android / Mailwise1932040915120121009 )
2015-10-05 13:02:40,411 n.b.e.b.b.m.MailBackend INFO - Collection: bm:\\no@email.com\email\Sent
2015-10-05 13:02:40,444 n.b.e.b.b.m.EmailCacheStorage INFO - Device wants mail delivered after or re-flagged after 2015-10-04 12:56:02.914 UNFILTERED
2015-10-05 13:02:40,445 n.b.e.b.b.m.EmailCacheStorage INFO - changes: received: 0 flag: 0 removed: 0
2015-10-05 13:02:40,445 n.b.e.b.b.m.EmailCacheStorage INFO - [no@email.com]: collectionId [24615] 0 changes found. (14ms (loadCache: 2ms, imap: 11ms (750 mails), updCache: 0ms, computeChanges: 1ms))
2015-10-05 13:02:40,450 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:40,450 n.b.e.b.b.m.MailBackend INFO - pre-marked some items (0) we will never send to the device
2015-10-05 13:02:40,450 n.b.e.b.b.ContentsExporter INFO - Get changed from 2015-10-04 12:56:02.914 on collectionId:24615, type: EMAIL
2015-10-05 13:02:40,450 n.b.e.i.SyncHandler INFO - WindowSize is 5. Send 0 change(s)
2015-10-05 13:02:40,451 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Sync>
<Collections>
<Collection>
<SyncKey>aa02cdaf-a0b0-4b7b-b66d-fe4c4098e153</SyncKey>
<CollectionId>24615</CollectionId>
<Status>1</Status>
</Collection>
</Collections>
</Sync>

2015-10-05 13:02:40,454 n.b.e.s.j.SyncStorage INFO - Nothing to mark
2015-10-05 13:02:42,029 n.b.e.ActiveSyncServlet INFO - [no@email.com] policy used: null
2015-10-05 13:02:42,029 n.b.e.ActiveSyncServlet INFO - activeSyncMethod: Ping
2015-10-05 13:02:42,029 n.b.e.ActiveSyncServlet INFO - Client supports protocol 12.1
2015-10-05 13:02:42,030 n.b.e.c.p.PingHandler INFO - from pda:
<?xml version="1.0" encoding="UTF-8"?><Ping>
<HeartbeatInterval>470</HeartbeatInterval>
<Folders>
<Folder>
<Id>24598</Id>
<Class>Email</Class>
</Folder>
<Folder>
<Id>24615</Id>
<Class>Email</Class>
</Folder>
</Folders>
</Ping>

2015-10-05 13:02:42,030 n.b.e.c.p.PingHandler INFO - process(no@email.com/Android)
2015-10-05 13:02:42,057 n.b.p.x.i.ConnectionPool INFO - already closed.
2015-10-05 13:02:42,057 n.b.e.b.b.BMBackend INFO - [no@email.com] device: no@email.com::Mailwise1932040915120121009, monitored collections: 2
2015-10-05 13:02:42,057 n.b.e.c.p.PingHandler INFO - Ping suspend for 470 seconds
2015-10-05 13:04:08,071 n.b.e.i.PushContinuation INFO - Continuation 8618 was allocated 830001ms ago.
2015-10-05 13:04:08,071 n.b.e.ActiveSyncServlet INFO - q: Cmd=Ping&User=no%40email.com&DeviceId=Mailwise1932040915120121009&DeviceType=Android pending: true resumed: false m: POST num:8618
2015-10-05 13:04:08,071 n.b.e.ActiveSyncServlet INFO - sendResponse
2015-10-05 13:04:08,071 n.b.e.i.Responder INFO - to pda:
<?xml version="1.0" encoding="UTF-8"?><Ping>
<Status>1</Status>
</Ping>

J’ai vérifié dans la table eas_sync_state, les sync_key sont bien là, après je sais pas trop comment le remplissage de la table fonctionne, mais si j’essaie d’accéder à un sous-dossier depuis mon téléphone, et que je rafraîchit la table, je vois bien du mouvement de rajout de synckey.

Donc voilà j’en suis là, et je n’arrive pas à avoir une sync correcte depuis un terminal Android.

Je précise aussi que ça fait pareil depuis d’autres comptes qui sont sur le serveur (car j’ai configuré plusieurs comptes sur mon téléphone).

Si une âme charitable veut bien m’aiguiller je lui en serai infiniment reconnaissant

A vous lire.

Toony · October 5, 2015, 2:32pm

Quel est le téléphone utilisé pour les tests (marques, modèle, version d’Androïd) ?
Vous synchronisez le téléphone en wifi ou via le réseau opérateur ?
Quelle période de récupération des mails configurez-vous sur votre téléphone (1 jour, 3 jours… tout) ?
Quelle est la taille de la BAL que vous souhaitez synchroniser ?

Il nous faudrait les logs complets du service EAS.

À priori quelque chose fait ne plaît pas à votre téléphone, il se met en erreur et refait une synchronisation complète.

psyray · October 5, 2015, 4:09pm

Le téléphone est un LG G3 d855, avec android 5.1.1, le téléphone est rooté et la ROM est une custom (Resurrection Remix 5.5.5)

Les deux, le problème est identique

J’ai testé un peu tout, mais ce qui est étrange c’est que quoi que je mette il reste toujours sur 1 jours.

2Go et elle est rempli à hauteur d’1.4Go

A quelle adresse puis-je vous l’envoyer ?

C’est ce que je me suis dit, mais je viens de le faire avec une tablette Galaxy TAB3 en android 4.4.2 et même topo.
Mais j’ai remarqué que ce problème ne se manifeste que lorsque j’ai plusieurs comptes EAS configurés sur le tél/tablette, et sur le même serveur BM
Dès lors que je ne met plus qu’un compte tout fonctionne nickel.

Un peu comme ce post

Toony · October 6, 2015, 7:53am

Attention avec les ROM custom, la partie ActiveSync est très liée à la ROM en général - et parfois même à l’opérateur - qui apporte son implémentation et/ou corrige/ajoute des bugs.

Ouvrez un ticket dans notre forge, en mettant un lien vers ce thread et attachez-y les logs.

[quote=psyray]
C’est ce que je me suis dit, mais je viens de le faire avec une tablette Galaxy TAB3 en android 4.4.2 et même topo.
Mais j’ai remarqué que ce problème ne se manifeste que lorsque j’ai plusieurs comptes EAS configurés sur le tél/tablette, et sur le même serveur BM
Dès lors que je ne met plus qu’un compte tout fonctionne nickel.

Un peu comme ce post[/quote]

ROM officielle sur cette tablette ?

psyray · October 6, 2015, 8:26am

La tablette a une ROM custom aussi.
Je vais tout réinstaller en ROM d’origine et tester tout ça.
Je vous tient au courant.
Je vais aussi poster le log dans la forge dans un nouveau ticket.
Merci de vos réponses rapides et efficaces.

psyray · October 6, 2015, 11:22am

Pour info, le ticket (BM-6303) vient d’être créé dans la forge.

psyray · October 6, 2015, 12:08pm

J’ai de nouvelles infos.
Il semblerait qu’il y ait des problèmes de données inconsistentes sur les boîtes mail que j’essaie de synchroniser.
J’ai utilisé adb logcat sur le LG d855 et ces messages d’erreur remontent :

W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6173): Account Ray has inconsistent mailbox data; fixing up...
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification

Est-ce que ces problèmes peuvent être la source de la re-synchronisation complète ?

psyray · October 6, 2015, 12:15pm

Et lors d’une perte de synchro et d’une resynchronisation, j’ai ceci :

V/WindowManager(  924): Adding window Window{24829b50 u0 Panel:com.syntomo.email/com.syntomo.email.activity.EmailActivity} at 4 of 13 (after Window{27e6683e u0 com.syntomo.email/com.syntomo.email.activity.EmailActivity})
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/ActivityManager(  924): Duplicate finish request for ActivityRecord{13657266 u0 com.syntomo.email/.activity.EmailActivity t3963 f}
V/WindowManager(  924): Adding window Window{beea7ae u0 Starting com.syntomo.email} at 5 of 14 (after Window{24829b50 u0 Panel:com.syntomo.email/com.syntomo.email.activity.EmailActivity})
I/Email.Welcome( 6070): onCreate()
I/Email.Welcome( 6070): startEmailActivity()
I/ActivityManager(  924): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x2000000 cmp=com.syntomo.email/.activity.EmailActivity (has extras)} from uid 10214 on display 0
V/WindowManager(  924): addAppToken: AppWindowToken{828743f token=Token{2aaa585e ActivityRecord{30b8cd99 u0 com.syntomo.email/.activity.EmailActivity t3963}}} to stack=1 task=3963 at 2
V/WindowManager(  924): Adding window Window{41d96d1 u0 com.syntomo.email/com.syntomo.email.activity.EmailActivity} at 6 of 16 (before Window{beea7ae u0 Starting com.syntomo.email})
V/WindowManager(  924): Adding window Window{22faac37 u0 Panel:com.syntomo.email/com.syntomo.email.activity.EmailActivity} at 7 of 17 (after Window{41d96d1 u0 com.syntomo.email/com.syntomo.email.activity.EmailActivity})
I/WindowManager(  924): Switching to real app window: Window{41d96d1 u0 com.syntomo.email/com.syntomo.email.activity.EmailActivity}
I/ActivityManager(  924): Displayed com.syntomo.email/.activity.EmailActivity: +299ms (total +407ms)
I/Timeline(  924): Timeline: Activity_windows_visible id: ActivityRecord{30b8cd99 u0 com.syntomo.email/.activity.EmailActivity t3963} time:1087302
W/Email   ( 6070): Couldn't find mailbox for changed message notification
D/Email.AttachmentService( 6070): Count: 0
W/Email   ( 6070): Couldn't find mailbox for changed message notification
W/Email   ( 6070): Couldn't find mailbox for changed message notification

et aussi ça

E/Mailbox: 19168[Account: 2]( 6173): Sync failed: 8 (unknown)
I/art     (  924): Explicit concurrent mark sweep GC freed 158338(6MB) AllocSpace objects, 1(16KB) LOS objects, 23% free, 52MB/68MB, paused 9.135ms total 152.198ms
I/art     ( 6070): Explicit concurrent mark sweep GC freed 124729(6MB) AllocSpace objects, 49(5MB) LOS objects, 29% free, 38MB/54MB, paused 2.004ms total 93.352ms
E/Mailbox: 181[Account: 2]( 6173): FolderSync failed: 9 (unknown)
E/Mailbox: 181[Account: 2]( 6173): Bad sync key; RESET and delete all folders
E/Mailbox: 19209[Account: 2]( 6173): Sync failed: 8 (unknown)

Donc il semblerait bien qu’il y ait un problème de synchro des dossiers avec les boîtes email.

Tout est ajouté dans le ticket sur la forge

J’attends votre avis