Skip to content

Commit ec86e43

Browse files
committed
Merge #220: Add log levels and advertise them to users via logging callback
515ce93 Logging: Pass LogData struct to logging callback (Cory Fields) 213574c Logging: reclassify remaining log messages (Cory Fields) e4de041 Logging: Break out expensive log messages and classify them as Trace (Cory Fields) 408874a Logging: Use new logging macros (Cory Fields) 67b092d Logging: Disable logging if messsage level is less than the requested level (Cory Fields) d0a1ba7 Logging: add log levels to mirror Core's (Cory Fields) 463a829 Logging: Disable moving or copying Logger (Cory Fields) 83a2e10 Logging: Add an EventLoop constructor to allow for user-specified log options (Cory Fields) Pull request description: Fixes #215. Alternative to #216. This is is implemented roughly as suggested [here](#216 (comment)): - Adds log levels. - Adds an additional "Raise" log level. - Uses the 'Trace' level by default, so existing behavior is unchanged. - Remains backwards-compatible via a new (deprecated) EventLoop constructor. Users should not observe any behavioral difference. However, they can now change the log level (using the `EventLoop` constructor which takes a `LogOptions`) to set a lower level. Once merged, Core should take advantage of the new functionality: - Update the callback function signature. - Set the requested log level. - Map mp log levels to Core ones inside the callback. ACKs for top commit: ryanofsky: Code review ACK 515ce93. Just rebased and fixed compile error caused by new log print since last review Tree-SHA512: 835f83f714d9bcff92ad480b53e65b929812e521c750a80dea0c42e88c4540bf514a70439b57ada47c2c26e24fd57e15a0a7c336e5c0cd10fe1b78d74f54f056
2 parents 58cf47a + 515ce93 commit ec86e43

File tree

8 files changed

+114
-61
lines changed

8 files changed

+114
-61
lines changed

example/calculator.cpp

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
#include <charconv>
1010
#include <cstring>
1111
#include <fstream>
12+
#include <functional>
1213
#include <iostream>
1314
#include <kj/async.h>
1415
#include <kj/common.h>
@@ -37,6 +38,7 @@ class InitImpl : public Init
3738
}
3839
};
3940

41+
// Exercises deprecated log callback signature
4042
static void LogPrint(bool raise, const std::string& message)
4143
{
4244
if (raise) throw std::runtime_error(message);

example/example.cpp

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -35,10 +35,10 @@ static auto Spawn(mp::EventLoop& loop, const std::string& process_argv0, const s
3535
return std::make_tuple(mp::ConnectStream<InitInterface>(loop, fd), pid);
3636
}
3737

38-
static void LogPrint(bool raise, const std::string& message)
38+
static void LogPrint(mp::LogMessage log_data)
3939
{
40-
if (raise) throw std::runtime_error(message);
41-
std::ofstream("debug.log", std::ios_base::app) << message << std::endl;
40+
if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message);
41+
std::ofstream("debug.log", std::ios_base::app) << log_data.message << std::endl;
4242
}
4343

4444
int main(int argc, char** argv)

example/printer.cpp

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -32,10 +32,10 @@ class InitImpl : public Init
3232
std::unique_ptr<Printer> makePrinter() override { return std::make_unique<PrinterImpl>(); }
3333
};
3434

35-
static void LogPrint(bool raise, const std::string& message)
35+
static void LogPrint(mp::LogMessage log_data)
3636
{
37-
if (raise) throw std::runtime_error(message);
38-
std::ofstream("debug.log", std::ios_base::app) << message << std::endl;
37+
if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message);
38+
std::ofstream("debug.log", std::ios_base::app) << log_data.message << std::endl;
3939
}
4040

4141
int main(int argc, char** argv)

include/mp/proxy-io.h

Lines changed: 72 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -98,22 +98,59 @@ class LoggingErrorHandler : public kj::TaskSet::ErrorHandler
9898
EventLoop& m_loop;
9999
};
100100

