diff --git a/helm/examples/tracing/README.md b/helm/examples/tracing/README.md index 5caba096c10..bf5cbcd1003 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 - (default: JLOG) "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,51 +54,65 @@ 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"} +00000165 MON EVT 2023-12-01 17:19:07.270 8 688 UNK "{ "name": "HTTPRequest", "trace_id": "891070fc4a9ef5a3751c19c555d7d4a8", "span_id": "23a47b5bb486ce58", "start": 1701451147269962337, "duration": 652093, "Attributes": {"http.request.method": "GET","hpcc.localid": "JJmSnTeFWTQL8ft9DcbYDK","hpcc.globalid": "JJmSnTedcRZ99RtnwWGwPN" } }"" ``` -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. Sample exported span data: ```json { - "Name":"propagatedServerSpan", - "TraceId":"beca49ca8f3138a2842e5cf21402bfff", - "SpanId":"6225221529c24252", - "kind":"Server", - "ParentSpanId":"4b960b3e4647da3f", - "Start":1696983526105561763, - "Duration":1056403, - "Description":"", - "Status":"Unset", - "TraceState":"hpcc=4b960b3e4647da3f", - "Attributes":{ - "hpcc.callerid":"IncomingCID", - "hpcc.globalid":"IncomingUGID" - }, - "Events":{ + "name": "HTTPRequest", + "trace_id": "53f47047517e9dd9f5ad8c318b4b4fe0", + "span_id": "b9489283b66c1073", + "start": 1701456073994968800, + "duration": 1002426, + "attributes": { + "http.request.method": "GET", + "hpcc.localid": "JJmvRRBJ1QYU8o4xe1sgxJ", + "hpcc.globalid": "JJmvRRBjnJGY6vgkjkAjJc" + }, + "events": [ + { + "name": "Acquiring lock", + "time_stamp": 1701456073995175400, + "attributes": { + "lock_name": "resourcelock" + } }, - "Links":{ + { + "name": "Got lock, doing work...", + "time_stamp": 1701456073995269400, + "attributes": { + "lock_name": "resourcelock" + } }, - "Resources":{ - "service.name":"unknown_service", - "telemetry.sdk.version":"1.9.1", - "telemetry.sdk.name":"opentelemetry", - "telemetry.sdk.language":"cpp" - }, - "InstrumentedLibrary":"esp" - + { + "name": "Release lock", + "time_stamp": 1701456073996269400, + "attributes": { + "lock_name": "resourcelock" + } + } + ], + "resources": { + "service.name": "unknown_service", + "telemetry.sdk.version": "1.9.1", + "telemetry.sdk.name": "opentelemetry", + "telemetry.sdk.language": "cpp" + } } ``` ## 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/helm/hpcc/values.schema.json b/helm/hpcc/values.schema.json index 4bd72fa1754..0b07509ec32 100644 --- a/helm/hpcc/values.schema.json +++ b/helm/hpcc/values.schema.json @@ -1121,7 +1121,7 @@ "properties": { "type": { "type": "string", - "enum": ["OTLP-HTTP", "OTLP-GRCP", "OS", "NONE"], + "enum": ["OTLP-HTTP", "OTLP-GRCP", "OS", "JLOG", "NONE"], "description": "The type of exporter in charge of forwarding span data to target back-end" } } @@ -1135,16 +1135,6 @@ "description": "Defines the manner in which trace data is processed - in batches, or simple as available" } } - }, - "logSpanStart": { - "type": "boolean", - "description": "If true, generate a log entry whenever a span is started", - "default": false - }, - "logSpanFinish": { - "type": "boolean", - "description": "If true, generate a log entry whenever a span is finished", - "default": true } }, "additionalProperties": { "type": ["integer", "string", "boolean"] } diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp index fd7a3d46ba9..ffe67b6ca30 100644 --- a/system/jlib/jtrace.cpp +++ b/system/jlib/jtrace.cpp @@ -23,6 +23,7 @@ #include "opentelemetry/sdk/trace/simple_processor_factory.h" #include "opentelemetry/sdk/trace/batch_span_processor_factory.h" #include "opentelemetry/exporters/ostream/span_exporter_factory.h"// auto exporter = opentelemetry::exporter::trace::OStreamSpanExporterFactory::Create(); +#include "opentelemetry/exporters/ostream/common_utils.h" //#define oldForEach ForEach // error: ‘ForEach’ was not declared in this scope #undef ForEach //opentelemetry defines ForEach #include "opentelemetry/exporters/memory/in_memory_span_exporter_factory.h" @@ -65,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()); } @@ -107,6 +108,294 @@ class NoopSpanExporterFactory } }; +/** + * Converts an OpenTelemetry span status to its string representation. + * These are OTel span status defined in include/opentelemetry/trace/span_metadata.h + * + * @param StatusCode The OpenTelemetry span status code to translate. + * @return The string representation of the OpenTelemetry status code. + */ +static const char * spanStatusToString(opentelemetry::trace::StatusCode spanStatus) +{ + switch(spanStatus) + { + case opentelemetry::trace::StatusCode::kUnset: + return "Unset"; + case opentelemetry::trace::StatusCode::kOk: + return "Ok"; + case opentelemetry::trace::StatusCode::kError: + return "Error"; + default: + return "Unknown"; + } +} + +/** + * Converts an OpenTelemetry span kind to its string representation. + * These are OTel span kinds defined in include/opentelemetry/trace/span_metadata.h, + * not HPCC JLib CSpan kinds + * + * @param spanKind The OpenTelemetry span kind to convert. + * @return The string representation of the OpenTelemetry span kind. + */ +static const char * spanKindToString(opentelemetry::trace::SpanKind spanKind) +{ + switch (spanKind) + { + case opentelemetry::trace::SpanKind::kClient: + return "Client"; + case opentelemetry::trace::SpanKind::kServer: + return "Server"; + case opentelemetry::trace::SpanKind::kProducer: + return "Producer"; + case opentelemetry::trace::SpanKind::kConsumer: + return "Consumer"; + case opentelemetry::trace::SpanKind::kInternal: + return "Internal"; + default: + return "Unknown"; + } +} + +class JLogSpanExporter final : public opentelemetry::sdk::trace::SpanExporter +{ +public: + JLogSpanExporter(SpanLogFlags spanLogFlags) : logFlags(spanLogFlags), shutDown(false) {} + + /** + * @return Returns a unique pointer to an empty recordable object + */ + virtual std::unique_ptr MakeRecordable() noexcept override + { + return std::unique_ptr(new opentelemetry::sdk::trace::SpanData()); + } + + /** + * Export - Formats recordable spans in HPCC Jlog format and reports to JLog + * + * @param recordables + * @return Always returns success + */ + opentelemetry::sdk::common::ExportResult Export( + const nostd::span> &recordables) noexcept override + { + if (isShutDown()) + return opentelemetry::sdk::common::ExportResult::kFailure; + + for (auto &recordable : recordables) + { + //Casting the recordable object to the type of the object that was previously created by + //JLogSpanExporter::MakeRecordable() - + auto span = std::unique_ptr( + static_cast(recordable.release())); + + if (span != nullptr) + { + char traceID[32] = {0}; + char spanID[16] = {0}; + + span->GetTraceId().ToLowerBase16(traceID); + span->GetSpanId().ToLowerBase16(spanID); + + StringBuffer out("{ \"type\": \"span\""); //for simple identification in log scraping + out.appendf(", \"name\": \"%s\"", span->GetName().data()); + out.append(", \"trace_id\": \"").append(32, traceID).append("\""); + out.append(", \"span_id\": \"").append(16, spanID).append("\""); + out.appendf(", \"start\": %lld", (long long)(span->GetStartTime().time_since_epoch()).count()); + out.appendf(", \"duration\": %lld", (long long)span->GetDuration().count()); + + if (hasMask(logFlags, SpanLogFlags::LogParentInfo)) + { + if (span->GetParentSpanId().IsValid()) + { + char parentSpanID[16] = {0}; + span->GetParentSpanId().ToLowerBase16(parentSpanID); + out.append(", \"parent_span_id\": \"").append(16, parentSpanID).append("\""); + } + + std::string traceStatestr = span->GetSpanContext().trace_state()->ToHeader(); + if (!traceStatestr.empty()) + out.appendf(", \"trace_state\": \"%s\"", traceStatestr.c_str()); + } + + if (hasMask(logFlags, SpanLogFlags::LogSpanDetails)) + { + out.appendf(", \"status\": \"%s\"", spanStatusToString(span->GetStatus())); + out.appendf(", \"kind\": \"%s\"", spanKindToString(span->GetSpanKind())); + const char * description = span->GetDescription().data(); + if (!isEmptyString(description)) + { + StringBuffer encoded; + encodeJSON(encoded, description); + out.appendf(", \"description\": \"%s\"", encoded.str()); + } + printInstrumentationScope(out, span->GetInstrumentationScope()); + } + + 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()); + } + } + return opentelemetry::sdk::common::ExportResult::kSuccess; + } + + /** + * Shut down the exporter. + * @param timeout an optional timeout. + * @return return the status of the operation. + */ + virtual bool Shutdown( + std::chrono::microseconds timeout = std::chrono::microseconds::max()) noexcept override + { + shutDown = true; + return true; + } + +private: + bool isShutDown() const noexcept + { + return shutDown; + } + +public: + static void printAttributes(StringBuffer & out, const std::unordered_map &map, const char * attsContainerName = "attributes") + { + if (map.size() == 0) + return; + + out.appendf(", \"%s\": {", attsContainerName); + + bool first = true; + for (const auto &kv : map) + { + if (!first) + out.append(","); + else + first = false; + + std::ostringstream attsOS; //used to exploit OTel convenience functions for printing attribute values + opentelemetry::exporter::ostream_common::print_value(kv.second, attsOS); + std::string val = attsOS.str(); + if (val.size() > 0) + { + StringBuffer encoded; + encodeJSON(encoded, val.c_str()); + out.appendf("\"%s\": \"%s\"", kv.first.c_str(), encoded.str()); + } + } + out.append(" }"); + } + + static void printEvents(StringBuffer & out, const std::vector &events) + { + if (events.size() == 0) + return; + + out.append(", \"events\":[ "); + bool first = true; + for (const auto &event : events) + { + if (!first) + out.append(","); + else + first = false; + + out.append("{ \"name\": \"").append(event.GetName().data()).append("\""); + out.appendf(", \"time_stamp\": %lld", (long long)event.GetTimestamp().time_since_epoch().count()); + + printAttributes(out, event.GetAttributes()); + out.append(" }"); + } + + out.append(" ]"); + } + + static void printLinks(StringBuffer & out, const std::vector &links) + { + if (links.size() == 0) + return; + + bool first = true; + + out.append(", \"links\": ["); + for (const auto &link : links) + { + if (!first) + out.append(","); + else + first = false; + + char traceID[32] = {0}; + char spanID[16] = {0}; + link.GetSpanContext().trace_id().ToLowerBase16(traceID); + link.GetSpanContext().span_id().ToLowerBase16(spanID); + + out.append(" { \"trace_id\": \"").append(32, traceID).append("\","); + out.append(" \"span_id\": \"").append(16, spanID).append("\","); + out.append(" \"trace_state\": \"").append(link.GetSpanContext().trace_state()->ToHeader().c_str()).append("\""); + printAttributes(out, link.GetAttributes()); + } + out.append(" ]"); + } + + static void printResources(StringBuffer & out, const opentelemetry::sdk::resource::Resource &resources) + { + auto attributes = resources.GetAttributes(); + if (attributes.size()) + printAttributes(out, attributes, "resources"); + } + + static void printInstrumentationScope(StringBuffer & out, + const opentelemetry::sdk::instrumentationscope::InstrumentationScope &instrumentation_scope) + { + out.appendf(", \"instrumented_library\": \"%s\"", instrumentation_scope.GetName().c_str()); + auto version = instrumentation_scope.GetVersion(); + if (version.size()) + out.appendf("-").append(version.c_str()); + } + +private: + SpanLogFlags logFlags = SpanLogFlags::LogNone; + std::atomic_bool shutDown; +}; + +/*#ifdef _USE_CPPUNIT +void testJLogExporterPrintAttributes(StringBuffer & out, const std::unordered_map & map, const char * attsContainerName) +{ + JLogSpanExporter::printAttributes(out, map, attsContainerName); +} + +void testJLogExporterPrintResources(StringBuffer & out, const opentelemetry::sdk::resource::Resource &resources) +{ + JLogSpanExporter::printResources(out, resources); +} +#endif +*/ +class JLogSpanExporterFactory +{ +public: + /** + * Create a JLogSpanExporter. + */ + static std::unique_ptr Create(SpanLogFlags logFlags) + { + return std::unique_ptr( + new JLogSpanExporter(logFlags)); + } +}; + class CHPCCHttpTextMapCarrier : public opentelemetry::context::propagation::TextMapCarrier { public: @@ -157,8 +446,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; @@ -190,16 +477,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; @@ -224,13 +501,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 @@ -241,17 +511,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); @@ -289,6 +548,22 @@ class CSpan : public CInterfaceOf span->SetAttribute(key, val); } + void addSpanEvent(const char * eventName, IProperties * attributes) override + { + if (span && !isEmptyString(eventName)) + { + std::map attributesMap; + Owned iter = attributes->getIterator(); + ForEach(*iter) + { + const char * key = iter->getPropKey(); + attributesMap.insert(std::pair(key, iter->queryPropValue())); + } + + span->AddEvent(eventName, attributesMap); + } + } + void addSpanEvent(const char * eventName) override { if (span && !isEmptyString(eventName)) @@ -428,13 +703,6 @@ class CSpan : public CInterfaceOf if (span != nullptr) { storeSpanContext(); - - if (queryInternalTraceManager().logSpanStart()) - { - StringBuffer out; - toLog(out); - LOG(MCmonitorEvent, "SpanStart: {%s}", out.str()); - } } } } @@ -513,10 +781,10 @@ class CNullSpan : public CInterfaceOf virtual void setSpanAttribute(const char * key, const char * val) override {} virtual void setSpanAttributes(const IProperties * attributes) override {} virtual void addSpanEvent(const char * eventName) override {} + virtual void addSpanEvent(const char * eventName, IProperties * attributes) override {}; 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; } @@ -579,15 +847,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); @@ -611,12 +870,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\""); @@ -634,12 +887,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\""); @@ -734,6 +981,9 @@ class CServerSpan : public CSpan if (!isEmptyString(hpccCallerId)) setSpanAttribute(kCallerIdOtelAttributeName, hpccCallerId.get()); + + if (!isEmptyString(hpccLocalId)) + setSpanAttribute(kLocalIdIdOtelAttributeName, hpccLocalId.get()); } public: @@ -761,28 +1011,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\""); @@ -819,7 +1047,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")) @@ -829,14 +1058,14 @@ void CTraceManager::initTracerProviderAndGlobalInternals(const IPropertyTree * t { StringBuffer exportType; exportConfig->getProp("@type", exportType); - DBGLOG("Exporter type: %s", exportType.str()); + LOG(MCoperatorInfo, "Exporter type: %s", exportType.str()); if (!exportType.isEmpty()) { if (stricmp(exportType.str(), "OS")==0) //To stdout/err { exporter = opentelemetry::exporter::trace::OStreamSpanExporterFactory::Create(); - DBGLOG("Tracing to stdout/err..."); + LOG(MCoperatorInfo, "Tracing exporter set OS"); } else if (stricmp(exportType.str(), "OTLP")==0 || stricmp(exportType.str(), "OTLP-HTTP")==0) { @@ -852,7 +1081,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()); + LOG(MCoperatorInfo,"Tracing exporter set to OTLP/HTTP to: (%s)", trace_opts.url.c_str()); } else if (stricmp(exportType.str(), "OTLP-GRPC")==0) { @@ -877,17 +1106,64 @@ 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()); + LOG(MCoperatorInfo, "Tracing exporter set to OTLP/GRPC to: (%s)", opts.endpoint.c_str()); + } + else if (stricmp(exportType.str(), "JLOG")==0) + { + StringBuffer logFlagsStr; + SpanLogFlags logFlags = SpanLogFlags::LogNone; + + if (exportConfig->getPropBool("@logSpanDetails", false)) + { + logFlags |= SpanLogFlags::LogSpanDetails; + logFlagsStr.append(" LogDetails "); + } + if (exportConfig->getPropBool("@logParentInfo", false)) + { + logFlags |= SpanLogFlags::LogParentInfo; + logFlagsStr.append(" LogParentInfo "); + } + if (exportConfig->getPropBool("@logAttributes", false)) + { + logFlags |= SpanLogFlags::LogAttributes; + logFlagsStr.append(" 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 "); + } + + //if no log feature flags provided, use default + if (logFlags == SpanLogFlags::LogNone) + logFlags = DEFAULT_SPAN_LOG_FLAGS; + + exporter = JLogSpanExporterFactory::Create(logFlags); + + LOG(MCoperatorInfo, "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"); + LOG(MCoperatorInfo, "Tracing to Prometheus currently not supported"); else if (stricmp(exportType.str(), "NONE")==0) - DBGLOG("Tracing exporter set to 'NONE', no trace exporting will be performed"); + { + exporter = NoopSpanExporterFactory::Create(); + LOG(MCoperatorInfo, "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()); + LOG(MCoperatorInfo, "Tracing exporter type not supported: '%s', JLog trace exporting will be performed", exportType.str()); } else - DBGLOG("Tracing exporter type not specified"); + LOG(MCoperatorInfo, "Tracing exporter type not specified"); } } @@ -910,15 +1186,15 @@ void CTraceManager::initTracerProviderAndGlobalInternals(const IPropertyTree * t //equal to max_queue_size. //size_t max_export_batch_size = 512 processor = opentelemetry::sdk::trace::BatchSpanProcessorFactory::Create(std::move(exporter), options); - DBGLOG("OpenTel tracing using batch Span Processor"); + LOG(MCoperatorInfo, "OpenTel tracing using batch Span Processor"); } else if (foundProcessorType && strcmp("simple", processorType.str())==0) { - DBGLOG("OpenTel tracing using batch simple Processor"); + LOG(MCoperatorInfo, "OpenTel tracing using batch simple Processor"); } else { - DBGLOG("OpenTel tracing detected invalid processor type: '%s'", processorType.str()); + LOG(MCoperatorInfo, "OpenTel tracing detected invalid processor type: '%s'", processorType.str()); } } @@ -943,7 +1219,7 @@ Expected Configuration format: alwaysCreateGlobalIds : false #optional - should global ids always be created? alwaysCreateTraceIds #optional - should trace ids always be created? exporter: #optional - Controls how trace data is exported/reported - type: OTLP #OS|OTLP|Prometheus|HPCC (default: no export, jlog entry) + type: OTLP #OS|OTLP|Prometheus|JLOG (default: JLOG) endpoint: "localhost:4317" #exporter specific key/value pairs useSslCredentials: true sslCredentialsCACcert: "ssl-certificate" @@ -959,14 +1235,18 @@ 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"); @@ -977,7 +1257,6 @@ void CTraceManager::initTracer(const IPropertyTree * traceConfig) toXML(traceConfig, xml); DBGLOG("traceConfig tree: %s", xml.str()); } - #endif bool disableTracing = traceConfig && traceConfig->getPropBool("@disabled", false); @@ -997,8 +1276,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..184e49c2232 100644 --- a/system/jlib/jtrace.hpp +++ b/system/jlib/jtrace.hpp @@ -17,7 +17,6 @@ #ifndef JTRACE_HPP #define JTRACE_HPP - /** * @brief This follows open telemetry's span attribute naming conventions * Known HPCC span Keys could be added here @@ -29,6 +28,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 { @@ -43,9 +58,9 @@ interface ISpan : extends IInterface virtual void setSpanAttribute(const char * key, const char * val) = 0; virtual void setSpanAttributes(const IProperties * attributes) = 0; virtual void addSpanEvent(const char * eventName) = 0; + virtual void addSpanEvent(const char * eventName, IProperties * attributes) = 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; @@ -69,6 +84,17 @@ interface ITraceManager : extends IInterface extern jlib_decl ISpan * getNullSpan(); extern jlib_decl void initTraceManager(const char * componentName, const IPropertyTree * componentConfig, const IPropertyTree * globalConfig); extern jlib_decl ITraceManager & queryTraceManager(); +/* +Temporarily disabled due to build issues in certain environments +#ifdef _USE_CPPUNIT +#include "opentelemetry/sdk/common/attribute_utils.h" +#include "opentelemetry/sdk/resource/resource.h" + +extern jlib_decl void testJLogExporterPrintResources(StringBuffer & out, const opentelemetry::sdk::resource::Resource &resources); +extern jlib_decl void testJLogExporterPrintAttributes(StringBuffer & out, const std::unordered_map & map, const char * attsContainerName); +#endif +*/ + //The following class is responsible for ensuring that the active span is restored in a context when the scope is exited //Use a template class so it can be reused for IContextLogger and IEspContext diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp index 9918b77c5ef..3a1ece2eb20 100644 --- a/testing/unittests/jlibtests.cpp +++ b/testing/unittests/jlibtests.cpp @@ -36,6 +36,9 @@ #include "jutil.hpp" #include "junicode.hpp" +#include "opentelemetry/sdk/common/attribute_utils.h" +#include "opentelemetry/sdk/resource/resource.h" + #include "unittests.hpp" #define CPPUNIT_ASSERT_EQUAL_STR(x, y) CPPUNIT_ASSERT_EQUAL(std::string(x),std::string(y)) @@ -60,6 +63,9 @@ class JlibTraceTest : public CppUnit::TestFixture CPPUNIT_TEST(testNullSpan); CPPUNIT_TEST(testClientSpanGlobalID); CPPUNIT_TEST(testEnsureTraceID); + + //CPPUNIT_TEST(testJTraceJLOGExporterprintResources); + //CPPUNIT_TEST(testJTraceJLOGExporterprintAttributes); CPPUNIT_TEST_SUITE_END(); const char * simulatedGlobalYaml = R"!!(global: @@ -104,6 +110,84 @@ class JlibTraceTest : public CppUnit::TestFixture protected: + /*void testJTraceJLOGExporterprintAttributes() + { + StringBuffer out; + testJLogExporterPrintAttributes(out, {}, "attributes"); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected non-empty printattributes", true, out.length() == 0); + + + testJLogExporterPrintAttributes(out, {{"url", "https://localhost"}, {"content-length", 562}, {"content-type", "html/text"}}, "attributes"); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected empty printattributes", false, out.length() == 0); + + Owned jtraceAsTree; + try + { + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected leading non-comma char in printattributes", true, out.charAt(0) == ','); + + out.setCharAt(0, '{'); + out.append("}"); + + jtraceAsTree.setown(createPTreeFromJSONString(out.str())); + } + catch (IException *e) + { + StringBuffer msg; + msg.append("Unexpected printAttributes format failure detected: "); + e->errorMessage(msg); + e->Release(); + CPPUNIT_ASSERT_MESSAGE(msg.str(), false); + } + + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected printresources format failure detected", true, jtraceAsTree != nullptr); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("attributes")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("attributes/url")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("attributes/content-length")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("attributes/content-type")); + }*/ + + /*void testJTraceJLOGExporterprintResources() + { + StringBuffer out; + auto dummyAttributes = opentelemetry::sdk::resource::ResourceAttributes + { + {"service.name", "shoppingcart"}, + {"service.instance.id", "instance-12"} + }; + auto dummyResources = opentelemetry::sdk::resource::Resource::Create(dummyAttributes); + + testJLogExporterPrintResources(out, dummyResources); + + Owned jtraceAsTree; + try + { + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected empty printresources return", false, out.length() == 0); + + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected leading non-comma char in printresources return", true, out.charAt(0) == ','); + + out.setCharAt(0, '{'); + out.append("}"); + + jtraceAsTree.setown(createPTreeFromJSONString(out.str())); + } + catch (IException *e) + { + StringBuffer msg; + msg.append("Unexpected printresources format failure detected: "); + e->errorMessage(msg); + e->Release(); + CPPUNIT_ASSERT_MESSAGE(msg.str(), false); + } + + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected printresources format failure detected", true, jtraceAsTree != nullptr); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/service.name")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/service.instance.id")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/telemetry.sdk.language")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/telemetry.sdk.version")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Missing resource attribute detected", true, jtraceAsTree->hasProp("resources/telemetry.sdk.name")); + }*/ + void testTraceDisableConfig() { Owned testTree = createPTreeFromYAMLString(disableTracingYaml, ipt_none, ptr_ignoreWhiteSpace, nullptr); @@ -383,32 +467,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("}");