PAM 4.5.x with Advanced Authentication 6.4.x MFA does not work

Dear community,


we are currently trying to integrate PAM 4.5 (on SLES) with AA 6.4.x as outlined in the documentation here:
www.netiq.com/.../t4ayo9ecmnrx.html

The configuration in the applications is working, i.e. the endpoint is successfully created in AA and can be linked in the generic event (white listed). Event name and endpoint name match in PAM and AA.
Chains are created (1. LDAP password and 2. TOTP) and the repo is referenced and named identically to the LDAP config in PAM and the resource in the credential vault.

eDirectory is being used as repo.


The settings in PAM are set to 'enabled' for secondary authentication.

Now, here is the issue:

When we try to login, be it to the web UI or via SSH relay to a protected resource, we get a login error after entering the users LDAP password.

In unified LOG with TRACE enabled I can see the following:

Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Authentication status 401, type 200 : Advanced Authentication

Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Warning, User authentication failed for i001888@vm-demo-eu-microfocus-pam-001

Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, start logon process completed.
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, Closing peer SSL 7fc63408a278
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, Closing peer 7fc63408a278
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Trace, spf_http_do_ReSTCall response ::
<o.n.NULL>
  <o.n.NULL current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1008" reason="PROCESS_STARTED" b.linked_logon="0" msg="Process has been started" status="MORE_DATA">
    <logon_hints>
      <policy b.save_password="1" b.cached_logon="1" b.disable_ldap_change="0" I.cached_logon_offline_period="60" sspr_caption="" sspr_url="" b.sspr_enabled="0"/>
    </logon_hints>
    <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
  </o.n.NULL>
</o.n.NULL>
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Trace, startLogon aa_do_ReSTCall response ::
<o.n.NULL>
  <o.n.NULL current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1008" reason="PROCESS_STARTED" b.linked_logon="0" msg="Process has been started" status="MORE_DATA">
    <logon_hints>
      <policy b.save_password="1" b.cached_logon="1" b.disable_ldap_change="0" I.cached_logon_offline_period="60" sspr_caption="" sspr_url="" b.sspr_enabled="0"/>
    </logon_hints>
    <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
  </o.n.NULL>
</o.n.NULL>
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, Logon process start - Response  -
<o.n.NULL current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1008" reason="PROCESS_STARTED" b.linked_logon="0" msg="Process has been started" status="MORE_DATA">
  <logon_hints>
    <policy b.save_password="1" b.cached_logon="1" b.disable_ldap_change="0" I.cached_logon_offline_period="60" sspr_caption="" sspr_url="" b.sspr_enabled="0"/>
  </logon_hints>
  <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
</o.n.NULL>
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, start logon -
<aaresponse current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1008" reason="PROCESS_STARTED" b.linked_logon="0" msg="Process has been started" status="MORE_DATA">
  <logon_hints>
    <policy b.save_password="1" b.cached_logon="1" b.disable_ldap_change="0" I.cached_logon_offline_period="60" sspr_caption="" sspr_url="" b.sspr_enabled="0"/>
  </logon_hints>
  <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
</aaresponse>
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Trace, spf_parser_put_bin binary spf_node_t 234:
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, aa_do_ReSTCall : sessionid = 6bRxq4qk4rvdu8JlwmXbZM2rGoORcApG
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, aa_do_ReSTCall : Final uri = https://testaafmicrofocus.acme-group.com/api/v1/logon/i6P1s5UBl1RP8bnglyEdkoz67JLneNkR/do_logon
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, spf_peer connect testaafmicrofocus.acme-group.com:443
Wed Jan 01 13:01:01 2025, 603, 1893754624, 1762, Debug, Connecting to testaafmicrofocus.acme-group.com:443
Wed Jan 01 13:01:01 2025, 606, 1893754624, 1762, Debug, spf_ssl_connect : Connecting to 'testaafmicrofocus.acme-group.com:443' in ssl mode '1'
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, spf_ssl_connect : SSL Connection opened - valid_site = 0 - valid_svc = 0 - verify callback = 21 - verified = 0
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Flushing 300 bytes
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Sending 300 bytes of data over ssl connection
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Writing 300 bytes from 7fc6340cdd70
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Written 300 bytes
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Sent 300 bytes of data over ssl connection
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Filling buffer
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, Buffer data:7fc6340cbd60 space:8192
Wed Jan 01 13:01:01 2025, 607, 1893754624, 1762, Debug, SSL has 0 bytes of pending data
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Socket has pending data (1)
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, spf_ssl_socket_recv : Reading 8192 bytes
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Read 1400 bytes
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, SSL has 0 bytes of pending data
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Socket has pending data (1)
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, spf_ssl_socket_recv : Reading 6792 bytes
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Read 426 bytes
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, SSL has 0 bytes of pending data
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Socket has no pending data (0)
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Buffer now has 1826 bytes available
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Response Headers - HTTP/1.1 200 OK
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Response Headers - Date: Wed, 01 Jan 2025 13:01:01 GMT
Wed Jan 01 13:01:01 2025, 663, 1893754624, 1762, Debug, Response Headers - Content-Type: application/json
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - Content-Length: 1318
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - Connection: keep-alive
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - Cache-Control: no-store
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - Strict-Transport-Security: max-age=63072000; includeSubdomains
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - Content-Security-Policy: frame-ancestors 'self' ; base-uri 'none'; script-src 'self' 'nonce-fadeaaa8552b221e5818c04155a383f2' 'unsafe-eval'; object-src 'none'
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - Referrer-Policy: no-referrer
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - X-Frame-Options: SAMEORIGIN
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - X-XSS-Protection: 1; mode=block
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Response Headers - X-Content-Type-Options: nosniff
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, logon completed.
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Closing peer SSL 7fc63408ad78
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Closing peer 7fc63408ad78
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Trace, spf_http_do_ReSTCall response ::
<o.n.NULL>
  <o.n.NULL current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" completed_methods="LDAP_PASSWORD:1" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1091" user_last_name="Chattertoni" user_first_name="Jordainn" user_dn="cn=i001888,ou=users,o=data" user_cn="i001888" user_role_assignments="ALL USERS" tenant_name="TOP" user_email="redacted" repo_obj_id="d7ee51302309584db87bd7ee51302309" repo_id="c0177f18c14211efbfe4ee14e15465a8" user_name="IDM1\\i001888" user_id="8b358e5317d2a714613105d526b421ce" plugins="LdapRules" b.linked_logon="0" msg="Welcome. Continue with the next login method" status="NEXT">
    <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
  </o.n.NULL>
