0003620: ActiveSync stops working randomly - SOGo

ID	Project	Category	View Status	Date Submitted	Last Update

0003620	SOGo	ActiveSync	public	2016-04-06 21:44	2017-08-27 00:45

Reporter	m_emelchenkov	Assigned To	ludovic
Priority	normal	Severity	major	Reproducibility	always
Status	resolved	Resolution	no change required
Product Version	nightly v2

Summary	0003620: ActiveSync stops working randomly
Description	After fixing bug http://sogo.nu/bugs/view.php?id=3606 ActiveSync almost stop working. It stops working forever until phone restart, after some time, I don't know how much exactly, because I use the phone as regular and somewhere in the middle of road found that stop receiving new emails, only manual checking working. ActiveSync dispatcher process never starts. Let me know which logs do you need because I will be really tired to remove messages content from debug output if you will require me to send you debug logs.
Tags	No tags attached.

tfu 2016-04-07 05:10 reporter ~0009935	Show the last requests and reponses to the device before it seems to stop. Does a manual sync work?

m_emelchenkov 2016-04-08 19:01 reporter ~0009946	Manual sync work. It worked for whole day and stop working after several hours. Here is log attached with a moment when it stops waiting for changes.

m_emelchenkov 2016-04-08 19:01 reporter	Log.txt (2,427 bytes) ... Apr 08 20:19:03 sogod [6322]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.008 - - 0 Apr 08 20:19:04 sogod [6321]: <0x0x7f9879907008[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 20:19:09 sogod [6321]: <0x0x7f9879907008[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 20:19:14 sogod [6321]: <0x0x7f9879907008[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 20:19:19 sogod [6321]: <0x0x7f9879907008[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 20:19:24 sogod [6321]: <0x0x7f9879907008[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 20:19:26 sogod [6322]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 401 0/0 0.001 - - 0 Apr 08 20:19:26 sogod [6322]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 200 0/0 0.002 - - 0 Apr 08 20:19:29 sogod [6321]: <0x0x7f9879907008[SOGoActiveSyncDispatcher]> EAS - response for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Status>5</Status> <HeartbeatInterval>570</HeartbeatInterval> </Ping> Apr 08 20:19:29 sogod [6321]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 20/187 589.561 - - 0 Apr 08 20:19:33 sogod [6321]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/ HTTP/1.1" 207 491/439 0.002 1531 67% 0 Apr 08 20:19:33 sogod [6321]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 207 651/717 0.006 2864 77% 0 Apr 08 20:19:33 sogod [6321]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 403 232/298 0.001 - - 0 Apr 08 20:19:33 sogod [6321]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.006 - - 0 Apr 08 20:19:53 sogod [6321]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 401 0/2217 0.001 - - 0 Apr 08 20:19:53 sogod [6321]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 207 1442/2217 0.015 10044 85% 0 Apr 08 20:19:53 sogod [6321]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 250/422 0.001 - - 0 Apr 08 20:19:53 sogod [6321]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 254/430 0.002 - - 0 ... Log.txt (2,427 bytes)

m_emelchenkov 2016-04-08 19:05 reporter	Log2.rtf (5,542 bytes) {\rtf1\ansi\ansicpg1252\cocoartf1404\cocoasubrtf460 {\fonttbl\f0\fnil\fcharset0 Menlo-Regular;} {\colortbl;\red255\green255\blue255;} \paperw11900\paperh16840\margl1440\margr1440\vieww28660\viewh14720\viewkind0 \pard\tx560\tx1120\tx1680\tx2240\tx2800\tx3360\tx3920\tx4480\tx5040\tx5600\tx6160\tx6720\pardirnatural\partightenfactor0 \f0\fs22 \cf0 \CocoaLigature0 Apr 08 21:16:34 sogod [6321]: <0x0x7f98798a90a8[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?>\ <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">\ <Sync xmlns="AirSync:">\ <Collections>\ <Collection>\ <SyncKey>661-1783</SyncKey>\ <CollectionId>mail%2F9c224603ff6be456110800004fca1e17</CollectionId>\ <GetChanges/>\ <WindowSize>25</WindowSize>\ <Options>\ <FilterType>5</FilterType>\ <MIMETruncation>1</MIMETruncation>\ <MIMESupport>0</MIMESupport>\ <BodyPreference xmlns="AirSyncBase:">\ <Type>1</Type>\ <TruncationSize>500</TruncationSize>\ </BodyPreference>\ </Options>\ </Collection>\ </Collections>\ </Sync>\ \ Apr 08 21:16:35 sogod [6321]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/105 0.383 - - 0\ Apr 08 21:16:35 sogod [6321]: <0x0x7f98796900c8[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?>\ <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">\ <Sync xmlns="AirSync:">\ <Collections>\ <Collection>\ <SyncKey>665-1681</SyncKey>\ <CollectionId>mail%2F9d224603ff6be456110800004fca1e17</CollectionId>\ <GetChanges/>\ <WindowSize>25</WindowSize>\ <Options>\ <FilterType>5</FilterType>\ <MIMETruncation>1</MIMETruncation>\ <MIMESupport>0</MIMESupport>\ <BodyPreference xmlns="AirSyncBase:">\ <Type>1</Type>\ <TruncationSize>500</TruncationSize>\ </BodyPreference>\ </Options>\ </Collection>\ </Collections>\ </Sync>\ \ Apr 08 21:16:35 sogod [6321]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/105 0.346 - - 0\ Apr 08 21:16:37 sogod [6321]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 401 0/0 0.001 - - 0\ Apr 08 21:16:37 sogod [6321]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 200 0/0 0.001 - - 0\ Apr 08 21:16:38 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?>\ <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">\ <Ping xmlns="Ping:">\ <Folders>\ <Folder>\ <Id>mail%2F9d224603ff6be456110800004fca1e17</Id>\ <Class>Email</Class>\ </Folder>\ <Folder>\ <Id>mail%2F9c224603ff6be456110800004fca1e17</Id>\ <Class>Email</Class>\ </Folder>\ <Folder>\ <Id>vcard%2Fpersonal</Id>\ <Class>Contacts</Class>\ </Folder>\ <Folder>\ <Id>vevent%2Fpersonal</Id>\ <Class>Calendar</Class>\ </Folder>\ </Folders>\ </Ping>\ \ Apr 08 21:16:39 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:16:43 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/ HTTP/1.1" 207 491/439 0.002 1531 67% 0\ Apr 08 21:16:43 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 207 651/717 0.014 2864 77% 0\ Apr 08 21:16:43 sogod [6322]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 403 232/298 0.002 - - 0\ Apr 08 21:16:44 sogod [6322]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.006 - - 0\ Apr 08 21:16:44 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:16:49 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:16:54 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:17:00 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:17:05 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:17:07 sogod [6322]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 401 0/0 0.001 - - 0\ Apr 08 21:17:07 sogod [6322]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 200 0/0 0.001 - - 0\ Apr 08 21:17:10 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:17:14 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/ HTTP/1.1" 207 491/439 0.002 1531 67% 0\ Apr 08 21:17:15 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 207 651/717 0.009 2864 77% 0\ Apr 08 21:17:15 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:17:15 sogod [6322]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 403 232/298 0.002 - - 0\ Apr 08 21:17:15 sogod [6322]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.007 - - 0\ Apr 08 21:17:20 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ Apr 08 21:17:25 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...\ } Log2.rtf (5,542 bytes)

m_emelchenkov 2016-04-08 19:07 reporter ~0009947	Also I attached Log2.txt, I didn't noticed this part when submitting previous message. It starts working again after around an hour. I don't remember what I do that time — maybe switched from Wi-Fi to 3G, maybe refreshed messages list — just want to show you that it started checking again after some event.

m_emelchenkov 2016-04-08 19:07 reporter	Log2.txt (5,087 bytes) Apr 08 21:16:34 sogod [6321]: <0x0x7f98798a90a8[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <SyncKey>661-1783</SyncKey> <CollectionId>mail%2F9c224603ff6be456110800004fca1e17</CollectionId> <GetChanges/> <WindowSize>25</WindowSize> <Options> <FilterType>5</FilterType> <MIMETruncation>1</MIMETruncation> <MIMESupport>0</MIMESupport> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <TruncationSize>500</TruncationSize> </BodyPreference> </Options> </Collection> </Collections> </Sync> Apr 08 21:16:35 sogod [6321]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/105 0.383 - - 0 Apr 08 21:16:35 sogod [6321]: <0x0x7f98796900c8[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <SyncKey>665-1681</SyncKey> <CollectionId>mail%2F9d224603ff6be456110800004fca1e17</CollectionId> <GetChanges/> <WindowSize>25</WindowSize> <Options> <FilterType>5</FilterType> <MIMETruncation>1</MIMETruncation> <MIMESupport>0</MIMESupport> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <TruncationSize>500</TruncationSize> </BodyPreference> </Options> </Collection> </Collections> </Sync> Apr 08 21:16:35 sogod [6321]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/105 0.346 - - 0 Apr 08 21:16:37 sogod [6321]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 401 0/0 0.001 - - 0 Apr 08 21:16:37 sogod [6321]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 200 0/0 0.001 - - 0 Apr 08 21:16:38 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Folders> <Folder> <Id>mail%2F9d224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F9c224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Apr 08 21:16:39 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:16:43 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/ HTTP/1.1" 207 491/439 0.002 1531 67% 0 Apr 08 21:16:43 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 207 651/717 0.014 2864 77% 0 Apr 08 21:16:43 sogod [6322]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 403 232/298 0.002 - - 0 Apr 08 21:16:44 sogod [6322]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.006 - - 0 Apr 08 21:16:44 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:16:49 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:16:54 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:17:00 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:17:05 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:17:07 sogod [6322]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 401 0/0 0.001 - - 0 Apr 08 21:17:07 sogod [6322]: 127.0.0.1 "OPTIONS /SOGo/dav/user@domain/ HTTP/1.1" 200 0/0 0.001 - - 0 Apr 08 21:17:10 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:17:14 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/ HTTP/1.1" 207 491/439 0.002 1531 67% 0 Apr 08 21:17:15 sogod [6322]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 207 651/717 0.009 2864 77% 0 Apr 08 21:17:15 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:17:15 sogod [6322]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 403 232/298 0.002 - - 0 Apr 08 21:17:15 sogod [6322]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.007 - - 0 Apr 08 21:17:20 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Apr 08 21:17:25 sogod [6321]: <0x0x7f9879acd068[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Log2.txt (5,087 bytes)

tfu 2016-04-08 19:31 reporter ~0009950	I don't see any bad in the logs. Have you searched the web whether this could be an iPhone specific issue. I quick search returned this: http://www.technobezz.com/5-ways-fix-iphone-5-emails-not-pushed/

m_emelchenkov 2016-04-08 19:47 reporter ~0009951	There are no solution on web because push or work, or not—I don't believe anyone seriously use any workarounds like turning on/off Air mode and so on. In case when it sometimes works sometimes not it is useless—when you don't know if you get new mail and can't answer in time—it is a headache. Of course, it could be iPhone-specific. Not very much people use ActiveSync protocol with own servers — they use it mostly with MS Exchange or Gmail (also, Gmail now is not for everyone too, because its ActiveSync becomes paid). So even if there any bugs with ActiveSync implementation with 3rd party services too few people reporting it to Apple. However, I can't say anything bad about iOS Mail, I really enjoy this app, I hope we finally find a root of problem and way to fix it. The best thing I can do is to test on the latest iOS 9.x when my new iPhone will arrive (because 8.x is already outdated). Please don't close the ticket, wait for several days, I'll report results here. PS: By the way, at Log.txt at 20:19:29 iOS send POST Ping and nothing happened after -- is it OK?

tfu 2016-04-08 20:21 reporter ~0009952	Oha, don't fill offended. I just said what I found when a spent some time looking into your problem. If there is some hint what's going wrong we can fix it. But for now we just know that the phone stops to send ping-requests. Sogo can just wait for the next request from the phone to serve it.

m_emelchenkov 2016-04-16 09:02 reporter ~0009987	Oha, don't fill offended. Never. I am a developer myself so understand how the process of finding bugs works. I offer to close this issue because I can't reproduce it anymore for several days. Maybe updating SOGo to one of new nightly builds helped, maybe restarting some SOGo-related server components like PostgreSQL or Memcached. If it will appear in future again, I'll open then it again. Thank you!

Date Modified	Username	Field	Change
2016-04-06 21:44	m_emelchenkov	New Issue
2016-04-07 05:10	tfu	Note Added: 0009935
2016-04-08 19:01	m_emelchenkov	Note Added: 0009946
2016-04-08 19:01	m_emelchenkov	File Added: Log.txt
2016-04-08 19:05	m_emelchenkov	File Added: Log2.rtf
2016-04-08 19:07	m_emelchenkov	Note Added: 0009947
2016-04-08 19:07	m_emelchenkov	File Added: Log2.txt
2016-04-08 19:31	tfu	Note Added: 0009950
2016-04-08 19:47	m_emelchenkov	Note Added: 0009951
2016-04-08 20:21	tfu	Note Added: 0009952
2016-04-16 09:02	m_emelchenkov	Note Added: 0009987
2016-04-16 10:34	ludovic	Status	new => closed
2016-04-16 10:34	ludovic	Assigned To	=> ludovic
2016-04-16 10:34	ludovic	Resolution	open => no change required
2017-08-27 00:45	ludovic	Status	closed => resolved

View Issue Details

Activities

Issue History