[SOLVED] iSync issues (calendar sync hangs)

[mbd]

Hi,

Just trying to play around with the iSync connector here and having some issues.

Client is running mac os x 10.4.8
Server is running ZCS 4.5.1_GA_660 (Network Edn) on a Mac OS X 10.4.8 server machine

I've installed the isync connector successfully on my client machine (from the server side downloads page). The machine never had the isync connector installed previously.

The account details have been entered correctly. When I try and reset sync data (i.e. clear all addressbook/calendar data from the zimbra account and populate it with data from the mac client), I go through the dialog boxes agreeing to remove the data on the zimbra server, etc.

The addressbook seems to work fine - I get agree to the '991 adds, 0 modifies and 0 deletes' and the 'Syncing local address book changes (x of 991) runs through its paces

I am then asked if it's OK to delete calendar data from the zimbra server. I agree, and then say OK to the '720 adds, 0 modifies and 0 deletes'.

However, as it starts processing the changes with the 'Syncing local calendar changes (x of 720)' display, it hangs at some point - it's not the same point each time. Sometimes it's when less than 100 records have been transferred. Once I got to 595. This last time I got to 134.

I've left it be for several hours just in case it needed some thinking time, but invariably, I have to force quit System Preferences and kill -9 the ZimbraHelper process to be able to get out of its state.

I've looked in ~/Library/Application/Support/Zimbra/com.zimbra.<string>/ folder for the logs.

Here's the last entry:

[Mon Feb 19 14:44:42 200] unable to find timezone info for Australia/Melbourne (901)
[Mon Feb 19 14:44:42 200] outgoing message ==> <?xml version='1.0'?>
<soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header>
<context xmlns="urn:zimbra">
<authToken>0_0a3e420e7bfdfbb96954ce332b0aeb3c483e6bdf_69643d33363a64333530666437312d336463632d343336382d623036332d6264396330336363363865373b6578703d31333a313137323032393330343930343b</authToken>
<sessionId id="2852"/>
</context>
</soap:Header>
<soap:Body>
<SetAppointmentRequest xmlns="urn:zimbraMail" l="56219">
<default ptst="NE"><m><su>Meeting with John</su>
<inv><tz stdoff="0" id="GMT"></tz>
<comp uid="com.apple.syncservices:F0BD4BCD-8B4A-452C-BFBE-86BB7DE2A524" type="event" allDay="0" fb="B" transp="O" name="Meeting with John" >
<s d="20070218T090000" tz="Australia/Melbourne"></s>
<e d="20070218T130000" tz="Australia/Melbourne"></e>
</comp></inv>
<mp ct="text/plain">
<content></content></mp></m></default>
</SetAppointmentRequest>
</soap:Body>
</soap:Envelope>
 (901)
[Mon Feb 19 14:44:42 200] incoming reply ==> <?xml version="1.0"?><soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope"><soap:Header><context xmlns="urn:zimbra"><sessionId id="2852">2852</sessionId><change token="80811"></change></context></soap:Header><soap:Body><soap:Fault><soap:Code><soap:Value>soap:Sender</soap:Value></soap:Code><soap:Reason><soap:Text>invalid request: invalid time zone "Australia/Melbourne"</soap:Text></soap:Reason><soap:Detail><Error xmlns="urn:zimbra"><Code>service.INVALID_REQUEST</Code><Trace>com.zimbra.common.service.ServiceException: invalid request: invalid time zone "Australia/Melbourne"
        at com.zimbra.common.service.ServiceException.INVALID_REQUEST(ServiceException.java:182)
        at com.zimbra.cs.service.mail.CalendarUtils.lookupAndAddToTzList(CalendarUtils.java:323)
        at com.zimbra.cs.service.mail.CalendarUtils.parseDtElement(CalendarUtils.java:541)
        at com.zimbra.cs.service.mail.CalendarUtils.parseInviteElementCommon(CalendarUtils.java:688)
        at com.zimbra.cs.service.mail.CalendarUtils.parseInviteForCreate(CalendarUtils.java:120)
        at com.zimbra.cs.service.mail.SetCalendarItem$SetCalendarItemInviteParser.parseInviteElement(SetCalendarItem.java:82)
        at com.zimbra.cs.service.mail.ParseMimeMessage$InviteParser.parse(ParseMimeMessage.java:139)
        at com.zimbra.cs.service.mail.ParseMimeMessage.parseMimeMsgSoap(ParseMimeMessage.java:254)
        at com.zimbra.cs.service.mail.CalendarRequest.handleMsgElement(CalendarRequest.java:109)
        at com.zimbra.cs.service.mail.SetCalendarItem.getSetCalendarItemData(SetCalendarItem.java:183)
        at com.zimbra.cs.service.mail.SetCalendarItem.handle(SetCalendarItem.java:109)
        at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:262)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:162)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:84)
        at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:223)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:162)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:667)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:613)
