After updating from 12.3 to 13-RELEASE (and recompiling all ports) I have noticed that logger(1) is exiting on signal 6. Having a look at the core file, an assertion has been triggered. ----- (gdb) bt #0 thr_kill () at thr_kill.S:4 #1 0x00000000203053a4 in __raise (s=s@entry=6) at /usr/src/lib/libc/gen/raise.c:52 #2 0x00000000203ba369 in abort () at /usr/src/lib/libc/stdlib/abort.c:67 #3 0x00000000202e82c1 in __assert (func=<optimized out>, file=<optimized out>, line=<optimized out>, failedexpr=<optimized out>) at /usr/src/lib/libc/gen/assert.c:51 #4 0x000000002024d582 in service_clean (sock=5, procfd=1, flags=<optimized out>) at /usr/src/lib/libcasper/libcasper/service.c:394 #5 service_start (service=service@entry=0x20a0a000, sock=sock@entry=5, procfd=procfd@entry=1) at /usr/src/lib/libcasper/libcasper/service.c:427 #6 0x000000002024c393 in service_execute (chanfd=5) at /usr/src/lib/libcasper/libcasper/libcasper_service.c:162 #7 0x000000002024d92b in zygote_main (sock=4) at /usr/src/lib/libcasper/libcasper/zygote.c:162 #8 0x000000002024d798 in zygote_init () at /usr/src/lib/libcasper/libcasper/zygote.c:209 #9 0x000000002024c3bb in casper_main_loop (fd=2) at /usr/src/lib/libcasper/libcasper/libcasper_service.c:233 #10 0x000000002024b8bf in cap_init () at /usr/src/lib/libcasper/libcasper/libcasper.c:105 #11 0x0000000000203361 in main (argc=<optimized out>, argv=<optimized out>) at /usr/src/usr.bin/logger/logger.c:179 (gdb) ----- Looks like an assertion ---- (gdb) up #2 0x00000000203ba369 in abort () at /usr/src/lib/libc/stdlib/abort.c:67 67 (void)raise(SIGABRT); (gdb) up #3 0x00000000202e82c1 in __assert (func=<optimized out>, file=<optimized out>, line=<optimized out>, failedexpr=<optimized out>) at /usr/src/lib/libc/gen/assert.c:51 51 abort(); (gdb) up #4 0x000000002024d582 in service_clean (sock=5, procfd=1, flags=<optimized out>) at /usr/src/lib/libcasper/libcasper/service.c:394 394 assert(procfd > STDERR_FILENO); ----
Thank you for the report and analysis Borja. Anything relevent in /etc/make.conf or /etc/src*.conf with respect to build environment?
Empty src.conf and this is make.conf. OPTIONS_UNSET=DOXYGEN DOCS DOCBOOK DOC DEFAULT_VERSIONS+=perl5=5.32 Nothing fancy.
Sorry I didn't add enough details. % uname -a FreeBSD hostname 13.0-RELEASE FreeBSD 13.0-RELEASE #0 ea31abc26: Tue Apr 20 06:12:14 UTC 2021 root@hostname:/usr/obj/usr/src/amd64.amd64/sys/DNS13 amd64 logger is being called by a script. --- LOGGER="logger -t program -p $syslog_priority" --- case X$basename in X*.extension) queue_and_upload file "$channel" "$fname" | ( cd /tmp && $LOGGER ) --- I am quite puzzled. This didn't fail in previous FreeBSD versions.
Is your script running with some low limit on the number of open fds in a process? Are you able to reproduce the problem by running logger(1) manually?
(In reply to Mark Johnston from comment #4) No relevant limitation, I checked it and it had a 500 MB memory limit. Removing it doesn't avoid the issue anyway. ---- Resource limits (current): cputime infinity secs filesize infinity kB datasize 33554432 kB stacksize 524288 kB coredumpsize infinity kB memoryuse infinity kB memorylocked 131072 kB maxprocesses 8514 openfiles 117306 sbsize infinity bytes vmemoryuse infinity kB pseudo-terminals infinity swapuse infinity kB kqueues infinity umtxp infinity ----- The same server was running 12.2 before updating to 13-RELEASE and it didn't happen. Of course after the make world and installworld I nuked all the installed ports, did a make delete-old and make delete-old-libs and I recompiled all the ports. And no, I can't reproduce it just running it from the command line. Checking whether something else is breaking it.
I am seeing the same problem.
So, nvlist_take_descriptor(nvl, "procfd") returns 1. Is it really wrong? Maybe stdout and stderr are not allocated in this scripting case?
It seems it is possible to trigger this assertion if I just close stdout. % cat test_logger.c #include <unistd.h> int main(void) { close(STDOUT_FILENO); return (execl("/usr/bin/logger", "-t", "program", "test", NULL)); } % cc -o test_logger test_logger.c % ./test_logger Assertion failed: (procfd > STDERR_FILENO), function service_clean, file /usr/home/jkim/src/head/lib/libcasper/libcasper/service.c, line 394. Broken pipe
Mariusz, can you please take a look at it? Thanks!
Created attachment 225324 [details] Quick fix. I have to think a little bit more about this issue. But in an attachment, you should find a quick fix for it.
(In reply to Mariusz Zaborski from comment #10) Yes, it worked for me. Please take your time. :-)
(In reply to Mariusz Zaborski from comment #10) I had similar assertions from lib/libcasper/libcasper/zygote.c:116. Can you please take a look at that, too? Thanks!
Created attachment 225343 [details] Quick fix (v2) I applied the same hack to zygote.c and it fixed the problem for me.
Ping... Any update?
A commit in branch main references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=aa310ebfba3d49a0b6b03a103b969731a8136a73 commit aa310ebfba3d49a0b6b03a103b969731a8136a73 Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mariusz Zaborski <oshogbo@FreeBSD.org> CommitDate: 2021-06-10 10:41:29 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. PR: 225343 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)
Should be fixed now.
This needs to be merged back to stable/13 as well, it seems. But not earlier?
(In reply to Mark Johnston from comment #17) Actually I think all supported branches have the same problem. We only noticed the problem because logger(1) was capsicumized by this commit. https://cgit.freebsd.org/src/commit?id=8838296e56bb9b6ae408cf23c0580095efb5a75c Note it wasn't MFC'd to any stable branches.
To make sure, I merged capsicumized logger for 12.2 and tested. As I suspected, it showed exactly same symptom. The patch was cleanly applied and it fixed the issue there, too.
I also tried it on 11.4. I applied the patch and it was built fine with a minor change, i.e., adding "#include <unistd.h>" to libcasper_impl.c. However, I don't know how to test it because logger is little different there.
A commit in branch stable/13 references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=934e10b4a388b13c2bcd8fbac8cd8cc4a641b1b0 commit 934e10b4a388b13c2bcd8fbac8cd8cc4a641b1b0 Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mariusz Zaborski <oshogbo@FreeBSD.org> CommitDate: 2021-06-15 18:14:43 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. PR: 255339 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ (cherry picked from commit aa310ebfba3d49a0b6b03a103b969731a8136a73) lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)
A commit in branch stable/12 references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=4e2ae05c3ae8c470829b4c3a78aa8c34a7f0b617 commit 4e2ae05c3ae8c470829b4c3a78aa8c34a7f0b617 Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mariusz Zaborski <oshogbo@FreeBSD.org> CommitDate: 2021-06-15 18:23:25 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. PR: 255339 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ (cherry picked from commit aa310ebfba3d49a0b6b03a103b969731a8136a73) lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)
A commit in branch stable/11 references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=6c0a51837f4ba242ea723a887c3b6120d9335c8f commit 6c0a51837f4ba242ea723a887c3b6120d9335c8f Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mariusz Zaborski <oshogbo@FreeBSD.org> CommitDate: 2021-06-15 18:30:27 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. PR: 255339 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ (cherry picked from commit aa310ebfba3d49a0b6b03a103b969731a8136a73) lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)
A commit in branch releng/13.0 references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=ba5ed8109cc99cccd4eebb626225afc5eefa16b0 commit ba5ed8109cc99cccd4eebb626225afc5eefa16b0 Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mark Johnston <markj@FreeBSD.org> CommitDate: 2021-06-29 17:09:02 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. Approved by: so Security: EN-21:19.libcasper PR: 255339 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ (cherry picked from commit aa310ebfba3d49a0b6b03a103b969731a8136a73) (cherry picked from commit 934e10b4a388b13c2bcd8fbac8cd8cc4a641b1b0) lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)
A commit in branch releng/12.2 references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=ee56c5900ae39748aa8dfcde743ad3815e4e78c2 commit ee56c5900ae39748aa8dfcde743ad3815e4e78c2 Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mark Johnston <markj@FreeBSD.org> CommitDate: 2021-06-29 17:08:43 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. Approved by: so Security: EN-21:19.libcasper PR: 255339 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ (cherry picked from commit aa310ebfba3d49a0b6b03a103b969731a8136a73) (cherry picked from commit 4e2ae05c3ae8c470829b4c3a78aa8c34a7f0b617) lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)
A commit in branch releng/11.4 references this bug: URL: https://cgit.FreeBSD.org/src/commit/?id=3d2c68f5378391e4edba9f1a9b0c9a994ba09f6e commit 3d2c68f5378391e4edba9f1a9b0c9a994ba09f6e Author: Mariusz Zaborski <oshogbo@FreeBSD.org> AuthorDate: 2021-06-09 21:46:51 +0000 Commit: Mark Johnston <markj@FreeBSD.org> CommitDate: 2021-06-29 17:08:28 +0000 libcasper: fix descriptors numbers Casper services expect that the first 3 descriptors (stdin/stdout/stderr) will point to /dev/null. Which Casper will ensure later. The Casper services are forked from the original process. If the initial process closes one of those descriptors, Casper may reuse one of them for it on purpose. If this is the case, then renumarate the descriptors used by Casper to higher numbers. This is done already after the fork, so it doesn't break the parent process. Approved by: so Security: EN-21:19.libcasper PR: 255339 Reported by: Borja Marcos <borjam (at) sarenet.es> Tested by: jkim@ (cherry picked from commit aa310ebfba3d49a0b6b03a103b969731a8136a73) (cherry picked from commit 6c0a51837f4ba242ea723a887c3b6120d9335c8f) lib/libcasper/libcasper/libcasper_impl.c | 27 +++++++++++++++++++++++++++ lib/libcasper/libcasper/libcasper_impl.h | 1 + lib/libcasper/libcasper/service.c | 23 +++++++++++++---------- lib/libcasper/libcasper/zygote.c | 15 +++++++++------ 4 files changed, 50 insertions(+), 16 deletions(-)