-
-
Notifications
You must be signed in to change notification settings - Fork 192
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
FTL crashed (sqlite3_finalize+0x37) #816
Comments
fix/fhriley-fix_buf_overflow
branch.
@JohnstonCode Are there TCP fork messages above this crash report? If so, and if this crash happened in a TCP worker fork, it is likely already fixed by #811 Try switching to |
Getting these messages before the crash
|
getting them when FTL restarts as well
|
Something is odd here. Your log contains messages from various different PIDs whereas there should only be |
Yes i am getting multiple PIDs.
|
Are you using |
I'm not using
|
Had another crash on the
|
Could you again share some more lines above the |
Sorry updated the above log. Also it has been running for 12 hours and |
This issue has been mentioned on Pi-hole Userspace. There might be relevant details there: https://discourse.pi-hole.net/t/multiple-instances-of-pihole-ftl-running/34865/5 |
This doesn't look right, but let's check what is going on!
There should be only one tree node related to FTL (I abbreviated quite a lot of unrelated lines with
Note that threads are wrapped in
Lines logged by the main process will be shown with an
Lines logged by a fork (TCP requests) will be shown with an
Finally, lines logged by threads are now also distinguishable with a
We can also log threads of forks but this is (luckily) not a thing in FTL (currently). |
|
Okay, thanks for that! Could you do the same again after setting I just tried this locally:
My observation is that after the fork crashes, it correctly signals a termination request to the main process which, in turn, correctly terminates all remaining processes. In my test, no zombies were are left on the system. It would likely be helpful if you could also provide the output of
where
where Thanks for your continued support in trying to squash this bug! I think we should be able to get a fix rather soon now. We're postponing the planned Pi-hole v5.1 release for this to ensure the bugfix will be included! |
Okay i will get all of that setup. Thanks you for continuing to look into this. It usually crashes around the 8 hour mark so will post as soon as it does. |
|
Thank you. Concerning the crash: I pushed a new update which hopefully resolves the crash. We do this by enforcing an unconditional refresh of the database connection on forking. We had this conditionally before, it may be that we forgot to do it in rare edge cases. Concerning the multiple PIDs after a crash: This is still puzzling. From your/proc` details above, we see
meaning that this process's parent is |
Thank you for getting that fixed.
|
Had another crash on Attached the various output in a text file as the FTL log is too big. |
@JohnstonCode Thanks, I think we're close to the solution. Can you set
in It will be interesting to see what this shows us in |
Okay, i have set those and restarted the DNS. Will report back once it crashes again. |
Im not getting the FTL crashed message in the log but the DNS service is stopping.
|
@JohnstonCode The status message is a red herring here. The check for DNS availability is done by checking if FTL is accepting TCP connections on port 53. As an anti-DoS strategy, the number of concurrent TCP connections is limited (as they are handled by forks). This limit defaults to 20: Line 18 in 3d7c095
And if we count, we see exactly these 20 already being active:
I will improve the check, I have this on my ToDo list for too long. It is actually straightforward to do. Otherwise, still no crash? |
Okay, we can also release a v5.1.1 real quick if we identify the solution to this only somewhat later. |
No, absolutely not. TCP forks coming and going is fine. |
Okay cheers |
This issue has been mentioned on Pi-hole Userspace. There might be relevant details there: https://discourse.pi-hole.net/t/multiple-instances-of-pihole-ftl-running/34865/16 |
This issue has been mentioned on Pi-hole Userspace. There might be relevant details there: https://discourse.pi-hole.net/t/dns-resolver-crashes/35171/4 |
Upgraded to 5.1 and had a crash.
|
Thanks, so we have now something which can actually be the reason to all this:
The termination event should be unique. When the first line is logged, the database handle is already closed. On the second try, random neutrino interaction causes a crash. I will investigate and push a fix. When we have it, we'll ship a FTL v5.1.1 version so this is resolved once and for all. Thanks for your continued support in getting this bug squashed! |
Thank you for continuing to look into this. Let me know if you need any more debug information. |
It is bizarre, but, at least, it is clear now what happens and why this is a problem:
There is a safety measure in place, preventing an already closed database connection from being closed another time. The issue here is that the termination signal arrives at exactly the same time where a database closing is already in progress. The first closing in interrupted somewhere in between and then the second try tries to work on half-rotted pointers, leading deeply into the nowhere. Whether or not this leads to a crash depends on the precise timing, e.g.,
the first call was interrupted in a non-critical phase so the second try just complained instead of failing hard. Often enough, when the client terminates quickly enough, nothing bad happens:
Here, you can see that both times the client disconnected by itself after exactly 2 minutes and 30 seconds minus 1 millisecond. This was enough to not cause any issues at all! My proposed fix is two-fold to ensure such a thing can never repeat:
@JohnstonCode Please run
and have a look for the message
and the absence of something like
and similar SQlite3 messages. |
checked out that branch. Will keep an eye on the logs. Thanks again for looking into this. |
@JohnstonCode I'd actually be interested which kind of hardware is doing this. This is more out of pure curiosity than anything else. Could you please run a
and check which device the mentioned source of the queries is? The PID
|
The device mentioned is my linksys router. I set the DNS in the router so all devices on my network use it. |
So all queries are shown as originating from the router? Too bad. Do you want to keep it like this or are you interested in seeing which client is doing what on your Pi-hole? Depending on the flexibility of your router, it may require switching to Pi-hole's DHCP server, but maybe it also be done with the stock router's hardware. |
@DL6ER Your fix does not appear to be correct. The |
Well, yes, but my code will result in something like this (x86-64 asm): .LC0:
.string "TCP worker already terminating!"
.LC1:
.string "client disconnected"
.LC2:
.string "timeout"
.LC3:
.string "TCP worker terminating (%s)"
FTL_TCP_worker_terminating:
push rbp
mov rbp, rsp
push rbx
sub rsp, 40
mov eax, edi
mov BYTE PTR [rbp-36], al
movzx eax, BYTE PTR worker_already_terminating[rip] ; Load worker_already_terminating from memory
test al, al ; Test if true, drop the result (but set SF, ZF, and PF status flags), can be either 1&1 == 1 (true) or 0&0 == 0 (false) here
je .L2 ; Jump to L2 (continue with the rest of the subroutine) if the test failed (worker_already_terminating == false)
mov edi, OFFSET FLAT:.LC0 ; Continue here only if worker_already_terminating == true
mov eax, 0
call logg ; Log to file
jmp .L1 ; Jump to the end of the subroutine (return)
.L2:
mov BYTE PTR worker_already_terminating[rip], 1 ; If the test failed (worker_already_terminating == false), we immediately set it to true (= 1)
cmp BYTE PTR [rbp-36], 0
je .L4
mov eax, OFFSET FLAT:.LC1 ; Prepare string "TCP worker terminating (client disconnected)"
jmp .L5
.L4:
mov eax, OFFSET FLAT:.LC2 ; Prepare string "TCP worker terminating (timeout)"
.L5:
mov QWORD PTR [rbp-24], rax
mov rax, QWORD PTR [rbp-24]
mov rsi, rax
mov edi, OFFSET FLAT:.LC3
mov eax, 0
call logg
mov eax, 0
call main_pid
mov ebx, eax
call getpid
cmp ebx, eax
.L1:
mov rbx, QWORD PTR [rbp-8]
leave
ret (I added comments for those who are interested but cannot really read assembler instructions) You can see that if Compare this to before where there were thousands of assembler instructions instead of two between the test and the set. Storing a I checked the C standard for this and found "7.17.8.1 The atomic_flag_test_and_set functions" on p: 285-286 of the C11 standard (ISO/IEC 9899:2011): #include <stdatomic.h>
//...
volatile atomic_flag worker_already_terminating = ATOMIC_FLAG_INIT; // volatile is now optional, leaving it there doesn't hurt and is explicit
void FTL_TCP_worker_terminating(bool finished)
{
if(atomic_flag_test_and_set(&worker_already_terminating)) // the function returns the previous state of the flag and sets it at the same time to true
{
logg("TCP worker already terminating!");
return;
}
//... Funnily enough, the assembly stays exactly the same as with my own implementation before. Using locks here or even ignore/pause signals for a while seems to be much of an overload to the actual problem. @fhriley I'm very interested in how you'd suggest improving this (from two instructions to uninterruptible). |
That was a good explanation of why the code is still broken after your change. You've definitely made it much less likely to occur, but it's still broken. Here is a simplified version of your fix. If the
Perhaps you were looking at the wrong assembly output? Here is the simplified example using the atomic test and set. Now it is using the An alternative solution to this bug would be to call |
BTW, I should probably point out that, in the days of multiprocessor/multicore systems, this is not true. CPUs have multiple levels of memory. A write to memory on one core/CPU might not be visible to another core/CPU for an indeterminate amount of time. This is why architectures have instructions to create barriers, etc. The x86 |
You're right, now that I check again, I see now that the assembly output in that tab doesn't change anymore for any changes in the C code. The Godbolt page generated an AJAX error which apparently killed the entire script without informing the user. My bad.
I don't think that's a good idea as the two termination paths are not equivalent. On a "regular" termination, there are some cleanup instructions like properly shutting down the connection, and shutting down possibly existing TCP connections to upstream servers. Furthermore, there is a log flushing before the fork exits. In the timeout event (on So I will go forward and push my |
@JohnstonCode just a quick question: Did you already see something in your log? We're looking at releasing an FTL v5.1.1 point release probably still today and if would be great if we'd already know if my proposed fix resolved the crashes for you. |
No seen any |
This should be fixed by the release of Pi-hole FTL 5.2. Feel free to re-open of create a new ticket with new information if the issue persists. |
Thanks for everything. |
Originally posted by @JohnstonCode in #770 (comment)
The text was updated successfully, but these errors were encountered: