[sync] funambol sync 1.1.5 on blackberry 7280 authn/login not working

Sun Oct 8 10:01:51 PDT 2006

Ah...I didn't update the framework.  I've done that now, thanks.

That debug output on line 264 I added.  You can see the actual line I
added in my email.  But, yeah, I needed to update the framework.

So, I did the upgrade and it's going better.  Now, I can login, but I
get "Synchronization failed: String index out of range: -9".  I think
that's an internal funambol error, since it's a Java exception message,
but it's probably getting a bad value from Horde somewhere.  Here's the
relevant section of the log file:

Oct 08 12:54:02 HORDE [debug] [horde] SyncML: Existing session
continued: syncmlscpimblackberry12345678 [on line 53 of
"/usr/share/pear/SyncML/Command/SyncHdr.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SyncML: authorized=1 version=1
msgid=1 source=sc-pim-blackberry
target=http://www.reliableresponse.net/horde/rpc.php
user=david at reliableresponse.net charset=UTF-8 wbxml= [on line 293 of
"/usr/share/pear/SyncML.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 275 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml'  AND (c.datatree_parents LIKE ':11:12:13%' OR
c.datatree_id = 13 OR c.datatree_id IN (11, 12) OR c.datatree_parents
LIKE ':11:12:80:79%' OR c.datatree_id = 79 OR c.datatree_id IN (11, 12,
80) OR c.datatree_parents LIKE ':605:606:607%' OR c.datatree_id = 607 OR
c.datatree_id IN (605, 606) OR c.datatree_parents LIKE
':605:606:829:828%' OR c.datatree_id = 828 OR c.datatree_id IN (605,
606, 829)) [on line 144 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 275 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml'  AND (c.datatree_parents LIKE ':11:12:13%' OR
c.datatree_id = 13 OR c.datatree_id IN (11, 12) OR c.datatree_parents
LIKE ':11:12:80:79%' OR c.datatree_id = 79 OR c.datatree_id IN (11, 12,
80) OR c.datatree_parents LIKE ':605:606:607%' OR c.datatree_id = 607 OR
c.datatree_id IN (605, 606) OR c.datatree_parents LIKE
':605:606:829:828%' OR c.datatree_id = 828 OR c.datatree_id IN (605,
606, 829)) [on line 144 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SyncML: SyncML: No info about
previous syncs found for id david at reliableresponse.net:sc-pim-blackberry
and database calendar [on line 81 of
"/usr/share/pear/SyncML/Command/Alert.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 275 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml'  AND (c.datatree_parents LIKE ':11:12:13%' OR
c.datatree_id = 13 OR c.datatree_id IN (11, 12) OR c.datatree_parents
LIKE ':11:12:80:79%' OR c.datatree_id = 79 OR c.datatree_id IN (11, 12,
80) OR c.datatree_parents LIKE ':605:606:607%' OR c.datatree_id = 607 OR
c.datatree_id IN (605, 606) OR c.datatree_parents LIKE
':605:606:829:828%' OR c.datatree_id = 828 OR c.datatree_id IN (605,
606, 829)) [on line 144 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 275 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml'  AND (c.datatree_parents LIKE ':11:12:13%' OR
c.datatree_id = 13 OR c.datatree_id IN (11, 12) OR c.datatree_parents
LIKE ':11:12:80:79%' OR c.datatree_id = 79 OR c.datatree_id IN (11, 12,
80) OR c.datatree_parents LIKE ':605:606:607%' OR c.datatree_id = 607 OR
c.datatree_id IN (605, 606) OR c.datatree_parents LIKE
':605:606:829:828%' OR c.datatree_id = 828 OR c.datatree_id IN (605,
606, 829)) [on line 144 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::remove(): SELECT datatree_id FROM horde_datatree WHERE
group_uid = ? AND datatree_parents LIKE ? ORDER BY datatree_id [on line
684 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::remove(): DELETE FROM horde_datatree_attributes WHERE
datatree_id = ? [on line 706 of
"/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::remove(): DELETE FROM horde_datatree WHERE datatree_id = ?
[on line 716 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 275 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml'  AND (c.datatree_parents LIKE ':11:12:13%' OR
c.datatree_id = 13 OR c.datatree_id IN (11, 12) OR c.datatree_parents
LIKE ':11:12:80:79%' OR c.datatree_id = 79 OR c.datatree_id IN (11, 12,
80) OR c.datatree_parents LIKE ':605:606:607%' OR c.datatree_id = 607 OR
c.datatree_id IN (605, 606) OR c.datatree_parents LIKE ':60
5:606:829:828%' OR c.datatree_id = 828 OR c.datatree_id IN (605, 606,
829)) [on line 144 of "/usr/share/pear/Horde/DataTree/sql.php"]
Oct 08 12:54:02 HORDE [debug] [horde] SyncML: SyncML: return message
completed [on line 377 of "/usr/share/pear/SyncML.php"]

Everything looks dandy to me.  The one warning, no previous sync info
found, is an obvious correct situation, since I've never successfully
synced from this device.

What can I do to help debug this?

-Dave

On Sun, 2006-10-08 at 16:44 +0200, Karsten Fourmont wrote:
> Hi,
> 
>  > Oct 08 10:26:42 HORDE [debug] [horde] SyncML: Authorizing with user=,
>  > cred data=<valid base64 encoding of username:password>, format=,
>  > type=syncml:auth-basic [on line 264 of "/usr/share/pear/SyncML.php"]
> 
> That's still the outdated version of SyncML.php if you look at the 
> current SyncML.php here:
> http://cvs.horde.org/co.php?r=head&f=framework%2FSyncML%2FSyncML.php
> you'll see that there's no such log line in line 264.
> 
> Did you run the install-packages script (in framework) to have the 
> current packages installed in your /usr/share/pear directory?
> 
> The alternative way when dealing with cvs versions is to use the 
> scripts/createsymlinks script to provide the hore pear packages in 
> horde/libs. Then you have to remove the horde data from /usr/share/pear. 
> See www.horde.org for description on this.
> 
> Cheers,
>   Karsten
> 
> 
> David Rudder wrote:
> > I updated my CVS, but no luck so far.  I added this line
> > to /usr/share/pear/SyncML.php
> >             $GLOBALS['backend']->logMessage('Authorizing with user=' .
> >                 $user . ', cred data=' . $hdr->getCredData() .
> >                 ', format=' . $hdr->getCredFormat() .
> >                 ', type=' . $hdr->getCredType(),
> >                 __FILE__, __LINE__, PEAR_LOG_DEBUG);
> > at line 260.
> > 
> > Here's the horde logs:
> > Oct 08 10:26:42 HORDE [debug] [horde] SyncML: Existing session
> > continued: syncmlscpimblackberry12345678 [on line 53 of
> > "/usr/share/pear/SyncML/Command/SyncHdr.php"]
> > Oct 08 10:26:42 HORDE [debug] [horde] SyncML: Authorizing with user=,
> > cred data=<valid base64 encoding of username:password>, format=,
> > type=syncml:auth-basic [on line 264 of "/usr/share/pear/SyncML.php"]
> > Oct 08 10:26:42 HORDE [debug] [horde] SyncML: Invalid authorization! [on
> > line 277 of "/usr/share/pear/SyncML.php"]
> > Oct 08 10:26:42 HORDE [debug] [horde] SyncML: authorized= version=1
> > msgid=1 source=sc-pim-blackberry
> > target=http://www.reliableresponse.net/horde/rpc.php user= charset=UTF-8
> > wbxml= [on line 299 of "/usr/share/pear/SyncML.php"]
> > Oct 08 10:26:42 HORDE [debug] [horde] SyncML: SyncML: return message
> > completed [on line 383 of "/usr/share/pear/SyncML.php"]
> > 
> > 
> > I can see the user and format variables are empty, but the information
> > should be available in the credentials.  
> > 
> > Is there anything I can do to help?  I can try to take a ethernet
> > sniffer snapshot, but it's difficult since this is on a hosted server.
> > 
> > Thanks,
> > Dave
> > 
> > On Sat, 2006-10-07 at 15:56 +0200, Karsten Fourmont wrote:
> >> Hi,
> >>
> >> it seems your using an outdated version of Horde/SyncML. Please give the
> >> current cvs version a try.
> >>
> >> Any feedback on the blackberry is appreciated.
> >>
> >> Cheers,
> >>   Karsten
> >>
> >> David Rudder wrote:
> >>> I believe it's the 1st authentication call, like Chuck says.  That's my
> >>> login name to a shared pop/imap server.  A typical POP session is
> >>> USER drig at noses.org
> >>> PASS mypassword  (password changed to protect the innocent)
> >>>
> >>> It's not treated as a domain within Horde.
> >>>
> >>> I found a difference between sync4j/funambol and syncevolution.  It
> >>> turns out that my blackberry is giving the auth type of
> >>> "syncml:auth-basic" and syncevolution is using "b64".  I hardcoded the
> >>> type to "b64" in /usr/share/pear/SyncML.php (line 260-ish) and the
> >>> authentication worked!  But, I got "Synchronization failed: String index
> >>> out of range: -9" on my bb. 
> >>>
> >>> So, I'm making a little progress....
> >>>
> >>> -Dave
> >>>
> >>> On Fri, 2006-09-29 at 12:00 -0700, sync-request at lists.horde.org wrote:
> >>>
> >>>
> >>>> Quoting Karsten Fourmont <fourmont at gmx.de>:
> >>>>
> >>>>> Anybody knows if I have to call
> >>>>>
> >>>>> $auth->authenticate('drig at noses.org', $pwd);
> >>>>> or
> >>>>> $auth->authenticate('drig', $pwd, true, 'noses.org');
> >>>>>
> >>>>> for this username?
> >>>> The former - "noses.org" isn't the kind of realm being passed in the  
> >>>> 2nd version. It's possible that IMP auth or other hooks aren't being  
> >>>> used the way that drig at noses.org needs, though.
> >>>>
> >>>> -chuck
> >>>>
> >>>> -- 
> >>>> "we are plastered to the windshield of the bus that is time." - Chris
> >>>>
> >>>
> >>
> 