</Trace></Error></soap:Detail></soap:Fault></soap:Body></soap:Envelope> (901)
[Mon Feb 19 14:44:42 200] SOAP message error: invalid request: invalid time zone "Australia/Melbourne",service.INVALID_REQUEST (901)
[assert] error: (null)
[assert] where: "ZimbraClient.mm", "-[ZimbraClient session:setAppointment:record:snapshot:map:]", line: 2209

[Mon Feb 19 14:44:42 200] unable to find timezone info for Australia/Melbourne (901)
[Mon Feb 19 14:44:42 200] outgoing message ==> <?xml version='1.0'?>
<soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header>
<context xmlns="urn:zimbra">
<authToken>0_0a3e420e7bfdfbb96954ce332b0aeb3c483e6bdf_69643d33363a64333530666437312d336463632d343336382d623036332d6264396330336363363865373b6578703d31333a313137323032393330343930343b</authToken>
<sessionId id="2852"/>
</context>
</soap:Header>
<soap:Body>
<SetAppointmentRequest xmlns="urn:zimbraMail" l="56215">
<default ptst="NE"><m><su>Altiris meeting</su>
<inv><tz stdoff="0" id="GMT"></tz>
<comp uid="com.apple.syncservices:D614F1A3-407C-4720-9C6C-348AECB0AB06" type="event" allDay="0" fb="B" transp="O" name="Altiris meeting" >
<s d="20060510T140000" tz="Australia/Melbourne"></s>
<e d="20060510T150000" tz="Australia/Melbourne"></e>
</comp></inv>
<mp ct="text/plain">
<content></content></mp></m></default>
</SetAppointmentRequest>
</soap:Body>
</soap:Envelope>

It obviously doesn't appear to like the Timezone setting of 'Australia/Melbourne' as set by the OS X client machine, but I'm not sure that this would be the cause of the hanging. There are over 100 similar errors in the sync attempt, so the above isn't a one-off error for the attempt.

Note that I've got multiple calendars in iCal, and have tried selecting to sync all calendars as well as just one, but the behaviour doesn't appear to change.

I'm happy to provide further data as requested if it will help get to the bottom of this.

BTW, should there be a forum category specifically for iSync? I wasn't sure where to post this question so picked this one based on previous queries for iSync posted in here as well...

[jholder]

Hi mdb,
I'm investigating, and someone will have somesort of an answer for you shortly.

Thanks
john

[eintel]

Hi John,

We also had a problem today with the iSync connector and the 'Australia/Melbourne' timezone.

In our case iSync did not hang, but we were unable to sync appointments from the mac iCal to zimbra. All day appointments went across ok, anything else did not sync.

