Zimbra4ucs connector exception

Hi, can’t seem to get the zimbra connector working on my testlab.

Have installed zimbra. And have run the zimbra connector wizard against a mail domain. And indeed an initial user account in the directory with an email specifed was initially created.

However any subsequent attempt to modify the user (password/zimbra account status) results in the below exception regarding ZimbraNotInitialized()

Not sure how to troubleshoot, as you can see from the zimbra4ucs log the initial setup and connection to zimbra is working. Seems only subsequent changes fail, there are files located in the /var/lib/zimbra4ucs-user-listener/ location.

Have tried uninstalling and reinstalling and removing domains and users from zimbra with no improvement.

Zimbra4ucs connector log shows wizard initialisation and subsequent failure to modify:

2018-07-07 14:40:34,777 - INFO - processing file: /var/lib/zimbra4ucs-user-listener/1530937964.531754
2018-07-07 14:40:34,778 - INFO - create uid=fblogs,cn=users,dc=homelab,dc=intranet
2018-07-07 14:40:34,778 - INFO - Request 'CreateAccountRequest' with {'a': [{'_content': 'fred', 'n': 'gn'}, {'_content': 'blogs', 'n': 'sn'}, {'_content': 'fred blogs', 'n': 'displayName'}, {'_content': 'FALSE', 'n': 'zimbraHideInGal'}, {'_content': 'active', 'n': 'zimbraAccountStatus'}, {'_content': 'FALSE', 'n': 'zimbraIsSystemAccount'}, {'_content': 'FALSE', 'n': 'zimbraIsAdminAccount'}, {'_content': 'FALSE', 'n': 'zimbraIsSystemResource'}], 'name': 'fred@homelab.intranet'}
2018-07-07 14:40:34,798 - INFO - processing file: /var/lib/zimbra4ucs-user-listener/1530937964.623981
2018-07-07 14:40:34,799 - INFO - modify uid=fblogs,cn=users,dc=homelab,dc=intranet
2018-07-07 14:40:34,799 - INFO - changes {'entryCSN': (['20180707043244.603316Z#000000#000#000000'], ['20180707043244.504695Z#000000#000#000000']), 'sambaPrimaryGroupSID': (['S-1-5-21-514488223-688142699-2505213924-513'], None)}
2018-07-07 14:40:34,800 - INFO - Request 'GetAccountRequest' with {'account': {'by': 'name', '_content': 'fred@homelab.intranet'}, 'attrs': 'zimbraId'}
2018-07-07 14:40:34,815 - INFO - Request 'ModifyAccountRequest' with {'a': [], 'id': u'abe45140-9cca-4c75-8eef-93db80e2f089'}
2018-07-07 14:40:34,836 - INFO - processing file: /var/lib/zimbra4ucs-user-listener/1530937968.721671
2018-07-07 14:40:34,837 - INFO - modify uid=fblogs,cn=users,dc=homelab,dc=intranet
2018-07-07 14:40:34,837 - INFO - changes {'sambaSID': (['S-1-5-21-514488223-688142699-2505213924-1128'], ['S-1-4-2020']), 'memberOf': (['cn=Domain Users,cn=groups,dc=homelab,dc=intranet'], None), 'modifiersName': (['cn=admin,dc=homelab,dc=intranet'], ['uid=Administrator,cn=users,dc=homelab,dc=intranet']), 'entryCSN': (['20180707043248.706396Z#000000#000#000000'], ['20180707043244.603316Z#000000#000#000000']), 'modifyTimestamp': (['20180707043248Z'], ['20180707043244Z'])}
2018-07-07 14:40:34,838 - INFO - Request 'GetAccountRequest' with {'account': {'by': 'name', '_content': 'fred@homelab.intranet'}, 'attrs': 'zimbraId'}
2018-07-07 14:40:34,855 - INFO - Request 'ModifyAccountRequest' with {'a': [], 'id': u'abe45140-9cca-4c75-8eef-93db80e2f089'}
2018-07-07 14:40:40,065 - INFO - started with args: ['start'], opts: {'data_dir_maildomain': '/var/lib/zimbra4ucs-maildomain-listener', 'log_file': '/var/log/univention/zimbra4ucs.log', 'log_level': '3', 'dry_run': False, 'data_dir_user': '/var/lib/zimbra4ucs-user-listener'}
2018-07-07 14:40:40,082 - INFO - checking changes for maildomains
2018-07-07 14:40:40,082 - INFO - checking changes for user
2018-07-07 14:40:45,086 - INFO - checking changes for maildomains
2018-07-07 14:40:45,086 - INFO - checking changes for user
2018-07-07 14:40:50,092 - INFO - checking changes for maildomains
2018-07-07 14:40:50,092 - INFO - checking changes for user
2018-07-07 14:40:55,099 - INFO - checking changes for maildomains
2018-07-07 14:40:55,099 - INFO - checking changes for user
2018-07-07 14:41:00,104 - INFO - checking changes for maildomains
2018-07-07 14:41:00,104 - INFO - checking changes for user
2018-07-07 14:41:05,108 - INFO - checking changes for maildomains
2018-07-07 14:41:05,108 - INFO - checking changes for user
2018-07-07 14:41:10,114 - INFO - checking changes for maildomains
2018-07-07 14:41:10,114 - INFO - checking changes for user
2018-07-07 14:41:15,120 - INFO - checking changes for maildomains
2018-07-07 14:41:15,120 - INFO - checking changes for user
2018-07-07 14:41:20,126 - INFO - checking changes for maildomains
2018-07-07 14:41:20,126 - INFO - checking changes for user
2018-07-07 14:41:25,133 - INFO - checking changes for maildomains
2018-07-07 14:41:25,133 - INFO - checking changes for user
2018-07-07 14:41:25,133 - INFO - processing file: /var/lib/zimbra4ucs-user-listener/1530938481.521915
2018-07-07 14:41:25,134 - INFO - modify uid=fblogs,cn=users,dc=homelab,dc=intranet
2018-07-07 14:41:25,134 - INFO - changes {'modifiersName': (['uid=Administrator,cn=users,dc=homelab,dc=intranet'], ['cn=admin,dc=homelab,dc=intranet']), 'entryCSN': (['20180707044121.516358Z#000000#000#000000'], ['20180707043248.706396Z#000000#000#000000']), 'modifyTimestamp': (['20180707044121Z'], ['20180707043248Z']), 'zimbraAccountStatus': (['locked'], ['active'])}
2018-07-07 14:41:25,134 - ERROR - <traceback object at 0x7fb1dba2b9e0>
Traceback (most recent call last):
  File "/usr/sbin/zimbra4ucs-connector", line 72, in run
    opts.dry_run)
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/tools.py", line 96, in process_files
    cls.modify(dn, new, old)
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/models.py", line 158, in ldap_modify
    return cls(cls.get_connection(), **cls.map_ldap_attributes(old)).modify(cls.map_ldap_attributes(new))
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/models.py", line 173, in get_connection
    cls.connection = ZimbraConfiguration.get_connection()
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/__init__.py", line 150, in get_connection
    raise ZimbraNotInitialized()
