From 1286eaf28ababd2e597812296288d113e11aaeca Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:26:45 +0200 Subject: [PATCH 1/7] s3:winbindd: debug negative idmap cache entries on log level = 1 metze --- source3/winbindd/wb_sid2gid.c | 4 ++-- 1 files changed, 2 insertions(+), 2 deletions(-) diff --git a/source3/winbindd/wb_sid2gid.c b/source3/winbindd/wb_sid2gid.c index cb95191..e427563 100644 --- a/source3/winbindd/wb_sid2gid.c +++ b/source3/winbindd/wb_sid2gid.c @@ -100,8 +100,8 @@ static void wb_sid2gid_lookup_done(struct tevent_req *subreq) if ((type != SID_NAME_DOM_GRP) && (type != SID_NAME_ALIAS) && (type != SID_NAME_WKN_GRP)) { - DEBUG(5, ("Sid %s is not a group.\n", - sid_string_dbg(&state->sid))); + DEBUG(1, ("Sid %s is not a group it's type=0x%X\n", + sid_string_dbg(&state->sid), type)); /* * We have to set the cache ourselves here, the child * which is normally responsible was not queried yet. -- 1.7.4.1 From a9e6a590b22ee21dc98323ef5d3d7933bca3beb9 Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:28:59 +0200 Subject: [PATCH 2/7] s3:winbindd/idmap_util: improve DEBUG messages and lower the log level Things like negative/expired cache entries should appear in the logs without log level = 10... metze --- source3/winbindd/idmap_util.c | 41 +++++++++++++++++++++++------------------ 1 files changed, 23 insertions(+), 18 deletions(-) diff --git a/source3/winbindd/idmap_util.c b/source3/winbindd/idmap_util.c index a44aaf5..b8495a1 100644 --- a/source3/winbindd/idmap_util.c +++ b/source3/winbindd/idmap_util.c @@ -48,11 +48,13 @@ NTSTATUS idmap_uid_to_sid(const char *domname, struct dom_sid *sid, uid_t uid) (unsigned int)uid, expired ? " (expired)": "")); if (expired && idmap_is_online()) { - DEBUG(10, ("revalidating expired entry\n")); + DEBUG(2, ("revalidating expired entry for uid %u => %s\n", + (unsigned int)uid, sid_string_dbg(sid))); goto backend; } if (is_null_sid(sid)) { - DEBUG(10, ("Returning negative cache entry\n")); + DEBUG(2, ("Returning negative cache entry: for uid %u\n", + (unsigned int)uid)); return NT_STATUS_NONE_MAPPED; } DEBUG(10, ("Returning positive cache entry\n")); @@ -66,7 +68,7 @@ backend: ret = idmap_backends_unixid_to_sid(domname, &map); if ( ! NT_STATUS_IS_OK(ret)) { - DEBUG(10, ("error mapping uid [%lu]\n", (unsigned long)uid)); + DEBUG(1, ("error mapping uid [%lu]\n", (unsigned long)uid)); return ret; } @@ -76,7 +78,7 @@ backend: ZERO_STRUCT(null_sid); idmap_cache_set_sid2uid(&null_sid, uid); } - DEBUG(10, ("uid [%lu] not mapped\n", (unsigned long)uid)); + DEBUG(1, ("uid [%lu] not mapped\n", (unsigned long)uid)); return NT_STATUS_NONE_MAPPED; } @@ -107,11 +109,13 @@ NTSTATUS idmap_gid_to_sid(const char *domname, struct dom_sid *sid, gid_t gid) (unsigned int)gid, expired ? " (expired)": "")); if (expired && idmap_is_online()) { - DEBUG(10, ("revalidating expired entry\n")); + DEBUG(2, ("revalidating expired entry git %u => %s\n", + (unsigned int)gid, sid_string_dbg(sid))); goto backend; } if (is_null_sid(sid)) { - DEBUG(10, ("Returning negative cache entry\n")); + DEBUG(2, ("Returning negative cache entry git %u\n", + (unsigned int)gid)); return NT_STATUS_NONE_MAPPED; } DEBUG(10, ("Returning positive cache entry\n")); @@ -125,7 +129,7 @@ backend: ret = idmap_backends_unixid_to_sid(domname, &map); if ( ! NT_STATUS_IS_OK(ret)) { - DEBUG(10, ("error mapping gid [%lu]\n", (unsigned long)gid)); + DEBUG(1, ("error mapping gid [%lu]\n", (unsigned long)gid)); return ret; } @@ -135,7 +139,7 @@ backend: ZERO_STRUCT(null_sid); idmap_cache_set_sid2gid(&null_sid, gid); } - DEBUG(10, ("gid [%lu] not mapped\n", (unsigned long)gid)); + DEBUG(1, ("gid [%lu] not mapped\n", (unsigned long)gid)); return NT_STATUS_NONE_MAPPED; } @@ -165,11 +169,11 @@ NTSTATUS idmap_sid_to_uid(const char *dom_name, struct dom_sid *sid, uid_t *uid) DEBUG(10, ("idmap_cache_find_sid2uid found %d%s\n", (int)(*uid), expired ? " (expired)": "")); if (expired && idmap_is_online()) { - DEBUG(10, ("revalidating expired entry\n")); + DEBUG(2, ("revalidating expired entry\n")); goto backend; } if ((*uid) == -1) { - DEBUG(10, ("Returning negative cache entry\n")); + DEBUG(2, ("Returning negative cache entry\n")); return NT_STATUS_NONE_MAPPED; } DEBUG(10, ("Returning positive cache entry\n")); @@ -192,7 +196,7 @@ backend: } if (map.status != ID_MAPPED) { - DEBUG(10, ("sid [%s] is not mapped\n", sid_string_dbg(sid))); + DEBUG(1, ("sid [%s] is not mapped\n", sid_string_dbg(sid))); if (winbindd_use_idmap_cache()) { idmap_cache_set_sid2uid(sid, -1); } @@ -200,7 +204,7 @@ backend: } if (map.xid.type != ID_TYPE_UID) { - DEBUG(10, ("sid [%s] not mapped to a uid " + DEBUG(1, ("sid [%s] not mapped to a uid " "[%u,%u,%u]\n", sid_string_dbg(sid), map.status, @@ -235,10 +239,11 @@ NTSTATUS idmap_sid_to_gid(const char *domname, struct dom_sid *sid, gid_t *gid) if (winbindd_use_idmap_cache() && idmap_cache_find_sid2gid(sid, gid, &expired)) { - DEBUG(10, ("idmap_cache_find_sid2gid found %d%s\n", + DEBUG(10, ("idmap_cache_find_sid2gid %s found %d%s\n", + sid_string_dbg(sid), (int)(*gid), expired ? " (expired)": "")); if (expired && idmap_is_online()) { - DEBUG(10, ("revalidating expired entry\n")); + DEBUG(2, ("revalidating expired entry\n")); goto backend; } if ((*gid) == -1) { @@ -256,8 +261,8 @@ backend: ret = idmap_backends_sid_to_unixid(domname, &map); if (!NT_STATUS_IS_OK(ret)) { - DEBUG(10, ("idmap_backends_sid_to_unixid failed: %s\n", - nt_errstr(ret))); + DEBUG(1, ("idmap_backends_sid_to_unixid failed for %s as GID: %s\n", + sid_string_dbg(sid), nt_errstr(ret))); if (winbindd_use_idmap_cache()) { idmap_cache_set_sid2gid(sid, -1); } @@ -265,7 +270,7 @@ backend: } if (map.status != ID_MAPPED) { - DEBUG(10, ("sid [%s] is not mapped\n", sid_string_dbg(sid))); + DEBUG(1, ("sid [%s] is not mapped as GID\n", sid_string_dbg(sid))); if (winbindd_use_idmap_cache()) { idmap_cache_set_sid2gid(sid, -1); } @@ -273,7 +278,7 @@ backend: } if (map.xid.type != ID_TYPE_GID) { - DEBUG(10, ("sid [%s] not mapped to a gid " + DEBUG(1, ("sid [%s] not mapped to a gid " "[%u,%u,%u]\n", sid_string_dbg(sid), map.status, -- 1.7.4.1 From eb14109da6fc4436b1eeedf8405279d2bd251393 Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:30:38 +0200 Subject: [PATCH 3/7] s3:winbindd/idmap_ad: improve DEBUG messages and lower the log level metze --- source3/winbindd/idmap_ad.c | 42 +++++++++++++++++++++++++++++++++--------- 1 files changed, 33 insertions(+), 9 deletions(-) diff --git a/source3/winbindd/idmap_ad.c b/source3/winbindd/idmap_ad.c index cf15f03..424b107 100644 --- a/source3/winbindd/idmap_ad.c +++ b/source3/winbindd/idmap_ad.c @@ -457,13 +457,13 @@ again: ctx->ad_schema->posix_gidnumber_attr, &id)) { - DEBUG(1, ("Could not get unix ID\n")); + DEBUG(1, ("Could not parse unix ID for sid %s\n", + sid_string_dbg(&sid))); continue; } - if (!idmap_unix_id_is_in_range(id, dom)) { - DEBUG(5, ("Requested id (%u) out of range (%u - %u). Filtered!\n", - id, dom->low_id, dom->high_id)); + DEBUG(1, ("Ignore sid %s for id (%u) out of range (%u - %u).\n", + sid_string_dbg(&sid), id, dom->low_id, dom->high_id)); continue; } @@ -495,8 +495,28 @@ again: /* mark all unknown/expired ones as unmapped */ for (i = 0; ids[i]; i++) { - if (ids[i]->status != ID_MAPPED) + if (ids[i]->status != ID_MAPPED) { + const char *type = NULL; + ids[i]->status = ID_UNMAPPED; + + switch (ids[i]->xid.type) { + case ID_TYPE_UID: + type = "uid"; + break; + + case ID_TYPE_GID: + type = "gid"; + break; + + default: + type = "unknown"; + break; + } + + DEBUG(1,("idmap_ad_unixids_to_sid: %s[%u] %u is umapped\n", + type, i, ids[i]->xid.id)); + } } done: @@ -654,12 +674,13 @@ again: ctx->ad_schema->posix_gidnumber_attr, &id)) { - DEBUG(1, ("Could not get unix ID\n")); + DEBUG(1, ("Could not get unix ID for sid %s\n", + sid_string_dbg(&sid))); continue; } if (!idmap_unix_id_is_in_range(id, dom)) { - DEBUG(5, ("Requested id (%u) out of range (%u - %u). Filtered!\n", - id, dom->low_id, dom->high_id)); + DEBUG(1, ("Requested id (%u) out of range (%u - %u). Filtered for sid %s!\n", + id, dom->low_id, dom->high_id, sid_string_dbg(&sid))); continue; } @@ -685,8 +706,11 @@ again: /* mark all unknown/expired ones as unmapped */ for (i = 0; ids[i]; i++) { - if (ids[i]->status != ID_MAPPED) + if (ids[i]->status != ID_MAPPED) { ids[i]->status = ID_UNMAPPED; + DEBUG(1,("idmap_ad_sids_to_unixids: sid[%u] %s is umapped\n", + i, sid_string_dbg(ids[i]->sid))); + } } done: -- 1.7.4.1 From d55317328e4fa913d2242ab68fa0fe123b631328 Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:42:49 +0200 Subject: [PATCH 4/7] s3:lookup_sids: DEBUG missing idmappings metze --- source3/passdb/lookup_sid.c | 7 +++++++ 1 files changed, 7 insertions(+), 0 deletions(-) diff --git a/source3/passdb/lookup_sid.c b/source3/passdb/lookup_sid.c index 2afa86e..cab918a 100644 --- a/source3/passdb/lookup_sid.c +++ b/source3/passdb/lookup_sid.c @@ -1507,6 +1507,13 @@ done: case WBC_ID_TYPE_NOT_SPECIFIED: break; } + + if (ids[i].type != WBC_ID_TYPE_NOT_SPECIFIED) { + continue; + } + + DEBUG(2,("sids_to_unix_ids: sid[%u][%s] is unmapped\n", + i, sid_string_dbg(&sids[i]))); } ret = true; fail: -- 1.7.4.1 From a88877923f56b731839d9a382d4329b229b86200 Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:49:32 +0200 Subject: [PATCH 5/7] s3:lookup_sid: let sid_to_gid and sid_to_uid use the same log levels metze --- source3/passdb/lookup_sid.c | 2 +- 1 files changed, 1 insertions(+), 1 deletions(-) diff --git a/source3/passdb/lookup_sid.c b/source3/passdb/lookup_sid.c index cab918a..e4c5ef9 100644 --- a/source3/passdb/lookup_sid.c +++ b/source3/passdb/lookup_sid.c @@ -1631,7 +1631,7 @@ bool sid_to_gid(const struct dom_sid *psid, gid_t *pgid) if ( !winbind_sid_to_gid(pgid, psid) ) { - DEBUG(10,("winbind failed to find a gid for sid %s\n", + DEBUG(5,("winbind failed to find a gid for sid %s\n", sid_string_dbg(psid))); /* winbind failed. do legacy */ return legacy_sid_to_gid(psid, pgid); -- 1.7.4.1 From e5b66727b38fea9a9714001a10c78a891856db2e Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:33:09 +0200 Subject: [PATCH 6/7] s3:auth_util: DEBUG ignored sids in a token with a lower log level metze --- source3/auth/auth_util.c | 2 +- 1 files changed, 1 insertions(+), 1 deletions(-) diff --git a/source3/auth/auth_util.c b/source3/auth/auth_util.c index c7e266a..ee5063a 100644 --- a/source3/auth/auth_util.c +++ b/source3/auth/auth_util.c @@ -500,7 +500,7 @@ NTSTATUS create_local_token(struct auth_serversupplied_info *server_info) for (i=1; inum_sids; i++) { if (ids[i].type != WBC_ID_TYPE_GID) { - DEBUG(10, ("Could not convert SID %s to gid, " + DEBUG(2, ("Could not convert SID %s to gid, " "ignoring it\n", sid_string_dbg(&t->sids[i]))); continue; -- 1.7.4.1 From a5e48d5294a25c034bb74c00f00ba24eaa19dff3 Mon Sep 17 00:00:00 2001 From: Stefan Metzmacher Date: Thu, 24 May 2012 09:33:55 +0200 Subject: [PATCH 7/7] s3:auth_util: DEBUG nt and unix token at a lower log level create_local_token() is a very important function, as a lot of access decisions are made based on the result. So better log the tokens without the need of "log level = 10" metze --- source3/auth/auth_util.c | 4 ++-- 1 files changed, 2 insertions(+), 2 deletions(-) diff --git a/source3/auth/auth_util.c b/source3/auth/auth_util.c index ee5063a..6e12f34 100644 --- a/source3/auth/auth_util.c +++ b/source3/auth/auth_util.c @@ -538,8 +538,8 @@ NTSTATUS create_local_token(struct auth_serversupplied_info *server_info) &server_info->security_token->num_sids); } - security_token_debug(DBGC_AUTH, 10, server_info->security_token); - debug_unix_user_token(DBGC_AUTH, 10, + security_token_debug(DBGC_AUTH, 4, server_info->security_token); + debug_unix_user_token(DBGC_AUTH, 4, server_info->utok.uid, server_info->utok.gid, server_info->utok.ngroups, -- 1.7.4.1