From 1ab46853f6927469c914736a58adc0603543441c Mon Sep 17 00:00:00 2001 From: Rodrigo Pastrana Date: Thu, 30 Nov 2023 15:46:00 -0500 Subject: [PATCH] HPCC-30470 Change2 - Adds JLog output config feature flags - Change jlog exporter to be more jlib centric - Replace lock w/ std:atomic bool - Suppress empty json elemets - Remove CSpan toLog - Remove toLog unittest - Remove log output at CSPan start/end - Updates tracing README - Adds jlog config sample - Defaults tracing to jlog Signed-off-by: Rodrigo Pastrana --- helm/examples/tracing/README.md | 44 +- .../tracing/jlog-collector-fulloutput.yaml | 10 + system/jlib/jtrace.cpp | 386 +++++++----------- system/jlib/jtrace.hpp | 17 +- testing/unittests/jlibtests.cpp | 26 -- 5 files changed, 200 insertions(+), 283 deletions(-) create mode 100644 helm/examples/tracing/jlog-collector-fulloutput.yaml diff --git a/helm/examples/tracing/README.md b/helm/examples/tracing/README.md index 5caba096c10..61098d70832 100644 --- a/helm/examples/tracing/README.md +++ b/helm/examples/tracing/README.md @@ -11,21 +11,26 @@ All configuration options detailed here are part of the HPCC Systems Helm chart, - disabled - (default: false) disables tracking and reporting of internal traces and spans - alwaysCreateGlobalIds - If true, assign newly created global ID to any requests that do not supply one. - optAlwaysCreateTraceIds - If true components generate trace/span ids if none are provided by the remote caller. -- logSpanStart - If true, generate a log entry whenever a span is started (default: false) -- logSpanFinish - If true, generate a log entry whenever a span is finished (default: true) - exporter - Defines The type of exporter in charge of forwarding span data to target back-end - - type - (defalt: NONE) "OTLP-HTTP" | "OTLP-GRCP" | "OS" | "NONE" + - type - (defalt: NONE) "OTLP-HTTP" | "OTLP-GRCP" | "OS" | "JLog" | "NONE" + - JLog + - logSpanDetails - Log span details such as description, status, kind + - logParentInfo - Log the span's parent info such as ParentSpanId, and TraceState + - logAttributes - Log the span's attributes + - logEvents - Log the span's events + - logLinks - Log the span's links + - logResources - Log the span's resources such as telemetry.sdk version, name, language - OTLP-HTTP - - endpoint - (default localhost:4318) Specifies the target OTLP-HTTP backend - - timeOutSecs - (default 10secs) - - consoleDebug - (default false) + - endpoint - (default localhost:4318) Specifies the target OTLP-HTTP backend + - timeOutSecs - (default 10secs) + - consoleDebug - (default false) - OTLP-GRCP - - endpoint: (default localhost:4317) The endpoint to export to. By default the OpenTelemetry Collector's default endpoint. - - useSslCredentials - By default when false, uses grpc::InsecureChannelCredentials; If true uses sslCredentialsCACertPath - - sslCredentialsCACertPath - Path to .pem file to be used for SSL encryption. - - timeOutSeconds - (default 10secs) Timeout for grpc deadline + - endpoint: (default localhost:4317) The endpoint to export to. By default the OpenTelemetry Collector's default endpoint. + - useSslCredentials - By default when false, uses grpc::InsecureChannelCredentials; If true uses sslCredentialsCACertPath + - sslCredentialsCACertPath - Path to .pem file to be used for SSL encryption. + - timeOutSeconds - (default 10secs) Timeout for grpc deadline - processor - Controls span processing style. One by one as available, or in batches. - - type - (default: simple) "simple" | "batch" + - type - (default: simple) "simple" | "batch" ### Sample configuration Below is a sample helm values block directing the HPCC tracing framework to process span information serially, and export the data over OTLP/HTTP protocol to localhost:4318 and output export debug information to console: @@ -49,16 +54,16 @@ helm install myTracedHPCC hpcc/hpcc -f otlp-http-collector-default.yaml ## Tracing information HPCC tracing information includes data needed to trace requests as they traverse over distributed components, and detailed information pertaining to important request subtasks in the form of span information. Each trace and all its related spans are assigned unique IDs which follow the Open Telemetry standard. -The start and end of spans are reported to HPCC component logs regardless of any exporter related configuration. +Tracing information can be exported to various Open Telemetry compatible endpoints including HPCC component logs, or OTLP collectors, etc. By default, tracing information is configured to be exported to HPCC component logs. Sample span reported as log event: ```console -000000A3 MON EVT 2023-10-10 22:12:23.827 24212 25115 Span start: {"Type":"Server","Name":"propagatedServerSpan","GlobalID":"IncomingUGID","CallerID":"IncomingCID","LocalID":"JDbF4xnv7LSWDV4Eug1SpJ","TraceID":"beca49ca8f3138a2842e5cf21402bfff","SpanID":"4b960b3e4647da3f"} -000000FF MON EVT 2023-10-10 22:12:24.927 24212 25115 Span end: {"Type":"Server","Name":"propagatedServerSpan","GlobalID":"IncomingUGID","CallerID":"IncomingCID","LocalID":"JDbF4xnv7LSWDV4Eug1SpJ","TraceID":"beca49ca8f3138a2842e5cf21402bfff","SpanID":"4b960b3e4647da3f"} +0000015D MON EVT 2023-11-30 16:27:54.648 8 210 UNK "{ "Name": "HTTPRequest", "TraceId": "2df78ee79efad958f14d23ce6f8d8efb", "SpanId": "8d1da51fff39bb5b", "Start": 1701361674647713804, "Duration": 873300, "Attributes": {"http.request.method": "GET","hpcc.globalid": "JJcnsgDMP2vsjVtKH5wxSh" } }" ``` -Each log statement denotes the time of the tracing event (start or stop), the span type, name, trace and span id, and any HPCC specific attribute such as legacy GlobalID (if any), HPCC CallerID (if any), LocalID (if any). +Each log statement includes a timestamp denoting the span start time, and a duration along with the span name, trace and span id, and any HPCC specific attribute such as legacy GlobalID (if any), HPCC CallerID (if any), LocalID (if any). +The span info logged can be expanded to include span resources, events, and other details (see configuration details). Spans exported via exporters will contain more detailed information such as explicit start time, duration, and any other attribute assigned to the span by the component instrumentation. @@ -79,10 +84,8 @@ Sample exported span data: "hpcc.callerid":"IncomingCID", "hpcc.globalid":"IncomingUGID" }, - "Events":{ - }, - "Links":{ - }, + "Events":{}, + "Links":{}, "Resources":{ "service.name":"unknown_service", "telemetry.sdk.version":"1.9.1", @@ -90,10 +93,11 @@ Sample exported span data: "telemetry.sdk.language":"cpp" }, "InstrumentedLibrary":"esp" - } ``` ## Directory Contents - 'otlp-http-collector-default.yaml' - Sample tracing configuration targeting OTLP/HTTP trace collector +- 'otlp-grcp-collector-default.yaml' - Sample tracing configuration targeting OTLP/GRCP trace collector +- 'jlog-collector-fulloutput.yaml' - Sample tracing configuration targeting HPCC component logs diff --git a/helm/examples/tracing/jlog-collector-fulloutput.yaml b/helm/examples/tracing/jlog-collector-fulloutput.yaml new file mode 100644 index 00000000000..c3ce5704e49 --- /dev/null +++ b/helm/examples/tracing/jlog-collector-fulloutput.yaml @@ -0,0 +1,10 @@ +global: + tracing: + exporter: + type: JLog + logSpanDetails: true + logParentInfo: true + logAttributes: true + logEvents: true + logLinks: true + logResources: true \ No newline at end of file diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp index 10b8e45b159..7ff1605aa6f 100644 --- a/system/jlib/jtrace.cpp +++ b/system/jlib/jtrace.cpp @@ -66,7 +66,7 @@ class NoopSpanExporter final : public opentelemetry::sdk::trace::SpanExporter /** * @return Returns a unique pointer to an empty recordable object */ - std::unique_ptr MakeRecordable() noexcept override + virtual std::unique_ptr MakeRecordable() noexcept override { return std::unique_ptr(new opentelemetry::sdk::trace::SpanData()); } @@ -135,57 +135,21 @@ const char * spanKindToString(opentelemetry::trace::SpanKind spanKind) } } -enum JLogExportLevel -{ - JLogExportLevelNone = 0, - JLogExportLevelMin = 1, - JLogExportLevelDefault = 2, - JLogExportLevelMax = 3 -}; - class JLogSpanExporter final : public opentelemetry::sdk::trace::SpanExporter { private: - JLogExportLevel logLevel = JLogExportLevelDefault; -public: - - inline JLogExportLevel jlogLevelFromStr(char const * str) - { - if (!isEmptyString(str)) - { - if(strnicmp(str, "NONE", 4)==0) - return JLogExportLevelNone; - if(strnicmp(str, "MIN", 3)==0) - return JLogExportLevelMin; - if(strnicmp(str, "DEFAULT", 7)==0) - return JLogExportLevelDefault; - if(strnicmp(str, "MAX", 3)==0) - return JLogExportLevelMax; - } - - return JLogExportLevelDefault; - } - JLogSpanExporter() {} - - JLogSpanExporter(const char * logLevel) - { - setLogLevel(jlogLevelFromStr(logLevel)); - } - - JLogSpanExporter(JLogExportLevel logLevel) - { - setLogLevel(logLevel); - } + SpanLogFlags logFlags = SpanLogFlags::LogNone; - void setLogLevel(JLogExportLevel level) +public: + JLogSpanExporter(SpanLogFlags spanLogFlags) : shutDown(false) { - logLevel = level; + logFlags = spanLogFlags; } /** * @return Returns a unique pointer to an empty recordable object */ - std::unique_ptr MakeRecordable() noexcept override + virtual std::unique_ptr MakeRecordable() noexcept override { return std::unique_ptr(new opentelemetry::sdk::trace::SpanData()); } @@ -208,57 +172,64 @@ class JLogSpanExporter final : public opentelemetry::sdk::trace::SpanExporter for (auto &recordable : recordables) { auto span = std::unique_ptr( - static_cast(recordable.release())); + static_cast(recordable.release())); if (span != nullptr) { - char trace_id[32] = {0}; - char span_id[16] = {0}; - char parent_span_id[16] = {0}; - - span->GetTraceId().ToLowerBase16(trace_id); - span->GetSpanId().ToLowerBase16(span_id); - span->GetParentSpanId().ToLowerBase16(parent_span_id); - - sout << "{" - << " \"Name\": \"" << span->GetName() << "\"," - << " \"TraceId\": \"" << std::string(trace_id, 32) << "\"," - << " \"SpanId\": \"" << std::string(span_id, 16) << "\"," - << " \"kind\": \"" << spanKindToString(span->GetSpanKind()) << "\"," - << " \"ParentSpanId\": \"" << std::string(parent_span_id, 16) << "\"," - << " \"Start\": " << span->GetStartTime().time_since_epoch().count() << "," - << " \"Duration\": " << span->GetDuration().count() << "," - << " \"Attributes\": "; - printAttributes(span->GetAttributes()); - - if ( logLevel > JLogExportLevelMin) + char traceID[32] = {0}; + char spanID[16] = {0}; + + + span->GetTraceId().ToLowerBase16(traceID); + span->GetSpanId().ToLowerBase16(spanID); + + + StringBuffer out; + out.setf("{ \"Name\": \"%s\"", span->GetName().data()); + out.append(", \"TraceId\": \"").append(32, traceID).append("\""); + out.append(", \"SpanId\": \"").append(16, spanID).append("\""); + out.appendf(", \"Start\": %ld", span->GetStartTime().time_since_epoch().count()); + out.appendf(", \"Duration\": %ld", span->GetDuration().count()); + + if (hasMask(logFlags, SpanLogFlags::LogParentInfo)) { - sout << "," - << " \"Description\": \"" << span->GetDescription() << "\"," - << " \"Status\": \"" << statusMap[int(span->GetStatus())] << "\"," - << " \"TraceState\": \"" << span->GetSpanContext().trace_state()->ToHeader() << "\""; + if (span->GetParentSpanId().IsValid()) + { + char parentSpanID[16] = {0}; + span->GetParentSpanId().ToLowerBase16(parentSpanID); + out.append(", \"ParentSpanId\": \"").append(16, parentSpanID).append("\""); + } + + const char * traceState = span->GetSpanContext().trace_state()->ToHeader().c_str(); + if (!isEmptyString(traceState)) + out.appendf(", \"TraceState\": \"%s\"", traceState); } - if ( logLevel > JLogExportLevelDefault) + if (hasMask(logFlags, SpanLogFlags::LogSpanDetails)) { - sout << ", \"Events\": "; - printEvents(span->GetEvents()); - sout << ","; - sout << " \"Links\": "; - printLinks(span->GetLinks()); - sout << ","; - sout << " \"Resources\": "; - printResources(span->GetResource()); - sout << ","; - sout << " \"InstrumentedLibrary\": \""; - printInstrumentationScope(span->GetInstrumentationScope()); - sout << "\""; + out.appendf(", \"Status\": \"%s\"", statusMap[int(span->GetStatus())].c_str()); + out.appendf(", \"kind\": \"%s\"", spanKindToString(span->GetSpanKind())); + const char * description = span->GetDescription().data(); + if (!isEmptyString(description)) + out.appendf(", \"Description\": \"%s\"", description); + printInstrumentationScope(out, span->GetInstrumentationScope()); } - sout << " }"; + + if (hasMask(logFlags, SpanLogFlags::LogAttributes)) + printAttributes(out, span->GetAttributes()); + + if (hasMask(logFlags, SpanLogFlags::LogEvents)) + printEvents(out, span->GetEvents()); + + if (hasMask(logFlags, SpanLogFlags::LogLinks)) + printLinks(out, span->GetLinks()); + + if (hasMask(logFlags, SpanLogFlags::LogResources)) + printResources(out, span->GetResource()); + + out.append(" }"); + LOG(MCmonitorEvent, "%s",out.str()); } - LOG(MCmonitorEvent, "%s",sout.str().c_str()); - sout.str(""); - sout.clear(); } return opentelemetry::sdk::common::ExportResult::kSuccess; } @@ -271,7 +242,6 @@ class JLogSpanExporter final : public opentelemetry::sdk::trace::SpanExporter virtual bool Shutdown( std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override { - const std::lock_guard locked(lock); shutDown = true; return true; } @@ -279,98 +249,101 @@ class JLogSpanExporter final : public opentelemetry::sdk::trace::SpanExporter private: bool isShutDown() const noexcept { - const std::lock_guard locked(lock); return shutDown; } - void printAttributes(const std::unordered_map &map) + void printAttributes(StringBuffer & out, const std::unordered_map &map, const char * attsContainerName = "Attributes") { - sout << "{ "; + if (map.size() == 0) + return; + + out.appendf(", \"%s\": {", attsContainerName); + bool first = true; for (const auto &kv : map) { if (!first) - sout << ","; + out.append(","); else first = false; - sout << "\"" << kv.first << "\": \""; - opentelemetry::exporter::ostream_common::print_value(kv.second, sout); - sout << "\""; + std::ostringstream attsOS; //used to exploit OTel convenience functions for printing attribute values + opentelemetry::exporter::ostream_common::print_value(kv.second, attsOS); + out.appendf("\"%s\": \"%s\"", kv.first.c_str(), attsOS.str().c_str()); + attsOS.clear(); } - sout << " }"; + out.append(" }"); + } - void printEvents(const std::vector &events) + void printEvents(StringBuffer & out, const std::vector &events) { - sout << "{ "; + if (events.size() == 0) + return; + + out.append(", \"Events\":{ "); bool first = true; for (const auto &event : events) { if (!first) - sout << ","; + out.append(","); else first = false; - sout << "{ "; - sout << " \"Name\": " << event.GetName() << "\"," - << " \"Timestamp\": " << event.GetTimestamp().time_since_epoch().count() << "\"," - << " \"Attributes\": "; - printAttributes(event.GetAttributes()); - sout << " }"; + out.append("{ \"Name\": \"").append(event.GetName().data()).append("\","); + out.appendf(" \"Timestamp\": %ld,", event.GetTimestamp().time_since_epoch().count()); + printAttributes(out, event.GetAttributes()); + out.append(" }"); } - sout << " }"; + out.append(" }"); } - void printLinks(const std::vector &links) + void printLinks(StringBuffer & out, const std::vector &links) { + if (links.size() == 0) + return; + bool first = true; - sout << "{ "; + out.append(", { \"links\": "); for (const auto &link : links) { if (!first) - sout << ","; + out.append(","); else first = false; - 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 << " {" - << " \"TraceId\": \"" << std::string(trace_id, 32) << "\"," - << " \"SpanId\": \"" << std::string(span_id, 16) << "\"," - << " \"TraceState\": \"" << link.GetSpanContext().trace_state()->ToHeader() << "\"," - << " \"Attributes\": "; - printAttributes(link.GetAttributes()); - sout << " }"; + char traceID[32] = {0}; + char spanID[16] = {0}; + link.GetSpanContext().trace_id().ToLowerBase16(traceID); + link.GetSpanContext().span_id().ToLowerBase16(spanID); + + out.append(" { \"TraceId\": \"").append(32, traceID).append("\","); + out.append(" \"SpanId\": \"").append(16, spanID).append("\","); + out.append(" \"TraceState\": \"").append(link.GetSpanContext().trace_state()->ToHeader().c_str()).append("\""); + printAttributes(out, link.GetAttributes()); } - sout << " }"; + out.append(" }"); } - void printResources(const opentelemetry::sdk::resource::Resource &resources) + void printResources(StringBuffer & out, const opentelemetry::sdk::resource::Resource &resources) { auto attributes = resources.GetAttributes(); if (attributes.size()) - printAttributes(attributes); + printAttributes(out, attributes, "Resources"); } - void printInstrumentationScope( + void printInstrumentationScope(StringBuffer & out, const opentelemetry::sdk::instrumentationscope::InstrumentationScope &instrumentation_scope) { + out.appendf(", \"InstrumentedLibrary\": \"%s\"", instrumentation_scope.GetName().c_str()); auto version = instrumentation_scope.GetVersion(); if (version.size()) - { - sout << " \"" << instrumentation_scope.GetName() << "\": "; - sout << version; - } + out.appendf("-").append(version.c_str()); } - bool shutDown = false; - std::ostringstream sout; - mutable opentelemetry::common::SpinLockMutex lock; + std::atomic_bool shutDown; // Mapping status number to the string from api/include/opentelemetry/trace/canonical_code.h std::map statusMap{{0, "Unset"}, {1, "Ok"}, {2, "Error"}}; @@ -382,16 +355,10 @@ class JLogSpanExporterFactory /** * Create a JLogSpanExporter. */ - static std::unique_ptr Create() + static std::unique_ptr Create(SpanLogFlags logFlags) { return std::unique_ptr( - new JLogSpanExporter()); - } - - static std::unique_ptr Create(const char * logLevel) - { - return std::unique_ptr( - new JLogSpanExporter(logLevel)); + new JLogSpanExporter(logFlags)); } }; @@ -445,8 +412,6 @@ class CTraceManager : implements ITraceManager, public CInterface bool enabled = true; bool optAlwaysCreateGlobalIds = false; bool optAlwaysCreateTraceIds = true; - bool optLogSpanStart = false; - bool optLogSpanFinish = true; StringAttr moduleName; nostd::shared_ptr tracer; @@ -478,16 +443,6 @@ class CTraceManager : implements ITraceManager, public CInterface return optAlwaysCreateTraceIds; } - bool logSpanStart() const - { - return optLogSpanStart; - } - - bool logSpanFinish() const - { - return optLogSpanFinish; - } - nostd::shared_ptr queryTracer() const { return tracer; @@ -512,13 +467,6 @@ class CSpan : public CInterfaceOf //Record the span as complete before we output the logging for the end of the span if (span != nullptr) span->End(); - - if (queryInternalTraceManager().logSpanFinish()) - { - StringBuffer out; - toLog(out); - LOG(MCmonitorEvent, "SpanFinish: {%s}", out.str()); - } } const char * getSpanID() const @@ -529,17 +477,6 @@ class CSpan : public CInterfaceOf ISpan * createClientSpan(const char * name) override; ISpan * createInternalSpan(const char * name) override; - virtual void toLog(StringBuffer & out) const override - { - out.append(",\"Name\":\"").append(name.get()).append("\""); - - if (span != nullptr) - { - out.append(",\"TraceID\":\"").append(traceID.get()).append("\""); - out.append(",\"SpanID\":\"").append(spanID.get()).append("\""); - } - } - virtual void toString(StringBuffer & out) const { toString(out, true); @@ -716,13 +653,6 @@ class CSpan : public CInterfaceOf if (span != nullptr) { storeSpanContext(); - - if (queryInternalTraceManager().logSpanStart()) - { - StringBuffer out; - toLog(out); - LOG(MCmonitorEvent, "SpanStart: {%s}", out.str()); - } } } } @@ -804,7 +734,6 @@ class CNullSpan : public CInterfaceOf virtual bool getSpanContext(IProperties * ctxProps, bool otelFormatted) const override { return false; } virtual void toString(StringBuffer & out) const override {} - virtual void toLog(StringBuffer & out) const override {} virtual void getLogPrefix(StringBuffer & out) const override {} virtual const char* queryGlobalId() const override { return nullptr; } @@ -867,15 +796,6 @@ class CChildSpan : public CSpan return localParentSpan->queryLocalId(); } - virtual void toLog(StringBuffer & out) const override - { - CSpan::toLog(out); - - out.append(",\"ParentSpanID\": \""); - out.append(localParentSpan->getSpanID()); - out.append("\""); - } - virtual void toString(StringBuffer & out, bool isLeaf) const { CSpan::toString(out, isLeaf); @@ -899,12 +819,6 @@ class CInternalSpan : public CChildSpan init(SpanFlags::None); } - void toLog(StringBuffer & out) const override - { - out.append("\"Type\":\"Internal\""); - CChildSpan::toLog(out); - } - void toString(StringBuffer & out, bool isLeaf) const override { out.append("\"Type\":\"Internal\""); @@ -922,12 +836,6 @@ class CClientSpan : public CChildSpan init(SpanFlags::None); } - void toLog(StringBuffer & out) const override - { - out.append("\"Type\":\"Client\""); - CChildSpan::toLog(out); - } - void toString(StringBuffer & out, bool isLeaf) const override { out.append("\"Type\":\"Client\""); @@ -1022,6 +930,9 @@ class CServerSpan : public CSpan if (!isEmptyString(hpccCallerId)) setSpanAttribute(kCallerIdOtelAttributeName, hpccCallerId.get()); + + if (!isEmptyString(hpccLocalId)) + setSpanAttribute(kLocalIdIdOtelAttributeName, hpccLocalId.get()); } public: @@ -1049,28 +960,6 @@ class CServerSpan : public CSpan return hpccLocalId.get(); } - virtual void toLog(StringBuffer & out) const override - { - out.append("\"Type\":\"Server\""); - CSpan::toLog(out); - - if (!isEmptyString(hpccGlobalId.get())) - out.append(",\"GlobalID\":\"").append(hpccGlobalId.get()).append("\""); - if (!isEmptyString(hpccCallerId.get())) - out.append(",\"CallerID\":\"").append(hpccCallerId.get()).append("\""); - if (!isEmptyString(hpccLocalId.get())) - out.append(",\"LocalID\":\"").append(hpccLocalId.get()).append("\""); - - if (remoteParentSpanCtx.IsValid()) - { - out.append(",\"ParentSpanID\":\""); - char spanId[16] = {0}; - remoteParentSpanCtx.span_id().ToLowerBase16(spanId); - out.append(16, spanId) - .append("\""); - } - } - virtual void toString(StringBuffer & out, bool isLeaf) const override { out.append("\"Type\":\"Server\""); @@ -1107,7 +996,8 @@ IProperties * getClientHeaders(const ISpan * span) void CTraceManager::initTracerProviderAndGlobalInternals(const IPropertyTree * traceConfig) { - std::unique_ptr exporter = NoopSpanExporterFactory::Create(); + //Trace to JLog by default. + std::unique_ptr exporter = JLogSpanExporterFactory::Create(DEFAULT_SPAN_LOG_FLAGS); //Administrators can choose to export trace data to a different backend by specifying the exporter type if (traceConfig && traceConfig->hasProp("exporter")) @@ -1124,7 +1014,7 @@ void CTraceManager::initTracerProviderAndGlobalInternals(const IPropertyTree * t if (stricmp(exportType.str(), "OS")==0) //To stdout/err { exporter = opentelemetry::exporter::trace::OStreamSpanExporterFactory::Create(); - DBGLOG("Tracing to stdout/err..."); + DBGLOG("Tracing exporter set OS"); } else if (stricmp(exportType.str(), "OTLP")==0 || stricmp(exportType.str(), "OTLP-HTTP")==0) { @@ -1140,7 +1030,7 @@ void CTraceManager::initTracerProviderAndGlobalInternals(const IPropertyTree * t trace_opts.console_debug = exportConfig->getPropBool("@consoleDebug", false); exporter = opentelemetry::exporter::otlp::OtlpHttpExporterFactory::Create(trace_opts); - DBGLOG("Exporting traces via OTLP/HTTP to: (%s)", trace_opts.url.c_str()); + DBGLOG("Tracing exporter set to OTLP/HTTP to: (%s)", trace_opts.url.c_str()); } else if (stricmp(exportType.str(), "OTLP-GRPC")==0) { @@ -1165,24 +1055,46 @@ void CTraceManager::initTracerProviderAndGlobalInternals(const IPropertyTree * t opts.timeout = std::chrono::seconds(exportConfig->getPropInt("@timeOutSecs")); exporter = otlp::OtlpGrpcExporterFactory::Create(opts); - DBGLOG("Exporting traces via OTLP/GRPC to: (%s)", opts.endpoint.c_str()); + DBGLOG("Tracing exporter set to OTLP/GRPC to: (%s)", opts.endpoint.c_str()); } else if (stricmp(exportType.str(), "JLog")==0) { - StringBuffer logLevel; - if (exportConfig->hasProp("@logLevel")) - exportConfig->getProp("@logLevel", logLevel); + StringBuffer logFlagsStr; + SpanLogFlags logFlags = DEFAULT_SPAN_LOG_FLAGS; //LogParentInfo|LogAttributes + + if (exportConfig->getPropBool("@logEvents", false)) + { + logFlags |= SpanLogFlags::LogEvents; + logFlagsStr.append(" LogEvents "); + } + if (exportConfig->getPropBool("@logLinks", false)) + { + logFlags |= SpanLogFlags::LogLinks; + logFlagsStr.append(" LogLinks "); + } + if (exportConfig->getPropBool("@logResources", false)) + { + logFlags |= SpanLogFlags::LogResources; + logFlagsStr.append(" LogLinks "); + } - exporter = JLogSpanExporterFactory::Create(logLevel.str()); + if ((logFlags & ~DEFAULT_SPAN_LOG_FLAGS) != SpanLogFlags::LogNone) + { + DBGLOG("Tracing exporter set to JLog: NEW INSTANCE!!!"); + exporter = JLogSpanExporterFactory::Create(logFlags); + } - DBGLOG("Exporting traces via JLOG: Log Level(%s)", logLevel.str()); + DBGLOG("Tracing exporter set to JLog: logFlags( LogAttributes LogParentInfo %s)", logFlagsStr.str()); } else if (stricmp(exportType.str(), "Prometheus")==0) DBGLOG("Tracing to Prometheus currently not supported"); else if (stricmp(exportType.str(), "NONE")==0) + { + exporter = NoopSpanExporterFactory::Create(); DBGLOG("Tracing exporter set to 'NONE', no trace exporting will be performed"); + } else - DBGLOG("Tracing exporter type not supported: '%s', no trace exporting will be performed", exportType.str()); + DBGLOG("Tracing exporter type not supported: '%s', JLog trace exporting will be performed", exportType.str()); } else DBGLOG("Tracing exporter type not specified"); @@ -1257,14 +1169,19 @@ void CTraceManager::initTracer(const IPropertyTree * traceConfig) if (!traceConfig) { const char * simulatedGlobalYaml = R"!!(global: -tracing: + tracing: disabled: false - exporter: - type: OTLP-HTTP - timeOutSecs: 15 - consoleDebug: true processor: - type: simple + type: simple + exporter: + type: JLog + logSpanDetails: true + logParentInfo: true + logAttributes: true + logEvents: true + logLinks: true + logResources: true + )!!"; testTree.setown(createPTreeFromYAMLString(simulatedGlobalYaml, ipt_none, ptr_ignoreWhiteSpace, nullptr)); traceConfig = testTree->queryPropTree("global/tracing"); @@ -1275,7 +1192,6 @@ void CTraceManager::initTracer(const IPropertyTree * traceConfig) toXML(traceConfig, xml); DBGLOG("traceConfig tree: %s", xml.str()); } - #endif bool disableTracing = traceConfig && traceConfig->getPropBool("@disabled", false); @@ -1295,8 +1211,6 @@ void CTraceManager::initTracer(const IPropertyTree * traceConfig) //Non open-telemetry tracing configuration if (traceConfig) { - optLogSpanStart = traceConfig->getPropBool("@logSpanStart", optLogSpanStart); - optLogSpanFinish = traceConfig->getPropBool("@logSpanFinish", optLogSpanFinish); optAlwaysCreateGlobalIds = traceConfig->getPropBool("@alwaysCreateGlobalIds", optAlwaysCreateGlobalIds); optAlwaysCreateTraceIds = traceConfig->getPropBool("@alwaysCreateTraceIds", optAlwaysCreateTraceIds); } diff --git a/system/jlib/jtrace.hpp b/system/jlib/jtrace.hpp index 8ace5e417d4..0a15a7dc106 100644 --- a/system/jlib/jtrace.hpp +++ b/system/jlib/jtrace.hpp @@ -29,6 +29,22 @@ static constexpr const char *kLegacyGlobalIdHttpHeaderName = "HPCC-Global-Id"; static constexpr const char *kLegacyCallerIdHttpHeaderName = "HPCC-Caller-Id"; static constexpr const char *kGlobalIdOtelAttributeName = "hpcc.globalid"; static constexpr const char *kCallerIdOtelAttributeName = "hpcc.callerid"; +static constexpr const char *kLocalIdIdOtelAttributeName = "hpcc.localid"; + +enum class SpanLogFlags : unsigned +{ + LogNone = 0x00000000, + LogSpanDetails = 0x00000001, + LogParentInfo = 0x00000002, + LogAttributes = 0x00000004, + LogEvents = 0x00000008, + LogLinks = 0x00000010, + LogResources = 0x00000020, +}; +BITMASK_ENUM(SpanLogFlags); + +static constexpr SpanLogFlags DEFAULT_SPAN_LOG_FLAGS = SpanLogFlags::LogAttributes | SpanLogFlags::LogParentInfo; + enum class SpanFlags : unsigned { @@ -45,7 +61,6 @@ interface ISpan : extends IInterface virtual void addSpanEvent(const char * eventName) = 0; virtual bool getSpanContext(IProperties * ctxProps, bool otelFormatted) const = 0; virtual void toString(StringBuffer & out) const = 0; - virtual void toLog(StringBuffer & out) const = 0; virtual void getLogPrefix(StringBuffer & out) const = 0; virtual ISpan * createClientSpan(const char * name) = 0; diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp index 9918b77c5ef..474d1ae35a0 100644 --- a/testing/unittests/jlibtests.cpp +++ b/testing/unittests/jlibtests.cpp @@ -383,32 +383,6 @@ class JlibTraceTest : public CppUnit::TestFixture Owned internalSpan2 = internalSpan->createInternalSpan("internalSpan2"); StringBuffer out; - out.set("{"); - internalSpan2->toLog(out); - out.append("}"); - { - Owned jtraceAsTree; - try - { - jtraceAsTree.setown(createPTreeFromJSONString(out.str())); - } - catch (IException *e) - { - StringBuffer msg; - msg.append("Unexpected toLog format failure detected: "); - e->errorMessage(msg); - e->Release(); - CPPUNIT_ASSERT_MESSAGE(msg.str(), false); - } - - CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected toLog format failure detected", true, jtraceAsTree != nullptr); - CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'TraceID' entry in toLog output", true, jtraceAsTree->hasProp("TraceID")); - CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'SpanID' entry in toLog output", true, jtraceAsTree->hasProp("SpanID")); - CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'Name' entry in toLog output", true, jtraceAsTree->hasProp("Name")); - CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'Type' entry in toLog output", true, jtraceAsTree->hasProp("Type")); - CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'ParentSpanID' entry in toLog output", true, jtraceAsTree->hasProp("ParentSpanID")); - } - out.set("{"); internalSpan2->toString(out); out.append("}");