Fast Repeating Sync Messages in sync.log

Discuss your pilot or production implementation with other Zimbra admins or our engineers.
Post Reply
swimmer
Posts: 8
Joined: Mon Nov 21, 2016 3:03 pm

Fast Repeating Sync Messages in sync.log

Post by swimmer »

I seem to have an issue with our mobile sync. Yesterday I had one user generating log messages in /opt/zimbra/sync.log basically every millisecond.

Code: Select all

2018-04-16 17:14:07,752 INFO  [qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=] [name=user1@our-domain.com;mid=13;ip=10.0.0.12;DeviceID=C5B703A73B21DCE987F7CD6DC004032E;Cmd=Sync;Version=12.1;class=Email;folder=2;] sync - C new: 569, S latest: 569, C confirmed: 569, new filter: UNSPECIFIED, prev filter: PAST_THREE_DAYS, modnew: 255003, modconfirmed: 255003
2018-04-16 17:14:07,754 INFO  [qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=] [name=user1@our-domain.com;mid=13;ip=10.0.0.12;DeviceID=C5B703A73B21DCE987F7CD6DC004032E;Cmd=Sync;Version=12.1;class=Email;folder=2;] sync - Folder[2], C:569/F, S:569/F, mod new: 255003, mod confirmed: 255003, server Exp/AddOrChg/Del: 0/0/0, track id: 0
2018-04-16 17:14:07,754 INFO  [qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=] [name=user1@our-domain.com;mid=13;ip=10.0.0.12;DeviceID=C5B703A73B21DCE987F7CD6DC004032E;Cmd=Sync;Version=12.1;class=Email;folder=5;] sync - C new: 923, S latest: 923, C confirmed: 923, new filter: UNSPECIFIED, prev filter: PAST_THREE_DAYS, modnew: 255003, modconfirmed: 255003
2018-04-16 17:14:07,756 INFO  [qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=] [name=user1@our-domain.com;mid=13;ip=10.0.0.12;DeviceID=C5B703A73B21DCE987F7CD6DC004032E;Cmd=Sync;Version=12.1;class=Email;folder=5;] sync - Folder[5], C:923/F, S:923/F, mod new: 255003, mod confirmed: 255003, server Exp/AddOrChg/Del: 0/0/0, track id: 0
2018-04-16 17:14:07,756 INFO  [qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=] [name=user1@our-domain.com;mid=13;ip=10.0.0.12;DeviceID=C5B703A73B21DCE987F7CD6DC004032E;Cmd=Sync;Version=12.1;class=Contacts;folder=7;] sync - C new: 2, S latest: 2, C confirmed: 2, new filter: UNSPECIFIED, prev filter: UNSPECIFIED, modnew: 214790, modconfirmed: 214790
2018-04-16 17:14:07,758 WARN  [qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=] [name=user1@our-domain.com;mid=13;ip=10.0.0.12;DeviceID=C5B703A73B21DCE987F7CD6DC004032E;Cmd=Sync;Version=12.1;class=Contacts;folder=7;] sync - MUST_RESYNC
com.zimbra.cs.mailbox.MailServiceException: sync token too old; tombstones have already been expired
ExceptionId:qtp509886383-116:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?eQAHBBDFtwOnOyHc6Yf3zW3ABAMuBNWv2HELV2luZG93c01haWw=:1523891647758:7fc4e1f23441193c
Code:mail.MUST_RESYNC
        at com.zimbra.cs.mailbox.MailServiceException.TOMBSTONES_EXPIRED(MailServiceException.java:585)
        at com.zimbra.cs.mailbox.Mailbox.getTombstones(Mailbox.java:3581)
        at com.zimbra.zimbrasync.commands.CollectionSync.findItemsToSync(CollectionSync.java:1152)
        at com.zimbra.zimbrasync.commands.CollectionSync.findServerChanges(CollectionSync.java:1085)
        at com.zimbra.zimbrasync.commands.CollectionSync.process(CollectionSync.java:911)
        at com.zimbra.zimbrasync.commands.Sync.process(Sync.java:134)
        at com.zimbra.zimbrasync.ZimbraSyncServlet.processCommand(ZimbraSyncServlet.java:698)
        at com.zimbra.zimbrasync.ZimbraSyncServlet.processPostRequest(ZimbraSyncServlet.java:555)
        at com.zimbra.zimbrasync.ZimbraSyncServlet.doPost(ZimbraSyncServlet.java:447)
        at com.zimbra.zimbrasync.ZimbraSync$HttpHandler.doPost(ZimbraSync.java:66)
        at com.zimbra.cs.extension.ExtensionDispatcherServlet.service(ExtensionDispatcherServlet.java:101)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:738)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651)
        at com.zimbra.cs.servlet.RequestStringFilter.doFilter(RequestStringFilter.java:54)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at com.zimbra.cs.servlet.SetHeaderFilter.doFilter(SetHeaderFilter.java:59)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:83)
        at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:351)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at com.zimbra.cs.servlet.ETagHeaderFilter.doFilter(ETagHeaderFilter.java:47)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at com.zimbra.cs.servlet.ContextPathBasedThreadPoolBalancerFilter.doFilter(ContextPathBasedThreadPoolBalancerFilter.java:107)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at com.zimbra.cs.servlet.ZimbraQoSFilter.doFilter(ZimbraQoSFilter.java:116)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at com.zimbra.cs.servlet.ZimbraInvalidLoginFilter.doFilter(ZimbraInvalidLoginFilter.java:117)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at org.eclipse.jetty.servlets.DoSFilter.doFilterChain(DoSFilter.java:457)
        at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:326)
        at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:299)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1622)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:549)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:544)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1111)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:478)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:183)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1045)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:199)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
        at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:309)
        at org.eclipse.jetty.server.handler.DebugHandler.handle(DebugHandler.java:81)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
        at org.eclipse.jetty.server.Server.handle(Server.java:462)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:279)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:232)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:534)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
        at java.lang.Thread.run(Thread.java:745)