101-
using LogFn = std::function<void(bool raise, std::string message)>;
101+
enum class Log {
102+
Trace = 0,
103+
Debug,
104+
Info,
105+
Warning,
106+
Error,
107+
Raise,
108+
};
109+
110+
struct LogMessage {
111+
112+
//! Message to be logged
113+
std::string message;
114+
115+
//! The severity level of this message
116+
Log level;
117+
};
118+
119+
using LogFn = std::function<void(LogMessage)>;
120+
121+
struct LogOptions {
122+
123+
//! External logging callback.
124+
LogFn log_fn;
125+
126+
//! Maximum number of characters to use when representing
127+
//! request and response structs as strings.
128+
size_t max_chars{200};
129+
130+
//! Messages with a severity level less than log_level will not be
131+
//! reported.
132+
Log log_level{Log::Trace};
133+
};
102134

103135
class Logger
104136
{
105137
public:
106-
Logger(bool raise, LogFn& fn) : m_raise(raise), m_fn(fn) {}
107-
Logger(Logger&& logger) : m_raise(logger.m_raise), m_fn(logger.m_fn), m_buffer(std::move(logger.m_buffer)) {}
138+
Logger(const LogOptions& options, Log log_level) : m_options(options), m_log_level(log_level) {}
139+
140+
Logger(Logger&&) = delete;
141+
Logger& operator=(Logger&&) = delete;
142+
Logger(const Logger&) = delete;
143+
Logger& operator=(const Logger&) = delete;
144+
108145
~Logger() noexcept(false)
109146
{
110-
if (m_fn) m_fn(m_raise, m_buffer.str());
147+
if (enabled()) m_options.log_fn({std::move(m_buffer).str(), m_log_level});
111148
}
112149

113150
template <typename T>
114151
friend Logger& operator<<(Logger& logger, T&& value)
115152
{
116-
if (logger.m_fn) logger.m_buffer << std::forward<T>(value);
153+
if (logger.enabled()) logger.m_buffer << std::forward<T>(value);
117154
return logger;
118155
}
119156

@@ -123,20 +160,25 @@ class Logger
123160
return logger << std::forward<T>(value);
124161
}
125162

126-
bool m_raise;
127-
LogFn& m_fn;
163+
explicit operator bool() const
164+
{
165+
return enabled();
166+
}
167+
168+
private:
169+
bool enabled() const
170+
{
171+
return m_options.log_fn && m_log_level >= m_options.log_level;
172+
}
173+
174+
const LogOptions& m_options;
175+
Log m_log_level;
128176
std::ostringstream m_buffer;
129177
};
130178

131-
struct LogOptions {
179+
#define MP_LOGPLAIN(loop, ...) if (mp::Logger logger{(loop).m_log_opts, __VA_ARGS__}; logger) logger
132180

133-
//! External logging callback.
134-
LogFn log_fn;
135-
136-
//! Maximum number of characters to use when representing
137-
//! request and response structs as strings.
138-
size_t max_chars{200};
139-
};
181+
#define MP_LOG(loop, ...) MP_LOGPLAIN(loop, __VA_ARGS__) << "{" << LongThreadName((loop).m_exe_name) << "} "
140182

141183
std::string LongThreadName(const char* exe_name);
142184

@@ -168,8 +210,19 @@ std::string LongThreadName(const char* exe_name);
168210
class EventLoop
169211
{
170212
public:
171-
//! Construct event loop object.
172-
EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr);
213+
//! Construct event loop object with default logging options.
214+
EventLoop(const char* exe_name, LogFn log_fn, void* context = nullptr)
215+
: EventLoop(exe_name, LogOptions{std::move(log_fn)}, context){}
216+
217+
//! Construct event loop object with specified logging options.
218+
EventLoop(const char* exe_name, LogOptions log_opts, void* context = nullptr);
219+
220+
//! Backwards-compatible constructor for previous (deprecated) logging callback signature
221+
EventLoop(const char* exe_name, std::function<void(bool, std::string)> old_callback, void* context = nullptr)
222+
: EventLoop(exe_name,
223+
LogFn{[old_callback = std::move(old_callback)](LogMessage log_data) {old_callback(log_data.level == Log::Raise, std::move(log_data.message));}},
224+
context){}
225+
173226
~EventLoop();
174227

