Merge pull request #46 from alephium/log-with-timestamp

polarker · web-flow · commit ca5823922cc6 · 2021-12-30T11:56:00.000+01:00
Add timestamp to miner log
diff --git a/src/blake3/blake3-common.hpp b/src/blake3/blake3-common.hpp
@@ -1,6 +1,8 @@
 #ifndef ALEPHIUM_BLAKE3_COMMON_H
 #define ALEPHIUM_BLAKE3_COMMON_H
 
+#include "../log.h"
+
 #define INLINE __forceinline__
 #define TRY(x)                                                                                                             \
     {                                                                                                                      \
@@ -9,7 +11,7 @@
         cudaError_t err = cudaGetLastError();                                                                              \
         if (err != cudaSuccess)                                                                                            \
         {                                                                                                                  \
-            printf("cudaError %d (%s) calling '%s' (%s line %d)\n", err, cudaGetErrorString(err), #x, __FILE__, __LINE__); \
+            LOGERR("cudaError %d (%s) calling '%s' (%s line %d)\n", err, cudaGetErrorString(err), #x, __FILE__, __LINE__); \
             exit(1);                                                                                                       \
         }                                                                                                                  \
     }
diff --git a/src/log.h b/src/log.h
@@ -0,0 +1,33 @@
+#ifndef ALEPHIUM_LOG_H
+#define ALEPHIUM_LOG_H
+
+#include <stdio.h>
+#include <time.h>
+
+#ifdef _WIN32
+#define localtime_r(a, b) localtime_s(b, a)
+#endif
+
+#define LOG_TIMESTAMP(stream)                       \
+{                                                   \
+    time_t now = time(NULL);                        \
+    struct tm time;                                 \
+    localtime_r(&now, &time);                       \
+    char str[24];                                   \
+    strftime(str, 24, "%Y-%m-%d %H:%M:%S", &time);  \
+    fprintf(stream, "%s | ", str);                  \
+}
+
+#define LOG_WITH_TS(stream, format, ...)            \
+{                                                   \
+    LOG_TIMESTAMP(stream);                          \
+    fprintf(stream, format, ##__VA_ARGS__);         \
+}
+
+#define LOG_WITHOUT_TS(format, ...) fprintf(stdout, format, ##__VA_ARGS__);
+
+#define LOG(format, ...) LOG_WITH_TS(stdout, format, ##__VA_ARGS__);
+
+#define LOGERR(format, ...) LOG_WITH_TS(stderr, format, ##__VA_ARGS__);
+
+#endif // ALEPHIUM_LOG_H
diff --git a/src/main.cu b/src/main.cu
@@ -16,7 +16,7 @@
 #include "template.h"
 #include "mining.h"
 #include "getopt.h"
-
+#include "log.h"
 
 std::atomic<uint32_t> found_solutions{0};
 
@@ -51,8 +51,7 @@ void on_write_end(uv_write_t *req, int status)
 {
     if (status < 0)
     {
-        fprintf(stderr, "error on_write_end %d", status);
-        exit(1);
+        LOGERR("error on_write_end %d\n", status);
     }
     free(req);
 }
@@ -85,7 +84,7 @@ void mine(mining_worker_t *worker)
     int32_t to_mine_index = next_chain_to_mine();
     if (to_mine_index == -1)
     {
-        printf("waiting for new tasks\n");
+        LOG("waiting for new tasks\n");
         worker->timer.data = worker;
         uv_timer_start(&worker->timer, mine_with_timer, 500, 0);
     } else {
@@ -95,7 +94,7 @@ void mine(mining_worker_t *worker)
         start_worker_mining(worker);
 
         duration_t elapsed = Time::now() - start;
-        // printf("=== mining time: %fs\n", elapsed.count());
+        // LOG("=== mining time: %fs\n", elapsed.count());
     }
 }
 
@@ -191,12 +190,12 @@ void log_hashrate(uv_timer_t *timer)
     if (current_time > start_time)
     {
         duration_t eplased = current_time - start_time;
-        printf("hashrate: %.0f MH/s ", total_mining_count.load() / eplased.count() / 1000000);
+        LOG("hashrate: %.0f MH/s ", total_mining_count.load() / eplased.count() / 1000000);
         for (int i = 0; i < gpu_count; i++)
         {
-            printf("gpu%d: %.0f MH/s ", i, device_mining_count[i].load() / eplased.count() / 1000000);
+            LOG_WITHOUT_TS("gpu%d: %.0f MH/s ", i, device_mining_count[i].load() / eplased.count() / 1000000);
         }
-        printf("solutions: %u\n", found_solutions.load(std::memory_order_relaxed));
+        LOG_WITHOUT_TS("solutions: %u\n", found_solutions.load(std::memory_order_relaxed));
     }
 }
 
@@ -250,7 +249,7 @@ void on_read(uv_stream_t *server, ssize_t nread, const uv_buf_t *buf)
 {
     if (nread < 0)
     {
-        fprintf(stderr, "error on_read %ld: might be that the full node is not synced, or miner wallets are not setup, try to reconnect\n", nread);
+        LOGERR("error on_read %ld: might be that the full node is not synced, or miner wallets are not setup, try to reconnect\n", nread);
         uv_timer_start(&reconnect_timer, try_to_reconnect, 5000, 0);
         return;
     }
@@ -274,7 +273,7 @@ void on_read(uv_stream_t *server, ssize_t nread, const uv_buf_t *buf)
             break;
 
         case SUBMIT_RESULT:
-            printf("submitted: %d -> %d: %d \n", message->submit_result->from_group, message->submit_result->to_group, message->submit_result->status);
+            LOG("submitted: %d -> %d: %d \n", message->submit_result->from_group, message->submit_result->to_group, message->submit_result->status);
             break;
         }
         free_server_message_except_jobs(message);
@@ -288,11 +287,11 @@ void on_connect(uv_connect_t *req, int status)
 {
     if (status < 0)
     {
-        fprintf(stderr, "connection error %d: might be that the full node is not reachable, try to reconnect\n", status);
+        LOGERR("connection error %d: might be that the full node is not reachable, try to reconnect\n", status);
         uv_timer_start(&reconnect_timer, try_to_reconnect, 5000, 0);
         return;
     }
-    printf("the server is connected %d %p\n", status, req);
+    LOG("the server is connected %d %p\n", status, req);
 
     tcp = req->handle;
     uv_read_start(req->handle, alloc_buffer, on_read);
@@ -325,7 +324,7 @@ int hostname_to_ip(char *ip_address, char *hostname)
     int res = getaddrinfo(hostname, NULL, &hints, &servinfo);
     if (res != 0)
     {
-        fprintf(stderr, "getaddrinfo: %s\n", gai_strerror(res));
+        LOGERR("getaddrinfo: %s\n", gai_strerror(res));
         return 1;
     }
 
@@ -349,19 +348,19 @@ int main(int argc, char **argv)
     int rc = WSAStartup(MAKEWORD(2, 2), &wsa);
     if (rc != 0)
     {
-        printf("Initialize winsock failed: %d", rc);
+        LOGERR("Initialize winsock failed: %d\n", rc);
         exit(1);
     }
     #endif
 
-    printf("Running gpu-miner version : %s\n", MINER_VERSION);
+    LOG("Running gpu-miner version : %s\n", MINER_VERSION);
 
     int gpu_count = 0;
     cudaGetDeviceCount(&gpu_count);
-    printf("GPU count: %d\n", gpu_count);
+    LOG("GPU count: %d\n", gpu_count);
     for (int i = 0; i < gpu_count; i++)
     {
-        printf("GPU #%d has #%d cores\n", i, get_device_cores(i));
+        LOG("GPU #%d has #%d cores\n", i, get_device_cores(i));
         use_device[i] = true;
     }
 
@@ -396,18 +395,22 @@ int main(int argc, char **argv)
             {
                 int device = atoi(argv[optind]);
                 if (device < 0 || device >= gpu_count) {
-                    printf("Invalid gpu index %d\n", device);
+                    LOGERR("Invalid gpu index %d\n", device);
                     exit(1);
                 }
                 use_device[device] = true;
             }
             break;
         default:
-            printf("Invalid command %c\n", command);
+            LOGERR("Invalid command %c\n", command);
             exit(1);
         }
     }