Turning off the users mobile phone did not end the log messages. I disabled the users mobile sync rights and set his exchange sync setting on the mobile phone from push to manual. This did end the log messages. Well, at least I only got log messages from that user when he manually synced.
Now today I have another user generating log messages each 30ms.

Code: Select all

2018-04-17 07:19:15,052 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - [Ping] (session 5161109) for [MESSAGE:2, MESSAGE:5, CONTACT:7, APPOINTMENT:10] suspending for 1680 seconds, isInitial=true
2018-04-17 07:19:15,052 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - [Ping] (session 5161108) Listener got cancelled after 0 seconds (targeted 1680 seconds)
2018-04-17 07:19:15,052 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - Response size 13 bytes
2018-04-17 07:19:15,052 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - HTTP/1.1 200 OK
2018-04-17 07:19:15,172 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - [Ping] (session 5161110) for [MESSAGE:2, MESSAGE:5, CONTACT:7, APPOINTMENT:10] suspending for 1680 seconds, isInitial=true
2018-04-17 07:19:15,172 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - [Ping] (session 5161109) Listener got cancelled after 0 seconds (targeted 1680 seconds)
2018-04-17 07:19:15,172 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - Response size 13 bytes
2018-04-17 07:19:15,172 INFO  [qtp509886383-5947:https://10.0.0.12:8443/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40our-domain.com&DeviceId=androidc486499769&DeviceType=Android] [name=user@our-domain.com;mid=95;ip=10.0.0.12;DeviceID=androidc486499769;Cmd=Ping;Version=12.1;] sync - HTTP/1.1 200 OK
The problem is, that the server was running out of disk space with all that log messages. I scheduled maintenance for friday to move the log folder from the system partition to a data partition, but I want to address the underlying problem too.


So my questions are:

[*]Where can I read more about these messages, how they are generated and how I can troubleshoot them?
[*]Is there something easy I am missing here?
Top
Post Reply

Return to “Administrators”