[Freeipa-users] Password-based authentication with AD users does not work

[Ronald Wimmer]

Hi,

when I try to login to an IPA client with my AD user it works perfectly
when I already have a kerberos ticket for my user. When I do not and I
try a password-based login it fails:

Password-based:
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_check_user_search] (0x0400):
Returning info for user [***@[e-mail]]
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pd_set_primary_name] (0x0400):
User's primary name is ***@xyz.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_dp_send_req] (0x0100):
Sending request with the following data:
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100):
command: SSS_PAM_PREAUTH
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100):
domain: XYZ
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): user:
***@xyz.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100):
service: sshd
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): ruser:
not set
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): rhost:
chupacabra.ipa.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100):
authtok type: 0
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100):
newauthtok type: 0
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100):
cli_pid: 31816
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): logon
name: myuser
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [sbus_add_timeout] (0x2000):
0x7f4c122ed450
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_dom_forwarder] (0x0100):
pam_dp_send_req returned 0
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [sbus_remove_timeout] (0x2000):
0x7f4c122ed450
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [sbus_dispatch] (0x4000): dbus
conn: 0x7f4c122e59c0
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [sbus_dispatch] (0x4000):
Dispatching.
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_dp_process_reply] (0x0200):
received: [4 (System error)][XYZ]
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_reply] (0x0200): pam_reply
called with result [4]: System error.
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_reply] (0x0200): blen: 20
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [reset_idle_timer] (0x4000): Idle
timer re-set for client [0x7f4c122f4640][21]

When I have a Kerberos ticket:
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_check_user_search] (0x0400):
Returning info for user [***@[e-mail]]
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pd_set_primary_name] (0x0400):
User's primary name is ***@xyz.mydomain.at
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_dp_send_req] (0x0100):
Sending request with the following data:
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100):
command: SSS_PAM_OPEN_SESSION
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100):
domain: XYZ
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): user:
***@xyz.mydomain.at
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100):
service: sshd
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): ruser:
not set
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): rhost:
chupacabra.ipa.mydomain.at
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100):
authtok type: 0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100):
newauthtok type: 0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100):
cli_pid: 31841
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): logon
name: myuser
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [sbus_add_timeout] (0x2000):
0x7f4c122ec4a0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_dom_forwarder] (0x0100):
pam_dp_send_req returned 0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [sbus_remove_timeout] (0x2000):
0x7f4c122ec4a0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [sbus_dispatch] (0x4000): dbus
conn: 0x7f4c122e59c0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [sbus_dispatch] (0x4000):
Dispatching.
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_dp_process_reply] (0x0200):
received: [0 (Success)][XYZ]
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_reply] (0x0200): pam_reply
called with result [0]: Success.
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_reply] (0x0200): blen: 20
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [reset_idle_timer] (0x4000): Idle
timer re-set for client [0x7f4c122f4640][21]

My question is why?

Regards,
Ronald

[Sumit Bose]

Hi,
when I try to login to an IPA client with my AD user it works perfectly when
I already have a kerberos ticket for my user. When I do not and I try a

Please send the sssd_domain.log and krb5_child.log form the same time as
well.

bye,
Sumit

(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending
SSS_PAM_PREAUTH
XYZ
sshd
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): ruser: not
set
chupacabra.ipa.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): authtok
type: 0
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): newauthtok
type: 0
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
31816
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_print_data] (0x0100): logon
name: myuser
0x7f4c122ed450
pam_dp_send_req returned 0
0x7f4c122ed450
0x7f4c122e59c0
Dispatching.
received: [4 (System error)][XYZ]
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_reply] (0x0200): pam_reply
called with result [4]: System error.
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [pam_reply] (0x0200): blen: 20
(Thu Apr 6 10:39:12 2017) [sssd[pam]] [reset_idle_timer] (0x4000): Idle
timer re-set for client [0x7f4c122f4640][21]
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending
SSS_PAM_OPEN_SESSION
XYZ
sshd
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): ruser: not
set
chupacabra.ipa.mydomain.at
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): authtok
type: 0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): newauthtok
type: 0
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
31841
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_print_data] (0x0100): logon
name: myuser
0x7f4c122ec4a0
pam_dp_send_req returned 0
0x7f4c122ec4a0
0x7f4c122e59c0
Dispatching.
received: [0 (Success)][XYZ]
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_reply] (0x0200): pam_reply
called with result [0]: Success.
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [pam_reply] (0x0200): blen: 20
(Thu Apr 6 10:41:00 2017) [sssd[pam]] [reset_idle_timer] (0x4000): Idle
timer re-set for client [0x7f4c122f4640][21]
My question is why?
Regards,
Ronald
--
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

