From 344b029eb55d053dc612085ef910853c572adda0 Mon Sep 17 00:00:00 2001 From: Noel Power 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 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 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