search

llvm / llvm-project

The LLVM Project is a collection of modular and reusable compiler and toolchain technologies.
http://llvm.org
Other
29.39k stars 12.15k forks source link

LLDB does not flush IO after expression evaluation which makes output of expression overlapped #110528

Open ikey4u opened 2 months ago

ikey4u commented 2 months ago

When debugging clang static analyzer, the output of evaluating dump of ProgramState of ExplodedNode seems does not work in LLDB, the issue is weirded that I cannot describe it in simple one or two statements. As a result, I spend a lot of time to create a docker environment that easy you to reproduce the problem, and the problem is described in the last.

Host

The following operations are executed in host.

Docker

The following operations are executed in docker, you can use following command to get into docker on your host:

docker exec -it lldb-bug bash
llvmbot commented 2 months ago

@llvm/issue-subscribers-lldb

Author: zhq (ikey4u)

When debugging clang static analyzer, the output of evaluating dump of ProgramState of ExplodedNode seems does not work in LLDB, the issue is weirded that I cannot describe it in simple one or two statements. As a result, I spend a lot of time to create a docker environment that easy you to reproduce the problem, and the problem is described in the last. # Host The following operations are executed in host. - Create docker base image docker pull centos:7.6.1810 - Create docker container mkdir -p ~/share/lldb-bug docker run --name lldb-bug -d -i -t -v ~/share/lldb-bug:/lldb-bug centos:7.6.1810 bash # Docker The following operations are executed in docker, you can use following command to get into docker on your host: docker exec -it lldb-bug bash - Update yum cp -a /etc/yum.repos.d /etc/yum.repos.d.bak sed -e "s|^mirrorlist=|#mirrorlist=|g" \ -e "s|^#baseurl=http://mirror.centos.org/centos/\$releasever|baseurl=https://mirrors.tuna.tsinghua.edu.cn/centos-vault/7.6.1810|g" \ -e "s|^#baseurl=http://mirror.centos.org/\$contentdir/\$releasever|baseurl=https://mirrors.tuna.tsinghua.edu.cn/centos-vault/7.6.1810|g" \ -i.bak \ /etc/yum.repos.d/CentOS-*.repo echo sslverify=false >> /etc/yum.conf cat >> /etc/yum.repos.d/CentOS-Base.repo <<EOF [sclo] name=CentOS-7.6.1810 -Sclo -mirrors.tuna.tsinghua.edu.cn/centos-vault failovermethod=priority baseurl=http://mirrors.tuna.tsinghua.edu.cn/centos-vault/7.6.1810/sclo/\$basearch/rh gpgcheck=0 enabled=1 gpgkey=http://mirrors.tuna.tsinghua.edu.cn/centos-vault/RPM-GPG-KEY-CentOS-7 EOF yum makecache - Install dependencies source /opt/rh/devtoolset-8/enable yum install -y pcre2-devel devtoolset-8 git make git patch openssl-devel zlib-devel readline-devel sqlite-devel bzip2-devel zlib libffi-devel cd /lldb-bug curl https://pyenv.run | bash echo 'export PYENV_ROOT="$HOME/.pyenv"' >> ~/.bashrc echo 'command -v pyenv >/dev/null || export PATH="$PYENV_ROOT/bin:$PATH"' >> ~/.bashrc echo 'eval "$(pyenv init -)"' >> ~/.bashrc source ~/.bashrc PYTHON_CONFIGURE_OPTS="--enable-shared" pyenv install 3.9.5 pyenv global 3.9.5 cd /lldb-bug curl -LO http://prdownloads.sourceforge.net/swig/swig-4.2.1.tar.gz tar zxvf swig-4.2.1.tar.gz cd swig-4.2.1 ./configure --prefix=${PWD}/out make make install cd /lldb-bug curl -LO https://www.thrysoee.dk/editline/libedit-20240517-3.1.tar.gz tar zxvf libedit-20240517-3.1.tar.gz cd libedit-20240517-3.1/ ./configure --prefix=${PWD}/out make make install cd /lldb-bug curl -LO https://github.com/Kitware/CMake/releases/download/v3.20.6/cmake-3.20.6-linux-x86_64.tar.gz tar zxvf cmake-3.20.6-linux-x86_64.tar.gz cd /lldb-bug curl -LO https://github.com/ninja-build/ninja/releases/download/v1.12.1/ninja-linux.zip unzip ninja-linux.zip -d ninja - Build lldb source /opt/rh/devtoolset-8/enable cd /lldb-bug git clone https://github.com/llvm/llvm-project.git cd llvm-project && git checkout tags/llvmorg-18.1.8 # build clang in release mode using gcc 8.3 which will be used to build # clang it self later since gcc 8.3 will crash randomly when build clang # in debug mode cd /lldb-bug export PKG_CONFIG_PATH=/lldb-bug/libedit-20240517-3.1/out/lib/pkgconfig:${PKG_CONFIG_PATH} export PATH=/lldb-bug/ninja:/lldb-bug/swig-4.2.1/out/bin:/lldb-bug/cmake-3.20.6-linux-x86_64/bin:${PATH} cmake -G "Ninja" -B /lldb-bug/llvm-project/build/Release \ -D CMAKE_EXPORT_COMPILE_COMMANDS=1 \ -D LLVM_ENABLE_PROJECTS="clang;" \ -D LLVM_PARALLEL_LINK_JOBS=1 \ -D LLVM_PARALLEL_COMPILE_JOBS=32 \ -D CMAKE_BUILD_TYPE=Release \ -S /lldb-bug/llvm-project/llvm time ninja -C /lldb-bug/llvm-project/build/Release # build clang and lldb in debug mode cd /lldb-bug export PKG_CONFIG_PATH=/lldb-bug/libedit-20240517-3.1/out/lib/pkgconfig:${PKG_CONFIG_PATH} export PATH=/lldb-bug/llvm-project/build/Release/bin/:/lldb-bug/ninja:/lldb-bug/swig-4.2.1/out/bin:/lldb-bug/cmake-3.20.6-linux-x86_64/bin:${PATH} cmake -G "Ninja" -B /lldb-bug/llvm-project/build/Debug \ -D CMAKE_CXX_COMPILER=clang++ \ -D CMAKE_C_COMPILER=clang \ -D CMAKE_EXPORT_COMPILE_COMMANDS=1 \ -D LLVM_ENABLE_PROJECTS="clang;lldb;" \ -D LLVM_PARALLEL_LINK_JOBS=1 \ -D LLVM_PARALLEL_COMPILE_JOBS=32 \ -D CMAKE_BUILD_TYPE=Debug \ -S /lldb-bug/llvm-project/llvm time ninja -C /lldb-bug/llvm-project/build/Debug - The time has finally come to reproduce the bug Create a div zero file in home directory: // /lldb-bug/divzero.cpp int foo(int x) { return x/0; } Load it using lldb: /lldb-bug/llvm-project/build/Debug/bin/lldb -- /lldb-bug/llvm-project/build/Debug/bin/clang++ --analyze -Xanalyzer -analyzer-checker=core.DivideZero /lldb-bug/divzero.cpp Disable ASLR in lldb when using lldb in a docker to avoid error `personality set failed: Operation not permitted`: settings set target.disable-aslr false And set a breakpoint in lldb: breakpoint set --name ExprEngine::Visit Then run lldb: r When the breakpoint hits, checke the ExplodeNode state using following command: * thread #1, name = 'clang++', stop reason = breakpoint 1.1 frame #0: 0x0000558522a13fc6 clang++`clang::ento::ExprEngine::Visit(this=0x00007ffcf1baf400, S=0x000055852d8bb390, Pred=0x000055852d8df550, DstTop=0x00007ffcf1baeb48) at ExprEngine.cpp:1714:33 1711 1712 void ExprEngine::Visit(const Stmt *S, ExplodedNode *Pred, 1713 ExplodedNodeSet &DstTop) { -> 1714 PrettyStackTraceLoc CrashInfo(getContext().getSourceManager(), 1715 S->getBeginLoc(), "Error evaluating statement"); 1716 ExplodedNodeSet Dst; 1717 StmtNodeBuilder Bldr(Pred, DstTop, *currBldrCtx); (lldb) p Pred->Location->dump() "kind": "Statement", "stmt_kind": "DeclRefExpr", "stmt_id": 606, "pointer": "0x55852d8bb390", "pretty": "x", "location": { "line": 2, "column": 12, "file": "/lldb-bug/divzero.cpp" }, "stmt_point_kind": "PreStmtPurgeDeadSymbols" Evaluated this expression after applying Fix-It(s): Pred->Location.dump() Note that lldb auto fix the command, and let's type the right command, the bug appears: (lldb) p Pred->Location.dump() (lldb) "Statement", "stmt_kind": "DeclRefExpr", "stmt_id": 606, "pointer": "0x55852d8bb390", "pretty": "x", "location": { "line": 2, "column": 12, "file": "/lldb-bug/divzero.cpp" }, "stmt_point_kind": "PreStmtPurgeDeadSymbols"(lldb) Note that the last `(lldb)` which is not right, and the content between the two `(lldb)` will not appear correctly on the terminal which seems is eat out by the terminal.
DavidSpickett commented 1 month ago