-    printf("will connect to broker @%s:%d\n", broker_ip, port);
+    LOG("will connect to broker @%s:%d\n", broker_ip, port);
+
+    #ifdef __linux__
+    signal(SIGPIPE, SIG_IGN);
+    #endif
 
     mining_workers_init(gpu_count);
     setup_gpu_worker_count(gpu_count, gpu_count * parallel_mining_works_per_gpu);
diff --git a/src/messages.h b/src/messages.h
@@ -8,6 +8,8 @@
 #include <string.h>
 #include <stdlib.h>
 
+#include "log.h"
+
 typedef struct blob_t {
     uint8_t *blob;
     ssize_t len;
@@ -40,7 +42,7 @@ char *bytes_to_hex(uint8_t *bytes, ssize_t len)
 void print_hex(const char* prefix, uint8_t *data, ssize_t nread)
 {
     char *hex_string = bytes_to_hex(data, nread);
-    printf("%s: %s\n", prefix, hex_string);
+    LOG("%s: %s\n", prefix, hex_string);
     free(hex_string);
 }
 
@@ -180,7 +182,7 @@ bool extract_bool(uint8_t **bytes)
     case 1:
         return true;
     default:
-        fprintf(stderr, "Invaid bool value");
+        LOGERR("Invaid bool value\n");
         exit(1);
     }
 }
