From 7a0745de876dee7f2c137f61daa906c4c95d359f Mon Sep 17 00:00:00 2001 From: Evgeny Yakimov Date: Thu, 8 Apr 2021 20:32:28 +0100 Subject: [PATCH] Add Links and Events to OStreamSpanExporter (#663) * Add Links and Events to OStreamSpanExporter Previously these were just ignored. Summary of changes: - Moved print methods into the translation unit - Added new print methods for links and events - Refactored tests - Added new convenience OStream capture utility - Restructured tests to focus on stream tests and feature tests - Added new tests for links and events * Add new test utility to bazel build --- exporters/ostream/BUILD | 11 + .../exporters/ostream/span_exporter.h | 20 +- exporters/ostream/src/span_exporter.cc | 52 ++- exporters/ostream/test/ostream_capture.h | 57 +++ exporters/ostream/test/ostream_span_test.cc | 381 +++++++++++------- 5 files changed, 358 insertions(+), 163 deletions(-) create mode 100644 exporters/ostream/test/ostream_capture.h diff --git a/exporters/ostream/BUILD b/exporters/ostream/BUILD index d1b5d5bd98..d16e727b59 100644 --- a/exporters/ostream/BUILD +++ b/exporters/ostream/BUILD @@ -60,10 +60,21 @@ cc_library( ], ) +cc_library( + name = "ostream_capture", + hdrs = [ + "test/ostream_capture.h", + ], + deps = [ + "//api", + ], +) + cc_test( name = "ostream_span_test", srcs = ["test/ostream_span_test.cc"], deps = [ + ":ostream_capture", ":ostream_span_exporter", "@com_google_googletest//:gtest_main", ], diff --git a/exporters/ostream/include/opentelemetry/exporters/ostream/span_exporter.h b/exporters/ostream/include/opentelemetry/exporters/ostream/span_exporter.h index 07d8b63e75..ce4f309e02 100644 --- a/exporters/ostream/include/opentelemetry/exporters/ostream/span_exporter.h +++ b/exporters/ostream/include/opentelemetry/exporters/ostream/span_exporter.h @@ -95,7 +95,7 @@ class OStreamSpanExporter final : public sdktrace::SpanExporter #endif - void print_value(sdkcommon::OwnedAttributeValue &value) + void print_value(const sdkcommon::OwnedAttributeValue &value) { #if __cplusplus < 201402L nostd::visit(OwnedAttributeValueVisitor(*this), value); @@ -104,17 +104,13 @@ class OStreamSpanExporter final : public sdktrace::SpanExporter #endif } - void printAttributes(std::unordered_map map) - { - size_t size = map.size(); - // size_t i = 1; - for (auto kv : map) - { - sout_ << "\t" << kv.first << ": "; - print_value(kv.second); - sout_ << std::endl; - } - } + // various print helpers + void printAttributes(const std::unordered_map &map, + const std::string prefix = "\n\t"); + + void printEvents(const std::vector &events); + + void printLinks(const std::vector &links); }; } // namespace trace } // namespace exporter diff --git a/exporters/ostream/src/span_exporter.cc b/exporters/ostream/src/span_exporter.cc index e3c279abbc..724b21e07c 100644 --- a/exporters/ostream/src/span_exporter.cc +++ b/exporters/ostream/src/span_exporter.cc @@ -69,10 +69,14 @@ sdktrace::ExportResult OStreamSpanExporter::Export( << "\n duration : " << span->GetDuration().count() << "\n description : " << span->GetDescription() << "\n span kind : " << span->GetSpanKind() - << "\n status : " << statusMap[int(span->GetStatus())] << "\n attributes : " - << "\n"; + << "\n status : " << statusMap[int(span->GetStatus())] + << "\n attributes : "; printAttributes(span->GetAttributes()); - sout_ << "}\n"; + sout_ << "\n events : "; + printEvents(span->GetEvents()); + sout_ << "\n links : "; + printLinks(span->GetLinks()); + sout_ << "\n}\n"; } } @@ -85,6 +89,48 @@ bool OStreamSpanExporter::Shutdown(std::chrono::microseconds timeout) noexcept return true; } +void OStreamSpanExporter::printAttributes( + const std::unordered_map &map, + const std::string prefix) +{ + for (const auto &kv : map) + { + sout_ << prefix << kv.first << ": "; + print_value(kv.second); + } +} + +void OStreamSpanExporter::printEvents(const std::vector &events) +{ + for (const auto &event : events) + { + sout_ << "\n\t{" + << "\n\t name : " << event.GetName() + << "\n\t timestamp : " << event.GetTimestamp().time_since_epoch().count() + << "\n\t attributes : "; + printAttributes(event.GetAttributes(), "\n\t\t"); + sout_ << "\n\t}"; + } +} + +void OStreamSpanExporter::printLinks(const std::vector &links) +{ + for (const auto &link : links) + { + char trace_id[32] = {0}; + char span_id[16] = {0}; + link.GetSpanContext().trace_id().ToLowerBase16(trace_id); + link.GetSpanContext().span_id().ToLowerBase16(span_id); + sout_ << "\n\t{" + << "\n\t trace_id : " << std::string(trace_id, 32) + << "\n\t span_id : " << std::string(span_id, 16) + << "\n\t tracestate : " << link.GetSpanContext().trace_state()->ToHeader() + << "\n\t attributes : "; + printAttributes(link.GetAttributes(), "\n\t\t"); + sout_ << "\n\t}"; + } +} + } // namespace trace } // namespace exporter OPENTELEMETRY_END_NAMESPACE diff --git a/exporters/ostream/test/ostream_capture.h b/exporters/ostream/test/ostream_capture.h new file mode 100644 index 0000000000..28aac5e8d4 --- /dev/null +++ b/exporters/ostream/test/ostream_capture.h @@ -0,0 +1,57 @@ +#pragma once + +#include +#include +#include + +OPENTELEMETRY_BEGIN_NAMESPACE +namespace exporter +{ +namespace ostream +{ +namespace test +{ +/** + * The OStreamCapture captures from the specified stream for its lifetime + */ +class OStreamCapture +{ +public: + /** + * Create a OStreamCapture which will capture the output of the ostream that it was constructed + * with for the lifetime of the instance. + */ + OStreamCapture(std::ostream &ostream) : stream_(ostream), buf_(ostream.rdbuf()) + { + stream_.rdbuf(captured_.rdbuf()); + } + + ~OStreamCapture() { stream_.rdbuf(buf_); } + + /** + * Returns the captured data from the stream. + */ + std::string GetCaptured() const { return captured_.str(); } + +private: + std::ostream &stream_; + std::streambuf *buf_; + std::stringstream captured_; +}; + +/** + * Helper method to invoke the passed func while recording the output of the specified stream and + * return the output afterwards. + */ +template +std::string WithOStreamCapture(std::ostream &stream, Func func) +{ + OStreamCapture capture(stream); + func(); + return capture.GetCaptured(); +} + +} // namespace test +} // namespace ostream +} // namespace exporter +OPENTELEMETRY_END_NAMESPACE diff --git a/exporters/ostream/test/ostream_span_test.cc b/exporters/ostream/test/ostream_span_test.cc index a9b33afdd2..4ff59dcabc 100644 --- a/exporters/ostream/test/ostream_span_test.cc +++ b/exporters/ostream/test/ostream_span_test.cc @@ -1,3 +1,4 @@ +#include "opentelemetry/common/key_value_iterable_view.h" #include "opentelemetry/sdk/trace/recordable.h" #include "opentelemetry/sdk/trace/simple_processor.h" #include "opentelemetry/sdk/trace/span_data.h" @@ -8,14 +9,20 @@ #include "opentelemetry/exporters/ostream/span_exporter.h" -#include +#include "ostream_capture.h" #include +#include + +using namespace opentelemetry::exporter::ostream::test; namespace trace = opentelemetry::trace; +namespace common = opentelemetry::common; namespace nostd = opentelemetry::nostd; namespace sdktrace = opentelemetry::sdk::trace; +using Attributes = std::initializer_list>; + // Testing Shutdown functionality of OStreamSpanExporter, should expect no data to be sent to Stream TEST(OStreamSpanExporter, Shutdown) { @@ -27,74 +34,52 @@ TEST(OStreamSpanExporter, Shutdown) auto recordable = processor->MakeRecordable(); recordable->SetName("Test Span"); - // Create stringstream to redirect to - std::stringstream stdoutOutput; - - // Save cout's buffer here - std::streambuf *sbuf = std::cout.rdbuf(); - - // Redirect cout to our stringstream buffer - std::cout.rdbuf(stdoutOutput.rdbuf()); + // Capture the output of cout + const auto captured = WithOStreamCapture(std::cout, [&]() { + EXPECT_TRUE(processor->Shutdown()); + processor->OnEnd(std::move(recordable)); + }); - EXPECT_TRUE(processor->Shutdown()); - processor->OnEnd(std::move(recordable)); - - std::cout.rdbuf(sbuf); - - ASSERT_EQ(stdoutOutput.str(), ""); + EXPECT_EQ(captured, ""); } +constexpr const char *kDefaultSpanPrinted = + "{\n" + " name : \n" + " trace_id : 00000000000000000000000000000000\n" + " span_id : 0000000000000000\n" + " parent_span_id: 0000000000000000\n" + " start : 0\n" + " duration : 0\n" + " description : \n" + " span kind : Internal\n" + " status : Unset\n" + " attributes : \n" + " events : \n" + " links : \n" + "}\n"; + // Testing what a default span that is not changed will print out, either all 0's or empty values TEST(OStreamSpanExporter, PrintDefaultSpan) { + std::stringstream output; auto exporter = std::unique_ptr( - new opentelemetry::exporter::trace::OStreamSpanExporter); + new opentelemetry::exporter::trace::OStreamSpanExporter(output)); auto processor = std::shared_ptr( new sdktrace::SimpleSpanProcessor(std::move(exporter))); auto recordable = processor->MakeRecordable(); - constexpr uint8_t trace_id_buf[] = {1, 2, 3, 4, 5, 6, 7, 8, 1, 2, 3, 4, 5, 6, 7, 8}; - opentelemetry::trace::TraceId t_id(trace_id_buf); - constexpr uint8_t span_id_buf[] = {1, 2, 3, 4, 5, 6, 7, 8}; - opentelemetry::trace::SpanId s_id(span_id_buf); - - recordable->SetIds(t_id, s_id, s_id); - - // Create stringstream to redirect to - std::stringstream stdoutOutput; - - // Save cout's buffer here - std::streambuf *sbuf = std::cout.rdbuf(); - - // Redirect cout to our stringstream buffer - std::cout.rdbuf(stdoutOutput.rdbuf()); - processor->OnEnd(std::move(recordable)); - std::cout.rdbuf(sbuf); - - std::string expectedOutput = - "{\n" - " name : \n" - " trace_id : 01020304050607080102030405060708\n" - " span_id : 0102030405060708\n" - " parent_span_id: 0102030405060708\n" - " start : 0\n" - " duration : 0\n" - " description : \n" - " span kind : Internal\n" - " status : Unset\n" - " attributes : \n" - "}\n"; - ASSERT_EQ(stdoutOutput.str(), expectedOutput); + EXPECT_EQ(output.str(), kDefaultSpanPrinted); } -// Testing if the changes we make to a span will carry over through the exporter -TEST(OStreamSpanExporter, PrintChangedSpanCout) +TEST(OStreamSpanExporter, PrintSpanWithBasicFields) { + std::stringstream output; auto exporter = std::unique_ptr( - new opentelemetry::exporter::trace::OStreamSpanExporter); + new opentelemetry::exporter::trace::OStreamSpanExporter(output)); auto processor = std::shared_ptr( new sdktrace::SimpleSpanProcessor(std::move(exporter))); @@ -115,21 +100,8 @@ TEST(OStreamSpanExporter, PrintChangedSpanCout) recordable->SetStatus(opentelemetry::trace::StatusCode::kOk, "Test Description"); recordable->SetSpanKind(opentelemetry::trace::SpanKind::kClient); - recordable->SetAttribute("attr1", "string"); - - // Create stringstream to redirect to - std::stringstream stdoutOutput; - - // Save cout's buffer here - std::streambuf *sbuf = std::cout.rdbuf(); - - // Redirect cout to our stringstream buffer - std::cout.rdbuf(stdoutOutput.rdbuf()); - processor->OnEnd(std::move(recordable)); - std::cout.rdbuf(sbuf); - std::string start = std::to_string(now.time_since_epoch().count()); std::string expectedOutput = @@ -146,134 +118,247 @@ TEST(OStreamSpanExporter, PrintChangedSpanCout) " span kind : Client\n" " status : Ok\n" " attributes : \n" - "\tattr1: string\n" + " events : \n" + " links : \n" "}\n"; - ASSERT_EQ(stdoutOutput.str(), expectedOutput); + EXPECT_EQ(output.str(), expectedOutput); } -// PrintChangedSpan to std::cerr -TEST(OStreamSpanExporter, PrintChangedSpanCerr) +TEST(OStreamSpanExporter, PrintSpanWithAttribute) { + std::stringstream output; auto exporter = std::unique_ptr( - new opentelemetry::exporter::trace::OStreamSpanExporter(std::cerr)); + new opentelemetry::exporter::trace::OStreamSpanExporter(output)); auto processor = std::shared_ptr( new sdktrace::SimpleSpanProcessor(std::move(exporter))); auto recordable = processor->MakeRecordable(); - recordable->SetName("Test Span"); + recordable->SetAttribute("attr1", "string"); - constexpr uint8_t trace_id_buf[] = {1, 2, 3, 4, 5, 6, 7, 8, 1, 2, 3, 4, 5, 6, 7, 8}; - opentelemetry::trace::TraceId t_id(trace_id_buf); - constexpr uint8_t span_id_buf[] = {1, 2, 3, 4, 5, 6, 7, 8}; - opentelemetry::trace::SpanId s_id(span_id_buf); + processor->OnEnd(std::move(recordable)); - recordable->SetIds(t_id, s_id, s_id); + std::string expectedOutput = + "{\n" + " name : \n" + " trace_id : 00000000000000000000000000000000\n" + " span_id : 0000000000000000\n" + " parent_span_id: 0000000000000000\n" + " start : 0\n" + " duration : 0\n" + " description : \n" + " span kind : Internal\n" + " status : Unset\n" + " attributes : \n" + "\tattr1: string\n" + " events : \n" + " links : \n" + "}\n"; + EXPECT_EQ(output.str(), expectedOutput); +} - opentelemetry::core::SystemTimestamp now(std::chrono::system_clock::now()); +TEST(OStreamSpanExporter, PrintSpanWithArrayAttribute) +{ + std::stringstream output; + auto exporter = std::unique_ptr( + new opentelemetry::exporter::trace::OStreamSpanExporter(output)); + auto processor = std::shared_ptr( + new sdktrace::SimpleSpanProcessor(std::move(exporter))); - recordable->SetStartTime(now); - recordable->SetDuration(std::chrono::nanoseconds(100)); - recordable->SetStatus(opentelemetry::trace::StatusCode::kOk, "Test Description"); - recordable->SetSpanKind(opentelemetry::trace::SpanKind::kConsumer); + auto recordable = processor->MakeRecordable(); - std::array array2 = {false, true, false}; - opentelemetry::nostd::span span2{array2.data(), array2.size()}; - recordable->SetAttribute("attr1", span2); + std::array array1 = {1, 2, 3}; + opentelemetry::nostd::span span1{array1.data(), array1.size()}; + recordable->SetAttribute("array1", span1); + + processor->OnEnd(std::move(recordable)); - // Create stringstream to redirect to - std::stringstream stdcerrOutput; + std::string expectedOutput = + "{\n" + " name : \n" + " trace_id : 00000000000000000000000000000000\n" + " span_id : 0000000000000000\n" + " parent_span_id: 0000000000000000\n" + " start : 0\n" + " duration : 0\n" + " description : \n" + " span kind : Internal\n" + " status : Unset\n" + " attributes : \n" + "\tarray1: [1,2,3]\n" + " events : \n" + " links : \n" + "}\n"; + EXPECT_EQ(output.str(), expectedOutput); +} - // Save cout's buffer here - std::streambuf *sbuf = std::cerr.rdbuf(); +TEST(OStreamSpanExporter, PrintSpanWithEvents) +{ + std::stringstream output; + auto exporter = std::unique_ptr( + new opentelemetry::exporter::trace::OStreamSpanExporter(output)); + auto processor = std::shared_ptr( + new sdktrace::SimpleSpanProcessor(std::move(exporter))); - // Redirect cout to our stringstream buffer - std::cerr.rdbuf(stdcerrOutput.rdbuf()); + auto recordable = processor->MakeRecordable(); + opentelemetry::core::SystemTimestamp now(std::chrono::system_clock::now()); + opentelemetry::core::SystemTimestamp next(std::chrono::system_clock::now() + + std::chrono::seconds(1)); - processor->OnEnd(std::move(recordable)); + std::string now_str = std::to_string(now.time_since_epoch().count()); + std::string next_str = std::to_string(next.time_since_epoch().count()); - std::cerr.rdbuf(sbuf); + recordable->AddEvent("hello", now); + recordable->AddEvent("world", next, + common::KeyValueIterableView({{"attr1", "string"}})); - std::string start = std::to_string(now.time_since_epoch().count()); + processor->OnEnd(std::move(recordable)); std::string expectedOutput = "{\n" - " name : Test Span\n" - " trace_id : 01020304050607080102030405060708\n" - " span_id : 0102030405060708\n" - " parent_span_id: 0102030405060708\n" - " start : " + - start + - "\n" - " duration : 100\n" - " description : Test Description\n" - " span kind : Consumer\n" - " status : Ok\n" + " name : \n" + " trace_id : 00000000000000000000000000000000\n" + " span_id : 0000000000000000\n" + " parent_span_id: 0000000000000000\n" + " start : 0\n" + " duration : 0\n" + " description : \n" + " span kind : Internal\n" + " status : Unset\n" " attributes : \n" - "\tattr1: [0,1,0]\n" + " events : \n" + "\t{\n" + "\t name : hello\n" + "\t timestamp : " + + now_str + + "\n" + "\t attributes : \n" + "\t}\n" + "\t{\n" + "\t name : world\n" + "\t timestamp : " + + next_str + + "\n" + "\t attributes : \n" + "\t\tattr1: string\n" + "\t}\n" + " links : \n" "}\n"; - ASSERT_EQ(stdcerrOutput.str(), expectedOutput); + EXPECT_EQ(output.str(), expectedOutput); } -// PrintChangedSpan to std::clog -TEST(OStreamSpanExporter, PrintChangedSpanClog) +TEST(OStreamSpanExporter, PrintSpanWithLinks) { + std::stringstream output; auto exporter = std::unique_ptr( - new opentelemetry::exporter::trace::OStreamSpanExporter(std::clog)); + new opentelemetry::exporter::trace::OStreamSpanExporter(output)); auto processor = std::shared_ptr( new sdktrace::SimpleSpanProcessor(std::move(exporter))); auto recordable = processor->MakeRecordable(); - recordable->SetName("Test Span"); + // produce valid SpanContext with pseudo span and trace Id. + uint8_t span_id_buf[opentelemetry::trace::SpanId::kSize] = { + 1, + }; + opentelemetry::trace::SpanId span_id{span_id_buf}; + uint8_t trace_id_buf[opentelemetry::trace::TraceId::kSize] = { + 2, + }; + opentelemetry::trace::TraceId trace_id{trace_id_buf}; + const auto span_context = opentelemetry::trace::SpanContext( + trace_id, span_id, + opentelemetry::trace::TraceFlags{opentelemetry::trace::TraceFlags::kIsSampled}, true); + + // and another to check preserving order. + uint8_t span_id_buf2[opentelemetry::trace::SpanId::kSize] = { + 3, + }; + opentelemetry::trace::SpanId span_id2{span_id_buf2}; + const auto span_context2 = opentelemetry::trace::SpanContext( + trace_id, span_id2, + opentelemetry::trace::TraceFlags{opentelemetry::trace::TraceFlags::kIsSampled}, true, + opentelemetry::trace::TraceState::FromHeader("state1=value")); + + recordable->AddLink(span_context); + recordable->AddLink(span_context2, + common::KeyValueIterableView({{"attr1", "string"}})); - constexpr uint8_t trace_id_buf[] = {1, 2, 3, 4, 5, 6, 7, 8, 1, 2, 3, 4, 5, 6, 7, 8}; - opentelemetry::trace::TraceId t_id(trace_id_buf); - constexpr uint8_t span_id_buf[] = {1, 2, 3, 4, 5, 6, 7, 8}; - opentelemetry::trace::SpanId s_id(span_id_buf); + processor->OnEnd(std::move(recordable)); - recordable->SetIds(t_id, s_id, s_id); - opentelemetry::core::SystemTimestamp now(std::chrono::system_clock::now()); + std::string expectedOutput = + "{\n" + " name : \n" + " trace_id : 00000000000000000000000000000000\n" + " span_id : 0000000000000000\n" + " parent_span_id: 0000000000000000\n" + " start : 0\n" + " duration : 0\n" + " description : \n" + " span kind : Internal\n" + " status : Unset\n" + " attributes : \n" + " events : \n" + " links : \n" + "\t{\n" + "\t trace_id : 02000000000000000000000000000000\n" + "\t span_id : 0100000000000000\n" + "\t tracestate : \n" + "\t attributes : \n" + "\t}\n" + "\t{\n" + "\t trace_id : 02000000000000000000000000000000\n" + "\t span_id : 0300000000000000\n" + "\t tracestate : state1=value\n" + "\t attributes : \n" + "\t\tattr1: string\n" + "\t}\n" + "}\n"; + EXPECT_EQ(output.str(), expectedOutput); +} - recordable->SetStartTime(now); - recordable->SetDuration(std::chrono::nanoseconds(100)); - recordable->SetStatus(opentelemetry::trace::StatusCode::kOk, "Test Description"); - recordable->SetSpanKind(opentelemetry::trace::SpanKind::kInternal); +// Test with the three common ostreams, tests are more of a sanity check and usage examples. +TEST(OStreamSpanExporter, PrintSpanToCout) +{ + auto exporter = std::unique_ptr( + new opentelemetry::exporter::trace::OStreamSpanExporter); + auto processor = std::shared_ptr( + new sdktrace::SimpleSpanProcessor(std::move(exporter))); - std::array array1 = {1, 2, 3}; - opentelemetry::nostd::span span1{array1.data(), array1.size()}; - recordable->SetAttribute("attr1", span1); + auto recordable = processor->MakeRecordable(); - // Create stringstream to redirect to - std::stringstream stdclogOutput; + const auto captured = + WithOStreamCapture(std::cout, [&]() { processor->OnEnd(std::move(recordable)); }); - // Save cout's buffer here - std::streambuf *sbuf = std::clog.rdbuf(); + EXPECT_EQ(captured, kDefaultSpanPrinted); +} - // Redirect cout to our stringstream buffer - std::clog.rdbuf(stdclogOutput.rdbuf()); +TEST(OStreamSpanExporter, PrintSpanToCerr) +{ + auto exporter = std::unique_ptr( + new opentelemetry::exporter::trace::OStreamSpanExporter(std::cerr)); + auto processor = std::shared_ptr( + new sdktrace::SimpleSpanProcessor(std::move(exporter))); - processor->OnEnd(std::move(recordable)); + auto recordable = processor->MakeRecordable(); - std::clog.rdbuf(sbuf); + const auto captured = + WithOStreamCapture(std::cerr, [&]() { processor->OnEnd(std::move(recordable)); }); - std::string start = std::to_string(now.time_since_epoch().count()); + EXPECT_EQ(captured, kDefaultSpanPrinted); +} - std::string expectedOutput = - "{\n" - " name : Test Span\n" - " trace_id : 01020304050607080102030405060708\n" - " span_id : 0102030405060708\n" - " parent_span_id: 0102030405060708\n" - " start : " + - start + - "\n" - " duration : 100\n" - " description : Test Description\n" - " span kind : Internal\n" - " status : Ok\n" - " attributes : \n" - "\tattr1: [1,2,3]\n" - "}\n"; - ASSERT_EQ(stdclogOutput.str(), expectedOutput); +TEST(OStreamSpanExporter, PrintSpanToClog) +{ + auto exporter = std::unique_ptr( + new opentelemetry::exporter::trace::OStreamSpanExporter(std::clog)); + auto processor = std::shared_ptr( + new sdktrace::SimpleSpanProcessor(std::move(exporter))); + + auto recordable = processor->MakeRecordable(); + + const auto captured = + WithOStreamCapture(std::clog, [&]() { processor->OnEnd(std::move(recordable)); }); + + EXPECT_EQ(captured, kDefaultSpanPrinted); }