175228
//! Run event loop. Does not return until shutdown. This should only be
@@ -210,15 +263,6 @@ class EventLoop
210263
//! Check if loop should exit.
211264
bool done() const MP_REQUIRES(m_mutex);
212265

213-
Logger log()
214-
{
215-
Logger logger(false, m_log_opts.log_fn);
216-
logger << "{" << LongThreadName(m_exe_name) << "} ";
217-
return logger;
218-
}
219-
Logger logPlain() { return {false, m_log_opts.log_fn}; }
220-
Logger raise() { return {true, m_log_opts.log_fn}; }
221-
222266
//! Process name included in thread names so combined debug output from
223267
//! multiple processes is easier to understand.
224268
const char* m_exe_name;
@@ -643,7 +687,7 @@ std::unique_ptr<ProxyClient<InitInterface>> ConnectStream(EventLoop& loop, int f
643687
init_client = connection->m_rpc_system->bootstrap(ServerVatId().vat_id).castAs<InitInterface>();
644688
Connection* connection_ptr = connection.get();
645689
connection->onDisconnect([&loop, connection_ptr] {
646-
loop.log() << "IPC client: unexpected network disconnect.";
690+
MP_LOG(loop, Log::Warning) << "IPC client: unexpected network disconnect.";
647691
delete connection_ptr;
648692
});
649693
});
@@ -666,7 +710,7 @@ void _Serve(EventLoop& loop, kj::Own<kj::AsyncIoStream>&& stream, InitImpl& init
666710
});
667711
auto it = loop.m_incoming_connections.begin();
668712
it->onDisconnect([&loop, it] {
669-
loop.log() << "IPC server: socket disconnected.";
713+
MP_LOG(loop, Log::Info) << "IPC server: socket disconnected.";
670714
loop.m_incoming_connections.erase(it);
671715
});
672716
}

include/mp/proxy-types.h