@@ -204,15 +206,15 @@ void extract_blob(uint8_t **bytes, blob_t *blob)
     memcpy(blob->blob, *bytes, size);
     *bytes = *bytes + size;
 
-    // printf("blob: %ld\n", blob->len);
-    // printf("%s\n", bytes_to_hex(blob->blob, blob->len));
+    // LOG("blob: %ld\n", blob->len);
+    // LOG("%s\n", bytes_to_hex(blob->blob, blob->len));
 }
 
 void extract_job(uint8_t **bytes, job_t *job)
 {
     job->from_group = extract_size(bytes);
     job->to_group = extract_size(bytes);
-    // printf("group: %d, %d\n", job->from_group, job->to_group);
+    // LOG("group: %d, %d\n", job->from_group, job->to_group);
     extract_blob(bytes, &job->header_blob);
     extract_blob(bytes, &job->txs_blob);
     extract_blob(bytes, &job->target);
@@ -222,7 +224,7 @@ void extract_jobs(uint8_t **bytes, jobs_t *jobs)
 {
     ssize_t jobs_size = extract_size(bytes);
 
-    // printf("jobs: %ld\n", jobs_size);
+    // LOG("jobs: %ld\n", jobs_size);
 
     jobs->len = jobs_size;
     jobs->jobs = (job_t **)malloc(jobs_size * sizeof(job_t*));
@@ -265,7 +267,7 @@ server_message_t *decode_server_message(blob_t *blob)
         server_message->jobs = (jobs_t *)malloc(sizeof(jobs_t));
         extract_jobs(&pos, server_message->jobs);
 
-        // printf("%p, %p, %p\n", bytes, pos, bytes + len);
+        // LOG("%p, %p, %p\n", bytes, pos, bytes + len);
         break;
 
     case 1:
@@ -275,7 +277,7 @@ server_message_t *decode_server_message(blob_t *blob)
         break;
 
     default:
-        fprintf(stderr, "Invalid server message kind");
+        LOGERR("Invalid server message kind\n");
         exit(1);
     }
 
diff --git a/src/mining.h b/src/mining.h
@@ -2,6 +2,7 @@
 #define ALEPHIUM_MINING_H
 
 #include "blake3.cu"
+#include "log.h"
 
 //#define SHOW_MINING_TIME  1
 
@@ -37,7 +38,7 @@ void start_worker_mining(mining_worker_t *worker)
     TRY( cudaEventElapsedTime(&time, startEvent, stopEvent) );
     TRY( cudaEventDestroy(&startEvent) );
     TRY( cudaEventDestroy(&stopEvent) );
-    printf(" === mining time: %f\n", time);
+    LOG(" === mining time: %f\n", time);
 #endif
 }
 
diff --git a/src/worker.h b/src/worker.h
@@ -13,6 +13,7 @@
 #include "blake3.cu"
 #include "uv.h"
 #include "template.h"
