Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Verify format specifiers in bpf_trace_printk in rewriter #1046

Merged
merged 1 commit into from
Mar 23, 2017

Conversation

pchaigno
Copy link
Contributor

@pchaigno pchaigno commented Mar 12, 2017

Verifies format specifiers while rewriting calls to bpf_trace_printk
and prints a warning the printk will be rejected by the kernel at
runtime.

For tests, redirects stderr at the file descriptor level in order to
catch warnings from the C library.

Fixes #124.

/cc @drzaeus77

I noticed the kernel doesn't check that the number of format
specifiers equals the number of arguments. Is that normal?
(CAP_SYS_ADMIN is required to call bpf_trace_printk, but it still
feels weird.)

Copy link
Collaborator

@drzaeus77 drzaeus77 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Overall looks ok.
[buildbot, test this please]

@@ -523,6 +524,54 @@ bool BTypeVisitor::VisitCallExpr(CallExpr *Call) {
return true;
}

bool BTypeVisitor::checkFormatSpecifiers(string fmt, SourceLocation loc) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not const string& to avoid copy?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed.

}
if (fmt[i] != '%')
continue;
if (nb_specifiers >= 3) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems like printing literal "%%" isn't supported here or in the kernel. Is that the right interpretation?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes. @4ast Is that on purpose?

@drzaeus77
Copy link
Collaborator

Buildbot, you're not listening!
[buildbot, test this please]

@drzaeus77
Copy link
Collaborator

Build failed legitimately on fedora it seems. Failed in py_test_clang with:

17: .../virtual/main.c:4:15: error: internal error: opLoc is invalid while preparing probe rewrite
17:     void *p = page->mapping;
17:               ^
17: 1 error generated.
17: .../virtual/main.c:1:30: error: expected expression

@pchaigno
Copy link
Contributor Author

The three errors are expected (see the Ubuntu builds), but we get a segfault afterwards:

17: Ran 32 tests in 14.410s
17: 
17: OK
17: 0
17: /home/fedora/jenkins/workspace/bcc-pr/label/fc25/build/tests/wrapper.sh: line 38:  1219 Segmentation fault      sudo bash -c "PYTHONPATH=$PYTHONPATH LD_LIBRARY_PATH=$LD_LIBRARY_PATH $cmd $1 $2"
17: Failed

I'll have to start a Fedora to check it out.

@goldshtn
Copy link
Collaborator

@pchaigno Have you had any luck reproducing the build issue?

@pchaigno
Copy link
Contributor Author

@goldshtn Yes, I'm able to reproduce. It doesn't look related to the changes I made though, since I'm able to reproduce by copying the new tests on the master branch. Weirdly, if I replace:

bpf_trace_printk("%0.2f\\n", 1.0);

with

bpf_trace_printk("%0.2f\\n", 1);

the segfault disappears...
I'm not sure how to interpret that, or the fact that it only fails on Fedora (yet consistently).

I'm trying to get more information, but my day job doesn't leave me much free time. I'd appreciate any help :-)

@goldshtn
Copy link
Collaborator

Yup, I can confirm that just an empty script that uses bpf_trace_printk("%0.2f\n", 1.0); causes a segfault when the program is exiting. This is the backtrace -- I haven't dug in yet, but it looks like a memory corruption of some sort:

