Bug 1125294 - "Mapping ID [4294967295] to SID failed" messages clutter the sssd domain log
Summary: "Mapping ID [4294967295] to SID failed" messages clutter the sssd domain log
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: sssd
Version: 6.6
Hardware: Unspecified
OS: Unspecified
low
medium
Target Milestone: rc
: ---
Assignee: Jakub Hrozek
QA Contact: Kaushik Banerjee
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-07-31 13:57 UTC by Kaushik Banerjee
Modified: 2014-08-19 14:43 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-08-19 11:49:53 UTC


Attachments (Terms of Use)
domain log since restarting sssd (161.87 KB, text/plain)
2014-08-06 09:38 UTC, Kaushik Banerjee
no flags Details

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.


Note You need to log in before you can comment on or make changes to this bug.