[tracing] Replace EE Trace macros with GRPC_TRACE_LOG (#36949)

Closes #36949

COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/36949 from drfloob:new-ee-trace 90a119e502
PiperOrigin-RevId: 644149042
dependabot/pip/urllib3-1.26.19
AJ Heller 9 months ago committed by Copybara-Service
parent f04eee5cae
commit 578b8fdb4d
  1. 2
      BUILD
  2. 1
      Package.swift
  3. 5
      build_autogenerated.yaml
  4. 2
      gRPC-C++.podspec
  5. 2
      gRPC-Core.podspec
  6. 1
      grpc.gemspec
  7. 1
      package.xml
  8. 35
      src/core/BUILD
  9. 14
      src/core/lib/event_engine/cf_engine/cf_engine.cc
  10. 57
      src/core/lib/event_engine/cf_engine/cfstream_endpoint.cc
  11. 1
      src/core/lib/event_engine/cf_engine/dns_service_resolver.cc
  12. 13
      src/core/lib/event_engine/default_event_engine.cc
  13. 44
      src/core/lib/event_engine/posix_engine/posix_endpoint.cc
  14. 9
      src/core/lib/event_engine/posix_engine/posix_engine.cc
  15. 6
      src/core/lib/event_engine/posix_engine/posix_engine_listener.cc
  16. 13
      src/core/lib/event_engine/thread_pool/work_stealing_thread_pool.cc
  17. 37
      src/core/lib/event_engine/trace.h
  18. 19
      src/core/lib/event_engine/windows/iocp.cc
  19. 26
      src/core/lib/event_engine/windows/win_socket.cc
  20. 17
      src/core/lib/event_engine/windows/windows_endpoint.cc
  21. 41
      src/core/lib/event_engine/windows/windows_engine.cc
  22. 19
      src/core/lib/event_engine/windows/windows_listener.cc
  23. 7
      src/core/lib/gprpp/debug_location.h
  24. 9
      src/core/lib/iomgr/event_engine_shims/endpoint.cc
  25. 17
      src/core/lib/iomgr/event_engine_shims/tcp_client.cc
  26. 1
      tools/doxygen/Doxyfile.c++.internal
  27. 1
      tools/doxygen/Doxyfile.core.internal
  28. 1
      tools/run_tests/sanity/banned_functions.py

@ -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"],

1
Package.swift generated

@ -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",

@ -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

2
gRPC-C++.podspec generated

@ -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',

2
gRPC-Core.podspec generated

@ -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',

1
grpc.gemspec generated

@ -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 )

1
package.xml generated

@ -1206,7 +1206,6 @@
<file baseinstalldir="/" name="src/core/lib/event_engine/thready_event_engine/thready_event_engine.h" role="src" />
<file baseinstalldir="/" name="src/core/lib/event_engine/time_util.cc" role="src" />
<file baseinstalldir="/" name="src/core/lib/event_engine/time_util.h" role="src" />
<file baseinstalldir="/" name="src/core/lib/event_engine/trace.h" role="src" />
<file baseinstalldir="/" name="src/core/lib/event_engine/utils.cc" role="src" />
<file baseinstalldir="/" name="src/core/lib/event_engine/utils.h" role="src" />
<file baseinstalldir="/" name="src/core/lib/event_engine/windows/grpc_polled_fd_windows.cc" role="src" />

@ -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",

@ -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<EventEngine::ConnectionHandle>(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;
}

@ -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<EventEngine::ResolvedAddress> 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<CFStreamEndpointImpl*>(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<CFStreamEndpointImpl*>(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<void(absl::Status)> 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<void(absl::Status)> 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<void(absl::Status)> 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<void(absl::Status)> 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++) {

@ -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 {

@ -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<EventEngine> GetDefaultEventEngine(
grpc_core::SourceLocation location) {
grpc_core::MutexLock lock(&*g_mu);
if (std::shared_ptr<EventEngine> 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<EventEngine> 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;
}

@ -39,11 +39,11 @@
#include <grpc/status.h>
#include <grpc/support/port_platform.h>
#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<void(absl::Status)> 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<void(absl::Status)> 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<void(absl::Status)> 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<void(absl::Status)> 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<void(absl::Status)> 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;
}

@ -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;
}

@ -40,12 +40,12 @@
#include <grpc/event_engine/event_engine.h>
#include <grpc/event_engine/memory_allocator.h>
#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().

@ -36,9 +36,9 @@
#include <grpc/support/thd_id.h>
#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<WorkStealingThreadPoolImpl>(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();

@ -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 <grpc/support/log.h>
#include <grpc/support/port_platform.h>
#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

@ -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<WinSocket> 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<DWORD>(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

@ -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;

@ -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<void(absl::Status)> on_read,
bool WindowsEndpoint::Write(absl::AnyInvocable<void(absl::Status)> 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();

@ -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<EventEngine::TaskHandle>(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<EventEngine::TaskHandle>(handle).c_str());
GRPC_TRACE_LOG(event_engine, INFO)
<< "WindowsEventEngine::" << this << " cancelling " << handle;
auto* cd = reinterpret_cast<TimerClosure*>(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<EventEngine::TaskHandle>(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<EventEngine::ConnectionHandle>(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<EventEngine::ConnectionHandle>(
connection_state->connection_handle())
.c_str());
GRPC_TRACE_LOG(event_engine, INFO) << "Successfully cancelled connection "
<< connection_state->connection_handle();
return true;
}

@ -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());
}

@ -21,6 +21,8 @@
#include <utility>
#include "absl/strings/str_cat.h"
#include <grpc/support/port_platform.h>
#if defined(__has_builtin)
@ -56,6 +58,11 @@ class SourceLocation {
int line_;
};
template <typename Sink>
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.

@ -32,12 +32,11 @@
#include <grpc/support/port_platform.h>
#include <grpc/support/time.h>
#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<EventEngineEndpointWrapper::grpc_event_engine_endpoint*>(
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

@ -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 <grpc/event_engine/event_engine.h>
#include <grpc/support/port_platform.h>
#include <grpc/support/time.h>
#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<int64_t>(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<intptr_t>(connection_handle), 0});
}

@ -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 \

@ -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 \

@ -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",

Loading…
Cancel
Save