Improve tracing

Author: aasasiku

instrumentation/nginx/CMakeLists.txt

@@ -23,6 +23,8 @@ add_library(otel_ngx_module SHARED
   src/otel_ngx_module_modules.c
   src/propagate.cpp
   src/script.cpp
+  src/post_batch_span_processor.cpp
+  src/post_span_processor.cpp
 )
 
 target_compile_options(otel_ngx_module

instrumentation/nginx/src/otel_ngx_module.cpp

@@ -21,6 +21,8 @@ extern ngx_module_t otel_ngx_module;
 #include "nginx_config.h"
 #include "nginx_utils.h"
 #include "propagate.h"
+#include "post_span_processor.h"
+#include "post_batch_span_processor.h"
 #include <opentelemetry/context/context.h>
 #include <opentelemetry/nostd/shared_ptr.h>
 #include <opentelemetry/sdk/trace/batch_span_processor.h>
@@ -496,21 +498,13 @@ TraceContext* CreateTraceContext(ngx_http_request_t* req, ngx_http_variable_valu
   return context;
 }
 
-ngx_int_t StartNgxSpan(ngx_http_request_t* req) {
-  if (!IsOtelEnabled(req)) {
-    return NGX_DECLINED;
-  }
-
-  // Internal requests must be called from another location in nginx, that should already have a trace. Without this check, a call would generate an extra (unrelated) span without much information
-  if (req->internal) {
-    return NGX_DECLINED;
-  }
+TraceContext* StartNgxTrace(ngx_http_request_t* req)  {
 
   ngx_http_variable_value_t* val = ngx_http_get_indexed_variable(req, otel_ngx_variables[0].index);
 
   if (!val) {
     ngx_log_error(NGX_LOG_ERR, req->connection->log, 0, "Unable to find OpenTelemetry context");
-    return NGX_DECLINED;
+    return nullptr;
   }
 
   TraceContext* context = CreateTraceContext(req, val);
@@ -524,30 +518,43 @@ ngx_int_t StartNgxSpan(ngx_http_request_t* req) {
     incomingContext = ExtractContext(&carrier);
   }
 
-  trace::StartSpanOptions startOpts;
-  startOpts.kind = trace::SpanKind::kServer;
-  startOpts.parent = GetCurrentSpan(incomingContext);
+  const auto operationName = GetOperationName(req);
+
+  std::initializer_list<std::pair<nostd::string_view, common::AttributeValue>> commonAttributes = {
+          {"http.method", FromNgxString(req->method_name)},
+          {"http.flavor", NgxHttpFlavor(req)},
+          {"http.target", FromNgxString(req->unparsed_uri)},
+          // Add http.route as its according to OpenTelemetry spec
+          {"http.route", FromNgxString(req->unparsed_uri)}
+  };
+
+  trace::StartSpanOptions requestStartOpts;
+  requestStartOpts.parent = GetCurrentSpan(incomingContext);
+  requestStartOpts.kind = trace::SpanKind::kServer;
+  context->request_span = GetTracer()->StartSpan(operationName,commonAttributes, requestStartOpts);
 
-  context->request_span = GetTracer()->StartSpan(
-    GetOperationName(req),
-    {
-      {"http.method", FromNgxString(req->method_name)},
-      {"http.flavor", NgxHttpFlavor(req)},
-      {"http.target", FromNgxString(req->unparsed_uri)},
-    },
-    startOpts);
+  trace::StartSpanOptions innerSpanOpts;
+  innerSpanOpts.parent = context->request_span->GetContext();
+  innerSpanOpts.kind = trace::SpanKind::kInternal;
+
+  context->inner_span = GetTracer()->StartSpan(operationName,commonAttributes,innerSpanOpts);
 
   nostd::string_view serverName = GetNgxServerName(req);
   if (!serverName.empty()) {
     context->request_span->SetAttribute("http.server_name", serverName);
+    context->inner_span->SetAttribute("http.server_name", serverName);
   }
 
   if (req->headers_in.host) {
-    context->request_span->SetAttribute("http.host", FromNgxString(req->headers_in.host->value));
+    const auto host = FromNgxString(req->headers_in.host->value);
+    context->request_span->SetAttribute("http.host", host);
+    context->inner_span->SetAttribute("http.host", host);
   }
 
   if (req->headers_in.user_agent) {
-    context->request_span->SetAttribute("http.user_agent", FromNgxString(req->headers_in.user_agent->value));
+    const auto userAgent = FromNgxString(req->headers_in.user_agent->value);
+    context->request_span->SetAttribute("http.user_agent", userAgent);
+    context->inner_span->SetAttribute("http.user_agent", userAgent);
   }
 
   if (locConf->captureHeaders) {
@@ -559,10 +566,24 @@ ngx_int_t StartNgxSpan(ngx_http_request_t* req) {
                        {excludedHeaders, 2});
   }
 
-  auto outgoingContext = incomingContext.SetValue(trace::kSpanKey, context->request_span);
+  auto outgoingContext = incomingContext.SetValue(trace::kSpanKey, context->inner_span);
 
   InjectContext(&carrier, outgoingContext);
 
+  return context;
+}
+
+ngx_int_t StartNgxSpan(ngx_http_request_t* req) {
+  if (!IsOtelEnabled(req)) {
+    return NGX_DECLINED;
+  }
+
+  if (req->internal) {
+    return NGX_DECLINED;
+  }
+
+  StartNgxTrace(req);
+
   return NGX_DECLINED;
 }
 
@@ -591,18 +612,7 @@ void AddScriptAttributes(
   }
 }
 
-ngx_int_t FinishNgxSpan(ngx_http_request_t* req) {
-  if (!IsOtelEnabled(req)) {
-    return NGX_DECLINED;
-  }
-
-  TraceContext* context = GetTraceContext(req);
-
-  if (!context) {
-    return NGX_DECLINED;
-  }
-
-  auto span = context->request_span;
+void UpdateSpan(nostd::shared_ptr<opentelemetry::trace::Span> span, ngx_http_request_t* req, bool captureHeaders = false) {
   const auto status_code = req->headers_out.status;
   span->SetAttribute("http.status_code", status_code);
 
@@ -612,9 +622,9 @@ ngx_int_t FinishNgxSpan(ngx_http_request_t* req) {
     span->SetStatus(trace::StatusCode::kOk);
   }
 
-  OtelNgxLocationConf* locConf = GetOtelLocationConf(req);
+  OtelNgxLocationConf *locConf = GetOtelLocationConf(req);
 
-  if (locConf->captureHeaders) {
+  if (locConf->captureHeaders && captureHeaders) {
     OtelCaptureHeaders(span, ngx_string("http.response.header."), &req->headers_out.headers,
 #if (NGX_PCRE)
                        locConf->sensitiveHeaderNames, locConf->sensitiveHeaderValues,
@@ -625,7 +635,46 @@ ngx_int_t FinishNgxSpan(ngx_http_request_t* req) {
   AddScriptAttributes(span.get(), GetOtelMainConf(req)->scriptAttributes, req);
   AddScriptAttributes(span.get(), locConf->customAttributes, req);
 
+  if (req->headers_out.status >= 400 && req->headers_out.status <= 599) {
+    span->SetStatus(trace::StatusCode::kError);
+  }
+
   span->UpdateName(GetOperationName(req));
+}
+
+ngx_int_t FinishNgxSpan(ngx_http_request_t* req) {
+  if (!IsOtelEnabled(req)) {
+    return NGX_DECLINED;
+  }
+
+  if (req->internal) {
+    return NGX_DECLINED;
+  }
+
+  TraceContext* context = GetTraceContext(req);
+
+  /*
+   * When nginx fails to process request (bad request, prematurely closed) then span is not started, here we can start
+   * a new span because there were no upstream calls anyway.
+   */
+  if (!context) {
+    context = StartNgxTrace(req);
+  }
+
+  auto span = context->request_span;
+  UpdateSpan(span, req, true);
+
+  if (context->inner_span) {
+
+    const bool hasUpstream = req->upstream != nullptr;
+    if (hasUpstream) {
+      context->inner_span->SetAttribute("span.kind", static_cast<int>(trace::SpanKind::kClient));
+    }
+
+    UpdateSpan(context->inner_span, req);
+
+    context->inner_span->End();
+  }
 
   span->End();
   return NGX_DECLINED;
@@ -642,7 +691,7 @@ static ngx_int_t InitModule(ngx_conf_t* conf) {
 
   const PhaseHandler handlers[] = {
     {NGX_HTTP_REWRITE_PHASE, StartNgxSpan},
-    {NGX_HTTP_LOG_PHASE, FinishNgxSpan},
+    {NGX_HTTP_LOG_PHASE, FinishNgxSpan}
   };
 
   for (const PhaseHandler& ph : handlers) {
@@ -1300,11 +1349,11 @@ CreateProcessor(const OtelNgxAgentConfig* conf, std::unique_ptr<sdktrace::SpanEx
     opts.max_export_batch_size = conf->processor.batch.maxExportBatchSize;
 
     return std::unique_ptr<sdktrace::SpanProcessor>(
-      new sdktrace::BatchSpanProcessor(std::move(exporter), opts));
+      new PostBatchSpanProcessor(std::move(exporter), opts));
   }
 
   return std::unique_ptr<sdktrace::SpanProcessor>(
-    new sdktrace::SimpleSpanProcessor(std::move(exporter)));
+    new PostSpanProcessor(std::move(exporter)));
 }
 
 static std::unique_ptr<sdktrace::Sampler> CreateSampler(const OtelNgxAgentConfig* conf) {

instrumentation/nginx/src/post_batch_span_processor.cpp

@@ -0,0 +1,8 @@
+#include "post_batch_span_processor.h"
+#include <opentelemetry/exporters/otlp/otlp_recordable.h>
+
+void PostBatchSpanProcessor::OnEnd(std::unique_ptr<opentelemetry::sdk::trace::Recordable> &&span) noexcept
+{
+  ProxyRecordable* proxy = static_cast<ProxyRecordable*>(span.get());
+  BatchSpanProcessor::OnEnd(std::move(proxy->GetRealRecordable()));
+}

instrumentation/nginx/src/post_batch_span_processor.h

@@ -0,0 +1,27 @@
+#ifndef OPENTELEMETRY_NGINX_POST_BATCH_SPAN_PROCESSOR_H
+#define OPENTELEMETRY_NGINX_POST_BATCH_SPAN_PROCESSOR_H
+
+#include "proxy_recordable.h"
+#include <opentelemetry/nostd/shared_ptr.h>
+#include <opentelemetry/sdk/trace/batch_span_processor.h>
+
+namespace trace = opentelemetry::trace;
+namespace nostd = opentelemetry::nostd;
+namespace sdktrace = opentelemetry::sdk::trace;
+
+class PostBatchSpanProcessor : public sdktrace::BatchSpanProcessor {
+public:
+
+    explicit PostBatchSpanProcessor(std::unique_ptr<sdktrace::SpanExporter> &&exporter,
+                                    const sdktrace::BatchSpanProcessorOptions &options) noexcept
+            : BatchSpanProcessor(std::move(exporter), options)
+    {}
+
+    void OnEnd(std::unique_ptr<opentelemetry::sdk::trace::Recordable> &&span) noexcept override;
+
+    std::unique_ptr<opentelemetry::sdk::trace::Recordable> MakeRecordable() noexcept override {
+      return std::unique_ptr<ProxyRecordable>(new ProxyRecordable());
+    }
+};
+
+#endif //OPENTELEMETRY_NGINX_POST_BATCH_SPAN_PROCESSOR_H

instrumentation/nginx/src/post_span_processor.cpp

@@ -0,0 +1,7 @@
+#include "post_span_processor.h"
+
+void PostSpanProcessor::OnEnd(std::unique_ptr<opentelemetry::sdk::trace::Recordable> &&span) noexcept
+{
+  ProxyRecordable* proxy = static_cast<ProxyRecordable*>(span.get());
+  SimpleSpanProcessor::OnEnd(std::move(proxy->GetRealRecordable()));
+}

instrumentation/nginx/src/post_span_processor.h

@@ -0,0 +1,26 @@
+#ifndef OPENTELEMETRY_NGINX_POST_SPAN_PROCESSOR_H
+#define OPENTELEMETRY_NGINX_POST_SPAN_PROCESSOR_H
+
+#include <opentelemetry/nostd/shared_ptr.h>
+#include <opentelemetry/sdk/trace/simple_processor.h>
+#include "proxy_recordable.h"
+
+namespace trace = opentelemetry::trace;
+namespace nostd = opentelemetry::nostd;
+namespace sdktrace = opentelemetry::sdk::trace;
+
+class PostSpanProcessor : public sdktrace::SimpleSpanProcessor {
+public:
+
+    explicit PostSpanProcessor(std::unique_ptr<sdktrace::SpanExporter> &&exporter) noexcept
+    : SimpleSpanProcessor(std::move(exporter))
+    {}
+
+    void OnEnd(std::unique_ptr<opentelemetry::sdk::trace::Recordable> &&span) noexcept override;
+
+    std::unique_ptr<opentelemetry::sdk::trace::Recordable> MakeRecordable() noexcept override {
+      return std::unique_ptr<ProxyRecordable>(new ProxyRecordable());
+    }
+};
+
+#endif //OPENTELEMETRY_NGINX_POST_SPAN_PROCESSOR_H

instrumentation/nginx/src/proxy_recordable.h

@@ -0,0 +1,83 @@
+#ifndef OPENTELEMETRY_NGINX_PROXY_RECORDABLE_H
+#define OPENTELEMETRY_NGINX_PROXY_RECORDABLE_H
+
+#include <opentelemetry/exporters/otlp/otlp_recordable.h>
+
+namespace trace = opentelemetry::trace;
+namespace nostd = opentelemetry::nostd;
+namespace sdktrace = opentelemetry::sdk::trace;
+
+/**
+ * Wraps actual recordable object so we could override span.kind through SetAttribute. This workarounds the problem that
+ * in OpenTelemetry cpp SDK span kind is immutable on a span, but it causes problems for this instrumentation library.
+ */
+class ProxyRecordable : public sdktrace::Recordable {
+public:
+
+    ProxyRecordable()
+            : _realRecordable(new opentelemetry::exporter::otlp::OtlpRecordable()) { }
+
+    std::unique_ptr<opentelemetry::exporter::otlp::OtlpRecordable> GetRealRecordable() {
+      return std::unique_ptr<opentelemetry::exporter::otlp::OtlpRecordable>(std::move(_realRecordable));
+    }
+
+    void SetIdentity(const opentelemetry::trace::SpanContext &span_context,
+                     opentelemetry::trace::SpanId parent_span_id) noexcept override {
+      _realRecordable->SetIdentity(span_context, parent_span_id);
+    }
+
+    virtual void SetAttribute(nostd::string_view key,
+                              const opentelemetry::common::AttributeValue &value) noexcept override {
+      if (key == "span.kind") {
+        trace::SpanKind kind = static_cast<trace::SpanKind>(nostd::get<int>(value));
+        _realRecordable->SetSpanKind(kind);
+      } else {
+        _realRecordable->SetAttribute(key, value);
+      }
+    }
+
+    void AddEvent(nostd::string_view name,
+                  opentelemetry::common::SystemTimestamp timestamp,
+                  const opentelemetry::common::KeyValueIterable &attributes) noexcept override {
+      _realRecordable->AddEvent(name, timestamp, attributes);
+    };
+
+    void AddLink(const opentelemetry::trace::SpanContext &span_context,
+                 const opentelemetry::common::KeyValueIterable &attributes) noexcept override {
+      _realRecordable->AddLink(span_context, attributes);
+    };
+
+    void SetStatus(opentelemetry::trace::StatusCode code,
+                   nostd::string_view description) noexcept override {
+      _realRecordable->SetStatus(code, description);
+    };
+
+    void SetName(nostd::string_view name) noexcept override {
+      _realRecordable->SetName(name);
+    };
+
+    void SetSpanKind(opentelemetry::trace::SpanKind span_kind) noexcept override {
+      _realRecordable->SetSpanKind(span_kind);
+    };
+
+    void SetResource(const opentelemetry::sdk::resource::Resource &resource) noexcept override {
+      _realRecordable->SetResource(resource);
+    };
+
+    void SetStartTime(opentelemetry::common::SystemTimestamp start_time) noexcept override {
+      _realRecordable->SetStartTime(start_time);
+    };
+
+    void SetDuration(std::chrono::nanoseconds duration) noexcept override {
+      _realRecordable->SetDuration(duration);
+    };
+
+    void SetInstrumentationScope(const sdktrace::InstrumentationScope &instrumentation_scope) noexcept override {
+      _realRecordable->SetInstrumentationScope(instrumentation_scope);
+    };
+
+private:
+    std::unique_ptr<opentelemetry::exporter::otlp::OtlpRecordable> _realRecordable;
+};
+
+#endif //OPENTELEMETRY_NGINX_PROXY_RECORDABLE_H

instrumentation/nginx/src/trace_context.h

@@ -22,7 +22,11 @@ struct TraceContext {
   TraceContext(ngx_http_request_t* req) : request(req), traceHeader{} {}
   /* The current request being handled by nginx. */
   ngx_http_request_t* request;
+  /* Span used to record incoming requests */
   opentelemetry::nostd::shared_ptr<opentelemetry::trace::Span> request_span;
+  /* Span used to record internal processing. This span could be internal or client
+   * depending if nginx handles request locally or calls upstream */
+   opentelemetry::nostd::shared_ptr<opentelemetry::trace::Span> inner_span;
   /* Headers to be injected for the upstream request. */
   TraceHeader traceHeader[2];
 };