Debug option -d causes syslog to be sent to clients

[ryanakca]

I am running gophernicus from inetd on OpenBSD 7.1 using the inetd configuration

gopher  stream  tcp     nowait  _gophernicus    /usr/local/libexec/in.gophernicus       in.gophernicus -h rak.ac -nm -nu -nx -nf

If I pass the debug option -d, i.e., use the inetd configuration

gopher  stream  tcp     nowait  _gophernicus    /usr/local/libexec/in.gophernicus       in.gophernicus -h rak.ac -nm -nu -nx -nf -d

then gophernicus sends clients debug logging output from syslog. For example, a client requesting the URL gopher://rak.ac:70/0/phlog/2022-03-20-Pittsburgh-Drivers-Test.md gets back (independently of gopher client):

gophernicus[10427]: generated platform string "OpenBSD/amd64 7.1"
gophernicus[10427]: client sent "/phlog/2022-03-20-Pittsburgh-Drivers-Test.md"
gophernicus[10427]: path to resource is "/var/gopher/phlog/2022-03-20-Pittsburgh-Drivers-Test.md"
gophernicus[10427]: request for "gopher://rak.ac:70/0/phlog/2022-03-20-Pittsburgh-Drivers-Test.md" from XXX.XXX.XXX.XXX
gophernicus[10427]: sending text file "/var/gopher/phlog/2022-03-20-Pittsburgh-Drivers-Test.md"
2022-03-20: Pittsburgh Driver's Test                         rak
================================================================
[....]

This behaviour was not present in 3.0.1, and it is not the behaviour described by the man page. If I additionally pass gophernicus the -l /path/to/some/logfile, then gophernicus sends only debug output, but no contents.

I have git-bisected the issue, and the first bad commit is 9c0b6a66a425ee4f693c49f5ac0c6af8e58e2335 .

[augfab]

Hi, my bad, I wasn't aware that inetd(8) merges stdout and stderr and sends both to the socket (as can be seen here, at lines 1809–1810 of the OpenBSD implementation).

Could you please check if commit 9e7885f (in my fork) fixes the issue? If so I'll open a pull request.

[ryanakca]

Thanks for the quick fix! I cherry-picked your commit onto 3.1.1. It fixed the first issue, namely, sending syslog contents to clients. However, the option -l /my/log/file now causes no output to be sent to clients (and no output to be written to the log file).

[augfab]

I just opened PR #108.

I'm not able to reproduce the second problem. Here's what I did:

Clean compile at 9e7885f:

$ git reset --hard 9e7885f
$ git clean -ffxd
$ ./configure
$ make

Local test with -d and without -l (without inetd or similar, just using standard I/O streams):

$ printf / | ./src/gophernicus -r . -h example.org -nm -nu -nx -nf > /tmp/out 2>&1
$ cat /tmp/out 
iGophernicus documentation  TITLE   null.host   1
i       null.host   1
1build-aux                             2022-May-29 14:12   -------- /build-aux/ example.org 70
0INSTALL.md                            2022-May-29 14:12     4.7 KB /INSTALL.md example.org 70
0Makefile.in                           2022-May-29 16:03     6.0 KB /Makefile.in    example.org 70
0README.md                             2022-May-29 14:56    13.9 KB /README.md  example.org 70
0changelog                             2022-May-29 14:12     2.4 KB /changelog  example.org 70
0configure                             2022-May-29 16:03    12.1 KB /configure  example.org 70
gerror.gif                             2020-Sep-03 21:19     0.5 KB /error.gif  example.org 70
0gophermap.sample                      2020-Nov-21 15:20     1.5 KB /gophermap.sample   example.org 70
0release.sh                            2022-May-29 14:12     1.2 KB /release.sh example.org 70
.
$ sha1sum -t /tmp/out 
a73ab644ae8441838be919521eb796f63c2a2c32  /tmp/out

Local test with -d and -l:

$ printf / | ./src/gophernicus -r . -h example.org -nm -nu -nx -nf -l /tmp/log > /tmp/out 2>&1
$ cat /tmp/log 
unknown example.org:70 - [31/May/2022:23:03:00 +0200] "GET 1/ HTTP/1.0" 200 4096 "" "Unknown gopher client"
$ cat /tmp/out 
iGophernicus documentation  TITLE   null.host   1
i       null.host   1
1build-aux                             2022-May-29 14:12   -------- /build-aux/ example.org 70
0INSTALL.md                            2022-May-29 14:12     4.7 KB /INSTALL.md example.org 70
0Makefile.in                           2022-May-29 16:03     6.0 KB /Makefile.in    example.org 70
0README.md                             2022-May-29 14:56    13.9 KB /README.md  example.org 70
0changelog                             2022-May-29 14:12     2.4 KB /changelog  example.org 70
0configure                             2022-May-29 16:03    12.1 KB /configure  example.org 70
gerror.gif                             2020-Sep-03 21:19     0.5 KB /error.gif  example.org 70
0gophermap.sample                      2020-Nov-21 15:20     1.5 KB /gophermap.sample   example.org 70
0release.sh                            2022-May-29 14:12     1.2 KB /release.sh example.org 70
.
$ sha1sum /tmp/out 
a73ab644ae8441838be919521eb796f63c2a2c32  /tmp/out

The output sent to client is exactly the same for both cases. The contents of the Apache-style log look normal.

So… not quite sure what's going on on your end :thinking:

[ryanakca]

Sorry for the slow response. I tried resetting to the commit you mentioned and rebuilding on OpenBSD 7.1. I had a sudden thought that maybe the log file was not getting added to the unveiled path (I haven't checked if this is the case, but gophernicus should add it to the unveil paths if it isn't already). Just in case, I added -U /tmp. I think the reason why no output is generated is that I get an Abort trap when I run gophernicus with -l /tmp/log (but not in the absence of this option):

<rak@hades:/home/rak/src/gophernicus:5508>$ printf / | ./src/gophernicus -r . -h example.org -nm -nu -nx -nf -d -U /tmp -l /tmp/log > /tmp/out 2>&1
Abort trap (core dumped)
<rak@hades:/home/rak/src/gophernicus:5509>$ echo backtrace full | gdb src/gophernicus gophernicus.core
GNU gdb 6.3
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "amd64-unknown-openbsd7.1"...
Core was generated by `gophernicus'.
Program terminated with signal 6, Aborted.
Loaded symbols for /home/rak/src/gophernicus/src/gophernicus
Reading symbols from /usr/lib/libc.so.96.1...done.
Loaded symbols for /usr/lib/libc.so.96.1
Reading symbols from /usr/libexec/ld.so...Error while reading shared library symbols:
Dwarf Error: wrong version in compilation unit header (is 4, should be 2) [in module /usr/libexec/ld.so]
#0  _thread_sys_open () at /tmp/-:3
3       /tmp/-: No such file or directory.
        in /tmp/-
(gdb) Hangup detected on fd 0
error detected on stdin

I'll try to figure out how to get gdb to give me more useful debugging information tomorrow. (I compiled with make CFLAGS=-g).

[augfab]

I had only tested on Ubuntu 20.04.4, not on OpenBSD :upside_down_face:.

The abort trap is specific to OpenBSD and seems to be coming from a missing cpath wpath pledge, necessary to write to the logfile. Adding these two pledges doesn't completely solve the problem, I'm still looking…

On OpenBSD, pledges are set only if shared memory is disabled (gophernicus.c:589-608), with option -nm.

The default pledges are: stdio rpath inet sendfd recvfd proc (line 591).

Additional pledges might be added: exec (for executable gophermaps) and getpw (to serve personal ~/public_gopher of all users), though not in your case (because of -nx and -nu).

Running tail -f /var/log/messages | grep gophernicus in a terminal alongside the aborting command gives:

$ tail -f /var/log/messages | grep gophernicus
Jun 17 10:18:29 augfab /bsd: gophernicus[86336]: pledge "wpath", syscall 5

when this command is run:

$ printf / | ./src/gophernicus -r . -h example.org -nm -nu -nx -nf -d -U /tmp -l /tmp/log > /tmp/out 2>&1
Abort trap (core dumped) 

With this diff it gets a bit further:

diff --git a/src/gophernicus.c b/src/gophernicus.c
index 0cf2d68..b2a15fd 100644
--- a/src/gophernicus.c
+++ b/src/gophernicus.c
@@ -603,6 +603,12 @@ int main(int argc, char *argv[])
            log_debug("personal gopherspaces enabled, adding `getpw' to pledge(2)");
        }

