@cryptotaxi247 / netdata-1 / commits / 5a944497d

Improve ACLK sync logging (#12534)

* Switch messages to ACLK RES, ACLK REQ, ACLK STA instead of OG, IN and just AC * Lookup hostname by node id * Record hostname when receiving an ACK for a chart sequence * Additional log_access info * Adjust log message when receing health log request * Remove redundant ACK log message * Remove duplicate log message * Remove duplicate sql statements * Rearrange variable definition for clarity * Make sure node is a valid UUID (check return code)

Stelios Fragkakis committed Mar 31, 2022 at 21:30 UTC 5a944497d39bee78b682882b9d43a80e2c33586b
5 files changed +283 -123
database/sqlite/sqlite_aclk_alert.c
+32 -17
@@ -127,7 +127,7 @@ void aclk_push_alert_event(struct aclk_database_worker_config *wc, struct aclk_d
127 int rc;
128
129 if (unlikely(!wc->alert_updates)) {
130 - log_access("AC [%s (%s)]: Ignoring alert push event, updates have been turned off for this node.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
130 + log_access("ACLK STA [%s (%s)]: Ignoring alert push event, updates have been turned off for this node.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
131 return;
132 }
133
@@ -274,7 +274,13 @@ void aclk_push_alert_event(struct aclk_database_worker_config *wc, struct aclk_d
274 db_execute(buffer_tostring(sql));
275 } else {
276 if (log_first_sequence_id)
277 - log_access("OG [%s (%s)]: Sent alert events, first sequence_id %"PRIu64", last sequence_id %"PRIu64, wc->node_id, wc->host->hostname, log_first_sequence_id, log_last_sequence_id);
277 + log_access(
278 + "ACLK RES [%s (%s)]: ALERTS SENT from %" PRIu64 " to %" PRIu64 " batch=%" PRIu64,
279 + wc->node_id,
280 + wc->host ? wc->host->hostname : "N/A",
281 + log_first_sequence_id,
282 + log_last_sequence_id,
283 + wc->alerts_batch_id);
284 log_first_sequence_id = 0;
285 log_last_sequence_id = 0;
286 }
@@ -295,7 +301,7 @@ void aclk_send_alarm_health_log(char *node_id)
301 if (unlikely(!node_id))
302 return;
303
298 - log_access("IN [%s (N/A)]: Request to send alarm health log.", node_id);
304 + char *hostname= NULL;
305
306 struct aclk_database_worker_config *wc = NULL;
307 struct aclk_database_cmd cmd;
@@ -304,14 +310,23 @@ void aclk_send_alarm_health_log(char *node_id)
310
311 rrd_rdlock();
312 RRDHOST *host = find_host_by_node_id(node_id);
307 - if (likely(host))
313 + if (likely(host)) {
314 wc = (struct aclk_database_worker_config *)host->dbsync_worker;
315 + hostname = host->hostname;
316 + }
317 + else
318 + hostname = get_hostname_by_node_id(node_id);
319 rrd_unlock();
320 +
321 + log_access("ACLK REQ [%s (%s)]: HEALTH LOG request received", node_id, hostname ? hostname : "N/A");
322 + if (unlikely(!host))
323 + freez(hostname);
324 +
325 if (wc)
326 aclk_database_enq_cmd(wc, &cmd);
327 else {
328 if (aclk_worker_enq_cmd(node_id, &cmd))
314 - log_access("AC [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
329 + log_access("ACLK STA [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
330 }
331 return;
332 }
@@ -398,7 +413,7 @@ void aclk_push_alarm_health_log(struct aclk_database_worker_config *wc, struct a
413 wc->alert_sequence_id = last_sequence;
414
415 aclk_send_alarm_log_health(&alarm_log);
401 - log_access("OG [%s (%s)]: Alarm health log sent, first sequence id %"PRIu64", last sequence id %"PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", first_sequence, last_sequence);
416 + log_access("ACLK RES [%s (%s)]: HEALTH LOG SENT from %"PRIu64" to %"PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", first_sequence, last_sequence);
417
418 rc = sqlite3_finalize(res);
419 if (unlikely(rc != SQLITE_OK))
@@ -422,7 +437,7 @@ void aclk_send_alarm_configuration(char *config_hash)
437 return;
438 }
439
425 - log_access("IN [%s (%s)]: Request to send alert config %s.", wc->node_id, wc->host ? wc->host->hostname : "N/A", config_hash);
440 + log_access("ACLK REQ [%s (%s)]: Request to send alert config %s.", wc->node_id, wc->host ? wc->host->hostname : "N/A", config_hash);
441
442 struct aclk_database_cmd cmd;
443 memset(&cmd, 0, sizeof(cmd));
@@ -532,14 +547,14 @@ int aclk_push_alert_config_event(struct aclk_database_worker_config *wc, struct
547 }
548
549 if (likely(p_alarm_config.cfg_hash)) {
535 - log_access("OG [%s (%s)]: Sent alert config %s.", wc->node_id, wc->host ? wc->host->hostname : "N/A", config_hash);
550 + log_access("ACLK RES [%s (%s)]: Sent alert config %s.", wc->node_id, wc->host ? wc->host->hostname : "N/A", config_hash);
551 aclk_send_provide_alarm_cfg(&p_alarm_config);
552 freez((char *) cmd.data_param);
553 freez(p_alarm_config.cfg_hash);
554 destroy_aclk_alarm_configuration(&alarm_config);
555 }
556 else
542 - log_access("AC [%s (%s)]: Alert config for %s not found.", wc->node_id, wc->host ? wc->host->hostname : "N/A", config_hash);
557 + log_access("ACLK STA [%s (%s)]: Alert config for %s not found.", wc->node_id, wc->host ? wc->host->hostname : "N/A", config_hash);
558
559 bind_fail:
560 rc = sqlite3_finalize(res);
@@ -559,7 +574,7 @@ void aclk_start_alert_streaming(char *node_id, uint64_t batch_id, uint64_t start
574 if (unlikely(!node_id))
575 return;
576
562 - log_access("IN [%s (N/A)]: Start streaming alerts with batch_id %"PRIu64" and start_seq_id %"PRIu64".", node_id, batch_id, start_seq_id);
577 + //log_access("ACLK REQ [%s (N/A)]: ALERTS STREAM from %"PRIu64" batch=%"PRIu64".", node_id, start_seq_id, batch_id);
578
579 uuid_t node_uuid;
580 if (uuid_parse(node_id, node_uuid))
@@ -575,14 +590,14 @@ void aclk_start_alert_streaming(char *node_id, uint64_t batch_id, uint64_t start
590 (struct aclk_database_worker_config *)find_inactive_wc_by_node_id(node_id);
591
592 if (unlikely(!host->health_enabled)) {
578 - log_access("AC [%s (N/A)]: Ignoring request to stream alert state changes, health is disabled.", node_id);
593 + log_access("ACLK STA [%s (N/A)]: Ignoring request to stream alert state changes, health is disabled.", node_id);
594 return;
595 }
596 } else
597 wc = (struct aclk_database_worker_config *)find_inactive_wc_by_node_id(node_id);
598
599 if (likely(wc)) {
585 - log_access("AC [%s (%s)]: Start streaming alerts enabled with batch_id %"PRIu64" and start_seq_id %"PRIu64".", node_id, wc->host ? wc->host->hostname : "N/A", batch_id, start_seq_id);
600 + log_access("ACLK REQ [%s (%s)]: ALERTS STREAM from %"PRIu64" batch=%"PRIu64, node_id, wc->host ? wc->host->hostname : "N/A", start_seq_id, batch_id);
601 __sync_synchronize();
602 wc->alerts_batch_id = batch_id;
603 wc->alerts_start_seq_id = start_seq_id;
@@ -590,7 +605,7 @@ void aclk_start_alert_streaming(char *node_id, uint64_t batch_id, uint64_t start
605 __sync_synchronize();
606 }
607 else
593 - log_access("AC [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
608 + log_access("ACLK STA [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
609
610 #else
611 UNUSED(node_id);
@@ -616,7 +631,7 @@ void sql_process_queue_removed_alerts_to_aclk(struct aclk_database_worker_config
631
632 db_execute(buffer_tostring(sql));
633
619 - log_access("AC [%s (%s)]: Queued removed alerts.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
634 + log_access("ACLK STA [%s (%s)]: Queued removed alerts.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
635
636 buffer_free(sql);
637 #endif
@@ -680,7 +695,7 @@ void aclk_process_send_alarm_snapshot(char *node_id, char *claim_id, uint64_t sn
695 cmd.completion = NULL;
696 aclk_database_enq_cmd(wc, &cmd);
697 } else
683 - log_access("AC [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
698 + log_access("ACLK STA [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
699 #else
700 UNUSED(node_id);
701 UNUSED(snapshot_id);
@@ -781,7 +796,7 @@ void aclk_push_alert_snapshot_event(struct aclk_database_worker_config *wc, stru
796 UNUSED(cmd);
797 // we perhaps we don't need this for snapshots
798 if (unlikely(!wc->alert_updates)) {
784 - log_access("AC [%s (%s)]: Ignoring alert snapshot event, updates have been turned off for this node.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
799 + log_access("ACLK STA [%s (%s)]: Ignoring alert snapshot event, updates have been turned off for this node.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
800 return;
801 }
802
@@ -797,7 +812,7 @@ void aclk_push_alert_snapshot_event(struct aclk_database_worker_config *wc, stru
812 if (unlikely(!claim_id))
813 return;
814
800 - log_access("OG [%s (%s)]: Sending alerts snapshot, snapshot_id %" PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", wc->alerts_snapshot_id);
815 + log_access("ACLK REQ [%s (%s)]: Sending alerts snapshot, snapshot_id %" PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", wc->alerts_snapshot_id);
816
817 aclk_mark_alert_cloud_ack(wc->uuid_str, wc->alerts_ack_sequence_id);
818
database/sqlite/sqlite_aclk_chart.c
+201 -105
@@ -7,8 +7,8 @@
7 #include "../../aclk/aclk_charts_api.h"
8 #include "../../aclk/aclk.h"
9
10 -static inline int sql_queue_chart_payload(struct aclk_database_worker_config *wc,
11 - void *data, enum aclk_database_opcode opcode)
10 +static inline int
11 +sql_queue_chart_payload(struct aclk_database_worker_config *wc, void *data, enum aclk_database_opcode opcode)
12 {
13 int rc;
14 if (unlikely(!wc))
@@ -40,11 +40,11 @@ static int payload_sent(char *uuid_str, uuid_t *uuid, void *payload, size_t payl
40 }
41 }
42
43 - rc = sqlite3_bind_blob(res, 1, uuid , sizeof(*uuid), SQLITE_STATIC);
43 + rc = sqlite3_bind_blob(res, 1, uuid, sizeof(*uuid), SQLITE_STATIC);
44 if (unlikely(rc != SQLITE_OK))
45 goto bind_fail;
46
47 - rc = sqlite3_bind_blob(res, 2, payload , payload_size, SQLITE_STATIC);
47 + rc = sqlite3_bind_blob(res, 2, payload, payload_size, SQLITE_STATIC);
48 if (unlikely(rc != SQLITE_OK))
49 goto bind_fail;
50
@@ -58,8 +58,13 @@ bind_fail:
58 return send_status;
59 }
60
61 -static int aclk_add_chart_payload(struct aclk_database_worker_config *wc, uuid_t *uuid, char *claim_id,
62 - ACLK_PAYLOAD_TYPE payload_type, void *payload, size_t payload_size)
61 +static int aclk_add_chart_payload(
62 + struct aclk_database_worker_config *wc,
63 + uuid_t *uuid,
64 + char *claim_id,
65 + ACLK_PAYLOAD_TYPE payload_type,
66 + void *payload,
67 + size_t payload_size)
68 {
69 static __thread sqlite3_stmt *res_chart = NULL;
70 int rc;
@@ -87,15 +92,15 @@ static int aclk_add_chart_payload(struct aclk_database_worker_config *wc, uuid_t
92 if (uuid_parse(claim_id, claim_uuid))
93 return 1;
94
90 - rc = sqlite3_bind_blob(res_chart, 1, &unique_uuid , sizeof(unique_uuid), SQLITE_STATIC);
95 + rc = sqlite3_bind_blob(res_chart, 1, &unique_uuid, sizeof(unique_uuid), SQLITE_STATIC);
96 if (unlikely(rc != SQLITE_OK))
97 goto bind_fail;
98
94 - rc = sqlite3_bind_blob(res_chart, 2, uuid , sizeof(*uuid), SQLITE_STATIC);
99 + rc = sqlite3_bind_blob(res_chart, 2, uuid, sizeof(*uuid), SQLITE_STATIC);
100 if (unlikely(rc != SQLITE_OK))
101 goto bind_fail;
102
98 - rc = sqlite3_bind_blob(res_chart, 3, &claim_uuid , sizeof(claim_uuid), SQLITE_STATIC);
103 + rc = sqlite3_bind_blob(res_chart, 3, &claim_uuid, sizeof(claim_uuid), SQLITE_STATIC);
104 if (unlikely(rc != SQLITE_OK))
105 goto bind_fail;
106
@@ -123,7 +128,6 @@ bind_fail:
128 return (rc != SQLITE_DONE);
129 }
130
126 -
131 int aclk_add_chart_event(struct aclk_database_worker_config *wc, struct aclk_database_cmd cmd)
132 {
133 int rc = 0;
@@ -158,15 +162,22 @@ int aclk_add_chart_event(struct aclk_database_worker_config *wc, struct aclk_dat
162 size_t size;
163 char *payload = generate_chart_instance_updated(&size, &chart_payload);
164 if (likely(payload))
161 - rc = aclk_add_chart_payload(wc, st->chart_uuid, claim_id, ACLK_PAYLOAD_CHART, (void *) payload, size);
165 + rc = aclk_add_chart_payload(wc, st->chart_uuid, claim_id, ACLK_PAYLOAD_CHART, (void *)payload, size);
166 freez(payload);
167 chart_instance_updated_destroy(&chart_payload);
168 }
169 return rc;
170 }
171
168 -static inline int aclk_upd_dimension_event(struct aclk_database_worker_config *wc, char *claim_id, uuid_t *dim_uuid,
169 - const char *dim_id, const char *dim_name, const char *chart_type_id, time_t first_time, time_t last_time)
172 +static inline int aclk_upd_dimension_event(
173 + struct aclk_database_worker_config *wc,
174 + char *claim_id,
175 + uuid_t *dim_uuid,
176 + const char *dim_id,
177 + const char *dim_name,
178 + const char *chart_type_id,
179 + time_t first_time,
180 + time_t last_time)
181 {
182 int rc = 0;
183 size_t size;
@@ -179,8 +190,13 @@ static inline int aclk_upd_dimension_event(struct aclk_database_worker_config *w
190
191 #ifdef NETDATA_INTERNAL_CHECKS
192 if (!first_time)
182 - info("Host %s (node %s) deleting dimension id=[%s] name=[%s] chart=[%s]",
183 - wc->host_guid, wc->node_id, dim_id, dim_name, chart_type_id);
193 + info(
194 + "Host %s (node %s) deleting dimension id=[%s] name=[%s] chart=[%s]",
195 + wc->host_guid,
196 + wc->node_id,
197 + dim_id,
198 + dim_name,
199 + chart_type_id);
200 #endif
201
202 dim_payload.node_id = wc->node_id;
@@ -216,8 +232,13 @@ void aclk_process_dimension_deletion(struct aclk_database_worker_config *wc, str
232 if (!claim_id)
233 return;
234
219 - rc = sqlite3_prepare_v2(db_meta, "DELETE FROM dimension_delete where host_id = @host_id " \
220 - "RETURNING dimension_id, dimension_name, chart_type_id, dim_id LIMIT 10;", -1, &res, 0);
235 + rc = sqlite3_prepare_v2(
236 + db_meta,
237 + "DELETE FROM dimension_delete where host_id = @host_id "
238 + "RETURNING dimension_id, dimension_name, chart_type_id, dim_id LIMIT 10;",
239 + -1,
240 + &res,
241 + 0);
242
243 if (rc != SQLITE_OK) {
244 error_report("Failed to prepare statement when trying to delete dimension deletes");
@@ -225,13 +246,13 @@ void aclk_process_dimension_deletion(struct aclk_database_worker_config *wc, str
246 return;
247 }
248
228 - rc = sqlite3_bind_blob(res, 1, &host_id , sizeof(host_id), SQLITE_STATIC);
249 + rc = sqlite3_bind_blob(res, 1, &host_id, sizeof(host_id), SQLITE_STATIC);
250 if (unlikely(rc != SQLITE_OK))
251 goto bind_fail;
252
253 unsigned count = 0;
254 while (sqlite3_step(res) == SQLITE_ROW) {
234 - (void) aclk_upd_dimension_event(
255 + (void)aclk_upd_dimension_event(
256 wc,
257 claim_id,
258 (uuid_t *)sqlite3_column_text(res, 3),
@@ -271,7 +292,7 @@ int aclk_add_dimension_event(struct aclk_database_worker_config *wc, struct aclk
292 time_t now = now_realtime_sec();
293
294 time_t first_t = rd->state->query_ops.oldest_time(rd);
274 - time_t last_t = rd->state->query_ops.latest_time(rd);
295 + time_t last_t = rd->state->query_ops.latest_time(rd);
296
297 int live = ((now - last_t) < MAX(RRDSET_MINIMUM_LIVE_MULTIPLIER * rd->update_every, rrdset_free_obsolete_time));
298
@@ -291,14 +312,16 @@ int aclk_add_dimension_event(struct aclk_database_worker_config *wc, struct aclk
312 return rc;
313 }
314
294 -
315 void aclk_send_chart_event(struct aclk_database_worker_config *wc, struct aclk_database_cmd cmd)
316 {
317 int rc;
318
319 wc->chart_pending = 0;
320 if (unlikely(!wc->chart_updates)) {
301 - log_access("AC [%s (%s)]: Ignoring chart push event, updates have been turned off for this node.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
321 + log_access(
322 + "ACLK STA [%s (%s)]: Ignoring chart push event, updates have been turned off for this node.",
323 + wc->node_id,
324 + wc->host ? wc->host->hostname : "N/A");
325 return;
326 }
327
@@ -332,15 +355,15 @@ void aclk_send_chart_event(struct aclk_database_worker_config *wc, struct aclk_d
355 }
356 }
357
335 - rc = sqlite3_bind_blob(res, 1, claim_uuid , sizeof(claim_uuid), SQLITE_STATIC);
358 + rc = sqlite3_bind_blob(res, 1, claim_uuid, sizeof(claim_uuid), SQLITE_STATIC);
359 if (unlikely(rc != SQLITE_OK))
360 goto bind_fail;
361
339 - char **payload_list = callocz(limit+1, sizeof(char *));
340 - size_t *payload_list_size = callocz(limit+1, sizeof(size_t));
341 - size_t *payload_list_max_size = callocz(limit+1, sizeof(size_t));
342 - struct aclk_message_position *position_list = callocz(limit+1, sizeof(*position_list));
343 - int *is_dim = callocz(limit+1, sizeof(*is_dim));
362 + char **payload_list = callocz(limit + 1, sizeof(char *));
363 + size_t *payload_list_size = callocz(limit + 1, sizeof(size_t));
364 + size_t *payload_list_max_size = callocz(limit + 1, sizeof(size_t));
365 + struct aclk_message_position *position_list = callocz(limit + 1, sizeof(*position_list));
366 + int *is_dim = callocz(limit + 1, sizeof(*is_dim));
367
368 int loop = cmd.param1;
369
@@ -398,11 +421,16 @@ void aclk_send_chart_event(struct aclk_database_worker_config *wc, struct aclk_d
421 db_unlock();
422
423 aclk_chart_inst_and_dim_update(payload_list, payload_list_size, is_dim, position_list, wc->batch_id);
401 - log_access("OG [%s (%s)]: Sending charts and dimensions update, batch_id %"PRIu64", first sequence %"PRIu64", last sequence %"PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", wc->batch_id, first_sequence, last_sequence);
424 + log_access(
425 + "ACLK RES [%s (%s)]: CHARTS SENT from %" PRIu64 " to %" PRIu64 " batch=%" PRIu64,
426 + wc->node_id,
427 + wc->host ? wc->host->hostname : "N/A",
428 + first_sequence,
429 + last_sequence,
430 + wc->batch_id);
431 wc->chart_sequence_id = last_sequence;
432 wc->chart_timestamp = last_timestamp;
404 - }
405 - else
433 + } else
434 break;
435 --loop;
436 }
@@ -411,11 +439,14 @@ void aclk_send_chart_event(struct aclk_database_worker_config *wc, struct aclk_d
439 time_t now = now_realtime_sec();
440 if (wc->rotation_after > now && wc->rotation_after < now + ACLK_DATABASE_ROTATION_DELAY)
441 wc->rotation_after = now + ACLK_DATABASE_ROTATION_DELAY;
414 - }
415 - else {
442 + } else {
443 wc->chart_payload_count = sql_get_pending_count(wc);
444 if (!wc->chart_payload_count)
418 - log_access("AC [%s (%s)]: Sync of charts and dimensions done in %ld seconds.", wc->node_id, wc->host ? wc->host->hostname : "N/A", now_realtime_sec() - wc->startup_time);
445 + log_access(
446 + "ACLK STA [%s (%s)]: Sync of charts and dimensions done in %ld seconds.",
447 + wc->node_id,
448 + wc->host ? wc->host->hostname : "N/A",
449 + now_realtime_sec() - wc->startup_time);
450 }
451
452 for (int i = 0; i <= limit; ++i)
@@ -487,31 +518,35 @@ int aclk_send_chart_config(struct aclk_database_worker_config *wc, struct aclk_d
518 }
519
520 if (likely(chart_config.config_hash)) {
490 - log_access("OG [%s (%s)]: Sending chart config for %s.", wc->node_id, wc->host ? wc->host->hostname : "N/A", hash_id);
521 + log_access(
522 + "ACLK REQ [%s (%s)]: Sending chart config for %s.",
523 + wc->node_id,
524 + wc->host ? wc->host->hostname : "N/A",
525 + hash_id);
526 aclk_chart_config_updated(&chart_config, 1);
527 destroy_chart_config_updated(&chart_config);
493 - }
494 - else
495 - log_access("AC [%s (%s)]: Chart config for %s not found.", wc->node_id, wc->host ? wc->host->hostname : "N/A", hash_id);
528 + } else
529 + log_access(
530 + "ACLK STA [%s (%s)]: Chart config for %s not found.",
531 + wc->node_id,
532 + wc->host ? wc->host->hostname : "N/A",
533 + hash_id);
534
497 - bind_fail:
498 - rc = sqlite3_finalize(res);
499 - if (unlikely(rc != SQLITE_OK))
500 - error_report("Failed to reset statement when pushing chart config hash, rc = %d", rc);
501 - fail:
502 - freez((char *) cmd.data_param);
503 - buffer_free(sql);
504 - return rc;
535 +bind_fail:
536 + rc = sqlite3_finalize(res);
537 + if (unlikely(rc != SQLITE_OK))
538 + error_report("Failed to reset statement when pushing chart config hash, rc = %d", rc);
539 +fail:
540 + freez((char *)cmd.data_param);
541 + buffer_free(sql);
542 + return rc;
543 }
544
507 -
545 void aclk_receive_chart_ack(struct aclk_database_worker_config *wc, struct aclk_database_cmd cmd)
546 {
547 int rc;
548 sqlite3_stmt *res = NULL;
549
513 - log_access("IN [%s (%s)]: Received ack chart sequence id %"PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", cmd.param1);
514 -
550 char sql[ACLK_SYNC_QUERY_SIZE];
551
552 snprintfz(sql,ACLK_SYNC_QUERY_SIZE-1,"UPDATE aclk_chart_%s SET date_updated=strftime('%%s','now') WHERE sequence_id <= @sequence_id "
@@ -530,6 +565,12 @@ void aclk_receive_chart_ack(struct aclk_database_worker_config *wc, struct aclk_
565 rc = execute_insert(res);
566 if (rc != SQLITE_DONE)
567 error_report("Failed to ACK sequence id, rc = %d", rc);
568 + else
569 + log_access(
570 + "ACLK STA [%s (%s)]: CHARTS ACKNOWLEDGED in the database upto %" PRIu64,
571 + wc->node_id,
572 + wc->host ? wc->host->hostname : "N/A",
573 + cmd.param1);
574
575 bind_fail:
576 if (unlikely(sqlite3_finalize(res) != SQLITE_OK))
@@ -540,15 +581,19 @@ bind_fail:
581 void aclk_receive_chart_reset(struct aclk_database_worker_config *wc, struct aclk_database_cmd cmd)
582 {
583 BUFFER *sql = buffer_create(1024);
543 - buffer_sprintf(sql, "UPDATE aclk_chart_%s SET status = NULL, date_submitted = NULL WHERE sequence_id >= %"PRIu64";",
544 - wc->uuid_str, cmd.param1);
584 + buffer_sprintf(
585 + sql,
586 + "UPDATE aclk_chart_%s SET status = NULL, date_submitted = NULL WHERE sequence_id >= %" PRIu64 ";",
587 + wc->uuid_str,
588 + cmd.param1);
589 db_execute(buffer_tostring(sql));
590 if (cmd.param1 == 1) {
591 buffer_flush(sql);
548 - log_access("IN [%s (%s)]: Received chart full resync.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
592 + log_access("ACLK REQ [%s (%s)]: Received chart full resync.", wc->node_id, wc->host ? wc->host->hostname : "N/A");
593 buffer_sprintf(sql, "DELETE FROM aclk_chart_payload_%s; DELETE FROM aclk_chart_%s; " \
594 "DELETE FROM aclk_chart_latest_%s;", wc->uuid_str, wc->uuid_str, wc->uuid_str);
595 db_lock();
596 +
597 db_execute("BEGIN TRANSACTION;");
598 db_execute(buffer_tostring(sql));
599 db_execute("COMMIT TRANSACTION;");
@@ -574,12 +619,14 @@ void aclk_receive_chart_reset(struct aclk_database_worker_config *wc, struct acl
619 rrdset_unlock(st);
620 }
621 rrdhost_unlock(host);
577 - }
578 - else
622 + } else
623 error_report("ACLK synchronization thread for %s is not linked to HOST", wc->host_guid);
580 - }
581 - else {
582 - log_access("AC [%s (%s)]: Restarting chart sync from sequence %"PRIu64, wc->node_id, wc->host ? wc->host->hostname : "N/A", cmd.param1);
624 + } else {
625 + log_access(
626 + "ACLK STA [%s (%s)]: Restarting chart sync from sequence %" PRIu64,
627 + wc->node_id,
628 + wc->host ? wc->host->hostname : "N/A",
629 + cmd.param1);
630 wc->chart_payload_count = sql_get_pending_count(wc);
631 sql_get_last_chart_sequence(wc);
632 }
@@ -588,7 +635,6 @@ void aclk_receive_chart_reset(struct aclk_database_worker_config *wc, struct acl
635 return;
636 }
637
591 -
638 //
639 // Functions called directly from ACLK threads and will queue commands
640 //
@@ -604,7 +650,12 @@ void aclk_get_chart_config(char **hash_id)
650 cmd.opcode = ACLK_DATABASE_PUSH_CHART_CONFIG;
651 for (int i = 0; hash_id[i]; ++i) {
652 // TODO: Verify that we have a valid hash_id
607 - log_access("IN [%s (%s)]: Request %d for chart config with hash %s received.", wc->node_id, wc->host ? wc->host->hostname : "N/A", i, hash_id[i]);
653 + log_access(
654 + "ACLK REQ [%s (%s)]: Request %d for chart config with hash %s received.",
655 + wc->node_id,
656 + wc->host ? wc->host->hostname : "N/A",
657 + i,
658 + hash_id[i]);
659 cmd.data_param = (void *)strdupz(hash_id[i]);
660 aclk_database_enq_cmd(wc, &cmd);
661 }
@@ -619,7 +670,7 @@ static void aclk_submit_param_command(char *node_id, enum aclk_database_opcode a
670 if (unlikely(!node_id))
671 return;
672
622 - struct aclk_database_worker_config *wc = NULL;
673 + struct aclk_database_worker_config *wc = NULL;
674 struct aclk_database_cmd cmd;
675 memset(&cmd, 0, sizeof(cmd));
676 cmd.opcode = aclk_command;
@@ -634,7 +685,7 @@ static void aclk_submit_param_command(char *node_id, enum aclk_database_opcode a
685 aclk_database_enq_cmd(wc, &cmd);
686 else {
687 if (aclk_worker_enq_cmd(node_id, &cmd))
637 - log_access("AC [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
688 + log_access("ACLK STA [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
689 }
690 return;
691 }
@@ -644,7 +695,10 @@ void aclk_ack_chart_sequence_id(char *node_id, uint64_t last_sequence_id)
695 if (unlikely(!node_id))
696 return;
697
647 - log_access("AC [%s (N/A)]: Node reports last sequence id received %"PRIu64, node_id, last_sequence_id);
698 + char *hostname = get_hostname_by_node_id(node_id);
699 + log_access("ACLK REQ [%s (%s)]: CHARTS ACKNOWLEDGED upto %" PRIu64, node_id, hostname ? hostname : "N/A",
700 + last_sequence_id);
701 + freez(hostname);
702 aclk_submit_param_command(node_id, ACLK_DATABASE_CHART_ACK, last_sequence_id);
703 return;
704 }
@@ -656,12 +710,14 @@ void aclk_start_streaming(char *node_id, uint64_t sequence_id, time_t created_at
710 if (unlikely(!node_id))
711 return;
712
659 - log_access("IN [%s (N/A)]: Start streaming charts from sequence %"PRIu64" t=%ld, batch=%"PRIu64, node_id,
660 - sequence_id, created_at, batch_id);
713 + // log_access("ACLK REQ [%s (N/A)]: CHARTS STREAM from %"PRIu64" t=%ld batch=%"PRIu64, node_id,
714 + // sequence_id, created_at, batch_id);
715
716 uuid_t node_uuid;
663 - if (uuid_parse(node_id, node_uuid))
717 + if (uuid_parse(node_id, node_uuid)) {
718 + log_access("ACLK REQ [%s (N/A)]: CHARTS STREAM ignored, invalid node id", node_id);
719 return;
720 + }
721
722 struct aclk_database_worker_config *wc = NULL;
723 rrd_rdlock();
@@ -679,10 +735,23 @@ void aclk_start_streaming(char *node_id, uint64_t sequence_id, time_t created_at
735 wc->batch_id = batch_id;
736 __sync_synchronize();
737 wc->batch_created = now_realtime_sec();
738 + log_access(
739 + "ACLK REQ [%s (%s)]: CHARTS STREAM from %" PRIu64 " t=%ld resets=%d",
740 + wc->node_id,
741 + wc->host ? wc->host->hostname : "N/A",
742 + wc->chart_sequence_id,
743 + wc->chart_timestamp,
744 + wc->chart_reset_count);
745 if (sequence_id > wc->chart_sequence_id || wc->chart_reset_count > 10) {
683 - log_access("AC [%s (%s)]: Requesting full resync from the cloud "
684 - "(reset=%d, remote_seq=%"PRIu64", local_seq=%"PRIu64")"
685 - , wc->node_id, wc->host ? wc->host->hostname : "N/A", wc->chart_reset_count, sequence_id, wc->chart_sequence_id);
746 + log_access(
747 + "ACLK RES [%s (%s)]: CHARTS FULL RESYNC REQUEST "
748 + "remote_seq=%" PRIu64 " local_seq=%" PRIu64 " resets=%d ",
749 + wc->node_id,
750 + wc->host ? wc->host->hostname : "N/A",
751 + sequence_id,
752 + wc->chart_sequence_id,
753 + wc->chart_reset_count);
754 +
755 chart_reset_t chart_reset;
756 chart_reset.claim_id = is_agent_claimed();
757 if (chart_reset.claim_id) {
@@ -697,26 +766,34 @@ void aclk_start_streaming(char *node_id, uint64_t sequence_id, time_t created_at
766 struct aclk_database_cmd cmd;
767 memset(&cmd, 0, sizeof(cmd));
768 // TODO: handle timestamp
700 - if (sequence_id < wc->chart_sequence_id || !sequence_id) { // || created_at != wc->chart_timestamp) {
701 - log_access("AC [%s (%s)]: Reset streaming charts from sequence %"PRIu64 \
702 - " t=%ld (reset count=%d)", wc->node_id, wc->host ? wc->host->hostname : "N/A", wc->chart_sequence_id,
703 - wc->chart_timestamp, wc->chart_reset_count);
769 + if (sequence_id < wc->chart_sequence_id ||
770 + !sequence_id) { // || created_at != wc->chart_timestamp) {
771 + log_access(
772 + "ACLK REQ [%s (%s)]: CHART RESET from %" PRIu64 " t=%ld batch=%" PRIu64,
773 + wc->node_id,
774 + wc->host ? wc->host->hostname : "N/A",
775 + wc->chart_sequence_id,
776 + wc->chart_timestamp,
777 + wc->batch_id);
778 cmd.opcode = ACLK_DATABASE_RESET_CHART;
779 cmd.param1 = sequence_id + 1;
780 cmd.completion = NULL;
781 aclk_database_enq_cmd(wc, &cmd);
708 - }
709 - else {
710 - log_access("AC [%s (%s)]: Start streaming charts enabled -- last streamed sequence %"PRIu64 \
711 - " t=%ld (reset count=%d)", wc->node_id, wc->host ? wc->host->hostname : "N/A", wc->chart_sequence_id,
712 - wc->chart_timestamp, wc->chart_reset_count);
782 + } else {
783 +// log_access(
784 +// "ACLK RES [%s (%s)]: CHARTS STREAM from %" PRIu64
785 +// " t=%ld resets=%d",
786 +// wc->node_id,
787 +// wc->host ? wc->host->hostname : "N/A",
788 +// wc->chart_sequence_id,
789 +// wc->chart_timestamp,
790 +// wc->chart_reset_count);
791 wc->chart_reset_count = 0;
792 wc->chart_updates = 1;
793 }
794 }
717 - }
718 - else
719 - log_access("AC [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
795 + } else
796 + log_access("ACLK STA [%s (N/A)]: ACLK synchronization thread is not active.", node_id);
797 return;
798 }
799 host = host->next;
@@ -748,7 +825,7 @@ static RRD_MEMORY_MODE sql_get_host_memory_mode(uuid_t *host_id)
825 }
826
827 while (sqlite3_step(res) == SQLITE_ROW) {
751 - memory_mode = (RRD_MEMORY_MODE) sqlite3_column_int(res, 0);
828 + memory_mode = (RRD_MEMORY_MODE)sqlite3_column_int(res, 0);
829 }
830
831 failed:
@@ -758,11 +835,13 @@ failed:
835 return memory_mode;
836 }
837
761 -#define SELECT_HOST_DIMENSION_LIST "SELECT d.dim_id, c.update_every, c.type||'.'||c.id, d.id, d.name FROM chart c, dimension d " \
762 - "WHERE d.chart_id = c.chart_id AND c.host_id = @host_id ORDER BY c.update_every ASC;"
838 +#define SELECT_HOST_DIMENSION_LIST \
839 + "SELECT d.dim_id, c.update_every, c.type||'.'||c.id, d.id, d.name FROM chart c, dimension d " \
840 + "WHERE d.chart_id = c.chart_id AND c.host_id = @host_id ORDER BY c.update_every ASC;"
841
764 -#define SELECT_HOST_CHART_LIST "SELECT distinct h.host_id, c.update_every, c.type||'.'||c.id FROM chart c, host h " \
765 - "WHERE c.host_id = h.host_id AND c.host_id = @host_id ORDER BY c.update_every ASC;"
842 +#define SELECT_HOST_CHART_LIST \
843 + "SELECT distinct h.host_id, c.update_every, c.type||'.'||c.id FROM chart c, host h " \
844 + "WHERE c.host_id = h.host_id AND c.host_id = @host_id ORDER BY c.update_every ASC;"
845
846 void aclk_update_retention(struct aclk_database_worker_config *wc, struct aclk_database_cmd cmd)
847 {
@@ -808,9 +887,9 @@ void aclk_update_retention(struct aclk_database_worker_config *wc, struct aclk_d
887 goto failed;
888 }
889
811 - time_t start_time = LONG_MAX;
812 - time_t first_entry_t;
813 - time_t last_entry_t;
890 + time_t start_time = LONG_MAX;
891 + time_t first_entry_t;
892 + time_t last_entry_t;
893 uint32_t update_every = 0;
894
895 struct retention_updated rotate_data;
@@ -829,9 +908,9 @@ void aclk_update_retention(struct aclk_database_worker_config *wc, struct aclk_d
908
909 // time_t now = now_realtime_sec();
910 while (sqlite3_step(res) == SQLITE_ROW) {
832 - if (!update_every || update_every != (uint32_t) sqlite3_column_int(res, 1)) {
911 + if (!update_every || update_every != (uint32_t)sqlite3_column_int(res, 1)) {
912 if (update_every) {
834 - debug(D_ACLK_SYNC,"Update %s for %u oldest time = %ld", wc->host_guid, update_every, start_time);
913 + debug(D_ACLK_SYNC, "Update %s for %u oldest time = %ld", wc->host_guid, update_every, start_time);
914 if (start_time == LONG_MAX)
915 rotate_data.interval_durations[rotate_data.interval_duration_count].retention = 0;
916 else
@@ -839,13 +918,14 @@ void aclk_update_retention(struct aclk_database_worker_config *wc, struct aclk_d
918 rotate_data.rotation_timestamp.tv_sec - start_time;
919 rotate_data.interval_duration_count++;
920 }
842 - update_every = (uint32_t) sqlite3_column_int(res, 1);
921 + update_every = (uint32_t)sqlite3_column_int(res, 1);
922 rotate_data.interval_durations[rotate_data.interval_duration_count].update_every = update_every;
923 start_time = LONG_MAX;
924 }
925 #ifdef ENABLE_DBENGINE
926 if (memory_mode == RRD_MEMORY_MODE_DBENGINE)
848 - rc = rrdeng_metric_latest_time_by_uuid((uuid_t *)sqlite3_column_blob(res, 0), &first_entry_t, &last_entry_t);
927 + rc =
928 + rrdeng_metric_latest_time_by_uuid((uuid_t *)sqlite3_column_blob(res, 0), &first_entry_t, &last_entry_t);
929 else
930 #endif
931 {
@@ -856,8 +936,7 @@ void aclk_update_retention(struct aclk_database_worker_config *wc, struct aclk_d
936 first_entry_t = rrdset_first_entry_t(st);
937 last_entry_t = rrdset_last_entry_t(st);
938 }
859 - }
860 - else {
939 + } else {
940 rc = 0;
941 first_entry_t = rotate_data.rotation_timestamp.tv_sec;
942 }
@@ -878,8 +957,12 @@ void aclk_update_retention(struct aclk_database_worker_config *wc, struct aclk_d
957
958 #ifdef NETDATA_INTERNAL_CHECKS
959 for (int i = 0; i < rotate_data.interval_duration_count; ++i)
881 - info("Update for host %s (node %s) for %u Retention = %u", wc->host_guid, wc->node_id,
882 - rotate_data.interval_durations[i].update_every, rotate_data.interval_durations[i].retention);
960 + info(
961 + "Update for host %s (node %s) for %u Retention = %u",
962 + wc->host_guid,
963 + wc->node_id,
964 + rotate_data.interval_durations[i].update_every,
965 + rotate_data.interval_durations[i].retention);
966 #endif
967 aclk_retention_updated(&rotate_data);
968 freez(rotate_data.node_id);
@@ -893,7 +976,6 @@ failed:
976 return;
977 }
978
896 -
979 uint32_t sql_get_pending_count(struct aclk_database_worker_config *wc)
980 {
981 char sql[ACLK_SYNC_QUERY_SIZE];
@@ -938,11 +1020,11 @@ void sql_get_last_chart_sequence(struct aclk_database_worker_config *wc)
1020 wc->chart_sequence_id = 0;
1021 wc->chart_timestamp = 0;
1022 while (sqlite3_step(res) == SQLITE_ROW) {
941 - wc->chart_sequence_id = (uint64_t) sqlite3_column_int64(res, 0);
942 - wc->chart_timestamp = (time_t) sqlite3_column_int64(res, 1);
1023 + wc->chart_sequence_id = (uint64_t)sqlite3_column_int64(res, 0);
1024 + wc->chart_timestamp = (time_t)sqlite3_column_int64(res, 1);
1025 }
1026
945 - debug(D_ACLK_SYNC,"Node %s reports last sequence_id=%"PRIu64, wc->node_id, wc->chart_sequence_id);
1027 + debug(D_ACLK_SYNC, "Node %s reports last sequence_id=%" PRIu64, wc->node_id, wc->chart_sequence_id);
1028
1029 rc = sqlite3_finalize(res);
1030 if (unlikely(rc != SQLITE_OK))
@@ -986,12 +1068,26 @@ void aclk_send_dimension_update(RRDDIM *rd)
1068 live ? 0 : last_entry_t);
1069
1070 if (!first_entry_t)
989 - debug(D_ACLK_SYNC, "%s: Update dimension chart=%s dim=%s live=%d (%ld, %ld)",
990 - rd->rrdset->rrdhost->hostname, rd->rrdset->name, rd->name, live, first_entry_t, last_entry_t);
1071 + debug(
1072 + D_ACLK_SYNC,
1073 + "%s: Update dimension chart=%s dim=%s live=%d (%ld, %ld)",
1074 + rd->rrdset->rrdhost->hostname,
1075 + rd->rrdset->name,
1076 + rd->name,
1077 + live,
1078 + first_entry_t,
1079 + last_entry_t);
1080 else
992 - debug(D_ACLK_SYNC, "%s: Update dimension chart=%s dim=%s live=%d (%ld, %ld) collected %ld seconds ago",
993 - rd->rrdset->rrdhost->hostname, rd->rrdset->name, rd->name, live, first_entry_t,
994 - last_entry_t, now - last_entry_t);
1081 + debug(
1082 + D_ACLK_SYNC,
1083 + "%s: Update dimension chart=%s dim=%s live=%d (%ld, %ld) collected %ld seconds ago",
1084 + rd->rrdset->rrdhost->hostname,
1085 + rd->rrdset->name,
1086 + rd->name,
1087 + live,
1088 + first_entry_t,
1089 + last_entry_t,
1090 + now - last_entry_t);
1091 rd->state->aclk_live_status = live;
1092 }
1093
database/sqlite/sqlite_aclk_node.c
+1 -1
@@ -63,7 +63,7 @@ void sql_build_node_info(struct aclk_database_worker_config *wc, struct aclk_dat
63 node_info.data.host_labels_head = labels->head;
64
65 aclk_update_node_info(&node_info);
66 - log_access("OG [%s (%s)]: Sending node info for guid [%s] (%s).", wc->node_id, wc->host->hostname, wc->host_guid, wc->host == localhost ? "parent" : "child");
66 + log_access("ACLK RES [%s (%s)]: NODE INFO SENT for guid [%s] (%s)", wc->node_id, wc->host->hostname, wc->host_guid, wc->host == localhost ? "parent" : "child");
67
68 netdata_rwlock_unlock(&labels->labels_rwlock);
69 rrd_unlock();
database/sqlite/sqlite_functions.c
+48
@@ -1879,6 +1879,54 @@ failed:
1879 return rc - 1;
1880 }
1881
1882 +#define SQL_SELECT_HOSTNAME_BY_NODE_ID "SELECT h.hostname FROM node_instance ni, " \
1883 +"host h WHERE ni.host_id = h.host_id AND ni.node_id = @node_id;"
1884 +
1885 +char *get_hostname_by_node_id(char *node)
1886 +{
1887 + sqlite3_stmt *res = NULL;
1888 + char *hostname = NULL;
1889 + int rc;
1890 +
1891 + rrd_rdlock();
1892 + RRDHOST *host = find_host_by_node_id(node);
1893 + rrd_unlock();
1894 + if (host)
1895 + return strdupz(host->hostname);
1896 +
1897 + if (unlikely(!db_meta)) {
1898 + if (default_rrd_memory_mode == RRD_MEMORY_MODE_DBENGINE)
1899 + error_report("Database has not been initialized");
1900 + return NULL;
1901 + }
1902 +
1903 + uuid_t node_id;
1904 + if (uuid_parse(node, node_id))
1905 + return NULL;
1906 +
1907 + rc = sqlite3_prepare_v2(db_meta, SQL_SELECT_HOSTNAME_BY_NODE_ID, -1, &res, 0);
1908 + if (unlikely(rc != SQLITE_OK)) {
1909 + error_report("Failed to prepare statement to fetch hostname by node id");
1910 + return NULL;
1911 + }
1912 +
1913 + rc = sqlite3_bind_blob(res, 1, &node_id, sizeof(node_id), SQLITE_STATIC);
1914 + if (unlikely(rc != SQLITE_OK)) {
1915 + error_report("Failed to bind host_id parameter to select node instance information");
1916 + goto failed;
1917 + }
1918 +
1919 + rc = sqlite3_step(res);
1920 + if (likely(rc == SQLITE_ROW))
1921 + hostname = strdupz((char *)sqlite3_column_text(res, 0));
1922 +
1923 +failed:
1924 + if (unlikely(sqlite3_finalize(res) != SQLITE_OK))
1925 + error_report("Failed to finalize the prepared statement when search for hostname by node id");
1926 +
1927 + return hostname;
1928 +}
1929 +
1930 #define SQL_SELECT_HOST_BY_NODE_ID "select host_id from node_instance where node_id = @node_id;"
1931
1932 int get_host_id(uuid_t *node_id, uuid_t *host_id)
database/sqlite/sqlite_functions.h
+1
@@ -99,4 +99,5 @@ extern struct node_instance_list *get_node_list(void);
99 extern void sql_load_node_id(RRDHOST *host);
100 extern void compute_chart_hash(RRDSET *st);
101 extern int sql_set_dimension_option(uuid_t *dim_uuid, char *option);
102 +char *get_hostname_by_node_id(char *node_id);
103 #endif //NETDATA_SQLITE_FUNCTIONS_H