From: Stefan Metzmacher Date: Fri, 18 Jun 2021 14:00:25 +0000 (+0000) Subject: vfs_preopen: add useful debug messages which can be configured on adjustable log... X-Git-Tag: tevent-0.11.0~92 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=83563b37213cdb58776e034c0bbd22ba55d51022;p=thirdparty%2Fsamba.git vfs_preopen: add useful debug messages which can be configured on adjustable log levels The following are the default values: preopen:nomatch_log_level = 5 preopen:match_log_level = 5 preopen:nodigits_log_level = 1 preopen:founddigits_log_level = 3 preopen:reset_log_level = 5 preopen:push_log_level = 3 preopen:queue_log_level = 10 This gives admins a way to debug/audit the preopen usage. Signed-off-by: Stefan Metzmacher Reviewed-by: Ralph Boehme --- diff --git a/docs-xml/manpages/vfs_preopen.8.xml b/docs-xml/manpages/vfs_preopen.8.xml index d1a90710f1e..e826d72ffef 100644 --- a/docs-xml/manpages/vfs_preopen.8.xml +++ b/docs-xml/manpages/vfs_preopen.8.xml @@ -117,6 +117,139 @@ + + preopen:nomatch_log_level = LOGLEVEL + + + In order to debug or audit the usage of the preopen logic + you can use this option to specify at what log level details + about filenames not matching any pattern from 'preopen:names' + are logged. + + + Defaults to the log level 5. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + + + preopen:match_log_level = LOGLEVEL + + + In order to debug or audit the usage of the preopen logic + you can use this option to specify at what log level details + about filenames actually matching a pattern from 'preopen:names' + are logged. + + + See also 'preopen:founddigits_log_level' and 'preopen:push_log_level'. + + + Defaults to the log level 5. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + + + preopen:nodigits_log_level = LOGLEVEL + + + In order to debug or audit problems with the preopen configuration + you can use this option to specify at what log level details + about filenames actually matching a pattern from 'preopen:names', + but at the same time don't contain the expected digits, are logged. + This is typically something the administrator wants to notice and + adjust the configuration in order to define more precisely where to + find the digits in the filename. + + + Defaults to the log level 1. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + + + preopen:founddigits_log_level = LOGLEVEL + + + In order to debug or audit the usage of the preopen logic + you can use this option to specify at what log level details + about filenames actually matching a pattern from 'preopen:names', + and at the same time having valid expected digits, are logged. This means enough information is available + in order to queue preopens. + + + Defaults to the log level 3. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + + + preopen:reset_log_level = LOGLEVEL + + + If a matching filename belongs to a different pattern from 'preopen:names', + a different parent directory or differs in a significant way from the last filename + that was found before, the module needs to reset it's internal queue state. + This means that no more preopens will be pushed to helper processes belonging to the + former queue state. In order to debug or audit such queue resets you can use this option to specify at what + log level details are logged. + + + Defaults to the log level 5. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + + + preopen:push_log_level = LOGLEVEL + + + In order to debug or audit the usage of the preopen logic + you can use this option to specify at what log level details + about filenames actually pushed to preopen helper processes are logged. + This means they will actually be preopened soon. + + + Defaults to the log level 3. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + + + preopen:queue_log_level = LOGLEVEL + + + In order to debug details about internal queue processing + you can use this option to specify at what log level the details are logged. + + + Defaults to the log level 10. + See also smb.conf5 + in the '' section + for special handling of the 'preopen' debug class. + + + + diff --git a/source3/modules/vfs_preopen.c b/source3/modules/vfs_preopen.c index 4dc5ba30b1d..ab0080c69f3 100644 --- a/source3/modules/vfs_preopen.c +++ b/source3/modules/vfs_preopen.c @@ -52,6 +52,14 @@ struct preopen_state { size_t to_read; /* How many bytes to read in children? */ int queue_max; + int queue_dbglvl; /* DBGLVL_DEBUG by default */ + int nomatch_dbglvl; /* DBGLVL_INFO by default */ + int match_dbglvl; /* DBGLVL_INFO by default */ + int reset_dbglvl; /* DBGLVL_INFO by default */ + int nodigits_dbglvl; /* DBGLVL_WARNING by default */ + int founddigits_dbglvl; /* DBGLVL_NOTICE by default */ + int push_dbglvl; /* DBGLVL_NOTICE by default */ + char *template_fname; /* Filename to be sent to children */ size_t number_start; /* start offset into "template_fname" */ int num_digits; /* How many digits is the number long? */ @@ -82,6 +90,16 @@ static void preopen_queue_run(struct preopen_state *state) char *pdelimiter; char delimiter; + DBG_PREFIX(state->queue_dbglvl, ("START: " + "last_fname[%s] start_offset=%zu num_digits=%d " + "last_pushed_num=%"PRIu64" queue_end_num=%"PRIu64" num_helpers=%d\n", + state->template_fname, + state->number_start, + state->num_digits, + state->fnum_sent, + state->fnum_queue_end, + state->num_helpers)); + pdelimiter = state->template_fname + state->number_start + state->num_digits; delimiter = *pdelimiter; @@ -100,6 +118,14 @@ static void preopen_queue_run(struct preopen_state *state) } if (helper == state->num_helpers) { /* everyone is busy */ + DBG_PREFIX(state->queue_dbglvl, ("BUSY: " + "template_fname[%s] start_offset=%zu num_digits=%d " + "last_pushed_num=%"PRIu64" queue_end_num=%"PRIu64"\n", + state->template_fname, + state->number_start, + state->num_digits, + state->fnum_sent, + state->fnum_queue_end)); return; } @@ -109,6 +135,10 @@ static void preopen_queue_run(struct preopen_state *state) (long long unsigned int)(state->fnum_sent + 1)); *pdelimiter = delimiter; + DBG_PREFIX(state->push_dbglvl, ( + "PUSH: fullpath[%s] to helper(idx=%d)\n", + state->template_fname, helper)); + to_write = talloc_get_size(state->template_fname); written = write_data(state->helpers[helper].fd, state->template_fname, to_write); @@ -119,6 +149,14 @@ static void preopen_queue_run(struct preopen_state *state) } state->fnum_sent += 1; } + DBG_PREFIX(state->queue_dbglvl, ("END: " + "template_fname[%s] start_offset=%zu num_digits=%d " + "last_pushed_num=%"PRIu64" queue_end_num=%"PRIu64"\n", + state->template_fname, + state->number_start, + state->num_digits, + state->fnum_sent, + state->fnum_queue_end)); } static void preopen_helper_readable(struct tevent_context *ev, @@ -142,7 +180,9 @@ static void preopen_helper_readable(struct tevent_context *ev, helper->busy = false; + DBG_PREFIX(state->queue_dbglvl, ("BEFORE: preopen_queue_run\n")); preopen_queue_run(state); + DBG_PREFIX(state->queue_dbglvl, ("AFTER: preopen_queue_run\n")); } static int preopen_helpers_destructor(struct preopen_state *c) @@ -338,6 +378,14 @@ static struct preopen_state *preopen_state_get(vfs_handle_struct *handle) return NULL; } + state->queue_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "queue_log_level", DBGLVL_DEBUG); + state->nomatch_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "nomatch_log_level", DBGLVL_INFO); + state->match_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "match_log_level", DBGLVL_INFO); + state->reset_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "reset_log_level", DBGLVL_INFO); + state->nodigits_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "nodigits_log_level", DBGLVL_WARNING); + state->founddigits_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "founddigits_log_level", DBGLVL_NOTICE); + state->push_dbglvl = lp_parm_int(SNUM(handle->conn), "preopen", "push_log_level", DBGLVL_NOTICE); + if (lp_parm_bool(SNUM(handle->conn), "preopen", "posix-basic-regex", false)) { status = samba_path_matching_regex_sub1_create(state, namelist, @@ -501,7 +549,7 @@ static int preopen_openat(struct vfs_handle_struct *handle, ssize_t replace_end = -1; bool need_reset = false; - DEBUG(10, ("preopen_open called on %s\n", smb_fname_str_dbg(smb_fname))); + DBG_DEBUG("called on %s\n", smb_fname_str_dbg(smb_fname)); state = preopen_state_get(handle); if (state == NULL) { @@ -552,15 +600,28 @@ static int preopen_openat(struct vfs_handle_struct *handle, match_idx = -1; } if (match_idx < 0) { - DEBUG(10, ("%s does not match the preopen:names list\n", - smb_fname_str_dbg(smb_fname))); + DBG_PREFIX(state->nomatch_dbglvl, ( + "No match with the preopen:names list by name[%s]\n", + smb_fname_str_dbg(smb_fname))); return res; } + if (replace_start != -1 && replace_end != -1) { + DBG_PREFIX(state->match_dbglvl, ( + "Pattern(idx=%zd) from preopen:names list matched name[%s] hints(start=%zd,end=%zd)\n", + match_idx, smb_fname_str_dbg(smb_fname), replace_start, replace_end)); + } else { + DBG_PREFIX(state->match_dbglvl, ( + "Pattern(idx=%zd) from preopen:names list matched name[%s]\n", + match_idx, smb_fname_str_dbg(smb_fname))); + } + new_template = talloc_asprintf( state, "%s/%s", dirname, smb_fname->base_name); if (new_template == NULL) { + DBG_ERR("talloc_asprintf(%s/%s) failed\n", + dirname, smb_fname_str_dbg(smb_fname)); return res; } @@ -572,40 +633,64 @@ static int preopen_openat(struct vfs_handle_struct *handle, if (!preopen_parse_fname(new_template, &num, &new_start, &new_digits)) { + DBG_PREFIX(state->nodigits_dbglvl, ( + "Pattern(idx=%zd) no valid digits found on fullpath[%s]\n", + match_idx, new_template)); TALLOC_FREE(new_template); return res; } new_end = new_start + new_digits; + DBG_PREFIX(state->founddigits_dbglvl, ( + "Pattern(idx=%zd) found num_digits[%d] start_offset[%zd] parsed_num[%lu] fullpath[%s]\n", + match_idx, new_digits, new_start, num, new_template)); + if (state->last_match_idx != match_idx) { /* * If a different pattern caused the match * we better reset the queue */ + if (state->last_match_idx != -1) { + DBG_PREFIX(state->reset_dbglvl, ("RESET: " + "pattern changed from idx=%zd to idx=%zd by fullpath[%s]\n", + state->last_match_idx, match_idx, new_template)); + } need_reset = true; } else if (state->number_start != new_start) { /* * If the digits started at a different possition * we better reset the queue */ + DBG_PREFIX(state->reset_dbglvl, ("RESET: " + "start_offset changed from byte=%zd to byte=%zd by fullpath[%s]\n", + state->number_start, new_start, new_template)); need_reset = true; } else if (state->num_digits != new_digits) { /* * If number of digits changed * we better reset the queue */ + DBG_PREFIX(state->reset_dbglvl, ("RESET: " + "num_digits changed %d to %d by fullpath[%s]\n", + state->num_digits, new_digits, new_template)); need_reset = true; } else if (strncmp(state->template_fname, new_template, new_start) != 0) { /* * If name before the digits changed * we better reset the queue */ + DBG_PREFIX(state->reset_dbglvl, ("RESET: " + "leading pathprefix[%.*s] changed by fullpath[%s]\n", + (int)state->number_start, state->template_fname, new_template)); need_reset = true; } else if (strcmp(state->template_fname + new_end, new_template + new_end) != 0) { /* * If name after the digits changed * we better reset the queue */ + DBG_PREFIX(state->reset_dbglvl, ("RESET: " + "trailing suffix[%s] changed by fullpath[%s]\n", + state->template_fname + new_end, new_template)); need_reset = true; } @@ -644,7 +729,9 @@ static int preopen_openat(struct vfs_handle_struct *handle, num_max = num_digits_max_value(state->num_digits); state->fnum_queue_end = MIN(num_max, num + state->queue_max); + DBG_PREFIX(state->queue_dbglvl, ("BEFORE: preopen_queue_run\n")); preopen_queue_run(state); + DBG_PREFIX(state->queue_dbglvl, ("AFTER: preopen_queue_run\n")); return res; }