Optimize the output of log and stat

src/log/log.cpp

@@ -21,7 +21,8 @@ struct log_config
 {
     enum log_output output;
     enum log_level level;
-    char log_file[256];
+    char work_dir[1024];
+    char log_file[1024];
 };
 
 struct log_context
@@ -194,9 +195,11 @@ static int log_reopen()
     int new_fd;
     int old_fd;
     struct tm local;
-    char buff[512] = {0};
+    char buff[4096] = {0};
     local_time(&local);
-    snprintf(buff, sizeof(buff), "%s.%d-%02d-%02d", g_log_ctx->config.log_file, local.tm_year + 1900, local.tm_mon + 1, local.tm_mday);
+    snprintf(buff, sizeof(buff), "%s/%s.%d-%02d-%02d",
+             g_log_ctx->config.work_dir, g_log_ctx->config.log_file,
+             local.tm_year + 1900, local.tm_mon + 1, local.tm_mday);
 
     new_fd = open(buff, O_WRONLY | O_APPEND | O_CREAT, 0644);
     if (new_fd == -1)
@@ -227,6 +230,12 @@ int log_init(const char *config_file)
 {
     memset(g_log_ctx, 0, sizeof(struct log_context));
 
+    if (getcwd(g_log_ctx->config.work_dir, sizeof(g_log_ctx->config.work_dir)) == NULL)
+    {
+        fprintf(stderr, "getcwd() failed, %s\n", strerror(errno));
+        return -1;
+    }
+
     if (parse_config(&g_log_ctx->config, config_file) != 0)
     {
         return -1;
@@ -255,6 +264,11 @@ void log_free()
     }
 }
 
+int log_level_enabled(enum log_level level)
+{
+    return level >= g_log_ctx->config.level;
+}
+
 void log_reload_level(const char *config_file)
 {
     struct log_config config;
@@ -267,11 +281,6 @@ void log_reload_level(const char *config_file)
 
 void log_print(enum log_level level, const char *module, const char *fmt, ...)
 {
-    if (level < g_log_ctx->config.level)
-    {
-        return;
-    }
-
     int nwrite;
     char buf[4096] = {0};
     char *p = buf;

src/log/log.h

@@ -18,32 +18,54 @@ enum log_level
     LOG_STATE = 6,
 };
 
-#define LOG_TRACE(module, format, ...) \
+#define LOG_TRACE(module, format, ...)                       \
-    log_print(LOG_TRACE, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_TRACE))                        \
+    {                                                        \
+        log_print(LOG_TRACE, module, format, ##__VA_ARGS__); \
+    }
 
-#define LOG_DEBUG(module, format, ...) \
+#define LOG_DEBUG(module, format, ...)                       \
-    log_print(LOG_DEBUG, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_DEBUG))                        \
+    {                                                        \
+        log_print(LOG_DEBUG, module, format, ##__VA_ARGS__); \
+    }
 
-#define LOG_INFO(module, format, ...) \
+#define LOG_INFO(module, format, ...)                       \
-    log_print(LOG_INFO, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_INFO))                        \
+    {                                                       \
+        log_print(LOG_INFO, module, format, ##__VA_ARGS__); \
+    }
 
-#define LOG_WARN(module, format, ...) \
+#define LOG_WARN(module, format, ...)                       \
-    log_print(LOG_WARN, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_WARN))                        \
+    {                                                       \
+        log_print(LOG_WARN, module, format, ##__VA_ARGS__); \
+    }
 
-#define LOG_ERROR(module, format, ...) \
+#define LOG_ERROR(module, format, ...)                       \
-    log_print(LOG_ERROR, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_ERROR))                        \
+    {                                                        \
+        log_print(LOG_ERROR, module, format, ##__VA_ARGS__); \
+    }
 
-#define LOG_FATAL(module, format, ...) \
+#define LOG_FATAL(module, format, ...)                       \
-    log_print(LOG_FATAL, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_FATAL))                        \
+    {                                                        \
+        log_print(LOG_FATAL, module, format, ##__VA_ARGS__); \
+    }
 
-#define LOG_STATE(module, format, ...) \
+#define LOG_STATE(module, format, ...)                       \
-    log_print(LOG_STATE, module, format, ##__VA_ARGS__);
+    if (log_level_enabled(LOG_STATE))                        \
+    {                                                        \
+        log_print(LOG_STATE, module, format, ##__VA_ARGS__); \
+    }
 
 // return  0: success
 // return -1: failed
 int log_init(const char *config_file);
 void log_free();
 
+int log_level_enabled(enum log_level level);
 void log_reload_level(const char *config_file);
 void log_print(enum log_level level, const char *module, const char *fmt, ...);
 

src/packet/packet_priv.h

@@ -15,6 +15,7 @@ extern "C"
 
 #define PACKET_MAX_LAYERS 32
 #define PACKET_LOG_ERROR(format, ...) LOG_ERROR("packet", format, ##__VA_ARGS__)
+#define PACKET_LOG_WARN(format, ...) LOG_WARN("packet", format, ##__VA_ARGS__)
 #define PACKET_LOG_DEBUG(format, ...) void(0)
 // #define PACKET_LOG_DEBUG(format, ...) LOG_DEBUG("packet", format, ##__VA_ARGS__)
 

src/packet/packet_utils.cpp

@@ -164,7 +164,7 @@ void packet_set_ctrl(struct packet *pkt)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to set ctrl");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to set ctrl");
     }
 }
 