[Ronald Wimmer]

Post by Sumit Bose

Hi,
when I try to login to an IPA client with my AD user it works perfectly when
I already have a kerberos ticket for my user. When I do not and I try a

Please send the sssd_domain.log and krb5_child.log form the same time as
well.

AD trust:
mydomain.at (forest root)
xyz (subdomain -> where myuser resides)

BCC (appearing in krb5_child.log) is not a domain here. It is my
company's name and might derive from some information in the AD.

sssd_domain.log snippet:
[....]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [sbus_dispatch]
(0x4000): dbus conn: 0x7f14f467feb0
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [sbus_dispatch]
(0x4000): Dispatching.
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[sbus_message_handler] (0x2000): Received SBUS method
org.freedesktop.sssd.dataprovider.pamHandler on path
/org/freedesktop/sssd/dataprovider
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [dp_pam_handler]
(0x0100): Got request with the following data
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): command: SSS_PAM_AUTHENTICATE
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): domain: XYZ
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): user: ***@xyz.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): service: sshd
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): tty: ssh
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): ruser:
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): rhost: chupacabra.ipa.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): authtok type: 1
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): newauthtok type: 0
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): priv: 1
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): cli_pid: 31812
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [pam_print_data]
(0x0100): logon name: not set
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [dp_attach_req]
(0x0400): DP Request [PAM Authenticate #15]: New request. Flags [0000].
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [dp_attach_req]
(0x0400): Number of active DP request: 1
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[krb5_auth_queue_send] (0x1000): Wait queue of user
[***@xyz.mydomain.at] is empty, running request [0x7f14f4670f70]
immediately.
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [krb5_setup]
(0x4000): No mapping for: ***@xyz.mydomain.at
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x7f14f468c030

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x7f14f468c0f0

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Running timer event 0x7f14f468c030 "ltdb_callback"

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Destroying timer event 0x7f14f468c0f0 "ltdb_timeout"

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Ending timer event 0x7f14f468c030 "ltdb_callback"

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x7f14f46aad10

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x7f14f468c4a0

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Running timer event 0x7f14f46aad10 "ltdb_callback"

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Destroying timer event 0x7f14f468c4a0 "ltdb_timeout"

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Ending timer event 0x7f14f46aad10 "ltdb_callback"

(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[get_server_status] (0x1000): Status of server 'ipa1.ipa.mydomain.at' is
'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [get_port_status]
(0x1000): Port status of port 0 for server 'ipa1.ipa.mydomain.at' is
'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6
seconds
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[get_server_status] (0x1000): Status of server 'ipa1.ipa.mydomain.at' is
'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[be_resolve_server_process] (0x1000): Saving the first resolved server
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[be_resolve_server_process] (0x0200): Found address for server
ipa1.ipa.mydomain.at: [10.66.39.130] TTL 86400
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[ipa_resolve_callback] (0x0400): Constructed uri
'ldap://ipa1.ipa.mydomain.at'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[unique_filename_destructor] (0x2000): Unlinking
[/var/lib/sss/pubconf/.krb5info_dummy_hs3EBJ]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [unlink_dbg]
(0x2000): File already removed:
[/var/lib/sss/pubconf/.krb5info_dummy_hs3EBJ]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_handler_setup] (0x2000): Setting up signal handler up for pid [31814]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_handler_setup] (0x2000): Signal handler set up for pid [31814]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[write_pipe_handler] (0x0400): All data has been sent!
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_sig_handler] (0x1000): Waiting for child [31814].
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_sig_handler] (0x0100): child [31814] finished successfully.
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[read_pipe_handler] (0x0400): EOF received, client finished
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[_be_fo_set_port_status] (0x8000): Setting status: PORT_NOT_WORKING.
Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 939
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_set_port_status] (0x0100): Marking port 0 of server
'ipa1.ipa.mydomain.at' as 'not working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_set_port_status] (0x0400): Marking port 0 of duplicate server
'ipa1.ipa.mydomain.at' as 'not working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[get_server_status] (0x1000): Status of server 'ipa1.ipa.mydomain.at' is
'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [get_port_status]
(0x1000): Port status of port 0 for server 'ipa1.ipa.mydomain.at' is
'not working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[get_server_status] (0x1000): Status of server 'ipa1.ipa.mydomain.at' is
'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [get_port_status]
(0x1000): Port status of port 0 for server 'ipa1.ipa.mydomain.at' is
'not working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_resolve_service_send] (0x0020): No available servers for service 'IPA'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[be_resolve_server_done] (0x1000): Server resolution failed: [5]:
Input/output error
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[be_mark_dom_offline] (0x1000): Marking subdomain xyz.mydomain.at offline
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[be_mark_subdom_offline] (0x1000): Marking subdomain xyz.mydomain.at as
inactive
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_handler_setup] (0x2000): Setting up signal handler up for pid [31815]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_handler_setup] (0x2000): Signal handler set up for pid [31815]
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[write_pipe_handler] (0x0400): All data has been sent!
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_sig_handler] (0x1000): Waiting for child [31815].
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[child_sig_handler] (0x0100): child [31815] finished successfully.
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[read_pipe_handler] (0x0400): EOF received, client finished
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[parse_krb5_child_response] (0x1000): child response [0][3][41].
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called
from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 1036
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_set_port_status] (0x0100): Marking port 0 of server
'ipa1.ipa.mydomain.at' as 'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[set_server_common_status] (0x0100): Marking server
'ipa1.ipa.mydomain.at' as 'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]]
[fo_set_port_status] (0x0400): Marking port 0 of duplicate server
'ipa1.ipa.mydomain.at' as 'working'
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [krb5_mod_ccname]
(0x4000): Save ccname [KEYRING:persistent:1073895519] for user
[***@xyz.mydomain.at].
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
start ldb transaction (nesting: 0)
(Thu Apr 6 10:39:12 2017) [sssd[be[ipa.mydomain.at]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x7f14f46b1d80
[...]

krb5_child.log snippet:
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [main] (0x0400):
krb5_child started.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [unpack_buffer]
(0x1000): total buffer size: [156]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [unpack_buffer]
(0x0100): cmd [241] uid [1073895519] gid [1073895519] validate [true]
enterprise principal [false] offline [false] UPN [***@BCC.MYDOMAIN.AT]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [unpack_buffer]
(0x0100): ccname: [KEYRING:persistent:1073895519] old_ccname:
[KEYRING:persistent:1073895519] keytab: [/etc/krb5.keytab]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [switch_creds]
(0x0200): Switch user to [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [switch_creds]
(0x0200): Switch user to [0][0].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[k5c_check_old_ccache] (0x4000): Ccache_file is
[KEYRING:persistent:1073895519] and is not active and TGT is valid.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[k5c_precreate_ccache] (0x4000): Recreating ccache
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [k5c_setup_fast]
(0x0100): SSSD_KRB5_FAST_PRINCIPAL is set to
[host/***@LINUX.MYDOMAIN.AT]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[find_principal_in_keytab] (0x4000): Trying to find principal
host/***@LINUX.MYDOMAIN.AT in keytab.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [match_principal]
(0x1000): Principal matched to the sample
(host/***@LINUX.MYDOMAIN.AT).
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[check_fast_ccache] (0x0200): FAST TGT is still valid.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [become_user]
(0x0200): Trying to become user [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [main] (0x2000):
Running as [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [k5c_setup]
(0x2000): Running as [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[set_lifetime_options] (0x0100): Cannot read
[SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from
environment.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [main] (0x0400):
Will perform online auth
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [tgt_req_child]
(0x1000): Attempting to get a TGT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[get_and_save_tgt] (0x0400): Attempting kinit for realm [BCC.MYDOMAIN.AT]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.830664: Getting
initial credentials for ***@BCC.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.830855: FAST
armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_LINUX.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.830976:
Retrieving host/***@LINUX.MYDOMAIN.AT ->
krb5_ccache_conf_data/fast_avail/krbtgt\/BCC.MYDOMAIN.AT\@***@X-CACHECONF:
from MEMORY:/var/lib/sss/db/fast_ccache_LINUX.MYDOMAIN.AT with result:
-1765328243/Matching credential not found
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.831121: Sending
request (167 bytes) to BCC.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.834221: Retrying
AS request with master KDC
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.834290: Getting
initial credentials for ***@BCC.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.834368: FAST
armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_LINUX.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.834434:
Retrieving host/***@LINUX.MYDOMAIN.AT ->
krb5_ccache_conf_data/fast_avail/krbtgt\/BCC.MYDOMAIN.AT\@***@X-CACHECONF:
from MEMORY:/var/lib/sss/db/fast_ccache_LINUX.MYDOMAIN.AT with result:
-1765328243/Matching credential not found
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[sss_child_krb5_trace_cb] (0x4000): [31814] 1491467952.834506: Sending
request (167 bytes) to BCC.MYDOMAIN.AT (master)
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[get_and_save_tgt] (0x0020): 1296: [-1765328230][Cannot find KDC for
realm "BCC.MYDOMAIN.AT"]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [map_krb5_error]
(0x0020): 1365: [-1765328230][Cannot find KDC for realm "BCC.MYDOMAIN.AT"]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [k5c_send_data]
(0x0200): Received error code 1432158228
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]]
[pack_response_packet] (0x2000): response packet size: [4]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [k5c_send_data]
(0x4000): Response sent.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31814]]]] [main] (0x0400):
krb5_child completed successfully
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [main] (0x0400):
krb5_child started.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [unpack_buffer]
(0x1000): total buffer size: [156]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [unpack_buffer]
(0x0100): cmd [241] uid [1073895519] gid [1073895519] validate [true]
enterprise principal [false] offline [true] UPN [***@BCC.MYDOMAIN.AT]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [unpack_buffer]
(0x0100): ccname: [KEYRING:persistent:1073895519] old_ccname:
[KEYRING:persistent:1073895519] keytab: [/etc/krb5.keytab]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [switch_creds]
(0x0200): Switch user to [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]]
[sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [switch_creds]
(0x0200): Switch user to [0][0].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]]
[k5c_check_old_ccache] (0x4000): Ccache_file is
[KEYRING:persistent:1073895519] and is not active and TGT is valid.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [become_user]
(0x0200): Trying to become user [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [main] (0x2000):
Running as [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [become_user]
(0x0200): Trying to become user [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [become_user]
(0x0200): Already user [1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [k5c_setup]
(0x2000): Running as [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]]
[set_lifetime_options] (0x0100): Cannot read
[SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]]
[set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from
environment.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [main] (0x0400):
Will perform offline auth
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]]
[create_empty_ccache] (0x1000): Existing ccache still valid, reusing
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [k5c_send_data]
(0x0200): Received error code 0
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]]
[pack_response_packet] (0x2000): response packet size: [53]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [k5c_send_data]
(0x4000): Response sent.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31815]]]] [main] (0x0400):
krb5_child completed successfully
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [main] (0x0400):
krb5_child started.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [unpack_buffer]
(0x1000): total buffer size: [51]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [unpack_buffer]
(0x0100): cmd [249] uid [1073895519] gid [1073895519] validate [true]
enterprise principal [false] offline [true] UPN [***@BCC.MYDOMAIN.AT]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [become_user]
(0x0200): Trying to become user [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [main] (0x2000):
Running as [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [become_user]
(0x0200): Trying to become user [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [become_user]
(0x0200): Already user [1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [k5c_setup]
(0x2000): Running as [1073895519][1073895519].
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[set_lifetime_options] (0x0100): Cannot read
[SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from
environment.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [main] (0x0400):
Will perform pre-auth
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [tgt_req_child]
(0x1000): Attempting to get a TGT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[get_and_save_tgt] (0x0400): Attempting kinit for realm [BCC.MYDOMAIN.AT]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[sss_child_krb5_trace_cb] (0x4000): [31817] 1491467952.889026: Getting
initial credentials for ***@BCC.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[sss_child_krb5_trace_cb] (0x4000): [31817] 1491467952.889307: Sending
request (167 bytes) to BCC.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[sss_child_krb5_trace_cb] (0x4000): [31817] 1491467952.892050: Retrying
AS request with master KDC
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[sss_child_krb5_trace_cb] (0x4000): [31817] 1491467952.892107: Getting
initial credentials for ***@BCC.MYDOMAIN.AT
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[sss_child_krb5_trace_cb] (0x4000): [31817] 1491467952.892252: Sending
request (167 bytes) to BCC.MYDOMAIN.AT (master)
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned
[-1765328230} during pre-auth.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [k5c_send_data]
(0x0200): Received error code 0
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]]
[pack_response_packet] (0x2000): response packet size: [4]
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [k5c_send_data]
(0x4000): Response sent.
(Thu Apr 6 10:39:12 2017) [[sssd[krb5_child[31817]]]] [main] (0x0400):
krb5_child completed successfully

Regards,
Ronald

[Ronald Wimmer]

Post by Ronald Wimmer
[...]
BCC (appearing in krb5_child.log) is not a domain here. It is my
company's name and might derive from some information in the AD.

After doing an LDAP search on the domain controller of my AD domain
(xyz.mydomain.at) I found out that my userPrincipalName is
***@bcc.mydomain.at - this can definitely not be changed!

[Sumit Bose]

Post by Ronald Wimmer

Post by Sumit Bose

Hi,
when I try to login to an IPA client with my AD user it works perfectly when
I already have a kerberos ticket for my user. When I do not and I try a

Please send the sssd_domain.log and krb5_child.log form the same time as
well.

mydomain.at (forest root)
xyz (subdomain -> where myuser resides)
BCC (appearing in krb5_child.log) is not a domain here. It is my company's
name and might derive from some information in the AD.

Yes, it is about the userPrincipalName attribute read from AD. Which IPA
server version do you use? Since RHEL-7.3 IPA supports those principals
coming from AD. For older versions you should add a workaround which is
e.g. described at the end of
https://www.redhat.com/archives/freeipa-users/2016-November/msg00069.html

HTH

bye,
Sumit

[Ronald Wimmer]

Post by Sumit Bose
[...]

Post by Ronald Wimmer
mydomain.at (forest root)
xyz (subdomain -> where myuser resides)
BCC (appearing in krb5_child.log) is not a domain here. It is my company's
name and might derive from some information in the AD.

Yes, it is about the userPrincipalName attribute read from AD. Which IPA
server version do you use? Since RHEL-7.3 IPA supports those principals
coming from AD. For older versions you should add a workaround which is
e.g. described at the end of
https://www.redhat.com/archives/freeipa-users/2016-November/msg00069.html
HTH
bye,
Sumit

I am using an up-to-date RHEL 7.3 IPA master. Is there no possibility to
override it?

[Sumit Bose]

Post by Ronald Wimmer

Post by Sumit Bose
[...]

Post by Ronald Wimmer
mydomain.at (forest root)
xyz (subdomain -> where myuser resides)
BCC (appearing in krb5_child.log) is not a domain here. It is my company's
name and might derive from some information in the AD.

Yes, it is about the userPrincipalName attribute read from AD. Which IPA
server version do you use? Since RHEL-7.3 IPA supports those principals
coming from AD. For older versions you should add a workaround which is
e.g. described at the end of
https://www.redhat.com/archives/freeipa-users/2016-November/msg00069.html
HTH
bye,
Sumit

I am using an up-to-date RHEL 7.3 IPA master. Is there no possibility to
override it?

Please check on the server with

ipa trust-find

if the BCC domain is listed as 'UPN suffixes:'. If not please try

ipa trust-fetch-domains

and check again. If the domain is listed then a 7.3 IPA client should be
able to detect it automatically on older clients you should set
'krb5_use_enterprise_principal = True' manually in sssd.conf.

HTH

bye,
Sumit

Post by Ronald Wimmer
--
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

[Ronald Wimmer]

Post by Sumit Bose

Post by Ronald Wimmer

Post by Sumit Bose
[...]

Post by Ronald Wimmer
mydomain.at (forest root)
xyz (subdomain -> where myuser resides)
BCC (appearing in krb5_child.log) is not a domain here. It is

my company's

Post by Sumit Bose

Post by Ronald Wimmer
name and might derive from some information in the AD.

Yes, it is about the userPrincipalName attribute read from AD. Which IPA
server version do you use? Since RHEL-7.3 IPA supports those principals
coming from AD. For older versions you should add a workaround which is
e.g. described at the end of
https://www.redhat.com/archives/freeipa-users/2016-November/msg00069.html
HTH
bye,
Sumit

I am using an up-to-date RHEL 7.3 IPA master. Is there no possibility to
override it?

Please check on the server with
ipa trust-find
if the BCC domain is listed as 'UPN suffixes:'. If not please try
ipa trust-fetch-domains
and check again. If the domain is listed then a 7.3 IPA client should be
able to detect it automatically on older clients you should set
'krb5_use_enterprise_principal = True' manually in sssd.conf.

Unfortunately, ipa trust-find shows some UPN suffixes but BCC is not
in the list.

Any other options left?

[Ronald Wimmer]

Post by Sumit Bose

Post by Ronald Wimmer

Post by Sumit Bose
[...]

Post by Ronald Wimmer
mydomain.at (forest root)
xyz (subdomain -> where myuser resides)
BCC (appearing in krb5_child.log) is not a domain here. It is my company's
name and might derive from some information in the AD.

Yes, it is about the userPrincipalName attribute read from AD. Which IPA
server version do you use? Since RHEL-7.3 IPA supports those principals
coming from AD. For older versions you should add a workaround which is
e.g. described at the end of
https://www.redhat.com/archives/freeipa-users/2016-November/msg00069.html
HTH
bye,
Sumit

I am using an up-to-date RHEL 7.3 IPA master. Is there no possibility to
override it?

Please check on the server with
ipa trust-find
if the BCC domain is listed as 'UPN suffixes:'. If not please try
ipa trust-fetch-domains
and check again. If the domain is listed then a 7.3 IPA client should be
able to detect it automatically on older clients you should set
'krb5_use_enterprise_principal = True' manually in sssd.conf.

I just checked with our AD guys. ipa trust-find only shows five UPN
suffixes. There are many more which are not shown inlcuding bcc.mydomain.at

Any idea why only a subset is shown?

[Sumit Bose]

Post by Ronald Wimmer

Post by Sumit Bose

Post by Ronald Wimmer

Post by Sumit Bose
[...]

Post by Ronald Wimmer
mydomain.at (forest root)
xyz (subdomain -> where myuser resides)
BCC (appearing in krb5_child.log) is not a domain here. It is my company's
name and might derive from some information in the AD.

Yes, it is about the userPrincipalName attribute read from AD. Which IPA
server version do you use? Since RHEL-7.3 IPA supports those principals
coming from AD. For older versions you should add a workaround which is
e.g. described at the end of
https://www.redhat.com/archives/freeipa-users/2016-November/msg00069.html
HTH
bye,
Sumit

I am using an up-to-date RHEL 7.3 IPA master. Is there no possibility to
override it?

Please check on the server with
ipa trust-find
if the BCC domain is listed as 'UPN suffixes:'. If not please try
ipa trust-fetch-domains
and check again. If the domain is listed then a 7.3 IPA client should be
able to detect it automatically on older clients you should set
'krb5_use_enterprise_principal = True' manually in sssd.conf.

I just checked with our AD guys. ipa trust-find only shows five UPN
suffixes. There are many more which are not shown inlcuding bcc.mydomain.at
Any idea why only a subset is shown?

I'm not aware of any limitation here. Have you tried to run 'ipa
trust-fetch-domains ad.forest.root' to update the list?

If this does not help please add 'log level = 100' to
/usr/share/ipa/smb.conf.empty so that it looks like:

[global]
log level = 100

and run trust-fetch-domains again. The debug output can then be found
in /var/log/httpd/error_log. The logs might contain data which should
not be shared publicly, so feel free to send them to me directly.

bye,
Sumit

Post by Ronald Wimmer
--
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

[Ronald Wimmer]

Post by Sumit Bose
[...]
I'm not aware of any limitation here. Have you tried to run 'ipa
trust-fetch-domains ad.forest.root' to update the list?
If this does not help please add 'log level = 100' to
[global]
log level = 100
and run trust-fetch-domains again. The debug output can then be found
in /var/log/httpd/error_log. [...]

Not one error in the error_log - absolutely nothing. Our AD guys
confirmed that there are many more UPN suffixes than the five I can see
when I run ipa trust-find.

Can somebody confirm that this UPN suffix mismatch is exactly the
problem preventing password-based login in my case?

[Sumit Bose]

Post by Sumit Bose
[...]
I'm not aware of any limitation here. Have you tried to run 'ipa
trust-fetch-domains ad.forest.root' to update the list?
If this does not help please add 'log level = 100' to
[global]
log level = 100
and run trust-fetch-domains again. The debug output can then be found
in /var/log/httpd/error_log. [...]

Not one error in the error_log - absolutely nothing. Our AD guys confirmed
that there are many more UPN suffixes than the five I can see when I run ipa
trust-find.
Can somebody confirm that this UPN suffix mismatch is exactly the problem
preventing password-based login in my case?

To close the thread, it turned out that the original issue with
authenticating with enterprise principals is a bug which is now tracked
by https://bugzilla.redhat.com/show_bug.cgi?id=1441077.

bye,
Sumit

--
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project