SUPPORT-8890. Добавлено логирование времени обработки запросов (включается переменной окружения SIGN_LOG_TIME)

(cherry picked from commit 1e10dbe5c565a621eab050c1c0d44a499318e34c)

# Conflicts:
#	CMakeLists.txt
#	src/modules/service_sign.c

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

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
+```
+
+

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;
 }

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;
@@ -305,6 +317,8 @@ sign_hash_data(const cryptopro_context_t *ctx, const str_t *data, /*out*/ str_t
         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");
         goto exit;
@@ -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;  
 }
 

src/utils/cryptopro.h

@@ -1,17 +1,18 @@
 #ifndef CRYPTOPRO_H_INCLUDED
 #define CRYPTOPRO_H_INCLUDED
 
+#include "capi.h"
 #include "str_t.h"
+#include "timer.h"
 
 #include <assert.h>
 #include <stdbool.h>
 
-#include "capi.h"
-
 
 typedef struct cryptopro_context_s {
     const str_t             *cert_thumbprint;
     const str_t             *password;
+    timer_context_t         *timer_ctx;
 
     HCERTSTORE              cert_store;
     PCCERT_CONTEXT          signer_cert;
@@ -20,12 +21,14 @@ typedef struct cryptopro_context_s {
 
 
 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);

src/utils/timer.c

@@ -0,0 +1,162 @@
+#include "timer.h"
+#include "logger.h"
+
+#include <errno.h>
+#include <stdlib.h>
+
+#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);
+}

src/utils/timer.h

@@ -0,0 +1,60 @@
+#ifndef TIMER_H_INCLUDED
+#define TIMER_H_INCLUDED
+
+#include <stdbool.h>
+#include <sys/time.h>
+
+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