ZimbraNotInitialized
2018-07-07 14:41:30,140 - INFO - checking changes for maildomains
2018-07-07 14:41:30,141 - INFO - checking changes for user
2018-07-07 14:41:30,141 - INFO - processing file: /var/lib/zimbra4ucs-user-listener/1530938481.521915
2018-07-07 14:41:30,141 - INFO - modify uid=fblogs,cn=users,dc=homelab,dc=intranet
2018-07-07 14:41:30,141 - INFO - changes {'modifiersName': (['uid=Administrator,cn=users,dc=homelab,dc=intranet'], ['cn=admin,dc=homelab,dc=intranet']), 'entryCSN': (['20180707044121.516358Z#000000#000#000000'], ['20180707043248.706396Z#000000#000#000000']), 'modifyTimestamp': (['20180707044121Z'], ['20180707043248Z']), 'zimbraAccountStatus': (['locked'], ['active'])}
2018-07-07 14:41:30,141 - ERROR - <traceback object at 0x7fb1dba43a28>
Traceback (most recent call last):
  File "/usr/sbin/zimbra4ucs-connector", line 72, in run
    opts.dry_run)
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/tools.py", line 96, in process_files
    cls.modify(dn, new, old)
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/models.py", line 158, in ldap_modify
    return cls(cls.get_connection(), **cls.map_ldap_attributes(old)).modify(cls.map_ldap_attributes(new))
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/models.py", line 173, in get_connection
    cls.connection = ZimbraConfiguration.get_connection()
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/__init__.py", line 150, in get_connection
    raise ZimbraNotInitialized()
ZimbraNotInitialized
2018-07-07 14:41:35,147 - INFO - checking changes for maildomains
2018-07-07 14:41:35,147 - INFO - checking changes for user
2018-07-07 14:41:35,148 - INFO - processing file: /var/lib/zimbra4ucs-user-listener/1530938481.521915
2018-07-07 14:41:35,148 - INFO - modify uid=fblogs,cn=users,dc=homelab,dc=intranet
2018-07-07 14:41:35,148 - INFO - changes {'modifiersName': (['uid=Administrator,cn=users,dc=homelab,dc=intranet'], ['cn=admin,dc=homelab,dc=intranet']), 'entryCSN': (['20180707044121.516358Z#000000#000#000000'], ['20180707043248.706396Z#000000#000#000000']), 'modifyTimestamp': (['20180707044121Z'], ['20180707043248Z']), 'zimbraAccountStatus': (['locked'], ['active'])}
2018-07-07 14:41:35,148 - ERROR - <traceback object at 0x7fb1dba2b488>
Traceback (most recent call last):
  File "/usr/sbin/zimbra4ucs-connector", line 72, in run
    opts.dry_run)
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/tools.py", line 96, in process_files
    cls.modify(dn, new, old)
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/models.py", line 158, in ldap_modify
    return cls(cls.get_connection(), **cls.map_ldap_attributes(old)).modify(cls.map_ldap_attributes(new))
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/models.py", line 173, in get_connection
    cls.connection = ZimbraConfiguration.get_connection()
  File "/usr/lib/pymodules/python2.7/zimbra4ucs/__init__.py", line 150, in get_connection
    raise ZimbraNotInitialized()
ZimbraNotInitialized

Zimbra /opt/zimbra/log/audit.log extract shows initialisation from module wizard:

2018-07-07 14:40:39,466 INFO  [qtp335471116-599:https:https://mail.homelab.intranet:7071/service/admin/soap] [name=admin@mail.homelab.intranet;mid=2;ip=192.168.1.10;port=48896;soapId=e48adca;] security - cmd=CreateAccount; name=zimbra4ucs@homelab.intranet; zimbraHideInGal=FALSE; zimbraAccountStatus=active; zimbraAuthLdapExternalDn=uid=zimbra4ucs,cn=users,dc=homelab,dc=intranet; displayName=Zimbra4UCS Service LDAP Account; zimbraIsAdminAccount=TRUE; gn=Zimbra4UCS Service; zimbraIsSystemResource=TRUE; description=Account used by Zimbra4UCS to authenticate against LDAP directory; zimbraIsSystemAccount=TRUE; sn=LDAP Account; zimbraMailStatus=enabled;
2018-07-07 14:40:39,495 INFO  [qtp335471116-625:https:https://mail.homelab.intranet:7071/service/admin/soap] [name=admin@mail.homelab.intranet;mid=2;ip=192.168.1.10;port=48900;soapId=e48adcc;] security - cmd=ModifyDomain; name=homelab.intranet; zimbraAuthLdapSearchFilter=(&(mailPrimaryAddress=%n)(objectClass=person)); zimbraAuthLdapSearchBindDn=uid=zimbra4ucs,cn=users,dc=homelab,dc=intranet; zimbraAuthLdapURL=ldap://ucs-4406.homelab.intranet:7389; zimbraAuthLdapStartTlsEnabled=TRUE; zimbraAuthLdapSearchBase=dc=homelab,dc=intranet; zimbraAuthLdapSearchBindPassword=2r4wb8EHhzftLgRXtz; zimbraAuthMech=ldap;

Nothing else comes through after this.

I think I worked out what I’m doing wrong.

There’s not really any documentation for the connector I could find other than what is in the wizard so I had made the assumption that you should run it once for each existing mail domain you want to adopt and sync with zimbra.

My issue was that because I ran the wizard several times against each existing domain, the last one I chose did not have a admin user inside it which I think is the source of the not initialised errors. If I make sure that the last time the wizard is run is against the maildomain that the original zimbra administrator account was assigned to it seems to work ok after that.

I realise now that you only need to run the wizard once against the mail domain that contains your admin user and any other mail domains you create in UCS will be synced after.

But it seems that running the wizard against existing mail domains in zimbra is the only way to get the connector to provision the LDAP auth settings. It doesn’t seem to modify existing domains - only ones it creates from scratch (other than in the wizard).

I suppose I could do this manually in zimbra instead, mirroring the settings of the first provisioned mail domain.

Hope I’m making sense.

1 Like
Mastodon