+       /* Writing to Apache-style combined access logfile requires open(2). */
+       if (*st.log_file) {
+           strlcat(pledges, " cpath wpath", sizeof(pledges));
+           log_debug("combined logging enabled, adding `cpath wpath' to pledge(2)");
+       }
+
        if (pledge(pledges, NULL) == -1)
            die(&st, "pledge", pledges);
    }

But then the open(2) call for "/tmp/log" fails with EACCES (using ktrace and kdump to see what's going on):

$ printf / | ktrace ./src/gophernicus -r . -h example.org -nm -nu -nx -nf -d -U /tmp -l /tmp/log > /tmp/out 2>&1
$ kdump
...
 63731 gophernicus CALL  open(0x7f7ffffd73e1,0x209<O_WRONLY|O_APPEND|O_CREAT>,0666<S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH>)
 63731 gophernicus NAMI  "/tmp/log"
 63731 gophernicus RET   open -1 errno 13 Permission denied
...
$ grep 13 /usr/include/sys/errno.h                                                                                                                                                                            
#define EACCES      13  /* Permission denied */

To be continued :smile:

[augfab]

I dug into this a little bit further today. Current unveil(2) setup restricts creating and writing to files (paths are unveiled with permission "r" only):

$ grep -n -e 'if.*unveil(' src/gophernicus.c
554:            if (unveil(st.server_root, "r") == -1)
565:                    if (unveil("/etc/pwd.db", "r") == -1)
577:                    if (unveil(extra_unveil, "r") == -1)
581:            if (unveil(NULL, NULL) == -1)

Citing from the manual:

Attempts to access paths not allowed by unveil() will result in an error of EACCES when the permissions argument does not match the attempted operation.

What could be done is add the directory name of the logfile to the unveiled paths with permissions "cw" (matching pledges cpath wpath)

[ryanakca]

On Sat, Jun 18, 2022 at 04:28:48AM -0700, Augustin Fabre wrote:

What could be done is add the directory name of the logfile to the unveiled paths with permissions "cw" (matching pledges cpath wpath)

I think this would probably be the best bet, so long as these permissions are documented under the -l option the man page or elsewhere (I could imagine someone not wanting to grant these permissions on the entirety of /var/log).

-- |)|/ Ryan Kavanagh | 4E46 9519 ED67 7734 268F ||\ https://rak.ac | BD95 8F7B F8FC 4A11 C97A

[augfab]

so long as these permissions are documented under the -l option the man page or elsewhere (I could imagine someone not wanting to grant these permissions on the entirety of /var/log).

Yes indeed, I don't know what the best approach is :confused:.

Here's what I did, it doesn't quite work yet. If the log is in an already unveiled path (only the permissions set last apply so for example if the logfile is in the server root, setting "cw" trumps "r" and nothing get served)

diff --git a/src/gophernicus.c b/src/gophernicus.c
index 0cf2d68..67fded6 100644
--- a/src/gophernicus.c
+++ b/src/gophernicus.c
@@ -578,6 +578,19 @@ int main(int argc, char *argv[])
                                die(&st, "unveil", extra_unveil);
                }

+               /* Apache-style combined access logfile requires
+                * creating and writing to file. */
+               if (*st.log_file) {
+                 char log_file[sizeof(st.log_file)];
+                 char *log_dir = NULL;
+                 memcpy(log_file, st.log_file, sizeof(log_dir));
+                 log_dir = dirname(log_file);
+                 if (log_dir == NULL)
+                   die(&st, "dirname", log_file);
+                 if (unveil(log_dir, "cw") == -1)
+                   die(&st, "unveil", log_dir);
+               }
+
                if (unveil(NULL, NULL) == -1)
                        die(&st, "unveil", "locking unveil");
        }

[ryanakca]

On Sat, Jun 18, 2022 at 04:28:48AM -0700, Augustin Fabre wrote:

What could be done is add the directory name of the logfile to the unveiled paths with permissions "cw" (matching pledges cpath wpath)

I think this would probably be the best bet, so long as these permissions are documented under the -l option the man page or elsewhere (I could imagine someone not wanting to grant these permissions on the entirety of /var/log).

-- |)|/ Ryan Kavanagh | 4E46 9519 ED67 7734 268F ||\ https://rak.ac | BD95 8F7B F8FC 4A11 C97A