This is a great report thankyou!

I am just back from vacation, so it will be a few days until I can look into this.

DavidSpickett commented 1 month ago

Something I noticed on my Ubuntu system:

$ cat /tmp/test.c
#include <stdio.h>

void print_no_newline() {
  printf("Output");
  fflush(stdout);
}

void print_with_newline() {
  printf("Output\n");
}

int main() {
  return 0;
}
(lldb) p print_with_newline()
Output
(lldb) p print_no_newline()
(lldb) lldb)
<...then as you start to type the new characters overwrite...>
(lldb) p db)
<...>
(lldb) p print_with_newline()
Output
(lldb)

This is despite the program itself calling fflush.

If I print a lot more characters I do see some of it:

(lldb) p print_no_newline()
(lldb) -----------------------------------------------------(lldb)
       ^---The cursor is here though.

So I think the data is making it out and to lldb but perhaps we don't reset the terminal correctly after printing it.

Note that the last (lldb) which is not right, and the content between the two (lldb) will not appear correctly on the terminal which seems is eat out by the terminal.

I wonder if the cursor is also after the first (lldb) in this case too?

ikey4u commented 1 month ago

Something I noticed on my Ubuntu system:

$ cat /tmp/test.c
#include <stdio.h>

void print_no_newline() {
  printf("Output");
  fflush(stdout);
}

