Skip to content

Commit bc73b15

Browse files
dmehaladmehala
authored
fix(telemetry): report logs only once (#207)
Changes: - Update telemetry API for logs to be consistent with metrics. - Add test to validate logs are send in `app-closing`.
1 parent 8f05ef9 commit bc73b15

File tree

5 files changed

+131
-91
lines changed

5 files changed

+131
-91
lines changed

‎include/datadog/telemetry/telemetry.h‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -57,21 +57,24 @@ void send_configuration_change();
5757
void capture_configuration_change(
5858
const std::vector<tracing::ConfigMetadata>& new_configuration);
5959

60+
/// The `log` namespace provides functions for reporting logs.
61+
namespace log {
6062
/// Report internal warning message to Datadog.
6163
///
6264
/// @param message The warning message to log.
63-
void report_warning_log(std::string message);
65+
void warning(std::string message);
6466

6567
/// Report internal error message to Datadog.
6668
///
6769
/// @param message The error message.
68-
void report_error_log(std::string message);
70+
void error(std::string message);
6971

7072
/// Report internal error message to Datadog.
7173
///
7274
/// @param message The error message.
7375
/// @param stacktrace Stacktrace leading to the error.
74-
void report_error_log(std::string message, std::string stacktrace);
76+
void error(std::string message, std::string stacktrace);
77+
} // namespace log
7578

7679
/// The `counter` namespace provides functions to track values.
7780
/// Counters can be useful for tracking the total number of an event occurring

‎src/datadog/telemetry/telemetry.cpp‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -75,23 +75,24 @@ void capture_configuration_change(
7575
instance());
7676
}
7777

