Bug 1125294

Summary: "Mapping ID [4294967295] to SID failed" messages clutter the sssd domain log
Product: Red Hat Enterprise Linux 6 Reporter: Kaushik Banerjee <kbanerje>
Component: sssdAssignee: Jakub Hrozek <jhrozek>
Status: CLOSED NOTABUG QA Contact: Kaushik Banerjee <kbanerje>
Severity: medium Docs Contact:
Priority: low    
Version: 6.6CC: grajaiya, jgalipea, kbanerje, lslebodn, mkosek, pbrezina, preichl
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-08-19 11:49:53 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
domain log since restarting sssd none

Description Kaushik Banerjee 2014-07-31 13:57:01 UTC 
Description of problem:
"Mapping ID [4294967295] to SID failed" messages clutter the sssd domain log

Version-Release number of selected component (if applicable):
sssd-1.11.6-12.el6

How reproducible:
Always

Steps to Reproduce:
1. Configure sssd with ad provider and set debug_level=0xfff0
2. start sssd.
3. Probably lookup a user or even don't do anything.
4. Observe the domain log

Actual results:
The domain logs are constantly cluttered with the following messages:
(Thu Jul 31 04:44:37 2014) [sssd[be[sssdad.com]]] [ad_account_can_shortcut] (0x0080): Mapping ID [4294967295] to SID failed: [IDMAP domain not found]
(Thu Jul 31 04:44:37 2014) [sssd[be[sssdad.com]]] [ad_account_info_handler] (0x0400): Cannot determine the right domain: Input/output error
(Thu Jul 31 04:44:37 2014) [sssd[be[sssdad.com]]] [users_get_send] (0x0080): [4294967295] did not match any configured ID mapping domain
(Thu Jul 31 04:44:37 2014) [sssd[be[sssdad.com]]] [users_get_send] (0x0080): [4294967295] did not match any configured ID mapping domain

Expected results:
Can we suppress these messages from cluttering up the logs?

Additional info:
Comment 2 Lukas Slebodnik 2014-08-05 14:28:09 UTC 
ID 4294967295 is in hexadecimal representation 0xffffffff. It is possible that -1 was returned from some function. Could you attach log files with high debug_level?
Comment 3 Jakub Hrozek 2014-08-05 20:09:36 UTC 
(In reply to Lukas Slebodnik from comment #2)
> ID 4294967295 is in hexadecimal representation 0xffffffff. It is possible
> that -1 was returned from some function. Could you attach log files with
> high debug_level?

I think this is the nobody or nfsnobody user. sssd_nss would help, but I think we should silence the debug message a bit either way.

special-casing -1 would be an option, too!
Comment 4 Jakub Hrozek 2014-08-06 07:48:03 UTC 
Setting needinfo as Lukas asked for the logs.
Comment 5 Kaushik Banerjee 2014-08-06 09:38:47 UTC 
Created attachment 924417 [details]
domain log since restarting sssd

The attached domain log shows the error messages.

Please note that I had only restarted sssd. Did not perform any activities on the system after restarting sssd.
Comment 6 Jakub Hrozek 2014-08-12 10:41:51 UTC 
Upstream ticket:
https://fedorahosted.org/sssd/ticket/2403
Comment 7 Lukas Slebodnik 2014-08-14 09:10:50 UTC 
From log files, It is obvious that external application call function getpwuid for uid 4294967295. I cannot say which application called it.

(Wed Aug  6 05:34:22 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][idnumber=4294967295] 
(Wed Aug  6 05:34:22 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][idnumber=4294967295] 
(Wed Aug  6 05:34:22 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][idnumber=4294967295] 
(Wed Aug  6 05:35:22 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][idnumber=4294967295] 
(Wed Aug  6 05:35:22 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][idnumber=4294967295] 
(Wed Aug  6 05:35:22 2014) [sssd[be[sssdad.com]]] [be_get_account_info] (0x0100): Got request for [4097][1][idnumber=4294967295]

The same behaviour can be simulated with executing command "getent passwd 4294967295" and the debug message is expected, because this uid is not in any ID Mapping range. It is not a bug.
Comment 8 Jakub Hrozek 2014-08-19 11:49:53 UTC 
(In reply to Lukas Slebodnik from comment #7)
> The same behaviour can be simulated with executing command "getent passwd
> 4294967295" and the debug message is expected, because this uid is not in
> any ID Mapping range. It is not a bug.

We fixed some of the DEBUG messages upstream. Per comment #7 closing this bugzilla as we don't plan on doing anything more.
Comment 9 Kaushik Banerjee 2014-08-19 11:57:32 UTC 
(In reply to Jakub Hrozek from comment #8)
> We fixed some of the DEBUG messages upstream. Per comment #7 closing this
> bugzilla as we don't plan on doing anything more.

Can you please elaborate on what is the debug message fix? and in which version of sssd does the fix exists?
Comment 10 Lukas Slebodnik 2014-08-19 12:03:17 UTC 
Actually, debug message was not fixed. There is nothing to fix; just debug level for this message was changed from SSSDBG_CONF_SETTINGS to the SSSDBG_FUNC_DATA.
Comment 11 Kaushik Banerjee 2014-08-19 13:16:46 UTC 
So, debug level for be_get_account_info is being changed from 0x0100 to 0x0200 ? If so, do we see this change in sssd-1.12 ?
Comment 12 Jakub Hrozek 2014-08-19 14:43:01 UTC 
(In reply to Kaushik Banerjee from comment #11)
> So, debug level for be_get_account_info is being changed from 0x0100 to
> 0x0200 ? If so, do we see this change in sssd-1.12 ?

Yes, 1.12.1 in particular.