[PATCH] D90654: [clangd] Add index server request logging
This revision was landed with ongoing or failed builds.
This revision was automatically updated to reflect the committed changes.
Closed by commit rG686d8a0911de: [clangd] Add index server request logging
(authored by sammccall).
Changed prior to commit:
https://reviews.llvm.org/D90654?vs=302423=304664#toc
Repository:
rG LLVM Github Monorepo
CHANGES SINCE LAST ACTION
https://reviews.llvm.org/D90654/new/
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,26 @@
+# 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: <<< FuzzyFindRequest
+# LOG-ALL: query: "gFoo"
+# LOG-ALL: >>> FuzzyFindReply
+# LOG-ALL: name: "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
@@ -28,6 +28,8 @@
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', default=[])
+ parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'), default=os.devnull)
args = parser.parse_args()
@@ -40,7 +42,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
@@ -53,7 +55,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:
print('Server initialization complete.', file=sys.stderr)
found_init_message = True
break
@@ -70,12 +75,14 @@
'--project-root=' + args.project_root, '--lit-test', '--sync'
],
stdin=in_file)
-
clangd_process.wait()
print(
'Clangd executed successfully, shutting down child processes.',
file=sys.stderr)
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 *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;
[PATCH] D90654: [clangd] Add index server request logging
sammccall marked 5 inline comments as done.
sammccall added a comment.
Oops, took a while to get back to this.
Planning to land this with some style unaddressed (%/S, --input-file) but
please do LMK if they're important and I'll fix.
Comment at: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py:31
+ parser.add_argument('--server-arg', action='append')
+ parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'),
default=os.devnull)
kbobyrev wrote:
> Why do we need `wb` here instead of `w`? I know that `subprocess.Popen`
> writes binary data but since we're writing actual text to file maybe we could
> convert to non-binary?
we're just redirecting data from one stream to another, I don't think there's
any reason to do character decoding+encoding on the way...
Comment at: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py:81
if __name__ == '__main__':
main()
kbobyrev wrote:
> this was `pipeline_helper.py` intended for `pipeline.test`, maybe we'll use
> it more so makes sense to rename it to just `helper.py` or somethting.
Agree - can do that as a followup.
Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:2
+# 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
kadircet wrote:
> nit: use `%/S` to not mix forward and backslashes.
Why do we want to avoid mixing them?
(This is copied from the other test which uses %S)
Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:3
+# 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
kadircet wrote:
> not sure if it is any easier, but it might make sense to just pass anything
> after `--` to server, rather than explicitly mentioning `--server-arg` before
> each one. I suppose we can also rename the script to `server_request_helper` ?
>
> This won't work if we decide to pass arbitrary client flags too though.
Yeah, there aren't a lot of these so i'd like it to be super-explicit for now.
Happy to change this if we end up with lots of tests passing various server
args (and few client args)
Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:5
+# 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
ArcsinX wrote:
> Maybe we can use `--input-file` option of FileCheck instead of `<` (the same
> for the next line)
Why would this be preferred? (`<` is roughly 5x more common in llvm/test and
clang/test - neither is used significantly in clang-tools-extra)
Repository:
rG LLVM Github Monorepo
CHANGES SINCE LAST ACTION
https://reviews.llvm.org/D90654/new/
https://reviews.llvm.org/D90654
___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
[PATCH] D90654: [clangd] Add index server request logging
ArcsinX added inline comments. Comment at: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py:43 args.index_file, args.project_root - ], + ] + args.server_arg, stderr=subprocess.PIPE) this breaks `remote-index/pipeline.test` test for me: ``` TypeError: can only concatenate list (not "NoneType") to list ``` Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:5 +# 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 Maybe we can use `--input-file` option of FileCheck instead of `<` (the same for the next line) Repository: rG LLVM Github Monorepo CHANGES SINCE LAST ACTION https://reviews.llvm.org/D90654/new/ https://reviews.llvm.org/D90654 ___ cfe-commits mailing list cfe-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
[PATCH] D90654: [clangd] Add index server request logging
kadircet added a comment. I wish there was an easy way to check redacted error logs too :/ Comment at: clang-tools-extra/clangd/index/remote/server/Server.cpp:335 return std::make_unique(OS, LogLevel); +llvm::errs() << "non redacted logger\n"; + } feels like this one, and the one below are residues? Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:2 +# 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 nit: use `%/S` to not mix forward and backslashes. Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:3 +# 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 not sure if it is any easier, but it might make sense to just pass anything after `--` to server, rather than explicitly mentioning `--server-arg` before each one. I suppose we can also rename the script to `server_request_helper` ? This won't work if we decide to pass arbitrary client flags too though. Comment at: clang-tools-extra/clangd/test/remote-index/public-log.test:6 +# 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 can you also add a check for TextProto printing ? I believe descriptor names should be enough. Repository: rG LLVM Github Monorepo CHANGES SINCE LAST ACTION https://reviews.llvm.org/D90654/new/ https://reviews.llvm.org/D90654 ___ cfe-commits mailing list cfe-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
[PATCH] D90654: [clangd] Add index server request logging
kbobyrev accepted this revision.
kbobyrev added inline comments.
This revision is now accepted and ready to land.
Comment at: clang-tools-extra/clangd/index/remote/server/Server.cpp:257
+
+ public:
+TextProto(const google::protobuf::Message ) : M(M) {}
nit: everything is public by default since it's `struct`, right? did you mean
to put `` behind `private`?
Comment at: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py:25
-
def main():
nit: PEP is against having <2 lines between functions :(
Comment at: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py:31
+ parser.add_argument('--server-arg', action='append')
+ parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'),
default=os.devnull)
Why do we need `wb` here instead of `w`? I know that `subprocess.Popen` writes
binary data but since we're writing actual text to file maybe we could convert
to non-binary?
Comment at: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py:81
if __name__ == '__main__':
main()
this was `pipeline_helper.py` intended for `pipeline.test`, maybe we'll use it
more so makes sense to rename it to just `helper.py` or somethting.
Repository:
rG LLVM Github Monorepo
CHANGES SINCE LAST ACTION
https://reviews.llvm.org/D90654/new/
https://reviews.llvm.org/D90654
___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
[PATCH] D90654: [clangd] Add index server request logging
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 *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