+#include "log.h"
 
 typedef struct mining_worker_t {
     uint32_t id;
@@ -95,7 +96,7 @@ void mining_worker_init(mining_worker_t *self, uint32_t id, int device_id) {
     cudaSetDevice(device_id);
     TRY(cudaStreamCreate(&(self->stream)));
     config_cuda(device_id, &self->grid_size, &self->block_size, &self->is_inline_miner);
-    printf("Worker %d: device id %d, grid size %d, block size %d. Using %s kernel\n", self->id, self->device_id,
+    LOG("Worker %d: device id %d, grid size %d, block size %d. Using %s kernel\n", self->id, self->device_id,
            self->grid_size, self->block_size, self->is_inline_miner ? "inline" : "reference");
 
     TRY(cudaMallocHost(hasher_ptr(self, true), hasher_len(self)));

Original file line number	Diff line number	Diff line change
`@@ -16,7 +16,7 @@`
`16`	`16`	`#include "template.h"`
`17`	`17`	`#include "mining.h"`
`18`	`18`	`#include "getopt.h"`
`19`		`-`
	`19`	`+#include "log.h"`
`20`	`20`
`21`	`21`	`std::atomic<uint32_t> found_solutions{0};`
`22`	`22`
`@@ -51,8 +51,7 @@ void on_write_end(uv_write_t *req, int status)`
`51`	`51`	`{`
`52`	`52`	`if (status < 0)`
`53`	`53`	`{`
`54`		`- fprintf(stderr, "error on_write_end %d", status);`
`55`		`- exit(1);`
	`54`	`+ LOGERR("error on_write_end %d\n", status);`
`56`	`55`	`}`
`57`	`56`	`free(req);`
`58`	`57`	`}`
`@@ -85,7 +84,7 @@ void mine(mining_worker_t *worker)`
`85`	`84`	`int32_t to_mine_index = next_chain_to_mine();`
`86`	`85`	`if (to_mine_index == -1)`
`87`	`86`	`{`
`88`		`- printf("waiting for new tasks\n");`
	`87`	`+ LOG("waiting for new tasks\n");`
`89`	`88`	`worker->timer.data = worker;`
`90`	`89`	`uv_timer_start(&worker->timer, mine_with_timer, 500, 0);`
`91`	`90`	`} else {`
`@@ -95,7 +94,7 @@ void mine(mining_worker_t *worker)`
`95`	`94`	`start_worker_mining(worker);`
`96`	`95`
`97`	`96`	`duration_t elapsed = Time::now() - start;`
`98`		`- // printf("=== mining time: %fs\n", elapsed.count());`
	`97`	`+ // LOG("=== mining time: %fs\n", elapsed.count());`
`99`	`98`	`}`
`100`	`99`	`}`
`101`	`100`
`@@ -191,12 +190,12 @@ void log_hashrate(uv_timer_t *timer)`
`191`	`190`	`if (current_time > start_time)`
`192`	`191`	`{`
`193`	`192`	`duration_t eplased = current_time - start_time;`
`194`		`- printf("hashrate: %.0f MH/s ", total_mining_count.load() / eplased.count() / 1000000);`
	`193`	`+ LOG("hashrate: %.0f MH/s ", total_mining_count.load() / eplased.count() / 1000000);`
`195`	`194`	`for (int i = 0; i < gpu_count; i++)`
`196`	`195`	`{`
`197`		`- printf("gpu%d: %.0f MH/s ", i, device_mining_count[i].load() / eplased.count() / 1000000);`
	`196`	`+ LOG_WITHOUT_TS("gpu%d: %.0f MH/s ", i, device_mining_count[i].load() / eplased.count() / 1000000);`
`198`	`197`	`}`
`199`		`- printf("solutions: %u\n", found_solutions.load(std::memory_order_relaxed));`
	`198`	`+ LOG_WITHOUT_TS("solutions: %u\n", found_solutions.load(std::memory_order_relaxed));`
`200`	`199`	`}`
`201`	`200`	`}`
`202`	`201`
`@@ -250,7 +249,7 @@ void on_read(uv_stream_t server, ssize_t nread, const uv_buf_t buf)`
`250`	`249`	`{`
`251`	`250`	`if (nread < 0)`
`252`	`251`	`{`
`253`		`- fprintf(stderr, "error on_read %ld: might be that the full node is not synced, or miner wallets are not setup, try to reconnect\n", nread);`
	`252`	`+ LOGERR("error on_read %ld: might be that the full node is not synced, or miner wallets are not setup, try to reconnect\n", nread);`
`254`	`253`	`uv_timer_start(&reconnect_timer, try_to_reconnect, 5000, 0);`
`255`	`254`	`return;`
`256`	`255`	`}`
`@@ -274,7 +273,7 @@ void on_read(uv_stream_t server, ssize_t nread, const uv_buf_t buf)`
`274`	`273`	`break;`
`275`	`274`
`276`	`275`	`case SUBMIT_RESULT:`
`277`		`- printf("submitted: %d -> %d: %d \n", message->submit_result->from_group, message->submit_result->to_group, message->submit_result->status);`
	`276`	`+ LOG("submitted: %d -> %d: %d \n", message->submit_result->from_group, message->submit_result->to_group, message->submit_result->status);`
`278`	`277`	`break;`
`279`	`278`	`}`
`280`	`279`	`free_server_message_except_jobs(message);`
`@@ -288,11 +287,11 @@ void on_connect(uv_connect_t *req, int status)`
`288`	`287`	`{`
`289`	`288`	`if (status < 0)`
`290`	`289`	`{`
`291`		`- fprintf(stderr, "connection error %d: might be that the full node is not reachable, try to reconnect\n", status);`
	`290`	`+ LOGERR("connection error %d: might be that the full node is not reachable, try to reconnect\n", status);`
`292`	`291`	`uv_timer_start(&reconnect_timer, try_to_reconnect, 5000, 0);`
`293`	`292`	`return;`
`294`	`293`	`}`
`295`		`- printf("the server is connected %d %p\n", status, req);`
	`294`	`+ LOG("the server is connected %d %p\n", status, req);`
`296`	`295`
`297`	`296`	`tcp = req->handle;`
`298`	`297`	`uv_read_start(req->handle, alloc_buffer, on_read);`
`@@ -325,7 +324,7 @@ int hostname_to_ip(char ip_address, char hostname)`
`325`	`324`	`int res = getaddrinfo(hostname, NULL, &hints, &servinfo);`
`326`	`325`	`if (res != 0)`
`327`	`326`	`{`
`328`		`- fprintf(stderr, "getaddrinfo: %s\n", gai_strerror(res));`
	`327`	`+ LOGERR("getaddrinfo: %s\n", gai_strerror(res));`
`329`	`328`	`return 1;`
`330`	`329`	`}`
`331`	`330`
`@@ -349,19 +348,19 @@ int main(int argc, char **argv)`
`349`	`348`	`int rc = WSAStartup(MAKEWORD(2, 2), &wsa);`
`350`	`349`	`if (rc != 0)`
`351`	`350`	`{`
`352`		`- printf("Initialize winsock failed: %d", rc);`
	`351`	`+ LOGERR("Initialize winsock failed: %d\n", rc);`
`353`	`352`	`exit(1);`
`354`	`353`	`}`
`355`	`354`	`#endif`
`356`	`355`
`357`		`- printf("Running gpu-miner version : %s\n", MINER_VERSION);`
	`356`	`+ LOG("Running gpu-miner version : %s\n", MINER_VERSION);`
`358`	`357`
`359`	`358`	`int gpu_count = 0;`
`360`	`359`	`cudaGetDeviceCount(&gpu_count);`
`361`		`- printf("GPU count: %d\n", gpu_count);`
	`360`	`+ LOG("GPU count: %d\n", gpu_count);`
`362`	`361`	`for (int i = 0; i < gpu_count; i++)`
`363`	`362`	`{`
`364`		`- printf("GPU #%d has #%d cores\n", i, get_device_cores(i));`
	`363`	`+ LOG("GPU #%d has #%d cores\n", i, get_device_cores(i));`
`365`	`364`	`use_device[i] = true;`
`366`	`365`	`}`
`367`	`366`
`@@ -396,18 +395,22 @@ int main(int argc, char **argv)`
`396`	`395`	`{`
`397`	`396`	`int device = atoi(argv[optind]);`
`398`	`397`	`if (device < 0 \|\| device >= gpu_count) {`
`399`		`- printf("Invalid gpu index %d\n", device);`
	`398`	`+ LOGERR("Invalid gpu index %d\n", device);`
`400`	`399`	`exit(1);`
`401`	`400`	`}`
`402`	`401`	`use_device[device] = true;`
`403`	`402`	`}`
`404`	`403`	`break;`
`405`	`404`	`default:`
`406`		`- printf("Invalid command %c\n", command);`
	`405`	`+ LOGERR("Invalid command %c\n", command);`
`407`	`406`	`exit(1);`
`408`	`407`	`}`
`409`	`408`	`}`
`410`		`- printf("will connect to broker @%s:%d\n", broker_ip, port);`
	`409`	`+ LOG("will connect to broker @%s:%d\n", broker_ip, port);`
	`410`	`+`
	`411`	`+ #ifdef __linux__`
	`412`	`+ signal(SIGPIPE, SIG_IGN);`
	`413`	`+ #endif`
`411`	`414`
`412`	`415`	`mining_workers_init(gpu_count);`
`413`	`416`	`setup_gpu_worker_count(gpu_count, gpu_count * parallel_mining_works_per_gpu);`