@@ -178,7 +178,7 @@ int packet_is_ctrl(const struct packet *pkt)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to check ctrl");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to check ctrl");
         return 0;
     }
 }
@@ -196,7 +196,7 @@ void packet_set_direction(struct packet *pkt, enum packet_direction dir)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to set direction");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to set direction");
     }
 }
 
@@ -214,7 +214,7 @@ enum packet_direction packet_get_direction(const struct packet *pkt)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to get direction");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to get direction");
     }
 
     return dir;
@@ -233,7 +233,7 @@ void packet_set_session_id(struct packet *pkt, uint64_t sess_id)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to set session id");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to set session id");
     }
 }
 
@@ -251,7 +251,7 @@ uint64_t packet_get_session_id(const struct packet *pkt)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to get session id");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to get session id");
     }
 
     return sess_id;
@@ -273,7 +273,7 @@ void packet_set_domain(struct packet *pkt, uint64_t domain)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to set domain");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to set domain");
     }
 }
 
@@ -294,7 +294,7 @@ uint64_t packet_get_domain(const struct packet *pkt)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to get domain");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to get domain");
     }
 
     return domain;
@@ -313,7 +313,7 @@ void packet_set_route_ctx(struct packet *pkt, const struct route_ctx *ctx)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to set route ctx");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to set route ctx");
     }
 }
 
@@ -332,7 +332,7 @@ void packet_get_route_ctx(const struct packet *pkt, struct route_ctx *ctx)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to get route ctx");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to get route ctx");
     }
 }
 
@@ -349,7 +349,7 @@ void packet_set_sid_list(struct packet *pkt, const struct sid_list *list)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to set sid list");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to set sid list");
     }
 }
 
@@ -364,7 +364,7 @@ void packet_get_sid_list(const struct packet *pkt, struct sid_list *list)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to get sid list");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to get sid list");
     }
 }
 
@@ -381,7 +381,7 @@ void packet_prepend_sid_list(struct packet *pkt, const struct sid_list *list)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to prepend sid list");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to prepend sid list");
     }
 }
 
@@ -398,6 +398,6 @@ void packet_append_sid_list(struct packet *pkt, const struct sid_list *list)
     }
     else
     {
-        PACKET_LOG_ERROR("packet origin is not marsio, failed to append sid list");
+        PACKET_LOG_WARN("packet origin is not marsio, failed to append sid list");
     }
 }

src/stellar/main.cpp