78-
void report_warning_log(std::string message) {
78+
namespace log {
79+
void warning(std::string message) {
7980
std::visit(details::Overload{
8081
[&](Telemetry& telemetry) { telemetry.log_warning(message); },
8182
[](NoopTelemetry) {},
8283
},
8384
instance());
8485
}
8586

86-
void report_error_log(std::string message) {
87+
void error(std::string message) {
8788
std::visit(details::Overload{
8889
[&](Telemetry& telemetry) { telemetry.log_error(message); },
8990
[](NoopTelemetry) {},
9091
},
9192
instance());
9293
}
9394

94-
void report_error_log(std::string message, std::string stacktrace) {
95+
void error(std::string message, std::string stacktrace) {
9596
std::visit(details::Overload{
9697
[&](Telemetry& telemetry) {
9798
telemetry.log_error(message, stacktrace);
@@ -100,6 +101,7 @@ void report_error_log(std::string message, std::string stacktrace) {
100101
},
101102
instance());
102103
}
104+
} // namespace log
103105

104106
namespace counter {
105107
void increment(const Counter& counter) {

‎src/datadog/telemetry/telemetry_impl.cpp‎

Lines changed: 23 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -76,16 +76,21 @@ std::string to_string(datadog::tracing::ConfigName name) {
7676
std::abort();
7777
}
7878

79-
nlohmann::json encode_log(const telemetry::LogMessage& log) {
80-
auto encoded = nlohmann::json{
81-
{"message", log.message},
82-
{"level", to_string(log.level)},
83-
{"tracer_time", log.timestamp},
84-
};
85-
if (log.stacktrace) {
86-
encoded.emplace("stack_trace", *log.stacktrace);
79+
nlohmann::json encode_logs(const std::vector<telemetry::LogMessage>& logs) {
80+
auto encoded_logs = nlohmann::json::array();
81+
for (auto& log : logs) {
82+
auto encoded = nlohmann::json{
83+
{"message", log.message},
84+
{"level", to_string(log.level)},
85+
{"tracer_time", log.timestamp},
86+
};
87+
if (log.stacktrace) {
88+
encoded.emplace("stack_trace", *log.stacktrace);
89+
}
90+
91+
encoded_logs.emplace_back(std::move(encoded));
8792
}
88-
return encoded;
93+
return encoded_logs;
8994
}
9095

9196
std::string_view to_string(details::MetricType type) {
@@ -371,13 +376,14 @@ std::string Telemetry::heartbeat_and_telemetry() {
371376
batch_payloads.emplace_back(std::move(distributions_json));
372377
}
373378

374-
if (!logs_.empty()) {
375-
auto encoded_logs = nlohmann::json::array();
376-
for (const auto& log : logs_) {
377-
auto encoded = encode_log(log);
378-
encoded_logs.emplace_back(std::move(encoded));
379-
}
379+
std::vector<telemetry::LogMessage> old_logs;
380+
{
381+
std::lock_guard l{log_mutex_};
382+
std::swap(old_logs, logs_);
383+
}
380384

385+
if (!old_logs.empty()) {
386+
auto encoded_logs = encode_logs(old_logs);
381387
assert(!encoded_logs.empty());
382388

383389
auto logs_payload = nlohmann::json::object({
@@ -434,12 +440,7 @@ std::string Telemetry::app_closing() {
434440
}
435441

436442
if (!logs_.empty()) {
437-
auto encoded_logs = nlohmann::json::array();
438-
for (const auto& log : logs_) {
439-
auto encoded = encode_log(log);
440-
encoded_logs.emplace_back(std::move(encoded));
441-
}
442-
443+
auto encoded_logs = encode_logs(logs_);
443444
assert(!encoded_logs.empty());
444445

445446
auto logs_payload = nlohmann::json::object({
@@ -667,6 +668,7 @@ void Telemetry::log(std::string message, telemetry::LogLevel level,
667668
auto timestamp = std::chrono::duration_cast<std::chrono::seconds>(
668669
clock_().wall.time_since_epoch())
669670
.count();
671+
std::lock_guard l{log_mutex_};
670672
logs_.emplace_back(
671673
telemetry::LogMessage{std::move(message), level, stacktrace, timestamp});
672674
}

‎src/datadog/telemetry/telemetry_impl.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -61,6 +61,7 @@ class Telemetry final {
6161
/// Configuration
6262
std::vector<tracing::ConfigMetadata> configuration_snapshot_;
6363

64+
std::mutex log_mutex_;
6465
std::vector<telemetry::LogMessage> logs_;
6566

6667
// Track sequence id per payload generated

‎test/telemetry/test_telemetry.cpp‎

Lines changed: 96 additions & 64 deletions
Original file line numberDiff line numberDiff line change
@@ -672,77 +672,109 @@ TELEMETRY_IMPLEMENTATION_TEST("Tracer telemetry API") {
672672
}
673673
}
674674
}
675+
}
675676

676-
SECTION("logs serialization") {
677-
SECTION("log level is correct") {
678-
struct TestCase {
679-
std::string_view name;
680-
std::string input;
681-
Optional<std::string> stacktrace;
682-
std::function<void(Telemetry&, const std::string&,
683-
const Optional<std::string>& stacktrace)>
684-
apply;
685-
std::string expected_log_level;
686-
};
687-
688-
auto test_case = GENERATE(values<TestCase>({
689-
{
690-
"warning log",
691-
"This is a warning log!",
692-
nullopt,
693-
[](Telemetry& telemetry, const std::string& input,
694-
const Optional<std::string>&) {
695-
telemetry.log_warning(input);
696-
},
697-
"WARNING",
698-
},
699-
{
700-
"error log",
701-
"This is an error log!",
702-
nullopt,
703-
[](Telemetry& telemetry, const std::string& input,
704-
const Optional<std::string>&) {
705-
telemetry.log_error(input);
706-
},
707-
"ERROR",
708-
},
709-
{
710-
"error log with stacktrace",
711-
"This is an error log with a fake stacktrace!",
712-
"error here\nthen here\nfinally here\n",
713-
[](Telemetry& telemetry, const std::string& input,
714-
Optional<std::string> stacktrace) {
715-
telemetry.log_error(input, *stacktrace);
716-
},
717-
"ERROR",
718-
},
719-
}));
720-
721-
CAPTURE(test_case.name);
677+
SECTION("logs reporting") {
678+
SECTION("log level is correct") {
679+
struct TestCase {
680+
std::string_view name;
681+
std::string input;
682+
Optional<std::string> stacktrace;
683+
std::function<void(Telemetry&, const std::string&,
684+
const Optional<std::string>& stacktrace)>
685+
apply;
686+
std::string expected_log_level;
687+
};
722688

723-
client->clear();
724-
test_case.apply(telemetry, test_case.input, test_case.stacktrace);
725-
scheduler->trigger_heartbeat();
689+
auto test_case = GENERATE(values<TestCase>({
690+
{
691+
"warning log",
692+
"This is a warning log!",
693+
nullopt,
694+
[](Telemetry& telemetry, const std::string& input,
695+
const Optional<std::string>&) {
696+
telemetry.log_warning(input);
697+
},
698+
"WARNING",
699+
},
700+
{
701+
"error log",
702+
"This is an error log!",
703+
nullopt,
704+
[](Telemetry& telemetry, const std::string& input,
705+
const Optional<std::string>&) { telemetry.log_error(input); },
706+
"ERROR",
707+
},
708+
{
709+
"error log with stacktrace",
710+
"This is an error log with a fake stacktrace!",
711+
"error here\nthen here\nfinally here\n",
712+
[](Telemetry& telemetry, const std::string& input,
713+
Optional<std::string> stacktrace) {
714+
telemetry.log_error(input, *stacktrace);
715+
},
716+
"ERROR",
717+
},
718+
}));
726719

727-
auto message_batch = nlohmann::json::parse(client->request_body);
728-
REQUIRE(is_valid_telemetry_payload(message_batch));
729-
REQUIRE(message_batch["payload"].size() == 2);
720+
CAPTURE(test_case.name);
730721

731-
auto logs_message = message_batch["payload"][1];
732-
REQUIRE(logs_message["request_type"] == "logs");
722+
client->clear();
723+
test_case.apply(telemetry, test_case.input, test_case.stacktrace);
724+
scheduler->trigger_heartbeat();
733725

734-
auto logs_payload = logs_message["payload"]["logs"];
735-
REQUIRE(logs_payload.size() == 1);
736-
CHECK(logs_payload[0]["level"] == test_case.expected_log_level);
737-
CHECK(logs_payload[0]["message"] == test_case.input);
738-
CHECK(logs_payload[0].contains("tracer_time"));
726+
auto message_batch = nlohmann::json::parse(client->request_body);
727+
REQUIRE(is_valid_telemetry_payload(message_batch));
728+
REQUIRE(message_batch["payload"].size() == 2);
739729

740-
if (test_case.stacktrace) {
741-
CHECK(logs_payload[0]["stack_trace"] == test_case.stacktrace);
742-
} else {
743-
CHECK(logs_payload[0].contains("stack_trace") == false);
744-
}
730+
auto logs_message = message_batch["payload"][1];
731+
REQUIRE(logs_message["request_type"] == "logs");
732+
733+
auto logs_payload = logs_message["payload"]["logs"];
734+
REQUIRE(logs_payload.size() == 1);
735+
CHECK(logs_payload[0]["level"] == test_case.expected_log_level);
736+
CHECK(logs_payload[0]["message"] == test_case.input);
737+
CHECK(logs_payload[0]["tracer_time"] == 1672484400);
738+
739+
if (test_case.stacktrace) {
740+
CHECK(logs_payload[0]["stack_trace"] == test_case.stacktrace);
741+
} else {
742+
CHECK(logs_payload[0].contains("stack_trace") == false);
743+
}
744+
745+
// Make sure the next heartbeat doesn't contains counters if no
746+
// datapoint has been incremented, decremented or set.
747+
client->clear();
748+
scheduler->trigger_heartbeat();
749+
750+
auto message_batch2 = nlohmann::json::parse(client->request_body);
751+
REQUIRE(is_valid_telemetry_payload(message_batch2) == true);
752+
REQUIRE(message_batch2["payload"].size() == 1);
753+
754+
auto payload2 = message_batch["payload"][0];
755+
CHECK(payload2["request_type"] == "app-heartbeat");
756+
}
757+
758+
SECTION("dtor sends logs in `app-closing` message") {
759+
{
760+
Telemetry tmp_telemetry{*finalize_config(), logger, client,
761+
scheduler, *url, clock};
762+
tmp_telemetry.log_warning("Be careful!");
763+
client->clear();
745764
}
765+
766+
auto message_batch = nlohmann::json::parse(client->request_body);
767+
REQUIRE(is_valid_telemetry_payload(message_batch));
768+
REQUIRE(message_batch["payload"].size() == 2);
769+
770+
auto logs_message = message_batch["payload"][1];
771+
REQUIRE(logs_message["request_type"] == "logs");
772+
773+
auto logs_payload = logs_message["payload"]["logs"];
774+
REQUIRE(logs_payload.size() == 1);
775+
CHECK(logs_payload[0]["level"] == "WARNING");
776+
CHECK(logs_payload[0]["message"] == "Be careful!");
777+
CHECK(logs_payload[0]["tracer_time"] == 1672484400);
746778
}
747779
}
748780
}

0 commit comments

Comments
 (0)