Discussion:
Troubleshooting SSO
(too old to reply)
Gould, Joshua
2015-03-30 13:08:54 UTC
Permalink
SSO works intermittently. I’m having trouble tracing the issue. Here is what I see from /var/log/secure. Where should I look for more detail to figure out why the SSO login is failing?

Mar 30 08:47:39 mid-ipa-vp01 sshd[9317]: Starting session: shell on pts/0 for root from 10.34.149.105 port 49725
Mar 30 08:47:39 mid-ipa-vp01 sshd[9322]: debug1: Setting controlling tty using TIOCSCTTY.
Mar 30 08:47:39 mid-ipa-vp01 sshd[9322]: debug1: PAM: reinitializing credentials
Mar 30 08:47:39 mid-ipa-vp01 sshd[9322]: debug1: permanently_set_uid: 0/0
Mar 30 08:49:05 mid-ipa-vp01 sshd[9317]: debug1: server_input_global_request: rtype ***@openssh.com want_reply 1
Mar 30 08:50:05 mid-ipa-vp01 sshd[9317]: debug1: server_input_global_request: rtype ***@openssh.com want_reply 1
Mar 30 08:51:57 mid-ipa-vp01 sshd[9317]: debug1: server_input_global_request: rtype ***@openssh.com want_reply 1
Mar 30 08:52:57 mid-ipa-vp01 sshd[9317]: debug1: server_input_global_request: rtype ***@openssh.com want_reply 1
Mar 30 08:53:51 mid-ipa-vp01 sshd[1388]: debug1: Forked child 12621.
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: Set /proc/self/oom_score_adj to 0
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: inetd sockets after dupping: 3, 3
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: Connection from 10.80.5.239 port 52982 on 10.127.26.73 port 22
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: Client protocol version 2.0; client software version PuTTY_Release_0.64
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: no match: PuTTY_Release_0.64
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: Enabling compatibility mode for protocol 2.0
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: Local version string SSH-2.0-OpenSSH_6.6.1
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SELinux support enabled [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: permanently_set_uid: 74/74 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: list_hostkey_types: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEXINIT received [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: client->server aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: server->client aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: KEX done [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: userauth-request for user adm-***@test.osuwmc service ssh-connection method none [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: attempt 0 failures 0 [preauth]
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: PAM: initializing for "adm-***@test.osuwmc"
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: PAM: setting PAM_RHOST to "svr-addc-vt01.test.osuwmc"
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: PAM: setting PAM_TTY to "ssh"
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: userauth-request for user adm-***@test.osuwmc service ssh-connection method gssapi-with-mic [preauth]
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: attempt 1 failures 0 [preauth]
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: Postponed gssapi-with-mic for adm-***@test.osuwmc from 10.80.5.239 port 52982 ssh2 [preauth]
Mar 30 08:53:58 mid-ipa-vp01 sshd[12621]: debug1: userauth-request for user adm-***@test.osuwmc service ssh-connection method password [preauth]
Mar 30 08:53:58 mid-ipa-vp01 sshd[12621]: debug1: attempt 2 failures 0 [preauth]
Mar 30 08:53:58 mid-ipa-vp01 sshd[12621]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=svr-addc-vt01.test.osuwmc user=adm-***@test.osuwmc
Mar 30 08:54:00 mid-ipa-vp01 sshd[12621]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=svr-addc-vt01.test.osuwmc user=adm-***@test.osuwmc
Mar 30 08:54:00 mid-ipa-vp01 sshd[12621]: debug1: PAM: password authentication accepted for adm-***@test.osuwmc
Mar 30 08:54:00 mid-ipa-vp01 sshd[12621]: debug1: do_pam_account: called
Sumit Bose
2015-03-30 13:35:16 UTC
Permalink
SSO works intermittently. I’m having trouble tracing the issue. Here is what I see from /var/log/secure. Where should I look for more detail to figure out why the SSO login is failing?
assuming you have a valid Kerberos ticket the most probable reason is
that libkrb5 cannot properly relate the Kerberos principal from the
ticket to the local user name you use at the login prompt. With DEBUG3
you should see some messages containing '*userok*'. If you see failures
related to these messages it most probable is this case.

Recent versions of SSSD will configure a plugin for libkrb5 which can
handle this. But for older version you either have to create a .k5login
file in the users home directory containing the Kerberos principal or
use auth_to_local directives in /etc/krb5.conf as described in
http://www.freeipa.org/page/Active_Directory_trust_setup#Edit_.2Fetc.2Fkrb5.conf

HTH

bye,
Sumit
Mar 30 08:47:39 mid-ipa-vp01 sshd[9317]: Starting session: shell on pts/0 for root from 10.34.149.105 port 49725
Mar 30 08:47:39 mid-ipa-vp01 sshd[9322]: debug1: Setting controlling tty using TIOCSCTTY.
Mar 30 08:47:39 mid-ipa-vp01 sshd[9322]: debug1: PAM: reinitializing credentials
Mar 30 08:47:39 mid-ipa-vp01 sshd[9322]: debug1: permanently_set_uid: 0/0
Mar 30 08:53:51 mid-ipa-vp01 sshd[1388]: debug1: Forked child 12621.
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: Set /proc/self/oom_score_adj to 0
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: inetd sockets after dupping: 3, 3
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: Connection from 10.80.5.239 port 52982 on 10.127.26.73 port 22
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: Client protocol version 2.0; client software version PuTTY_Release_0.64
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: no match: PuTTY_Release_0.64
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: Enabling compatibility mode for protocol 2.0
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: Local version string SSH-2.0-OpenSSH_6.6.1
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SELinux support enabled [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: permanently_set_uid: 74/74 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: list_hostkey_types: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEXINIT received [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: client->server aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: server->client aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: kex: diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Mar 30 08:53:51 mid-ipa-vp01 sshd[12621]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: KEX done [preauth]
Mar 30 08:53:52 mid-ipa-vp01 sshd[12621]: debug1: attempt 0 failures 0 [preauth]
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: PAM: setting PAM_RHOST to "svr-addc-vt01.test.osuwmc"
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: PAM: setting PAM_TTY to "ssh"
Mar 30 08:53:53 mid-ipa-vp01 sshd[12621]: debug1: attempt 1 failures 0 [preauth]
Mar 30 08:53:58 mid-ipa-vp01 sshd[12621]: debug1: attempt 2 failures 0 [preauth]
Mar 30 08:54:00 mid-ipa-vp01 sshd[12621]: debug1: do_pam_account: called
--
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freei
Gould, Joshua
2015-03-30 14:09:00 UTC
Permalink
I configured the .k5login per the RH docs.

$ cat .k5login
adm-***@TEST.OSUWMC
TEST.OSUWMC\adm-faru03
$


I upped the debugging to DEBUG3 but I can¹t make sense of the error. Can
you help? I¹m getting better but I can¹t get this one yet.

Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: Connection from 10.80.5.239 port
50824 on 10.127.26.73 port 22
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: Client protocol version
2.0; client software version PuTTY_Release_0.64
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: no match:
PuTTY_Release_0.64
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: Enabling compatibility
mode for protocol 2.0
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: Local version string
SSH-2.0-OpenSSH_6.6.1
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: fd 3 setting O_NONBLOCK
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: ssh_sandbox_init:
preparing rlimit sandbox
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: Network child is on pid
12794
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: preauth child monitor
started
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SELinux support enabled
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
ssh_selinux_change_context: setting context from
'system_u:system_r:sshd_t:s0-s0:c0.c1023' to
'system_u:system_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: privsep user:group 74:74
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: permanently_set_uid:
74/74 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: list_hostkey_types:
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_KEXINIT
received [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
curve25519-***@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha
2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchan
ge-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-***@openssh.c
om,aes256-***@openssh.com,chacha20-***@openssh.com,aes128-cbc,3des-cbc
,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-***@lysato
r.liu.se [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-***@openssh.c
om,aes256-***@openssh.com,chacha20-***@openssh.com,aes128-cbc,3des-cbc
,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-***@lysato
r.liu.se [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
hmac-md5-***@openssh.com,hmac-sha1-***@openssh.com,umac-64-***@openssh.com,
umac-128-***@openssh.com,hmac-sha2-256-***@openssh.com,hmac-sha2-512-***@op
enssh.com,hmac-ripemd160-***@openssh.com,hmac-sha1-96-***@openssh.com,hmac-
md5-96-***@openssh.com,hmac-md5,hmac-sha1,umac-***@openssh.com,umac-***@open
ssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-***@openssh.c
om,hmac-sha1-96,hmac-md5-96 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
hmac-md5-***@openssh.com,hmac-sha1-***@openssh.com,umac-64-***@openssh.com,
umac-128-***@openssh.com,hmac-sha2-256-***@openssh.com,hmac-sha2-512-***@op
enssh.com,hmac-ripemd160-***@openssh.com,hmac-sha1-96-***@openssh.com,hmac-
md5-96-***@openssh.com,hmac-md5,hmac-sha1,umac-***@openssh.com,umac-***@open
ssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-***@openssh.c
om,hmac-sha1-96,hmac-md5-96 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
none,***@openssh.com [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
none,***@openssh.com [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
first_kex_follows 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
reserved 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,dif
fie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-
sha1 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
ssh-rsa,ssh-dss [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
aes256-ctr,aes256-cbc,rijndael-***@lysator.liu.se,aes192-ctr,aes192-cbc,aes
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
aes256-ctr,aes256-cbc,rijndael-***@lysator.liu.se,aes192-ctr,aes192-cbc,aes
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
none,zlib [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
none,zlib [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
first_kex_follows 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_parse_kexinit:
reserved 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: kex: client->server
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: kex: server->client
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: kex:
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 120 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 120
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 121
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: kex:
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 120 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 120
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 121
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1:
SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_choose_dh: waiting
for MONITOR_ANS_MODULI [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 1 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 0
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_moduli: got
parameters: 1024 4096 8192
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 1
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 0 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_choose_dh: remaining
0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1:
SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: bits set: 2077/4096
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: bits set: 2021/4096
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_key_sign entering
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 6 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 7 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 6
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_sign
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_sign:
signature 0x7f4788d8c440(271)
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 7
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 6 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1:
SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_derive_keys [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: set_newkeys: mode 1
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: expecting
SSH2_MSG_NEWKEYS [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: set_newkeys: mode 0
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_NEWKEYS
received [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: KEX done [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: userauth-request for
user adm-***@test.osuwmc service ssh-connection method none [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: attempt 0 failures 0
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_getpwnamallow
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 8 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_getpwnamallow:
waiting for MONITOR_ANS_PWNAM [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 9 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 8
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_pwnamallow
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: Trying to reverse map
address 10.80.5.239.
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: parse_server_config:
config reprocess config len 899
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_pwnamallow:
sending MONITOR_ANS_PWNAM: 1
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 9
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 8 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: input_userauth_request:
setting up authctxt for adm-***@test.osuwmc [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_start_pam entering
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 100 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_inform_authserv
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 4 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_inform_authrole
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 80 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: input_userauth_request:
try method none [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: userauth_finish: failure
partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password"
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 100
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: PAM: initializing for
"adm-***@test.osuwmc"
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: PAM: setting PAM_RHOST
to "svr-addc-vt01.test.osuwmc"
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: PAM: setting PAM_TTY to
"ssh"
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 100 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: userauth-request for
user adm-***@test.osuwmc service ssh-connection method gssapi-with-mic
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: attempt 1 failures 0
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: input_userauth_request:
try method gssapi-with-mic [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 42 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 43 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 4
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_authserv:
service=ssh-connection, style=
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 4 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 80
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_authrole: role=
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 80 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 42
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 43
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: Postponed gssapi-with-mic for
adm-***@test.osuwmc from 10.80.5.239 port 50824 ssh2 [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug1: userauth-request for
user adm-***@test.osuwmc service ssh-connection method password
[preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug1: attempt 2 failures 0
[preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug2: input_userauth_request:
try method password [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_auth_password
entering [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 12 [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_auth_password:
waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3:
mm_request_receive_expect entering: type 13 [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 12
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: PAM: sshpam_passwd_conv
called with 1 messages
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: pam_unix(sshd:auth):
authentication failure; logname= uid=0 euid=0 tty=ssh ruser=
rhost=svr-addc-vt01.test.osuwmc user=adm-***@test.osuwmc
Mar 30 09:57:25 mid-ipa-vp01 sshd[12793]: pam_sss(sshd:auth):
authentication success; logname= uid=0 euid=0 tty=ssh ruser=
rhost=svr-addc-vt01.test.osuwmc user=adm-***@test.osuwmc
Mar 30 09:57:25 mid-ipa-vp01 sshd[12793]: debug1: PAM: password
Post by Sumit Bose
assuming you have a valid Kerberos ticket the most probable reason is
that libkrb5 cannot properly relate the Kerberos principal from the
ticket to the local user name you use at the login prompt. With DEBUG3
you should see some messages containing '*userok*'. If you see failures
related to these messages it most probable is this case.
Recent versions of SSSD will configure a plugin for libkrb5 which can
handle this. But for older version you either have to create a .k5login
file in the users home directory containing the Kerberos principal or
use auth_to_local directives in /etc/krb5.conf as described in
https://urldefense.proofpoint.com/v2/url?u=http-3A__www.freeipa.org_page_A
ctive-5FDirectory-5Ftrust-5Fsetup-23Edit-5F.2Fetc.2Fkrb5.conf&d=AwIDaQ&c=k
9MF1d71ITtkuJx-PdWme51dKbmfPEvxwt8SFEkBfs4&r=C8H0y1Bn8C6Mf5i9qrqkUDy3xSk8z
PbIs_SvJwojC24&m=4CkfthdUOBBXSFdkUzW4imHzEchORW-ZPDVNXQlaZ3A&s=a7-Ti-Mlcie
m4dhsLicRf0Qg6sZDhThV-kMNED2rYug&e=
HTH
bye,
Sumit
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Sumit Bose
2015-03-30 14:58:18 UTC
Permalink
Post by Gould, Joshua
I configured the .k5login per the RH docs.
$ cat .k5login
TEST.OSUWMC\adm-faru03
The second line is not needed. Please note that .k5login must only be
read-writable for the owner.

Can you check by calling klist in a Windows Command window if you got
a proper host/... ticket for the IPA host?

What version of IPA and SSSD are you using.

Can you check if the following works on a IPA host:

kinit adm-***@TEST.OSUWMC
kvno host/name.of.the.ipa-***@IPA.REALM
ssh -v -l adm-***@test.osuwmc name.of.the.ipa-client.to.login

The error messages return by the ssh -v output might help to see why
GSSAPI auth failed.

bye,
Sumit
Post by Gould, Joshua
$
I upped the debugging to DEBUG3 but I can¹t make sense of the error. Can
you help? I¹m getting better but I can¹t get this one yet.
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: Connection from 10.80.5.239 port
50824 on 10.127.26.73 port 22
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: Client protocol version
2.0; client software version PuTTY_Release_0.64
PuTTY_Release_0.64
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: Enabling compatibility
mode for protocol 2.0
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: Local version string
SSH-2.0-OpenSSH_6.6.1
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: fd 3 setting O_NONBLOCK
preparing rlimit sandbox
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: Network child is on pid
12794
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: preauth child monitor
started
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SELinux support enabled
[preauth]
ssh_selinux_change_context: setting context from
'system_u:system_r:sshd_t:s0-s0:c0.c1023' to
'system_u:system_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: privsep user:group 74:74
[preauth]
74/74 [preauth]
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_KEXINIT
received [preauth]
2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchan
ge-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
r.liu.se [preauth]
r.liu.se [preauth]
om,hmac-sha1-96,hmac-md5-96 [preauth]
om,hmac-sha1-96,hmac-md5-96 [preauth]
[preauth]
[preauth]
first_kex_follows 0 [preauth]
reserved 0 [preauth]
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,dif
fie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-
sha1 [preauth]
ssh-rsa,ssh-dss [preauth]
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
none,zlib [preauth]
none,zlib [preauth]
[preauth]
[preauth]
first_kex_follows 0 [preauth]
reserved 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: kex: client->server
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: kex: server->client
aes256-ctr hmac-sha2-256 none [preauth]
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 120 [preauth]
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 120
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 121
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 120 [preauth]
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 120
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 121
SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 0 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_choose_dh: waiting
for MONITOR_ANS_MODULI [preauth]
mm_request_receive_expect entering: type 1 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 0
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_moduli: got
parameters: 1024 4096 8192
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 1
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 0 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_choose_dh: remaining
0 [preauth]
SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: bits set: 2077/4096
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: bits set: 2021/4096
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_key_sign entering
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 6 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN [preauth]
mm_request_receive_expect entering: type 7 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 6
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_sign
signature 0x7f4788d8c440(271)
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 7
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 6 used
once, disabling now
SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: kex_derive_keys [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: set_newkeys: mode 1
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: expecting
SSH2_MSG_NEWKEYS [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: set_newkeys: mode 0
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: SSH2_MSG_NEWKEYS
received [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: KEX done [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: userauth-request for
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: attempt 0 failures 0
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_getpwnamallow
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 8 [preauth]
waiting for MONITOR_ANS_PWNAM [preauth]
mm_request_receive_expect entering: type 9 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 8
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_pwnamallow
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: Trying to reverse map
address 10.80.5.239.
config reprocess config len 899
sending MONITOR_ANS_PWNAM: 1
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 9
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 8 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_start_pam entering
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 100 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_inform_authserv
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 4 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_inform_authrole
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 80 [preauth]
try method none [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: userauth_finish: failure
partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password"
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 100
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: PAM: initializing for
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: PAM: setting PAM_RHOST
to "svr-addc-vt01.test.osuwmc"
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: PAM: setting PAM_TTY to
"ssh"
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 100 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: userauth-request for
[preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug1: attempt 1 failures 0
[preauth]
try method gssapi-with-mic [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 42 [preauth]
mm_request_receive_expect entering: type 43 [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 4
service=ssh-connection, style=
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 4 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 80
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_answer_authrole: role=
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug2: monitor_read: 80 used
once, disabling now
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 42
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 43
Mar 30 09:57:20 mid-ipa-vp01 sshd[12793]: Postponed gssapi-with-mic for
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug1: userauth-request for
[preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug1: attempt 2 failures 0
[preauth]
try method password [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_auth_password
entering [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_request_send
entering: type 12 [preauth]
waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
mm_request_receive_expect entering: type 13 [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering [preauth]
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: mm_request_receive
entering
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: monitor_read: checking
request 12
Mar 30 09:57:23 mid-ipa-vp01 sshd[12793]: debug3: PAM: sshpam_passwd_conv
called with 1 messages
authentication failure; logname= uid=0 euid=0 tty=ssh ruser=
authentication success; logname= uid=0 euid=0 tty=ssh ruser=
Mar 30 09:57:25 mid-ipa-vp01 sshd[12793]: debug1: PAM: password
Post by Sumit Bose
assuming you have a valid Kerberos ticket the most probable reason is
that libkrb5 cannot properly relate the Kerberos principal from the
ticket to the local user name you use at the login prompt. With DEBUG3
you should see some messages containing '*userok*'. If you see failures
related to these messages it most probable is this case.
Recent versions of SSSD will configure a plugin for libkrb5 which can
handle this. But for older version you either have to create a .k5login
file in the users home directory containing the Kerberos principal or
use auth_to_local directives in /etc/krb5.conf as described in
https://urldefense.proofpoint.com/v2/url?u=http-3A__www.freeipa.org_page_A
ctive-5FDirectory-5Ftrust-5Fsetup-23Edit-5F.2Fetc.2Fkrb5.conf&d=AwIDaQ&c=k
9MF1d71ITtkuJx-PdWme51dKbmfPEvxwt8SFEkBfs4&r=C8H0y1Bn8C6Mf5i9qrqkUDy3xSk8z
PbIs_SvJwojC24&m=4CkfthdUOBBXSFdkUzW4imHzEchORW-ZPDVNXQlaZ3A&s=a7-Ti-Mlcie
m4dhsLicRf0Qg6sZDhThV-kMNED2rYug&e=
HTH
bye,
Sumit
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Jan Pazdziora
2015-03-30 14:45:43 UTC
Permalink
SSO works intermittently. I’m having trouble tracing the issue. Here is what I see from /var/log/secure. Where should I look for more detail to figure out why the SSO login is failing?
What OS versions is this and how was the machine enrolled --
ipa-client-install, realm join, or some other way?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-us
Gould, Joshua
2015-03-30 14:50:11 UTC
Permalink
It¹s actually my IPA server which is also a client, so both are 7.1. My
memory is fuzzy as far as the client on the server. Isn¹t it setup already
as part of the server install?
Post by Jan Pazdziora
SSO works intermittently. I¹m having trouble tracing the issue. Here is
what I see from /var/log/secure. Where should I look for more detail to
figure out why the SSO login is failing?
What OS versions is this and how was the machine enrolled --
ipa-client-install, realm join, or some other way?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Jan Pazdziora
2015-03-30 14:55:42 UTC
Permalink
Post by Gould, Joshua
It¹s actually my IPA server which is also a client, so both are 7.1. My
memory is fuzzy as far as the client on the server. Isn¹t it setup already
as part of the server install?
So you are logging in from the server to the server? But you have

Connection from 10.80.5.239 port 52982 on 10.127.26.73 port 22
debug1: Client protocol version 2.0; client software version PuTTY_Release_0.64

in the log -- different IP addresses, and the client looks like Putty,
which would mean you try to log in from a Windows machine ...

So that test.osuwmc realm -- is that your IPA server's realm, or AD
realm?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Gould, Joshua
2015-03-30 15:04:58 UTC
Permalink
Sorry I mis-read your question!

We’re trying SSO from the test domain conroller via ssh (putty) to the
test IPA server.

Unix.test.osuwmc is the IPA realm.
Test.osuwmc is the AD realm.

IPA server is RHEL 7.1
Windows AD DC is Windows Server 2008 R2

They have a two way trust and we’re mapping SID’s. Since most of our SID’s
are in the 300,000, we chose to add 1M to each SID to make mapping them
easy.

Right now I have the allow-all rule configured to allow everyone in on
every service to every host, just to rule that out.

# ipa trust-show
Realm name: TEST.OSUWMC
Realm name: test.osuwmc
Domain NetBIOS name: TEST
Domain Security Identifier: S-1-5-21-226267946-722566613-1883572810
Trust direction: Two-way trust
Trust type: Active Directory domain
# ipa idrange-find --all
----------------
2 ranges matched
----------------
dn: cn=TEST.OSUWMC_id_range,cn=ranges,cn=etc,dc=unix,dc=test,dc=osuwmc
Range name: TEST.OSUWMC_id_range
First Posix ID of the range: 1000000
Number of IDs in the range: 900000
First RID of the corresponding RID range: 0
Domain SID of the trusted domain: S-1-5-21-226267946-722566613-1883572810
Range type: Active Directory domain range
iparangetyperaw: ipa-ad-trust
objectclass: ipatrustedaddomainrange, ipaIDrange

dn:
cn=UNIX.TEST.OSUWMC_id_range,cn=ranges,cn=etc,dc=unix,dc=test,dc=osuwmc
Range name: UNIX.TEST.OSUWMC_id_range
First Posix ID of the range: 233600000
Number of IDs in the range: 200000
First RID of the corresponding RID range: 1000
First RID of the secondary RID range: 100000000
Range type: local domain range
iparangetyperaw: ipa-local
objectclass: top, ipaIDrange, ipaDomainIDRange
----------------------------
Number of entries returned 2
----------------------------
# # id adm-***@test.osuwmc
uid=1398410(adm-***@test.osuwmc) gid=1398410(adm-***@test.osuwmc)
groups=1398410(adm-***@test.osuwmc), 233600008(citrix_users)
#
Post by Jan Pazdziora
Post by Gould, Joshua
It¹s actually my IPA server which is also a client, so both are 7.1. My
memory is fuzzy as far as the client on the server. Isn¹t it setup already
as part of the server install?
So you are logging in from the server to the server? But you have
Connection from 10.80.5.239 port 52982 on 10.127.26.73 port 22
debug1: Client protocol version 2.0; client software version
PuTTY_Release_0.64
in the log -- different IP addresses, and the client looks like Putty,
which would mean you try to log in from a Windows machine ...
So that test.osuwmc realm -- is that your IPA server's realm, or AD
realm?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the p
Jan Pazdziora
2015-03-30 15:08:29 UTC
Permalink
Post by Gould, Joshua
We’re trying SSO from the test domain conroller via ssh (putty) to the
test IPA server.
Unix.test.osuwmc is the IPA realm. > Test.osuwmc is the AD realm.
IPA server is RHEL 7.1
Windows AD DC is Windows Server 2008 R2
They have a two way trust and we’re mapping SID’s. Since most of our SID’s
are in the 300,000, we chose to add 1M to each SID to make mapping them
easy.
Can you check that

/etc/krb5.conf

contains line

includedir /var/lib/sss/pubconf/krb5.include.d/

and that

/var/lib/sss/pubconf/krb5.include.d/localauth_plugin

exists and configures

module = sssd:/usr/lib64/sssd/modules/sssd_krb5_localauth_plugin.so

?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org fo
Gould, Joshua
2015-03-30 15:17:07 UTC
Permalink
The include is there:
# head /etc/krb5.conf
includedir /var/lib/sss/pubconf/krb5.include.d/

[logging]
default = FILE:/var/log/krb5libs.log
kdc = FILE:/var/log/krb5kdc.log
admin_server = FILE:/var/log/kadmind.log

[libdefaults]
default_realm = UNIX.TEST.OSUWMC
dns_lookup_realm = true

# ls -l /var/lib/sss/pubconf/krb5.include.d/localauth_plugin
-rw-r--r--. 1 root root 118 Mar 30 08:46
/var/lib/sss/pubconf/krb5.include.d/localauth_plugin
# grep module /var/lib/sss/pubconf/krb5.include.d/localauth_plugin
module = sssd:/usr/lib64/sssd/modules/sssd_krb5_localauth_plugin.so
#




Different write-ups had slightly different examples for this line. Would
this be the issue?

# auth_to_local =
RULE:[1:$1@$0](^.*@TEST.OSUWMC$)s/@TEST.OSUWMC/@test.osuwmc/
auth_to_local = RULE:[1:$1 $0](^ *
Post by Jan Pazdziora
We¹re trying SSO from the test domain conroller via ssh (putty) to the
test IPA server.
Unix.test.osuwmc is the IPA realm. > Test.osuwmc is the AD realm.
IPA server is RHEL 7.1
Windows AD DC is Windows Server 2008 R2
They have a two way trust and we¹re mapping SID¹s. Since most of our
SID¹s
are in the 300,000, we chose to add 1M to each SID to make mapping them
easy.
Can you check that
/etc/krb5.conf
contains line
includedir /var/lib/sss/pubconf/krb5.include.d/
and that
/var/lib/sss/pubconf/krb5.include.d/localauth_plugin
exists and configures
module = sssd:/usr/lib64/sssd/modules/sssd_krb5_localauth_plugin.so
?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Dmitri Pal
2015-03-30 15:56:45 UTC
Permalink
Post by Gould, Joshua
# head /etc/krb5.conf
includedir /var/lib/sss/pubconf/krb5.include.d/
[logging]
default = FILE:/var/log/krb5libs.log
kdc = FILE:/var/log/krb5kdc.log
admin_server = FILE:/var/log/kadmind.log
[libdefaults]
default_realm = UNIX.TEST.OSUWMC
dns_lookup_realm = true
# ls -l /var/lib/sss/pubconf/krb5.include.d/localauth_plugin
-rw-r--r--. 1 root root 118 Mar 30 08:46
/var/lib/sss/pubconf/krb5.include.d/localauth_plugin
# grep module /var/lib/sss/pubconf/krb5.include.d/localauth_plugin
module = sssd:/usr/lib64/sssd/modules/sssd_krb5_localauth_plugin.so
#
Different write-ups had slightly different examples for this line. Would
this be the issue?
# auth_to_local =
auth_to_local = RULE:[1:$1 $0](^ *
If you use the plugin then this RULE should not be needed.
Have you tried commenting it out and restarting SSSD?
Post by Gould, Joshua
Post by Jan Pazdziora
We¹re trying SSO from the test domain conroller via ssh (putty) to the
test IPA server.
Unix.test.osuwmc is the IPA realm. > Test.osuwmc is the AD realm.
IPA server is RHEL 7.1
Windows AD DC is Windows Server 2008 R2
They have a two way trust and we¹re mapping SID¹s. Since most of our
SID¹s
are in the 300,000, we chose to add 1M to each SID to make mapping them
easy.
Can you check that
/etc/krb5.conf
contains line
includedir /var/lib/sss/pubconf/krb5.include.d/
and that
/var/lib/sss/pubconf/krb5.include.d/localauth_plugin
exists and configures
module = sssd:/usr/lib64/sssd/modules/sssd_krb5_localauth_plugin.so
?
--
Jan Pazdziora
Principal Software Engineer, Identity Management Engineering, Red Hat
--
Thank you,
Dmitri Pal

Sr. Engineering Manager IdM portfolio
Red Hat, Inc.
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Gould, Joshua
2015-03-30 17:42:10 UTC
Permalink
Post by Dmitri Pal
Post by Gould, Joshua
# auth_to_local =
auth_to_local = RULE:[1:$1 $0](^ *
If you use the plugin then this RULE should not be needed.
Have you tried commenting it out and restarting SSSD?
I commented out those lines and restarted SSSD. I still was not able to
get in with SSO.

Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: fd 5 is not O_NONBLOCK
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug1: Forked child 13750.
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: send_rexec_state:
entering fd = 8 config len 899
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: ssh_msg_send: type 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: send_rexec_state: done
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: oom_adjust_restore
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: Set /proc/self/oom_score_adj to 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: rexec start in 5 out 5
newsock 5 pipe 7 sock 8
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: inetd sockets after
dupping: 3, 3
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: Connection from 10.80.5.239 port
65333 on 10.127.26.73 port 22
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Client protocol version
2.0; client software version PuTTY_Release_0.64
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: no match:
PuTTY_Release_0.64
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Enabling compatibility
mode for protocol 2.0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Local version string
SSH-2.0-OpenSSH_6.6.1
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: fd 3 setting O_NONBLOCK
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: ssh_sandbox_init:
preparing rlimit sandbox
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: Network child is on pid
13751
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: preauth child monitor
started
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3:
ssh_selinux_change_context: setting context from
'system_u:system_r:sshd_t:s0-s0:c0.c1023' to 'system_u:
system_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: privsep user:group 74:74
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: permanently_set_uid:
74/74 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: list_hostkey_types:
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_KEXINIT
received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
curve25519-***@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha
2-nistp521
,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,di
ffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-***@openssh.c
om,aes256-
***@openssh.com,chacha20-***@openssh.com,aes128-cbc,3des-cbc,blowfish-
cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-***@lysator.liu.se
[prea
uth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-***@openssh.c
om,aes256-
***@openssh.com,chacha20-***@openssh.com,aes128-cbc,3des-cbc,blowfish-
cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-***@lysator.liu.se
[prea
uth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
hmac-md5-***@openssh.com,hmac-sha1-***@openssh.com,umac-64-***@openssh.com,
umac-128-e
***@openssh.com,hmac-sha2-256-***@openssh.com,hmac-sha2-512-***@openssh.com,
hmac-ripemd160-***@openssh.com,hmac-sha1-96-***@openssh.com,hmac-md5-96-etm
@ope
nssh.com,hmac-md5,hmac-sha1,umac-***@openssh.com,umac-***@openssh.com,hmac-s
ha2-256,hmac-sha2-512,hmac-ripemd160,hmac-***@openssh.com,hmac-sha1-9
6,hm
ac-md5-96 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
hmac-md5-***@openssh.com,hmac-sha1-***@openssh.com,umac-64-***@openssh.com,
umac-128-e
***@openssh.com,hmac-sha2-256-***@openssh.com,hmac-sha2-512-***@openssh.com,
hmac-ripemd160-***@openssh.com,hmac-sha1-96-***@openssh.com,hmac-md5-96-etm
@ope
nssh.com,hmac-md5,hmac-sha1,umac-***@openssh.com,umac-***@openssh.com,hmac-s
ha2-256,hmac-sha2-512,hmac-ripemd160,hmac-***@openssh.com,hmac-sha1-9
6,hm
ac-md5-96 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
none,***@openssh.com [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
none,***@openssh.com [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
first_kex_follows 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
reserved 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,dif
fie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-
sha1 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
ssh-rsa,ssh-dss [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
aes256-ctr,aes256-cbc,rijndael-***@lysator.liu.se,aes192-ctr,aes192-cbc,aes
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
aes256-ctr,aes256-cbc,rijndael-***@lysator.liu.se,aes192-ctr,aes192-cbc,aes
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
none,zlib [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
none,zlib [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
first_kex_follows 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_parse_kexinit:
reserved 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex: client->server
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex: server->client
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex:
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 120 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 120
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 121
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex:
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 120 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 120
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 121
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1:
SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_choose_dh: waiting
for MONITOR_ANS_MODULI [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 1 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_moduli: got
parameters: 1024 4096 8192
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 1
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 0 used
once, disabling now
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_choose_dh: remaining
0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1:
SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: bits set: 2013/4096
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: bits set: 2017/4096
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_key_sign entering
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 6 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 7 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 6
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_sign
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_sign:
signature 0x7f60fd611d20(271)
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 7
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 6 used
once, disabling now
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1:
SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_derive_keys [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: set_newkeys: mode 1
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: expecting
SSH2_MSG_NEWKEYS [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: set_newkeys: mode 0
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_NEWKEYS
received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: KEX done [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
user adm-***@test.osuwmc service ssh-connection method none [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: attempt 0 failures 0
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_getpwnamallow
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 8 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_getpwnamallow:
waiting for MONITOR_ANS_PWNAM [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 9 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 8
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pwnamallow
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: Trying to reverse map
address 10.80.5.239.
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: parse_server_config:
config reprocess config len 899
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pwnamallow:
sending MONITOR_ANS_PWNAM: 1
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 9
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 8 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: input_userauth_request:
setting up authctxt for adm-***@test.osuwmc [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_start_pam entering
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 100 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_inform_authserv
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 4 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_inform_authrole
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 80 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: input_userauth_request:
try method none [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: userauth_finish: failure
partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password"
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 100
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: initializing for
"adm-***@test.osuwmc"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: setting PAM_RHOST
to "svr-addc-vt01.test.osuwmc"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: setting PAM_TTY to
"ssh"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 100 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
user adm-***@test.osuwmc service ssh-connection method gssapi-with-mic
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: attempt 1 failures 0
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: input_userauth_request:
try method gssapi-with-mic [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 42 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 43 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 4
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_authserv:
service=ssh-connection, style=
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 4 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 80
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_authrole: role=
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 80 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 42
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 43
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: Postponed gssapi-with-mic for
adm-***@test.osuwmc from 10.80.5.239 port 65333 ssh2 [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
user adm-***@test.osuwmc service ssh-connection method password
[preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug1: attempt 2 failures 0
[preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug2: input_userauth_request:
try method password [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password
entering [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 12 [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password:
waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 13 [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 12
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: PAM: sshpam_passwd_conv
called with 1 messages
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: pam_unix(sshd:auth):
authentication failure; logname= uid=0 euid=0 tty=ssh ruser=
rhost=svr-addc-vt01.test.osuwmc user=adm-***@test.osuwmc
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: pam_sss(sshd:auth):
authentication success; logname= uid=0 euid=0 tty=ssh ruser=
rhost=svr-addc-vt01.test.osuwmc user=adm-***@test.osuwmc
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug1: PAM: password
authentication accepted for adm-***@test.osuwmc
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_authpassword:
sending result 1
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 13
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 102
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug1: do_pam_account: called
Mar 30 13:33:42 mid-ipa-vp01 sshd[13719]: debug1:
server_input_global_request: rtype ***@openssh.com want_reply 1
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: PAM: do_pam_account
pam_acct_mgmt = 0 (Success)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 103
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: Accepted password for
adm-***@test.osuwmc from 10.80.5.239 port 65333 ssh2
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: monitor_child_preauth:
adm-***@test.osuwmc has been authenticated by privileged process
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Waiting
for new keys
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 26
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_newkeys_from_blob:
0x7f60fd62ff00(159)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Waiting
for second key
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_newkeys_from_blob:
0x7f60fd62ff00(159)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Getting
compression state
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Getting
Network I/O buffers
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 122
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 123
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password: user
authenticated [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_do_pam_account
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 102 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 103 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_do_pam_account
returning 1 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_send_keystate:
Sending new keys: 0x7f60fd61fc90 0x7f60fd610a40 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_newkeys_to_blob:
converting 0x7f60fd61fc90 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_newkeys_to_blob:
converting 0x7f60fd610a40 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_send_keystate: New
keys have been sent [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_send_keystate:
Sending compression state [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 26 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_send_keystate:
Finished sending state [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 122 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3:
mm_request_receive_expect entering: type 123 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: monitor_read_log: child
log fd closed
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_share_sync: Share sync
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_share_sync: Share
sync end
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3:
ssh_sandbox_parent_finish: finished
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: temporarily_use_uid:
1398410/1398410 (e=0/0)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: ssh_gssapi_storecreds:
Not a GSSAPI mechanism
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: restore_uid: 0/0
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3:
sshd_selinux_setup_variables: setting execution context
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: PAM: establishing
credentials
Mar 30 13:33:44 mid-ipa-vp01 sshd[13750]: debug3: PAM: opening session
Mar 30 13:33:45 mid-ipa-vp01 sshd[13750]: pam_unix(sshd:session): session
opened for user adm-***@test.osuwmc by (uid=0)
Mar 30 13:33:46 mid-ipa-vp01 sshd[13750]: User child is on pid 13761
Mar 30 13:33:46 mid-ipa-vp01 sshd[13761]: debug1: PAM: establishing
credentials
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3:
sshd_selinux_setup_variables: setting execution context
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: permanently_set_uid:
1398410/1398410
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: set_newkeys: mode 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: set_newkeys: mode 1
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: Entering interactive
session for SSH2.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 10 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 11 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: server_init_dispatch_20
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: Received SSH2_MSG_IGNORE
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1:
server_input_channel_open: ctype session rchan 256 win 16384 max 16384
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: input_session_request
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: channel 0: new
[server-session]
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: session_unused: session
id 0 unused
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_new: session 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_open: channel 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_open: session 0:
link with channel 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1:
server_input_channel_open: confirm session
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1:
server_input_channel_req: channel 0 request pty-req reply 1
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_by_channel:
session 0 channel 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1:
session_input_channel_req: session 0 req pty-req
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: Allocating pty.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_request_send
entering: type 28
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_pty_allocate: waiting
for MONITOR_ANS_PTY
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 28
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pty entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: session_unused: session
id 0 unused
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug1: session_new: session 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3:
mm_request_receive_expect entering: type 29
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: ssh_selinux_setup_pty:
setting TTY context on /dev/pts/2
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: ssh_selinux_setup_pty:
done
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 29
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pty: tty
/dev/pts/2 ptyfd 5
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_pty_req: session
0 alloc /dev/pts/2
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1:
server_input_channel_req: channel 0 request shell reply 1
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_by_channel:
session 0 channel 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1:
session_input_channel_req: session 0 req shell
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: Starting session: shell on pts/2
for adm-***@test.osuwmc from 10.80.5.239 port 65333
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 3 setting TCP_NODELAY
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: packet_set_tos: set
IP_TOS 0x10
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: channel 0: rfd 14 isatty
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 14 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: fd 12 is O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug1: Setting controlling tty
using TIOCSCTTY.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: mm_request_send
entering: type 124
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3:
mm_request_receive_expect entering: type 125
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 124
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 125
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: Copy environment:
KRB5CCNAME=FILE:/tmp/krb5cc_1398410_B30vDK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: Copy environment:
SELINUX_ROLE_REQUESTED=
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: Copy environment:
SELINUX_LEVEL_REQUESTED=
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: Copy environment:
SELINUX_USE_CURRENT_RANGE=
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: Copy environment:
XDG_SESSION_ID=10
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: Copy environment:
XDG_RUNTIME_DIR=/run/user/1398410

Just in case, here is my krb5.conf

includedir /var/lib/sss/pubconf/krb5.include.d/

[logging]
default = FILE:/var/log/krb5libs.log
kdc = FILE:/var/log/krb5kdc.log
admin_server = FILE:/var/log/kadmind.log

[libdefaults]
default_realm = UNIX.TEST.OSUWMC
dns_lookup_realm = true
dns_lookup_kdc = true
rdns = false
ticket_lifetime = 24h
forwardable = yes
udp_preference_limit = 0
# default_ccache_name = KEYRING:persistent:%{uid}

[realms]
UNIX.TEST.OSUWMC = {
kdc = mid-ipa-vp01.unix.test.osuwmc:88
master_kdc = mid-ipa-vp01.unix.test.osuwmc:88
admin_server = mid-ipa-vp01.unix.test.osuwmc:749
default_domain = unix.test.osuwmc
pkinit_anchors = FILE:/etc/ipa/ca.crt
# auth_to_local =
RULE:[1:$1@$0](^.*@TEST.OSUWMC$)s/@TEST.OSUWMC/@test.osuwmc/
# auth_to_local = RULE:[1:$1 $0](^ *
TEST.OSUWMC$)s/@TEST.OSUWMC/@test.osuwmc/
auth_to_local = DEFAULT
}

[domain_realm]
.unix.test.osuwmc = UNIX.TEST.OSUWMC
unix.test.osuwmc = UNIX.TEST.OSUWMC

[dbmodules]
UNIX.TEST.OSUWMC = {
db_library = ipadb.so
}
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Jan Cholasta
2015-03-31 05:56:53 UTC
Permalink
Hi,
Post by Gould, Joshua
Post by Dmitri Pal
Post by Gould, Joshua
# auth_to_local =
auth_to_local = RULE:[1:$1 $0](^ *
If you use the plugin then this RULE should not be needed.
Have you tried commenting it out and restarting SSSD?
I commented out those lines and restarted SSSD. I still was not able to
get in with SSO.
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: fd 5 is not O_NONBLOCK
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug1: Forked child 13750.
entering fd = 8 config len 899
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: ssh_msg_send: type 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: send_rexec_state: done
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: oom_adjust_restore
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: Set /proc/self/oom_score_adj to 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: rexec start in 5 out 5
newsock 5 pipe 7 sock 8
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: inetd sockets after
dupping: 3, 3
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: Connection from 10.80.5.239 port
65333 on 10.127.26.73 port 22
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Client protocol version
2.0; client software version PuTTY_Release_0.64
PuTTY_Release_0.64
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Enabling compatibility
mode for protocol 2.0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Local version string
SSH-2.0-OpenSSH_6.6.1
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: fd 3 setting O_NONBLOCK
preparing rlimit sandbox
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: Network child is on pid
13751
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: preauth child monitor
started
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
[preauth]
ssh_selinux_change_context: setting context from
system_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: privsep user:group 74:74
[preauth]
74/74 [preauth]
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_KEXINIT
received [preauth]
2-nistp521
,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,di
ffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
om,aes256-
[prea
uth]
om,aes256-
[prea
uth]
umac-128-e
@ope
6,hm
ac-md5-96 [preauth]
umac-128-e
@ope
6,hm
ac-md5-96 [preauth]
[preauth]
[preauth]
first_kex_follows 0 [preauth]
reserved 0 [preauth]
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,dif
fie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-
sha1 [preauth]
ssh-rsa,ssh-dss [preauth]
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
none,zlib [preauth]
none,zlib [preauth]
[preauth]
[preauth]
first_kex_follows 0 [preauth]
reserved 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex: client->server
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex: server->client
aes256-ctr hmac-sha2-256 none [preauth]
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 120 [preauth]
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 120
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 121
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 120 [preauth]
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 120
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 121
SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_choose_dh: waiting
for MONITOR_ANS_MODULI [preauth]
mm_request_receive_expect entering: type 1 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_moduli: got
parameters: 1024 4096 8192
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 1
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 0 used
once, disabling now
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_choose_dh: remaining
0 [preauth]
SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: bits set: 2013/4096
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: bits set: 2017/4096
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_key_sign entering
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 6 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN [preauth]
mm_request_receive_expect entering: type 7 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 6
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_sign
signature 0x7f60fd611d20(271)
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 7
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 6 used
once, disabling now
SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_derive_keys [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: set_newkeys: mode 1
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: expecting
SSH2_MSG_NEWKEYS [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: set_newkeys: mode 0
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_NEWKEYS
received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: KEX done [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: attempt 0 failures 0
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_getpwnamallow
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 8 [preauth]
waiting for MONITOR_ANS_PWNAM [preauth]
mm_request_receive_expect entering: type 9 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 8
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pwnamallow
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: Trying to reverse map
address 10.80.5.239.
config reprocess config len 899
sending MONITOR_ANS_PWNAM: 1
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 9
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 8 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_start_pam entering
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 100 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_inform_authserv
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 4 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_inform_authrole
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 80 [preauth]
try method none [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: userauth_finish: failure
partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password"
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 100
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: initializing for
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: setting PAM_RHOST
to "svr-addc-vt01.test.osuwmc"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: setting PAM_TTY to
"ssh"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 100 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: attempt 1 failures 0
[preauth]
try method gssapi-with-mic [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 42 [preauth]
mm_request_receive_expect entering: type 43 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 4
service=ssh-connection, style=
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 4 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 80
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_authrole: role=
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 80 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 42
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 43
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: Postponed gssapi-with-mic for
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
[preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug1: attempt 2 failures 0
[preauth]
try method password [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password
entering [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 12 [preauth]
waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
mm_request_receive_expect entering: type 13 [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 12
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: PAM: sshpam_passwd_conv
called with 1 messages
authentication failure; logname= uid=0 euid=0 tty=ssh ruser=
authentication success; logname= uid=0 euid=0 tty=ssh ruser=
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug1: PAM: password
sending result 1
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 13
mm_request_receive_expect entering: type 102
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug1: do_pam_account: called
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: PAM: do_pam_account
pam_acct_mgmt = 0 (Success)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 103
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: Accepted password for
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Waiting
for new keys
mm_request_receive_expect entering: type 26
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
0x7f60fd62ff00(159)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Waiting
for second key
0x7f60fd62ff00(159)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Getting
compression state
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Getting
Network I/O buffers
mm_request_receive_expect entering: type 122
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 123
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password: user
authenticated [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_do_pam_account
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 102 [preauth]
mm_request_receive_expect entering: type 103 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_do_pam_account
returning 1 [preauth]
Sending new keys: 0x7f60fd61fc90 0x7f60fd610a40 [preauth]
converting 0x7f60fd61fc90 [preauth]
converting 0x7f60fd610a40 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_send_keystate: New
keys have been sent [preauth]
Sending compression state [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 26 [preauth]
Finished sending state [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 122 [preauth]
mm_request_receive_expect entering: type 123 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: monitor_read_log: child
log fd closed
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_share_sync: Share sync
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_share_sync: Share
sync end
ssh_sandbox_parent_finish: finished
1398410/1398410 (e=0/0)
Not a GSSAPI mechanism
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: restore_uid: 0/0
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
sshd_selinux_setup_variables: setting execution context
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: PAM: establishing
credentials
Mar 30 13:33:44 mid-ipa-vp01 sshd[13750]: debug3: PAM: opening session
Mar 30 13:33:45 mid-ipa-vp01 sshd[13750]: pam_unix(sshd:session): session
Mar 30 13:33:46 mid-ipa-vp01 sshd[13750]: User child is on pid 13761
Mar 30 13:33:46 mid-ipa-vp01 sshd[13761]: debug1: PAM: establishing
credentials
sshd_selinux_setup_variables: setting execution context
1398410/1398410
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: set_newkeys: mode 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: set_newkeys: mode 1
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: Entering interactive
session for SSH2.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 10 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 11 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: server_init_dispatch_20
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: Received SSH2_MSG_IGNORE
server_input_channel_open: ctype session rchan 256 win 16384 max 16384
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: input_session_request
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: channel 0: new
[server-session]
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: session_unused: session
id 0 unused
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_new: session 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_open: channel 0
link with channel 0
server_input_channel_open: confirm session
server_input_channel_req: channel 0 request pty-req reply 1
session 0 channel 0
session_input_channel_req: session 0 req pty-req
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: Allocating pty.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_request_send
entering: type 28
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_pty_allocate: waiting
for MONITOR_ANS_PTY
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 28
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pty entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: session_unused: session
id 0 unused
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug1: session_new: session 0
mm_request_receive_expect entering: type 29
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
setting TTY context on /dev/pts/2
done
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 29
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pty: tty
/dev/pts/2 ptyfd 5
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_pty_req: session
0 alloc /dev/pts/2
server_input_channel_req: channel 0 request shell reply 1
session 0 channel 0
session_input_channel_req: session 0 req shell
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: Starting session: shell on pts/2
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 3 setting TCP_NODELAY
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: packet_set_tos: set
IP_TOS 0x10
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: channel 0: rfd 14 isatty
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 14 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: fd 12 is O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug1: Setting controlling tty
using TIOCSCTTY.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: mm_request_send
entering: type 124
mm_request_receive_expect entering: type 125
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 124
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 125
KRB5CCNAME=FILE:/tmp/krb5cc_1398410_B30vDK
SELINUX_ROLE_REQUESTED=
SELINUX_LEVEL_REQUESTED=
SELINUX_USE_CURRENT_RANGE=
XDG_SESSION_ID=10
XDG_RUNTIME_DIR=/run/user/1398410
Just in case, here is my krb5.conf
includedir /var/lib/sss/pubconf/krb5.include.d/
[logging]
default = FILE:/var/log/krb5libs.log
kdc = FILE:/var/log/krb5kdc.log
admin_server = FILE:/var/log/kadmind.log
[libdefaults]
default_realm = UNIX.TEST.OSUWMC
dns_lookup_realm = true
dns_lookup_kdc = true
rdns = false
ticket_lifetime = 24h
forwardable = yes
udp_preference_limit = 0
# default_ccache_name = KEYRING:persistent:%{uid}
[realms]
UNIX.TEST.OSUWMC = {
kdc = mid-ipa-vp01.unix.test.osuwmc:88
master_kdc = mid-ipa-vp01.unix.test.osuwmc:88
admin_server = mid-ipa-vp01.unix.test.osuwmc:749
default_domain = unix.test.osuwmc
pkinit_anchors = FILE:/etc/ipa/ca.crt
# auth_to_local =
# auth_to_local = RULE:[1:$1 $0](^ *
auth_to_local = DEFAULT
}
[domain_realm]
.unix.test.osuwmc = UNIX.TEST.OSUWMC
unix.test.osuwmc = UNIX.TEST.OSUWMC
[dbmodules]
UNIX.TEST.OSUWMC = {
db_library = ipadb.so
}
I'm not sure if this would be of any help to you, but in case you have
GSSAPI credential delegation enabled in PuTTY, you also need to allow
them to be delegated to the IPA server using:

$ ipa host-mod <ipa server fqdn> --ok-as-delegate=1

Honza
--
Jan Cholasta
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Sumit Bose
2015-03-31 07:30:47 UTC
Permalink
Post by Jan Cholasta
Hi,
Post by Gould, Joshua
Post by Dmitri Pal
Post by Gould, Joshua
# auth_to_local =
auth_to_local = RULE:[1:$1 $0](^ *
If you use the plugin then this RULE should not be needed.
Have you tried commenting it out and restarting SSSD?
I commented out those lines and restarted SSSD. I still was not able to
get in with SSO.
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: fd 5 is not O_NONBLOCK
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug1: Forked child 13750.
entering fd = 8 config len 899
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: ssh_msg_send: type 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[12789]: debug3: send_rexec_state: done
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: oom_adjust_restore
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: Set /proc/self/oom_score_adj to 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: rexec start in 5 out 5
newsock 5 pipe 7 sock 8
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: inetd sockets after
dupping: 3, 3
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: Connection from 10.80.5.239 port
65333 on 10.127.26.73 port 22
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Client protocol version
2.0; client software version PuTTY_Release_0.64
PuTTY_Release_0.64
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Enabling compatibility
mode for protocol 2.0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: Local version string
SSH-2.0-OpenSSH_6.6.1
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: fd 3 setting O_NONBLOCK
preparing rlimit sandbox
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: Network child is on pid
13751
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: preauth child monitor
started
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
[preauth]
ssh_selinux_change_context: setting context from
system_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: privsep user:group 74:74
[preauth]
74/74 [preauth]
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_KEXINIT
received [preauth]
2-nistp521
,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,di
ffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
om,aes256-
[prea
uth]
om,aes256-
[prea
uth]
umac-128-e
@ope
6,hm
ac-md5-96 [preauth]
umac-128-e
@ope
6,hm
ac-md5-96 [preauth]
[preauth]
[preauth]
first_kex_follows 0 [preauth]
reserved 0 [preauth]
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,dif
fie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-
sha1 [preauth]
ssh-rsa,ssh-dss [preauth]
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,a
rcfour128 [preauth]
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
none,zlib [preauth]
none,zlib [preauth]
[preauth]
[preauth]
first_kex_follows 0 [preauth]
reserved 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex: client->server
aes256-ctr hmac-sha2-256 none [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: kex: server->client
aes256-ctr hmac-sha2-256 none [preauth]
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 120 [preauth]
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 120
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 121
diffie-hellman-group-exchange-sha256 need=32 dh_need=32 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 120 [preauth]
mm_request_receive_expect entering: type 121 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 120
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 121
SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 0 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_choose_dh: waiting
for MONITOR_ANS_MODULI [preauth]
mm_request_receive_expect entering: type 1 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 0
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_moduli: got
parameters: 1024 4096 8192
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 1
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 0 used
once, disabling now
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_choose_dh: remaining
0 [preauth]
SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: bits set: 2013/4096
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: bits set: 2017/4096
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_key_sign entering
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 6 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN [preauth]
mm_request_receive_expect entering: type 7 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 6
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_sign
signature 0x7f60fd611d20(271)
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 7
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 6 used
once, disabling now
SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: kex_derive_keys [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: set_newkeys: mode 1
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: expecting
SSH2_MSG_NEWKEYS [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug2: set_newkeys: mode 0
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: SSH2_MSG_NEWKEYS
received [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: KEX done [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug1: attempt 0 failures 0
[preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_getpwnamallow
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 8 [preauth]
waiting for MONITOR_ANS_PWNAM [preauth]
mm_request_receive_expect entering: type 9 [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 8
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pwnamallow
Mar 30 13:33:35 mid-ipa-vp01 sshd[13750]: debug3: Trying to reverse map
address 10.80.5.239.
config reprocess config len 899
sending MONITOR_ANS_PWNAM: 1
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 9
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 8 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_start_pam entering
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 100 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_inform_authserv
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 4 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_inform_authrole
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 80 [preauth]
try method none [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: userauth_finish: failure
partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password"
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 100
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: initializing for
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: setting PAM_RHOST
to "svr-addc-vt01.test.osuwmc"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: PAM: setting PAM_TTY to
"ssh"
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 100 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
[preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug1: attempt 1 failures 0
[preauth]
try method gssapi-with-mic [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 42 [preauth]
mm_request_receive_expect entering: type 43 [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 4
service=ssh-connection, style=
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 4 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 80
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_authrole: role=
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug2: monitor_read: 80 used
once, disabling now
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 42
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 43
Mar 30 13:33:36 mid-ipa-vp01 sshd[13750]: Postponed gssapi-with-mic for
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug1: userauth-request for
[preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug1: attempt 2 failures 0
[preauth]
try method password [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password
entering [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 12 [preauth]
waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
mm_request_receive_expect entering: type 13 [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 12
Mar 30 13:33:39 mid-ipa-vp01 sshd[13750]: debug3: PAM: sshpam_passwd_conv
called with 1 messages
authentication failure; logname= uid=0 euid=0 tty=ssh ruser=
authentication success; logname= uid=0 euid=0 tty=ssh ruser=
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug1: PAM: password
sending result 1
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 13
mm_request_receive_expect entering: type 102
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:40 mid-ipa-vp01 sshd[13750]: debug1: do_pam_account: called
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: PAM: do_pam_account
pam_acct_mgmt = 0 (Success)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 103
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: Accepted password for
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Waiting
for new keys
mm_request_receive_expect entering: type 26
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
0x7f60fd62ff00(159)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Waiting
for second key
0x7f60fd62ff00(159)
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug2: mac_setup: setup
hmac-sha2-256
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Getting
compression state
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_get_keystate: Getting
Network I/O buffers
mm_request_receive_expect entering: type 122
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 123
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_auth_password: user
authenticated [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_do_pam_account
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 102 [preauth]
mm_request_receive_expect entering: type 103 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_do_pam_account
returning 1 [preauth]
Sending new keys: 0x7f60fd61fc90 0x7f60fd610a40 [preauth]
converting 0x7f60fd61fc90 [preauth]
converting 0x7f60fd610a40 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_send_keystate: New
keys have been sent [preauth]
Sending compression state [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 26 [preauth]
Finished sending state [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 122 [preauth]
mm_request_receive_expect entering: type 123 [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering [preauth]
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: monitor_read_log: child
log fd closed
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_share_sync: Share sync
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug3: mm_share_sync: Share
sync end
ssh_sandbox_parent_finish: finished
1398410/1398410 (e=0/0)
Not a GSSAPI mechanism
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: restore_uid: 0/0
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
sshd_selinux_setup_variables: setting execution context
Mar 30 13:33:43 mid-ipa-vp01 sshd[13750]: debug1: PAM: establishing
credentials
Mar 30 13:33:44 mid-ipa-vp01 sshd[13750]: debug3: PAM: opening session
Mar 30 13:33:45 mid-ipa-vp01 sshd[13750]: pam_unix(sshd:session): session
Mar 30 13:33:46 mid-ipa-vp01 sshd[13750]: User child is on pid 13761
Mar 30 13:33:46 mid-ipa-vp01 sshd[13761]: debug1: PAM: establishing
credentials
sshd_selinux_setup_variables: setting execution context
1398410/1398410
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: set_newkeys: mode 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: set_newkeys: mode 1
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: Entering interactive
session for SSH2.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 10 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 11 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: server_init_dispatch_20
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: Received SSH2_MSG_IGNORE
server_input_channel_open: ctype session rchan 256 win 16384 max 16384
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: input_session_request
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: channel 0: new
[server-session]
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: session_unused: session
id 0 unused
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_new: session 0
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_open: channel 0
link with channel 0
server_input_channel_open: confirm session
server_input_channel_req: channel 0 request pty-req reply 1
session 0 channel 0
session_input_channel_req: session 0 req pty-req
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: Allocating pty.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_request_send
entering: type 28
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_pty_allocate: waiting
for MONITOR_ANS_PTY
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 28
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pty entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: session_unused: session
id 0 unused
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug1: session_new: session 0
mm_request_receive_expect entering: type 29
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug1: SELinux support enabled
setting TTY context on /dev/pts/2
done
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 29
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_answer_pty: tty
/dev/pts/2 ptyfd 5
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug1: session_pty_req: session
0 alloc /dev/pts/2
server_input_channel_req: channel 0 request shell reply 1
session 0 channel 0
session_input_channel_req: session 0 req shell
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: Starting session: shell on pts/2
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 3 setting TCP_NODELAY
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: packet_set_tos: set
IP_TOS 0x10
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: channel 0: rfd 14 isatty
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug2: fd 14 setting O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13761]: debug3: fd 12 is O_NONBLOCK
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug1: Setting controlling tty
using TIOCSCTTY.
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: mm_request_send
entering: type 124
mm_request_receive_expect entering: type 125
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13762]: debug3: mm_request_receive
entering
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: monitor_read: checking
request 124
Mar 30 13:33:47 mid-ipa-vp01 sshd[13750]: debug3: mm_request_send
entering: type 125
KRB5CCNAME=FILE:/tmp/krb5cc_1398410_B30vDK
SELINUX_ROLE_REQUESTED=
SELINUX_LEVEL_REQUESTED=
SELINUX_USE_CURRENT_RANGE=
XDG_SESSION_ID=10
XDG_RUNTIME_DIR=/run/user/1398410
Just in case, here is my krb5.conf
includedir /var/lib/sss/pubconf/krb5.include.d/
[logging]
default = FILE:/var/log/krb5libs.log
kdc = FILE:/var/log/krb5kdc.log
admin_server = FILE:/var/log/kadmind.log
[libdefaults]
default_realm = UNIX.TEST.OSUWMC
dns_lookup_realm = true
dns_lookup_kdc = true
rdns = false
ticket_lifetime = 24h
forwardable = yes
udp_preference_limit = 0
# default_ccache_name = KEYRING:persistent:%{uid}
[realms]
UNIX.TEST.OSUWMC = {
kdc = mid-ipa-vp01.unix.test.osuwmc:88
master_kdc = mid-ipa-vp01.unix.test.osuwmc:88
admin_server = mid-ipa-vp01.unix.test.osuwmc:749
default_domain = unix.test.osuwmc
pkinit_anchors = FILE:/etc/ipa/ca.crt
# auth_to_local =
# auth_to_local = RULE:[1:$1 $0](^ *
auth_to_local = DEFAULT
}
[domain_realm]
.unix.test.osuwmc = UNIX.TEST.OSUWMC
unix.test.osuwmc = UNIX.TEST.OSUWMC
[dbmodules]
UNIX.TEST.OSUWMC = {
db_library = ipadb.so
}
I'm not sure if this would be of any help to you, but in case you have
GSSAPI credential delegation enabled in PuTTY, you also need to allow them
$ ipa host-mod <ipa server fqdn> --ok-as-delegate=1
This is only needed if you want that your Kerberos credentials (the TGT) are
forwarded from the Windows client to the IPA client so that you can use
them to access kerberized services from the IPA client as well without
the need to call kinit.

This is not needed for authentication because here only the service
ticket is send to the IPA client and not the TGT.

Can you do the follwoing checks:

Can you check by calling klist in a Windows Command window if you got
a proper host/... ticket for the IPA host?

What version of IPA and SSSD are you using.

Can you check if the following works on a IPA host:

kinit adm-***@TEST.OSUWMC
kvno host/name.of.the.ipa-***@IPA.REALM
ssh -v -l adm-***@test.osuwmc name.of.the.ipa-client.to.login

The error messages return by the ssh -v output might help to see why
GSSAPI auth failed.

bye,
Sumit
Post by Jan Cholasta
Honza
--
Jan Cholasta
--
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Gould, Joshua
2015-03-31 14:02:37 UTC
Permalink
Klist in Windows showed one ticket for the IPA domain.

#0> Client: adm-faru03 @ test.osuwmc
Server: krbtgt/UNIX.TEST.OSUWMC @ TEST.OSUWMC
KerbTicket Encryption Type: AES-256-CTS-HMAC-SHA1-96
Ticket Flags 0x40a40000 -> forward able renewable pre_authent
ok_as_delegate
Start Time: 3/31/2015: 9:29:25 (local)
End Time: 3/31/2015: 15:28:22 (local)
Session Key Type: AES-256-CTS-HMAC-SHA1-96

IPA and SSSD are:
ipa-server.x86_64
4.1.0-18.el7_1.3
sssd.x86_64
1.12.2-58.el7_1.6.1

Kinit adm-***@TEST.OSUWMC was telling. Once it reported ³kinit: KDC
reply did not match expectations while getting initial credentials². We
waited a minute or two (were discussing results) and tried again just
adding the -V flag and it worked.
Post by Sumit Bose
Can you check by calling klist in a Windows Command window if you got
a proper host/... ticket for the IPA host?
What version of IPA and SSSD are you using.
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Gould, Joshua
2015-03-31 14:03:16 UTC
Permalink
Putty error was:

Event Log: GSSAPI authentication initialisation failed
Event Log: No authority could be contacted for authentication.The domain
name of the authenticating party could be wrong, the domain could be
unreachable, or there might have been a trust relationship failure.
Post by Gould, Joshua
Klist in Windows showed one ticket for the IPA domain.
KerbTicket Encryption Type: AES-256-CTS-HMAC-SHA1-96
Ticket Flags 0x40a40000 -> forward able renewable pre_authent
ok_as_delegate
Start Time: 3/31/2015: 9:29:25 (local)
End Time: 3/31/2015: 15:28:22 (local)
Session Key Type: AES-256-CTS-HMAC-SHA1-96
ipa-server.x86_64
4.1.0-18.el7_1.3
sssd.x86_64
1.12.2-58.el7_1.6.1
reply did not match expectations while getting initial credentials². We
waited a minute or two (were discussing results) and tried again just
adding the -V flag and it worked.
Post by Sumit Bose
Can you check by calling klist in a Windows Command window if you got
a proper host/... ticket for the IPA host?
What version of IPA and SSSD are you using.
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info
Sumit Bose
2015-03-31 14:40:49 UTC
Permalink
Post by Gould, Joshua
Klist in Windows showed one ticket for the IPA domain.
KerbTicket Encryption Type: AES-256-CTS-HMAC-SHA1-96
Ticket Flags 0x40a40000 -> forward able renewable pre_authent
ok_as_delegate
Start Time: 3/31/2015: 9:29:25 (local)
End Time: 3/31/2015: 15:28:22 (local)
Session Key Type: AES-256-CTS-HMAC-SHA1-96
The means that you do not have a ticket for the IPA client. Please make
sure you use 'mid-ipa-vp01.unix.test.osuwmc' as hostname with putty.

Since the AD DC gave you the cross-realm TGT (the ticket you've shown
above) I would expect that you Windows client has issues resolving a KDC
in the IPA domain. Please check on the Windows client with the nslookup
utility you DNS SRV records like

_kerberos._tcp.dc._msdcs.unix.test.osuwmc

and

_kerberos._tcp.unix.test.osuwmc

can be resolved.
Post by Gould, Joshua
ipa-server.x86_64
4.1.0-18.el7_1.3
sssd.x86_64
1.12.2-58.el7_1.6.1
reply did not match expectations while getting initial credentials². We
waited a minute or two (were discussing results) and tried again just
adding the -V flag and it worked.
Which errors do you see when using ssh in the IPA client after calling
kinit? Or is it working in this case?

bye,
Sumit
Post by Gould, Joshua
Post by Sumit Bose
Can you check by calling klist in a Windows Command window if you got
a proper host/... ticket for the IPA host?
What version of IPA and SSSD are you using.
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Gould, Joshua
2015-04-07 20:17:30 UTC
Permalink
On 4/6/15, 2:26 PM, "Gould, Joshua" <***@osumc.edu> wrote:

On 4/4/15, 9:57 AM, "Sumit Bose" <***@redhat.com> wrote:

Really strange but SSO is working from the test Windows box to both the
IPA server and client. No changes were made other than I added the linux
client to the IPA domain. (It was with ipa-client-install, it
auto-discovered the values, which I used and I enrolled it with the admin
ad-user).

Note: ssh connection from Windows test machine to IPA client and IPA
server used the exact same saved putty config other than changing the
hostname.

SSO from Windows to our two IPA clients seems to work intermittently
today. (no config changes on either end)

In both cases, the first attempted to connect via Putty/SSO failed but
signin to password worked. We then disconnected the ssh session and
immediately tried SSO via SSH to the same client SSO worked. We were able
to replicate this for both clients.

SSH output from the failed SSO logins: (Sorry but the kvno and other
command were not captured)

To Test Client01:
-sh-4.2$ export KRB5_TRACE=/dev/stdout
-sh-4.2$ kinit ad-***@TEST.OSUWMC
[23557] 1428416095.525107: Getting initial credentials for
ad-***@TEST.OSUWMC
[23557] 1428416095.527977: Sending request (170 bytes) to TEST.OSUWMC
[23557] 1428416095.529496: Resolving hostname test-dc-vt01.test.osuwmc.
[23557] 1428416095.530694: Sending initial UDP request to dgram
10.0.0.239:88
[23557] 1428416095.531745: Received answer (187 bytes) from dgram
10.0.0.239:88
[23557] 1428416095.531978: Response was not from master KDC
[23557] 1428416095.532006: Received error from KDC: -1765328359/Additional
pre-authentication required
[23557] 1428416095.532039: Processing preauth types: 16, 15, 19, 2
[23557] 1428416095.532053: Selected etype info: etype aes256-cts, salt
"TEST.OSUWMCad-user", params ""
[23557] 1428416095.532094: PKINIT client has no configured identity;
giving up
[23557] 1428416095.532111: PKINIT client has no configured identity;
giving up
[23557] 1428416095.532122: Preauth module pkinit (16) (real) returned:
22/Invalid argument
[23557] 1428416095.532132: PKINIT client has no configured identity;
giving up
[23557] 1428416095.532139: Preauth module pkinit (14) (real) returned:
22/Invalid argument
Password for ad-***@TEST.OSUWMC:
[23557] 1428416098.700510: AS key obtained for encrypted timestamp:
aes256-cts/BA80
[23557] 1428416098.700574: Encrypted timestamp (for 1428416098.622522):
plain 301AA011180F32303135303430373134313435385AA1050203097FBA, encrypted
DDE7C80B8F1F1B5877E7E05764895E024E65D83CA6BFB633E4281384E03D60F27AB6A6EDF68
C161720933FD481FF881BE203238F816D4393
[23557] 1428416098.700600: Preauth module encrypted_timestamp (2) (real)
returned: 0/Success
[23557] 1428416098.700605: Produced preauth for next request: 2
[23557] 1428416098.700626: Sending request (248 bytes) to TEST.OSUWMC
[23557] 1428416098.701350: Resolving hostname test-dc-vt01.test.osuwmc.
[23557] 1428416098.701661: Sending initial UDP request to dgram
10.0.0.239:88
[23557] 1428416098.703161: Received answer (94 bytes) from dgram
10.0.0.239:88
[23557] 1428416098.703374: Response was not from master KDC
[23557] 1428416098.703397: Received error from KDC: -1765328332/Response
too big for UDP, retry with TCP
[23557] 1428416098.703403: Request or response is too big for UDP;
retrying with TCP
[23557] 1428416098.703408: Sending request (248 bytes) to TEST.OSUWMC (tcp
only)
[23557] 1428416098.703735: Resolving hostname test-dc-vt01.test.osuwmc.
[23557] 1428416098.704667: Initiating TCP connection to stream
10.0.0.239:88
[23557] 1428416098.705090: Sending TCP request to stream 10.0.0.239:88
[23557] 1428416098.706260: Received answer (1649 bytes) from stream
10.0.0.239:88
[23557] 1428416098.706268: Terminating TCP connection to stream
10.0.0.239:88
[23557] 1428416098.706486: Response was not from master KDC
[23557] 1428416098.706522: Processing preauth types: 19
[23557] 1428416098.706530: Selected etype info: etype aes256-cts, salt
"TEST.OSUWMCad-user", params ""
[23557] 1428416098.706538: Produced preauth for next request: (empty)
[23557] 1428416098.706546: AS key determined by preauth: aes256-cts/BA80
[23557] 1428416098.706600: Decrypted AS reply; session key is:
aes256-cts/21BF
[23557] 1428416098.706605: FAST negotiation: unavailable
[23557] 1428416098.706629: Initializing
KEYRING:persistent:2398410:krb_ccache_v8K2ML2 with default princ
ad-***@TEST.OSUWMC
[23557] 1428416098.706675: Removing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23557] 1428416098.706683: Storing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC in
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23557] 1428416098.706754: Storing config in
KEYRING:persistent:2398410:krb_ccache_v8K2ML2 for
krbtgt/***@TEST.OSUWMC: pa_type: 2
[23557] 1428416098.706771: Removing ad-***@TEST.OSUWMC ->
krb5_ccache_conf_data/pa_type/krbtgt\/TEST.OSUWMC\@***@X-CACHECONF:
from KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23557] 1428416098.706778: Storing ad-***@TEST.OSUWMC ->
krb5_ccache_conf_data/pa_type/krbtgt\/TEST.OSUWMC\@***@X-CACHECONF:
in KEYRING:persistent:2398410:krb_ccache_v8K2ML2
-sh-4.2$ kvno host/ipa-***@UNIX.TEST.OSUWMC
[23558] 1428416110.253431: Getting credentials ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC using ccache
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23558] 1428416110.253762: Retrieving ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_v8K2ML2 with result:
-1765328243/Matching credential not found
[23558] 1428416110.253818: Retrieving ad-***@TEST.OSUWMC ->
krbtgt/***@UNIX.TEST.OSUWMCfrom
KEYRING:persistent:2398410:krb_ccache_v8K2ML2 with result:
-1765328243/Matching credential not found
[23558] 1428416110.253884: Retrieving ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_v8K2ML2 with result: 0/Success
[23558] 1428416110.253893: Starting with TGT for client realm:
ad-***@TEST.OSUWMC -> krbtgt/***@TEST.OSUWMC
[23558] 1428416110.253938: Retrieving ad-***@TEST.OSUWMC ->
krbtgt/***@UNIX.TEST.OSUWMCfrom
KEYRING:persistent:2398410:krb_ccache_v8K2ML2 with result:
-1765328243/Matching credential not found
[23558] 1428416110.253950: Requesting TGT
krbtgt/***@TEST.OSUWMC using TGT
krbtgt/***@TEST.OSUWMC
[23558] 1428416110.253993: Generated subkey for TGS request:
aes256-cts/254A
[23558] 1428416110.254042: etypes requested in TGS request: aes256-cts,
aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[23558] 1428416110.254198: Encoding request body and padata into FAST
request
[23558] 1428416110.254278: Sending request (1847 bytes) to TEST.OSUWMC
[23558] 1428416110.255292: Resolving hostname test-dc-vt01.test.osuwmc.
[23558] 1428416110.255979: Sending initial UDP request to dgram
10.0.0.239:88
[23558] 1428416110.257177: Received answer (99 bytes) from dgram
10.0.0.239:88
[23558] 1428416110.257431: Response was not from master KDC
[23558] 1428416110.257454: Request or response is too big for UDP;
retrying with TCP
[23558] 1428416110.257460: Sending request (1847 bytes) to TEST.OSUWMC
(tcp only)
[23558] 1428416110.257728: Resolving hostname test-dc-vt02.test.osuwmc.
[23558] 1428416110.258043: Initiating TCP connection to stream
10.0.0.240:88
[23558] 1428416110.258388: Sending TCP request to stream 10.0.0.240:88
[23558] 1428416110.259470: Received answer (1581 bytes) from stream
10.0.0.240:88
[23558] 1428416110.259479: Terminating TCP connection to stream
10.0.0.240:88
[23558] 1428416110.259733: Response was not from master KDC
[23558] 1428416110.259763: Decoding FAST response
[23558] 1428416110.259866: TGS reply is for ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMCwith session key aes256-cts/B18C
[23558] 1428416110.259892: TGS request result: 0/Success
[23558] 1428416110.259902: Removing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23558] 1428416110.259909: Storing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC in
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23558] 1428416110.259993: Received TGT for service realm:
krbtgt/***@TEST.OSUWMC
[23558] 1428416110.260000: Requesting tickets for
host/ipa-***@UNIX.TEST.OSUWMC, referrals on
[23558] 1428416110.260017: Generated subkey for TGS request:
aes256-cts/7B9B
[23558] 1428416110.260048: etypes requested in TGS request: aes256-cts,
aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[23558] 1428416110.260112: Encoding request body and padata into FAST
request
[23558] 1428416110.260175: Sending request (1883 bytes) to
UNIX.TEST.OSUWMC (tcp only)
[23558] 1428416110.260222: Initiating TCP connection to stream
10.127.26.73:88
[23558] 1428416110.260275: Sending TCP request to stream 10.127.26.73:88
[23558] 1428416110.270716: Received answer (1837 bytes) from stream
10.127.26.73:88
[23558] 1428416110.270731: Terminating TCP connection to stream
10.127.26.73:88
[23558] 1428416110.270787: Response was from master KDC
[23558] 1428416110.270802: Decoding FAST response
[23558] 1428416110.270883: FAST reply key: aes256-cts/84BD
[23558] 1428416110.270917: TGS reply is for ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC with session key
aes256-cts/52FE
[23558] 1428416110.270938: TGS request result: 0/Success
[23558] 1428416110.270943: Received creds for desired service
host/ipa-***@UNIX.TEST.OSUWMC
[23558] 1428416110.270951: Removing ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
[23558] 1428416110.270958: Storing ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC in
KEYRING:persistent:2398410:krb_ccache_v8K2ML2
host/ipa-***@UNIX.TEST.OSUWMC: kvno = 2
-sh-4.2$ ssh -v -l ad-***@test.osuwmc ipa-vp01.unix.test.osuwmc
OpenSSH_6.6.1, OpenSSL 1.0.1e-fips 11 Feb 2013
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 56: Applying options for *
debug1: Executing proxy command: exec /usr/bin/sss_ssh_knownhostsproxy -p
22 ipa-vp01.unix.test.osuwmc
debug1: SELinux support enabled
debug1: permanently_drop_suid: 2398410
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_rsa type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_rsa-cert type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_dsa type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_dsa-cert type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ecdsa type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ecdsa-cert type
-1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ed25519 type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ed25519-cert
type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1
debug1: Remote protocol version 2.0, remote software version OpenSSH_6.6.1
debug1: match: OpenSSH_6.6.1 pat OpenSSH_6.6.1* compat 0x04000000
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5-***@openssh.com none
debug1: kex: client->server aes128-ctr hmac-md5-***@openssh.com none
debug1: kex: curve25519-***@libssh.org need=16 dh_need=16
debug1: kex: curve25519-***@libssh.org need=16 dh_need=16
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA
a2:57:a3:0f:09:87:d3:de:d5:9f:34:30:55:7b:2b:2f
The authenticity of host 'ipa-vp01.unix.test.osuwmc (<no hostip for
proxy command>)' can't be established.
ECDSA key fingerprint is a2:57:a3:0f:09:87:d3:de:d5:9f:34:30:55:7b:2b:2f.
Are you sure you want to continue connecting (yes/no)?
Host key verification failed.
-sh-4.2$


To Test Client 02:
-sh-4.2$ export KRB5_TRACE=/dev/stdout
-sh-4.2$ kinit ad-***@TEST.OSUWMC
[18737] 1428416089.475861: Getting initial credentials for
ad-***@TEST.OSUWMC
[18737] 1428416089.476283: Sending request (170 bytes) to TEST.OSUWMC
[18737] 1428416089.478142: Resolving hostname test-dc-vt01.test.osuwmc.
[18737] 1428416089.479506: Sending initial UDP request to dgram
10.0.0.239:88
[18737] 1428416089.481046: Received answer (187 bytes) from dgram
10.0.0.239:88
[18737] 1428416089.481416: Response was not from master KDC
[18737] 1428416089.481449: Received error from KDC: -1765328359/Additional
pre-authentication required
[18737] 1428416089.481502: Processing preauth types: 16, 15, 19, 2
[18737] 1428416089.481520: Selected etype info: etype aes256-cts, salt
"TEST.OSUWMCad-user", params ""
Password for ad-***@TEST.OSUWMC:
[18737] 1428416093.323345: AS key obtained for encrypted timestamp:
aes256-cts/BA80
[18737] 1428416093.323414: Encrypted timestamp (for 1428416093.258716):
plain 301AA011180F32303135303430373134313435335AA105020303F29C, encrypted
87E3A643A6E79049617EB83F143B6EA7A4D81E938FD9F1554BF168FB217D46A4D622D47E6CD
5A18F82835113BA3109900EACBBDEAEAE023E
[18737] 1428416093.323443: Preauth module encrypted_timestamp (2) (real)
returned: 0/Success
[18737] 1428416093.323448: Produced preauth for next request: 2
[18737] 1428416093.323569: Sending request (248 bytes) to TEST.OSUWMC
[18737] 1428416093.324696: Resolving hostname test-dc-vt02.test.osuwmc.
[18737] 1428416093.325245: Sending initial UDP request to dgram
10.0.0.240:88
[18737] 1428416093.328637: Received answer (94 bytes) from dgram
10.0.0.240:88
[18737] 1428416093.328999: Response was not from master KDC
[18737] 1428416093.329024: Received error from KDC: -1765328332/Response
too big for UDP, retry with TCP
[18737] 1428416093.329030: Request or response is too big for UDP;
retrying with TCP
[18737] 1428416093.329035: Sending request (248 bytes) to TEST.OSUWMC (tcp
only)
[18737] 1428416093.329431: Resolving hostname test-dc-vt02.test.osuwmc.
[18737] 1428416093.330588: Initiating TCP connection to stream
10.0.0.240:88
[18737] 1428416093.331004: Sending TCP request to stream 10.0.0.240:88
[18737] 1428416093.332070: Received answer (1649 bytes) from stream
10.0.0.240:88
[18737] 1428416093.332079: Terminating TCP connection to stream
10.0.0.240:88
[18737] 1428416093.332468: Response was not from master KDC
[18737] 1428416093.332523: Processing preauth types: 19
[18737] 1428416093.332532: Selected etype info: etype aes256-cts, salt
"TEST.OSUWMCad-user", params ""
[18737] 1428416093.332539: Produced preauth for next request: (empty)
[18737] 1428416093.332548: AS key determined by preauth: aes256-cts/BA80
[18737] 1428416093.332601: Decrypted AS reply; session key is:
aes256-cts/82EC
[18737] 1428416093.332605: FAST negotiation: unavailable
[18737] 1428416093.332630: Initializing
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with default princ
ad-***@TEST.OSUWMC
[18737] 1428416093.332683: Removing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18737] 1428416093.332692: Storing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC in
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18737] 1428416093.332764: Storing config in
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 for
krbtgt/***@TEST.OSUWMC: pa_type: 2
[18737] 1428416093.332782: Removing ad-***@TEST.OSUWMC ->
krb5_ccache_conf_data/pa_type/krbtgt\/TEST.OSUWMC\@***@X-CACHECONF:
from KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18737] 1428416093.332790: Storing ad-***@TEST.OSUWMC ->
krb5_ccache_conf_data/pa_type/krbtgt\/TEST.OSUWMC\@***@X-CACHECONF:
in KEYRING:persistent:2398410:krb_ccache_6FRGCV2
-sh-4.2$ kvno host/ipa-***@UNIX.TEST.OSUWMC
[18738] 1428416107.49615: Getting credentials ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC using ccache
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18738] 1428416107.49815: Retrieving ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with result:
-1765328243/Matching credential not found
[18738] 1428416107.49865: Retrieving ad-***@TEST.OSUWMC ->
krbtgt/***@UNIX.TEST.OSUWMCfrom
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with result:
-1765328243/Matching credential not found
[18738] 1428416107.49928: Retrieving ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with result: 0/Success
[18738] 1428416107.49937: Starting with TGT for client realm:
ad-***@TEST.OSUWMC -> krbtgt/***@TEST.OSUWMC
[18738] 1428416107.49977: Retrieving ad-***@TEST.OSUWMC ->
krbtgt/***@UNIX.TEST.OSUWMCfrom
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with result:
-1765328243/Matching credential not found
[18738] 1428416107.49985: Requesting TGT
krbtgt/***@TEST.OSUWMC using TGT
krbtgt/***@TEST.OSUWMC
[18738] 1428416107.50025: Generated subkey for TGS request: aes256-cts/F437
[18738] 1428416107.50074: etypes requested in TGS request: aes256-cts,
aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[18738] 1428416107.50201: Encoding request body and padata into FAST
request
[18738] 1428416107.50272: Sending request (1847 bytes) to TEST.OSUWMC
[18738] 1428416107.51530: Resolving hostname test-dc-vt01.test.osuwmc.
[18738] 1428416107.52259: Sending initial UDP request to dgram
10.0.0.239:88
[18738] 1428416107.53561: Received answer (99 bytes) from dgram
10.0.0.239:88
[18738] 1428416107.53964: Response was not from master KDC
[18738] 1428416107.53985: Request or response is too big for UDP; retrying
with TCP
[18738] 1428416107.53990: Sending request (1847 bytes) to TEST.OSUWMC (tcp
only)
[18738] 1428416107.54364: Resolving hostname test-dc-vt01.test.osuwmc.
[18738] 1428416107.54756: Initiating TCP connection to stream
10.0.0.239:88
[18738] 1428416107.55031: Sending TCP request to stream 10.0.0.239:88
[18738] 1428416107.56052: Received answer (1581 bytes) from stream
10.0.0.239:88
[18738] 1428416107.56063: Terminating TCP connection to stream
10.0.0.239:88
[18738] 1428416107.56436: Response was not from master KDC
[18738] 1428416107.56495: Decoding FAST response
[18738] 1428416107.56567: TGS reply is for ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMCwith session key aes256-cts/7E5C
[18738] 1428416107.56589: TGS request result: 0/Success
[18738] 1428416107.56598: Removing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18738] 1428416107.56605: Storing ad-***@TEST.OSUWMC ->
krbtgt/***@TEST.OSUWMC in
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18738] 1428416107.56680: Received TGT for service realm:
krbtgt/***@TEST.OSUWMC
[18738] 1428416107.56687: Requesting tickets for
host/ipa-***@UNIX.TEST.OSUWMC, referrals on
[18738] 1428416107.56702: Generated subkey for TGS request: aes256-cts/5751
[18738] 1428416107.56734: etypes requested in TGS request: aes256-cts,
aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
[18738] 1428416107.56787: Encoding request body and padata into FAST
request
[18738] 1428416107.56845: Sending request (1883 bytes) to UNIX.TEST.OSUWMC
(tcp only)
[18738] 1428416107.56892: Initiating TCP connection to stream
10.127.26.73:88
[18738] 1428416107.57108: Sending TCP request to stream 10.127.26.73:88
[18738] 1428416107.72793: Received answer (1837 bytes) from stream
10.127.26.73:88
[18738] 1428416107.72806: Terminating TCP connection to stream
10.127.26.73:88
[18738] 1428416107.72874: Response was from master KDC
[18738] 1428416107.72892: Decoding FAST response
[18738] 1428416107.73008: FAST reply key: aes256-cts/24D0
[18738] 1428416107.73047: TGS reply is for ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC with session key
aes256-cts/7A6C
[18738] 1428416107.73071: TGS request result: 0/Success
[18738] 1428416107.73075: Received creds for desired service
host/ipa-***@UNIX.TEST.OSUWMC
[18738] 1428416107.73083: Removing ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18738] 1428416107.73090: Storing ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC in
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
host/ipa-***@UNIX.TEST.OSUWMC: kvno = 2
-sh-4.2$ ssh -v -l ad-***@test.osuwmc ipa-vp01.unix.test.osuwmc
OpenSSH_6.6.1, OpenSSL 1.0.1e-fips 11 Feb 2013
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 56: Applying options for *
debug1: Executing proxy command: exec /usr/bin/sss_ssh_knownhostsproxy -p
22 ipa-vp01.unix.test.osuwmc
debug1: SELinux support enabled
Could not create directory '/home/test.osuwmc/ad-user/.ssh'.
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_rsa type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_rsa-cert type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_dsa type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_dsa-cert type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ecdsa type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ecdsa-cert type
-1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ed25519 type -1
debug1: identity file /home/test.osuwmc/ad-user/.ssh/id_ed25519-cert
type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1
debug1: permanently_drop_suid: 2398410
debug1: Remote protocol version 2.0, remote software version OpenSSH_6.6.1
debug1: match: OpenSSH_6.6.1 pat OpenSSH_6.6.1* compat 0x04000000
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5-***@openssh.com none
debug1: kex: client->server aes128-ctr hmac-md5-***@openssh.com none
debug1: kex: curve25519-***@libssh.org need=16 dh_need=16
debug1: kex: curve25519-***@libssh.org need=16 dh_need=16
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA
a2:57:a3:0f:09:87:d3:de:d5:9f:34:30:55:7b:2b:2f
debug1: Host 'ipa-vp01.unix.test.osuwmc' is known and matches the
ECDSA host key.
debug1: Found key in /var/lib/sss/pubconf/known_hosts:1
debug1: ssh_ecdsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue:
publickey,gssapi-keyex,gssapi-with-mic,password
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug1: Next authentication method: gssapi-with-mic
[18739] 1428416121.60316: Convert service host (service with host as
instance) on host ipa-vp01.unix.test.osuwmc to principal
[18739] 1428416121.63528: Remote host after forward canonicalization:
ipa-vp01.unix.test.osuwmc
[18739] 1428416121.63576: Remote host after reverse DNS processing:
ipa-vp01.unix.test.osuwmc
[18739] 1428416121.63615: Got service principal
host/ipa-***@UNIX.TEST.OSUWMC
[18739] 1428416121.64537: ccselect can't find appropriate cache for server
principal host/ipa-***@UNIX.TEST.OSUWMC
[18739] 1428416121.64660: Getting credentials ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC using ccache
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18739] 1428416121.64760: Retrieving ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with result: 0/Success
[18739] 1428416121.64860: Creating authenticator for
ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC, seqnum 357380851,
subkey aes256-cts/C722, session key aes256-cts/7A6C
[18739] 1428416121.68510: Convert service host (service with host as
instance) on host ipa-vp01.unix.test.osuwmc to principal
[18739] 1428416121.69117: Remote host after forward canonicalization:
ipa-vp01.unix.test.osuwmc
[18739] 1428416121.69131: Remote host after reverse DNS processing:
ipa-vp01.unix.test.osuwmc
[18739] 1428416121.69144: Got service principal
host/ipa-***@UNIX.TEST.OSUWMC
[18739] 1428416121.69854: ccselect can't find appropriate cache for server
principal host/ipa-***@UNIX.TEST.OSUWMC
[18739] 1428416121.69921: Getting credentials ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC using ccache
KEYRING:persistent:2398410:krb_ccache_6FRGCV2
[18739] 1428416121.69983: Retrieving ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC from
KEYRING:persistent:2398410:krb_ccache_6FRGCV2 with result: 0/Success
[18739] 1428416121.70043: Creating authenticator for
ad-***@TEST.OSUWMC ->
host/ipa-***@UNIX.TEST.OSUWMC, seqnum 103136204,
subkey aes256-cts/1442, session key aes256-cts/7A6C
[18739] 1428416123.217669: Convert service host (service with host as
instance) on host ipa-vp01.unix.test.osuwmc to principal
[18739] 1428416123.218358: Remote host after forward canonicalization:
ipa-vp01.unix.test.osuwmc
[18739] 1428416123.218373: Remote host after reverse DNS processing:
ipa-vp01.unix.test.osuwmc
[18739] 1428416123.218392: Got service principal
host/ipa-***@UNIX.TEST.OSUWMC
[18739] 1428416123.218509: Read AP-REP, time 1428416121.70050, subkey
aes256-cts/519A, seqnum 855383497
debug1: Authentication succeeded (gssapi-with-mic).
Authenticated to ipa-vp01.unix.test.osuwmc (via proxy).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-***@openssh.com
debug1: Entering interactive session.
debug1: Sending environment.
debug1: Sending env LANG = en_US.UTF-8
Last login: Tue Apr 7 10:14:30 2015 from 10.0.5
-sh-4.2$
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
Continue reading on narkive:
Loading...