@@ -63,6 +63,17 @@ static int all_session_have_freed(void)
     return 1;
 }
 
+static int all_stat_have_output(void)
+{
+    static int count = 0;
+    if (runtime->stat_last_output_ts == stellar_get_monotonic_time_msec())
+    {
+        count++;
+    }
+
+    return count == 2;
+}
+
 int main(int argc, char **argv)
 {
     stellar_update_time_cache();
@@ -138,8 +149,9 @@ int main(int argc, char **argv)
         usleep(1000); // 1ms
 
         // Only available in dump file mode, automatically exits when all sessions have been released
-        if (packet_io_wait_exit(runtime->packet_io) && all_session_have_freed())
+        if (packet_io_wait_exit(runtime->packet_io) && all_session_have_freed() && all_stat_have_output())
         {
+            STELLAR_LOG_STATE("all sessions have been released and all stat have been output, notify threads to exit !!!");
             ATOMIC_SET(&runtime->need_exit, 1);
         }
     }

src/stellar/stat.cpp

@@ -113,6 +113,8 @@ struct stat_id
 
 struct stellar_stat
 {
+    char output_file[2048];
+
     // thread stat
     uint16_t nr_thread;
     int flag[MAX_THREAD_NUM]; // IS_FREE or IS_BUSY
@@ -134,12 +136,20 @@ struct stellar_stat
 // /opt/MESA/bin/fieldstat_exporter.py local -j log/stellar_fs4.json -e -l --clear-screen
 struct stellar_stat *stellar_stat_new(uint16_t nr_thread)
 {
+    char cwd[1024] = {0};
     struct stellar_stat *stat = (struct stellar_stat *)calloc(1, sizeof(struct stellar_stat));
     if (stat == NULL)
     {
         return NULL;
     }
 
+    if (getcwd(cwd, sizeof(cwd)) == NULL)
+    {
+        STAT_LOG_ERROR("failed to get current working directory: %s", strerror(errno));
+        goto error_out;
+    }
+    snprintf(stat->output_file, sizeof(stat->output_file), "%s/log/stellar_fs4.json", cwd);
+
     stat->fs = fieldstat_easy_new(1, "stellar", NULL, 0);
     if (stat->fs == NULL)
     {
@@ -448,10 +458,10 @@ void stellar_stat_output(struct stellar_stat *stat)
     fieldstat_easy_output(stat->fs, &buff, &len);
     if (buff)
     {
-        FILE *fp = fopen("/opt/tsg/stellar/log/stellar_fs4.json", "w+");
+        FILE *fp = fopen(stat->output_file, "w+");
         if (fp == NULL)
         {
-            STAT_LOG_ERROR("failed to open file: %s, %s", "/opt/tsg/stellar/log/stellar_fs4.json", strerror(errno));
+            STAT_LOG_ERROR("failed to open file: %s, %s", stat->output_file, strerror(errno));
         }
         else
         {

test/conf/stellar.toml

@@ -27,27 +27,27 @@ tcp_overload_evict_old_sess = 1 # 1: evict old session, 0: bypass new session
 udp_overload_evict_old_sess = 1 # 1: evict old session, 0: bypass new session
 
 # TCP timeout
-tcp_init_timeout = 5000           # range: [1, 60000] (ms)
+tcp_init_timeout = 50           # range: [1, 60000] (ms)
-tcp_handshake_timeout = 5000      # range: [1, 60000] (ms)
+tcp_handshake_timeout = 50      # range: [1, 60000] (ms)
-tcp_data_timeout = 5000           # range: [1, 15999999000] (ms)
+tcp_data_timeout = 50           # range: [1, 15999999000] (ms)
-tcp_half_closed_timeout = 5000    # range: [1, 604800000] (ms)
+tcp_half_closed_timeout = 50    # range: [1, 604800000] (ms)
-tcp_time_wait_timeout = 5000      # range: [1, 600000] (ms)
+tcp_time_wait_timeout = 50      # range: [1, 600000] (ms)
-tcp_discard_timeout = 10000       # range: [1, 15999999000] (ms)
+tcp_discard_timeout = 50        # range: [1, 15999999000] (ms)
-tcp_unverified_rst_timeout = 5000 # range: [1, 600000] (ms)
+tcp_unverified_rst_timeout = 50 # range: [1, 600000] (ms)
 # UDP timeout
-udp_data_timeout = 5000    # range: [1, 15999999000] (ms)
+udp_data_timeout = 50    # range: [1, 15999999000] (ms)
-udp_discard_timeout = 5000 # range: [1, 15999999000] (ms)
+udp_discard_timeout = 50 # range: [1, 15999999000] (ms)
 
 # duplicate packet filter
 duplicated_packet_filter_enable = 1
 duplicated_packet_filter_capacity = 1000000   # range: [1, 4294967295]
-duplicated_packet_filter_timeout = 10000      # range: [1, 60000] (ms)
+duplicated_packet_filter_timeout = 100        # range: [1, 60000] (ms)
 duplicated_packet_filter_error_rate = 0.00001 # range: [0.0, 1.0]
 
 # evicted session filter
 evicted_session_filter_enable = 1
 evicted_session_filter_capacity = 1000000   # range: [1, 4294967295]
-evicted_session_filter_timeout = 10000      # range: [1, 60000] (ms)
+evicted_session_filter_timeout = 100        # range: [1, 60000] (ms)
 evicted_session_filter_error_rate = 0.00001 # range: [0.0, 1.0]
 
 # TCP reassembly (Per direction)

test/packet_injector.cpp

@@ -230,6 +230,17 @@ static int all_session_have_freed(void)
     return 1;
 }
 
+static int all_stat_have_output(void)
+{
+    static int count = 0;
+    if (runtime->stat_last_output_ts == stellar_get_monotonic_time_msec())
+    {
+        count++;
+    }
+
+    return count == 2;
+}
+
 static void usage(char *cmd)
 {
     printf("Usage: %s [options]\n\n", cmd);
@@ -449,8 +460,9 @@ int main(int argc, char **argv)
         usleep(1000); // 1ms
 
         // Only available in dump file mode, automatically exits when all sessions have been released
-        if (packet_io_wait_exit(runtime->packet_io) && all_session_have_freed())
+        if (packet_io_wait_exit(runtime->packet_io) && all_session_have_freed() && all_stat_have_output())
         {
+            STELLAR_LOG_STATE("all sessions have been released and all stat have been output, notify threads to exit !!!");
             ATOMIC_SET(&runtime->need_exit, 1);
         }
     }

test/packet_injector_test_frame.cpp

@@ -142,18 +142,21 @@ void packet_injector_test_frame_run(struct packet_injector_case *test)
     char input_dir_abs_path[1024] = {0};
     char output_dir_abs_path[1024] = {0};
     char expect_dir_abs_path[1024] = {0};
+    char log_dir_abs_path[1024] = {0};
 
     // absulute path
     snprintf(config_file_abs_path, sizeof(config_file_abs_path), "%s/conf/stellar.toml", test->work_dir);
     snprintf(input_dir_abs_path, sizeof(input_dir_abs_path), "%s/input/", test->work_dir);
     snprintf(output_dir_abs_path, sizeof(output_dir_abs_path), "%s/output/", test->work_dir);
     snprintf(expect_dir_abs_path, sizeof(expect_dir_abs_path), "%s/expect/", test->work_dir);
+    snprintf(log_dir_abs_path, sizeof(log_dir_abs_path), "%s/log/", test->work_dir);
 
     // create directory
     system_cmd("rm -rf %s", test->work_dir);
     system_cmd("mkdir -p %s", input_dir_abs_path);
     system_cmd("mkdir -p %s", output_dir_abs_path);
     system_cmd("mkdir -p %s", expect_dir_abs_path);
+    system_cmd("mkdir -p %s", log_dir_abs_path);
 
     // copy file to work directory
     if (test->c2s_expect_pcap)