diff --git a/cpp/src/arrow/flight/sql/server.cc b/cpp/src/arrow/flight/sql/server.cc index a5cb842de8f49..2a02b6a965274 100644 --- a/cpp/src/arrow/flight/sql/server.cc +++ b/cpp/src/arrow/flight/sql/server.cc @@ -32,6 +32,10 @@ #include "arrow/flight/sql/sql_info_internal.h" #include "arrow/type.h" #include "arrow/util/checked_cast.h" +#include "arrow/util/logging_v2.h" + +#define ARROW_FLIGHT_SQL_LOG(LEVEL, ...) \ + ARROW_LOG_WITH("FlightSqlServer", LEVEL, __VA_ARGS__) #define PROPERTY_TO_OPTIONAL(COMMAND, PROPERTY) \ COMMAND.has_##PROPERTY() ? std::make_optional(COMMAND.PROPERTY()) : std::nullopt @@ -723,6 +727,7 @@ Status FlightSqlServerBase::DoPut(const ServerCallContext& context, if (!any.ParseFromArray(request.cmd.data(), static_cast(request.cmd.size()))) { return Status::Invalid("Unable to parse command"); } + ARROW_FLIGHT_SQL_LOG(INFO, "[DoPut] command: ", request.cmd); if (any.Is()) { ARROW_ASSIGN_OR_RAISE(StatementUpdate internal_command, @@ -794,6 +799,7 @@ Status FlightSqlServerBase::DoAction(const ServerCallContext& context, const Action& action, std::unique_ptr* result_stream) { std::vector results; + ARROW_FLIGHT_SQL_LOG(INFO, "[DoAction] action.type: ", action.type); if (action.type == ActionType::kCancelFlightInfo.type) { std::string_view body(*action.body); ARROW_ASSIGN_OR_RAISE(auto request, CancelFlightInfoRequest::Deserialize(body)); diff --git a/cpp/src/arrow/flight/sql/server_test.cc b/cpp/src/arrow/flight/sql/server_test.cc index 42e0c7d7a1f12..49ade67cf73ca 100644 --- a/cpp/src/arrow/flight/sql/server_test.cc +++ b/cpp/src/arrow/flight/sql/server_test.cc @@ -24,6 +24,7 @@ #include "arrow/array/array_binary.h" #include "arrow/array/array_nested.h" #include "arrow/array/array_primitive.h" +#include "arrow/flight/server_tracing_middleware.h" #include "arrow/flight/sql/client.h" #include "arrow/flight/sql/column_metadata.h" #include "arrow/flight/sql/example/sqlite_server.h" @@ -37,11 +38,59 @@ #include "arrow/table.h" #include "arrow/testing/builder.h" #include "arrow/testing/gtest_util.h" +#include "arrow/util/logging_v2.h" + +#ifdef ARROW_TELEMETRY +#include "arrow/telemetry/logging.h" +#include "arrow/util/tracing_internal.h" + +#include +#include +#include +#include +#include +#endif using arrow::internal::checked_cast; namespace arrow::flight::sql { +#ifdef ARROW_TELEMETRY +class OtelEnvironment : public ::testing::Environment { + public: + void SetUp() override { + std::vector> processors; + auto tracer_provider = + opentelemetry::nostd::shared_ptr( + new opentelemetry::sdk::trace::TracerProvider(std::move(processors))); + opentelemetry::trace::Provider::SetTracerProvider(std::move(tracer_provider)); + + opentelemetry::context::propagation::GlobalTextMapPropagator::SetGlobalPropagator( + opentelemetry::nostd::shared_ptr< + opentelemetry::context::propagation::TextMapPropagator>( + new opentelemetry::trace::propagation::HttpTraceContext())); + + auto provider_options = telemetry::LoggerProviderOptions::Defaults(); + ASSERT_OK(telemetry::GlobalLoggerProvider::Initialize(provider_options)); + auto logging_options = telemetry::LoggingOptions::Defaults(); + logging_options.severity_threshold = telemetry::LogLevel::ARROW_TRACE; + logging_options.flush_severity = telemetry::LogLevel::ARROW_TRACE; + std::shared_ptr logger1, logger2; + ASSERT_OK_AND_ASSIGN(logger1, telemetry::GlobalLoggerProvider::MakeLogger( + "FlightGrpcServer", logging_options)); + ASSERT_OK_AND_ASSIGN(logger2, telemetry::GlobalLoggerProvider::MakeLogger( + "FlightSqlServer", logging_options)); + ASSERT_OK(util::LoggerRegistry::RegisterLogger(logger1->name(), logger1)); + ASSERT_OK(util::LoggerRegistry::RegisterLogger(logger2->name(), logger2)); + } + + void TearDown() override { EXPECT_TRUE(telemetry::GlobalLoggerProvider::ShutDown()); } +}; + +static ::testing::Environment* kOtelEnvironment = + ::testing::AddGlobalTestEnvironment(new OtelEnvironment); +#endif + /// \brief Auxiliary variant visitor used to assert that GetSqlInfo's values are /// correctly placed on its DenseUnionArray class SqlInfoDenseUnionValidator { @@ -150,6 +199,8 @@ class TestFlightSqlServer : public ::testing::Test { void SetUp() override { ASSERT_OK_AND_ASSIGN(auto location, Location::ForGrpcTcp("0.0.0.0", 0)); arrow::flight::FlightServerOptions options(location); + options.middleware.push_back({"FlightSqlTracingMiddleware", + arrow::flight::MakeTracingServerMiddlewareFactory()}); ASSERT_OK_AND_ASSIGN(server, example::SQLiteFlightSqlServer::Create()); ASSERT_OK(server->Init(options)); diff --git a/cpp/src/arrow/flight/transport/grpc/grpc_server.cc b/cpp/src/arrow/flight/transport/grpc/grpc_server.cc index 28fc736aa0088..994c3eb213203 100644 --- a/cpp/src/arrow/flight/transport/grpc/grpc_server.cc +++ b/cpp/src/arrow/flight/transport/grpc/grpc_server.cc @@ -37,8 +37,12 @@ #include "arrow/flight/transport_server.h" #include "arrow/flight/types.h" #include "arrow/util/logging.h" +#include "arrow/util/logging_v2.h" #include "arrow/util/uri.h" +#define ARROW_FLIGHT_LOG(LEVEL, ...) \ + ARROW_LOG_WITH("FlightGrpcServer", LEVEL, __VA_ARGS__) + namespace arrow { namespace flight { namespace transport { @@ -335,6 +339,8 @@ class GrpcServiceHandler final : public FlightService::Service { return flight_context.FinishRequest(result); } if (instance != nullptr) { + ARROW_FLIGHT_LOG( + INFO, "[MakeCallContext] Started call for middleware: ", instance->name()); flight_context.middleware_.push_back(instance); flight_context.middleware_map_.insert({factory.first, instance}); } @@ -531,6 +537,7 @@ class GrpcServiceHandler final : public FlightService::Service { CHECK_ARG_NOT_NULL(flight_context, request, "Action cannot be null"); Action action; SERVICE_RETURN_NOT_OK(flight_context, internal::FromProto(*request, &action)); + ARROW_FLIGHT_LOG(INFO, "[DoAction] action.type=", action.type); std::unique_ptr results; SERVICE_RETURN_NOT_OK(flight_context,