From 43fe9be6fa31242ec670d6214e31c6dbe87eb942 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=D0=9D=D0=B0=D0=B8=D0=BB=D1=8F=20=D0=90=D0=BB=D0=B0=D1=88?= =?UTF-8?q?=D0=BA=D0=BE=D0=B2=D0=B0?= Date: Thu, 13 Feb 2025 13:15:06 +0300 Subject: [PATCH] =?UTF-8?q?SUPPORT-8890.=20=D0=94=D0=BE=D0=B1=D0=B0=D0=B2?= =?UTF-8?q?=D0=BB=D0=B5=D0=BD=D0=BE=20=D0=BB=D0=BE=D0=B3=D0=B8=D1=80=D0=BE?= =?UTF-8?q?=D0=B2=D0=B0=D0=BD=D0=B8=D0=B5=20=D0=B2=D1=80=D0=B5=D0=BC=D0=B5?= =?UTF-8?q?=D0=BD=D0=B8=20=D0=BE=D0=B1=D1=80=D0=B0=D0=B1=D0=BE=D1=82=D0=BA?= =?UTF-8?q?=D0=B8=20=D0=B7=D0=B0=D0=BF=D1=80=D0=BE=D1=81=D0=BE=D0=B2=20(?= =?UTF-8?q?=D0=B2=D0=BA=D0=BB=D1=8E=D1=87=D0=B0=D0=B5=D1=82=D1=81=D1=8F=20?= =?UTF-8?q?=D0=BF=D0=B5=D1=80=D0=B5=D0=BC=D0=B5=D0=BD=D0=BD=D0=BE=D0=B9=20?= =?UTF-8?q?=D0=BE=D0=BA=D1=80=D1=83=D0=B6=D0=B5=D0=BD=D0=B8=D1=8F=20SIGN?= =?UTF-8?q?=5FLOG=5FTIME)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit (cherry picked from commit 1e10dbe5c565a621eab050c1c0d44a499318e34c) # Conflicts: # CMakeLists.txt # src/modules/service_sign.c --- CMakeLists.txt | 1 + README.md | 16 ++++ src/modules/service_sign.c | 19 ++++- src/utils/cryptopro.c | 34 +++++++- src/utils/cryptopro.h | 17 ++-- src/utils/timer.c | 162 +++++++++++++++++++++++++++++++++++++ src/utils/timer.h | 60 ++++++++++++++ 7 files changed, 297 insertions(+), 12 deletions(-) create mode 100644 src/utils/timer.c create mode 100644 src/utils/timer.h diff --git a/CMakeLists.txt b/CMakeLists.txt index b970d76..f7d6ee5 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -126,6 +126,7 @@ ADD_EXECUTABLE (${PROJECT_NAME} ${UTILS_DIR}/library.c ${UTILS_DIR}/logger.c ${UTILS_DIR}/str_t.c + ${UTILS_DIR}/timer.c ${UTILS_DIR}/uuid.c ${FCGISRV_DIR}/fcgi_map.c ${FCGISRV_DIR}/fcgi_server.c diff --git a/README.md b/README.md index 96c34dc..a4b27e3 100644 --- a/README.md +++ b/README.md @@ -100,3 +100,19 @@ sign_cert_password = \*\*\*\* *\# пароль от контейнера* - В секции **\[verify\]** задать настройки проверки подписи маркера доступа: location = /verify *\# значение по умолчанию: /verify* esia_cert_thumbprint = sha1_thumbprint_of_esia_cert0,sha1_thumbprint_of_esia_cert1 *\# список SHA1 отпечатков сертификатов ЕСИА, указанных через запятую (без пробелов)* + +## Логирование времени обработки запросов + +***Для включения*** логирования времени обработки запросов необходимо задать переменную окружения SIGN_LOG_TIME: + +``` +export SIGN_LOG_TIME=on +``` + +***Для отключения*** логирования времени обработки запросов необходимо удалить переменную окружения SIGN_LOG_TIME: + +``` +unset SIGN_LOG_TIME +``` + + diff --git a/src/modules/service_sign.c b/src/modules/service_sign.c index dd886e7..ea237a7 100644 --- a/src/modules/service_sign.c +++ b/src/modules/service_sign.c @@ -4,6 +4,7 @@ #include "utils/cryptopro.h" #include "utils/json_writer.h" +#include "utils/timer.h" #include "utils/uuid.h" #define SIGN_CONF_SECTION "sign" @@ -26,6 +27,8 @@ typedef struct sign_service_s { cryptopro_context_t cryptopro_ctx; + timer_context_t timer_ctx; + } sign_service_t; typedef struct fcgi_sign_request_s { @@ -130,9 +133,12 @@ sign_service_create(const sign_conf_t *conf) hsign->conf = conf; + init_timers(&hsign->timer_ctx); + cryptopro_context_set(&hsign->cryptopro_ctx, &conf->sign_cert_thumbprint, - &conf->sign_cert_password); + &conf->sign_cert_password, + &hsign->timer_ctx); if (open_signer_cert(&hsign->cryptopro_ctx)) { goto error; @@ -163,11 +169,13 @@ fcgi_handler_status_t fcgi_sign_handler(FCGX_Request* request, void* ctx) { fcgi_handler_status_t status = HANDLER_ERROR; - const sign_service_t *hsign = (const sign_service_t *) ctx; + sign_service_t *hsign = (sign_service_t *) ctx; fcgi_sign_request_t req_info = {0}; LOG_TRACE("fcgi_sign_handler enter"); + timer_on_fcgi_sign_handler_enter(&hsign->timer_ctx); + if (request == NULL) { LOG_ERROR("fcgi_sign_handler exit with error. Desc: request is NULL"); goto exit; @@ -190,11 +198,15 @@ fcgi_sign_handler(FCGX_Request* request, void* ctx) goto exit; } + timer_on_sign_content_enter(&hsign->timer_ctx); + if (sign_content_with_state(hsign, &req_info)) { status = HANDLER_ERROR; goto exit; } + timer_on_sign_content_exit(&hsign->timer_ctx); + // status = HANDLER_SUCCESS; exit: @@ -202,6 +214,9 @@ exit: fcgi_sign_request_clear(&req_info); + timer_on_fcgi_sign_handler_exit(&hsign->timer_ctx); + timer_log_sign(&hsign->timer_ctx); + LOG_TRACE("fcgi_sign_handler exit"); return status; } diff --git a/src/utils/cryptopro.c b/src/utils/cryptopro.c index 71b3f63..a6e2833 100644 --- a/src/utils/cryptopro.c +++ b/src/utils/cryptopro.c @@ -180,17 +180,21 @@ exit: } static bool -verify_cert_chain(PCCERT_CONTEXT certificate) +verify_cert_chain(PCCERT_CONTEXT certificate, timer_context_t *timer_ctx) { bool is_verified = false; LOG_TRACE("verify_cert_chain enter"); + timer_on_get_cert_chain_enter(timer_ctx); + PCCERT_CHAIN_CONTEXT chain_ctx = get_cert_chain(certificate); if (chain_ctx == NULL) { goto exit; } + timer_on_get_cert_chain_exit(timer_ctx); + if (!check_cert_chain_policy(chain_ctx)) { goto exit; } @@ -280,10 +284,16 @@ sign_hash_data(const cryptopro_context_t *ctx, const str_t *data, /*out*/ str_t BYTE *pbSignedMessageBlob; DWORD cbSignedMessageBlob; - if (!verify_cert_chain(ctx->signer_cert)) { + timer_on_verify_cert_chain_enter(ctx->timer_ctx); + + if (!verify_cert_chain(ctx->signer_cert, ctx->timer_ctx)) { goto exit; } + timer_on_verify_cert_chain_exit(ctx->timer_ctx); + + timer_on_acquire_private_key_enter(ctx->timer_ctx); + if (!cp_function_list.CryptAcquireCertificatePrivateKey( ctx->signer_cert, CRYPT_ACQUIRE_SILENT_FLAG | CRYPT_ACQUIRE_CACHE_FLAG, @@ -295,6 +305,8 @@ sign_hash_data(const cryptopro_context_t *ctx, const str_t *data, /*out*/ str_t goto exit; } + timer_on_acquire_private_key_exit(ctx->timer_ctx); + if (!cp_function_list.CryptCreateHash(hCryptProv, CALG_GR3411_2012_256, 0, 0, &hash)) { LOG_ERROR("CryptCreateHash() failed"); goto exit; @@ -304,6 +316,8 @@ sign_hash_data(const cryptopro_context_t *ctx, const str_t *data, /*out*/ str_t LOG_ERROR("CryptHashData() failed"); goto exit; } + + timer_on_sign_hash_enter(ctx->timer_ctx); if (!cp_function_list.CryptSignHash(hash, AT_KEYEXCHANGE, NULL, 0, NULL, &cbSignedMessageBlob)) { LOG_ERROR("CryptSignHash() failed"); @@ -318,6 +332,8 @@ sign_hash_data(const cryptopro_context_t *ctx, const str_t *data, /*out*/ str_t goto exit; } + timer_on_sign_hash_exit(ctx->timer_ctx); + sign->data = (char*)pbSignedMessageBlob; sign->len = (size_t)cbSignedMessageBlob; @@ -627,9 +643,14 @@ cryptopro_verify(const str_t* cert_thumbprint, const str_t* alg, const str_t* da HCRYPTKEY hPubKey = 0; str_t sign_reversed = str_t_null; ALG_ID alg_id; + timer_context_t timer_ctx = {}; + + init_timers(&timer_ctx); LOG_TRACE("cryptopro_verify enter"); + timer_on_cryptopro_verify_enter(&timer_ctx); + *is_verified = false; if (alg_id_from_str(alg, &alg_id, verify_error)) { @@ -650,10 +671,14 @@ cryptopro_verify(const str_t* cert_thumbprint, const str_t* alg, const str_t* da goto exit; } - if (!verify_cert_chain(certificate)) { + timer_on_verify_cert_chain_enter(&timer_ctx); + + if (!verify_cert_chain(certificate, &timer_ctx)) { goto exit; } + timer_on_verify_cert_chain_exit(&timer_ctx); + if (!cp_function_list.CryptAcquireContext(&hCryptProv, NULL, NULL, PROV_GOST_2012_256, CRYPT_VERIFYCONTEXT)) { LOG_ERROR("CryptAcquireContext() failed"); @@ -727,6 +752,9 @@ exit: cp_function_list.GetLastError()); } + timer_on_cryptopro_verify_exit(&timer_ctx); + timer_log_verify(&timer_ctx); + return rc; } diff --git a/src/utils/cryptopro.h b/src/utils/cryptopro.h index 6391017..5919fc6 100644 --- a/src/utils/cryptopro.h +++ b/src/utils/cryptopro.h @@ -1,31 +1,34 @@ #ifndef CRYPTOPRO_H_INCLUDED #define CRYPTOPRO_H_INCLUDED +#include "capi.h" #include "str_t.h" +#include "timer.h" #include #include -#include "capi.h" - typedef struct cryptopro_context_s { - const str_t *cert_thumbprint; - const str_t *password; + const str_t *cert_thumbprint; + const str_t *password; + timer_context_t *timer_ctx; - HCERTSTORE cert_store; - PCCERT_CONTEXT signer_cert; + HCERTSTORE cert_store; + PCCERT_CONTEXT signer_cert; } cryptopro_context_t; static inline void -cryptopro_context_set(cryptopro_context_t *ctx, const str_t *cert_thumbprint, const str_t *password) +cryptopro_context_set(cryptopro_context_t *ctx, const str_t *cert_thumbprint, + const str_t *password, timer_context_t *timer_ctx) { assert(ctx != NULL); ctx->cert_thumbprint = cert_thumbprint; ctx->password = password; + ctx->timer_ctx = timer_ctx; } bool cryptopro_init(const char* cp_file); diff --git a/src/utils/timer.c b/src/utils/timer.c new file mode 100644 index 0000000..c2fb2bc --- /dev/null +++ b/src/utils/timer.c @@ -0,0 +1,162 @@ +#include "timer.h" +#include "logger.h" + +#include +#include + +#define ENV_SIGN_LOG_TIME "SIGN_LOG_TIME" + +void +init_timers(timer_context_t *ctx) +{ + const char* slt = getenv(ENV_SIGN_LOG_TIME); + if (slt != NULL) { + LOG_INFO("environment variable '" ENV_SIGN_LOG_TIME "'='%s' -> timings logging: ON", slt); + ctx->is_timer_on = true; + } else { + LOG_INFO("environment variable '" ENV_SIGN_LOG_TIME "' does not exist " + "-> timings logging: OFF"); + ctx->is_timer_on = false; + } +} + +static inline void +set_timer(bool is_timer_on, struct timeval *timer, const char *timer_name) +{ + if (!is_timer_on) { + return; + } + + if (gettimeofday(timer, NULL)) { + LOG_WARN("gettimeofday(%s) failed. Desc: %s", timer_name, strerror(errno)); + } +} + +static inline time_t +get_diff(const struct timeval *tv_start, const struct timeval *tv_end) +{ + return (tv_end->tv_sec - tv_start->tv_sec) * 1000 + + (tv_end->tv_usec - tv_start->tv_usec) / 1000; +} + +void +timer_on_fcgi_sign_handler_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->sign_handler_start, "sign_handler_start"); +} + +void +timer_on_fcgi_sign_handler_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->sign_handler_end, "sign_handler_end"); +} + +void +timer_on_sign_content_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->sign_content_start, "sign_content_start"); +} + +void +timer_on_sign_content_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->sign_content_end, "sign_content_end"); +} + +void +timer_on_verify_cert_chain_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->verify_cert_chain_start, "verify_cert_chain_start"); +} + +void +timer_on_verify_cert_chain_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->verify_cert_chain_end, "verify_cert_chain_end"); +} + +void +timer_on_acquire_private_key_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->acquire_private_key_start, "acquire_private_key_start"); +} + +void +timer_on_acquire_private_key_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->acquire_private_key_end, "acquire_private_key_end"); +} + +void timer_on_sign_hash_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->sign_hash_start, "sign_hash_start"); +} + +void timer_on_sign_hash_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->sign_hash_end, "sign_hash_end"); +} + +void +timer_on_get_cert_chain_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->get_cert_chain_start, "get_cert_chain_start"); +} + +void +timer_on_get_cert_chain_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->get_cert_chain_end, "get_cert_chain_end"); +} + +void timer_on_cryptopro_verify_enter(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->cryptopro_verify_start, "cryptopro_verify_start"); +} + +void timer_on_cryptopro_verify_exit(timer_context_t *ctx) +{ + set_timer(ctx->is_timer_on, &ctx->cryptopro_verify_end, "cryptopro_verify_end"); +} + +void +timer_log_sign(const timer_context_t *ctx) +{ + if (!ctx->is_timer_on) { + return; + } + + time_t diff_sign_handler = get_diff(&ctx->sign_handler_start, &ctx->sign_handler_end); + time_t diff_sign_content = get_diff(&ctx->sign_content_start, &ctx->sign_content_end); + time_t diff_verify_cert_chain = get_diff(&ctx->verify_cert_chain_start, + &ctx->verify_cert_chain_end); + time_t diff_get_cert_chain = get_diff(&ctx->get_cert_chain_start, &ctx->get_cert_chain_end); + time_t diff_acquire_private_key = get_diff(&ctx->acquire_private_key_start, + &ctx->acquire_private_key_end); + time_t diff_sign_hash = get_diff(&ctx->sign_hash_start, &ctx->sign_hash_end); + + LOG_INFO("sign_handler: %ld sign_content: %ld verify_cert_chain: %ld " + "get_cert_chain: %ld acquire_private_key: %ld sign_hash: %ld", + diff_sign_handler, + diff_sign_content, + diff_verify_cert_chain, + diff_get_cert_chain, + diff_acquire_private_key, + diff_sign_hash); +} + +void +timer_log_verify(const timer_context_t *ctx) +{ + if (!ctx->is_timer_on) { + return; + } + + time_t diff_verify_handler = get_diff(&ctx->cryptopro_verify_start, &ctx->cryptopro_verify_end); + time_t diff_verify_cert_chain = get_diff(&ctx->verify_cert_chain_start, + &ctx->verify_cert_chain_end); + + LOG_INFO("verify_handler: %ld verify_cert_chain: %ld", + diff_verify_handler, + diff_verify_cert_chain); +} \ No newline at end of file diff --git a/src/utils/timer.h b/src/utils/timer.h new file mode 100644 index 0000000..762ee35 --- /dev/null +++ b/src/utils/timer.h @@ -0,0 +1,60 @@ +#ifndef TIMER_H_INCLUDED +#define TIMER_H_INCLUDED + +#include +#include + +typedef struct timer_context_s +{ + bool is_timer_on; + + struct timeval sign_handler_start; + struct timeval sign_handler_end; + + struct timeval sign_content_start; + struct timeval sign_content_end; + + struct timeval verify_cert_chain_start; + struct timeval verify_cert_chain_end; + + struct timeval acquire_private_key_start; + struct timeval acquire_private_key_end; + + struct timeval sign_hash_start; + struct timeval sign_hash_end; + + struct timeval get_cert_chain_start; + struct timeval get_cert_chain_end; + + struct timeval cryptopro_verify_start; + struct timeval cryptopro_verify_end; + +} timer_context_t; + +void init_timers(timer_context_t *ctx); + +void timer_on_fcgi_sign_handler_enter(timer_context_t *ctx); +void timer_on_fcgi_sign_handler_exit(timer_context_t *ctx); + +void timer_on_sign_content_enter(timer_context_t *ctx); +void timer_on_sign_content_exit(timer_context_t *ctx); + +void timer_on_verify_cert_chain_enter(timer_context_t *ctx); +void timer_on_verify_cert_chain_exit(timer_context_t *ctx); + +void timer_on_acquire_private_key_enter(timer_context_t *ctx); +void timer_on_acquire_private_key_exit(timer_context_t *ctx); + +void timer_on_sign_hash_enter(timer_context_t *ctx); +void timer_on_sign_hash_exit(timer_context_t *ctx); + +void timer_on_get_cert_chain_enter(timer_context_t *ctx); +void timer_on_get_cert_chain_exit(timer_context_t *ctx); + +void timer_on_cryptopro_verify_enter(timer_context_t *ctx); +void timer_on_cryptopro_verify_exit(timer_context_t *ctx); + +void timer_log_sign(const timer_context_t *ctx); +void timer_log_verify(const timer_context_t *ctx); + +#endif // TIMER_H_INCLUDED \ No newline at end of file