Times shifting when syncing with z-push

raceface2nd

I figured out that this timeshift only happens, when externals are involved. If appointments or calendar entries are created between users on the same server everything is working well.

Following versions are running:
Kopano core 8.1.1.10-8.1
Kopano webapp 3.2.0.335-19.1
Z-Push 2.3.4
Kopano webmeetings 3.0.0.36

Thanks for every hint to solve this!

Andy

Sebastian

How do the external ones see/create the meeting request?

Does it happen in both directions?

External sends MR to Kopano user -> -1h shift ?
Kopano user sends MR to external -> -1h shift ?

For case 1, please dump the incoming RFC2822 message via the log_raw_email option of the dagent.
For both cases: Do I understand correctly that this time shift is also visible in WebApp? Or only in Z-Push?
If it’s also wrong in WebApp than it sounds more like a general server config issue.

raceface2nd

The externals create the MR mostly by using Exchange.

The timeshift happens not in every case in both directions.

yes, External MR to Kopano user -> -1h shift
if the MR to external is created via z-push -> -1h shift

If the MR to an external is created with the WebApp -> no shift.

I dumped a MR, do you need the whole message or only the content?

Thx!

Andy

Sebastian

The more data the better. Have you seen this with more than one external environment?

A few more questions trying to pinpoint this down further:

External MR to Kopano
1.A) when opening the MR in Webapp (calendar): with -1h shift?
1.B) when looking in your mobile calendar: with -1h shift?
MR sent from mobile to external:

Can you post the WBXML MR email from your Z-Push log? It’s should be an email with an ICS attachment listed fully in the WBXML debug log. The timezone information should be there.

I wonder if this could be related to https://jira.kopano.io/browse/KC-313 which is fixed in KC 8.2. DST is going to start soon in Europe so this could quite possibly be related.

I am still not sure in which cases you are having this problems and specifically, in which cases everything works fine. We need to list all these cases to find a pattern.

Cheers,
Seb

raceface2nd

That’s weired. When I open the dumped .eml file in Outlook of the external user and it shows up with correct times. Opening the .eml file in a different Outlook it results in a timeshift of -2h. Opening the .eml file as an attachment in the WebApp results in a timeshift of -2h.

The timeshift can be reproduced with different external users.

I extracted the calendar information from the .eml file and for me it looks okay:

BEGIN:VCALENDAR
METHOD:REQUEST
PRODID:Microsoft Exchange Server 2010
VERSION:2.0
BEGIN:VTIMEZONE
TZID:(UTC+01:00) Amsterdam\, Berlin\, Bern\, Rom\, Stockholm\, Wien
BEGIN:STANDARD
DTSTART:16010101T030000
TZOFFSETFROM:+0200
TZOFFSETTO:+0100
RRULE:FREQ=YEARLY;INTERVAL=1;BYDAY=-1SU;BYMONTH=10
END:STANDARD
BEGIN:DAYLIGHT
DTSTART:16010101T020000
TZOFFSETFROM:+0100
TZOFFSETTO:+0200
RRULE:FREQ=YEARLY;INTERVAL=1;BYDAY=-1SU;BYMONTH=3
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
ORGANIZER;CN=external user
ATTENDEE;ROLE=REQ-PARTICIPANT;PARTSTAT=NEEDS-ACTION;RSVP=TRUE;CN=kopano user:MAILTO:kopano user
DESCRIPTION;LANGUAGE=de-DE:\n
UID:040000008200E00074C5B7101A82E0080000000088B585F27BA1D201000000000000000 010000000CBF89C2DAC252D4A9E119F3B9DCA79FE
SUMMARY;LANGUAGE=de-DE:extern -> kopano 11:00
DTSTART;TZID="(UTC+01:00) Amsterdam, Berlin, Bern, Rom, Stockholm, Wien":2017 0323T110000
DTEND;TZID="(UTC+01:00) Amsterdam, Berlin, Bern, Rom, Stockholm, Wien":201703 23T113000
CLASS:PUBLIC
PRIORITY:5
DTSTAMP:20170320T131716Z
TRANSP:OPAQUE
STATUS:CONFIRMED
SEQUENCE:1
LOCATION;LANGUAGE=de-DE:
X-MICROSOFT-CDO-APPT-SEQUENCE:1
X-MICROSOFT-CDO-OWNERAPPTID:2115216008
X-MICROSOFT-CDO-BUSYSTATUS:TENTATIVE
X-MICROSOFT-CDO-INTENDEDSTATUS:BUSY
X-MICROSOFT-CDO-ALLDAYEVENT:FALSE
X-MICROSOFT-CDO-IMPORTANCE:1
X-MICROSOFT-CDO-INSTTYPE:0
X-MICROSOFT-DISALLOW-COUNTER:FALSE
BEGIN:VALARM
DESCRIPTION:REMINDER
TRIGGER;RELATED=START:-PT15M
ACTION:DISPLAY
END:VALARM
END:VEVENT
END:VCALENDAR`

Andy

Edit: added code block

Sebastian

This MR coming from exchange? Where did you take it from? From the raw log of the dagent or from the webapp?
Incoming mails are processed to be converted into MAPI objects. Taking the raw data (before being processed) is always preferred, because it can be used to reproduce the issue.

Please also have a look at my previous questions.

raceface2nd

Yes, this is the MR coming from exchange. The request was set to 11am 03-23-2017. I took it from the raw .eml file dagent created after enabling it. I opened this .eml file with an .eml viewer to extract the calendar entry and mask the email adresses. The spaces in the DTSTART and DTEND are coming from copy and paste into the browser.

Regarding your other questions:

External MR to Kopano:
1.a) correct; -1h shift
1.b) correct; -1h shift
This is what I logged, when I created an MR with a mobile device:

20/03/2017 16:38:07 [24010] [DEBUG] [unknown] DeviceManager->GetBackendIdForFolderId(): folderid U35b54 => fd240b6b36644c088db90c8535dccfd3f30000000000
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] SyncCollections->AddCollection(): Folder id 'U35b54' : ref. PolicyKey '374280224', ref. Lifetime '900', last sync at '1490017627'
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I     <WindowSize>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I      25
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I     </WindowSize>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I     <Perform>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I      <Add>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I       <ClientEntryId>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        oid{331:30003:c}
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I       </ClientEntryId>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I       <Data>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:Timezone>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         xP///00AaQB0AHQAZQBsAGUAdQByAG8AcADkAGkAcwBjAGgAZQAgAFoAZQBpAHQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAE0AaQB0AHQAZQBs$
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:Timezone>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:AllDayEvent>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         0
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:AllDayEvent>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <AirSyncBase:Body>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         <AirSyncBase:Type>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I          2
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         </AirSyncBase:Type>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         <AirSyncBase:Data/>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </AirSyncBase:Body>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:BusyStatus>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         2
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:BusyStatus>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:DtStamp>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         20170320T153805Z
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:DtStamp>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:EndTime>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         20170324T113000Z
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:EndTime>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:MeetingStatus>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         0
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:MeetingStatus>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:OrganizerEmail>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         kopano user
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:OrganizerEmail>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:Reminder>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         15
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:Reminder>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:Sensitivity>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         0
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:Sensitivity>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:Subject>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         Mobile to external 24.03.2017 12:00
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:Subject>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:StartTime>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         20170324T110000Z
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:StartTime>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:UID>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         040000008200E00074C5B7101A82E00800000000777457EC286D674FA99243FFABCDBAD5100000001C4741344CDB554BA9DDF832948FBF1C
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:UID>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:ResponseRequested>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         1
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:ResponseRequested>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        <POOMCAL:DisallowNewTimeProposal>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I         0
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I        </POOMCAL:DisallowNewTimeProposal>
20/03/2017 16:38:07 [24010] [WBXML] [unknown] I       </Data>
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] Sync->getImporter(): initialize importer
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] Sync->loadStates(): loading states for folder 'U35b54'
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/b/9/3c39bcedc8a73e0fb86d2f4aeb89ca9b-588c2116-444f-4c01-a0ab-70b81f26d35e-3'
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/b/9/3c39bcedc8a73e0fb86d2f4aeb89ca9b-588c2116-444f-4c01-a0ab-70b81f26d35e-2'
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/b/9/3c39bcedc8a73e0fb86d2f4aeb89ca9b-588c2116-444f-4c01-a0ab-70b81f26$
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] ZPush::GetAdditionalSyncFolderStore('fd240b6b36644c088db90c8535dccfd3f30000000000'): 'false'
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] BackendKopano->GetImporter() folderid: 'fd240b6b36644c088db90c8535dccfd3f30000000000'
20/03/2017 16:38:07 [24010] [DEBUG] [unknown] ImportChangesICS->Config(): initializing importer with state: 0x4404000016ae0000

This MR is for 12:00 03-24-2017. But I am not sure where to locate the .ics file?

I was not sure either in which cases this happens. But now I am sure:

case 1: getting an MR from external servers -> -1h shift -> webApp and z-push show the same shift
case 2: sending an MR to externals via z-push -> -1h shift at the external side -> webApp and z-push are showing correct.

Maybe the following screenshot helps to understand the problem:

0_1490026064894_upload-ba631e5c-5351-40b9-b26d-e06be8cf6486

I was wondering if it could be kind of problem with daylight saving? I did not test it with iOS, so I am not sure if it’s related to the bug you mentioned. I only tested with w10m, Android, OL2013 (win7), OL2016(win10).

Andy

Sebastian

When you create a MR from the mobile, there are two parts in the log.

you posted it. That’s the mobile saving the appointment in the calendar.
normally right afterwards the phone sends an email with an attached ICS file to the attendees. You can see there exactly what the phone sent to the external party.

I also think that the DTSTART of the incoming exchange appointment looks wrong:

DTSTART:16010101T030000

So, this is the 16.01.101? Is it missing 1900 so this should be 2001? That looks really strange.

I am really running of ideas, but if WebApp and Z-Push show the same incoming MR wrong, then this is something server wide, something general. Not sure if system configuration or another issue.
We’ve tested to reproduce this with office 365 but of course everything is correct.

raceface2nd

Hi, the MR should be for 24.03.2017 12:00.

I’ve everything running on an virtual UCS appliance and upgraded z-push to version 2.3.5 today but the problem still exists. I checked all timezone settings I could imagine again and again, all have Europe/Berlin.

For testing I used several external accounts . . . Office365; self hosted exchange 2010; gmail. The problem is the same with all externals.

Can it be that some process is getting confused with the daylight saving?

I would appreciate any ideas that help to solve the issue.

Andy

raceface2nd

So . . . this weired thing with the timeshift could not let me sleep.

Regarding the fact, that the server which shows the problems is live and hosting email services for a hand full of domains I did not want to start over until I really know, what the problem is.

I did setup a brand new virtual appliance with UCS and Kopano in a totally different environment only for one domain at this moment and checked again and again and have NOT been able to reproduce the issue.

But I still have some questions:

Is it worth to research where the error is coming from?
May it be, that the error is related to the VPS which is hosting the UCS with Kopano?
Should it work to perform an ActiveDirectory Takeover with a new UCS installation ?
If I perform a takeover with UCS, do I have to manually migrate Kopano or will it be migrated while the takeover automatically?

Thanks!

Andy

raceface2nd

[EDIT]Something coming with the Nextcloud-Package from the UCS App Center caused the issue. I could reproduce this 2 times.[/EDIT]

[EDIT]It seems, that the UCS app OpenProject or Nextcloud caused the described behaviour. Without having installed one of them on the same UCS machine everything works like a charm. @Sebastian: Thank you for your help trying to figure the reason out.[/EDIT]

I reinstalled the server manually completely but the issue still exists, when installing Kopano within UCS on a KVM VPS.

I don’t find it logic that this shift happens. Can this environment be the cause for this behaviour?

Andy

Sebastian

It would be awesome to find out why/how this happens. Does Own/Nextcloud change the timezone php configuration somehow? That’s the only thing I can think how this could happen.

raceface2nd

I doubt that NC/ OC itself causes the issue. The Univention (UCS) NC package installs NC within a docker container. I am guessing, that there is more automatically installed by the UCS app center than only docker and the corresponding NC image. Especially the fact, that UCS runs NC within a docker container let me doubt, that NC/ OC is the reason.

I posted this case already into the univention forum, but got no feedback at all already. Maybe everybody is at the CeBIT at the moment.