The logs had the same exception that mdb saw.
Server is 4.5.1 (Network) on CentOS machine. Mac was 10.4.7 or 10.4.8 (sorry didn't get exact version).

Could you also let us know any solution/explanation that you find.

thanks
Ben

Originally Posted by jholder

Hi mdb,
I'm investigating, and someone will have somesort of an answer for you shortly.

Thanks
john

[jholder]

Hey guys-
There is a bug that *kinda* fits this, but I'm still trying to figure out if the scope of that bug fits this error.

I'll let you know what I find out.

-john

[sam]

I've filed bug 14821 for this issue. Should be fixed in 4.5.3.

[sculi2000]

Sorry you are having some problems. We've fixed the timezone issue, but I'd like to see if we could reproduce the hanging problem. Would you be able to send along a backup of your iCal calendars so that we could try and reproduce the problem in-house?

Thanks,

Scott

[mbd]

Originally Posted by sculi2000

Sorry you are having some problems. We've fixed the timezone issue, but I'd like to see if we could reproduce the hanging problem. Would you be able to send along a backup of your iCal calendars so that we could try and reproduce the problem in-house?

Thanks,

Scott

Unfortunately not - there is a lot of private information stored within. I'm happy to run tests and provide results if that would be of assistance though.

[sculi2000]

Great! Thanks very much for the offer to help. So a couple of things...

Can you check the crashlog and see if there is an entry for ZimbraHelper? If so, can you send along the info in the crashlog?

If there isn't a crashlog, when you notice the sync hanging, it'd be very helpful to do the following things.

1) Open up a terminal session
2) Do a 'ps auxww | grep ZimbraHelper' and send along the output
3) Run sample...something like "sample <pid of ZimbraHelper> 10"...and then send along the output.

Thanks again for the help.

Scott

[mbd]

Originally Posted by sculi2000

Great! Thanks very much for the offer to help. So a couple of things...

Can you check the crashlog and see if there is an entry for ZimbraHelper? If so, can you send along the info in the crashlog?

I tried using the sync this morning and it almost appeared to be working this time (though it reported all the calendar entries had transferred in the preference pane, not all my events were appearing in the zimbra calendar, and the preference pane reported that an error had occurred in syncing).

I tried reseting sync data again, and this time it hung at change #106 of 785.

There is no mention of zimbra helper in my crashreporter.log

Originally Posted by sculi2000

If there isn't a crashlog, when you notice the sync hanging, it'd be very helpful to do the following things.

1) Open up a terminal session
2) Do a 'ps auxww | grep ZimbraHelper' and send along the output
3) Run sample...something like "sample <pid of ZimbraHelper> 10"...and then send along the output.

I've done a number of these:

#1 is while the preference pane was not progressing.

Analysis of sampling pid 4056 every 10.000000 milliseconds
Call graph:
    1000 Thread_0f07
      1000 start
        1000 _start
          1000 main
            1000 ZimbraHelper::Sync(NSString*, NSArray*, bool, bool, bool, bool)
              1000 ZimbraHelper::SyncCalendars(NSMutableDictionary*, bool, bool)
                1000 -[ZimbraClient session:setAppointment:record:snapshot:map:]
                  1000 -[ZimbraClient sendMessage:faultCode:faultText:]
                    1000 -[SOAPClient sendMessage:waitForReply:]
                      1000 -[NSRunLoop runMode:beforeDate:]
                        1000 CFRunLoopRunInMode
                          1000 CFRunLoopRunSpecific
                            1000 mach_msg_trap
                              1000 mach_msg_trap
    1000 Thread_1003
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 +[NSURLConnection(NSURLConnectionInternal) _resourceLoadLoop:]
            1000 CFRunLoopRunInMode
              1000 CFRunLoopRunSpecific
                1000 mach_msg_trap
                  1000 mach_msg_trap
    1000 Thread_1103
      1000 _pthread_body
        1000 select
          1000 select
    1000 Thread_1203
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 +[NSURLCache _diskCacheSyncLoop:]
            1000 CFRunLoopRunInMode
              1000 CFRunLoopRunSpecific
                1000 mach_msg_trap
                  1000 mach_msg_trap
    1000 Thread_1303
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 -[NSUIHeartBeat _heartBeatThread:]
            992 syscall_thread_switch
              992 syscall_thread_switch
            4 NSPopAutoreleasePool
              3 -[NSWindow release]
                3 NSDecrementExtraRefCountWasZero
                  3 _CFDictionaryDecrementValue
                    3 _CFDictionaryDecrementValue
              1 _CFRelease
                1 szone_free
                  1 szone_free
            2 -[NSUIHeartBeat _heartBeatThread:]
            1 -[NSApplication _keyWindowForHeartBeat]
              1 -[NSRecursiveLock unlock]
                1 -[NSRecursiveLock unlock]
            1 objc_msgSend_stret
              1 objc_msgSend_stret

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):
        mach_msg_trap        3000
        select        1000
        syscall_thread_switch        992

#2 is after clicking on the cancel button.

