Attachment 17442 Details for Bug 15128 – debug & hacky repro tweak

[patch] debug & hacky repro tweak

hacky-repro.patch (text/plain), 15.57 KB, created by Noel Power on 2022-07-24 14:00:52 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Noel Power

Created: 2022-07-24 14:00:52 UTC

Size: 15.57 KB

patch

obsolete

>From 344b029eb55d053dc612085ef910853c572adda0 Mon Sep 17 00:00:00 2001
>From: Noel Power <noel.power@suse.com>
>Date: Tue, 14 Jun 2022 15:55:50 +0100
>Subject: [PATCH 1/3] some debug
>
>---
> source3/smbd/conn.c           |  6 +++--
> source3/smbd/process.c        |  4 ++--
> source3/smbd/server_exit.c    |  2 ++
> source3/smbd/smb2_negprot.c   |  2 ++
> source3/smbd/smb2_server.c    | 43 +++++++++++++++++++++++++++++++++++
> source3/smbd/smbXsrv_client.c | 19 +++++++++++++---
> source3/winbindd/winbindd.c   |  3 ++-
> 7 files changed, 71 insertions(+), 8 deletions(-)
>
>diff --git a/source3/smbd/conn.c b/source3/smbd/conn.c
>index 044242d5697..21b8582ebc8 100644
>--- a/source3/smbd/conn.c
>+++ b/source3/smbd/conn.c
>@@ -66,6 +66,7 @@ connection_struct *conn_new(struct smbd_server_connection *sconn)
> 		DBG_ERR("talloc_zero failed\n");
> 		return NULL;
> 	}
>+	DBG_ERR("### new con created!!! %p\n", conn);
> 	conn->params = talloc(conn, struct share_params);
> 	if (conn->params == NULL) {
> 		DBG_ERR("talloc_zero failed\n");
>@@ -114,7 +115,7 @@ connection_struct *conn_new(struct smbd_server_connection *sconn)
> 
> 	DLIST_ADD(sconn->connections, conn);
> 	sconn->num_connections++;
>-
>+	DBG_ERR("## sconn %p added connection %p, num conns = %d\n", sconn, conn, sconn->num_connections);
> 	return conn;
> }
> 
>@@ -229,7 +230,8 @@ void conn_free(connection_struct *conn)
> 	DLIST_REMOVE(conn->sconn->connections, conn);
> 	SMB_ASSERT(conn->sconn->num_connections > 0);
> 	conn->sconn->num_connections--;
>-
>+	
>+	DBG_ERR("## sconn %p removed connection %p, num conns = %d\n", conn->sconn, conn, conn->sconn->num_connections);
> 	conn_free_internal(conn);
> }
> 
>diff --git a/source3/smbd/process.c b/source3/smbd/process.c
>index 5015c143a04..0760b0cf3cd 100644
>--- a/source3/smbd/process.c
>+++ b/source3/smbd/process.c
>@@ -2921,7 +2921,7 @@ static bool deadtime_fn(const struct timeval *now, void *private_data)
> {
> 	struct smbd_server_connection *sconn =
> 		(struct smbd_server_connection *)private_data;
>-
>+	DBG_ERR("## num open conns = %d\n", conn_num_open(sconn));
> 	if ((conn_num_open(sconn) == 0)
> 	    || (conn_idle_all(sconn, now->tv_sec))) {
> 		DEBUG( 2, ( "Closing idle connection\n" ) );
>@@ -4022,7 +4022,7 @@ void smbd_process(struct tevent_context *ev_ctx,
> 	if (sconn == NULL) {
> 		exit_server("failed to create smbd_server_connection");
> 	}
>-
>+	DBG_ERR("### created new smbd_server_connection %p\n", sconn);
> 	client->sconn = sconn;
> 	sconn->client = client;
> 
>diff --git a/source3/smbd/server_exit.c b/source3/smbd/server_exit.c
>index a00edcd2368..d8f1122343b 100644
>--- a/source3/smbd/server_exit.c
>+++ b/source3/smbd/server_exit.c
>@@ -248,11 +248,13 @@ static void exit_server_common(enum server_exit_reason how,
> 
> void smbd_exit_server(const char *const explanation)
> {
>+	DBG_ERR("#### exiting because %s\n", explanation);
> 	exit_server_common(SERVER_EXIT_ABNORMAL, explanation);
> }
> 
> void smbd_exit_server_cleanly(const char *const explanation)
> {
>+	DBG_ERR("#### exiting because %s\n", explanation);
> 	exit_server_common(SERVER_EXIT_NORMAL, explanation);
> }
> 
>diff --git a/source3/smbd/smb2_negprot.c b/source3/smbd/smb2_negprot.c
>index c6c9e50e32a..750d919c72d 100644
>--- a/source3/smbd/smb2_negprot.c
>+++ b/source3/smbd/smb2_negprot.c
>@@ -798,6 +798,7 @@ NTSTATUS smbd_smb2_request_process_negprot(struct smbd_smb2_request *req)
> 		.outdyn = outdyn,
> 	};
> 
>+	DBG_ERR("## calling smb2srv_client_mc_negprot_send\n");
> 	subreq = smb2srv_client_mc_negprot_send(state,
> 						req->xconn->client->raw_ev_ctx,
> 						req);
>@@ -821,6 +822,7 @@ static void smbd_smb2_request_process_negprot_mc_done(struct tevent_req *subreq)
> 
> 	status = smb2srv_client_mc_negprot_recv(subreq);
> 	TALLOC_FREE(subreq);
>+	DBG_ERR("### mc_negprot done with status %s\n", nt_errstr(status));
> 	if (NT_STATUS_EQUAL(status, NT_STATUS_MESSAGE_RETRIEVED)) {
> 		/*
> 		 * The connection was passed to another process
>diff --git a/source3/smbd/smb2_server.c b/source3/smbd/smb2_server.c
>index 0e4b98f8c35..d82645ae1ea 100644
>--- a/source3/smbd/smb2_server.c
>+++ b/source3/smbd/smb2_server.c
>@@ -3052,8 +3052,12 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 				NT_STATUS_ACCESS_DENIED);
> 	}
> 
>+	DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s]\n",
>+		smb2_opcode_name(opcode));
> 	call = smbd_smb2_call(opcode);
> 	if (call == NULL) {
>+		DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+			smb2_opcode_name(opcode));
> 		return smbd_smb2_request_error(req, NT_STATUS_INVALID_PARAMETER);
> 	}
> 
>@@ -3075,6 +3079,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 		allowed_flags |= SMB2_HDR_FLAG_REPLAY_OPERATION;
> 	}
> 	if ((flags & ~allowed_flags) != 0) {
>+		DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+			smb2_opcode_name(opcode));
> 		return smbd_smb2_request_error(req, NT_STATUS_INVALID_PARAMETER);
> 	}
> 
>@@ -3084,6 +3090,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 		 * for compounded requests.
> 		 */
> 		if (!NT_STATUS_IS_OK(session_status)) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+				smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req, NT_STATUS_INVALID_PARAMETER);
> 		}
> 	} else {
>@@ -3113,6 +3121,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 			} else {
> 				status = NT_STATUS_USER_SESSION_DELETED;
> 			}
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+				smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req, status);
> 		}
> 
>@@ -3142,6 +3152,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 								      req,
> 								      &session);
> 				if (!NT_STATUS_IS_OK(error)) {
>+					DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+						smb2_opcode_name(opcode));
> 					return smbd_smb2_request_error(req, error);
> 				}
> 
>@@ -3157,6 +3169,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 			goto skipped_signing;
> 		}
> 		if (!NT_STATUS_IS_OK(status)) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req, status);
> 		}
> 
>@@ -3169,6 +3183,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 		}
> 
> 		if (!NT_STATUS_IS_OK(session_status)) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req, session_status);
> 		}
> 	}
>@@ -3196,6 +3212,8 @@ NTSTATUS smbd_smb2_request_dispatch(struct smbd_smb2_request *req)
> 		size_t needed = 8;
> 
> 		if (needed > body_size) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req,
> 					NT_STATUS_INVALID_PARAMETER);
> 		}
>@@ -3225,6 +3243,8 @@ skipped_signing:
> 
> 	if (call->need_session) {
> 		if (!NT_STATUS_IS_OK(session_status)) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req, session_status);
> 		}
> 	}
>@@ -3242,6 +3262,8 @@ skipped_signing:
> 		 */
> 		status = smbd_smb2_request_check_tcon(req);
> 		if (!NT_STATUS_IS_OK(status)) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req, status);
> 		}
> 		if (req->tcon->global->encryption_flags & SMBXSRV_ENCRYPTION_DESIRED) {
>@@ -3252,6 +3274,8 @@ skipped_signing:
> 		}
> 		if (encryption_required && !req->was_encrypted) {
> 			req->do_encryption = true;
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req,
> 				NT_STATUS_ACCESS_DENIED);
> 		} else if (encryption_desired) {
>@@ -3267,6 +3291,8 @@ skipped_signing:
> 
> 		session_info = req->session->global->auth_session_info;
> 		if (session_info == NULL) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 			return NT_STATUS_INVALID_HANDLE;
> 		}
> 
>@@ -3286,12 +3312,16 @@ skipped_signing:
> 		if (update_session_global) {
> 			status = smbXsrv_session_update(x);
> 			if (!NT_STATUS_IS_OK(status)) {
>+				DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 				return smbd_smb2_request_error(req, status);
> 			}
> 		}
> 		if (update_tcon_global) {
> 			status = smbXsrv_tcon_update(req->tcon);
> 			if (!NT_STATUS_IS_OK(status)) {
>+				DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 				return smbd_smb2_request_error(req, status);
> 			}
> 		}
>@@ -3308,6 +3338,8 @@ skipped_signing:
> 		SMB_ASSERT(call->need_tcon);
> 
> 		if (needed > body_size) {
>+			DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+				smb2_opcode_name(opcode));
> 			return smbd_smb2_request_error(req,
> 					NT_STATUS_INVALID_PARAMETER);
> 		}
>@@ -3320,6 +3352,8 @@ skipped_signing:
> 			if (req->compound_related &&
> 			    !NT_STATUS_IS_OK(req->compound_create_err))
> 			{
>+				DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 				return smbd_smb2_request_error(req,
> 						req->compound_create_err);
> 			}
>@@ -3329,11 +3363,15 @@ skipped_signing:
> 			 * detailed error codes...
> 			 */
> 			if (opcode != SMB2_OP_IOCTL) {
>+				DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 				return smbd_smb2_request_error(req,
> 						NT_STATUS_FILE_CLOSED);
> 			}
> 		} else {
> 			if (fsp->fsp_flags.encryption_required && !req->was_encrypted) {
>+				DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+					smb2_opcode_name(opcode));
> 				return smbd_smb2_request_error(req,
> 						NT_STATUS_ACCESS_DENIED);
> 			}
>@@ -3342,6 +3380,8 @@ skipped_signing:
> 
> 	status = smbd_smb2_request_dispatch_update_counts(req, call->modify);
> 	if (!NT_STATUS_IS_OK(status)) {
>+		DBG_ERR("#### smbd_smb2_request_dispatch: about to call opcode[%s] got error\n",
>+			smb2_opcode_name(opcode));
> 		return smbd_smb2_request_error(req, status);
> 	}
> 
>@@ -3490,6 +3530,9 @@ skipped_signing:
> 		return_value = smbd_smb2_request_error(req, NT_STATUS_INVALID_PARAMETER);
> 		break;
> 	}
>+	DBG_ERR("#### smbd_smb2_request_dispatch: [%s] returning %s\n",
>+		smb2_opcode_name(opcode),
>+		nt_errstr(return_value));
> 	return return_value;
> }
> 
>diff --git a/source3/smbd/smbXsrv_client.c b/source3/smbd/smbXsrv_client.c
>index 277ae1bab25..54b71af11b4 100644
>--- a/source3/smbd/smbXsrv_client.c
>+++ b/source3/smbd/smbXsrv_client.c
>@@ -292,6 +292,7 @@ static NTSTATUS smb2srv_client_connection_pass(struct smbd_smb2_request *smb2req
> 		.client_connect_time = global->initial_connect_time,
> 	};
> 
>+	DBG_ERR("### connection_pass\n");
> 	reqlen = iov_buflen(smb2req->in.vector, smb2req->in.vector_count);
> 	if (reqlen == -1) {
> 		return NT_STATUS_INVALID_BUFFER_SIZE;
>@@ -491,6 +492,13 @@ static void smb2srv_client_mc_negprot_next(struct tevent_req *req)
> 		 * smbXsrv_client_global.tdb
> 		 */
> 		client->global->client_guid = xconn->smb2.client.guid;
>+		if (true) {
>+			struct GUID_txt_buf gbuf;
>+
>+			DBG_ERR("#### first time client_guid[%s] stored\n",
>+				  GUID_buf_string(&client->global->client_guid,
>+						  &gbuf));
>+		}
> 
> 		client->global->db_rec = state->db_rec;
> 		state->db_rec = NULL;
>@@ -531,7 +539,7 @@ static void smb2srv_client_mc_negprot_next(struct tevent_req *req)
> 		tevent_req_nterror(req, NT_STATUS_INTERNAL_DB_CORRUPTION);
> 		return;
> 	}
>-
>+	DBG_ERR("### not the first time\n");
> 	subreq = messaging_filtered_read_send(state,
> 					      state->ev,
> 					      client->msg_ctx,
>@@ -674,7 +682,7 @@ static void smb2srv_client_mc_negprot_watched(struct tevent_req *subreq)
> 		tevent_req_callback_data(subreq,
> 		struct tevent_req);
> 	NTSTATUS status;
>-
>+	DBG_ERR("### some change in db\n");
> 	status = dbwrap_watched_watch_recv(subreq, NULL, NULL);
> 	TALLOC_FREE(subreq);
> 	if (tevent_req_nterror(req, status)) {
>@@ -809,7 +817,12 @@ NTSTATUS smbXsrv_client_create(TALLOC_CTX *mem_ctx,
> 			  GUID_buf_string(&global->client_guid, &buf));
> 		NDR_PRINT_DEBUG(smbXsrv_clientB, &client_blob);
> 	}
>+	if (true) {
>+		struct GUID_txt_buf buf;
> 
>+		DBG_ERR("### client_guid[%s] created\n",
>+			  GUID_buf_string(&global->client_guid, &buf));
>+	}
> 	subreq = messaging_filtered_read_send(client,
> 					client->raw_ev_ctx,
> 					client->msg_ctx,
>@@ -845,7 +858,7 @@ static NTSTATUS smb2srv_client_connection_passed(struct smbXsrv_client *client,
> 	ZERO_STRUCT(passed_blob);
> 	passed_blob.version = smbXsrv_version_global_current();
> 	passed_blob.info.info0 = &passed_info0;
>-
>+	DBG_ERR("### connection passed\n");
> 	if (DEBUGLVL(DBGLVL_DEBUG)) {
> 		NDR_PRINT_DEBUG(smbXsrv_connection_passB, &passed_blob);
> 	}
>diff --git a/source3/winbindd/winbindd.c b/source3/winbindd/winbindd.c
>index 58c5ffbced4..2d1de366bdd 100644
>--- a/source3/winbindd/winbindd.c
>+++ b/source3/winbindd/winbindd.c
>@@ -1237,7 +1237,8 @@ static void winbindd_listen_fde_handler(struct tevent_context *ev,
> {
> 	struct winbindd_listen_state *s = talloc_get_type_abort(private_data,
> 					  struct winbindd_listen_state);
>-
>+	DBG_ERR("### in fd handlee, num_clients = %d\n",
>+			 lp_winbind_max_clients());
> 	while (winbindd_num_clients() > lp_winbind_max_clients() - 1) {
> 		DEBUG(5,("winbindd: Exceeding %d client "
> 			 "connections, removing idle "
>-- 
>2.35.3
>
>
>From 90fb9dc14a36787ae04bd4aad04450286f54610d Mon Sep 17 00:00:00 2001
>From: Noel Power <noel.power@suse.com>
>Date: Fri, 15 Jul 2022 18:22:03 +0100
>Subject: [PATCH 2/3] psuedo randomly inject the suspicious failure
>
>well not randonly at all really but whenever we get a disconnect
>e.g. a multiple of 3 disconnections then trigger the error, at
>least this way it wont happen all the time and we get a chance to
>see things working as they should
>---
> source3/smbd/smbXsrv_tcon.c | 11 +++++++----
> 1 file changed, 7 insertions(+), 4 deletions(-)
>
>diff --git a/source3/smbd/smbXsrv_tcon.c b/source3/smbd/smbXsrv_tcon.c
>index 6b105522855..fb2b55b2fef 100644
>--- a/source3/smbd/smbXsrv_tcon.c
>+++ b/source3/smbd/smbXsrv_tcon.c
>@@ -901,14 +901,17 @@ NTSTATUS smbXsrv_tcon_disconnect(struct smbXsrv_tcon *tcon, uint64_t vuid)
> 
> 	table = tcon->table;
> 	tcon->table = NULL;
>-
>+	DBG_ERR("### got disconnect for %p\n", tcon->compat);
> 	if (tcon->compat) {
> 		bool ok;
>-
>+		static int i;
>+		int res = i % 3;
>+		i = i + 1;
> 		ok = chdir_current_service(tcon->compat);
>-		if (!ok) {
>+		DBG_ERR("## %d\n",  res);
>+		if (!ok || res == 0) {
> 			status = NT_STATUS_INTERNAL_ERROR;
>-			DEBUG(0, ("smbXsrv_tcon_disconnect(0x%08x, '%s'): "
>+			DEBUG(0, ("#### smbXsrv_tcon_disconnect(0x%08x, '%s'): "
> 				  "chdir_current_service() failed: %s\n",
> 				  tcon->global->tcon_global_id,
> 				  tcon->global->share_name,
>-- 
>2.35.3
>
>
>From af9f3f58c87821e38ba2c6a27fed3f8da433c602 Mon Sep 17 00:00:00 2001
>From: Noel Power <noel.power@suse.com>
>Date: Fri, 15 Jul 2022 18:23:29 +0100
>Subject: [PATCH 3/3] trigger the scanning of
> smbd_server_connection->connections quicker
>
>---
> source3/smbd/process.c | 3 ++-
> 1 file changed, 2 insertions(+), 1 deletion(-)
>
>diff --git a/source3/smbd/process.c b/source3/smbd/process.c
>index 0760b0cf3cd..b35ddca44be 100644
>--- a/source3/smbd/process.c
>+++ b/source3/smbd/process.c
>@@ -4220,7 +4220,8 @@ void smbd_process(struct tevent_context *ev_ctx,
> 	}
> 
> 	if (!(event_add_idle(ev_ctx, NULL,
>-			     timeval_set(IDLE_CLOSED_TIMEOUT, 0),
>+			     //timeval_set(IDLE_CLOSED_TIMEOUT, 2),
>+			     timeval_set(2, 2),
> 			     "deadtime", deadtime_fn, sconn))) {
> 		DEBUG(0, ("Could not add deadtime event\n"));
> 		exit(1);
>-- 
>2.35.3
>

Actions: View

Attachments on bug 15128: 17440 | 17441 | 17442 | 17443 | 17444 | 17457 | 17458 | 17459 | 17478 | 17479 | 17481 | 17482 | 17483