Page 1 of 2 12 LastLast
Results 1 to 10 of 12

Thread: Z-Push 2.3.5b0: ProvisioningRequiredException breaks sync

  1. #1
    Junior Member
    Join Date
    Aug 2009
    Location
    Bavaria
    Posts
    15

    Z-Push 2.3.5b0: ProvisioningRequiredException breaks sync

    Hi,

    I am using Zarafa and Z-Push for several years now, and during the last year the synchronization breaks on 4 different Android devices every few weeks (not all the the same moment).
    All contacts, calendar entries would disappear from the mobile, mails would remain and still update. I can usually fix it by clearing loop detection data and forcing a resync.

    Does this log make any sense?

    Apache log:
    Code:
    26789:2003:66:873c:6f00:14ed:1533:dc7c:fe19 - marco [28/Dec/2016:10:15:16 +0100] "POST /Microsoft-Server-ActiveSync?Cmd=FolderSync&User=marco&DeviceId=ASUSt1460782466334&DeviceType=ASUSZ00A HTTP/1.1" 449 443 "-" "Android/5.0-EAS-1.3"
    26790:2003:66:873c:6f00:14ed:1533:dc7c:fe19 - marco [28/Dec/2016:10:15:16 +0100] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=marco&DeviceId=ASUSt1460782466334&DeviceType=ASUSZ00A HTTP/1.1" 449 443 "-" "Android/5.0-EAS-1.3"
    26791:2003:66:873c:6f00:14ed:1533:dc7c:fe19 - marco [28/Dec/2016:10:15:16 +0100] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=marco&DeviceId=ASUSt1460782466334&DeviceType=ASUSZ00A HTTP/1.1" 449 443 "-" "Android/5.0-EAS-1.3"
    27085:2003:66:873c:6f00:14ed:1533:dc7c:fe19 - marco [28/Dec/2016:10:19:24 +0100] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=marco&DeviceId=ASUSt1460782466334&DeviceType=ASUSZ00A HTTP/1.1" 200 14490 "-" "Android/5.0-EAS-1.3"
    Since I cannot post the z-push.log for message length restrictions, I have attached it here.

    I have the WBXML as well, shall I send it to anyone?

    The device without hierarchy could be one that has never synced since the last Z-Push update:
    Code:
    # z-push-admin -a fixstates
    
    Validating and fixing states (this can take some time):
            Checking username casings: Processed: 8 - Converted: 0 - Removed: 0
            Checking available devicedata & user linking: Processed: 8 - Fixed: 0
            Checking for unreferenced (obsolete) state files: Processed: 16 - Deleted: 0
            Checking for hierarchy folder data state: Devices: 8 - Processed: 7 - Fixed: 0 - Device+User without hierarchy: 1
            Checking flags of shared folders: Devices: 8 - Devices with additional folders: 0 - Fixed: 0

    Code:
    # z-push-admin -a list -u stan23
    
    Synchronized devices of user: stan23
    -----------------------------------------------------
    DeviceId:               asust1460782466334
    Device type:            ASUSZA
    UserAgent:              Android/5.0-EAS-1.3
    Device Model:           ASUS_Z00AD
    Device OS:              Android 5.0
    ActiveSync version:     14.0
    First sync:             2016-04-16 07:13
    Last sync:              2016-12-29 21:31
    Total folders:          30
    Short folder Ids:       Yes
    Synchronized folders:   5
    Synchronized data:      Emails(3) Contacts Calendars
    Status:                 OK
    WipeRequest on:         not set
    WipeRequest by:         not set
    Wiped on:               not set
    Policy name:            default
    Attention needed:       No errors known
    Attached Files Attached Files
    Last edited by stan23; 29-12-2016 at 08:32 PM.

  2. #2
    Senior Member
    Join Date
    Sep 2007
    Location
    Aka SebastianBrasil
    Posts
    1,462
    Hi Stan,

    let me see if I got this correctly:
    - The devices stop syncing and perform a resync without any interaction?
    - this happens without good reason, but not all on the same time. Is there any other possible reason? Do you use mysql states and is perhaps your DB not available for certain points in time (e.g. during a backup)?
    - Do the devices "come back" on their own? If you need to interfere, what do you do? Clearing loop detection just accelerates a possible resync (if in loop detection by a glitch).

    From your log it just seems as the provisioning data got outdated (or lost) and z-push forces your device to perform provisioning again.
    Do you have the wbxml log from while this happened or only afterwards?
    A log pre/during the resync might be interesting (could indicate why your states/provisioning data gets lost).

    Cheers,
    Sebastian

  3. #3
    Junior Member
    Join Date
    Aug 2009
    Location
    Bavaria
    Posts
    15
    Hi Sebastian,

    sorry for my confusing explanation.

    Observation on the device:
    - mails are still received and can be sent, so there's no impact on mails
    - all contacts disappear from the Android device
    - all calendar entries disappear from the device

    It does not happen on all 4 devices at the same time. Sometimes only one is affected, most of the time 2 or 3 are affected.
    Since my wife and I are sending calendar invitations to each other, it could be caused by a broken calendar entry.

    The devices do not resync on their own, I have to trigger the resync by clearing loop detection data and forcing a resync:
    Code:
    z-push-admin -a clearloop -d asust1460782466334 -u stan23
    z-push-admin -a resync -d asust1460782466334 -u stan23
    The mySQL backup happens at midnight like this:
    Code:
    #https://forums.zarafa.com/showthread.php?12750-Correct-way-to-do-live-mysqldump-Why-does-Zarafa-Wiki-Manuals-promote-a-wrong-way
    PARAMS='--skip-opt --single-transaction --routines --add-drop-table --create-options --extended-insert --quick --set-charset '
    [...]
    mysqldump -u$USER -p$PASSWD $PARAMS $DATABASE > $BACKUPDIR/$DATABASE"_dump"
    I do have the wbxml log, but it is 80 MB zipped
    Shall I try to extract the necessary part (I might miss the part why the states get lost) or upload the full file?

  4. #4
    Junior Member
    Join Date
    Aug 2009
    Location
    Bavaria
    Posts
    15
    Hi,

    this happened again today and I tried to look myself into the WBXML log.

    Is the device key supposed to chage or is this a bug on my mobile phone?
    Code:
    Line 22908: 31/01/2017 13:50:33 [ 7162] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '920708894': false
    Line 22966: 31/01/2017 13:50:33 [ 7789] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '920708894': false
    Line 23030: 31/01/2017 13:50:33 [ 9295] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '920708894': false
    Line 23261: 31/01/2017 13:51:26 [ 6009] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '920708894': false
    Line 23319: 31/01/2017 13:51:27 [28980] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '920708894': false
    Line 23383: 31/01/2017 13:51:27 [ 6009] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '920708894': false
    Line 23722: 31/01/2017 13:51:33 [ 9295] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '997276095': true   <-- changed once
    Line 24032: 31/01/2017 13:51:44 [ 7789] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('704342860') saved device key '704342860': false  <-- changed again
    Line 24090: 31/01/2017 13:51:45 [ 9296] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('704342860') saved device key '704342860': false
    Line 24154: 31/01/2017 13:51:45 [28646] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('704342860') saved device key '704342860': false
    Line 24221: 31/01/2017 13:51:46 [28646] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('704342860') saved device key '704342860': false
    Line 24397: 31/01/2017 13:51:47 [28646] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '704342860': true
    Line 24425: 31/01/2017 13:51:47 [ 9296] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('704342860') saved device key '704342860': false
    Line 24592: 31/01/2017 13:51:48 [ 9296] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('920708894') saved device key '704342860': true
    Line 24620: 31/01/2017 13:51:48 [12561] [DEBUG] [stan23] [asust1460782466334] DeviceManager->ProvisioningRequired('704342860') saved device key '704342860': false

  5. #5
    Senior Member
    Join Date
    Nov 2007
    Location
    Belo Horizonte, Brazil
    Posts
    1,471
    Hi Stan,

    the saved device key is actually a provisioning key saved on the device and it might change if the device starts a new Provisioning request.

    However after some time your device sends an old provisioning key again which is weird. Could you post the WBXML log from say 31/01/2017 13:51:27 until 31/01/2017 13:51:48 (maybe even a couple of request after that)?

    Manfred
    Please do not PM me asking for support. Use the forum instead. Thank you.
    I usually check the mobility thread at the end of the day, so please have some patience if there's no immediate response. Asking to look at certain thread per PM won't result in a faster answer.

  6. #6
    Junior Member
    Join Date
    Aug 2009
    Location
    Bavaria
    Posts
    15
    Hi Manfred,

    I've sent you the WBXML by PM.

    I think I was refreshing my mails when suddenly my mobile did not refresh anymore and then I figured out that sync stopped.

  7. #7
    Senior Member
    Join Date
    Nov 2007
    Location
    Belo Horizonte, Brazil
    Posts
    1,471
    Hi Stan,

    I've downloaded the log and will take a look at it, but I probably won't be able to comment anything on it today.

    Manfred
    Please do not PM me asking for support. Use the forum instead. Thank you.
    I usually check the mobility thread at the end of the day, so please have some patience if there's no immediate response. Asking to look at certain thread per PM won't result in a faster answer.

  8. #8
    Junior Member
    Join Date
    Aug 2009
    Location
    Bavaria
    Posts
    15
    No worries.
    I'm experiencing broken sync since months.

    Now I know how to reliably recover:
    - clear loop detection and force resync in z-push-admin
    - force mobile to sync calendar and contacts again by deselecting and reselecting both options

    But my family and me would prefer if it does not break at all :-)

  9. #9
    Senior Member
    Join Date
    Sep 2007
    Location
    Aka SebastianBrasil
    Posts
    1,462
    I had a look at your log and I understand what is going on.

    Your device does perform a new provisioning request on it's own. In such a request the policies get redeployed to your device and a new provisioning key is generated.
    - In your log the new key 704342860 becomes valid in request pid 9296 at 31/01/2017 13:51:44 (line 5577 of your pm'ed log).
    - In the following request your device syncs the hierarchy and the new key is correctly validated (line 5604).
    - Next request everything is fine (line 5662), but there are no changes in the contacts, so the collection meta data is not updated (*cbf314f1-e81c-4ff5-86a1-56a62ba9a874-fd).
    - Exactly same thing for the next request (line 5726) - no changes in the calendar, no meta data update (*78efcf1e-812e-40bd-b5a2-eaec25a67624-fd). This folder is synched twice.

    Then the trouble starts. The device does a Ping request. For Ping itself the device does not send a provisioning key as in the standard sync requests. To still be able to detect policy changes, we take the so called reference policy key from the metadata of each folder and consider the last one. This is done in lines 5870+5871, 5877, 5883, 5889, 5895, 5900 (last one is the hierarchy meta data).
    The key is the same (the old one): 920708894, which is then used in Ping (line 5905).
    But we know, that this one will not match (line 5959) so we decide to request a FolderSync (which normally should lead to an update).
    This then loops for a few times, Ping, FolderSync, Sync, Ping etc which after some point triggers the ProcessLoopDetection that decides to resynchronize your hierarchy.

    I think the fix is that we need to force the update of the meta data in case the provisioning keys of the metadata doesn't match the one sent from the device.
    I created a ticket for this https://jira.z-hub.io/browse/ZP-1151 and will fix it asap.

    Cheers,
    Sebastian

  10. #10
    Junior Member
    Join Date
    Aug 2009
    Location
    Bavaria
    Posts
    15
    That's great, thanks a lot!
    I'll update to b1 as soon as it is available and keep monitoring.

Page 1 of 2 12 LastLast

Similar Threads

  1. Replies: 2
    Last Post: 12-11-2015, 09:21 AM
  2. Two EAS accounts on one device Breaks Z-push
    By jktp34 in forum Z-Push when using other backends
    Replies: 12
    Last Post: 18-10-2015, 12:01 AM
  3. Z-Push 2.2 Beta1 breaks provisioning with WP7.8 on Lumia 710
    By baloan in forum Z-Push when using Kopano/Zarafa
    Replies: 2
    Last Post: 08-11-2014, 04:06 PM
  4. Z-Push: PHP warning about HTTP_RAW_POST_DATA breaks headers output
    By TheSpooler in forum Z-Push when using Kopano/Zarafa
    Replies: 1
    Last Post: 05-10-2014, 10:31 AM
  5. Z-Push 2.1.2 & 2.1.3 breaks with WP7.8 on Lumia 710
    By baloan in forum Z-Push when using Kopano/Zarafa
    Replies: 3
    Last Post: 06-08-2014, 10:13 PM

Bookmarks

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •