SASL Authentication Problem

Paul Bronson signaldeveloper at gmail.com
Tue Aug 25 18:04:10 CEST 2015 

Steps:

Finalized setup of kolab multi domain from directions. Turned off
canonicalization via your script.

Logged into kolabwebadmin, setup new domain "example.com"

Created new user. Logs in fine with:

Server Error: STATUS: Mailbox does not exist

Log as follows:

2015-08-25 12:01:02,031 pykolab.auth DEBUG [1293]: Starting LDAP...
2015-08-25 12:01:02,031 pykolab.auth DEBUG [1293]: Connecting to LDAP...
2015-08-25 12:01:02,031 pykolab.auth DEBUG [1293]: Attempting to use LDAP
URI ldap://localhost:389
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.set_option
((17, 3), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.set_option
((17, 3), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.simple_bind
(('cn=Directory Manager', 'JL1VsXSC55jkVH3', None, None), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.result4
((1, 1, -1, 0, 0, 0), {})
2015-08-25 12:01:02,045 sqlalchemy.engine.base.Engine INFO PRAGMA
table_info("entry")
2015-08-25 12:01:02,045 sqlalchemy.engine.base.Engine INFO PRAGMA
table_info("entry")
2015-08-25 12:01:02,045 sqlalchemy.engine.base.Engine INFO ()
2015-08-25 12:01:02,045 sqlalchemy.engine.base.Engine INFO ()
2015-08-25 12:01:02,048 sqlalchemy.pool.NullPool DEBUG [1293]: Connection
<sqlite3.Connection object at 0x24bdf10> checked out from pool
2015-08-25 12:01:02,048 sqlalchemy.pool.NullPool DEBUG [1293]: Connection
<sqlite3.Connection object at 0x24bdf10> checked out from pool
2015-08-25 12:01:02,049 sqlalchemy.engine.base.Engine INFO BEGIN (implicit)
2015-08-25 12:01:02,049 sqlalchemy.engine.base.Engine INFO BEGIN (implicit)
2015-08-25 12:01:02,050 sqlalchemy.engine.base.Engine INFO SELECT entry.id
AS entry_id, entry.uniqueid AS entry_uniqueid, entry.result_attribute AS
entry_result_attribute, entry.last_change AS entry_last_change
FROM entry ORDER BY entry.last_change DESC
 LIMIT ? OFFSET ?
2015-08-25 12:01:02,050 sqlalchemy.engine.base.Engine INFO SELECT entry.id
AS entry_id, entry.uniqueid AS entry_uniqueid, entry.result_attribute AS
entry_result_attribute, entry.last_change AS entry_last_change
FROM entry ORDER BY entry.last_change DESC
 LIMIT ? OFFSET ?
2015-08-25 12:01:02,050 sqlalchemy.engine.base.Engine INFO (1, 0)
2015-08-25 12:01:02,050 sqlalchemy.engine.base.Engine INFO (1, 0)
2015-08-25 12:01:02,051 pykolab.auth DEBUG [1293]: Using timestamp
'19000101000000Z'
2015-08-25 12:01:02,051 pykolab.auth DEBUG [1293]: Using filter
'(&(|(objectclass=kolabinetorgperson)(|(objectclass=kolabgroupofuniquenames)(objectclass=kolabgroupofurls))(|(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(objectclass=kolabsharedfolder))(objectclass=kolabsharedfolder))(modifytimestamp>=19000101000000Z))'
2015-08-25 12:01:02,052 pykolab.auth DEBUG [1293]: Finding domain root dn
for domain maindomain.com
2015-08-25 12:01:02,053 pykolab.auth DEBUG [1293]: Searching with filter
'(&(associatedDomain=maindomain.com))'
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.search_ext
(('cn=kolab,cn=config',
  2,
  '(&(associatedDomain=maindomain.com))',
  None,
  0,
  None,
  None,
  -1,
  0),
 {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
2015-08-25 12:01:02,054 pykolab.auth DEBUG [1293]: Synchronization is
searching against base DN: dc=maindomain,dc=com
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.search_ext
(('dc=maindomain,dc=com',
  2,

'(&(|(objectclass=kolabinetorgperson)(|(objectclass=kolabgroupofuniquenames)(objectclass=kolabgroupofurls))(|(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(objectclass=kolabsharedfolder))(objectclass=kolabsharedfolder))(modifytimestamp>=19000101000000Z))',
  ['*', 'nsuniqueid', 'mail', 'modifytimestamp'],
  0,
  [('1.2.840.113556.1.4.319', False, '0\x06\x02\x02\x01\xf4\x04\x00')],
  None,
  -1,
  0),
 {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268efc8>
ldap://localhost:389 - ReconnectLDAPObject.result4
((3, 1, -1, 0, 0, 0), {})
2015-08-25 12:01:02,058 pykolab.cli INFO Synchronizing users for
maindomain.com took 0 seconds
2015-08-25 12:01:02,058 pykolab.cli DEBUG [1293]: Running for domain
example.com
2015-08-25 12:01:02,058 pykolab.auth DEBUG [1293]: Called for domain '
example.com'
2015-08-25 12:01:02,058 pykolab.auth DEBUG [1293]: Called for domain None
2015-08-25 12:01:02,059 pykolab.auth DEBUG [1293]: Using section example.com
and domain example.com
2015-08-25 12:01:02,059 pykolab.auth DEBUG [1293]: Using section example.com
and domain example.com
2015-08-25 12:01:02,059 pykolab.cli INFO Worker process PoolWorker-2
handling cn=Accounting Managers,ou=Groups,dc=maindomain,dc=com
2015-08-25 12:01:02,059 pykolab.cli INFO Worker process PoolWorker-1
handling cn=Directory Administrators,dc=maindomain,dc=com
2015-08-25 12:01:02,059 pykolab.auth DEBUG [1293]: Connecting to
Authentication backend for domain example.com
2015-08-25 12:01:02,059 pykolab.cli INFO Worker process PoolWorker-3
handling cn=HR Managers,ou=Groups,dc=maindomain,dc=com
2015-08-25 12:01:02,059 pykolab.cli INFO Worker process PoolWorker-4
handling cn=QA Managers,ou=Groups,dc=maindomain,dc=com
2015-08-25 12:01:02,059 pykolab.cli INFO Worker process PoolWorker-5
handling cn=PD Managers,ou=Groups,dc=maindomain,dc=com
2015-08-25 12:01:02,059 pykolab.auth DEBUG [1293]: Section example.com has
no option 'auth_mechanism'
2015-08-25 12:01:02,060 pykolab.auth DEBUG [1293]: Starting LDAP...
2015-08-25 12:01:02,060 pykolab.auth DEBUG [1293]: Connecting to LDAP...
2015-08-25 12:01:02,061 pykolab.auth DEBUG [1293]: Attempting to use LDAP
URI ldap://localhost:389
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.set_option
((17, 3), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.set_option
((17, 3), {})
2015-08-25 12:01:02,061 pykolab.auth DEBUG [1293]: Listing domains...
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.simple_bind
(('cn=Directory Manager', 'JL1VsXSC55jkVH3', None, None), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.result4
((1, 1, -1, 0, 0, 0), {})
2015-08-25 12:01:02,063 pykolab.auth DEBUG [1293]: Searching with filter
'(&(associatedDomain=example.com))'
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.search_ext
(('cn=kolab,cn=config',
  2,
  '(&(associatedDomain=example.com))',
  ['associateddomain'],
  0,
  None,
  None,
  -1,
  0),
 {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x26f7050>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
2015-08-25 12:01:02,065 pykolab.auth DEBUG [1293]: Using section example.com
and domain example.com
2015-08-25 12:01:02,065 pykolab.auth DEBUG [1293]: Using section example.com
and domain example.com
2015-08-25 12:01:02,065 pykolab.auth DEBUG [1293]: Connecting to
Authentication backend for domain example.com
2015-08-25 12:01:02,065 pykolab.auth DEBUG [1293]: Section example.com has
no option 'auth_mechanism'
2015-08-25 12:01:02,065 pykolab.auth DEBUG [1293]: Starting LDAP...
2015-08-25 12:01:02,065 pykolab.auth DEBUG [1293]: Connecting to LDAP...
2015-08-25 12:01:02,066 pykolab.auth DEBUG [1293]: Attempting to use LDAP
URI ldap://localhost:389
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.set_option
((17, 3), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.set_option
((17, 3), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.simple_bind
(('cn=Directory Manager', 'JL1VsXSC55jkVH3', None, None), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.result4
((1, 1, -1, 0, 0, 0), {})
2015-08-25 12:01:02,070 sqlalchemy.engine.base.Engine INFO SELECT entry.id
AS entry_id, entry.uniqueid AS entry_uniqueid, entry.result_attribute AS
entry_result_attribute, entry.last_change AS entry_last_change
FROM entry ORDER BY entry.last_change DESC
 LIMIT ? OFFSET ?
2015-08-25 12:01:02,070 sqlalchemy.engine.base.Engine INFO SELECT entry.id
AS entry_id, entry.uniqueid AS entry_uniqueid, entry.result_attribute AS
entry_result_attribute, entry.last_change AS entry_last_change
FROM entry ORDER BY entry.last_change DESC
 LIMIT ? OFFSET ?
2015-08-25 12:01:02,070 sqlalchemy.engine.base.Engine INFO (1, 0)
2015-08-25 12:01:02,070 sqlalchemy.engine.base.Engine INFO (1, 0)
2015-08-25 12:01:02,071 pykolab.auth DEBUG [1293]: Using timestamp
'19000101000000Z'
2015-08-25 12:01:02,071 pykolab.auth DEBUG [1293]: Using filter
'(&(|(objectclass=kolabinetorgperson)(|(objectclass=kolabgroupofuniquenames)(objectclass=kolabgroupofurls))(|(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(objectclass=kolabsharedfolder))(objectclass=kolabsharedfolder))(modifytimestamp>=19000101000000Z))'
2015-08-25 12:01:02,071 pykolab.auth DEBUG [1293]: Finding domain root dn
for domain example.com
2015-08-25 12:01:02,075 pykolab.auth DEBUG [1293]: Searching with filter
'(&(associatedDomain=example.com))'
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.search_ext
(('cn=kolab,cn=config',
  2,
  '(&(associatedDomain=example.com))',
  None,
  0,
  None,
  None,
  -1,
  0),
 {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.result4
((2, False, 0, 0, 0, 0), {})
2015-08-25 12:01:02,076 pykolab.auth DEBUG [1293]: Synchronization is
searching against base DN: dc=example,dc=com
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.search_ext
(('dc=example,dc=com',
  2,

'(&(|(objectclass=kolabinetorgperson)(|(objectclass=kolabgroupofuniquenames)(objectclass=kolabgroupofurls))(|(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(objectclass=kolabsharedfolder))(objectclass=kolabsharedfolder))(modifytimestamp>=19000101000000Z))',
  ['*', 'nsuniqueid', 'mail', 'modifytimestamp'],
  0,
  [('1.2.840.113556.1.4.319', False, '0\x06\x02\x02\x01\xf4\x04\x00')],
  None,
  -1,
  0),
 {})
*** <ldap.ldapobject.ReconnectLDAPObject instance at 0x268fa28>
ldap://localhost:389 - ReconnectLDAPObject.result4
((3, 1, -1, 0, 0, 0), {})
2015-08-25 12:01:02,079 pykolab.cli INFO Synchronizing users for example.com
took 0 seconds
2015-08-25 12:01:02,080 pykolab.cli INFO Worker process PoolWorker-6
handling cn=Directory Administrators,dc=example,dc=com
2015-08-25 12:01:02,080 pykolab.cli INFO Worker process PoolWorker-7
handling uid=person,ou=People,dc=example,dc=com



Kolab lm shows nothing. Not even the exist mailbox on maindomain.com





On Tue, Aug 25, 2015 at 11:12 AM, Timotheus Pokorra <timotheus at kolab.org>
wrote:

> > That seems to eliminate my errors, but when I log in with a user on a
> > secondary domain I get:
> >
> > Server Error: STATUS: Mailbox does not exist
>
> does this show anything unusual:
>
> service kolabd stop
> kolab -d 9 sync 2>&1 | tee kolab-sync.log
> service kolabd start
>
> does this now show the mailbox:
> kolab lm
>
> Timotheus
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kolab.org/pipermail/users/attachments/20150825/1f522107/attachment-0001.html>

More information about the users mailing list