Attachment 7591 Details for Bug 8952 – Additional DEBUG Patches for v3-6-test

[patch] Additional DEBUG Patches for v3-6-test

tmp36-2.diff (text/plain), 12.56 KB, created by Stefan Metzmacher on 2012-05-24 08:40:08 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Stefan Metzmacher

Created: 2012-05-24 08:40:08 UTC

Size: 12.56 KB

patch

obsolete

>From 1286eaf28ababd2e597812296288d113e11aaeca Mon Sep 17 00:00:00 2001
>From: Stefan Metzmacher <metze@samba.org>
>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 <metze@samba.org>
>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 <metze@samba.org>
>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 <metze@samba.org>
>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 <metze@samba.org>
>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 <metze@samba.org>
>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; i<t->num_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 <metze@samba.org>
>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
>

Flags:

ira: review-

Actions: View

Attachments on bug 8952: 7575 | 7576 | 7577 | 7578 | 7579 | 7580 | 7586 | 7587 | 7590 | 7591 | 7592 | 7593