[sync] Help with sync setup
Harkin Banks
harkinbanks83 at gmail.com
Mon Jan 19 16:16:16 UTC 2009
I am trying to get sync working and am using a BlackBerry Curve 8330 with
the Funambol PIM sync plugin to do so. On the client side, the BlackBerry
indicates that it is syncing calendar item 4/7 and then fails with an error
message:
Sync may have failed due to loss of Internet connectivity. If the problem
presists...
I'm pretty sure that this has nothing to do with connectivity, however, as
signal is strong, the connection is just fine. Not only that, there is a
bunch of stuff (below) happening on the server side when I try to do the
sync. Further, the error log on the BB reads:
Http error: code=[500] msg=[Internal Server Error]
On the server side, below is the portion of horde.log that's generate on the
sync attempt. (NB: I have trimmed the sync down to just a calendar sync to
try to get the size of the log output under control a bit.) The thing is
that there is nothing that is officially an "error" as you can see.
Any thoughts are much appreciated. Thank you.
tail of horde.log:
Jan 19 16:02:10 HORDE [debug] [horde] Backend of class SyncML_Backend_Horde
created [pid 15502 on line 292 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend.php"]
Jan 19 16:02:10 HORDE [debug] [horde] New session created:
83a6aecb6a75254d019708e167cf7226 [pid 15502 on line 197 of
"/kolab/var/kolab/www/client/lib/SyncML/Command/SyncHdr.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Checking authentication for user
hbanks at example.com [pid 15502 on line 626 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Hook _prefs_change_hook_last_login in
application horde not called. [pid 15502 on line 1683 of
"/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Authenticated: yes; version: 1.2;
message ID: 1; source URI: fbb-809900296; target URI:
http://example.com/client/rpc.php; user: hbanks at example.com; charset: UTF-8;
wbxml: no [pid 15502 on line 432 of
"/kolab/var/kolab/www/client/lib/SyncML.php"]
Jan 19 16:02:10 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::readSyncAnchors(): SELECT syncml_clientanchor,
syncml_serveranchor FROM horde_syncml_anchors WHERE syncml_syncpartner = ?
AND syncml_db = ? AND syncml_uid = ?, values: fbb-809900296, calendar,
hbanks at example.com [pid 15502 on line 743 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:10 HORDE [debug] [horde] No info about previous syncs found for
device fbb-809900296 and database calendar [pid 15502 on line 197 of
"/kolab/var/kolab/www/client/lib/SyncML/Command/Alert.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Creating SyncML_Sync object for
database calendar; sync type 201 [pid 15502 on line 289 of
"/kolab/var/kolab/www/client/lib/SyncML/Command/Alert.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Received <Final> from client. [pid
15502 on line 50 of
"/kolab/var/kolab/www/client/lib/SyncML/Command/Final.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Handle <Final> for state Init [pid
15502 on line 663 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Sending <Final> to client [pid 15502
on line 502 of "/kolab/var/kolab/www/client/lib/SyncML.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Return message completed [pid 15502 on
line 543 of "/kolab/var/kolab/www/client/lib/SyncML.php"]
Jan 19 16:02:10 HORDE [debug] [horde] Max memory usage: 5242880 bytes [pid
15502 on line 339 of "/kolab/var/kolab/www/client/lib/Horde/Registry.php"]
Jan 19 16:02:14 HORDE [debug] [horde] Backend of class SyncML_Backend_Horde
created [pid 5298 on line 292 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend.php"]
Jan 19 16:02:14 HORDE [debug] [horde] Existing session continued:
83a6aecb6a75254d019708e167cf7226 [pid 5298 on line 204 of
"/kolab/var/kolab/www/client/lib/SyncML/Command/SyncHdr.php"]
Jan 19 16:02:14 HORDE [debug] [horde] Authenticated: yes; version: 1.2;
message ID: 2; source URI: fbb-809900296; target URI:
http://example.com/client/rpc.php; user: hbanks at example.com; charset: UTF-8;
wbxml: no [pid 5298 on line 432 of
"/kolab/var/kolab/www/client/lib/SyncML.php"]
Jan 19 16:02:14 HORDE [debug] [horde] Created device class
SyncML_Device_Sync4j [pid 5298 on line 55 of
"/kolab/var/kolab/www/client/lib/SyncML/Device.php"]
Jan 19 16:02:14 HORDE [debug] [horde] Handling <Replace> sent from client
[pid 5298 on line 211 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:14 HORDE [debug] [horde] Created device class
SyncML_Device_Sync4j [pid 5298 on line 55 of
"/kolab/var/kolab/www/client/lib/SyncML/Device.php"]
Jan 19 16:02:14 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131473272 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [horde] checking modification date of entry
suid 20090119T152505Z610510ed9zys4oy8 at example.com in calendar [pid 5298 on
line 554 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [kronolith] Hook _horde_hook_share_init in
application horde not called. [pid 5298 on line 1683 of
"/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [kronolith] Hook
_prefs_change_hook_display_remote_cals in application horde not called. [pid
5298 on line 1683 of "/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [nag] Hook _horde_hook_share_init in
application horde not called. [pid 5298 on line 1683 of
"/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [nag] Hook
_prefs_change_hook_display_tasklists in application horde not called. [pid
5298 on line 1683 of "/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [kronolith] Hook
_prefs_change_hook_display_external_cals in application horde not called.
[pid 5298 on line 1683 of "/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [kronolith] Hook
_prefs_change_hook_display_cals in application horde not called. [pid 5298
on line 1683 of "/kolab/var/kolab/www/client/lib/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getChangeTS(): SELECT syncml_timestamp FROM
horde_syncml_map WHERE syncml_syncpartner = ? AND syncml_db = ? AND
syncml_uid = ? AND syncml_suid = ?, values: fbb-809900296, calendar,
hbanks at example.com, 20090119T152505Z610510ed9zys4oy8 at example.com [pid 5298
on line 963 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:14 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131473272 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] Replaced in server db calendar client
id 2131473272 -> server id 20090119T152505Z610510ed9zys4oy8 at example.com [pid
5298 on line 468 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131473272 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::createUidMap(): UPDATE horde_syncml_map SET
syncml_suid = ?, syncml_timestamp = ? WHERE syncml_syncpartner = ? AND
syncml_db = ? AND syncml_uid = ? AND syncml_cuid = ?, values:
20090119T152505Z610510ed9zys4oy8 at example.com, 1232380936, fbb-809900296,
calendar, hbanks at example.com, 2131473272 [pid 5298 on line 859 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] Replaced entry
20090119T152505Z610510ed9zys4oy8 at example.com due to client request [pid 5298
on line 328 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:16 HORDE [debug] [horde] Handling <Replace> sent from client
[pid 5298 on line 211 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:16 HORDE [debug] [horde] Created device class
SyncML_Device_Sync4j [pid 5298 on line 55 of
"/kolab/var/kolab/www/client/lib/SyncML/Device.php"]
Jan 19 16:02:16 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131471728 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] checking modification date of entry
suid 20090119T152526Z16665xvw7wii8iw4 at example.com in calendar [pid 5298 on
line 554 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getChangeTS(): SELECT syncml_timestamp FROM
horde_syncml_map WHERE syncml_syncpartner = ? AND syncml_db = ? AND
syncml_uid = ? AND syncml_suid = ?, values: fbb-809900296, calendar,
hbanks at example.com, 20090119T152526Z16665xvw7wii8iw4 at example.com [pid 5298
on line 963 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:16 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131471728 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] Replaced in server db calendar client
id 2131471728 -> server id 20090119T152526Z16665xvw7wii8iw4 at example.com [pid
5298 on line 468 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131471728 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::createUidMap(): UPDATE horde_syncml_map SET
syncml_suid = ?, syncml_timestamp = ? WHERE syncml_syncpartner = ? AND
syncml_db = ? AND syncml_uid = ? AND syncml_cuid = ?, values:
20090119T152526Z16665xvw7wii8iw4 at example.com, 1232380940, fbb-809900296,
calendar, hbanks at example.com, 2131471728 [pid 5298 on line 859 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] Replaced entry
20090119T152526Z16665xvw7wii8iw4 at example.com due to client request [pid 5298
on line 328 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:20 HORDE [debug] [horde] Handling <Replace> sent from client
[pid 5298 on line 211 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:20 HORDE [debug] [horde] Created device class
SyncML_Device_Sync4j [pid 5298 on line 55 of
"/kolab/var/kolab/www/client/lib/SyncML/Device.php"]
Jan 19 16:02:20 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131471720 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] checking modification date of entry
suid 20090119T152541Z40636jrgja8yqh8o at example.com in calendar [pid 5298 on
line 554 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getChangeTS(): SELECT syncml_timestamp FROM
horde_syncml_map WHERE syncml_syncpartner = ? AND syncml_db = ? AND
syncml_uid = ? AND syncml_suid = ?, values: fbb-809900296, calendar,
hbanks at example.com, 20090119T152541Z40636jrgja8yqh8o at example.com [pid 5298
on line 963 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:20 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131471720 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] Replaced in server db calendar client
id 2131471720 -> server id 20090119T152541Z40636jrgja8yqh8o at example.com [pid
5298 on line 468 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131471720 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::createUidMap(): UPDATE horde_syncml_map SET
syncml_suid = ?, syncml_timestamp = ? WHERE syncml_syncpartner = ? AND
syncml_db = ? AND syncml_uid = ? AND syncml_cuid = ?, values:
20090119T152541Z40636jrgja8yqh8o at example.com, 1232380944, fbb-809900296,
calendar, hbanks at example.com, 2131471720 [pid 5298 on line 859 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] Replaced entry
20090119T152541Z40636jrgja8yqh8o at example.com due to client request [pid 5298
on line 328 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:24 HORDE [debug] [horde] Handling <Replace> sent from client
[pid 5298 on line 211 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:24 HORDE [debug] [horde] Created device class
SyncML_Device_Sync4j [pid 5298 on line 55 of
"/kolab/var/kolab/www/client/lib/SyncML/Device.php"]
Jan 19 16:02:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131473558 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] checking modification date of entry
suid 20090119T152600Z15783ad5oi6k6o4k at example.com in calendar [pid 5298 on
line 554 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getChangeTS(): SELECT syncml_timestamp FROM
horde_syncml_map WHERE syncml_syncpartner = ? AND syncml_db = ? AND
syncml_uid = ? AND syncml_suid = ?, values: fbb-809900296, calendar,
hbanks at example.com, 20090119T152600Z15783ad5oi6k6o4k at example.com [pid 5298
on line 963 of "/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131473558 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:31 HORDE [debug] [horde] Replaced in server db calendar client
id 2131473558 -> server id 20090119T152600Z15783ad5oi6k6o4k at example.com [pid
5298 on line 468 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:31 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::_getSuid(): SELECT syncml_suid FROM horde_syncml_map
WHERE syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ? AND
syncml_cuid = ?, values: fbb-809900296, calendar, hbanks at example.com,
2131473558 [pid 5298 on line 891 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:31 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::createUidMap(): UPDATE horde_syncml_map SET
syncml_suid = ?, syncml_timestamp = ? WHERE syncml_syncpartner = ? AND
syncml_db = ? AND syncml_uid = ? AND syncml_cuid = ?, values:
20090119T152600Z15783ad5oi6k6o4k at example.com, 1232380951, fbb-809900296,
calendar, hbanks at example.com, 2131473558 [pid 5298 on line 859 of
"/kolab/var/kolab/www/client/lib/SyncML/Backend/Horde.php"]
Jan 19 16:02:32 HORDE [debug] [horde] Replaced entry
20090119T152600Z15783ad5oi6k6o4k at example.com due to client request [pid 5298
on line 328 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:32 HORDE [debug] [horde] Received <Final> from client. [pid
5298 on line 50 of
"/kolab/var/kolab/www/client/lib/SyncML/Command/Final.php"]
Jan 19 16:02:32 HORDE [debug] [horde] Handle <Final> for state Sync [pid
5298 on line 663 of "/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:32 HORDE [debug] [horde] Creating <Sync> output for server
changes in database calendar [pid 5298 on line 379 of
"/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:32 HORDE [debug] [horde] Created device class
SyncML_Device_Sync4j [pid 5298 on line 55 of
"/kolab/var/kolab/www/client/lib/SyncML/Device.php"]
Jan 19 16:02:32 HORDE [debug] [horde] Compiling server changes from
1970-01-01 00:00:00 to 2009-01-19 16:02:10 [pid 5298 on line 409 of
"/kolab/var/kolab/www/client/lib/SyncML/Sync.php"]
Jan 19 16:02:32 HORDE [debug] [kronolith] Max memory usage: 13107200 bytes
[pid 5298 on line 339 of
"/kolab/var/kolab/www/client/lib/Horde/Registry.php"]
More information about the sync
mailing list