The branch, master has been updated via c2f8fde9f30 s3:test: Test winbind call depth trace via 51d559d8f49 s3:winbind: Move tevent_req_create() before debug macros to have the right call depth via 4b6e8e1c117 s3:winbind: Deactivate call depth tracking in child winbindd via a6c1211504b s3:winbind: Activate the call depth tracking in main winbindd via 3b1b37b1cf8 debug: Call depth: Indent the debug text via 7ba3b1b09de debug: Call depth: Print ", depth=..." in the debug header via e3e687b659a debug: Call depth: Interface via 13d2db03973 debug: Fix whitespaces in debug.c via c7a3b256291 selftest: Update devel_env.sh for SAMBA_DCERPCD_DONT_LOG_STDOUT=1 via fd7187daed8 s3:tests: Add support for SMBD_DONT_LOG_STDOUT=1 in test_chdir_cache.sh from 56c6f0b6d64 selftest: Only run samba.tests.smb3unix in developer mode
https://git.samba.org/?p=samba.git;a=shortlog;h=master - Log ----------------------------------------------------------------- commit c2f8fde9f308b0962cbb4cfa4fffda8c770e14db Author: Pavel Filipenský <pfilipen...@samba.org> Date: Wed Jan 25 02:01:22 2023 +0100 s3:test: Test winbind call depth trace BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> Autobuild-User(master): Andreas Schneider <a...@cryptomilk.org> Autobuild-Date(master): Thu Jan 26 15:07:57 UTC 2023 on atb-devel-224 commit 51d559d8f498d9941b50953bfe33d9f4110c2c96 Author: Pavel Filipenský <pfilipen...@samba.org> Date: Mon Sep 12 16:06:09 2022 +0200 s3:winbind: Move tevent_req_create() before debug macros to have the right call depth BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit 4b6e8e1c1178bd0e3177b12b22d60c7e3c44c1af Author: Pavel Filipenský <pfili...@redhat.com> Date: Fri Jun 17 18:03:35 2022 +0200 s3:winbind: Deactivate call depth tracking in child winbindd BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit a6c1211504bbfc84cae7545539ba38e35417dc42 Author: Pavel Filipenský <pfili...@redhat.com> Date: Thu Jun 16 17:56:39 2022 +0200 s3:winbind: Activate the call depth tracking in main winbindd BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit 3b1b37b1cf8f3599f2970cea1d9f0daa36afe4af Author: Pavel Filipenský <pfilipen...@samba.org> Date: Fri Aug 26 11:42:42 2022 +0200 debug: Call depth: Indent the debug text BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit 7ba3b1b09de327f77ee11b1c5ba3a77260ce2342 Author: Pavel Filipenský <pfilipen...@samba.org> Date: Fri Aug 26 11:42:42 2022 +0200 debug: Call depth: Print ", depth=..." in the debug header BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit e3e687b659ac0d60a0e1f0775ab3cc7181b3cc29 Author: Pavel Filipenský <pfilipen...@samba.org> Date: Fri Aug 26 11:41:44 2022 +0200 debug: Call depth: Interface BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit 13d2db03973c4e26b2cff0925faab785a3c12494 Author: Pavel Filipenský <pfili...@redhat.com> Date: Fri Jun 10 15:35:53 2022 +0200 debug: Fix whitespaces in debug.c BUG: https://bugzilla.samba.org/show_bug.cgi?id=15287 Signed-off-by: Pavel Filipenský <pfilipen...@samba.org> Reviewed-by: Andreas Schneider <a...@samba.org> commit c7a3b256291dd7d18d67b7f909a00fbd2103e1b8 Author: Andreas Schneider <a...@samba.org> Date: Wed Jan 25 17:26:17 2023 +0100 selftest: Update devel_env.sh for SAMBA_DCERPCD_DONT_LOG_STDOUT=1 Signed-off-by: Andreas Schneider <a...@samba.org> Reviewed-by: Pavel Filipenský <pfili...@redhat.com> commit fd7187daed85f4ea51762c029ae8ef3fa893b2fb Author: Andreas Schneider <a...@samba.org> Date: Mon Jan 23 10:21:33 2023 +0100 s3:tests: Add support for SMBD_DONT_LOG_STDOUT=1 in test_chdir_cache.sh BUG: https://bugzilla.samba.org/show_bug.cgi?id=15291 Signed-off-by: Andreas Schneider <a...@samba.org> Reviewed-by: Ralph Boehme <s...@samba.org> ----------------------------------------------------------------------- Summary of changes: lib/util/debug.c | 42 +++++++- lib/util/debug.h | 2 + selftest/devel_env.sh | 1 + selftest/target/Samba3.pm | 1 + source3/script/tests/test_chdir_cache.sh | 16 ++- .../script/tests/test_winbind_call_depth_trace.sh | 113 +++++++++++++++++++++ source3/selftest/tests.py | 9 +- source3/winbindd/wb_lookupsids.c | 10 +- source3/winbindd/wb_sids2xids.c | 6 +- source3/winbindd/winbindd.c | 2 + source3/winbindd/winbindd_dual.c | 6 ++ 11 files changed, 193 insertions(+), 15 deletions(-) create mode 100755 source3/script/tests/test_winbind_call_depth_trace.sh Changeset truncated at 500 lines: diff --git a/lib/util/debug.c b/lib/util/debug.c index 517157ef6a8..43d5151fbab 100644 --- a/lib/util/debug.c +++ b/lib/util/debug.c @@ -1598,6 +1598,17 @@ static void bufr_print( void ) format_pos = 0; } +/* + * If set (by tevent_thread_call_depth_set()) to value > 0, debug code will use + * it for the trace indentation. + */ +static size_t debug_call_depth = 0; + +size_t *debug_call_depth_addr(void) +{ + return &debug_call_depth; +} + /*************************************************************************** Format the debug message text. @@ -1624,8 +1635,21 @@ static void format_debug_text( const char *msg ) for( i = 0; msg[i]; i++ ) { /* Indent two spaces at each new line. */ if(timestamp && 0 == format_pos) { + /* Limit the maximum indentation to 20 levels */ + size_t depth = MIN(20, debug_call_depth); format_bufr[0] = format_bufr[1] = ' '; format_pos = 2; + /* + * Indent by four spaces for each depth level, + * but only if the current debug level is >= 8. + */ + if (depth > 0 && debuglevel_get() >= 8 && + format_pos + 4 * depth < FORMAT_BUFR_SIZE) { + memset(&format_bufr[format_pos], + ' ', + 4 * depth); + format_pos += 4 * depth; + } } /* If there's room, copy the character to the format buffer. */ @@ -1841,6 +1865,16 @@ bool dbghdrclass(int level, int cls, const char *location, const char *func) } } + if (debug_call_depth > 0) { + state.hs_len += snprintf(state.header_str + state.hs_len, + sizeof(state.header_str) - state.hs_len, + ", depth=%zu", + debug_call_depth); + if (state.hs_len >= sizeof(state.header_str) - 1) { + goto full; + } + } + state.header_str[state.hs_len] = ']'; state.hs_len++; if (state.hs_len < sizeof(state.header_str) - 1) { @@ -1929,12 +1963,12 @@ static uint64_t debug_traceid = 0; uint64_t debug_traceid_set(uint64_t id) { - uint64_t old_id = debug_traceid; - debug_traceid = id; - return old_id; + uint64_t old_id = debug_traceid; + debug_traceid = id; + return old_id; } uint64_t debug_traceid_get(void) { - return debug_traceid; + return debug_traceid; } diff --git a/lib/util/debug.h b/lib/util/debug.h index f58bb005145..4bbfa05df65 100644 --- a/lib/util/debug.h +++ b/lib/util/debug.h @@ -378,4 +378,6 @@ uint64_t debug_traceid_set(uint64_t id); /* Get the current traceid. */ uint64_t debug_traceid_get(void); +size_t *debug_call_depth_addr(void); + #endif /* _SAMBA_DEBUG_H */ diff --git a/selftest/devel_env.sh b/selftest/devel_env.sh index d1c0736ab09..bbb99e0a250 100644 --- a/selftest/devel_env.sh +++ b/selftest/devel_env.sh @@ -9,3 +9,4 @@ export TDB_NO_FSYNC=1 export NMBD_DONT_LOG_STDOUT=1 export SMBD_DONT_LOG_STDOUT=1 export WINBINDD_DONT_LOG_STDOUT=1 +export SAMBA_DCERPCD_DONT_LOG_STDOUT=1 diff --git a/selftest/target/Samba3.pm b/selftest/target/Samba3.pm index 6f93694f1b3..f9346ae812e 100755 --- a/selftest/target/Samba3.pm +++ b/selftest/target/Samba3.pm @@ -2854,6 +2854,7 @@ sub provision($$) lock directory = $lockdir log file = $logdir/log.\%m log level = $server_log_level + winbind debug traceid = yes debug pid = yes max log size = 0 diff --git a/source3/script/tests/test_chdir_cache.sh b/source3/script/tests/test_chdir_cache.sh index c649d2b07b3..11967180d35 100755 --- a/source3/script/tests/test_chdir_cache.sh +++ b/source3/script/tests/test_chdir_cache.sh @@ -9,7 +9,7 @@ if [ $# -lt 5 ]; then echo Usage: test_chdir_user.sh \ - --configfile=SERVERCONFFILE SMBCLIENT SMBCONTROL SERVER SHARE + --configfile=SERVERCONFFILE SMBCLIENT SMBCONTROL SERVER SHARE PREFIX TESTENV exit 1 fi @@ -23,6 +23,12 @@ SERVER=$1 shift 1 SHARE=$1 shift 1 +PREFIX=${1} +shift 1 +TESTENV=${1} +shift 1 + +PREFIX_ABS="$(readlink -f "${PREFIX}")" # Do not let deprecated option warnings muck this up SAMBA_DEPRECATED_SUPPRESS=1 @@ -30,8 +36,6 @@ export SAMBA_DEPRECATED_SUPPRESS conf_dir=$(dirname ${SERVERCONFFILE}) -log_file=${conf_dir}/../smbd_test.log - error_inject_conf=${conf_dir}/error_inject.conf rm -f ${error_inject_conf} @@ -52,6 +56,12 @@ ${SMBCLIENT} //${SERVER}/${SHARE} ${CONF} -U${USER}%${PASSWORD} \ <smbclient-stdin >smbclient-stdout 2>smbclient-stderr & CLIENT_PID=$! +log_file="${PREFIX_ABS}/${TESTENV}/smbd_test.log" +# Add support for "SMBD_DONT_LOG_STDOUT=1" +if [ -r "${PREFIX_ABS}/${TESTENV}/logs/log.smbd" ]; then + log_file="${PREFIX_ABS}/${TESTENV}/logs/log.smbd" +fi + # Count the number of chdir_current_service: vfs_ChDir.*failed: Permission denied # errors that are already in the log (should be zero). num_errs=$(grep "chdir_current_service: vfs_ChDir.*failed: Permission denied" ${log_file} | wc -l) diff --git a/source3/script/tests/test_winbind_call_depth_trace.sh b/source3/script/tests/test_winbind_call_depth_trace.sh new file mode 100755 index 00000000000..6d978beca8f --- /dev/null +++ b/source3/script/tests/test_winbind_call_depth_trace.sh @@ -0,0 +1,113 @@ +#!/bin/sh + +# Copyright (c) Pavel Filipenský <pfilipen...@samba.org> +# License: GPLv3 + +if [ $# -lt 4 ]; then + echo "Usage: test_winbind_call_depth_trace SMBCONTROL CONFIGURATION PREFIX TESTENV" + exit 1 +fi + +SMBCONTROL="${1}" +CONFIGURATION=${2} +PREFIX="${3}" +TESTENV="${4}" +shift 4 + +incdir=$(dirname "$0")/../../../testprogs/blackbox +. "$incdir"/subunit.sh + +failed=0 + +PREFIX_ABS="$(readlink -f "${PREFIX}")" +# Strip from TESTENV the ':local' if present +TESTENV_SUBDIR=${TESTENV%:*} + +LOGFILE="${PREFIX_ABS}/${TESTENV_SUBDIR}/logs/log.winbindd" +# Add support for "WINBINDD_DONT_LOG_STDOUT=1" +if [ ! -r "${LOGFILE}" ]; then + TEST_LOGFILE="${PREFIX_ABS}/${TESTENV_SUBDIR}/winbindd_test.log" + subunit_start_test "test winbind call depth trace" + subunit_skip_test "test winbind call depth trace" <<EOF +Test is skipped, we need $LOGFILE but have only $TEST_LOGFILE which is missing debug headers (they are not printed to stdout). +EOF + exit 0 +fi + +saved_level=1 + +get_winbind_loglevel() +{ + s1=$(${SMBCONTROL} "${CONFIGURATION}" winbind debuglevel) + # We need to get the all level from output like this: + # "PID 664474: all:1 tdb:1 printdrivers:1 lanman:1 smb:1 rpc_parse:1 rpc_srv:1 rpc_cli:1 passdb:1 sam:1..." + # 1. remove PID 664474: + s2=${s1#PID*: } + # "all:1 tdb:1 printdrivers:1 lanman:1 smb:1 rpc_parse:1 rpc_srv:1 rpc_cli:1 passdb" + # 2. remove " tdb:1 printdrivers:1 ..." + s3=${s2%% *} + # "all:1" + # 3. remove "all:" + saved_level=${s3#all:} +} + +# Example of trace line +# [2023/01/25 00:20:33.307038, 5, pid=535581, effective(0, 0), real(0, 0), class=winbind, traceid=78, depth=4] ../../source3/winbindd/wb_group_members.c:310(wb_group_members_send) +test_winbind_call_depth_trace() +{ + get_winbind_loglevel + + # If loglevel < 10, set it to 10. + if [ "$saved_level" -lt 10 ]; then + ${SMBCONTROL} "${CONFIGURATION}" winbind debug 10 + fi + + COUNT1=$(grep -c wb_group_members_send "$LOGFILE") + + id ADDOMAIN/alice + ret=$? + + # Restore loglevel, if it was changed. + if [ "$saved_level" -lt 10 ]; then + ${SMBCONTROL} "${CONFIGURATION}" winbind debug "$saved_level" + fi + + if [ $ret != 0 ]; then + echo "Command 'id ADDOMAIN/alice' failed!" + return 1 + fi + + # Check that there are more lines with wb_group_members_send + COUNT2=$(grep -c wb_group_members_send "$LOGFILE") + if [ "$COUNT1" -eq "$COUNT2" ]; then + echo "The number of the trace lines in $LOGFILE has not increased." + return 1 + fi + + # Test that the depth of last line with 'wb_group_members_send' is: depth=4 + COUNT3=$(grep wb_group_members_send "$LOGFILE" | tail -1 | grep -c depth=4) + if [ "$COUNT3" -ne 1 ]; then + echo "The last line with wb_group_members_send should have depth=4." + return 1 + fi + + # Test that the indentation of the line below last 'wb_group_members_send' is indented by 2+4*4 spaces: + COUNT4=$(grep -A1 wb_group_members_send "$LOGFILE" | tail -1| grep -c '^ WB command group_members start') + if [ "$COUNT4" -ne 1 ]; then + echo "The line after the last line with wb_group_members_send should be indented by 18 spaces." + return 1 + fi + + return 0 +} + +case ${TESTENV} in +ad_member*) + ;; +*) + echo "Test is for ad_member only, but called for ${TESTENV}." | subunit_fail_test "test winbind call depth trace" + exit 1; +esac + +testit "test winbind call depth trace" test_winbind_call_depth_trace || failed=$((failed + 1)) +testok "$0" "$failed" diff --git a/source3/selftest/tests.py b/source3/selftest/tests.py index 187f3ccd9c0..76b8ad980ee 100755 --- a/source3/selftest/tests.py +++ b/source3/selftest/tests.py @@ -608,6 +608,11 @@ plantestsuite("samba3.wbinfo_user_info", env, "nsswitch/tests/test_wbinfo_user_info.sh"), '$DOMAIN', '$REALM', '$DOMAIN', 'alice', 'alice', 'jane', 'jane.doe', env]) +plantestsuite("samba3.winbind_call_depth_trace", env, + [os.path.join(srcdir(), + "source3/script/tests/test_winbind_call_depth_trace.sh"), + smbcontrol, configuration, '$PREFIX', env]) + env = "fl2008r2dc:local" plantestsuite("samba3.wbinfo_user_info", env, [os.path.join(srcdir(), @@ -1402,7 +1407,9 @@ plantestsuite("samba3.blackbox.chdir-cache", "simpleserver:local", os.path.join(bindir(), "smbclient"), os.path.join(bindir(), "smbcontrol"), '$SERVER_IP', - "error_inject"]) + "error_inject", + '$PREFIX', + 'simpleserver']) plantestsuite("samba3.blackbox.netfileenum", "simpleserver:local", [os.path.join(samba3srcdir, diff --git a/source3/winbindd/wb_lookupsids.c b/source3/winbindd/wb_lookupsids.c index d0259119731..3473f7a1c97 100644 --- a/source3/winbindd/wb_lookupsids.c +++ b/source3/winbindd/wb_lookupsids.c @@ -116,6 +116,11 @@ struct tevent_req *wb_lookupsids_send(TALLOC_CTX *mem_ctx, struct wb_lookupsids_state *state; uint32_t i; + req = tevent_req_create(mem_ctx, &state, struct wb_lookupsids_state); + if (req == NULL) { + return NULL; + } + D_INFO("WB command lookupsids start.\nLooking up %"PRIu32" SID(s)\n", num_sids); if (CHECK_DEBUGLVL(DBGLVL_INFO)) { @@ -125,10 +130,7 @@ struct tevent_req *wb_lookupsids_send(TALLOC_CTX *mem_ctx, i, dom_sid_str_buf(&sids[i], &buf)); } } - req = tevent_req_create(mem_ctx, &state, struct wb_lookupsids_state); - if (req == NULL) { - return NULL; - } + state->ev = ev; state->sids = sids; state->num_sids = num_sids; diff --git a/source3/winbindd/wb_sids2xids.c b/source3/winbindd/wb_sids2xids.c index 9a3507ba702..f0f6c23fc20 100644 --- a/source3/winbindd/wb_sids2xids.c +++ b/source3/winbindd/wb_sids2xids.c @@ -81,15 +81,15 @@ struct tevent_req *wb_sids2xids_send(TALLOC_CTX *mem_ctx, uint32_t i; uint32_t num_valid = 0; - D_INFO("WB command sids2xids start.\n" - "Resolving %"PRIu32" SID(s).\n", num_sids); - req = tevent_req_create(mem_ctx, &state, struct wb_sids2xids_state); if (req == NULL) { return NULL; } + D_INFO("WB command sids2xids start.\n" + "Resolving %"PRIu32" SID(s).\n", num_sids); + state->ev = ev; state->num_sids = num_sids; diff --git a/source3/winbindd/winbindd.c b/source3/winbindd/winbindd.c index 50dc6d6bd92..16b9eebeb89 100644 --- a/source3/winbindd/winbindd.c +++ b/source3/winbindd/winbindd.c @@ -440,6 +440,7 @@ static struct tevent_req *process_request_send( if (req == NULL) { return NULL; } + tevent_thread_call_depth_start(req); state->cli_state = cli_state; state->ev = ev; @@ -1636,6 +1637,7 @@ int main(int argc, const char **argv) if (lp_winbind_debug_traceid()) { winbind_debug_traceid_setup(global_event_context()); + tevent_thread_call_depth_activate(debug_call_depth_addr()); } ok = initialize_password_db(true, global_event_context()); if (!ok) { diff --git a/source3/winbindd/winbindd_dual.c b/source3/winbindd/winbindd_dual.c index 8cb59b2f752..d9c32b10072 100644 --- a/source3/winbindd/winbindd_dual.c +++ b/source3/winbindd/winbindd_dual.c @@ -1742,6 +1742,12 @@ static bool fork_domain_child(struct winbindd_child *child) state.cli.sock = fdpair[0]; close(fdpair[1]); + /* Reset traceid and deactivate call_depth tracking */ + if (lp_winbind_debug_traceid()) { + debug_traceid_set(1); + tevent_thread_call_depth_deactivate(); + } + status = winbindd_reinit_after_fork(child, child->logfilename); /* setup callbacks again, one of them is removed in reinit_after_fork */ -- Samba Shared Repository