Lines changed: 23 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -568,7 +568,7 @@ template <typename Client>
568568
void clientDestroy(Client& client)
569569
{
570570
if (client.m_context.connection) {
571-
client.m_context.loop->log() << "IPC client destroy " << typeid(client).name();
571+
MP_LOG(*client.m_context.loop, Log::Info) << "IPC client destroy " << typeid(client).name();
572572
} else {
573573
KJ_LOG(INFO, "IPC interrupted client destroy", typeid(client).name());
574574
}
@@ -577,7 +577,7 @@ void clientDestroy(Client& client)
577577
template <typename Server>
578578
void serverDestroy(Server& server)
579579
{
580-
server.m_context.loop->log() << "IPC server destroy " << typeid(server).name();
580+
MP_LOG(*server.m_context.loop, Log::Info) << "IPC server destroy " << typeid(server).name();
581581
}
582582

583583
//! Entry point called by generated client code that looks like:
@@ -605,7 +605,7 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel
605605
// declaration so the server method runs in a dedicated thread.
606606
assert(!g_thread_context.loop_thread);
607607
g_thread_context.waiter = std::make_unique<Waiter>();
608-
proxy_client.m_context.loop->logPlain()
608+
MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info)
609609
<< "{" << g_thread_context.thread_name
610610
<< "} IPC client first request from current thread, constructing waiter";
611611
}
@@ -629,15 +629,19 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel
629629
using FieldList = typename ProxyClientMethodTraits<typename Request::Params>::Fields;
630630
invoke_context.emplace(*proxy_client.m_context.connection, thread_context);
631631
IterateFields().handleChain(*invoke_context, request, FieldList(), typename FieldObjs::BuildParams{&fields}...);
632-
proxy_client.m_context.loop->logPlain()
632+
MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Debug)
633633
<< "{" << thread_context.thread_name << "} IPC client send "
634-
<< TypeName<typename Request::Params>() << " " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
634+
<< TypeName<typename Request::Params>();
635+
MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Trace)
636+
<< "send data: " << LogEscape(request.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
635637

636638
proxy_client.m_context.loop->m_task_set->add(request.send().then(
637639
[&](::capnp::Response<typename Request::Results>&& response) {
638-
proxy_client.m_context.loop->logPlain()
640+
MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Debug)
639641
<< "{" << thread_context.thread_name << "} IPC client recv "
640-
<< TypeName<typename Request::Results>() << " " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
642+
<< TypeName<typename Request::Results>();
643+
MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Trace)
644+
<< "recv data: " << LogEscape(response.toString(), proxy_client.m_context.loop->m_log_opts.max_chars);
641645
try {
642646
IterateFields().handleChain(
643647
*invoke_context, response, FieldList(), typename FieldObjs::ReadResults{&fields}...);
@@ -653,7 +657,7 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel
653657
disconnected = "IPC client method call interrupted by disconnect.";
654658
} else {
655659
kj_exception = kj::str("kj::Exception: ", e).cStr();
656-
proxy_client.m_context.loop->logPlain()
660+
MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Info)
657661
<< "{" << thread_context.thread_name << "} IPC client exception " << kj_exception;
658662
}
659663
const Lock lock(thread_context.waiter->m_mutex);
@@ -665,8 +669,8 @@ void clientInvoke(ProxyClient& proxy_client, const GetRequest& get_request, Fiel
665669
Lock lock(thread_context.waiter->m_mutex);
666670
thread_context.waiter->wait(lock, [&done]() { return done; });
667671
if (exception) std::rethrow_exception(exception);
668-
if (!kj_exception.empty()) proxy_client.m_context.loop->raise() << kj_exception;
669-
if (disconnected) proxy_client.m_context.loop->raise() << disconnected;
672+
if (!kj_exception.empty()) MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Raise) << kj_exception;
673+
if (disconnected) MP_LOGPLAIN(*proxy_client.m_context.loop, Log::Raise) << disconnected;
670674
}
671675

672676
//! Invoke callable `fn()` that may return void. If it does return void, replace
@@ -700,8 +704,10 @@ kj::Promise<void> serverInvoke(Server& server, CallContext& call_context, Fn fn)
700704
using Results = typename decltype(call_context.getResults())::Builds;
701705

702706
int req = ++server_reqs;
703-
server.m_context.loop->log() << "IPC server recv request #" << req << " "
704-
<< TypeName<typename Params::Reads>() << " " << LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars);
707+
MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server recv request #" << req << " "
708+
<< TypeName<typename Params::Reads>();
709+
MP_LOG(*server.m_context.loop, Log::Trace) << "request data: "
710+
<< LogEscape(params.toString(), server.m_context.loop->m_log_opts.max_chars);
705711

706712
try {
707713
using ServerContext = ServerInvokeContext<Server, CallContext>;
@@ -717,14 +723,15 @@ kj::Promise<void> serverInvoke(Server& server, CallContext& call_context, Fn fn)
717723
return ReplaceVoid([&]() { return fn.invoke(server_context, ArgList()); },
718724
[&]() { return kj::Promise<CallContext>(kj::mv(call_context)); })
719725
.then([&server, req](CallContext call_context) {
720-
server.m_context.loop->log() << "IPC server send response #" << req << " " << TypeName<Results>()
721-
<< " " << LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars);
726+
MP_LOG(*server.m_context.loop, Log::Debug) << "IPC server send response #" << req << " " << TypeName<Results>();
727+
MP_LOG(*server.m_context.loop, Log::Trace) << "response data: "
728+
<< LogEscape(call_context.getResults().toString(), server.m_context.loop->m_log_opts.max_chars);
722729
});
723730
} catch (const std::exception& e) {
724-
server.m_context.loop->log() << "IPC server unhandled exception: " << e.what();
731+
MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception: " << e.what();
725732
throw;
726733
} catch (...) {
727-
server.m_context.loop->log() << "IPC server unhandled exception";
734+
MP_LOG(*server.m_context.loop, Log::Error) << "IPC server unhandled exception";
728735
throw;
729736
}
730737
}