void print_with_newline() {
  printf("Output\n");
}

int main() {
  return 0;
}
(lldb) p print_with_newline()
Output
(lldb) p print_no_newline()
(lldb) lldb)
<...then as you start to type the new characters overwrite...>
(lldb) p db)
<...>
(lldb) p print_with_newline()
Output
(lldb)

This is despite the program itself calling fflush.

If I print a lot more characters I do see some of it:

(lldb) p print_no_newline()
(lldb) -----------------------------------------------------(lldb)
       ^---The cursor is here though.

So I think the data is making it out and to lldb but perhaps we don't reset the terminal correctly after printing it.

Note that the last (lldb) which is not right, and the content between the two (lldb) will not appear correctly on the terminal which seems is eat out by the terminal.

I wonder if the cursor is also after the first (lldb) in this case too?

Yes! And when you type directly, it will override the line (only the part walked by cursor), the remaining part of the line is still there.

DavidSpickett commented 1 month ago

I've reproduced your specific example on Ubuntu as well:

$ ./bin/lldb -- ./bin/clang++ --analyze -Xanalyzer -analyzer-checker=core.DivideZero ./divzero.cpp
<...>
(lldb)  breakpoint set --name ExprEngine::Visit
Breakpoint 1: no locations (pending).
WARNING:  Unable to resolve breakpoint to any actual locations.
(lldb) r
Process 3026646 launched: '/home/david.spickett/build-llvm-aarch64/bin/clang++' (aarch64)
1 location added to breakpoint 1
Process 3026646 stopped
<...>
-> 1722   PrettyStackTraceLoc CrashInfo(getContext().getSourceManager(),
<...>
(lldb) p Pred->Location->dump()
"kind": "Statement", "stmt_kind": "DeclRefExpr", "stmt_id": 1512, "pointer": "0xaaaaaad030e0", "pretty": "x", "location": { "line": 2, "column": 14, "file": "./divzero.cpp" }, "stmt_point_kind": "PreStmtPurgeDeadSymbols"  Evaluated this expression after applying Fix-It(s):
    Pred->Location.dump()
(lldb) p Pred->Location.dump()
"kind": "Statement", "stmt_kind": "DeclRefExpr", "stmt_id": 1512, "pointer": "0xaaaaaad030e0", "pretty": "x", "location": { "line": 2, "column": 14, "file": "./divzero.cpp" }, "stmt_point_ki(lldb) reStmtPurgeDeadSymbols"(lldb)
                                                                                                                                                                                                     ^--Cursor is here.

A standalone reproducer for this is:

$ cat /tmp/test.c
#include <stdio.h>

typedef struct Foo {
  void (*fn)(void);
} Foo;

void print_with_no_newline() {
  fprintf(stderr, "abcdefghijklmnopqrstuvwxyz");
}

Foo f;

int main() {
  Foo* the_foo = &f;
  the_foo->fn = print_with_no_newline;

  return 0;
}

Note that it prints to stderr like the dump does, stderr being unbuffered.

$ gcc /tmp/test.c -o /tmp/test.o -g && /tmp/test.o
$ ./bin/lldb /tmp/test.o -o "b main" -o "run"
(lldb) target create "/tmp/test.o"
Current executable set to '/tmp/test.o' (aarch64).
(lldb) b mainly indexing DWARF: test.o...
Breakpoint 1: where = test.o`main + 4 at test.c:14:8, address = 0x00000000000007d0
(lldb) run
<...>
-> 14     Foo* the_foo = &f;
   15     the_foo->fn = print_with_no_newline;
<...>
(lldb) n
<...>
(lldb) n
<...>
-> 17     return 0;
   18   }
(lldb) p the_foo.fn()
abcdefghijklmnopqrstuvwxyz  Evaluated this expression after applying Fix-It(s):
    the_foo->fn()
(lldb) p the_foo->fn()
(lldb) hijklmnopqrstuvwxyz(lldb)
       ^--Cursor is here

The interesting thing is that the "Evaluated this expression..." does seem to take care to appear after the debugee's output (though it'd be nice to be on a new line), which implies there's a way for the other output to be handled properly.

But anyway, I will see how that works. In the meantime your workaround is to add the newline manually:

(lldb) p the_foo.fn(); (void)fprintf(stderr, "\n")
abcdefghijklmnopqrstuvwxyz
  Evaluated this expression after applying Fix-It(s):
    the_foo->fn(); (void)fprintf(stderr, "\n")
(lldb) p the_foo->fn(); (void)fprintf(stderr, "\n")
abcdefghijklmnopqrstuvwxyz
(lldb)

I suspect that Location.dump() does not add a newline because it calls print json that doesn't want to add a newline. I don't think anyone would object to you adding a newline in Location.dump() though, if you feel like fixing it.

ikey4u commented 1 month ago

There are many dump functions in Clang Static Analyzer, add new line in dump() is not a good solution since it just avoids the problem in this situation . Have a quick search in source of lldb, I got the following code snippet:

    // Only mention Fix-Its if the expression evaluator applied them.
    // Compiler errors refer to the final expression after applying Fix-It(s).
    if (!fixed_expression.empty() && target.GetEnableNotifyAboutFixIts()) {
      Stream &error_stream = result.GetErrorStream();
      error_stream << "  Evaluated this expression after applying Fix-It(s):\n";
      error_stream << "    " << fixed_expression << "\n";
    }
    // TODO

I guess that \n flushes the stream.

Add following line to the location marked as // TODO solves the problem:

result.GetOutputStream().EOL();

But this is not great, one possible elegant solution is to check if the previous output/error stream ends with a newline, if not we force append a new line to the stream.