[Freeipa-users] Debugging failed password checks (SSH) for AD users at the other end of 1-way trusts

[Sumit Bose]

On Tue, Dec 06, 2016 at 03:17:33PM -0500, List dedicated to discussions about use, configuration and deployment of the IPA server. wrote:
> 
> Appreciate the assistance!
> 
> Is there a better debug level balance than 10 for this sort of situation?
> The domain logs were several hundred MBs by the time I started looking for
> useful info if there is a different level I can use that would better at
> producing actionable error/log messages I'll gladly switch ...
> 
> 
> List dedicated to discussions about use, configuration and deployment of the
> IPA server. wrote:
> > > (Tue Dec  6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [main] (0x0400):
> > > >  krb5_child started.
> > > >  (Tue Dec  6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [unpack_buffer]
> > > >  (0x1000): total buffer size: [158]
> > > >  (Tue Dec  6 15:36:48 2016) [[sssd[krb5_child[4005]]]] [unpack_buffer]
> > > >  (0x0100): cmd [241] uid [1843770609] gid [1843770609] validate [false]
> > > >  enterprise principal [false] offline [true] UPN [user at COMPANY.ORG]
> > 
> >                                ^^^^^^^^^^^^^^^
> > 
> > The backend switch to offline mode, please send the SSSD domain logs
> > around this time as well. If possible please start about 5 minutes
> > earlier.
> > 
> > bye,
> > Sumit
> 
> I searched through the massive SSSD domain logs and had trouble finding the
> right area so here are the lines surrounding my own username when I tried to
> authenticate via SSH using AD credentials:
> 
> 
...
> 
...
> [sss_krb5_expire_callback_func] (0x2000): exp_time: [2742397]
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [get_and_save_tgt]
> (0x0100): TGT validation is disabled.
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]]
> [sss_get_ccache_name_for_principal] (0x4000): Location:
> [KEYRING:persistent:1843770609]
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]]
> [sss_get_ccache_name_for_principal] (0x4000): tmp_ccname:
> [KEYRING:persistent:1843770609:krb_ccache_OVBc5zF]
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [create_ccache]
> (0x4000): Initializing ccache of type [KEYRING]
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [create_ccache]
> (0x4000): CC supports switch
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [create_ccache]
> (0x4000): returning: 0
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]]
> [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the
> same, none will be deleted.
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [k5c_send_data]
> (0x0200): Received error code 0
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]]
> [pack_response_packet] (0x2000): response packet size: [144]
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [k5c_send_data]
> (0x4000): Response sent.
> (Tue Dec  6 19:57:11 2016) [[sssd[krb5_child[12406]]]] [main] (0x0400):
> krb5_child completed successfully
...
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]]
> [sss_krb5_expire_callback_func] (0x2000): exp_time: [2742394]
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [get_and_save_tgt]
> (0x0100): TGT validation is disabled.
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]]
> [sss_get_ccache_name_for_principal] (0x4000): Location:
> [KEYRING:persistent:1843770609]
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]]
> [sss_get_ccache_name_for_principal] (0x4000): tmp_ccname:
> [KEYRING:persistent:1843770609:krb_ccache_OVBc5zF]
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [create_ccache]
> (0x4000): Initializing ccache of type [KEYRING]
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [create_ccache]
> (0x4000): CC supports switch
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [create_ccache]
> (0x4000): returning: 0
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]]
> [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the
> same, none will be deleted.
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [k5c_send_data]
> (0x0200): Received error code 0
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]]
> [pack_response_packet] (0x2000): response packet size: [144]
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [k5c_send_data]
> (0x4000): Response sent.
> (Tue Dec  6 19:57:14 2016) [[sssd[krb5_child[12417]]]] [main] (0x0400):
> krb5_child completed successfully
> 
> 

Both authentications where successful against the backend. For the logs
it looks like you use an alternative domain suffix on the AD side so
that all user if other domains in the forest can use the forest root
suffix as realm, in the user principal (user at NAFTA.COMPANY.ORG ->
user at COMPANY.ORG).

I would expect that there are messages like "UPN used in the request
...differ by more than just the case." in the domain log at 'Tue Dec  6
19:57:11' and 'Tue Dec  6 19:57:14'.

If that's the case updating to 4.4 would help because in this release
IPA can forward the enterprise principals properly and SSSD will not
reject the changed principal because sSSD will be aware of the change.

But there are workarounds to make it work with your version as well,
please see e.g. the suggestion from
https://www.redhat.com/archives/freeipa-users/2016-May/msg00205.html .

HTH

bye,
Sumit