LDAP Service in FAC 4.1

[Michael_McDonnell]

Has something changed regarding the LDAP service or schema in FAC 4.1?

I have been experimenting with FAC 4.1 in my lab environment. In my lab I have FAC setup as an LDAP server. There are several local users setup on FAC and I have a FortiGate VM and vCenter setup to authenticate against FAC using LDAP. Under FAC 4.0 things worked as expected. After upgrading to FAC 4.1 I have been unable to get LDAP to work.

I even setup a brand new FAC deployment (instead of an upgrade of the existing server) and got the same results.

I am unable to authenticate any users against the FAC 4.1 LDAP service. Every attempt to authenticate (using either simple or standard binding) fails with "Invalid Credentials"

The debug logs shows the following for a typical attempt:

2016-04-11T08:21:39.797271-06:00 FortiAuthenticator slapd[12751]: slap_listener_activate(7):

2016-04-11T08:21:39.797517-06:00 FortiAuthenticator slapd[12751]: >>> slap_listener(ldap:///)

2016-04-11T08:21:39.798320-06:00 FortiAuthenticator slapd[12751]: connection_get(11): got connid=1024

2016-04-11T08:21:39.798329-06:00 FortiAuthenticator slapd[12751]: connection_read(11): checking for input on id=1024

2016-04-11T08:21:39.798334-06:00 FortiAuthenticator slapd[12751]: op tag 0x60, time 1460384499

2016-04-11T08:21:39.798338-06:00 FortiAuthenticator slapd[12751]: conn=1024 op=0 do_bind

2016-04-11T08:21:39.798342-06:00 FortiAuthenticator slapd[12751]: >>> dnPrettyNormal: <uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host>

2016-04-11T08:21:39.798346-06:00 FortiAuthenticator slapd[12751]: <<< dnPrettyNormal: <uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host>, <uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host>

2016-04-11T08:21:39.798349-06:00 FortiAuthenticator slapd[12751]: do_bind: version=3 dn="uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host" method=128

2016-04-11T08:21:39.798352-06:00 FortiAuthenticator slapd[12751]: ==>backsql_bind()

2016-04-11T08:21:39.798355-06:00 FortiAuthenticator slapd[12751]: ==>backsql_get_db_conn()

2016-04-11T08:21:39.798359-06:00 FortiAuthenticator slapd[12751]: <==backsql_get_db_conn()

2016-04-11T08:21:39.798362-06:00 FortiAuthenticator slapd[12751]: ==>backsql_attrlist_add(): adding "userPassword" to list

2016-04-11T08:21:39.798690-06:00 FortiAuthenticator slapd[12751]: ==>backsql_attrlist_add(): attribute "userPassword" is in list

2016-04-11T08:21:39.798699-06:00 FortiAuthenticator slapd[12751]: ==>backsql_attrlist_add(): adding "objectClass" to list

2016-04-11T08:21:39.798703-06:00 FortiAuthenticator slapd[12751]: ==>backsql_dn2id("uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host")

2016-04-11T08:21:39.798707-06:00 FortiAuthenticator slapd[12751]: backsql_dn2id("uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host"): id_query "SELECT id,keyval,oc_map_id,dn FROM ldap_entries WHERE upper(dn)=upper(?)"

2016-04-11T08:21:39.799333-06:00 FortiAuthenticator slapd[12751]: backsql_dn2id("uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host"): id=20 keyval=8 oc_id=1 dn=uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host

2016-04-11T08:21:39.799342-06:00 FortiAuthenticator slapd[12751]: >>> dnPrettyNormal: <uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host>

2016-04-11T08:21:39.799346-06:00 FortiAuthenticator slapd[12751]: <<< dnPrettyNormal: <uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host>, <uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host>

2016-04-11T08:21:39.799349-06:00 FortiAuthenticator slapd[12751]: <==backsql_dn2id("uid=vsphere-ldap,cn=ldap_admins,dc=oneview,dc=host"): err=0

2016-04-11T08:21:39.799493-06:00 FortiAuthenticator slapd[12751]: ==>backsql_attrlist_add(): attribute "userPassword" is in list

2016-04-11T08:21:39.799508-06:00 FortiAuthenticator slapd[12751]: ==>backsql_attrlist_add(): attribute "objectClass" is in list

2016-04-11T08:21:39.799511-06:00 FortiAuthenticator slapd[12751]: ==>backsql_attrlist_add(): adding "ref" to list

2016-04-11T08:21:39.799513-06:00 FortiAuthenticator slapd[12751]: ==>backsql_id2entry()

2016-04-11T08:21:39.799515-06:00 FortiAuthenticator slapd[12751]: backsql_id2entry(): custom attribute list

2016-04-11T08:21:39.799517-06:00 FortiAuthenticator slapd[12751]: backsql_id2entry(): attribute "userPassword" is not defined for objectlass "facPerson"

2016-04-11T08:21:39.799519-06:00 FortiAuthenticator slapd[12751]: ==>backsql_get_attr_vals(): oc="facPerson" attr="objectClass" keyval=8

2016-04-11T08:21:39.800085-06:00 FortiAuthenticator slapd[12751]: backsql_get_attr_vals(): number of values in query: 5

2016-04-11T08:21:39.800774-06:00 FortiAuthenticator slapd[12751]: <==backsql_get_attr_vals()

2016-04-11T08:21:39.800782-06:00 FortiAuthenticator slapd[12751]: backsql_id2entry(): attribute "ref" is not defined for objectlass "facPerson"

2016-04-11T08:21:39.800785-06:00 FortiAuthenticator slapd[12751]: <==backsql_id2entry()

2016-04-11T08:21:39.800789-06:00 FortiAuthenticator slapd[12751]: send_ldap_result: conn=1024 op=0 p=3

2016-04-11T08:21:39.800792-06:00 FortiAuthenticator slapd[12751]: send_ldap_response: msgid=1 tag=97 err=49

2016-04-11T08:21:39.800795-06:00 FortiAuthenticator slapd[12751]: <==backsql_bind()

2016-04-11T08:21:39.854379-06:00 FortiAuthenticator slapd[12751]: connection_get(11): got connid=1024

2016-04-11T08:21:39.854395-06:00 FortiAuthenticator slapd[12751]: connection_read(11): checking for input on id=1024

2016-04-11T08:21:39.854407-06:00 FortiAuthenticator slapd[12751]: op tag 0x42, time 1460384499

2016-04-11T08:21:39.854411-06:00 FortiAuthenticator slapd[12751]: ber_get_next on fd 11 failed errno=0 (Success)

2016-04-11T08:21:39.854415-06:00 FortiAuthenticator slapd[12751]: conn=1024 op=1 do_unbind

2016-04-11T08:21:39.854418-06:00 FortiAuthenticator slapd[12751]: connection_close: conn=1024 sd=11

[jamesdreid]

I am seeing the exact same issue with my installation with a nearly identical log output.  I have a ticket open with support to see if I can get it resolved and will send along any updates/resolutions as they are identified.

[Carl_Windsor_FTNT]

This is known issue and is fixed on FortiAuthenticator 4.1.1 under bug ID 0368376.  ETA is tracking towards the end of the month (May).