</o.n.NULL>
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Secondary login - Response  -
<o.n.NULL current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" completed_methods="LDAP_PASSWORD:1" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1091" user_last_name="Chattertoni" user_first_name="Jordainn" user_dn="cn=i001888,ou=users,o=data" user_cn="i001888" user_role_assignments="ALL USERS" tenant_name="TOP" user_email="redacted" repo_obj_id="d7ee51302309584db87bd7ee51302309" repo_id="c0177f18c14211efbfe4ee14e15465a8" user_name="IDM1\\i001888" user_id="8b358e5317d2a714613105d526b421ce" plugins="LdapRules" b.linked_logon="0" msg="Welcome. Continue with the next login method" status="NEXT">
  <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
</o.n.NULL>
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Secondary login - Response  -
<o.n.NULL current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" completed_methods="LDAP_PASSWORD:1" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1091" user_last_name="Chattertoni" user_first_name="Jordainn" user_dn="cn=i001888,ou=users,o=data" user_cn="i001888" user_role_assignments="ALL USERS" tenant_name="TOP" user_email="redacted" repo_obj_id="d7ee51302309584db87bd7ee51302309" repo_id="c0177f18c14211efbfe4ee14e15465a8" user_name="IDM1\\i001888" user_id="8b358e5317d2a714613105d526b421ce" plugins="LdapRules" b.linked_logon="0" msg="Welcome. Continue with the next login method" status="NEXT">
  <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
</o.n.NULL>
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Trace, aa_login response ::
<aaresponse current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" completed_methods="LDAP_PASSWORD:1" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1091" user_last_name="Chattertoni" user_first_name="Jordainn" user_dn="cn=i001888,ou=users,o=data" user_cn="i001888" user_role_assignments="ALL USERS" tenant_name="TOP" user_email="redacted" repo_obj_id="d7ee51302309584db87bd7ee51302309" repo_id="c0177f18c14211efbfe4ee14e15465a8" user_name="IDM1\\i001888" user_id="8b358e5317d2a714613105d526b421ce" plugins="LdapRules" b.linked_logon="0" msg="Welcome. Continue with the next login method" status="NEXT">
  <a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
</aaresponse>
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Debug, Authentication status 401, type 200 : Advanced Authentication
Wed Jan 01 13:01:01 2025, 664, 1893754624, 1762, Warning, User authentication failed for i001888@vm-demo-eu-microfocus-pam-001
Wed Jan 01 13:01:01 2025, 665, 1893754624, 1762, Debug, --> spf_context_lookup_service (null)

In AA LOGs I cannot see any error. The 1. method LDAP Password seems to be successfully validated by AAF. 

And as you can see in the LOGs, the AA response seems to be a successful one:

Plain XML

<aaresponse current_category_id="" category_id="" data_id="AA-PAM-NATIVE" event_data_id="AA-PAM-NATIVE" b.event_all_categories="1" event_type="Generic" event_name="AA-PAM-Native" logon_process_id="i6P1s5UBl1RP8bnglyEdkoz67JLneNkR" completed_methods="LDAP_PASSWORD:1" current_method="LDAP_PASSWORD:1" msgid="AUCORE-1091" user_last_name="Chattertoni" user_first_name="Jordainn" user_dn="cn=i001888,ou=users,o=data" user_cn="i001888" user_role_assignments="ALL USERS" tenant_name="TOP" user_email="redacted" repo_obj_id="d7ee51302309584db87bd7ee51302309" repo_id="c0177f18c14211efbfe4ee14e15465a8" user_name="IDM1\\i001888" user_id="8b358e5317d2a714613105d526b421ce" plugins="LdapRules" b.linked_logon="0" msg="Welcome. Continue with the next login method" status="NEXT">
<a.chains risk_level="NONE" image_name="default" b.apply_for_ep_owner="0" I.position="0" methods.1="TOTP:1" methods.0="LDAP_PASSWORD:1" short_name="" name="DEMO PAM MFA" b.is_enabled="1" tenant_id="def0def0def0def0def0def0def0def0" id_hex="92e19154c60211ef90a14e76f5d96541"/>
</aaresponse>

Better readable XML Tree

Methods LDAP password and TOTP are (auto-)enrolled and tested for the user.

Any ideas, what we could look for or what the underlying issue could be?

Side node:

We also tried the OAuth2 integration with AA as described here:

www.netiq.com/.../t4hr5ti99y9o.html

This one works like a charm for the web UI. But it seems you cannot use it to enforce MFA for protected resource access.

Best regards,

Philipp