Analysis of sampling pid 4056 every 10.000000 milliseconds
Call graph:
    1000 Thread_0f07
      1000 start
        1000 _start
          1000 main
            1000 ZimbraHelper::Sync(NSString*, NSArray*, bool, bool, bool, bool)
              1000 ZimbraHelper::SyncCalendars(NSMutableDictionary*, bool, bool)
                1000 -[ZimbraClient session:setAppointment:record:snapshot:map:]
                  1000 -[ZimbraClient sendMessage:faultCode:faultText:]
                    1000 -[SOAPClient sendMessage:waitForReply:]
                      1000 -[NSRunLoop runMode:beforeDate:]
                        1000 CFRunLoopRunInMode
                          1000 CFRunLoopRunSpecific
                            1000 mach_msg_trap
                              1000 mach_msg_trap
    1000 Thread_1003
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 +[NSURLConnection(NSURLConnectionInternal) _resourceLoadLoop:]
            1000 CFRunLoopRunInMode
              1000 CFRunLoopRunSpecific
                1000 mach_msg_trap
                  1000 mach_msg_trap
    1000 Thread_1103
      1000 _pthread_body
        1000 select
          1000 select
    1000 Thread_1203
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 +[NSURLCache _diskCacheSyncLoop:]
            1000 CFRunLoopRunInMode
              1000 CFRunLoopRunSpecific
                1000 mach_msg_trap
                  1000 mach_msg_trap
    1000 Thread_1303
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 -[NSUIHeartBeat _heartBeatThread:]
            994 syscall_thread_switch
              994 syscall_thread_switch
            6 -[NSUIHeartBeat _heartBeatThread:]

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):
        mach_msg_trap        3000
        select        1000
        syscall_thread_switch        994
        -[NSUIHeartBeat _heartBeatThread:]        6

#3 is after force-quitting System Preferences

Analysis of sampling pid 4056 every 10.000000 milliseconds
Call graph:
    1000 Thread_0f07
      1000 start
        1000 _start
          1000 main
            1000 ZimbraHelper::Sync(NSString*, NSArray*, bool, bool, bool, bool)
              1000 ZimbraHelper::SyncCalendars(NSMutableDictionary*, bool, bool)
                1000 -[ZimbraClient session:setAppointment:record:snapshot:map:]
                  1000 -[ZimbraClient sendMessage:faultCode:faultText:]
                    1000 -[SOAPClient sendMessage:waitForReply:]
                      1000 -[NSRunLoop runMode:beforeDate:]
                        1000 CFRunLoopRunInMode
                          1000 CFRunLoopRunSpecific
                            1000 mach_msg_trap
                              1000 mach_msg_trap
    1000 Thread_1003
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 +[NSURLConnection(NSURLConnectionInternal) _resourceLoadLoop:]
            1000 CFRunLoopRunInMode
              1000 CFRunLoopRunSpecific
                1000 mach_msg_trap
                  1000 mach_msg_trap
    1000 Thread_1103
      1000 _pthread_body
        1000 select
          1000 select
    1000 Thread_1203
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 +[NSURLCache _diskCacheSyncLoop:]
            1000 CFRunLoopRunInMode
              1000 CFRunLoopRunSpecific
                1000 mach_msg_trap
                  1000 mach_msg_trap
    1000 Thread_1303
      1000 _pthread_body
        1000 forkThreadForFunction
          1000 -[NSUIHeartBeat _heartBeatThread:]
            996 syscall_thread_switch
              996 syscall_thread_switch
            2 -[NSWindow(NSWindow_Theme) heartBeat:]
              2 objc_msgSend
                2 objc_msgSend
            1 -[NSUIHeartBeat _heartBeatThread:]
            1 -[NSViewHierarchyLock unlock]
              1 -[NSViewHierarchyLock unlock]

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):
        mach_msg_trap        3000
        select        1000
        syscall_thread_switch        996

Hope this helps!

[sculi2000]

Thanks for this information. From the looks of it, I'd guess the machine on which the sync is running is having trouble receiving data from the zimbra server at some point during the sync.

Couple of questions...

Is the machine connected wirelessly to the network? While the sync is hanging, can you access the server via the web client?

Thanks,

Scott