Here is the krb5_child.log directly related to the third login attempt:
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [main] (0x0400): krb5_child
started.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [unpack_buffer] (0x1000): total
buffer size: [241]
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [unpack_buffer] (0x0100): cmd [241]
uid [3001] gid [3001] validate [false] enterprise principal [false] offline [true] UPN
[bernd(a)EBN.ELSTER.DE]
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [unpack_buffer] (0x0100): ccname:
[FILE:/tmp/krb5cc_3001_XXXXXX] old_ccname: [FILE:/tmp/krb5cc_3001_XXXXXX] keytab:
[/etc/krb5.keytab]
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [check_use_fast] (0x0100): Not
using FAST.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [old_ccache_valid] (0x0400): Saved
ccache FILE:/tmp/krb5cc_3001_XXXXXX doesn't exist, ignoring
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [k5c_check_old_ccache] (0x4000):
Ccache_file is [FILE:/tmp/krb5cc_3001_XXXXXX] and is not active and TGT is not valid.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [k5c_precreate_ccache] (0x4000):
Recreating ccache
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [privileged_krb5_setup] (0x0080):
Cannot open the PAC responder socket
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [main] (0x2000): Running as
[0][0].
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [become_user] (0x0200): Trying to
become user [3001][3001].
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [k5c_setup] (0x2000): Running as
[3001][3001].
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [set_lifetime_options] (0x0100): No
specific renewable lifetime requested.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [set_lifetime_options] (0x0100): No
specific lifetime requested.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [main] (0x0400): Will perform
offline auth
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [create_empty_ccache] (0x1000):
Creating empty ccache
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [create_empty_cred] (0x2000):
Created empty krb5_creds.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [create_ccache] (0x4000):
Initializing ccache of type [FILE]
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [create_ccache] (0x4000):
returning: 0
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [k5c_send_data] (0x0200): Received
error code 0
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [pack_response_packet] (0x2000):
response packet size: [52]
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [k5c_send_data] (0x4000): Response
sent.
(Wed Jun 7 11:19:02 2017) [[sssd[krb5_child[15210]]]] [main] (0x0400): krb5_child
completed successfully
and the sssd_REALM.log
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_dispatch] (0x4000): dbus conn:
0xa274c0
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_dispatch] (0x4000): Dispatching.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_message_handler] (0x2000): Received
SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_get_sender_id_send] (0x2000): Not a
sysbus message, quit
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_get_account_info_handler] (0x0200): Got
request for [0x3][BE_REQ_INITGROUPS][name=bernd@realm]
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sss_domain_get_state] (0x1000): Domain REALM
is Active
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa1d090
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0xa49f30
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0xa49f30 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa1d090
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0xa38650
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0xa38650 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa1d090
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x9f3100
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0x9f3100 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_attach_req] (0x0400): DP Request
[Initgroups #40]: New request. Flags [0x0001].
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_attach_req] (0x0400): Number of active DP
request: 1
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sss_domain_get_state] (0x1000): Domain REALM
is Active
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [_dp_req_recv] (0x0400): DP Request
[Initgroups #40]: Receiving request data.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_req_reply_gen_error] (0x0080): DP Request
[Initgroups #40]: Finished. Backend is currently offline.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_table_value_destructor] (0x0400):
Removing [0:1:0x0001:3::REALM:name=bernd@realm] from reply table
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_req_destructor] (0x0400): DP Request
[Initgroups #40]: Request removed.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_req_destructor] (0x0400): Number of
active DP request: 0
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_dispatch] (0x4000): dbus conn:
0xa274c0
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_dispatch] (0x4000): Dispatching.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_message_handler] (0x2000): Received
SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path
/org/freedesktop/sssd/dataprovider
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sbus_get_sender_id_send] (0x2000): Not a
sysbus message, quit
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_pam_handler] (0x0100): Got request with
the following data
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): command:
SSS_PAM_AUTHENTICATE
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): domain: REALM
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): user: bernd@realm
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): service: login
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): tty: /dev/tty1
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): ruser:
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): rhost:
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): authtok type: 4
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): newauthtok type:
0
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): priv: 1
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): cli_pid: 15088
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [pam_print_data] (0x0100): logon name: not
set
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_attach_req] (0x0400): DP Request [PAM
Authenticate #41]: New request. Flags [0000].
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_attach_req] (0x0400): Number of active DP
request: 1
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sss_domain_get_state] (0x1000): Domain REALM
is Active
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [krb5_auth_queue_send] (0x1000): Wait queue
of user [bernd@realm] is empty, running request [0xa4c460] immediately.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [krb5_setup] (0x4000): No mapping for:
bernd@realm
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa1d090
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0xa38650
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0xa38650 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa1d090
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa38650
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0xa39730
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa38650
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0xa39730 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa38650
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [krb5_get_simple_upn] (0x4000): Using simple
UPN [bernd@REALM].
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [check_ccache_re] (0x1000): Ccache directory
name [/tmp] does not contain illegal patterns.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [check_ccache_re] (0x1000): Ccache directory
name [FILE:/tmp/krb5cc_3001_XXXXXX] does not contain illegal patterns.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [fo_resolve_service_send] (0x0100): Trying to
resolve service 'KERBEROS'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [get_server_status] (0x1000): Status of
server 'ldap-krb-template' is 'working'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [get_port_status] (0x1000): Port status of
port 0 for server 'ldap-krb-template' is 'working'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [fo_resolve_service_activate_timeout]
(0x2000): Resolve timeout set to 6 seconds
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [get_server_status] (0x1000): Status of
server 'ldap-krb-template' is 'working'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [be_resolve_server_process] (0x1000): Saving
the first resolved server
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [be_resolve_server_process] (0x0200): Found
address for server ldap-krb-template: [192.168.56.120] TTL 7200
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [unique_filename_destructor] (0x2000):
Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_r2D42Q]
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [unlink_dbg] (0x2000): File already removed:
[/var/lib/sss/pubconf/.krb5info_dummy_r2D42Q]
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [child_handler_setup] (0x2000): Setting up
signal handler up for pid [15210]
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [child_handler_setup] (0x2000): Signal
handler set up for pid [15210]
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [write_pipe_handler] (0x0400): All data has
been sent!
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [child_sig_handler] (0x1000): Waiting for
child [15210].
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [child_sig_handler] (0x0100): child [15210]
finished successfully.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [read_pipe_handler] (0x0400): EOF received,
client finished
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [parse_krb5_child_response] (0x1000): child
response [0][3][40].
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [_be_fo_set_port_status] (0x8000): Setting
status: PORT_WORKING. Called from: ../src/providers/krb5/krb5_auth.c: krb5_auth_done:
1059
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [fo_set_port_status] (0x0100): Marking port 0
of server 'ldap-krb-template' as 'working'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [set_server_common_status] (0x0100): Marking
server 'ldap-krb-template' as 'working'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [fo_set_port_status] (0x0400): Marking port 0
of duplicate server 'ldap-krb-template' as 'working'
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [krb5_mod_ccname] (0x4000): Save ccname
[FILE:/tmp/krb5cc_3001_lCjeWT] for user [bernd@realm].
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): start ldb transaction
(nesting: 0)
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa38c50
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0xa4a770
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa38c50
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0xa4a770 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa38c50
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sysdb_ldb_msg_difference] (0x2000):
Replaced/extended attr [ccacheFile] of entry
[name=bernd@realm,cn=users,cn=REALM,cn=sysdb]
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): start ldb transaction
(nesting: 1)
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0xa39a40
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0xa4a1d0
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Running timer event 0xa39a40
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Destroying timer event
0xa4a1d0 "ltdb_timeout"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): Ending timer event 0xa39a40
"ltdb_callback"
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): commit ldb transaction
(nesting: 1)
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [sysdb_set_entry_attr] (0x0200): Entry
[name=bernd@realm,cn=users,cn=REALM,cn=sysdb] has set [cache, ts_cache] attrs.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [ldb] (0x4000): commit ldb transaction
(nesting: 0)
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [krb5_auth_cache_creds] (0x0080): Delayed
authentication is only available for password authentication (single factor).
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [check_wait_queue] (0x1000): Wait queue for
user [bernd@realm] is empty.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [krb5_auth_queue_done] (0x1000):
krb5_auth_queue request [0xa4c460] done.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_req_done] (0x0400): DP Request [PAM
Authenticate #41]: Request handler finished [0]: Erfolg
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [_dp_req_recv] (0x0400): DP Request [PAM
Authenticate #41]: Receiving request data.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_req_destructor] (0x0400): DP Request [PAM
Authenticate #41]: Request removed.
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_req_destructor] (0x0400): Number of
active DP request: 0
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_method_enabled] (0x0400): Target selinux
is not configured
(Wed Jun 7 11:19:02 2017) [sssd[be[REALM]]] [dp_pam_reply] (0x1000): DP Request [PAM
Authenticate #41]: Sending result [4][REALM]