diff --git a/docs/ftldns/debugging.md b/docs/ftldns/debugging.md index 862b164..ed520b2 100644 --- a/docs/ftldns/debugging.md +++ b/docs/ftldns/debugging.md @@ -1,6 +1,8 @@ +# Debugging FTLDNS using `gdb` + Once you are used to it, you can skip most of the steps. Debugging *FTL*DNS is quite easy. `pihole-FTL` has been designed so that a debugger can be attached to an already running process. This will give you insights into how software (not limited to `pihole-FTL`) works. -### Prerequirements (only required once) +## Prerequirements (only required once) 1. Install `screen` and `gdb` using `sudo apt-get install screen gdb` 2. Start a screen session (it will allow you to come back even if the SSH connection died) @@ -14,7 +16,7 @@ Once you are used to it, you can skip most of the steps. Debugging *FTL*DNS is q You can omit this step, however, you will have to remember to run the quoted line on *every start* of `gdb` in order to properly debug FTL. -### Start of debugging session +## Start of debugging session 1. Use `sudo gdb -p $(pidof pihole-FTL)` to attach the debugger to the already running `pihole-FTL` process 2. Once loading of the symbols has finished (the `(gdb)` input prompt is shown), enter `continue` to continue the operation of `pihole-FTL` inside the debugger. All debugger features are now available. diff --git a/docs/ftldns/valgrind.md b/docs/ftldns/valgrind.md new file mode 100644 index 0000000..f1bcb81 --- /dev/null +++ b/docs/ftldns/valgrind.md @@ -0,0 +1,221 @@ +# Debugging FTLDNS using `valgrind` + +Ocassionally, debugging may require us to run `pihole-FTL` in `valgrind`. We also use it to measure performance and check that our memory layout is optimal (= minimal footprint). + +`Valgrind` is a flexible program for debugging and profiling Linux executables. It consists of a core, which provides a synthetic CPU in software, and a series of debugging and profiling tools. + +## `memcheck` + +The arguably most often used tool in `valgrind` is `memcheck`. Note: When running FTL in Memcheck, it runs about 10-30x slower than normal. Especially the initial import of queries from the database is largely slowed down as SQLite3 frequently allocates and releases heap memory. + +Memcheck is a memory error detector. It can detect the following problems that are common in C and C++ programs. + +1. Accessing memory you shouldn't, e.g. overrunning and underrunning heap blocks, overrunning the top of the stack, and accessing memory after it has been freed. +2. Using undefined values, i.e. values that have not been initialised, or that have been derived from other undefined values. +3. Incorrect freeing of heap memory, such as double-freeing heap blocks, or mismatched use of `malloc`/`new`/`new[]` versus `free`/`delete`/`delete[]` +4. Overlapping `src` and `dst` pointers in `memcpy` and related functions. +5. Passing a fishy (presumably negative) value to the size parameter of a memory allocation function. +6. Memory leaks. + +Problems like these can be difficult to find by other means, often remaining undetected for long periods, then causing occasional, difficult-to-diagnose crashes. + +Make sure to terminate any existing FTL process before starting FTL inside `valgrind`. + +### Preparations + +You have to stop the regular `pihole-FTL` process before starting a `valgrind` debugging session: + +``` bash +sudo service pihole-FTL stop +``` + +Furthermore, you'll have to strip the networking capabilities from the binary using: + +``` bash +sudo setcap -r /usr/bin/pihole-FTL +``` + +They'll automatically be re-added when using `sudo service pihole-FTL start` next time. + +### Command + +We suggest the following one-liner to run `pihole-FTL` in `memcheck`: + +``` +sudo rm /dev/shm/FTL-*; sudo valgrind --trace-children=yes --leak-check=full --track-origins=yes -s /usr/bin/pihole-FTL &> valgrind.log +``` + +If you compile FTL from source, use + +``` +sudo rm /dev/shm/FTL-*; ./build.sh && sudo valgrind --trace-children=yes --leak-check=full --track-origins=yes -s ./pihole-FTL &> valgrind.log +``` + +The used options are: + +1. `trace-children=yes` - Valgrind will trace into sub-processes initiated via the exec system call. This is necessary for multi-process programs. We use this to go down into possibly user scripts on DHCP activity, etc. +2. `leak-check=full` - When enabled, search for memory leaks when the client program finishes. Each individual leak will be shown in detail and/or counted as an error. +3. `track-origins=yes` - Memcheck tracks the origin of uninitialised values. By default, it does not, which means that although it can tell you that an uninitialised value is being used in a dangerous way, it cannot tell you where the uninitialised value came from. This often makes it difficult to track down the root problem. +When set to `yes`, Memcheck keeps track of the origins of all uninitialised values. Then, when an uninitialised value error is reported, Memcheck will try to show the origin of the value. + +### False-positive memory issues + +You may see lines like: + + +??? info "`main_dnsmasq`: Syscall param sendmsg(msg.msg_control) points to uninitialised byte(s)" + ``` + ==2681669== Syscall param sendmsg(msg.msg_control) points to uninitialised byte(s) + ==2681669== at 0x49C112D: __libc_sendmsg (sendmsg.c:28) + ==2681669== by 0x49C112D: sendmsg (sendmsg.c:25) + ==2681669== by 0x188C5B: send_from (forward.c:97) + ==2681669== by 0x18C7C1: reply_query (forward.c:1347) + ==2681669== by 0x17C45B: check_dns_listeners (dnsmasq.c:1770) + ==2681669== by 0x17E759: main_dnsmasq (dnsmasq.c:1209) + ==2681669== by 0x146649: main (main.c:96) + ==2681669== Address 0x1fff000088 is on thread 1's stack + ==2681669== in frame #1, created by send_from (forward.c:34) + ==2681669== Uninitialised value was created by a stack allocation + ==2681669== at 0x188B7D: send_from (forward.c:34) + ``` + ``` + ==2681669== Syscall param sendmsg(msg.msg_control) points to uninitialised byte(s) + ==2681669== at 0x49C112D: __libc_sendmsg (sendmsg.c:28) + ==2681669== by 0x49C112D: sendmsg (sendmsg.c:25) + ==2681669== by 0x188C5B: send_from (forward.c:97) + ==2681669== by 0x18BCFB: receive_query (forward.c:1726) + ==2681669== by 0x17C3DA: check_dns_listeners (dnsmasq.c:1797) + ==2681669== by 0x17E759: main_dnsmasq (dnsmasq.c:1209) + ==2681669== by 0x146649: main (main.c:96) + ==2681669== Address 0x1ffeffff88 is on thread 1's stack + ==2681669== in frame #1, created by send_from (forward.c:34) + ==2681669== Uninitialised value was created by a stack allocation + ==2681669== at 0x188B7D: send_from (forward.c:34) + ``` + + + +??? info "`main_dnsmasq`: Syscall param write(buf) points to uninitialised byte(s)" + ``` + ==2681688== Syscall param write(buf) points to uninitialised byte(s) + ==2681688== at 0x49C02CF: __libc_write (write.c:26) + ==2681688== by 0x49C02CF: write (write.c:24) + ==2681688== by 0x1C10D4: read_write (util.c:698) + ==2681688== by 0x17080B: cache_end_insert.part.0 (cache.c:688) + ==2681688== by 0x1AA7B1: extract_addresses (rfc1035.c:894) + ==2681688== by 0x187CA0: process_reply (forward.c:786) + ==2681688== by 0x189C63: tcp_request (forward.c:2321) + ==2681688== by 0x17C6B3: check_dns_listeners (dnsmasq.c:1978) + ==2681688== by 0x17E759: main_dnsmasq (dnsmasq.c:1209) + ==2681688== by 0x146649: main (main.c:96) + ==2681688== Address 0x4d013dc is 140 bytes inside a block of size 1,120,000 alloc'd + ==2681688== at 0x483DD99: calloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x1C0324: safe_malloc (util.c:282) + ==2681688== by 0x1716F7: cache_init (cache.c:111) + ==2681688== by 0x17E089: main_dnsmasq (dnsmasq.c:396) + ==2681688== by 0x146649: main (main.c:96) + ==2681688== Uninitialised value was created by a stack allocation + ==2681688== at 0x1AA4F0: extract_addresses (rfc1035.c:537) + ``` + + +These are known false-positives as use of `-O2` and above is not recommended with Memcheck (`pihole-FTL` is typically compiled with `-O3`). It occasionally reports uninitialised-value errors which don't really exist. + +### Known memory leaks + +Usually the GNU C library (`libc.so`) doesn't bother to free that memory when the program ends - there would be no point, since the Linux kernel reclaims all process resources when a process exits anyway, so it would just slow things down. The glibc authors realised that this behaviour causes leak checkers, such as Valgrind, to falsely report leaks in glibc, when a leak check is done at exit. In order to avoid this, they provided a routine called `__libc_freeres` specifically to make glibc release all memory it has allocated. This, however, does not cover the memory allocated by `res_init()` for `gethostbyaddr()`. + + +??? info "`gethostbyaddr`: 28 bytes in 1 blocks are definitely lost" + ``` + ==2681688== 28 bytes in 1 blocks are definitely lost in loss record 49 of 200 + ==2681688== at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x84B840E: ??? + ==2681688== by 0x84B5C43: ??? + ==2681688== by 0x84A9904: ??? + ==2681688== by 0x84A9C26: ??? + ==2681688== by 0x4B022ED: gethostbyaddr_r@@GLIBC_2.2.5 (getXXbyYY_r.c:315) + ==2681688== by 0x4B02008: gethostbyaddr (getXXbyYY.c:135) + ==2681688== by 0x155BC6: resolveHostname.part.0 (resolve.c:216) + ==2681688== by 0x155FF4: resolveHostname (resolve.c:134) + ==2681688== by 0x155FF4: resolveAndAddHostname (resolve.c:319) + ==2681688== by 0x156F42: resolveUpstreams (resolve.c:553) + ==2681688== by 0x156F42: DNSclient_thread (resolve.c:608) + ==2681688== by 0x49B5608: start_thread (pthread_create.c:477) + ==2681688== by 0x4AF1292: clone (clone.S:95) + ``` + ``` + ==2681688== 96 bytes in 1 blocks are definitely lost in loss record 100 of 200 + ==2681688== at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x4A710D4: __libc_alloc_buffer_allocate (alloc_buffer_allocate.c:26) + ==2681688== by 0x4B145A8: alloc_buffer_allocate (alloc_buffer.h:143) + ==2681688== by 0x4B145A8: __resolv_conf_allocate (resolv_conf.c:411) + ==2681688== by 0x4B11EB1: __resolv_conf_load (res_init.c:592) + ==2681688== by 0x4B141B2: __resolv_conf_get_current (resolv_conf.c:163) + ==2681688== by 0x4B12464: __res_vinit (res_init.c:614) + ==2681688== by 0x155DCC: resolveHostname.part.0 (resolve.c:180) + ==2681688== by 0x155FF4: resolveHostname (resolve.c:134) + ==2681688== by 0x155FF4: resolveAndAddHostname (resolve.c:319) + ==2681688== by 0x156BFA: resolveClients (resolve.c:462) + ==2681688== by 0x156BFA: DNSclient_thread (resolve.c:605) + ==2681688== by 0x49B5608: start_thread (pthread_create.c:477) + ==2681688== by 0x4AF1292: clone (clone.S:95) + ``` + + +This, and similar, loss record can safely be ignored. + +For performance reasons, we keep a few prepared SQL statement always ready for execution in the main thread. However, this has the disadvatage that forks will inherit them. As [it is not safe](https://www.sqlite.org/howtocorrupt.html) to use a database connection across forks, we discard the open connection and open a new one. This will inevitably lead to a memory loss, however, the SQLite3 engine is not able to handle this any better. + +As forking relies on [copy-on-write](https://en.wikipedia.org/wiki/Copy-on-write), this does not *actually* lead to a memory wasting as the resource will be shared between the fork and the original process. Furthermore, TCP workers are typically rare and short-lived so this leak isn't anything we are too worried about. + + +??? info "`gravityDB_open`: *(some)* bytes in 1 blocks are definitely lost" + ``` + ==2681688== 40 (32 direct, 8 indirect) bytes in 1 blocks are definitely lost in loss record 75 of 200 + ==2681688== at 0x483DD99: calloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x15AE74: new_sqlite3_stmt_vec (vector.c:22) + ==2681688== by 0x16241E: gravityDB_open (gravity-db.c:184) + ==2681688== by 0x16241E: gravityDB_open (gravity-db.c:100) + ==2681688== by 0x14AE3C: FTL_reload_all_domainlists (datastructure.c:463) + ==2681688== by 0x161D84: DB_thread (database-thread.c:86) + ==2681688== by 0x49B5608: start_thread (pthread_create.c:477) + ==2681688== by 0x4AF1292: clone (clone.S:95) + ==2681688== + ==2681688== 40 (32 direct, 8 indirect) bytes in 1 blocks are definitely lost in loss record 76 of 200 + ==2681688== at 0x483DD99: calloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x15AE74: new_sqlite3_stmt_vec (vector.c:22) + ==2681688== by 0x16245E: gravityDB_open (gravity-db.c:186) + ==2681688== by 0x16245E: gravityDB_open (gravity-db.c:100) + ==2681688== by 0x14AE3C: FTL_reload_all_domainlists (datastructure.c:463) + ==2681688== by 0x161D84: DB_thread (database-thread.c:86) + ==2681688== by 0x49B5608: start_thread (pthread_create.c:477) + ==2681688== by 0x4AF1292: clone (clone.S:95) + ==2681688== + ==2681688== 40 (32 direct, 8 indirect) bytes in 1 blocks are definitely lost in loss record 77 of 200 + ==2681688== at 0x483DD99: calloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x15AE74: new_sqlite3_stmt_vec (vector.c:22) + ==2681688== by 0x16243E: gravityDB_open (gravity-db.c:188) + ==2681688== by 0x16243E: gravityDB_open (gravity-db.c:100) + ==2681688== by 0x14AE3C: FTL_reload_all_domainlist (datastructure.c:463) + ==2681688== by 0x161D84: DB_thread (database-thread.c:86) + ==2681688== by 0x49B5608: start_thread (pthread_create.c:477) + ==2681688== by 0x4AF1292: clone (clone.S:95) + ``` + ``` + ==2681688== 188,505 (704 direct, 187,801 indirect) bytes in 1 blocks are definitely lost in loss record 199 of 200 + ==2681688== at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so) + ==2681688== by 0x2196BA: sqlite3MemMalloc (sqlite3.c:23771) + ==2681688== by 0x28E77A: sqlite3Malloc (sqlite3.c:27686) + ==2681688== by 0x28E77A: sqlite3MallocZero (sqlite3.c:27925) + ==2681688== by 0x28E77A: openDatabase (sqlite3.c:164957) + ==2681688== by 0x162149: gravityDB_open (gravity-db.c:119) + ==2681688== by 0x162149: gravityDB_open (gravity-db.c:100) + ==2681688== by 0x14AE3C: FTL_reload_all_domainlists (datastructure.c:463) + ==2681688== by 0x161D84: DB_thread (database-thread.c:86) + ==2681688== by 0x49B5608: start_thread (pthread_create.c:477) + ==2681688== by 0x4AF1292: clone (clone.S:95) + ``` + + +{!abbreviations.md!} diff --git a/mkdocs.yml b/mkdocs.yml index 077f8fa..d3ff3ca 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -107,7 +107,9 @@ nav: - 'Signals': 'ftldns/signals.md' - 'Compatibility': ftldns/compatibility.md - 'Install from source': ftldns/compile.md - - 'Debugging FTLDNS': ftldns/debugging.md + - 'Debugging FTLDNS': + - 'gdb': ftldns/debugging.md + - 'valgrind': ftldns/valgrind.md - 'In-depth manual': ftldns/in-depth.md - 'RegEx blocking': - "Overview": regex/overview.md