diff --git a/appsec/src/extension/commands/request_exec.c b/appsec/src/extension/commands/request_exec.c index ab2484714e..3c6b35d876 100644 --- a/appsec/src/extension/commands/request_exec.c +++ b/appsec/src/extension/commands/request_exec.c @@ -38,7 +38,7 @@ dd_result dd_request_exec(dd_conn *nonnull conn, zval *nonnull data) struct ctx ctx = {.data = data}; - return dd_command_exec(conn, &_spec, &ctx); + return dd_command_exec_req_info(conn, &_spec, &ctx.req_info); } static dd_result _pack_command(mpack_writer_t *nonnull w, void *nonnull _ctx) diff --git a/appsec/src/extension/commands/request_init.c b/appsec/src/extension/commands/request_init.c index dc8632bd11..54db5ef7ed 100644 --- a/appsec/src/extension/commands/request_init.c +++ b/appsec/src/extension/commands/request_init.c @@ -44,7 +44,7 @@ static const dd_command_spec _spec = { dd_result dd_request_init( dd_conn *nonnull conn, struct req_info_init *nonnull ctx) { - return dd_command_exec(conn, &_spec, ctx); + return dd_command_exec_req_info(conn, &_spec, &ctx->req_info); } static dd_result _request_pack(mpack_writer_t *nonnull w, void *nonnull _ctx) diff --git a/appsec/src/extension/commands/request_shutdown.c b/appsec/src/extension/commands/request_shutdown.c index 0f66c3e380..2c4a580ef7 100644 --- a/appsec/src/extension/commands/request_shutdown.c +++ b/appsec/src/extension/commands/request_shutdown.c @@ -28,7 +28,7 @@ static const dd_command_spec _spec = { dd_result dd_request_shutdown( dd_conn *nonnull conn, struct req_shutdown_info *nonnull req_info) { - return dd_command_exec(conn, &_spec, req_info); + return dd_command_exec_req_info(conn, &_spec, &req_info->req_info); } static dd_result _request_pack(mpack_writer_t *nonnull w, void *nonnull ctx) diff --git a/appsec/src/extension/commands_ctx.h b/appsec/src/extension/commands_ctx.h index 9d78a3d53c..ab185db9d2 100644 --- a/appsec/src/extension/commands_ctx.h +++ b/appsec/src/extension/commands_ctx.h @@ -4,6 +4,7 @@ #include struct req_info { + const char *nullable command_name; // for logging zend_object *nullable root_span; zend_string *nullable client_ip; }; diff --git a/appsec/src/extension/commands_helpers.c b/appsec/src/extension/commands_helpers.c index 5ba4e5e55e..bd236bf10d 100644 --- a/appsec/src/extension/commands_helpers.c +++ b/appsec/src/extension/commands_helpers.c @@ -194,6 +194,13 @@ dd_result ATTR_WARN_UNUSED dd_command_exec(dd_conn *nonnull conn, return _dd_command_exec(conn, false, spec, ctx); } +dd_result ATTR_WARN_UNUSED dd_command_exec_req_info(dd_conn *nonnull conn, + const dd_command_spec *nonnull spec, struct req_info *nonnull ctx) +{ + ctx->command_name = spec->name; + return _dd_command_exec(conn, false, spec, ctx); +} + dd_result ATTR_WARN_UNUSED dd_command_exec_cred(dd_conn *nonnull conn, const dd_command_spec *nonnull spec, void *unspecnull ctx) { @@ -361,6 +368,8 @@ static void _command_process_block_parameters(mpack_node_t root) } } + mlog(dd_log_debug, "Blocking parameters: status_code=%d, type=%d", + status_code, type); dd_set_block_code_and_type(status_code, type); } @@ -425,7 +434,8 @@ dd_result dd_command_proc_resp_verd_span_data( if (verd_len > INT_MAX) { verd_len = INT_MAX; } - mlog(dd_log_debug, "Verdict of request_init was '%.*s'", (int)verd_len, + mlog(dd_log_debug, "Verdict of %s was '%.*s'", + ctx->command_name ? ctx->command_name : "(unknown)", (int)verd_len, verd_str); } diff --git a/appsec/src/extension/commands_helpers.h b/appsec/src/extension/commands_helpers.h index 58154031c7..45321bb0aa 100644 --- a/appsec/src/extension/commands_helpers.h +++ b/appsec/src/extension/commands_helpers.h @@ -25,6 +25,9 @@ typedef struct _dd_command_spec { dd_result ATTR_WARN_UNUSED dd_command_exec(dd_conn *nonnull conn, const dd_command_spec *nonnull spec, void *unspecnull ctx); +dd_result ATTR_WARN_UNUSED dd_command_exec_req_info(dd_conn *nonnull conn, + const dd_command_spec *nonnull spec, struct req_info *nonnull ctx); + dd_result ATTR_WARN_UNUSED dd_command_exec_cred(dd_conn *nonnull conn, const dd_command_spec *nonnull spec, void *unspecnull ctx); diff --git a/appsec/src/extension/php_compat.h b/appsec/src/extension/php_compat.h index 736cf9a2d9..702a4c84b3 100644 --- a/appsec/src/extension/php_compat.h +++ b/appsec/src/extension/php_compat.h @@ -29,7 +29,15 @@ static zend_always_inline zend_string *zend_string_init_interned( const char *str, size_t len, int persistent) { zend_string *ret = zend_string_init(str, len, persistent); +# ifdef ZTS + // believe it or not zend_new_interned_string() is an identity function + // set the interned flag manually so zend_string_release() is a no-op + GC_FLAGS(ret) |= IS_STR_INTERNED; + zend_string_hash_val(ret); + return ret; +# else return zend_new_interned_string(ret); +# endif } #endif diff --git a/appsec/src/extension/request_abort.c b/appsec/src/extension/request_abort.c index 03a89ae084..08b8744666 100644 --- a/appsec/src/extension/request_abort.c +++ b/appsec/src/extension/request_abort.c @@ -128,6 +128,7 @@ static void _set_content_type(const char *nonnull content_type) static void _set_output(const char *nonnull output, size_t length) { size_t written = php_output_write(output, length); + mlog_g(dd_log_debug, "php_output_write() returned %zu", written); if (written != length) { mlog(dd_log_info, "could not write full response (written: %zu)", written); @@ -146,8 +147,8 @@ static dd_response_type _get_response_type_from_accept_header( dd_php_get_string_elem_cstr(_server, LSTRARG("HTTP_ACCEPT")); if (!accept_zstr) { mlog(dd_log_info, - "Could not find Accept header, using default content-type"); - goto exit; + "Could not find Accept header, using default content-type (json)"); + return response_type_json; } const char *accept_end = ZSTR_VAL(accept_zstr) + ZSTR_LEN(accept_zstr); @@ -172,7 +173,7 @@ static dd_response_type _get_response_type_from_accept_header( return response_type_html; } -exit: + mlog_g(dd_log_debug, "No recognized accept header, defaulting to json"); return response_type_json; } @@ -214,6 +215,7 @@ void dd_request_abort_redirect() } if (!_abort_prelude()) { + mlog(dd_log_debug, "_abort_prelude has failed"); return; } @@ -221,6 +223,9 @@ void dd_request_abort_redirect() uint line_len = (uint)spprintf( &line, 0, "Location: %s", ZSTR_VAL(_redirection_location)); + mlog_g(dd_log_debug, "Will forward to %s with status %d", + ZSTR_VAL(_redirection_location), _redirection_response_code); + SG(sapi_headers).http_response_code = _redirection_response_code; int res = sapi_header_op(SAPI_HEADER_REPLACE, &(sapi_header_line){.line = line, .line_len = line_len}); @@ -232,7 +237,7 @@ void dd_request_abort_redirect() efree(line); if (sapi_flush() == SUCCESS) { - mlog(dd_log_debug, "Successful call to sapi_flush()"); + mlog_g(dd_log_debug, "Successful call to sapi_flush()"); } else { mlog(dd_log_warning, "Call to sapi_flush() failed"); } @@ -299,6 +304,7 @@ void _request_abort_static_page(int response_code, int type) } if (!_abort_prelude()) { + mlog(dd_log_debug, "_abort_prelude has failed"); zend_string_release(body); return; } @@ -434,8 +440,10 @@ static void _suppress_error_reporting(void); ATTR_FORMAT(1, 2) static void _emit_error(const char *format, ...) { - va_list args; + mlog_g(dd_log_debug, "_emit_error() called: during_request_startup: %d", + PG(during_request_startup)); + va_list args; va_start(args, format); if (PG(during_request_startup)) { /* if emitting error during startup, RSHUTDOWN will not run (except fpm) @@ -615,6 +623,7 @@ static zend_string *nonnull _get_json_blocking_template() return _empty_zstr; } if (ZSTR_LEN(body_error_json) == 0) { + zend_string_release(body_error_json); return _body_error_json_def; } @@ -635,6 +644,7 @@ static zend_string *nonnull _get_html_blocking_template() return _empty_zstr; } if (ZSTR_LEN(body_error_html) == 0) { + zend_string_release(body_error_html); return _body_error_html_def; } diff --git a/appsec/tests/integration/src/docker/apache2-fpm/entrypoint.sh b/appsec/tests/integration/src/docker/apache2-fpm/entrypoint.sh index f3f7433555..ca5cb7faac 100755 --- a/appsec/tests/integration/src/docker/apache2-fpm/entrypoint.sh +++ b/appsec/tests/integration/src/docker/apache2-fpm/entrypoint.sh @@ -20,4 +20,4 @@ enable_extensions.sh php-fpm -y /etc/php-fpm.conf -c /etc/php/php.ini service apache2 start -exec tail -F "${LOGS_PHP[@]}" "${LOGS_APACHE[@]}" +exec tail -n +1 -F "${LOGS_PHP[@]}" "${LOGS_APACHE[@]}" diff --git a/appsec/tests/integration/src/docker/apache2-mod/entrypoint.sh b/appsec/tests/integration/src/docker/apache2-mod/entrypoint.sh index df94b70c57..81b37162c8 100755 --- a/appsec/tests/integration/src/docker/apache2-mod/entrypoint.sh +++ b/appsec/tests/integration/src/docker/apache2-mod/entrypoint.sh @@ -19,4 +19,4 @@ enable_extensions.sh service apache2 start -exec tail -F "${LOGS_PHP[@]}" "${LOGS_APACHE[@]}" +exec tail -n +1 -F "${LOGS_PHP[@]}" "${LOGS_APACHE[@]}" diff --git a/appsec/tests/integration/src/docker/nginx-fpm/entrypoint.sh b/appsec/tests/integration/src/docker/nginx-fpm/entrypoint.sh index a3068651e9..d26b3152ee 100755 --- a/appsec/tests/integration/src/docker/nginx-fpm/entrypoint.sh +++ b/appsec/tests/integration/src/docker/nginx-fpm/entrypoint.sh @@ -16,4 +16,4 @@ enable_extensions.sh php-fpm -y /etc/php-fpm.conf -c /etc/php/php.ini service nginx start -exec tail -F "${LOGS_PHP[@]}" "${LOGS_NGINX[@]}" +exec tail -n +1 -F "${LOGS_PHP[@]}" "${LOGS_NGINX[@]}" diff --git a/appsec/tests/integration/src/test/www/roadrunner/run.sh b/appsec/tests/integration/src/test/www/roadrunner/run.sh index a0e886fd77..7135d342ad 100755 --- a/appsec/tests/integration/src/test/www/roadrunner/run.sh +++ b/appsec/tests/integration/src/test/www/roadrunner/run.sh @@ -18,5 +18,5 @@ echo datadog.trace.cli_enabled=true >> /etc/php/php.ini ./rr serve 2>&1 >> /tmp/logs/rr.log & -tail -f "${LOGS_PHP[@]}" +tail -n +1 -F "${LOGS_PHP[@]}"