diff --git a/README.md b/README.md index 11c56f6..9a74cd5 100644 --- a/README.md +++ b/README.md @@ -140,6 +140,9 @@ All with no changes to your application and minimal overhead. @: @:- e.g., xyz@/path/to.php:10-20 + --peek-max-len= Limit each peeked value to `len` chars + (increase `-b` for longer output) + (default: 255) -D, --peek-pdo Peek at the SQL and arguments of PDO queries. Emits varpeek events. -g, --peek-global= Peek at the contents of a global var diff --git a/phpspy.c b/phpspy.c index 22ddd14..d4d981d 100644 --- a/phpspy.c +++ b/phpspy.c @@ -39,6 +39,7 @@ static char *opt_path_child_out = "phpspy.%d.out"; static char *opt_path_child_err = "phpspy.%d.err"; static char *opt_phpv = "auto"; static int opt_pause = 0; +static int opt_peek_max_len = PHPSPY_DEFAULT_PEEK_MAX_LEN; static int (*opt_event_handler)(struct trace_context_s *context, int event_type) = event_handler_fout; static char *opt_event_handler_opts = NULL; static int opt_continue_on_error = 0; @@ -197,6 +198,9 @@ void usage(FILE *fp, int exit_code) { fprintf(fp, " @:\n"); fprintf(fp, " @:-\n"); fprintf(fp, " e.g., xyz@/path/to.php:10-20\n"); + fprintf(fp, " --peek-max-len= Limit each peeked value to `len` chars\n"); + fprintf(fp, " (increase `-b` for longer output)\n"); + fprintf(fp, " (default: %d)\n", opt_peek_max_len); fprintf(fp, " -D, --peek-pdo Peek at the SQL and arguments of PDO\n"); fprintf(fp, " queries. Emits varpeek events.\n"); fprintf(fp, " -g, --peek-global= Peek at the contents of a global var\n"); @@ -275,6 +279,7 @@ static void parse_opts(int argc, char **argv) { { "version", no_argument, NULL, 'v' }, { "pause-process", no_argument, NULL, 'S' }, { "peek-var", required_argument, NULL, 'e' }, + { "peek-max-len", required_argument, NULL, PHPSPY_LONGOPT_PEEK_MAX_LEN }, { "peek-global", required_argument, NULL, 'g' }, { "peek-pdo", no_argument, NULL, 'D' }, { "top", no_argument, NULL, 't' }, @@ -385,6 +390,7 @@ static void parse_opts(int argc, char **argv) { exit(0); case 'S': opt_pause = 1; break; case 'e': varpeek_add(optarg); break; + case PHPSPY_LONGOPT_PEEK_MAX_LEN: opt_peek_max_len = atoi_with_min_or_exit("--peek-max-len", optarg, 1); break; case 'g': glopeek_add(optarg); break; case 't': opt_top_mode = 1; break; case PHPSPY_LONGOPT_LIBNAME_AWK_PATT: opt_libname_awk_patt = optarg; break; @@ -447,6 +453,15 @@ int main_pid(pid_t pid) { } #endif + context.peek_buf_size = (size_t)opt_peek_max_len + 1; + context.peek_buf = malloc(context.peek_buf_size); + if (!context.peek_buf) { + log_perror("main_pid: malloc peek buffer"); + if (context.stack_ptrs) utarray_free(context.stack_ptrs); + context.event_handler(&context, PHPSPY_TRACE_EVENT_DEINIT); + return PHPSPY_ERR; + } + /* calc stop_time */ stop_time = NULL; if (in_pgrep_mode) { @@ -503,6 +518,7 @@ int main_pid(pid_t pid) { if (context.stack_ptrs) utarray_free(context.stack_ptrs); context.event_handler(&context, PHPSPY_TRACE_EVENT_DEINIT); + free(context.peek_buf); /* in pgrep mode, trigger done condition if we went over the trace limit. it is ok for multiple threads to call this. */ diff --git a/phpspy.h b/phpspy.h index 16fc0f0..6c558cf 100644 --- a/phpspy.h +++ b/phpspy.h @@ -50,6 +50,7 @@ #ifndef PHPSPY_STR_SIZE #define PHPSPY_STR_SIZE 256 #endif +#define PHPSPY_DEFAULT_PEEK_MAX_LEN (PHPSPY_STR_SIZE - 1) #define PHPSPY_MAX_ARRAY_BUCKETS 128 #define PHPSPY_MAX_ARRAY_TABLE_SIZE 512 #define PHPSPY_HASH_FLAG_PACKED (1 << 2) @@ -96,6 +97,7 @@ enum { PHPSPY_LONGOPT_LIBNAME_AWK_PATT, PHPSPY_LONGOPT_EVENT_HANDLER, PHPSPY_LONGOPT_EVENT_HANDLER_OPTS, + PHPSPY_LONGOPT_PEEK_MAX_LEN, }; typedef struct varpeek_var_s { @@ -177,8 +179,9 @@ typedef struct trace_context_s { void *event_udata; int (*event_handler)(struct trace_context_s *context, int event_type); const char *event_handler_opts; - char buf[PHPSPY_STR_SIZE]; - size_t buf_len; + char *peek_buf; + size_t peek_buf_size; + size_t peek_buf_len; UT_array *stack_ptrs; } trace_context; diff --git a/phpspy_trace.c b/phpspy_trace.c index 2711d22..3057536 100644 --- a/phpspy_trace.c +++ b/phpspy_trace.c @@ -292,12 +292,12 @@ static int trace_globals(trace_context *context) { /* Print the element within the array */ - rv = sprint_zarray_val(context, garray, gentry->varname, context->buf, sizeof(context->buf), &context->buf_len); + rv = sprint_zarray_val(context, garray, gentry->varname, context->peek_buf, context->peek_buf_size, &context->peek_buf_len); if (rv == PHPSPY_OK) { context->event.glopeek.gentry = gentry; - context->event.glopeek.zval_str = context->buf; - context->event.glopeek.zval_str_len = context->buf_len; + context->event.glopeek.zval_str = context->peek_buf; + context->event.glopeek.zval_str_len = context->peek_buf_len; try(rv, context->event_handler(context, PHPSPY_TRACE_EVENT_GLOPEEK)); } } @@ -319,7 +319,7 @@ static int trace_globals(trace_context *context) { */ static int trace_locals(trace_context *context, zend_op *zop, zend_execute_data *remote_execute_data, zend_op_array *op_array, char *file, int file_len) { int rv, i, num_vars_found, num_vars_peeking; - char tmp[PHPSPY_STR_SIZE]; + char var_name[PHPSPY_STR_SIZE]; size_t tmp_len; zend_string *zstrp; varpeek_entry *entry; @@ -336,16 +336,16 @@ static int trace_locals(trace_context *context, zend_op *zop, zend_execute_data for (i = 0; i < op_array->last_var; i++) { try_copy_proc_mem("var", op_array->vars + i, &zstrp, sizeof(zstrp)); - try(rv, sprint_zstring(context, "var", zstrp, tmp, sizeof(tmp), &tmp_len)); - HASH_FIND(hh, entry->varmap, tmp, tmp_len, var); + try(rv, sprint_zstring(context, "var", zstrp, var_name, sizeof(var_name), &tmp_len)); + HASH_FIND(hh, entry->varmap, var_name, tmp_len, var); if (!var) continue; num_vars_found += 1; /* See ZEND_CALL_VAR_NUM macro in php-src */ try_copy_proc_mem("zval", ((zval*)(remote_execute_data)) + ((int)(5 + i)), &zv, sizeof(zv)); - try(rv, sprint_zval(context, &zv, tmp, sizeof(tmp), &tmp_len)); + try(rv, sprint_zval(context, &zv, context->peek_buf, context->peek_buf_size, &tmp_len)); context->event.varpeek.entry = entry; context->event.varpeek.var = var; - context->event.varpeek.zval_str = tmp; + context->event.varpeek.zval_str = context->peek_buf; context->event.varpeek.zval_str_len = tmp_len; try(rv, context->event_handler(context, PHPSPY_TRACE_EVENT_VARPEEK)); if (num_vars_found >= num_vars_peeking) break; @@ -366,7 +366,8 @@ static int trace_pdo(trace_context *context, zend_execute_data *remote_execute_d zend_object lobj; pdo_stmt_t lstmt; zval first_arg; - char buf[PHPSPY_STR_SIZE]; + char *buf = context->peek_buf; + size_t buf_size = context->peek_buf_size; size_t buf_len; uint8_t this_type; @@ -401,7 +402,7 @@ static int trace_pdo(trace_context *context, zend_execute_data *remote_execute_d if (lobj.properties_table[0].u1.v.type == PHPSPY_ZVAL_TYPE_STRING) { try(rv, sprint_zstring(context, "pdo_qs", - lobj.properties_table[0].value.str, buf, sizeof(buf), &buf_len)); + lobj.properties_table[0].value.str, buf, buf_size, &buf_len)); context->event.varpeek.entry = &entry; context->event.varpeek.var = &var_sql; context->event.varpeek.zval_str = buf; @@ -414,7 +415,7 @@ static int trace_pdo(trace_context *context, zend_execute_data *remote_execute_d try_copy_proc_mem("pdo_arg0", ((zval*)remote_execute_data) + 5, &first_arg, sizeof(first_arg)); if (first_arg.u1.v.type == PHPSPY_ZVAL_TYPE_ARRAY) { - rv = sprint_zarray(context, first_arg.value.arr, buf, sizeof(buf), &buf_len); + rv = sprint_zarray(context, first_arg.value.arr, buf, buf_size, &buf_len); if (rv == PHPSPY_OK && buf_len > 0) { context->event.varpeek.entry = &entry; context->event.varpeek.var = &var_args; @@ -428,7 +429,7 @@ static int trace_pdo(trace_context *context, zend_execute_data *remote_execute_d void *rstmt = (void*)((char*)robj - offsetof(pdo_stmt_t, std)); try_copy_proc_mem("pdo_stmt", rstmt, &lstmt, sizeof(lstmt)); if (lstmt.bound_params) { - rv = sprint_pdo_binds(context, lstmt.bound_params, buf, sizeof(buf), &buf_len); + rv = sprint_pdo_binds(context, lstmt.bound_params, buf, buf_size, &buf_len); if (rv == PHPSPY_OK && buf_len > 0) { context->event.varpeek.entry = &entry; context->event.varpeek.var = &var_args; @@ -445,7 +446,7 @@ static int trace_pdo(trace_context *context, zend_execute_data *remote_execute_d ((zval*)remote_execute_data) + 5, &first_arg, sizeof(first_arg)); if (first_arg.u1.v.type == PHPSPY_ZVAL_TYPE_STRING) { try(rv, sprint_zstring(context, "pdo_sql", - first_arg.value.str, buf, sizeof(buf), &buf_len)); + first_arg.value.str, buf, buf_size, &buf_len)); context->event.varpeek.entry = &entry; context->event.varpeek.var = &var_sql; context->event.varpeek.zval_str = buf; diff --git a/tests/test_glopeek.sh b/tests/test_glopeek.sh index 792acda..314f261 100755 --- a/tests/test_glopeek.sh +++ b/tests/test_glopeek.sh @@ -32,3 +32,16 @@ declare -A test_expected test_expected[glopeek1 ]="^# glopeek server.Ez = 1" test_expected[glopeek2 ]="^# glopeek server.FY = 2" test_invoke + +peek_length=5000 +peek_buffer_size=8192 +php_src=""$php_file" +test_phpspy_opts=(--limit=0 --buffer-size "$peek_buffer_size" --peek-max-len "$peek_length" --peek-global "globals.long_value" -- "${PHP[@]}" "$php_file") +declare -A test_expected +test_expected[glopeek_long]="^# glopeek globals.long_value = x{$peek_length}$" +test_invoke +rm -f "$php_file" diff --git a/tests/test_varpeek.sh b/tests/test_varpeek.sh index 4c02690..d580e4e 100755 --- a/tests/test_varpeek.sh +++ b/tests/test_varpeek.sh @@ -34,3 +34,35 @@ declare -A test_expected test_expected[varpeek2 ]="^# varpeek a@$php_file:4 = k=42,j=dolphin$" test_invoke rm -f "$php_file" + +peek_length=5000 +peek_buffer_size=8192 +php_src=""$php_file" +test_phpspy_opts=(--limit=0 --buffer-size "$peek_buffer_size" --peek-max-len "$peek_length" --peek-var "a@$php_file:4" -- "${PHP[@]}" "$php_file") +declare -A test_expected +test_expected[varpeek_long]="^# varpeek a@$php_file:4 = x{$peek_length}$" +test_invoke +rm -f "$php_file" + +help_output=$("$PHPSPY" --help) +test_assert_re peek_max_len_help "peek-max-len=" "$help_output" + +virtual_memory_limit_kib=131072 +oversized_peek_length=268435456 +allocation_error=$( + ulimit -v "$virtual_memory_limit_kib" + "$PHPSPY" \ + --peek-max-len "$oversized_peek_length" \ + --limit=1 \ + --child-stdout=/dev/null \ + --child-stderr=/dev/null \ + -- "${PHP[@]}" -r 'sleep(1);' 2>&1 +) +test_assert_re peek_max_len_allocation_error "^main_pid: malloc peek buffer:" "$allocation_error" diff --git a/tests/test_varpeek_pdo.sh b/tests/test_varpeek_pdo.sh index 8e59a01..9ba3bf4 100755 --- a/tests/test_varpeek_pdo.sh +++ b/tests/test_varpeek_pdo.sh @@ -27,6 +27,39 @@ test_expected[pdo_args_execute_array]="^# varpeek #pdo_args@PDOStatement::execut test_invoke rm -f "$php_file" +# Long query +peek_length=5000 +peek_max_length=6000 +peek_buffer_size=8192 +php_src="sqliteCreateFunction('slow', function (\$x) { sleep(1); return \$x; }, 1); +\$stmt = \$pdo->prepare(\"SELECT slow(:value) AS r WHERE '\$long_sql_part' <> ''\"); +\$stmt->execute([':value' => 'ok']);" +php_file=$(mktemp) +echo "$php_src" >"$php_file" +test_phpspy_opts=(--limit=1 --buffer-size "$peek_buffer_size" --peek-max-len "$peek_max_length" --peek-pdo -- "${PHP[@]}" "$php_file") +declare -A test_expected +test_expected[pdo_sql_long]="^# varpeek #pdo_sql@PDOStatement::execute = SELECT slow\(:value\) AS r WHERE 'x{$peek_length}' <> ''$" +test_invoke +rm -f "$php_file" + +# Long execute argument +php_src="sqliteCreateFunction('slow', function (\$x) { sleep(1); return \$x; }, 1); +\$stmt = \$pdo->prepare('SELECT slow(:value) AS r'); +\$stmt->execute([':value' => \$long_value]);" +php_file=$(mktemp) +echo "$php_src" >"$php_file" +test_phpspy_opts=(--limit=1 --buffer-size "$peek_buffer_size" --peek-max-len "$peek_max_length" --peek-pdo -- "${PHP[@]}" "$php_file") +declare -A test_expected +test_expected[pdo_args_long]="^# varpeek #pdo_args@PDOStatement::execute = :value=x{$peek_length}$" +test_invoke +rm -f "$php_file" + # PDOStatement::execute with packed (positional) array read -r -d '' php_src <<'EOD'