Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[INTEGRATION] SSSD integration #739

Open
vincentDcmps opened this issue Nov 18, 2023 · 26 comments
Open

[INTEGRATION] SSSD integration #739

vincentDcmps opened this issue Nov 18, 2023 · 26 comments
Labels
integration Connection between LLDAP and a service question Further information is requested

Comments

@vincentDcmps
Copy link

Describe the bug
Hello I try to integrate LLDAP with sssd
I have an attribute uidnumber to my user and can request it with ldapsearch

but when sssd try ti request LLDAP I have this error

[error]: [LDAP] Service Error: while handling incoming messages: while receiving LDAP op: ldapmsg invalid

no more with verbose mode
@vincentDcmps vincentDcmps added the bug Something isn't working label Nov 18, 2023
@martadinata666 martadinata666 changed the title [BUG] SSD integration [BUG] SSSD integration Nov 18, 2023
@nitnelave
Copy link
Member

Hmm, is there any relevant logging from sssd?

Otherwise, I'd be curious to see a packet capture (with tcpdump) of the LDAP traffic to LLDAP

@vincentDcmps
Copy link
Author

I have done a packet capture
https://vault.ducamps.eu/#/send/syGHEmYDQKOFWC58dgN9Wg/wMOCI-I2MIxLfkC8zw3MHw

@vincentDcmps
Copy link
Author

sssd log here:
https://vault.ducamps.eu/#/send/EJymlXMkQzCb8IMzqhmkLw/wuTPJiDP0dwE4qKUXvnS9w

@nitnelave
Copy link
Member

Sorry @vincentDcmps the link has expired, could you re-upload it if you still have it?

@vincentDcmps
Copy link
Author

https://vault.ducamps.eu/#/send/vtQ_K72oTQyh2WqAx8K-ZQ/6QfL_32S4pHrJ4PyF8Sr4A
https://vault.ducamps.eu/#/send/XKY5p2pnSt-j5pzRven5JQ/wll1Vz-3ugP_3yTnT9Q8Hg

@nitnelave
Copy link
Member

Alright, found the culprit: "controlType: 1.3.6.1.4.1.42.2.27.8.5.1 (passwordPolicy)". I'll talk with @Firstyear to see what we can do at the parsing level.

@nitnelave
Copy link
Member

Filed kanidm/ldap3#46

@vincentDcmps
Copy link
Author

vincentDcmps commented Jan 7, 2024 •
edited

Hi thanks your pull request seem to be merge do you know if you can integrate last version in lldap to test?
or maybe is already in latest docker build if it's the case I have now the following message in LLDAP log

2024-01-07T10:03:45.279238344+00:00  WARN     ┝━ 🚧 [warn]: Unsupported control oid | oid: 1.3.6.1.4.1.42.2.27.8.5.1
2024-01-07T10:03:45.279241366+00:00  INFO     ┕━ LDAP request [ 1.14µs | 0.64% ]
2024-01-07T10:03:45.279340201+00:00  ERROR    🚨 [error]: [LDAP] Service Error: while handling incoming messages: while receiving LDAP op: ldapmsg invalid

@nitnelave nitnelave mentioned this issue Jan 8, 2024
Merged
@nitnelave
Copy link
Member

Merged a change updating the dependency. Can you retry?

@vincentDcmps
Copy link
Author

vincentDcmps commented Jan 8, 2024 •
edited

ldap3_proto 0.4.2 is release 30th november fix commit are on 19th december so our requested modification is not in this version, no?

for information need to update rust:alpine image to 3.19 in root's dockerfile

@vincentDcmps
Copy link
Author

vincentDcmps commented Jan 8, 2024 •
edited

I have try to build lldap with last commit of ldap3_proto
by updating Cargo.toml with this

ldap3_proto = { git = "https://github.com/kanidm/ldap3.git"}

but I get following compilation issue:

101.2 error[E0603]: enum `LdapControl` is private
101.2   --> server/src/infra/ldap_server.rs:17:26
101.2    |
101.2 17 | use ldap3_proto::{proto::LdapControl, proto::LdapMsg, proto::LdapOp, LdapCodec};
101.2    |                          ^^^^^^^^^^^ private enum
101.2    |
101.2 note: the enum `LdapControl` is defined here
101.2   --> /usr/local/cargo/git/checkouts/ldap3-cfea33e97f10dc62/3870de5/proto/src/proto.rs:18:5
101.2    |
101.2 18 | use crate::control::LdapControl;
101.2    |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^
101.2
101.3 warning: unused import: `GroupColumn`
101.3   --> server/src/domain/types.rs:13:24
101.3    |
101.3 13 | pub use super::model::{GroupColumn, UserColumn};
101.3    |                        ^^^^^^^^^^^
101.3    |
101.3    = note: `#[warn(unused_imports)]` on by default
101.3
108.6 For more information about this error, try `rustc --explain E0603`.
108.6 warning: `lldap` (bin "lldap") generated 1 warning
108.6 error: could not compile `lldap` (bin "lldap") due to previous error; 1 warning emitted
108.6 warning: build failed, waiting for other jobs to finish...

I don't know rust at all so hard to debug for me

@nitnelave
Copy link
Member

I talked to @Firstyear about it, it's expected that there are breaks since it's not a released version. He's going to prepare another release soon that will include the fix.

@nitnelave nitnelave mentioned this issue Jan 16, 2024
Merged
@nitnelave
Copy link
Member

Can you try with the newest latest? It should work.

@vincentDcmps
Copy link
Author

so it's a litle better I explain
I have try to switch from my current ldap to my dev lldap, after that I can get some information:

root@gerard-dev:/var/log/sssd# getent passwd toto
toto:*:1000003:1000003:toto::

but after that I have try to remove my complete cache

oot@gerard-dev:/var/log/sssd# systemctl stop sssd
oot@gerard-dev:/var/log/sssd# rm -rf /var/lib/sss/db/
oot@gerard-dev:/var/log/sssd# rm -rf /var/lib/sss/db/*
oot@gerard-dev:/var/log/sssd# systemctl start sssd

and after that I can't get any information with the command getent
seem that sssd request some sudo attribute, I think first test work because this attribute was already in cache
so I think a lot of work is need to integrate sssd with lldap :)
below the sssd_ldap.log