Program received signal SIGSEGV, Segmentation fault.
0x00007fffeed87dfc in void llvm::DeleteContainerSeconds<llvm::DenseMap<llvm::APFloat, llvm::ConstantFP*, llvm::DenseMapAPFloatKeyInfo, llvm::detail::DenseMapPair<llvm::APFloat, llvm::ConstantFP*> > >(llvm::DenseMap<llvm::APFloat, llvm::ConstantFP*, llvm::DenseMapAPFloatKeyInfo, llvm::detail::DenseMapPair<llvm::APFloat, llvm::ConstantFP*> >&) () from /lib64/libbcc.so.0
Missing separate debuginfos, use: dnf debuginfo-install clang-libs-3.8.1-1.fc25.x86_64 elfutils-libelf-0.168-1.fc25.x86_64 llvm-libs-3.8.1-2.fc25.x86_64
(gdb) bt
#0  0x00007fffeed87dfc in void llvm::DeleteContainerSeconds<llvm::DenseMap<llvm::APFloat, llvm::ConstantFP*, llvm::DenseMapAPFloatKeyInfo, llvm::detail::DenseMapPair<llvm::APFloat, llvm::ConstantFP*> > >(llvm::DenseMap<llvm::APFloat, llvm::ConstantFP*, llvm::DenseMapAPFloatKeyInfo, llvm::detail::DenseMapPair<llvm::APFloat, llvm::ConstantFP*> >&) () from /lib64/libbcc.so.0
#1  0x00007fffeed886c5 in llvm::LLVMContextImpl::~LLVMContextImpl() () from /lib64/libbcc.so.0
#2  0x00007fffeed839c1 in llvm::LLVMContext::~LLVMContext() () from /lib64/libbcc.so.0
#3  0x00007fffee0ba97b in ebpf::BPFModule::~BPFModule() () from /lib64/libbcc.so.0
#4  0x00007fffee0b8a8e in bpf_module_destroy () from /lib64/libbcc.so.0
#5  0x00007fffefb44c58 in ffi_call_unix64 () at ../src/x86/unix64.S:76
#6  0x00007fffefb446ba in ffi_call (cif=cif@entry=0x7fffffffdca0, fn=fn@entry=0x7fffee0b8a80 <bpf_module_destroy>, rvalue=<optimized out>, rvalue@entry=0x7fffffffdbf0, avalue=avalue@entry=0x7fffffffdbd0)
    at ../src/x86/ffi64.c:525
#7  0x00007fffefd57957 in _call_function_pointer (argcount=1, resmem=0x7fffffffdbf0, restype=<optimized out>, atypes=<optimized out>, avalues=0x7fffffffdbd0, pProc=0x7fffee0b8a80 <bpf_module_destroy>, 
    flags=4361) at /usr/src/debug/Python-2.7.13/Modules/_ctypes/callproc.c:841
#8  _ctypes_callproc (pProc=pProc@entry=0x7fffee0b8a80 <bpf_module_destroy>, argtuple=argtuple@entry=(93824995766496,), flags=4361, 
    argtypes=argtypes@entry=(<built-in method from_param of _ctypes.PyCSimpleType object at remote 0x555555823e60>,), restype=None, checker=0x0)
    at /usr/src/debug/Python-2.7.13/Modules/_ctypes/callproc.c:1184
#9  0x00007fffefd51382 in PyCFuncPtr_call (self=<optimized out>, inargs=<optimized out>, kwds=<optimized out>) at /usr/src/debug/Python-2.7.13/Modules/_ctypes/_ctypes.c:3979
#10 0x00007ffff7a41003 in PyObject_Call (func=func@entry=<_FuncPtr(__name__='bpf_module_destroy') at remote 0x7ffff7eb6ae0>, arg=arg@entry=(93824995766496,), kw=kw@entry=0x0)
    at /usr/src/debug/Python-2.7.13/Objects/abstract.c:2547
#11 0x00007ffff7ad9828 in do_call (nk=0, na=1, pp_stack=0x7fffffffdea0, func=<optimized out>) at /usr/src/debug/Python-2.7.13/Python/ceval.c:4646
#12 call_function (oparg=<optimized out>, pp_stack=0x7fffffffdea0) at /usr/src/debug/Python-2.7.13/Python/ceval.c:4451
#13 PyEval_EvalFrameEx (
    f=f@entry=Frame 0x7fffe7400250, for file /usr/lib/python2.7/site-packages/bcc/__init__.py, line 1100, in cleanup (self=<BPF(funcs={'trace_entry': <Function(fd=4, name='trace_entry', bpf=<...>) at remote 0x7ffff7ea0710>}, tables={}, open_tracepoints={}, open_uprobes={}, open_kprobes={}, tracefile=None, _user_cb=None, _reader_cb_impl=<CFunctionType at remote 0x7fffe7e69940>, module=93824995766496, debug=0, open_perf_events={}) at remote 0x7ffff7ea0610>, k='p___kmalloc', v=<c_void_p at remote 0x7fffe7e3ae60>), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.13/Python/ceval.c:3063
#14 0x00007ffff7addadc in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=locals@entry=0x0, args=args@entry=0x7ffff7e79aa8, argcount=1, kws=kws@entry=0x7ffff7faa068, kwcount=0, 
    defs=0x0, defcount=0, closure=0x0) at /usr/src/debug/Python-2.7.13/Python/ceval.c:3661
#15 0x00007ffff7a6604d in function_call (func=<function at remote 0x7fffe6fabcf8>, 
    arg=(<BPF(funcs={'trace_entry': <Function(fd=4, name='trace_entry', bpf=<...>) at remote 0x7ffff7ea0710>}, tables={}, open_tracepoints={}, open_uprobes={}, open_kprobes={}, tracefile=None, _user_cb=None, _reader_cb_impl=<CFunctionType at remote 0x7fffe7e69940>, module=93824995766496, debug=0, open_perf_events={}) at remote 0x7ffff7ea0610>,), kw={}) at /usr/src/debug/Python-2.7.13/Objects/funcobject.c:523
#16 0x00007ffff7a41003 in PyObject_Call (func=func@entry=<function at remote 0x7fffe6fabcf8>, 
    arg=arg@entry=(<BPF(funcs={'trace_entry': <Function(fd=4, name='trace_entry', bpf=<...>) at remote 0x7ffff7ea0710>}, tables={}, open_tracepoints={}, open_uprobes={}, open_kprobes={}, tracefile=None, _user_cb=None, _reader_cb_impl=<CFunctionType at remote 0x7fffe7e69940>, module=93824995766496, debug=0, open_perf_events={}) at remote 0x7ffff7ea0610>,), kw=kw@entry={})
    at /usr/src/debug/Python-2.7.13/Objects/abstract.c:2547
#17 0x00007ffff7ad8093 in ext_do_call (nk=<optimized out>, na=1, flags=<optimized out>, pp_stack=0x7fffffffe148, func=<function at remote 0x7fffe6fabcf8>) at /usr/src/debug/Python-2.7.13/Python/ceval.c:4743
#18 PyEval_EvalFrameEx (
    f=f@entry=Frame 0x7ffff7e64de0, for file /usr/lib64/python2.7/atexit.py, line 24, in _run_exitfuncs (exc_info=None, func=<instancemethod at remote 0x7ffff7f2db90>, targs=(), kargs={}), 
    throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.13/Python/ceval.c:3102
#19 0x00007ffff7addadc in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=locals@entry=0x0, args=args@entry=0x7ffff7faa068, argcount=0, kws=kws@entry=0x0, kwcount=0, defs=0x0, 
    defcount=0, closure=0x0) at /usr/src/debug/Python-2.7.13/Python/ceval.c:3661
#20 0x00007ffff7a65f6c in function_call (func=<function at remote 0x7ffff7ea1e60>, arg=(), kw=0x0) at /usr/src/debug/Python-2.7.13/Objects/funcobject.c:523
#21 0x00007ffff7a41003 in PyObject_Call (func=func@entry=<function at remote 0x7ffff7ea1e60>, arg=arg@entry=(), kw=<optimized out>) at /usr/src/debug/Python-2.7.13/Objects/abstract.c:2547
#22 0x00007ffff7ad3bc7 in PyEval_CallObjectWithKeywords (func=func@entry=<function at remote 0x7ffff7ea1e60>, arg=(), arg@entry=0x0, kw=kw@entry=0x0) at /usr/src/debug/Python-2.7.13/Python/ceval.c:4298
#23 0x00007ffff7af8c67 in call_sys_exitfunc () at /usr/src/debug/Python-2.7.13/Python/pythonrun.c:1764
#24 Py_Finalize () at /usr/src/debug/Python-2.7.13/Python/pythonrun.c:423
#25 0x00007ffff7b0adbb in Py_Main (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/Python-2.7.13/Modules/main.c:665
#26 0x00007ffff6d23401 in __libc_start_main (main=0x5555555547a0 <main>, argc=2, argv=0x7fffffffe578, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe568)
    at ../csu/libc-start.c:289
#27 0x00005555555547da in _start ()

/cc @drzaeus77

@drzaeus77
Copy link
Collaborator

Hmm, maybe something with how LLVM deals with floats (unsupported in bpf), that only happens on Fedora due to the LLVM version that is used. I would suggest fixing up this PR to use 1 instead of 1.0 so we can merge it, and open a separate issue for the crash and debug that separately.

Verifies format specifiers while rewriting calls to bpf_trace_printk
and prints a warning the printk will be rejected by the kernel at
runtime.

For tests, redirects stderr at the file descriptor level in order to
catch warnings from the C library.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants