diff --git a/BUILD b/BUILD index 53c84945f50..7b2cca3c1c3 100644 --- a/BUILD +++ b/BUILD @@ -1685,7 +1685,6 @@ grpc_cc_library( "//src/core:event_engine_query_extensions", "//src/core:event_engine_shim", "//src/core:event_engine_tcp_socket_utils", - "//src/core:event_engine_trace", "//src/core:event_log", "//src/core:examine_stack", "//src/core:experiments", @@ -3128,6 +3127,7 @@ grpc_cc_library( grpc_cc_library( name = "debug_location", + external_deps = ["absl/strings"], language = "c++", public_hdrs = ["//src/core:lib/gprpp/debug_location.h"], visibility = ["@grpc:debug_location"], diff --git a/Package.swift b/Package.swift index 367dc96f994..260c070857e 100644 --- a/Package.swift +++ b/Package.swift @@ -1218,7 +1218,6 @@ let package = Package( "src/core/lib/event_engine/thready_event_engine/thready_event_engine.h", "src/core/lib/event_engine/time_util.cc", "src/core/lib/event_engine/time_util.h", - "src/core/lib/event_engine/trace.h", "src/core/lib/event_engine/utils.cc", "src/core/lib/event_engine/utils.h", "src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc", diff --git a/build_autogenerated.yaml b/build_autogenerated.yaml index de10143e6fa..e937a527def 100644 --- a/build_autogenerated.yaml +++ b/build_autogenerated.yaml @@ -864,7 +864,6 @@ libs: - src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h - src/core/lib/event_engine/thready_event_engine/thready_event_engine.h - src/core/lib/event_engine/time_util.h - - src/core/lib/event_engine/trace.h - src/core/lib/event_engine/utils.h - src/core/lib/event_engine/windows/grpc_polled_fd_windows.h - src/core/lib/event_engine/windows/iocp.h @@ -2402,7 +2401,6 @@ libs: - src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h - src/core/lib/event_engine/thready_event_engine/thready_event_engine.h - src/core/lib/event_engine/time_util.h - - src/core/lib/event_engine/trace.h - src/core/lib/event_engine/utils.h - src/core/lib/event_engine/windows/grpc_polled_fd_windows.h - src/core/lib/event_engine/windows/iocp.h @@ -4501,7 +4499,6 @@ libs: - src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h - src/core/lib/event_engine/thready_event_engine/thready_event_engine.h - src/core/lib/event_engine/time_util.h - - src/core/lib/event_engine/trace.h - src/core/lib/event_engine/utils.h - src/core/lib/event_engine/windows/grpc_polled_fd_windows.h - src/core/lib/event_engine/windows/iocp.h @@ -6795,7 +6792,6 @@ targets: - src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h - src/core/lib/event_engine/thready_event_engine/thready_event_engine.h - src/core/lib/event_engine/time_util.h - - src/core/lib/event_engine/trace.h - src/core/lib/event_engine/utils.h - src/core/lib/event_engine/windows/grpc_polled_fd_windows.h - src/core/lib/event_engine/windows/iocp.h @@ -12519,7 +12515,6 @@ targets: - src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h - src/core/lib/event_engine/thready_event_engine/thready_event_engine.h - src/core/lib/event_engine/time_util.h - - src/core/lib/event_engine/trace.h - src/core/lib/event_engine/utils.h - src/core/lib/event_engine/windows/grpc_polled_fd_windows.h - src/core/lib/event_engine/windows/iocp.h diff --git a/gRPC-C++.podspec b/gRPC-C++.podspec index a22b5704b0d..45d20d5aa5d 100644 --- a/gRPC-C++.podspec +++ b/gRPC-C++.podspec @@ -951,7 +951,6 @@ Pod::Spec.new do |s| 'src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h', 'src/core/lib/event_engine/thready_event_engine/thready_event_engine.h', 'src/core/lib/event_engine/time_util.h', - 'src/core/lib/event_engine/trace.h', 'src/core/lib/event_engine/utils.h', 'src/core/lib/event_engine/windows/grpc_polled_fd_windows.h', 'src/core/lib/event_engine/windows/iocp.h', @@ -2225,7 +2224,6 @@ Pod::Spec.new do |s| 'src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h', 'src/core/lib/event_engine/thready_event_engine/thready_event_engine.h', 'src/core/lib/event_engine/time_util.h', - 'src/core/lib/event_engine/trace.h', 'src/core/lib/event_engine/utils.h', 'src/core/lib/event_engine/windows/grpc_polled_fd_windows.h', 'src/core/lib/event_engine/windows/iocp.h', diff --git a/gRPC-Core.podspec b/gRPC-Core.podspec index 256ddb0ffde..e4e3f69602d 100644 --- a/gRPC-Core.podspec +++ b/gRPC-Core.podspec @@ -1337,7 +1337,6 @@ Pod::Spec.new do |s| 'src/core/lib/event_engine/thready_event_engine/thready_event_engine.h', 'src/core/lib/event_engine/time_util.cc', 'src/core/lib/event_engine/time_util.h', - 'src/core/lib/event_engine/trace.h', 'src/core/lib/event_engine/utils.cc', 'src/core/lib/event_engine/utils.h', 'src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc', @@ -2996,7 +2995,6 @@ Pod::Spec.new do |s| 'src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.h', 'src/core/lib/event_engine/thready_event_engine/thready_event_engine.h', 'src/core/lib/event_engine/time_util.h', - 'src/core/lib/event_engine/trace.h', 'src/core/lib/event_engine/utils.h', 'src/core/lib/event_engine/windows/grpc_polled_fd_windows.h', 'src/core/lib/event_engine/windows/iocp.h', diff --git a/grpc.gemspec b/grpc.gemspec index 79fe97f48fd..557a52dbe81 100644 --- a/grpc.gemspec +++ b/grpc.gemspec @@ -1224,7 +1224,6 @@ Gem::Specification.new do |s| s.files += %w( src/core/lib/event_engine/thready_event_engine/thready_event_engine.h ) s.files += %w( src/core/lib/event_engine/time_util.cc ) s.files += %w( src/core/lib/event_engine/time_util.h ) - s.files += %w( src/core/lib/event_engine/trace.h ) s.files += %w( src/core/lib/event_engine/utils.cc ) s.files += %w( src/core/lib/event_engine/utils.h ) s.files += %w( src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc ) diff --git a/package.xml b/package.xml index d86081bdb75..b3c2b6e941b 100644 --- a/package.xml +++ b/package.xml @@ -1206,7 +1206,6 @@ - diff --git a/src/core/BUILD b/src/core/BUILD index fc6a9b8f7fb..e8fbbeeeebf 100644 --- a/src/core/BUILD +++ b/src/core/BUILD @@ -1905,8 +1905,8 @@ grpc_cc_library( "absl/base:core_headers", "absl/container:flat_hash_set", "absl/functional:any_invocable", + "absl/log", "absl/log:check", - "absl/log:log", "absl/time", "absl/types:optional", ], @@ -1916,7 +1916,6 @@ grpc_cc_library( "event_engine_basic_work_queue", "event_engine_thread_count", "event_engine_thread_local", - "event_engine_trace", "event_engine_work_queue", "examine_stack", "forkable", @@ -1926,6 +1925,7 @@ grpc_cc_library( "//:backoff", "//:event_engine_base_hdrs", "//:gpr", + "//:grpc_trace", ], ) @@ -2249,8 +2249,8 @@ grpc_cc_library( "absl/container:flat_hash_map", "absl/functional:any_invocable", "absl/hash", + "absl/log", "absl/log:check", - "absl/log:log", "absl/status", "absl/status:statusor", "absl/strings", @@ -2260,7 +2260,6 @@ grpc_cc_library( "event_engine_common", "event_engine_extensions", "event_engine_tcp_socket_utils", - "event_engine_trace", "experiments", "iomgr_port", "load_file", @@ -2282,6 +2281,7 @@ grpc_cc_library( "//:exec_ctx", "//:gpr", "//:grpc_public_hdrs", + "//:grpc_trace", "//:ref_counted_ptr", ], ) @@ -2372,8 +2372,8 @@ grpc_cc_library( external_deps = [ "absl/base:core_headers", "absl/functional:any_invocable", + "absl/log", "absl/log:check", - "absl/log:log", "absl/status", "absl/status:statusor", "absl/strings", @@ -2381,7 +2381,6 @@ grpc_cc_library( ], deps = [ "event_engine_tcp_socket_utils", - "event_engine_trace", "iomgr_port", "posix_event_engine_base_hdrs", "posix_event_engine_closure", @@ -2396,6 +2395,7 @@ grpc_cc_library( "//:event_engine_base_hdrs", "//:exec_ctx", "//:gpr", + "//:grpc_trace", ], ) @@ -2421,7 +2421,6 @@ grpc_cc_library( "event_engine_poller", "event_engine_tcp_socket_utils", "event_engine_thread_pool", - "event_engine_trace", "event_engine_utils", "forkable", "init_internally", @@ -2467,7 +2466,6 @@ grpc_cc_library( "event_engine_common", "event_engine_tcp_socket_utils", "event_engine_thread_pool", - "event_engine_trace", "event_engine_utils", "init_internally", "iomgr_port", @@ -2519,7 +2517,6 @@ grpc_cc_library( "event_engine_tcp_socket_utils", "event_engine_thread_pool", "event_engine_time_util", - "event_engine_trace", "//:debug_location", "//:event_engine_base_hdrs", "//:gpr", @@ -2547,7 +2544,6 @@ grpc_cc_library( "error", "event_engine_tcp_socket_utils", "event_engine_thread_pool", - "event_engine_trace", "status_helper", "windows_iocp", "//:debug_location", @@ -2578,7 +2574,6 @@ grpc_cc_library( "error", "event_engine_tcp_socket_utils", "event_engine_thread_pool", - "event_engine_trace", "windows_endpoint", "windows_iocp", "//:event_engine_base_hdrs", @@ -2611,7 +2606,6 @@ grpc_cc_library( "event_engine_common", "event_engine_tcp_socket_utils", "event_engine_thread_pool", - "event_engine_trace", "event_engine_utils", "init_internally", "posix_event_engine_closure", @@ -2657,22 +2651,6 @@ grpc_cc_library( ], ) -# TODO(hork): delete this target when refactoring to GRPC_TRACE_LOG(flag, level) -grpc_cc_library( - name = "event_engine_trace", - hdrs = [ - "lib/event_engine/trace.h", - ], - external_deps = [ - "absl/log:log", - ], - deps = [ - "//:gpr", - "//:gpr_platform", - "//:grpc_trace", - ], -) - grpc_cc_library( name = "event_engine_shim", srcs = [ @@ -2793,7 +2771,6 @@ grpc_cc_library( deps = [ "channel_args", "default_event_engine_factory", - "event_engine_trace", "no_destruct", "thready_event_engine", "//:config", diff --git a/src/core/lib/event_engine/cf_engine/cf_engine.cc b/src/core/lib/event_engine/cf_engine/cf_engine.cc index 83f4a57aca3..b7656dd771e 100644 --- a/src/core/lib/event_engine/cf_engine/cf_engine.cc +++ b/src/core/lib/event_engine/cf_engine/cf_engine.cc @@ -30,7 +30,6 @@ #include "src/core/lib/event_engine/posix_engine/timer_manager.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/thread_pool/thread_pool.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/utils.h" #include "src/core/lib/gprpp/crash.h" @@ -44,8 +43,8 @@ struct CFEventEngine::Closure final : public EventEngine::Closure { EventEngine::TaskHandle handle; void Run() override { - GRPC_EVENT_ENGINE_TRACE("CFEventEngine:%p executing callback:%s", engine, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "CFEventEngine:" << engine << " executing callback:" << handle; { grpc_core::MutexLock lock(&engine->task_mu_); engine->known_handles_.erase(handle); @@ -145,9 +144,8 @@ bool CFEventEngine::CancelConnectInternal(ConnectionHandle handle, grpc_core::MutexLock lock(&conn_mu_); if (!conn_handles_.contains(handle)) { - GRPC_EVENT_ENGINE_TRACE( - "Unknown connection handle: %s", - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "Unknown connection handle: " << handle; return false; } conn_handles_.erase(handle); @@ -210,8 +208,8 @@ EventEngine::TaskHandle CFEventEngine::RunAfterInternal( grpc_core::MutexLock lock(&task_mu_); known_handles_.insert(handle); cd->handle = handle; - GRPC_EVENT_ENGINE_TRACE("CFEventEngine:%p scheduling callback:%s", this, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "CFEventEngine:" << this << " scheduling callback:" << handle; timer_manager_.TimerInit(&cd->timer, when_ts, cd); return handle; } diff --git a/src/core/lib/event_engine/cf_engine/cfstream_endpoint.cc b/src/core/lib/event_engine/cf_engine/cfstream_endpoint.cc index a2307fe36f9..337a5bc5a2f 100644 --- a/src/core/lib/event_engine/cf_engine/cfstream_endpoint.cc +++ b/src/core/lib/event_engine/cf_engine/cfstream_endpoint.cc @@ -23,7 +23,6 @@ #include "absl/strings/str_format.h" #include "src/core/lib/event_engine/cf_engine/cfstream_endpoint.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/gprpp/strerror.h" namespace grpc_event_engine { @@ -68,9 +67,9 @@ absl::StatusOr CFReadStreamLocallAddress( } // namespace bool CFStreamEndpointImpl::CancelConnect(absl::Status status) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE( - "CFStreamEndpointImpl::CancelConnect: status: %s, this: %p", - status.ToString().c_str(), this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::CancelConnect: status: " << status + << ", this: " << this; return open_event_.SetShutdown(std::move(status)); } @@ -85,8 +84,8 @@ void CFStreamEndpointImpl::Connect( return; } - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStreamEndpointImpl::Connect: %s", - addr_uri.value().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::Connect: " << addr_uri.value(); peer_address_ = std::move(addr); auto host_port = ResolvedAddressToNormalizedString(peer_address_); @@ -96,8 +95,8 @@ void CFStreamEndpointImpl::Connect( } peer_address_string_ = host_port.value(); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE( - "CFStreamEndpointImpl::Connect, host_port: %s", host_port->c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::Connect, host_port: " << peer_address_string_; std::string host_string; std::string port_string; @@ -163,8 +162,9 @@ void CFStreamEndpointImpl::Connect( void* client_callback_info) { auto self = static_cast(client_callback_info); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE( - "CFStreamEndpointImpl::ReadCallback, type: %lu, this: %p", type, self); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::ReadCallback, type: " << type + << ", this: " << self; switch (type) { case kCFStreamEventOpenCompleted: @@ -177,8 +177,8 @@ void CFStreamEndpointImpl::Connect( break; case kCFStreamEventErrorOccurred: { auto status = CFErrorToStatus(CFReadStreamCopyError(stream)); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStream Read error: %s", - status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStream Read error: " << status; self->open_event_.SetShutdown(status); self->read_event_.SetShutdown(status); @@ -194,8 +194,9 @@ void CFStreamEndpointImpl::WriteCallback(CFWriteStreamRef stream, CFStreamEventType type, void* client_callback_info) { auto self = static_cast(client_callback_info); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE( - "CFStreamEndpointImpl::WriteCallback, type: %lu, this: %p", type, self); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::WriteCallback, type: " << type + << ", this: " << self; switch (type) { case kCFStreamEventOpenCompleted: @@ -208,8 +209,8 @@ void CFStreamEndpointImpl::WriteCallback(CFWriteStreamRef stream, break; case kCFStreamEventErrorOccurred: { auto status = CFErrorToStatus(CFWriteStreamCopyError(stream)); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStream Write error: %s", - status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStream Write error: " << status; self->open_event_.SetShutdown(status); self->read_event_.SetShutdown(status); @@ -239,8 +240,8 @@ CFStreamEndpointImpl::~CFStreamEndpointImpl() { } void CFStreamEndpointImpl::Shutdown() { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStreamEndpointImpl::Shutdown: this: %p", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::Shutdown: this: " << this; auto shutdownStatus = absl::Status(absl::StatusCode::kUnknown, @@ -259,8 +260,8 @@ void CFStreamEndpointImpl::Shutdown() { bool CFStreamEndpointImpl::Read( absl::AnyInvocable on_read, SliceBuffer* buffer, const EventEngine::Endpoint::ReadArgs* /* args */) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStreamEndpointImpl::Read, this: %p", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::Read, this: " << this; read_event_.NotifyOn(new PosixEngineClosure( [that = Ref(), on_read = std::move(on_read), @@ -278,8 +279,8 @@ bool CFStreamEndpointImpl::Read( void CFStreamEndpointImpl::DoRead( absl::AnyInvocable on_read, SliceBuffer* buffer) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStreamEndpointImpl::DoRead, this: %p", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::DoRead, this: " << this; auto buffer_index = buffer->AppendIndexed( Slice(memory_allocator_.MakeSlice(kDefaultReadBufferSize))); @@ -292,8 +293,8 @@ void CFStreamEndpointImpl::DoRead( if (read_size < 0) { auto status = CFErrorToStatus(CFReadStreamCopyError(cf_read_stream_)); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStream read error: %s, read_size: %ld", - status.ToString().c_str(), read_size); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStream read error: " << status << ", read_size: " << read_size; on_read(status); return; } @@ -305,8 +306,8 @@ void CFStreamEndpointImpl::DoRead( bool CFStreamEndpointImpl::Write( absl::AnyInvocable on_writable, SliceBuffer* data, const EventEngine::Endpoint::WriteArgs* /* args */) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStreamEndpointImpl::Write, this: %p", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::Write, this: " << this; write_event_.NotifyOn(new PosixEngineClosure( [that = Ref(), on_writable = std::move(on_writable), @@ -324,8 +325,8 @@ bool CFStreamEndpointImpl::Write( void CFStreamEndpointImpl::DoWrite( absl::AnyInvocable on_writable, SliceBuffer* data) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("CFStreamEndpointImpl::DoWrite, this: %p", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "CFStreamEndpointImpl::DoWrite, this: " << this; size_t total_written_size = 0; for (size_t i = 0; i < data->Count(); i++) { diff --git a/src/core/lib/event_engine/cf_engine/dns_service_resolver.cc b/src/core/lib/event_engine/cf_engine/dns_service_resolver.cc index 3a8ade4ed04..8c0cd0b694a 100644 --- a/src/core/lib/event_engine/cf_engine/dns_service_resolver.cc +++ b/src/core/lib/event_engine/cf_engine/dns_service_resolver.cc @@ -26,7 +26,6 @@ #include "src/core/lib/event_engine/cf_engine/dns_service_resolver.h" #include "src/core/lib/event_engine/posix_engine/lockfree_event.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/gprpp/host_port.h" namespace grpc_event_engine { diff --git a/src/core/lib/event_engine/default_event_engine.cc b/src/core/lib/event_engine/default_event_engine.cc index 743b788c72f..45520f581ed 100644 --- a/src/core/lib/event_engine/default_event_engine.cc +++ b/src/core/lib/event_engine/default_event_engine.cc @@ -26,7 +26,6 @@ #include "src/core/lib/config/core_configuration.h" #include "src/core/lib/debug/trace.h" #include "src/core/lib/event_engine/default_event_engine_factory.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/no_destruct.h" #include "src/core/lib/gprpp/sync.h" @@ -79,15 +78,15 @@ std::shared_ptr GetDefaultEventEngine( grpc_core::SourceLocation location) { grpc_core::MutexLock lock(&*g_mu); if (std::shared_ptr engine = g_event_engine->lock()) { - GRPC_EVENT_ENGINE_TRACE( - "Returning existing EventEngine::%p. use_count:%ld. Called from " - "[%s:%d]", - engine.get(), engine.use_count(), location.file(), location.line()); + GRPC_TRACE_LOG(event_engine, INFO) + << "Returning existing EventEngine::" << engine.get() + << ". use_count:" << engine.use_count() << ". Called from " << location; return engine; } std::shared_ptr engine{CreateEventEngine()}; - GRPC_EVENT_ENGINE_TRACE("Created DefaultEventEngine::%p. Called from [%s:%d]", - engine.get(), location.file(), location.line()); + GRPC_TRACE_LOG(event_engine, INFO) + << "Created DefaultEventEngine::" << engine.get() << ". Called from " + << location; *g_event_engine = engine; return engine; } diff --git a/src/core/lib/event_engine/posix_engine/posix_endpoint.cc b/src/core/lib/event_engine/posix_engine/posix_endpoint.cc index 708c8cee82b..d2b2b63a398 100644 --- a/src/core/lib/event_engine/posix_engine/posix_endpoint.cc +++ b/src/core/lib/event_engine/posix_engine/posix_endpoint.cc @@ -39,11 +39,11 @@ #include #include +#include "src/core/lib/debug/trace.h" #include "src/core/lib/event_engine/posix_engine/event_poller.h" #include "src/core/lib/event_engine/posix_engine/internal_errqueue.h" #include "src/core/lib/event_engine/posix_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/experiments/experiments.h" #include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/load_file.h" @@ -564,7 +564,8 @@ void PosixEndpointImpl::HandleRead(absl::Status status) { grpc_core::MutexLock lock(&read_mu_); ret = HandleReadLocked(status); if (ret) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Read complete", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Read complete"; cb = std::move(read_cb_); read_cb_ = nullptr; incoming_buffer_ = nullptr; @@ -582,7 +583,8 @@ bool PosixEndpointImpl::Read(absl::AnyInvocable on_read, SliceBuffer* buffer, const EventEngine::Endpoint::ReadArgs* args) { grpc_core::ReleasableMutexLock lock(&read_mu_); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Read", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Read"; CHECK(read_cb_ == nullptr); incoming_buffer_ = buffer; incoming_buffer_->Clear(); @@ -624,9 +626,8 @@ bool PosixEndpointImpl::Read(absl::AnyInvocable on_read, // asynchronously. lock.Release(); engine_->Run([on_read = std::move(on_read), status, this]() mutable { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE( - "Endpoint[%p]: Read failed immediately: %s", this, - status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Read failed immediately: " << status; on_read(status); }); Unref(); @@ -636,8 +637,8 @@ bool PosixEndpointImpl::Read(absl::AnyInvocable on_read, // callback. incoming_buffer_ = nullptr; Unref(); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Read succeeded immediately", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Read succeeded immediately"; return true; } return false; @@ -1111,8 +1112,8 @@ bool PosixEndpointImpl::TcpFlush(absl::Status& status) { void PosixEndpointImpl::HandleWrite(absl::Status status) { if (!status.ok()) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write failed: %s", this, - status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write failed: " << status; absl::AnyInvocable cb_ = std::move(write_cb_); write_cb_ = nullptr; if (current_zerocopy_send_ != nullptr) { @@ -1130,8 +1131,8 @@ void PosixEndpointImpl::HandleWrite(absl::Status status) { DCHECK(status.ok()); handle_->NotifyOnWrite(on_write_); } else { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write complete: %s", this, - status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write complete: " << status; absl::AnyInvocable cb_ = std::move(write_cb_); write_cb_ = nullptr; current_zerocopy_send_ = nullptr; @@ -1150,8 +1151,8 @@ bool PosixEndpointImpl::Write( DCHECK_EQ(current_zerocopy_send_, nullptr); DCHECK_NE(data, nullptr); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write %" PRIdPTR " bytes", - this, data->Length()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write " << data->Length() << " bytes"; if (data->Length() == 0) { TcpShutdownTracedBufferList(); @@ -1159,13 +1160,14 @@ bool PosixEndpointImpl::Write( status = TcpAnnotateError(absl::InternalError("EOF")); engine_->Run( [on_writable = std::move(on_writable), status, this]() mutable { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write failed: %s", - this, status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write failed: " << status; on_writable(status); }); return false; } - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write skipped", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write skipped"; return true; } @@ -1197,16 +1199,16 @@ bool PosixEndpointImpl::Write( // asynchronously. engine_->Run( [on_writable = std::move(on_writable), status, this]() mutable { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write failed: %s", - this, status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write failed: " << status; on_writable(status); }); return false; } // Write succeeded immediately. Return true and don't run the on_writable // callback. - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Endpoint[%p]: Write succeded immediately", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Endpoint[" << this << "]: Write succeded immediately"; return true; } diff --git a/src/core/lib/event_engine/posix_engine/posix_engine.cc b/src/core/lib/event_engine/posix_engine/posix_engine.cc index ac739083239..5f72d2b7b7e 100644 --- a/src/core/lib/event_engine/posix_engine/posix_engine.cc +++ b/src/core/lib/event_engine/posix_engine/posix_engine.cc @@ -50,7 +50,6 @@ #include "src/core/lib/event_engine/posix_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/posix_engine/timer.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/utils.h" #include "src/core/lib/gprpp/crash.h" #include "src/core/lib/gprpp/no_destruct.h" @@ -446,8 +445,8 @@ struct PosixEventEngine::ClosureData final : public EventEngine::Closure { EventEngine::TaskHandle handle; void Run() override { - GRPC_EVENT_ENGINE_TRACE("PosixEventEngine:%p executing callback:%s", engine, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "PosixEventEngine:" << engine << " executing callback:" << handle; { grpc_core::MutexLock lock(&engine->mu_); engine->known_handles_.erase(handle); @@ -523,8 +522,8 @@ EventEngine::TaskHandle PosixEventEngine::RunAfterInternal( grpc_core::MutexLock lock(&mu_); known_handles_.insert(handle); cd->handle = handle; - GRPC_EVENT_ENGINE_TRACE("PosixEventEngine:%p scheduling callback:%s", this, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "PosixEventEngine:" << this << " scheduling callback:" << handle; timer_manager_->TimerInit(&cd->timer, when_ts, cd); return handle; } diff --git a/src/core/lib/event_engine/posix_engine/posix_engine_listener.cc b/src/core/lib/event_engine/posix_engine/posix_engine_listener.cc index f81f57b5289..fcc98fe4c8f 100644 --- a/src/core/lib/event_engine/posix_engine/posix_engine_listener.cc +++ b/src/core/lib/event_engine/posix_engine/posix_engine_listener.cc @@ -40,12 +40,12 @@ #include #include +#include "src/core/lib/debug/trace.h" #include "src/core/lib/event_engine/posix_engine/event_poller.h" #include "src/core/lib/event_engine/posix_engine/posix_endpoint.h" #include "src/core/lib/event_engine/posix_engine/posix_engine_listener.h" #include "src/core/lib/event_engine/posix_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/gprpp/status_helper.h" #include "src/core/lib/gprpp/strerror.h" #include "src/core/lib/gprpp/time.h" @@ -127,8 +127,8 @@ void PosixEngineListenerImpl::AsyncConnectionAcceptor::Start() { void PosixEngineListenerImpl::AsyncConnectionAcceptor::NotifyOnAccept( absl::Status status) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("Acceptor[%p]: NotifyOnAccept: %s", this, - status.ToString().c_str()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "Acceptor[" << this << "]: NotifyOnAccept: " << status; if (!status.ok()) { // Shutting down the acceptor. Unref the ref grabbed in // AsyncConnectionAcceptor::Start(). diff --git a/src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.cc b/src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.cc index 0bc7e22ab11..83e4e406461 100644 --- a/src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.cc +++ b/src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.cc @@ -36,9 +36,9 @@ #include #include "src/core/lib/backoff/backoff.h" +#include "src/core/lib/debug/trace.h" #include "src/core/lib/event_engine/common_closures.h" #include "src/core/lib/event_engine/thread_local.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/work_queue/basic_work_queue.h" #include "src/core/lib/event_engine/work_queue/work_queue.h" #include "src/core/lib/gprpp/crash.h" @@ -174,8 +174,8 @@ thread_local WorkQueue* g_local_queue = nullptr; WorkStealingThreadPool::WorkStealingThreadPool(size_t reserve_threads) : pool_{std::make_shared(reserve_threads)} { if (g_log_verbose_failures) { - GRPC_EVENT_ENGINE_TRACE( - "%s", "WorkStealingThreadPool verbose failures are enabled"); + GRPC_TRACE_LOG(event_engine, INFO) + << "WorkStealingThreadPool verbose failures are enabled"; } pool_->Start(); } @@ -455,10 +455,9 @@ void WorkStealingThreadPool::WorkStealingThreadPoolImpl::Lifeguard:: // TODO(hork): new threads may spawn when there is no work in the global // queue, nor any work to steal. Add more sophisticated logic about when to // start a thread. - GRPC_EVENT_ENGINE_TRACE( - "Starting new ThreadPool thread due to backlog (total threads: %" PRIuPTR - ")", - living_thread_count + 1); + GRPC_TRACE_LOG(event_engine, INFO) + << "Starting new ThreadPool thread due to backlog (total threads: " + << living_thread_count + 1; pool_->StartThread(); // Tell the lifeguard to monitor the pool more closely. backoff_.Reset(); diff --git a/src/core/lib/event_engine/trace.h b/src/core/lib/event_engine/trace.h deleted file mode 100644 index 5b91ffb949e..00000000000 --- a/src/core/lib/event_engine/trace.h +++ /dev/null @@ -1,37 +0,0 @@ -// Copyright 2022 The gRPC Authors -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. -#ifndef GRPC_SRC_CORE_LIB_EVENT_ENGINE_TRACE_H -#define GRPC_SRC_CORE_LIB_EVENT_ENGINE_TRACE_H - -#include -#include - -#include "src/core/lib/debug/trace.h" - -#define GRPC_EVENT_ENGINE_TRACE(format, ...) \ - if (GRPC_TRACE_FLAG_ENABLED(event_engine)) { \ - gpr_log(GPR_ERROR, "(event_engine) " format, __VA_ARGS__); \ - } - -#define GRPC_EVENT_ENGINE_ENDPOINT_TRACE(format, ...) \ - if (GRPC_TRACE_FLAG_ENABLED(event_engine_endpoint)) { \ - gpr_log(GPR_ERROR, "(event_engine endpoint) " format, __VA_ARGS__); \ - } - -#define GRPC_EVENT_ENGINE_POLLER_TRACE(format, ...) \ - if (GRPC_TRACE_FLAG_ENABLED(event_engine_poller)) { \ - gpr_log(GPR_ERROR, "(event_engine poller) " format, __VA_ARGS__); \ - } - -#endif // GRPC_SRC_CORE_LIB_EVENT_ENGINE_TRACE_H diff --git a/src/core/lib/event_engine/windows/iocp.cc b/src/core/lib/event_engine/windows/iocp.cc index c3b9a37e87f..b81ec3dc500 100644 --- a/src/core/lib/event_engine/windows/iocp.cc +++ b/src/core/lib/event_engine/windows/iocp.cc @@ -25,7 +25,6 @@ #include "src/core/lib/event_engine/thread_pool/thread_pool.h" #include "src/core/lib/event_engine/time_util.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/windows/iocp.h" #include "src/core/lib/event_engine/windows/win_socket.h" #include "src/core/lib/gprpp/crash.h" @@ -60,9 +59,9 @@ std::unique_ptr IOCP::Watch(SOCKET socket) { } void IOCP::Shutdown() { - GRPC_EVENT_ENGINE_POLLER_TRACE( - "IOCP::%p shutting down. Outstanding kicks: %d", this, - outstanding_kicks_.load()); + GRPC_TRACE_LOG(event_engine_poller, INFO) + << "IOCP::" << this + << " shutting down. Outstanding kicks: " << outstanding_kicks_.load(); while (outstanding_kicks_.load() > 0) { Work(std::chrono::hours(42), []() {}); } @@ -74,18 +73,20 @@ Poller::WorkResult IOCP::Work(EventEngine::Duration timeout, DWORD bytes = 0; ULONG_PTR completion_key; LPOVERLAPPED overlapped; - GRPC_EVENT_ENGINE_POLLER_TRACE("IOCP::%p doing work", this); + GRPC_TRACE_LOG(event_engine_poller, INFO) + << "IOCP::" << this << " doing work"; BOOL success = GetQueuedCompletionStatus( iocp_handle_, &bytes, &completion_key, &overlapped, static_cast(Milliseconds(timeout))); if (success == 0 && overlapped == nullptr) { - GRPC_EVENT_ENGINE_POLLER_TRACE("IOCP::%p deadline exceeded", this); + GRPC_TRACE_LOG(event_engine_poller, INFO) + << "IOCP::" << this << " deadline exceeded"; return Poller::WorkResult::kDeadlineExceeded; } CHECK(completion_key); CHECK(overlapped); if (overlapped == &kick_overlap_) { - GRPC_EVENT_ENGINE_POLLER_TRACE("IOCP::%p kicked", this); + GRPC_TRACE_LOG(event_engine_poller, INFO) << "IOCP::" << this << " kicked"; outstanding_kicks_.fetch_sub(1); if (completion_key == (ULONG_PTR)&kick_token_) { return Poller::WorkResult::kKicked; @@ -93,8 +94,8 @@ Poller::WorkResult IOCP::Work(EventEngine::Duration timeout, grpc_core::Crash( absl::StrFormat("Unknown custom completion key: %lu", completion_key)); } - GRPC_EVENT_ENGINE_POLLER_TRACE("IOCP::%p got event on OVERLAPPED::%p", this, - overlapped); + GRPC_TRACE_LOG(event_engine_poller, INFO) + << "IOCP::" << this << " got event on OVERLAPPED::" << overlapped; // Safety note: socket is guaranteed to exist when managed by a // WindowsEndpoint. If an overlapped event came in, then either a read event // handler is registered, which keeps the socket alive, or the WindowsEndpoint diff --git a/src/core/lib/event_engine/windows/win_socket.cc b/src/core/lib/event_engine/windows/win_socket.cc index c5dc520cd7c..ef1a0f0e46a 100644 --- a/src/core/lib/event_engine/windows/win_socket.cc +++ b/src/core/lib/event_engine/windows/win_socket.cc @@ -22,7 +22,6 @@ #include "src/core/lib/event_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/thread_pool/thread_pool.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/windows/win_socket.h" #include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/sync.h" @@ -49,7 +48,8 @@ WinSocket::WinSocket(SOCKET socket, ThreadPool* thread_pool) noexcept WinSocket::~WinSocket() { CHECK(is_shutdown_.load()); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WinSocket::%p destroyed", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WinSocket::" << this << " destroyed"; } SOCKET WinSocket::raw_socket() { return socket_; } @@ -57,8 +57,8 @@ SOCKET WinSocket::raw_socket() { return socket_; } void WinSocket::Shutdown() { // if already shutdown, return early. Otherwise, set the shutdown flag. if (is_shutdown_.exchange(true)) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WinSocket::%p already shutting down", - this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WinSocket::" << this << " already shutting down"; return; } // Grab the function pointer for DisconnectEx for that specific socket. @@ -84,14 +84,15 @@ void WinSocket::Shutdown() { } } closesocket(socket_); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WinSocket::%p socket closed", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WinSocket::" << this << " socket closed"; } void WinSocket::Shutdown(const grpc_core::DebugLocation& location, absl::string_view reason) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE( - "WinSocket::%p Shut down from %s:%d. Reason: %s", this, location.file(), - location.line(), reason.data()); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WinSocket::" << this << " Shut down from " << location.file() << ":" + << location.line() << ". Reason: " << reason.data(); Shutdown(); } @@ -170,10 +171,11 @@ void WinSocket::OpState::GetOverlappedResult(SOCKET sock) { bool WinSocket::IsShutdown() { return is_shutdown_.load(); } WinSocket::OpState* WinSocket::GetOpInfoForOverlapped(OVERLAPPED* overlapped) { - GRPC_EVENT_ENGINE_POLLER_TRACE( - "WinSocket::%p looking for matching OVERLAPPED::%p. " - "read(%p) write(%p)", - this, overlapped, &read_info_.overlapped_, &write_info_.overlapped_); + GRPC_TRACE_LOG(event_engine_poller, INFO) + << "WinSocket::" << this + << " looking for matching OVERLAPPED::" << overlapped << ". read(" + << &read_info_.overlapped_ << ") write(" << &write_info_.overlapped_ + << ")"; if (overlapped == &read_info_.overlapped_) return &read_info_; if (overlapped == &write_info_.overlapped_) return &write_info_; return nullptr; diff --git a/src/core/lib/event_engine/windows/windows_endpoint.cc b/src/core/lib/event_engine/windows/windows_endpoint.cc index 9ace8ddccb5..ffd2abc3d06 100644 --- a/src/core/lib/event_engine/windows/windows_endpoint.cc +++ b/src/core/lib/event_engine/windows/windows_endpoint.cc @@ -26,7 +26,6 @@ #include "src/core/lib/event_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/thread_pool/thread_pool.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/windows/windows_endpoint.h" #include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/status_helper.h" @@ -74,11 +73,12 @@ WindowsEndpoint::WindowsEndpoint( WindowsEndpoint::~WindowsEndpoint() { io_state_->socket->Shutdown(DEBUG_LOCATION, "~WindowsEndpoint"); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("~WindowsEndpoint::%p", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) << "~WindowsEndpoint::" << this; } void WindowsEndpoint::AsyncIOState::DoTcpRead(SliceBuffer* buffer) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WindowsEndpoint::%p reading", endpoint); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WindowsEndpoint::" << endpoint << " reading"; if (socket->IsShutdown()) { socket->read_info()->SetErrorStatus( absl::InternalError("Socket is shutting down.")); @@ -148,7 +148,8 @@ bool WindowsEndpoint::Read(absl::AnyInvocable on_read, bool WindowsEndpoint::Write(absl::AnyInvocable on_writable, SliceBuffer* data, const WriteArgs* /* args */) { - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WindowsEndpoint::%p writing", this); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WindowsEndpoint::" << this << " writing"; if (io_state_->socket->IsShutdown()) { io_state_->thread_pool->Run( [on_writable = std::move(on_writable)]() mutable { @@ -278,8 +279,8 @@ void WindowsEndpoint::HandleReadClosure::Run() { // Deletes the shared_ptr when this closure returns // Note that the endpoint may have already been destroyed. auto io_state = std::move(io_state_); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WindowsEndpoint::%p Handling Read Event", - io_state->endpoint); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WindowsEndpoint::" << io_state->endpoint << " Handling Read Event"; const auto result = io_state->socket->read_info()->result(); if (!result.error_status.ok()) { buffer_->Clear(); @@ -339,8 +340,8 @@ void WindowsEndpoint::HandleReadClosure::DonateSpareSlices( void WindowsEndpoint::HandleWriteClosure::Run() { // Deletes the shared_ptr when this closure returns auto io_state = std::move(io_state_); - GRPC_EVENT_ENGINE_ENDPOINT_TRACE("WindowsEndpoint::%p Handling Write Event", - io_state->endpoint); + GRPC_TRACE_LOG(event_engine_endpoint, INFO) + << "WindowsEndpoint::" << io_state->endpoint << " Handling Write Event"; const auto result = io_state->socket->write_info()->result(); if (!result.error_status.ok()) { buffer_->Clear(); diff --git a/src/core/lib/event_engine/windows/windows_engine.cc b/src/core/lib/event_engine/windows/windows_engine.cc index 7d683d52691..28763382c22 100644 --- a/src/core/lib/event_engine/windows/windows_engine.cc +++ b/src/core/lib/event_engine/windows/windows_engine.cc @@ -36,7 +36,6 @@ #include "src/core/lib/event_engine/posix_engine/timer_manager.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" #include "src/core/lib/event_engine/thread_pool/thread_pool.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/utils.h" #include "src/core/lib/event_engine/windows/grpc_polled_fd_windows.h" #include "src/core/lib/event_engine/windows/iocp.h" @@ -190,9 +189,8 @@ struct WindowsEventEngine::TimerClosure final : public EventEngine::Closure { EventEngine::TaskHandle handle; void Run() override { - GRPC_EVENT_ENGINE_TRACE( - "WindowsEventEngine:%p executing callback:%s", engine, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "WindowsEventEngine:" << engine << " executing callback:" << handle; { grpc_core::MutexLock lock(&engine->task_mu_); engine->known_handles_.erase(handle); @@ -214,7 +212,7 @@ WindowsEventEngine::WindowsEventEngine() } WindowsEventEngine::~WindowsEventEngine() { - GRPC_EVENT_ENGINE_TRACE("~WindowsEventEngine::%p", this); + GRPC_TRACE_LOG(event_engine, INFO) << "~WindowsEventEngine::" << this; { task_mu_.Lock(); if (!known_handles_.empty()) { @@ -253,9 +251,8 @@ WindowsEventEngine::~WindowsEventEngine() { bool WindowsEventEngine::Cancel(EventEngine::TaskHandle handle) { grpc_core::MutexLock lock(&task_mu_); if (!known_handles_.contains(handle)) return false; - GRPC_EVENT_ENGINE_TRACE( - "WindowsEventEngine::%p cancelling %s", this, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "WindowsEventEngine::" << this << " cancelling " << handle; auto* cd = reinterpret_cast(handle.keys[0]); bool r = timer_manager_.TimerCancel(&cd->timer); known_handles_.erase(handle); @@ -292,9 +289,8 @@ EventEngine::TaskHandle WindowsEventEngine::RunAfterInternal( grpc_core::MutexLock lock(&task_mu_); known_handles_.insert(handle); cd->handle = handle; - GRPC_EVENT_ENGINE_TRACE( - "WindowsEventEngine:%p scheduling callback:%s", this, - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "WindowsEventEngine:" << this << " scheduling callback:" << handle; timer_manager_.TimerInit(&cd->timer, when_ts, cd); return handle; } @@ -360,8 +356,8 @@ void WindowsEventEngine::OnConnectCompleted( known_connection_handles_.erase(state->connection_handle()); } if (erased_handles != 1 || !Cancel(state->timer_handle())) { - GRPC_EVENT_ENGINE_TRACE( - "%s", "Not accepting connection since the deadline timer has fired"); + GRPC_TRACE_LOG(event_engine, INFO) + << "Not accepting connection since the deadline timer has fired"; return; } // Release refs held by the deadline timer. @@ -413,8 +409,8 @@ EventEngine::ConnectionHandle WindowsEventEngine::Connect( }); return EventEngine::ConnectionHandle::kInvalid; } - GRPC_EVENT_ENGINE_TRACE("EventEngine::%p connecting to %s", this, - uri->c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "EventEngine::" << this << " connecting to " << *uri; // Use dualstack sockets where available. ResolvedAddress address = addr; ResolvedAddress addr6_v4mapped; @@ -540,17 +536,16 @@ EventEngine::ConnectionHandle WindowsEventEngine::Connect( bool WindowsEventEngine::CancelConnect(EventEngine::ConnectionHandle handle) { if (handle == EventEngine::ConnectionHandle::kInvalid) { - GRPC_EVENT_ENGINE_TRACE("%s", - "Attempted to cancel an invalid connection handle"); + GRPC_TRACE_LOG(event_engine, INFO) + << "Attempted to cancel an invalid connection handle"; return false; } // Erase the connection handle, which may be unknown { grpc_core::MutexLock lock(&connection_mu_); if (known_connection_handles_.erase(handle) != 1) { - GRPC_EVENT_ENGINE_TRACE( - "Unknown connection handle: %s", - HandleToString(handle).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "Unknown connection handle: " << handle; return false; } } @@ -581,10 +576,8 @@ bool WindowsEventEngine::CancelConnectInternalStateLocked( ConnectionState* connection_state) { connection_state->socket()->Shutdown(DEBUG_LOCATION, "CancelConnect"); // Release the connection_state shared_ptr owned by the connected callback. - GRPC_EVENT_ENGINE_TRACE("Successfully cancelled connection %s", - HandleToString( - connection_state->connection_handle()) - .c_str()); + GRPC_TRACE_LOG(event_engine, INFO) << "Successfully cancelled connection " + << connection_state->connection_handle(); return true; } diff --git a/src/core/lib/event_engine/windows/windows_listener.cc b/src/core/lib/event_engine/windows/windows_listener.cc index 5a682fbcc8f..c04346fb9be 100644 --- a/src/core/lib/event_engine/windows/windows_listener.cc +++ b/src/core/lib/event_engine/windows/windows_listener.cc @@ -21,7 +21,6 @@ #include "absl/strings/str_format.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/event_engine/windows/iocp.h" #include "src/core/lib/event_engine/windows/win_socket.h" #include "src/core/lib/event_engine/windows/windows_endpoint.h" @@ -52,10 +51,9 @@ void WindowsEventEngineListener::SinglePortSocketListener:: CHECK_NE(io_state_, nullptr); grpc_core::ReleasableMutexLock lock(&io_state_->mu); if (io_state_->listener_socket->IsShutdown()) { - GRPC_EVENT_ENGINE_TRACE( - "SinglePortSocketListener::%p listener socket is shut down. Shutting " - "down listener.", - io_state_->port_listener); + GRPC_TRACE_LOG(event_engine, INFO) + << "SinglePortSocketListener::" << io_state_->port_listener + << " listener socket is shut down. Shutting down listener."; lock.Release(); io_state_.reset(); return; @@ -103,7 +101,7 @@ WindowsEventEngineListener::SinglePortSocketListener:: io_state_->listener_socket->Shutdown(DEBUG_LOCATION, "~SinglePortSocketListener"); UnlinkIfUnixDomainSocket(listener_sockname()); - GRPC_EVENT_ENGINE_TRACE("~SinglePortSocketListener::%p", this); + GRPC_TRACE_LOG(event_engine, INFO) << "~SinglePortSocketListener::" << this; } absl::StatusOr< @@ -179,9 +177,9 @@ WindowsEventEngineListener::SinglePortSocketListener::StartLocked() { } } io_state_->accept_socket = accept_socket; - GRPC_EVENT_ENGINE_TRACE( - "SinglePortSocketListener::%p listening. listener_socket::%p", this, - io_state_->listener_socket.get()); + GRPC_TRACE_LOG(event_engine, INFO) + << "SinglePortSocketListener::" << this + << " listening. listener_socket::" << io_state_->listener_socket.get(); return absl::OkStatus(); } @@ -311,8 +309,7 @@ WindowsEventEngineListener::WindowsEventEngineListener( on_shutdown_(std::move(on_shutdown)) {} WindowsEventEngineListener::~WindowsEventEngineListener() { - GRPC_EVENT_ENGINE_TRACE( - "%s", absl::StrFormat("~WindowsEventEngineListener::%p", this).c_str()); + GRPC_TRACE_LOG(event_engine, INFO) << "~WindowsEventEngineListener::" << this; ShutdownListeners(); on_shutdown_(absl::OkStatus()); } diff --git a/src/core/lib/gprpp/debug_location.h b/src/core/lib/gprpp/debug_location.h index 2637d316d10..89a948da7f6 100644 --- a/src/core/lib/gprpp/debug_location.h +++ b/src/core/lib/gprpp/debug_location.h @@ -21,6 +21,8 @@ #include +#include "absl/strings/str_cat.h" + #include #if defined(__has_builtin) @@ -56,6 +58,11 @@ class SourceLocation { int line_; }; +template +void AbslStringify(Sink& out, const SourceLocation& location) { + out.Append(absl::StrCat("[", location.file(), ":", location.line(), "]")); +} + // Used for tracking file and line where a call is made for debug builds. // No-op for non-debug builds. // Callers can use the DEBUG_LOCATION macro in either case. diff --git a/src/core/lib/iomgr/event_engine_shims/endpoint.cc b/src/core/lib/iomgr/event_engine_shims/endpoint.cc index f83db8ea877..0dfff51dd32 100644 --- a/src/core/lib/iomgr/event_engine_shims/endpoint.cc +++ b/src/core/lib/iomgr/event_engine_shims/endpoint.cc @@ -32,12 +32,11 @@ #include #include +#include "src/core/lib/debug/trace.h" #include "src/core/lib/event_engine/extensions/can_track_errors.h" #include "src/core/lib/event_engine/extensions/supports_fd.h" #include "src/core/lib/event_engine/query_extensions.h" -#include "src/core/lib/event_engine/shim.h" #include "src/core/lib/event_engine/tcp_socket_utils.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/gprpp/construct_destruct.h" #include "src/core/lib/gprpp/debug_location.h" #include "src/core/lib/gprpp/sync.h" @@ -353,7 +352,8 @@ void EndpointDestroy(grpc_endpoint* ep) { auto* eeep = reinterpret_cast( ep); - GRPC_EVENT_ENGINE_TRACE("EventEngine::Endpoint %p Destroy", eeep->wrapper); + GRPC_TRACE_LOG(event_engine, INFO) + << "EventEngine::Endpoint::" << eeep->wrapper << " EndpointDestroy"; eeep->wrapper->TriggerShutdown(nullptr); eeep->wrapper->Unref(); } @@ -411,7 +411,8 @@ EventEngineEndpointWrapper::EventEngineEndpointWrapper( } else { fd_ = -1; } - GRPC_EVENT_ENGINE_TRACE("EventEngine::Endpoint %p Create", eeep_->wrapper); + GRPC_TRACE_LOG(event_engine, INFO) + << "EventEngine::Endpoint " << eeep_->wrapper << " Create"; } } // namespace diff --git a/src/core/lib/iomgr/event_engine_shims/tcp_client.cc b/src/core/lib/iomgr/event_engine_shims/tcp_client.cc index 640b3efb289..2880415e192 100644 --- a/src/core/lib/iomgr/event_engine_shims/tcp_client.cc +++ b/src/core/lib/iomgr/event_engine_shims/tcp_client.cc @@ -15,17 +15,15 @@ #include "absl/status/status.h" #include "absl/status/statusor.h" -#include "absl/strings/str_cat.h" -#include "absl/strings/string_view.h" #include #include #include #include "src/core/lib/address_utils/sockaddr_utils.h" +#include "src/core/lib/debug/trace.h" #include "src/core/lib/event_engine/default_event_engine.h" #include "src/core/lib/event_engine/resolved_address_internal.h" -#include "src/core/lib/event_engine/trace.h" #include "src/core/lib/iomgr/closure.h" #include "src/core/lib/iomgr/endpoint.h" #include "src/core/lib/iomgr/error.h" @@ -64,8 +62,8 @@ int64_t event_engine_tcp_client_connect( } else { *endpoint = nullptr; } - GRPC_EVENT_ENGINE_TRACE("EventEngine::Connect Status: %s", - ep.status().ToString().c_str()); + GRPC_TRACE_LOG(event_engine, INFO) + << "EventEngine::Connect Status: " << ep.status(); grpc_core::ExecCtx::Run(DEBUG_LOCATION, on_connect, absl_status_to_grpc_error(conn_status)); }, @@ -75,15 +73,14 @@ int64_t event_engine_tcp_client_connect( : grpc_event_engine::experimental::MemoryAllocator(), std::max(grpc_core::Duration::Milliseconds(1), deadline - grpc_core::Timestamp::Now())); - GRPC_EVENT_ENGINE_TRACE("EventEngine::Connect Peer: %s, handle: %" PRId64, - (*addr_uri).c_str(), - static_cast(handle.keys[0])); + GRPC_TRACE_LOG(event_engine, INFO) + << "EventEngine::Connect Peer: " << *addr_uri << ", handle: " << handle; return handle.keys[0]; } bool event_engine_tcp_client_cancel_connect(int64_t connection_handle) { - GRPC_EVENT_ENGINE_TRACE("EventEngine::CancelConnect handle: %" PRId64, - connection_handle); + GRPC_TRACE_LOG(event_engine, INFO) + << "EventEngine::CancelConnect handle: " << connection_handle; return GetDefaultEventEngine()->CancelConnect( {static_cast(connection_handle), 0}); } diff --git a/tools/doxygen/Doxyfile.c++.internal b/tools/doxygen/Doxyfile.c++.internal index 29afe69ed0a..cf6eb657b4f 100644 --- a/tools/doxygen/Doxyfile.c++.internal +++ b/tools/doxygen/Doxyfile.c++.internal @@ -2227,7 +2227,6 @@ src/core/lib/event_engine/thready_event_engine/thready_event_engine.cc \ src/core/lib/event_engine/thready_event_engine/thready_event_engine.h \ src/core/lib/event_engine/time_util.cc \ src/core/lib/event_engine/time_util.h \ -src/core/lib/event_engine/trace.h \ src/core/lib/event_engine/utils.cc \ src/core/lib/event_engine/utils.h \ src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc \ diff --git a/tools/doxygen/Doxyfile.core.internal b/tools/doxygen/Doxyfile.core.internal index 021efd50be5..6b3601d8359 100644 --- a/tools/doxygen/Doxyfile.core.internal +++ b/tools/doxygen/Doxyfile.core.internal @@ -1996,7 +1996,6 @@ src/core/lib/event_engine/thready_event_engine/thready_event_engine.cc \ src/core/lib/event_engine/thready_event_engine/thready_event_engine.h \ src/core/lib/event_engine/time_util.cc \ src/core/lib/event_engine/time_util.h \ -src/core/lib/event_engine/trace.h \ src/core/lib/event_engine/utils.cc \ src/core/lib/event_engine/utils.h \ src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc \ diff --git a/tools/run_tests/sanity/banned_functions.py b/tools/run_tests/sanity/banned_functions.py index f849a645a7c..98321763486 100755 --- a/tools/run_tests/sanity/banned_functions.py +++ b/tools/run_tests/sanity/banned_functions.py @@ -101,7 +101,6 @@ BANNED_EXCEPT = { "./src/core/lib/event_engine/cf_engine/cf_engine.cc", "./src/core/lib/event_engine/posix_engine/posix_engine.cc", "./src/core/lib/event_engine/posix_engine/timer_manager.cc", - "./src/core/lib/event_engine/trace.h", "./src/core/lib/event_engine/windows/windows_endpoint.cc", "./src/core/lib/event_engine/windows/windows_engine.cc", "./src/core/lib/experiments/config.cc",