(2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x0040): [RID#13] Unexpected result from ldap: Server is unwilling to perform(53), Unsupported user attribute for substring filter: AttributeName(CaseInsensitiveString("sudohost"))
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-16 20:38:03): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_execute] (0x0400): Back end is offline
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_execute] (0x0400): Task [Check if online (periodic)]: executing task, timeout 60 seconds
   *  (2024-01-16 20:38:05): [be[LDAP]] [check_if_online] (0x2000): Schedule check_if_online_delayed in 0s.
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_done] (0x0400): Task [Check if online (periodic)]: finished successfully
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_schedule] (0x0400): Task [Check if online (periodic)]: scheduling task 131 seconds from last execution time [1705434016]
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
   *  (2024-01-16 20:38:05): [be[LDAP]] [check_if_online_delayed] (0x2000): Trying to go back online!
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_reset_services] (0x1000): Resetting all servers in all services
   *  (2024-01-16 20:38:05): [be[LDAP]] [set_server_common_status] (0x0100): Marking server 'lldapLdap.service.consul' as 'name not resolved'
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_set_port_status] (0x0100): Marking port 389 of server 'lldapLdap.service.consul' as 'neutral'
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'lldapLdap.service.consul' as 'neutral'
   *  (2024-01-16 20:38:05): [be[LDAP]] [dp_attach_req] (0x0400): [RID#13] DP Request [Online Check #13]: REQ_TRACE: New request. Flags [0000].
   *  (2024-01-16 20:38:05): [be[LDAP]] [dp_attach_req] (0x0400): [RID#13] Number of active DP request: 1
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_send] (0x0100): [RID#13] Trying to resolve service 'LDAP'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'name not resolved'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_port_status] (0x1000): [RID#13] Port status of port 389 for server 'lldapLdap.service.consul' is 'neutral'
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_activate_timeout] (0x2000): [RID#13] Resolve timeout [dns_resolver_timeout] set to 6 seconds
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'name not resolved'
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_is_address] (0x4000): [RID#13] [lldapLdap.service.consul] does not look like an IP address
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying files
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#13] Trying to resolve A record of 'lldapLdap.service.consul' in files
   *  (2024-01-16 20:38:05): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'resolving name'
   *  (2024-01-16 20:38:05): [be[LDAP]] [check_if_online_delayed] (0x2000): Check online req created.
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying files
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#13] Trying to resolve AAAA record of 'lldapLdap.service.consul' in files
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_next] (0x0200): [RID#13] No more address families to retry
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying DNS
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_dns_query] (0x0100): [RID#13] Trying to resolve A record of 'lldapLdap.service.consul' in DNS
   *  (2024-01-16 20:38:05): [be[LDAP]] [schedule_request_timeout] (0x2000): [RID#13] Scheduling a timeout of 3 seconds
   *  (2024-01-16 20:38:05): [be[LDAP]] [schedule_timeout_watcher] (0x2000): [RID#13] Scheduling DNS timeout watcher
   *  (2024-01-16 20:38:05): [be[LDAP]] [unschedule_timeout_watcher] (0x4000): [RID#13] Unscheduling DNS timeout watcher
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_dns_parse] (0x1000): [RID#13] Parsing an A reply
   *  (2024-01-16 20:38:05): [be[LDAP]] [request_watch_destructor] (0x0400): [RID#13] Deleting request watch
   *  (2024-01-16 20:38:05): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'name resolved'
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_resolve_server_process] (0x1000): [RID#13] Saving the first resolved server
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_resolve_server_process] (0x0200): [RID#13] Found address for server lldapLdap.service.consul: [192.168.121.39] TTL 0
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_uri_callback] (0x0400): [RID#13] Constructed uri 'ldap://lldapLdap.service.consul'
   *  (2024-01-16 20:38:05): [be[LDAP]] [sssd_async_socket_init_send] (0x4000): [RID#13] Using file descriptor [19] for the connection.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sssd_async_socket_init_send] (0x0400): [RID#13] Setting 6 seconds timeout [ldap_network_timeout] for connecting
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_ldap_connect_callback_add] (0x4000): [RID#13] New connection to [ldap://lldapLdap.service.consul:389/??base] with fd [19]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_rootdse_send] (0x4000): [RID#13] Getting rootdse
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#13] calling ldap_search_ext with [(objectclass=*)][].
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [*]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [altServer]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [namingContexts]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedControl]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedExtension]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedFeatures]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedLDAPVersion]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedSASLMechanisms]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [domainControllerFunctionality]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [defaultNamingContext]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [lastUSN]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [highestCommittedUSN]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#13] ldap_search_ext called, msgid = 1
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_add] (0x2000): [RID#13] New operation 1 timeout 6
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997dcb0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_ENTRY]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_entry] (0x1000): [RID#13] OriginalDN: [].
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [objectClass]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [vendorName]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [vendorVersion]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedLDAPVersion]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedExtension]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedControl]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_entry] (0x1000): [RID#13] Attribute [supportedControl] has no values, skipping.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedFeatures]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [defaultNamingContext]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [namingContexts]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [isGlobalCatalogReady]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997dcb0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997dcb0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#13] Search result: Success(0), no errmsg set
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#13] Total count [1]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#13] Operation 1 finished
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_rootdse_done] (0x2000): [RID#13] Got rootdse
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_rootdse_done] (0x2000): [RID#13] Skipping auto-detection of match rule
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_server_opts_from_rootdse] (0x0200): [RID#13] No known USN scheme is supported by this server!
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_cli_auth_step] (0x0100): [RID#13] expire timeout is 900
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_cli_auth_step] (0x1000): [RID#13] the connection will expire at 1705434785
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_send] (0x0100): [RID#13] Executing simple bind as: uid=admin,ou=people,dc=ducamps,dc=eu
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_send] (0x2000): [RID#13] ldap simple bind sent, msgid = 2
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_add] (0x2000): [RID#13] New operation 2 timeout 8
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997dcb0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997dcb0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_BIND]
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_done] (0x1000): [RID#13] Server returned no controls.
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_done] (0x0400): [RID#13] Bind result: Success(0), no errmsg set
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#13] Operation 2 finished
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_cli_connect_recv] (0x0400): [RID#13] Connection established.
   *  (2024-01-16 20:38:05): [be[LDAP]] [_be_fo_set_port_status] (0x8000): [RID#13] Setting status: PORT_WORKING. Called from: ../src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2155
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_set_port_status] (0x0100): [RID#13] Marking port 389 of server 'lldapLdap.service.consul' as 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_set_port_status] (0x0400): [RID#13] Marking port 389 of duplicate server 'lldapLdap.service.consul' as 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_handle_release] (0x2000): [RID#13] Trace: sh[0x55974997dcb0], connected[1], ops[(nil)], ldap[0x5597499a1a90], destructor_lock[0], release_memory[0]
   *  (2024-01-16 20:38:05): [be[LDAP]] [remove_connection_callback] (0x4000): [RID#13] Successfully removed connection callback.
   *  (2024-01-16 20:38:05): [be[LDAP]] [dp_req_done] (0x0400): [RID#13] DP Request [Online Check #13]: Request handler finished [0]: Success
   *  (2024-01-16 20:38:05): [be[LDAP]] [_dp_req_recv] (0x0400): [RID#13] DP Request [Online Check #13]: Receiving request data.
   *  (2024-01-16 20:38:05): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#13] DP Request [Online Check #13]: Request removed.
   *  (2024-01-16 20:38:05): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#13] Number of active DP request: 0
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_check_online_done] (0x0400): [RID#13] Backend is online
   *  (2024-01-16 20:38:05): [be[LDAP]] [reactivate_subdoms] (0x1000): [RID#13] Resetting all subdomains
   *  (2024-01-16 20:38:05): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#13] Domain LDAP is Active
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_disable] (0x0400): [RID#13] Task [Check if online (periodic)]: disabling task
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_run_online_cb] (0x0080): [RID#13] Going online. Running callbacks.
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_online_cb] (0x0400): [RID#13] Back end is online
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_enable] (0x0400): [RID#13] Task [SUDO Smart Refresh]: enabling task
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_schedule] (0x0400): [RID#13] Task [SUDO Smart Refresh]: scheduling task 900 seconds from now [1705434785]
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_online_cb] (0x0400): [RID#13] Back end is online
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_enable] (0x0400): [RID#13] Task [SUDO Full Refresh]: enabling task
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_schedule] (0x0400): [RID#13] Task [SUDO Full Refresh]: scheduling task 0 seconds from now [1705433885]
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_execute] (0x0400): [RID#13] Task [SUDO Full Refresh]: executing task, timeout 21600 seconds
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_full_refresh_send] (0x0400): [RID#13] Issuing a full refresh of sudo rules
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#13] beginning to connect
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_send] (0x0100): [RID#13] Trying to resolve service 'LDAP'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_port_status] (0x1000): [RID#13] Port status of port 389 for server 'lldapLdap.service.consul' is 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_activate_timeout] (0x2000): [RID#13] Resolve timeout [dns_resolver_timeout] set to 6 seconds
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_resolve_server_process] (0x1000): [RID#13] Saving the first resolved server
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_resolve_server_process] (0x0200): [RID#13] Found address for server lldapLdap.service.consul: [192.168.121.39] TTL 0
   *  (2024-01-16 20:38:05): [be[LDAP]] [sssd_async_socket_init_send] (0x4000): [RID#13] Using file descriptor [19] for the connection.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sssd_async_socket_init_send] (0x0400): [RID#13] Setting 6 seconds timeout [ldap_network_timeout] for connecting
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_ldap_connect_callback_add] (0x4000): [RID#13] New connection to [ldap://lldapLdap.service.consul:389/??base] with fd [19]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_rootdse_send] (0x4000): [RID#13] Getting rootdse
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#13] calling ldap_search_ext with [(objectclass=*)][].
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [*]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [altServer]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [namingContexts]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedControl]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedExtension]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedFeatures]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedLDAPVersion]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [supportedSASLMechanisms]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [domainControllerFunctionality]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [defaultNamingContext]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [lastUSN]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [highestCommittedUSN]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#13] ldap_search_ext called, msgid = 1
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_add] (0x2000): [RID#13] New operation 1 timeout 6
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_ENTRY]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_entry] (0x1000): [RID#13] OriginalDN: [].
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [objectClass]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [vendorName]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [vendorVersion]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedLDAPVersion]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedExtension]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedControl]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_entry] (0x1000): [RID#13] Attribute [supportedControl] has no values, skipping.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [supportedFeatures]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [defaultNamingContext]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [namingContexts]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#13] No sub-attributes for [isGlobalCatalogReady]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#13] Search result: Success(0), no errmsg set
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#13] Total count [1]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#13] Operation 1 finished
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_rootdse_done] (0x2000): [RID#13] Got rootdse
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_rootdse_done] (0x2000): [RID#13] Skipping auto-detection of match rule
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_server_opts_from_rootdse] (0x0200): [RID#13] No known USN scheme is supported by this server!
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_cli_auth_step] (0x0100): [RID#13] expire timeout is 900
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_cli_auth_step] (0x1000): [RID#13] the connection will expire at 1705434785
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_send] (0x0100): [RID#13] Executing simple bind as: uid=admin,ou=people,dc=ducamps,dc=eu
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_send] (0x2000): [RID#13] ldap simple bind sent, msgid = 2
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_add] (0x2000): [RID#13] New operation 2 timeout 8
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_online_cb] (0x0400): [RID#13] We are back online. SUDO host information will be renewed on next refresh.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[0x55974997a650], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_BIND]
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_done] (0x1000): [RID#13] Server returned no controls.
   *  (2024-01-16 20:38:05): [be[LDAP]] [simple_bind_done] (0x0400): [RID#13] Bind result: Success(0), no errmsg set
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#13] Operation 2 finished
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_cli_connect_recv] (0x0400): [RID#13] Connection established.
   *  (2024-01-16 20:38:05): [be[LDAP]] [_be_fo_set_port_status] (0x8000): [RID#13] Setting status: PORT_WORKING. Called from: ../src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2155
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_set_port_status] (0x0100): [RID#13] Marking port 389 of server 'lldapLdap.service.consul' as 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_set_port_status] (0x0400): [RID#13] Marking port 389 of duplicate server 'lldapLdap.service.consul' as 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_done] (0x2000): [RID#13] Old USN: 0, New USN: 0
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_conn_data_start_idle_timer] (0x0100): [RID#13] idle timeout is 900
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_conn_data_start_idle_timer] (0x4000): [RID#13] Scheduling connection idle timer to run at 1705434785
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_done] (0x4000): [RID#13] notify connected to op #1
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_refresh_connect_done] (0x0400): [RID#13] SUDO LDAP connection successful
   *  (2024-01-16 20:38:05): [be[LDAP]] [check_ipv4_addr] (0x0200): [RID#13] Loopback IPv4 address 127.0.0.1
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_get_ip_addresses] (0x2000): [RID#13] Found IP address: 192.168.121.99 in network 192.168.121.0/24
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_get_ip_addresses] (0x2000): [RID#13] Found IP address: 192.168.121.100 in network 192.168.121.0/24
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_get_ip_addresses] (0x2000): [RID#13] Found IP address: 10.0.1.6 in network 10.0.1.0/24
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_get_ip_addresses] (0x2000): [RID#13] Found IP address: 172.17.0.1 in network 172.17.0.0/16
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_get_hostnames_send] (0x2000): [RID#13] Found hostname: gerard-dev
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_is_address] (0x4000): [RID#13] [gerard-dev] does not look like an IP address
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying files
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#13] Trying to resolve A record of 'gerard-dev' in files
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_done] (0x4000): [RID#13] caching successful connection after 1 notifies
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_run_unconditional_online_cb] (0x4000): [RID#13] List of unconditional online callbacks is empty, nothing to do.
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying files
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#13] Trying to resolve AAAA record of 'gerard-dev' in files
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_next] (0x0200): [RID#13] No more address families to retry
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying DNS
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[(nil)], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_dns_query] (0x0100): [RID#13] Trying to resolve A record of 'gerard-dev' in DNS
   *  (2024-01-16 20:38:05): [be[LDAP]] [schedule_request_timeout] (0x2000): [RID#13] Scheduling a timeout of 3 seconds
   *  (2024-01-16 20:38:05): [be[LDAP]] [schedule_timeout_watcher] (0x2000): [RID#13] Scheduling DNS timeout watcher
   *  (2024-01-16 20:38:05): [be[LDAP]] [unschedule_timeout_watcher] (0x4000): [RID#13] Unscheduling DNS timeout watcher
   *  (2024-01-16 20:38:05): [be[LDAP]] [resolv_gethostbyname_dns_parse] (0x1000): [RID#13] Parsing an A reply
   *  (2024-01-16 20:38:05): [be[LDAP]] [request_watch_destructor] (0x0400): [RID#13] Deleting request watch
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_get_hostnames_done] (0x2000): [RID#13] Found fqdn: gerard-dev.ducamps-dev.eu
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_sudo_load_sudoers_send] (0x0400): [RID#13] About to fetch sudo rules
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_search_bases_ex_next_base] (0x0400): [RID#13] Issuing LDAP lookup with base [dc=ducamps,dc=eu]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#13] calling ldap_search_ext with [(&(objectClass=sudoRole)(|(&(!(sudoHost=*))(cn=defaults))(sudoHost=ALL)(sudoHost=gerard-dev)(sudoHost=gerard-dev.ducamps-dev.eu)(sudoHost=192.168.121.99)(sudoHost=192.168.121.0/24)(sudoHost=192.168.121.100)(sudoHost=192.168.121.0/24)(sudoHost=10.0.1.6)(sudoHost=10.0.1.0/24)(sudoHost=172.17.0.1)(sudoHost=172.17.0.0/16)(sudoHost=+*)))][dc=ducamps,dc=eu].
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [objectClass]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [objectClass]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [cn]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoCommand]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoHost]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoUser]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoOption]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoRunAs]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoRunAsUser]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoRunAsGroup]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoNotBefore]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoNotAfter]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [sudoOrder]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#13] Requesting attrs: [modifyTimestamp]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#13] ldap_search_ext called, msgid = 3
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_add] (0x2000): [RID#13] New operation 3 timeout 6
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x55974997b1c0], connected[1], ops[0x55974998e570], ldap[0x5597499a1a90]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#13] Search result: Server is unwilling to perform(53), Unsupported user attribute for substring filter: AttributeName(CaseInsensitiveString("sudohost"))
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_get_generic_op_finished] (0x0040): [RID#13] Unexpected result from ldap: Server is unwilling to perform(53), Unsupported user attribute for substring filter: AttributeName(CaseInsensitiveString("sudohost"))
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-16 20:38:05): [be[LDAP]] [generic_ext_search_handler] (0x0020): [RID#13] sdap_get_generic_ext_recv request failed: [5]: Input/output error
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#13] Operation 3 finished
   *  (2024-01-16 20:38:05): [be[LDAP]] [generic_ext_search_handler] (0x0020): [RID#13] sdap_get_generic_ext_recv request failed: [5]: Input/output error
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_send] (0x0020): [RID#13] No available servers for service 'LDAP'
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_search_bases_ex_done] (0x0400): [RID#13] Receiving data from base [dc=ducamps,dc=eu]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_done] (0x0200): [RID#13] communication error on cached connection, moving to next server
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#13] advising for connection retry #1
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#13] releasing operation connection
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_release_conn_data] (0x4000): [RID#13] Releasing unused connection with fd [19]
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_handle_release] (0x2000): [RID#13] Trace: sh[0x55974997b1c0], connected[1], ops[(nil)], ldap[0x5597499a1a90], destructor_lock[0], release_memory[0]
   *  (2024-01-16 20:38:05): [be[LDAP]] [remove_connection_callback] (0x4000): [RID#13] Successfully removed connection callback.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#13] beginning to connect
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_send] (0x0100): [RID#13] Trying to resolve service 'LDAP'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_port_status] (0x1000): [RID#13] Port status of port 389 for server 'lldapLdap.service.consul' is 'not working'
   *  (2024-01-16 20:38:05): [be[LDAP]] [get_port_status] (0x0080): [RID#13] SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues.
   *  (2024-01-16 20:38:05): [be[LDAP]] [fo_resolve_service_send] (0x0020): [RID#13] No available servers for service 'LDAP'
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-16 20:38:05): [be[LDAP]] [be_ptask_done] (0x0040): [RID#13] Task [SUDO Full Refresh]: failed with [11]: Resource temporarily unavailable
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_destroy] (0x4000): [RID#13] releasing operation connection
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_done] (0x0040): [RID#13] Task [SUDO Full Refresh]: failed with [11]: Resource temporarily unavailable
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_done] (0x0040): [RID#13] Failed to connect, going offline (5 [Input/output error])
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_schedule] (0x0400): [RID#13] Task [SUDO Full Refresh]: scheduling task 21600 seconds from now [1705455485]
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_resolve_server_done] (0x1000): [RID#13] Server [NULL] resolution failed: [5]: Input/output error
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_op_connect_done] (0x0040): [RID#13] Failed to connect, going offline (5 [Input/output error])
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-16 20:38:07): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_mark_offline] (0x2000): [RID#13] Going offline!
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_mark_offline] (0x2000): [RID#13] Enable check_if_online_ptask.
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_enable] (0x0400): [RID#13] Task [Check if online (periodic)]: enabling task
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_schedule] (0x0400): [RID#13] Task [Check if online (periodic)]: scheduling task 85 seconds from now [1705433970]
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_run_offline_cb] (0x0080): [RID#13] Going offline. Running callbacks.
   *  (2024-01-16 20:38:05): [be[LDAP]] [sdap_id_release_conn_data] (0x4000): [RID#13] Releasing unused connection with fd [-1]
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_offline_cb] (0x0400): [RID#13] Back end is offline
   *  (2024-01-16 20:38:05): [be[LDAP]] [be_ptask_disable] (0x0400): [RID#13] Task [SUDO Smart Refresh]: disabling task
   *  (2024-01-16 20:38:06): [be[LDAP]] [be_ptask_offline_cb] (0x0400): [RID#13] Back end is offline
   *  (2024-01-16 20:38:06): [be[LDAP]] [be_ptask_disable] (0x0400): [RID#13] Task [SUDO Full Refresh]: disabling task
   *  (2024-01-16 20:38:07): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-16 20:38:07): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-16 20:38:07): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
   *  (2024-01-16 20:38:07): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
   *  (2024-01-16 20:38:07): [be[LDAP]] [dp_get_account_info_send] (0x0200): Got request for [0x1][BE_REQ_USER][name=*@ldap]
   *  (2024-01-16 20:38:07): [be[LDAP]] [dp_attach_req] (0x0400): [RID#14] DP Request [Account #14]: REQ_TRACE: New request. [sssd.nss CID #2] Flags [0x0001].
   *  (2024-01-16 20:38:07): [be[LDAP]] [dp_attach_req] (0x0400): [RID#14] [CID #2] Backend is offline! Using cached data if available
   *  (2024-01-16 20:38:07): [be[LDAP]] [dp_attach_req] (0x0400): [RID#14] Number of active DP request: 1
   *  (2024-01-16 20:38:07): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#14] Domain LDAP is Active
   *  (2024-01-16 20:38:07): [be[LDAP]] [_dp_req_recv] (0x0400): DP Request [Account #14]: Receiving request data.
   *  (2024-01-16 20:38:07): [be[LDAP]] [dp_req_destructor] (0x0400): DP Request [Account #14]: Request removed.
   *  (2024-01-16 20:38:07): [be[LDAP]] [dp_req_destructor] (0x0400): Number of active DP request: 0
   *  (2024-01-16 20:38:07): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-16 20:38:07): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2024-01-16 20:38:07): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
   *  ... skipping repetitive backtrace ...
(2024-01-16 20:38:10): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline

@nitnelave
Copy link
Member

Ah, it's doing a substring search on a custom attribute... That's quite hard to support right now. I don't think it's going to work any time soon. I have a vague plan in mind, but it'll take a long time, if ever, to do.

@Firstyear
Copy link

SSSD loves to do substring searches in the most inefficient ways possible. I think if you remove "sudo" as a provider on the sssd.conf it stops it asking for sudohost. Generally you can ignore all the sudo queries it emits.

@vincentDcmps
Copy link
Author

I have already try that but sssd seem contunue to do sudo request

@Firstyear
Copy link

Depends how @nitnelave wants to proceed here, but I'd say simply dropping/ignoring any request that asks for sudo related terms with an empty response would silence the problem.

@Firstyear
Copy link

Or open a bug with SSSD?

@nitnelave
Copy link
Member

One thing that I can do is that if the substring filter concerns an attribute that doesn't exist, I can replace it with just "false". At least LLDAP will give a valid response to the query, if not the best possible.

@Firstyear
Copy link

One thing that I can do is that if the substring filter concerns an attribute that doesn't exist, I can replace it with just "false". At least LLDAP will give a valid response to the query, if not the best possible.

I actually think that's what the ldap specification requires. An unknown filter component evaluates to "false" or "empty set".

@nitnelave nitnelave mentioned this issue Jan 17, 2024
Merged
@nitnelave
Copy link
Member

Alright, let's have another try with latest!

@vincentDcmps
Copy link
Author

seem to have always some query issue on domain name from my understanding

   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_match_rule_add] (0x4000): Adding match rule for :1.4: org.freedesktop.DBus.NameOwnerChanged
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.AddMatch: Success
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_match_rule_add] (0x4000): Adding match rule for :1.4: org.freedesktop.DBus.NameAcquired
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.AddMatch: Success
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.DataProvider.Client.Register on /sssd
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.GetConnectionUnixUser on /org/freedesktop/DBus
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.GetConnectionUnixUser: Success
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_senders_add] (0x2000): Inserting identity of sender [sssd.pam]: 0
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_client_register] (0x0100): Added Frontend client [pam]
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_client_register] (0x0100): Cancel DP ID timeout [0x55f452a93f80]
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.DataProvider.Client.Register: Success
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_name_owner_changed] (0x4000): Name of owner :1.5 has changed from [] to [:1.5]
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_name_owner_changed] (0x4000): Name of owner sssd.pam has changed from [] to [sssd.pam]
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getDomains on /sssd
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_attach_req] (0x0400): [RID#3] DP Request [Subdomains #3]: REQ_TRACE: New request. Flags [0000].
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_attach_req] (0x0400): [RID#3] Number of active DP request: 1
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_find_method] (0x0100): [RID#3] Target [subdomains] is not initialized
   *  (2024-01-18 19:14:47): [be[LDAP]] [_dp_req_recv] (0x0400): DP Request [Subdomains #3]: Receiving request data.
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_req_destructor] (0x0400): DP Request [Subdomains #3]: Request removed.
   *  (2024-01-18 19:14:47): [be[LDAP]] [dp_req_destructor] (0x0400): Number of active DP request: 0
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_issue_request_done] (0x0200): sssd.dataprovider.getDomains: Error [1432158215]: DP target is not configured
   *  (2024-01-18 19:14:47): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-18 19:14:48): [be[LDAP]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
   *  (2024-01-18 19:14:48): [be[LDAP]] [check_if_online_delayed] (0x2000): Trying to go back online!
   *  (2024-01-18 19:14:48): [be[LDAP]] [fo_reset_services] (0x1000): Resetting all servers in all services
   *  (2024-01-18 19:14:48): [be[LDAP]] [set_server_common_status] (0x0100): Marking server 'lldapLdap.service.consul' as 'name not resolved'
   *  (2024-01-18 19:14:48): [be[LDAP]] [fo_set_port_status] (0x0100): Marking port 389 of server 'lldapLdap.service.consul' as 'neutral'
   *  (2024-01-18 19:14:48): [be[LDAP]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'lldapLdap.service.consul' as 'neutral'
   *  (2024-01-18 19:14:48): [be[LDAP]] [dp_attach_req] (0x0400): [RID#4] DP Request [Online Check #4]: REQ_TRACE: New request. Flags [0000].
   *  (2024-01-18 19:14:48): [be[LDAP]] [dp_attach_req] (0x0400): [RID#4] Number of active DP request: 1
   *  (2024-01-18 19:14:48): [be[LDAP]] [fo_resolve_service_send] (0x0100): [RID#4] Trying to resolve service 'LDAP'
   *  (2024-01-18 19:14:48): [be[LDAP]] [get_server_status] (0x1000): [RID#4] Status of server 'lldapLdap.service.consul' is 'name not resolved'
   *  (2024-01-18 19:14:48): [be[LDAP]] [get_port_status] (0x1000): [RID#4] Port status of port 389 for server 'lldapLdap.service.consul' is 'neutral'
   *  (2024-01-18 19:14:48): [be[LDAP]] [fo_resolve_service_activate_timeout] (0x2000): [RID#4] Resolve timeout [dns_resolver_timeout] set to 6 seconds
   *  (2024-01-18 19:14:48): [be[LDAP]] [get_server_status] (0x1000): [RID#4] Status of server 'lldapLdap.service.consul' is 'name not resolved'
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_is_address] (0x4000): [RID#4] [lldapLdap.service.consul] does not look like an IP address
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#4] Querying files
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#4] Trying to resolve A record of 'lldapLdap.service.consul' in files
   *  (2024-01-18 19:14:48): [be[LDAP]] [set_server_common_status] (0x0100): [RID#4] Marking server 'lldapLdap.service.consul' as 'resolving name'
   *  (2024-01-18 19:14:48): [be[LDAP]] [check_if_online_delayed] (0x2000): Check online req created.
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#4] Querying files
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#4] Trying to resolve AAAA record of 'lldapLdap.service.consul' in files
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_next] (0x0200): [RID#4] No more address families to retry
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#4] Querying DNS
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_dns_query] (0x0100): [RID#4] Trying to resolve A record of 'lldapLdap.service.consul' in DNS
   *  (2024-01-18 19:14:48): [be[LDAP]] [schedule_request_timeout] (0x2000): [RID#4] Scheduling a timeout of 3 seconds
   *  (2024-01-18 19:14:48): [be[LDAP]] [schedule_timeout_watcher] (0x2000): [RID#4] Scheduling DNS timeout watcher
   *  (2024-01-18 19:14:48): [be[LDAP]] [unschedule_timeout_watcher] (0x4000): [RID#4] Unscheduling DNS timeout watcher
   *  (2024-01-18 19:14:48): [be[LDAP]] [request_watch_destructor] (0x0400): [RID#4] Deleting request watch
   *  (2024-01-18 19:14:48): [be[LDAP]] [resolv_gethostbyname_done] (0x0040): [RID#4] querying hosts database failed [5]: Input/output error
********************** BACKTRACE DUMP ENDS HERE *********************************

@nitnelave
Copy link
Member

That seems to be a configuration error: it can't resolve the service name to even try to send a query to LLDAP. In the previous logs you had an A record for the service, now it doesn't seem to be there (?)

@vincentDcmps
Copy link
Author

get an error when I try to process to a login with my test user

   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#9] calling ldap_search_ext with [(&(uid=admin)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [objectClass]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [uid]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [userPassword]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [uidNumber]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [gecos]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [homeDirectory]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [loginShell]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [krbPrincipalName]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [cn]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowLastChange]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowMin]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowMax]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowWarning]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowInactive]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowExpire]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [shadowFlag]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [krbLastPwdChange]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [krbPasswordExpiration]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [pwdAttribute]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [authorizedService]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [accountExpires]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [userAccountControl]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [nsAccountLock]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [host]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [rhost]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [loginDisabled]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [loginExpirationTime]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [loginAllowedTimeMap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [sshPublicKey]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [userCertificate;binary]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [mail]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#9] ldap_search_ext called, msgid = 10
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_op_add] (0x2000): [RID#9] New operation 10 timeout 6
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfb2710], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_message] (0x4000): [RID#9] Message type: [LDAP_RES_SEARCH_ENTRY]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_entry] (0x1000): [RID#9] OriginalDN: [uid=admin,ou=people,dc=ducamps,dc=eu].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [objectClass]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [uid]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [uidNumber]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [gidNumber]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [homeDirectory]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [cn]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#9] No sub-attributes for [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfb2710], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfb2710], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_message] (0x4000): [RID#9] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#9] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#9] Total count [1]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#9] Operation 10 finished
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#9] Receiving info for the user
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#9] Storing the user
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x0400): [RID#9] Save user
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_get_sid_str] (0x1000): [RID#9] No [objectSID] attribute. [0][Success]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x4000): [RID#9] objectSID: not available for user
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x4000): [RID#9] Failed to retrieve UUID [2][No such file or directory].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_primary_name] (0x0400): [RID#9] Processing object admin
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x0400): [RID#9] Processing user admin@ldap
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x2000): [RID#9] Adding originalDN [uid=admin,ou=people,dc=ducamps,dc=eu] to attributes of [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x0400): [RID#9] Original memberOf is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] Adding original mod-Timestamp [2024-01-07T09:19:36.347806367+00:00] to attributes of [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x0400): [RID#9] User principal is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowLastChange is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowMin is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowMax is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowWarning is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowInactive is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowExpire is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] shadowFlag is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] krbLastPwdChange is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] krbPasswordExpiration is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] pwdAttribute is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] authorizedService is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] adAccountExpires is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] adUserAccountControl is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] nsAccountLock is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] authorizedHost is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] authorizedRHost is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] ndsLoginDisabled is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] ndsLoginExpirationTime is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] ndsLoginAllowedTimeMap is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] sshPublicKey is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] authType is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] userCertificate is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#9] mail is not available for [admin@ldap].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_save_user] (0x0400): [RID#9] Storing info for user admin@ldap
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_set_entry_attr] (0x0200): [RID#9] Entry [name=admin@ldap,cn=users,cn=LDAP,cn=sysdb] has set [ts_cache] attrs.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [userPassword] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [loginShell] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [userPrincipalName] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowLastChange] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowMin] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowMax] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowWarning] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowInactive] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowExpire] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [shadowFlag] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [krbLastPwdChange] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [krbPasswordExpiration] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [pwdAttribute] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [authorizedService] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [adAccountExpires] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [adUserAccountControl] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [nsAccountLock] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [authorizedHost] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [authorizedRHost] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [ndsLoginDisabled] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [ndsLoginExpirationTime] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [ndsLoginAllowedTimeMap] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [sshPublicKey] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [userCertificate] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#9] Removing attribute [mail] from [admin@ldap]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_store_user] (0x0400): [RID#9] User "admin@ldap" has been stored
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#9] Commit change
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#9] Process user's groups
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_initgr_rfc2307_next_base] (0x0400): [RID#9] Searching for groups with base [dc=ducamps,dc=eu]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#9] calling ldap_search_ext with [(&(memberuid=admin)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [objectClass]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [cn]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [userPassword]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#9] ldap_search_ext called, msgid = 11
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_op_add] (0x2000): [RID#9] New operation 11 timeout 6
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfe7030], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfe7030], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_message] (0x4000): [RID#9] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#9] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#9] Total count [0]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#9] Operation 11 finished
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_initgr_common_store] (0x2000): [RID#9] Updating memberships for admin@ldap
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_initgr_done] (0x4000): [RID#9] Initgroups done
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_search_group_by_id] (0x0400): [RID#9] No such entry
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#9] reusing cached connection
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_id_conn_data_not_idle] (0x4000): [RID#9] Marking connection as not idle
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_groups_next_base] (0x0400): [RID#9] Searching for groups with base [dc=ducamps,dc=eu]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#9] calling ldap_search_ext with [(&(gidNumber=1000000)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [objectClass]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [cn]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [userPassword]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [memberuid]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#9] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#9] ldap_search_ext called, msgid = 12
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_op_add] (0x2000): [RID#9] New operation 12 timeout 6
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfe7030], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfe7030], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_message] (0x4000): [RID#9] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#9] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#9] Total count [0]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#9] Operation 12 finished
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_groups_process] (0x0400): [RID#9] Search for groups, returned 0 results.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#9] releasing operation connection
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_get_initgr_pgid] (0x4000): [RID#9] No need to check for domain local group memberships.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_id_op_destroy] (0x4000): [RID#9] releasing operation connection
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#9] releasing operation connection
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_id_conn_data_idle] (0x4000): [RID#9] Marking connection as idle
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_done] (0x0400): [RID#9] DP Request [Initgroups #9]: Request handler finished [0]: Success
   *  (2024-01-20  9:03:55): [be[LDAP]] [_dp_req_recv] (0x0400): [RID#9] DP Request [Initgroups #9]: Receiving request data.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#9] DP Request [Initgroups #9]: Request removed.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#9] Number of active DP request: 0
   *  (2024-01-20  9:03:55): [be[LDAP]] [sysdb_set_entry_attr] (0x0200): [RID#9] Entry [name=admin@ldap,cn=users,cn=LDAP,cn=sysdb] has set [ts_cache] attrs.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_get_account_info_initgroups_resolv_done] (0x0400): [RID#9] Ordering NSS responder to update memory cache
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[(nil)], ldap[0x560b4df6c630]
   *  (2024-01-20  9:03:55): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_reply_std] (0x1000): [RID#9] DP Request [Initgroups #9]: Returning [Success]: 0,0,Success
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.pamHandler on /sssd
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_pam_handler_send] (0x0100): Got request with the following data
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): command: SSS_PAM_ACCT_MGMT
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): domain: LDAP
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): user: admin@ldap
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): service: su
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): tty: /dev/pts/1
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): ruser: root
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): rhost:
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): priv: 1
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): cli_pid: 2379
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): child_pid: 0
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): logon name: not set
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): flags: 0
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_attach_req] (0x0400): [RID#10] DP Request [PAM Account #10]: REQ_TRACE: New request. [sssd.pam CID #2] Flags [0000].
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_attach_req] (0x0400): [RID#10] Number of active DP request: 1
   *  (2024-01-20  9:03:55): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#10] Domain LDAP is Active
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_access_permit_handler_send] (0x4000): [RID#10] Access permit, returning PAM_SUCCESS.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_done] (0x0400): [RID#10] DP Request [PAM Account #10]: Request handler finished [0]: Success
   *  (2024-01-20  9:03:55): [be[LDAP]] [_dp_req_recv] (0x0400): [RID#10] DP Request [PAM Account #10]: Receiving request data.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#10] DP Request [PAM Account #10]: Request removed.
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#10] Number of active DP request: 0
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_method_enabled] (0x0400): [RID#10] Target selinux is not configured
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.pamHandler: Success
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.pamHandler on /sssd
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_pam_handler_send] (0x0100): Got request with the following data
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): command: SSS_PAM_OPEN_SESSION
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): domain: LDAP
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): user: admin@ldap
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): service: su
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): tty: /dev/pts/1
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): ruser: root
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): rhost:
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): authtok type: 0 (No authentication token available)
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): priv: 1
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): cli_pid: 2379
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): child_pid: 0
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): logon name: not set
   *  (2024-01-20  9:03:55): [be[LDAP]] [pam_print_data] (0x0100): flags: 0
   *  (2024-01-20  9:03:55): [be[LDAP]] [dp_method_enabled] (0x0400): Target session is not configured
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.pamHandler: Success
   *  (2024-01-20  9:03:55): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:28): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:28): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:28): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
   *  (2024-01-20  9:04:28): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_get_account_info_send] (0x0200): Got request for [0x1][BE_REQ_USER][name=pam_unix_non_existent:@ldap]
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_attach_req] (0x0400): [RID#11] DP Request [Account #11]: REQ_TRACE: New request. [sssd.nss CID #9] Flags [0x0001].
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_attach_req] (0x0400): [RID#11] Number of active DP request: 1
   *  (2024-01-20  9:04:28): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#11] Domain LDAP is Active
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#11] reusing cached connection
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_id_conn_data_not_idle] (0x4000): [RID#11] Marking connection as not idle
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_search_user_next_base] (0x0400): [RID#11] Searching for users with base [dc=ducamps,dc=eu]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#11] calling ldap_search_ext with [(&(uid=pam_unix_non_existent:)(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [objectClass]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [uid]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [userPassword]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [uidNumber]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [gecos]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [homeDirectory]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [loginShell]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [krbPrincipalName]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [cn]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowLastChange]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowMin]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowMax]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowWarning]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowInactive]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowExpire]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [shadowFlag]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [krbLastPwdChange]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [krbPasswordExpiration]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [pwdAttribute]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [authorizedService]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [accountExpires]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [userAccountControl]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [nsAccountLock]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [host]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [rhost]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [loginDisabled]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [loginExpirationTime]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [loginAllowedTimeMap]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [sshPublicKey]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [userCertificate;binary]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#11] Requesting attrs: [mail]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#11] ldap_search_ext called, msgid = 13
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_op_add] (0x2000): [RID#11] New operation 13 timeout 6
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfb9c40], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_process_message] (0x4000): [RID#11] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#11] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#11] Total count [0]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#11] Operation 13 finished
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_search_user_process] (0x0400): [RID#11] Search for users, returned 0 results.
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_search_user_process] (0x2000): [RID#11] Retrieved total 0 users
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#11] releasing operation connection
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_id_conn_data_idle] (0x4000): [RID#11] Marking connection as idle
   *  (2024-01-20  9:04:28): [be[LDAP]] [sysdb_search_by_name] (0x0400): [RID#11] No such entry
   *  (2024-01-20  9:04:28): [be[LDAP]] [sysdb_cache_search_groups] (0x2000): [RID#11] Search groups with filter: (&(objectCategory=group)(ghost=pam_unix_non_existent:@ldap))
   *  (2024-01-20  9:04:28): [be[LDAP]] [sysdb_cache_search_groups] (0x2000): [RID#11] No such entry
   *  (2024-01-20  9:04:28): [be[LDAP]] [sysdb_delete_user] (0x0400): [RID#11] Error: 2 (No such file or directory)
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_req_done] (0x0400): [RID#11] DP Request [Account #11]: Request handler finished [0]: Success
   *  (2024-01-20  9:04:28): [be[LDAP]] [_dp_req_recv] (0x0400): [RID#11] DP Request [Account #11]: Receiving request data.
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#11] DP Request [Account #11]: Request removed.
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#11] Number of active DP request: 0
   *  (2024-01-20  9:04:28): [be[LDAP]] [dp_req_reply_std] (0x1000): [RID#11] DP Request [Account #11]: Returning [Success]: 0,0,Success
   *  (2024-01-20  9:04:28): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[(nil)], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:28): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:04:28): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_get_account_info_send] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sss_domain_get_state] (0x1000): Domain LDAP is Active
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_attach_req] (0x0400): [RID#12] DP Request [Initgroups #12]: REQ_TRACE: New request. [sssd.pam CID #3] Flags [0x0001].
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_attach_req] (0x0400): [RID#12] Number of active DP request: 1
   *  (2024-01-20  9:04:32): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#12] Domain LDAP is Active
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#12] reusing cached connection
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_conn_data_not_idle] (0x4000): [RID#12] Marking connection as not idle
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_send] (0x4000): [RID#12] Retrieving info for initgroups call
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#12] reusing cached connection
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_conn_data_not_idle] (0x4000): [RID#12] Marking connection as not idle
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_next_base] (0x0400): [RID#12] Searching for users with base [dc=ducamps,dc=eu]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#12] calling ldap_search_ext with [(&(uid=toto)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [objectClass]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [uid]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [userPassword]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [uidNumber]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [gecos]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [homeDirectory]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [loginShell]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [krbPrincipalName]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [cn]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowLastChange]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowMin]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowMax]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowWarning]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowInactive]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowExpire]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [shadowFlag]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [krbLastPwdChange]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [krbPasswordExpiration]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [pwdAttribute]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [authorizedService]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [accountExpires]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [userAccountControl]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [nsAccountLock]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [host]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [rhost]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [loginDisabled]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [loginExpirationTime]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [loginAllowedTimeMap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [sshPublicKey]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [userCertificate;binary]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [mail]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#12] ldap_search_ext called, msgid = 14
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_add] (0x2000): [RID#12] New operation 14 timeout 6
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfe5eb0], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_message] (0x4000): [RID#12] Message type: [LDAP_RES_SEARCH_ENTRY]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_entry] (0x1000): [RID#12] OriginalDN: [uid=toto,ou=people,dc=ducamps,dc=eu].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [objectClass]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [uid]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [uidNumber]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [gidNumber]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [homeDirectory]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [loginShell]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [cn]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_parse_range] (0x2000): [RID#12] No sub-attributes for [mail]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfe5eb0], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_message] (0x4000): [RID#12] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#12] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#12] Total count [1]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#12] Operation 14 finished
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#12] Receiving info for the user
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#12] Storing the user
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x0400): [RID#12] Save user
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_get_sid_str] (0x1000): [RID#12] No [objectSID] attribute. [0][Success]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x4000): [RID#12] objectSID: not available for user
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x4000): [RID#12] Failed to retrieve UUID [2][No such file or directory].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_primary_name] (0x0400): [RID#12] Processing object toto
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x0400): [RID#12] Processing user toto@ldap
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x2000): [RID#12] Adding originalDN [uid=toto,ou=people,dc=ducamps,dc=eu] to attributes of [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x0400): [RID#12] Original memberOf is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] Adding original mod-Timestamp [2024-01-16T19:29:36.940401748+00:00] to attributes of [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x0400): [RID#12] User principal is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowLastChange is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowMin is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowMax is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowWarning is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowInactive is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowExpire is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] shadowFlag is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] krbLastPwdChange is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] krbPasswordExpiration is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] pwdAttribute is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] authorizedService is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] adAccountExpires is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] adUserAccountControl is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] nsAccountLock is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] authorizedHost is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] authorizedRHost is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] ndsLoginDisabled is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] ndsLoginExpirationTime is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] ndsLoginAllowedTimeMap is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] sshPublicKey is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] authType is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] userCertificate is not available for [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_attrs_add_ldap_attr] (0x2000): [RID#12] Adding mail [toto@toto.com] to attributes of [toto@ldap].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_save_user] (0x0400): [RID#12] Storing info for user toto@ldap
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_set_entry_attr] (0x0200): [RID#12] Entry [name=toto@ldap,cn=users,cn=LDAP,cn=sysdb] has set [ts_cache] attrs.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [userPassword] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [userPrincipalName] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowLastChange] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowMin] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowMax] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowWarning] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowInactive] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowExpire] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [shadowFlag] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [krbLastPwdChange] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [krbPasswordExpiration] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [pwdAttribute] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [authorizedService] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [adAccountExpires] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [adUserAccountControl] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [nsAccountLock] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [authorizedHost] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [authorizedRHost] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [ndsLoginDisabled] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [ndsLoginExpirationTime] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [ndsLoginAllowedTimeMap] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [sshPublicKey] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_remove_attrs] (0x2000): [RID#12] Removing attribute [userCertificate] from [toto@ldap]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_store_user] (0x0400): [RID#12] User "toto@ldap" has been stored
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#12] Commit change
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_user] (0x4000): [RID#12] Process user's groups
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_initgr_rfc2307_next_base] (0x0400): [RID#12] Searching for groups with base [dc=ducamps,dc=eu]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#12] calling ldap_search_ext with [(&(memberuid=toto)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [objectClass]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [cn]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [userPassword]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#12] ldap_search_ext called, msgid = 15
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_add] (0x2000): [RID#12] New operation 15 timeout 6
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfb19c0], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4dfb19c0], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_message] (0x4000): [RID#12] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#12] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#12] Total count [0]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#12] Operation 15 finished
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_initgr_common_store] (0x2000): [RID#12] Updating memberships for toto@ldap
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_done] (0x4000): [RID#12] Initgroups done
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_search_group_by_id] (0x0400): [RID#12] No such entry
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_op_connect_step] (0x4000): [RID#12] reusing cached connection
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_conn_data_not_idle] (0x4000): [RID#12] Marking connection as not idle
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_groups_next_base] (0x0400): [RID#12] Searching for groups with base [dc=ducamps,dc=eu]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x0400): [RID#12] calling ldap_search_ext with [(&(gidNumber=10003)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][dc=ducamps,dc=eu].
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [objectClass]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [cn]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [userPassword]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [gidNumber]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [memberuid]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x1000): [RID#12] Requesting attrs: [modifyTimestamp]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_ext_step] (0x2000): [RID#12] ldap_search_ext called, msgid = 16
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_add] (0x2000): [RID#12] New operation 16 timeout 6
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4df5dd00], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[0x560b4df5dd00], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_message] (0x4000): [RID#12] Message type: [LDAP_RES_SEARCH_RESULT]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_op_finished] (0x0400): [RID#12] Search result: Success(0), no errmsg set
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_generic_op_finished] (0x2000): [RID#12] Total count [0]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#12] Operation 16 finished
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_groups_process] (0x0400): [RID#12] Search for groups, returned 0 results.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#12] releasing operation connection
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_get_initgr_pgid] (0x4000): [RID#12] No need to check for domain local group memberships.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_op_destroy] (0x4000): [RID#12] releasing operation connection
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_op_done] (0x4000): [RID#12] releasing operation connection
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_conn_data_idle] (0x4000): [RID#12] Marking connection as idle
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_done] (0x0400): [RID#12] DP Request [Initgroups #12]: Request handler finished [0]: Success
   *  (2024-01-20  9:04:32): [be[LDAP]] [_dp_req_recv] (0x0400): [RID#12] DP Request [Initgroups #12]: Receiving request data.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#12] DP Request [Initgroups #12]: Request removed.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#12] Number of active DP request: 0
   *  (2024-01-20  9:04:32): [be[LDAP]] [sysdb_set_entry_attr] (0x0200): [RID#12] Entry [name=toto@ldap,cn=users,cn=LDAP,cn=sysdb] has set [ts_cache] attrs.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_get_account_info_initgroups_resolv_done] (0x0400): [RID#12] Ordering NSS responder to update memory cache
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4df9e1c0], connected[1], ops[(nil)], ldap[0x560b4df6c630]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_reply_std] (0x1000): [RID#12] DP Request [Initgroups #12]: Returning [Success]: 0,0,Success
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.pamHandler on /sssd
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_pam_handler_send] (0x0100): Got request with the following data
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): domain: LDAP
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): user: toto@ldap
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): service: su
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): tty: /dev/pts/1
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): ruser: admin
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): rhost:
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): authtok type: 1 (Password)
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): newauthtok type: 0 (No authentication token available)
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): priv: 0
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): cli_pid: 2395
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): child_pid: 0
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): logon name: not set
   *  (2024-01-20  9:04:32): [be[LDAP]] [pam_print_data] (0x0100): flags: 0
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_attach_req] (0x0400): [RID#13] DP Request [PAM Authenticate #13]: REQ_TRACE: New request. [sssd.pam CID #3] Flags [0000].
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_attach_req] (0x0400): [RID#13] Number of active DP request: 1
   *  (2024-01-20  9:04:32): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#13] Domain LDAP is Active
   *  (2024-01-20  9:04:32): [be[LDAP]] [find_password_expiration_attributes] (0x4000): [RID#13] No password policy requested.
   *  (2024-01-20  9:04:32): [be[LDAP]] [fo_resolve_service_send] (0x0100): [RID#13] Trying to resolve service 'LDAP'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'working'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_server_status] (0x0100): [RID#13] Hostname resolution expired, resetting the server status of 'lldapLdap.service.consul'
   *  (2024-01-20  9:04:32): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'name not resolved'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_port_status] (0x1000): [RID#13] Port status of port 389 for server 'lldapLdap.service.consul' is 'working'
   *  (2024-01-20  9:04:32): [be[LDAP]] [fo_resolve_service_activate_timeout] (0x2000): [RID#13] Resolve timeout [dns_resolver_timeout] set to 6 seconds
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'name not resolved'
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_is_address] (0x4000): [RID#13] [lldapLdap.service.consul] does not look like an IP address
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying files
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#13] Trying to resolve A record of 'lldapLdap.service.consul' in files
   *  (2024-01-20  9:04:32): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'resolving name'
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying files
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_files_send] (0x0100): [RID#13] Trying to resolve AAAA record of 'lldapLdap.service.consul' in files
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_next] (0x0200): [RID#13] No more address families to retry
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_step] (0x2000): [RID#13] Querying DNS
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_dns_query] (0x0100): [RID#13] Trying to resolve A record of 'lldapLdap.service.consul' in DNS
   *  (2024-01-20  9:04:32): [be[LDAP]] [schedule_request_timeout] (0x2000): [RID#13] Scheduling a timeout of 3 seconds
   *  (2024-01-20  9:04:32): [be[LDAP]] [schedule_timeout_watcher] (0x2000): [RID#13] Scheduling DNS timeout watcher
   *  (2024-01-20  9:04:32): [be[LDAP]] [unschedule_timeout_watcher] (0x4000): [RID#13] Unscheduling DNS timeout watcher
   *  (2024-01-20  9:04:32): [be[LDAP]] [resolv_gethostbyname_dns_parse] (0x1000): [RID#13] Parsing an A reply
   *  (2024-01-20  9:04:32): [be[LDAP]] [request_watch_destructor] (0x0400): [RID#13] Deleting request watch
   *  (2024-01-20  9:04:32): [be[LDAP]] [set_server_common_status] (0x0100): [RID#13] Marking server 'lldapLdap.service.consul' as 'name resolved'
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_resolve_server_process] (0x1000): [RID#13] Saving the first resolved server
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_resolve_server_process] (0x0200): [RID#13] Found address for server lldapLdap.service.consul: [192.168.121.39] TTL 0
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_uri_callback] (0x0400): [RID#13] Constructed uri 'ldap://lldapLdap.service.consul'
   *  (2024-01-20  9:04:32): [be[LDAP]] [sssd_async_socket_init_send] (0x4000): [RID#13] Using file descriptor [23] for the connection.
   *  (2024-01-20  9:04:32): [be[LDAP]] [sssd_async_socket_init_send] (0x0400): [RID#13] Setting 6 seconds timeout [ldap_network_timeout] for connecting
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_ldap_connect_callback_add] (0x4000): [RID#13] New connection to [ldap://lldapLdap.service.consul:389/??base] with fd [23]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_sys_connect_done] (0x0100): [RID#13] Executing START TLS
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_add] (0x2000): [RID#13] New operation 1 timeout 8
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_result] (0x2000): Trace: sh[0x560b4dff5f10], connected[1], ops[0x560b4df5dd00], ldap[0x560b4dfbc400]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_process_message] (0x4000): [RID#13] Message type: [LDAP_RES_EXTENDED]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_connect_done] (0x0080): [RID#13] START TLS result: Server is unwilling to perform(53), Unsupported extended operation: 1.3.6.1.4.1.1466.20037
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_connect_done] (0x0080): [RID#13] ldap_install_tls failed: [Connect error] [The TLS connection was non-properly terminated.]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_op_destructor] (0x2000): [RID#13] Operation 1 finished
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_handle_release] (0x2000): [RID#13] Trace: sh[0x560b4dff5f10], connected[1], ops[(nil)], ldap[0x560b4dfbc400], destructor_lock[0], release_memory[0]
   *  (2024-01-20  9:04:32): [be[LDAP]] [remove_connection_callback] (0x4000): [RID#13] Successfully removed connection callback.
   *  (2024-01-20  9:04:32): [be[LDAP]] [_be_fo_set_port_status] (0x8000): [RID#13] Setting status: PORT_NOT_WORKING. Called from: ../src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_done: 1644
   *  (2024-01-20  9:04:32): [be[LDAP]] [fo_set_port_status] (0x0100): [RID#13] Marking port 389 of server 'lldapLdap.service.consul' as 'not working'
   *  (2024-01-20  9:04:32): [be[LDAP]] [fo_set_port_status] (0x0400): [RID#13] Marking port 389 of duplicate server 'lldapLdap.service.consul' as 'not working'
   *  (2024-01-20  9:04:32): [be[LDAP]] [fo_resolve_service_send] (0x0100): [RID#13] Trying to resolve service 'LDAP'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'name resolved'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_port_status] (0x1000): [RID#13] Port status of port 389 for server 'lldapLdap.service.consul' is 'not working'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_port_status] (0x0080): [RID#13] SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues.
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_server_status] (0x1000): [RID#13] Status of server 'lldapLdap.service.consul' is 'name resolved'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_port_status] (0x1000): [RID#13] Port status of port 389 for server 'lldapLdap.service.consul' is 'not working'
   *  (2024-01-20  9:04:32): [be[LDAP]] [get_port_status] (0x0080): [RID#13] SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues.
   *  (2024-01-20  9:04:32): [be[LDAP]] [fo_resolve_service_send] (0x0020): [RID#13] No available servers for service 'LDAP'
********************** BACKTRACE DUMP ENDS HERE *********************************

(2024-01-20  9:04:36): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_resolve_server_done] (0x1000): [RID#13] Server [NULL] resolution failed: [5]: Input/output error
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_mark_offline] (0x2000): [RID#13] Going offline!
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_mark_offline] (0x2000): [RID#13] Initialize check_if_online_ptask.
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_ptask_create] (0x0400): [RID#13] Periodic task [Check if online (periodic)] was created
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_ptask_schedule] (0x0400): [RID#13] Task [Check if online (periodic)]: scheduling task 89 seconds from now [1705737961]
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_run_offline_cb] (0x0080): [RID#13] Going offline. Running callbacks.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_done] (0x0400): [RID#13] DP Request [PAM Authenticate #13]: Request handler finished [0]: Success
   *  (2024-01-20  9:04:32): [be[LDAP]] [_dp_req_recv] (0x0400): [RID#13] DP Request [PAM Authenticate #13]: Receiving request data.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#13] DP Request [PAM Authenticate #13]: Request removed.
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_req_destructor] (0x0400): [RID#13] Number of active DP request: 0
   *  (2024-01-20  9:04:32): [be[LDAP]] [dp_method_enabled] (0x0400): [RID#13] Target selinux is not configured
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.pamHandler: Success
   *  (2024-01-20  9:04:32): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_ptask_offline_cb] (0x0400): [RID#13] Back end is offline
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_ptask_disable] (0x0400): [RID#13] Task [SUDO Smart Refresh]: disabling task
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_ptask_offline_cb] (0x0400): [RID#13] Back end is offline
   *  (2024-01-20  9:04:32): [be[LDAP]] [be_ptask_disable] (0x0400): [RID#13] Task [SUDO Full Refresh]: disabling task
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_id_release_conn_data] (0x4000): [RID#13] Releasing unused connection with fd [19]
   *  (2024-01-20  9:04:32): [be[LDAP]] [sdap_handle_release] (0x2000): [RID#13] Trace: sh[0x560b4df9e1c0], connected[1], ops[(nil)], ldap[0x560b4df6c630], destructor_lock[0], release_memory[0]
   *  (2024-01-20  9:04:32): [be[LDAP]] [remove_connection_callback] (0x4000): [RID#13] Successfully removed connection callback.
   *  (2024-01-20  9:04:36): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:36): [be[LDAP]] [sbus_dispatch] (0x4000): Dispatching.
   *  (2024-01-20  9:04:36): [be[LDAP]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
   *  (2024-01-20  9:04:36): [be[LDAP]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.pam]
   *  (2024-01-20  9:04:36): [be[LDAP]] [dp_get_account_info_send] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=admin@ldap]
   *  (2024-01-20  9:04:36): [be[LDAP]] [sss_domain_get_state] (0x1000): Domain LDAP is Active
   *  (2024-01-20  9:04:36): [be[LDAP]] [dp_attach_req] (0x0400): [RID#14] DP Request [Initgroups #14]: REQ_TRACE: New request. [sssd.pam CID #2] Flags [0x0001].
   *  (2024-01-20  9:04:36): [be[LDAP]] [dp_attach_req] (0x0400): [RID#14] [CID #2] Backend is offline! Using cached data if available
   *  (2024-01-20  9:04:36): [be[LDAP]] [dp_attach_req] (0x0400): [RID#14] Number of active DP request: 1
   *  (2024-01-20  9:04:36): [be[LDAP]] [sss_domain_get_state] (0x1000): [RID#14] Domain LDAP is Active
   *  (2024-01-20  9:04:36): [be[LDAP]] [_dp_req_recv] (0x0400): DP Request [Initgroups #14]: Receiving request data.
   *  (2024-01-20  9:04:36): [be[LDAP]] [dp_req_destructor] (0x0400): DP Request [Initgroups #14]: Request removed.
   *  (2024-01-20  9:04:36): [be[LDAP]] [dp_req_destructor] (0x0400): Number of active DP request: 0
   *  (2024-01-20  9:04:36): [be[LDAP]] [sbus_issue_request_done] (0x0040): sssd.dataprovider.getAccountInfo: Error [1432158212]: SSSD is offline
********************** BACKTRACE DUMP ENDS HERE *********************************

@nitnelave
Copy link
Member

Okay, that's a lot of logging... A couple of notes:

  • From what I can tell, you tried logging in with the "admin" user, and it failed, then you tried logging in with the "toto" user and it failed again (that would be useful info to add to the logs, along with what was the error message when it failed, so we don't have to piece it back together from the logs).
  • Logging in as the admin failed because it's looking for a user named "pam_unix_non_existent:" (which of course doesn't exist)
  • Getting the groups doesn't return any result because they're expected to have a gidNumber attribute, which I guess you haven't added yet. Same for users, they're supposed to have the uidNumber
  • Logging in as "toto" fails because it tries to start a STARTTLS session. Can you disable that? Either use plain LDAP or switch to the more secure LDAPS (LDAP over SSL).

@nitnelave nitnelave added question Further information is requested integration Connection between LLDAP and a service and removed bug Something isn't working labels Jan 22, 2024
@nitnelave nitnelave changed the title [BUG] SSSD integration [INTEGRATION] SSSD integration Jan 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
integration Connection between LLDAP and a service question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Firstyear @nitnelave @vincentDcmps