sammccall created this revision.
sammccall added reviewers: kbobyrev, kadircet.
Herald added subscribers: cfe-commits, usaxena95, arphaman.
Herald added a project: clang.
sammccall requested review of this revision.
Herald added subscribers: MaskRay, ilya-biryukov.
- Add verbose logging of payloads
- Add public logging of request summaries
- fix non-logging of messages in request scopes (oops!)
- add test for public/non-public logging, extending pipeline_helper a bit.
We've accumulated quite a lot of duplication in the request handlers by now.
I should factor that out, but not in this patch...
Repository:
rG LLVM Github Monorepo
https://reviews.llvm.org/D90654
Files:
clang-tools-extra/clangd/index/remote/server/Server.cpp
clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
clang-tools-extra/clangd/test/remote-index/public-log.test
Index: clang-tools-extra/clangd/test/remote-index/public-log.test
===================================================================
--- /dev/null
+++ clang-tools-extra/clangd/test/remote-index/public-log.test
@@ -0,0 +1,24 @@
+# RUN: rm -rf %t
+# RUN: clangd-indexer %S/Inputs/Source.cpp > %t.idx
+# RUN: %python %S/pipeline_helper.py --input-file-name=%s --server-arg=--log=verbose --server-arg=-log-public --server-log=%t.public.log --project-root=%S --index-file=%t.idx > /dev/null
+# RUN: %python %S/pipeline_helper.py --input-file-name=%s --server-arg=--log=verbose --server-log=%t.log --project-root=%S --index-file=%t.idx > /dev/null
+# RUN: FileCheck --check-prefixes=LOG,LOG-PUBLIC %s < %t.public.log
+# RUN: FileCheck --check-prefixes=LOG,LOG-ALL %s < %t.log
+# REQUIRES: clangd-remote-index
+
+# LOG: Server listening on
+{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}}
+---
+# Verify that request and response bodies are included in the verbose logs,
+# but not when --log-public is on.
+# The request summary should be included in either case.
+{"jsonrpc":"2.0","id":1,"method":"workspace/symbol","params":{"query":"gFoo"}}
+# LOG-ALL: gFoo
+# LOG-ALL: getFoo
+# LOG-PUBLIC-NOT: gFoo
+# LOG-PUBLIC-NOT: getFoo
+# LOG: request v1/FuzzyFind => OK: 1 results in {{.*}}ms
+---
+{"jsonrpc":"2.0","id":4,"method":"shutdown"}
+---
+{"jsonrpc":"2.0","method":"exit"}
Index: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
===================================================================
--- clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
+++ clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
@@ -22,12 +22,13 @@
if server_process.poll() is None:
server_process.kill()
-
def main():
parser = argparse.ArgumentParser()
parser.add_argument('--input-file-name', required=True)
parser.add_argument('--project-root', required=True)
parser.add_argument('--index-file', required=True)
+ parser.add_argument('--server-arg', action='append')
+ parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'), default=os.devnull)
args = parser.parse_args()
@@ -39,7 +40,7 @@
index_server_process = subprocess.Popen([
'clangd-index-server', '--server-address=' + server_address,
args.index_file, args.project_root
- ],
+ ] + args.server_arg,
stderr=subprocess.PIPE)
# This will kill index_server_process if it hangs without printing init
@@ -52,7 +53,10 @@
# Wait for the server to warm-up.
found_init_message = False
while index_server_process.poll() is None:
- if b'Server listening' in index_server_process.stderr.readline():
+ line = index_server_process.stderr.readline()
+ args.server_log.write(line)
+ args.server_log.flush()
+ if b'Server listening' in line:
found_init_message = True
break
@@ -66,9 +70,11 @@
'--project-root=' + args.project_root, '--lit-test', '--sync'
],
stdin=in_file)
-
clangd_process.wait()
index_server_process.kill()
+ for line in index_server_process.stderr:
+ args.server_log.write(line)
+ args.server_log.flush()
if __name__ == '__main__':
Index: clang-tools-extra/clangd/index/remote/server/Server.cpp
===================================================================
--- clang-tools-extra/clangd/index/remote/server/Server.cpp
+++ clang-tools-extra/clangd/index/remote/server/Server.cpp
@@ -94,10 +94,14 @@
}
private:
+ using stopwatch = std::chrono::steady_clock;
+
grpc::Status Lookup(grpc::ServerContext *Context,
const LookupRequest *Request,
grpc::ServerWriter<LookupReply> *Reply) override {
- WithContextValue(CurrentRequest, Context);
+ auto StartTime = stopwatch::now();
+ WithContextValue WithRequestContext(CurrentRequest, Context);
+ logRequest(*Request);
trace::Span Tracer("LookupRequest");
auto Req = ProtobufMarshaller->fromProtobuf(Request);
if (!Req) {
@@ -116,21 +120,26 @@
}
LookupReply NextMessage;
*NextMessage.mutable_stream_result() = *SerializedItem;
+ logResponse(NextMessage);
Reply->Write(NextMessage);
++Sent;
});
LookupReply LastMessage;
LastMessage.mutable_final_result()->set_has_more(true);
+ logResponse(LastMessage);
Reply->Write(LastMessage);
SPAN_ATTACH(Tracer, "Sent", Sent);
SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+ logRequestSummary("v1/Lookup", Sent, StartTime);
return grpc::Status::OK;
}
grpc::Status FuzzyFind(grpc::ServerContext *Context,
const FuzzyFindRequest *Request,
grpc::ServerWriter<FuzzyFindReply> *Reply) override {
- WithContextValue(CurrentRequest, Context);
+ auto StartTime = stopwatch::now();
+ WithContextValue WithRequestContext(CurrentRequest, Context);
+ logRequest(*Request);
trace::Span Tracer("FuzzyFindRequest");
auto Req = ProtobufMarshaller->fromProtobuf(Request);
if (!Req) {
@@ -150,20 +159,25 @@
}
FuzzyFindReply NextMessage;
*NextMessage.mutable_stream_result() = *SerializedItem;
+ logResponse(NextMessage);
Reply->Write(NextMessage);
++Sent;
});
FuzzyFindReply LastMessage;
LastMessage.mutable_final_result()->set_has_more(HasMore);
+ logResponse(LastMessage);
Reply->Write(LastMessage);
SPAN_ATTACH(Tracer, "Sent", Sent);
SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+ logRequestSummary("v1/FuzzyFind", Sent, StartTime);
return grpc::Status::OK;
}
grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request,
grpc::ServerWriter<RefsReply> *Reply) override {
- WithContextValue(CurrentRequest, Context);
+ auto StartTime = stopwatch::now();
+ WithContextValue WithRequestContext(CurrentRequest, Context);
+ logRequest(*Request);
trace::Span Tracer("RefsRequest");
auto Req = ProtobufMarshaller->fromProtobuf(Request);
if (!Req) {
@@ -182,21 +196,26 @@
}
RefsReply NextMessage;
*NextMessage.mutable_stream_result() = *SerializedItem;
+ logResponse(NextMessage);
Reply->Write(NextMessage);
++Sent;
});
RefsReply LastMessage;
LastMessage.mutable_final_result()->set_has_more(HasMore);
+ logResponse(LastMessage);
Reply->Write(LastMessage);
SPAN_ATTACH(Tracer, "Sent", Sent);
SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+ logRequestSummary("v1/Refs", Sent, StartTime);
return grpc::Status::OK;
}
grpc::Status Relations(grpc::ServerContext *Context,
const RelationsRequest *Request,
grpc::ServerWriter<RelationsReply> *Reply) override {
- WithContextValue(CurrentRequest, Context);
+ auto StartTime = stopwatch::now();
+ WithContextValue WithRequestContext(CurrentRequest, Context);
+ logRequest(*Request);
trace::Span Tracer("RelationsRequest");
auto Req = ProtobufMarshaller->fromProtobuf(Request);
if (!Req) {
@@ -217,17 +236,47 @@
}
RelationsReply NextMessage;
*NextMessage.mutable_stream_result() = *SerializedItem;
+ logResponse(NextMessage);
Reply->Write(NextMessage);
++Sent;
});
RelationsReply LastMessage;
LastMessage.mutable_final_result()->set_has_more(true);
+ logResponse(LastMessage);
Reply->Write(LastMessage);
SPAN_ATTACH(Tracer, "Sent", Sent);
SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+ logRequestSummary("v1/Relations", Sent, StartTime);
return grpc::Status::OK;
}
+ // Proxy object to allow proto messages to be lazily serialized as text.
+ struct TextProto {
+ const google::protobuf::Message &M;
+
+ public:
+ TextProto(const google::protobuf::Message &M) : M(M) {}
+ friend llvm::raw_ostream &operator<<(llvm::raw_ostream &OS,
+ const TextProto &P) {
+ return OS << P.M.DebugString();
+ }
+ };
+
+ void logRequest(const google::protobuf::Message &M) {
+ vlog("<<< {0}\n{1}", M.GetDescriptor()->name(), TextProto(M));
+ }
+ void logResponse(const google::protobuf::Message &M) {
+ vlog(">>> {0}\n{1}", M.GetDescriptor()->name(), TextProto(M));
+ }
+ void logRequestSummary(llvm::StringLiteral RequestName, unsigned Sent,
+ stopwatch::time_point StartTime) {
+ auto Duration = stopwatch::now() - StartTime;
+ auto Millis =
+ std::chrono::duration_cast<std::chrono::milliseconds>(Duration).count();
+ log("[public] request {0} => OK: {1} results in {2}ms", RequestName, Sent,
+ Millis);
+ }
+
std::unique_ptr<Marshaller> ProtobufMarshaller;
clangd::SymbolIndex &Index;
};
@@ -281,8 +330,10 @@
}
std::unique_ptr<Logger> makeLogger(llvm::raw_ostream &OS) {
- if (!LogPublic)
+ if (!LogPublic) {
return std::make_unique<StreamLogger>(OS, LogLevel);
+ llvm::errs() << "non redacted logger\n";
+ }
// Redacted mode:
// - messages outside the scope of a request: log fully
// - messages tagged [public]: log fully
@@ -293,6 +344,8 @@
using StreamLogger::StreamLogger;
void log(Level L, const char *Fmt,
const llvm::formatv_object_base &Message) override {
+ llvm::errs() << "redactedlogger! "
+ << Context::current().get(CurrentRequest) << "\n";
if (Context::current().get(CurrentRequest) == nullptr ||
llvm::StringRef(Fmt).startswith("[public]"))
return StreamLogger::log(L, Fmt, Message);
_______________________________________________
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