include/mp/type-context.h

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -150,16 +150,16 @@ auto PassField(Priority<1>, TypeList<>, ServerContext& server_context, const Fn&
150150
// thread.
151151
KJ_IF_MAYBE (thread_server, perhaps) {
152152
const auto& thread = static_cast<ProxyServer<Thread>&>(*thread_server);
153-
server.m_context.loop->log()
153+
MP_LOG(*server.m_context.loop, Log::Debug)
154154
<< "IPC server post request #" << req << " {" << thread.m_thread_context.thread_name << "}";
155155
if (!thread.m_thread_context.waiter->post(std::move(invoke))) {
156-
server.m_context.loop->log()
156+
MP_LOG(*server.m_context.loop, Log::Error)
157157
<< "IPC server error request #" << req
158158
<< " {" << thread.m_thread_context.thread_name << "}" << ", thread busy";
159159
throw std::runtime_error("thread busy");
160160
}
161161
} else {
162-
server.m_context.loop->log()
162+
MP_LOG(*server.m_context.loop, Log::Error)
163163
<< "IPC server error request #" << req << ", missing thread to execute request";
164164
throw std::runtime_error("invalid thread handle");
165165
}

src/mp/proxy.cpp

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ thread_local ThreadContext g_thread_context;
4242
void LoggingErrorHandler::taskFailed(kj::Exception&& exception)
4343
{
4444
KJ_LOG(ERROR, "Uncaught exception in daemonized task.", exception);
45-
m_loop.log() << "Uncaught exception in daemonized task.";
45+
MP_LOG(m_loop, Log::Error) << "Uncaught exception in daemonized task.";
4646
}
4747

4848
EventLoopRef::EventLoopRef(EventLoop& loop, Lock* lock) : m_loop(&loop), m_lock(lock)
@@ -191,13 +191,13 @@ void EventLoop::addAsyncCleanup(std::function<void()> fn)
191191
startAsyncThread();
192192
}
193193

194-
EventLoop::EventLoop(const char* exe_name, LogFn log_fn, void* context)
194+
EventLoop::EventLoop(const char* exe_name, LogOptions log_opts, void* context)
195195
: m_exe_name(exe_name),
196196
m_io_context(kj::setupAsyncIo()),
197197
m_task_set(new kj::TaskSet(m_error_handler)),
198+
m_log_opts(std::move(log_opts)),
198199
m_context(context)
199200
{
200-
m_log_opts.log_fn = log_fn;
201201
int fds[2];
202202
KJ_SYSCALL(socketpair(AF_UNIX, SOCK_STREAM, 0, fds));
203203
m_wait_fd = fds[0];
@@ -251,9 +251,9 @@ void EventLoop::loop()
251251
break;
252252
}
253253
}
254-
log() << "EventLoop::loop done, cancelling event listeners.";
254+
MP_LOG(*this, Log::Info) << "EventLoop::loop done, cancelling event listeners.";
255255
m_task_set.reset();
256-
log() << "EventLoop::loop bye.";
256+
MP_LOG(*this, Log::Info) << "EventLoop::loop bye.";
257257
wait_stream = nullptr;
258258
KJ_SYSCALL(::close(post_fd));
259259
const Lock lock(m_mutex);

test/mp/test/test.cpp

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -67,9 +67,9 @@ class TestSetup
6767

6868
TestSetup(bool client_owns_connection = true)
6969
: thread{[&] {
70-
EventLoop loop("mptest", [](bool raise, const std::string& log) {
71-
std::cout << "LOG" << raise << ": " << log << "\n";
72-
if (raise) throw std::runtime_error(log);
70+
EventLoop loop("mptest", [](mp::LogMessage log_data) {
71+
std::cout << "LOG" << (int)log_data.level << ": " << log_data.message << "\n";
72+
if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message);
7373
});
7474
auto pipe = loop.m_io_context.provider->newTwoWayPipe();
7575

0 commit comments

Comments
 (0)