Gophermoon 0.3 - a Gopher-Server in Lua – Part 4

Version 0.2 of Gophermoon did send all output from stdout (standard out) and stderr (standard error) back to the socket. For error messages, that was not ideal, as Lua stack traces do not honor the Gopher protocol :)

In this version 0.3 I have added a logging channel for Gophermoon. Writing a log-file into the filesystem does not work, as Gophermoon runs inside an ephermeral container, and all changes to the file system are lost once the client request is done and the session terminates.

So logging is done via syslog. While it is possible to have a syslog-daemon (or systemd-journald) running inside the container, that would make the container more complex. My solution is to have the systemd unit catch all data from the stderr file descriptor and send that to syslog (and implicit to the systemd journal as well).

A small change in the Gophermoon systemd service unit (/etc/systemd/system/gophermoon@.service):

[Unit]
Description=GopherMoon Gopher Server in Lua

[Service]
ExecStart=/bin/systemd-nspawn -q -x --private-network -D /srv/gophermoon /bin/lua /bin/gophermoon
StandardInput=socket
StandardError=syslog

Standard input and standard output are still connected to the socket (from Systemd socket activation, see Part 1), but all data written into standard error will now end up in the Syslog/Journal.

Systemd needs to be made aware of the changes:

systemctl daemon-reload

The function write_log in Gophermoon is used to write a log entry:

--- write a log entry
function write_log(severity,msg)
  io.stderr:write(severity .. ": " .. msg .. "\n")
end

Example use from the source code:

[...]
write_log("INFO", "Selector is " .. selector)
[...]
   if isReadable(filepath) then
      send_textfile(filepath)
   else
      send_error("Selector [" .. selector .. "] not found")
      write_log("ERROR","Selector not found")
   end
[...]

The systemctl status command for the socket activation unit of Gophermoon gives a count of connections (successful and unsuccessful):

 * gophermoon.socket - GopherMoon - Gopher-Server in Lua
   Loaded: loaded (/etc/systemd/system/gophermoon.socket; enabled; vendor preset: disabled)
   Active: active (listening) since Sa 2017-12-23 22:54:44 CET; 2 days ago
   Listen: [::]:70 (Stream)
   Accepted: 209; Connected: 0

Dez 23 22:54:44 gopher.defaultroutes.de systemd[1]: Stopping GopherMoon - Gopher-Server in Lua.
Dez 23 22:54:44 gopher.defaultroutes.de systemd[1]: Listening on GopherMoon - Gopher-Server in Lua.
Dez 23 22:54:44 gopher.defaultroutes.de systemd[1]: Starting GopherMoon - Gopher-Server in Lua.

Systemd creates a new service unit for each new connection, the unit name contains

• a counting number (number of connections since restart of the socket unit)
• local IP-Address and port of the current connection
• remote IP-Address and port of the current connection

Here is a Lua-Error message and stack trace from stderr in the Systemd journal:

# journalctl  -u "gophermoon@*"
Dez 26 19:21:28 gopher.defaultroutes.de systemd[1]: Started GopherMoon Gopher Server in Lua (185.22.143.172:49828).
Dez 26 19:21:28 gopher.defaultroutes.de systemd[1]: Starting GopherMoon Gopher Server in Lua (185.22.143.172:49828)...
Dez 26 19:21:29 gopher.defaultroutes.de systemd-nspawn[29973]: Info: Selector is /0/filedoesnotexists
Dez 26 19:21:29 gopher.defaultroutes.de systemd-nspawn[29973]: /bin/lua: /bin/gophermoon:37: attempt to index a nil value (global 'f')
Dez 26 19:21:29 gopher.defaultroutes.de systemd-nspawn[29973]: stack traceback:
Dez 26 19:21:29 gopher.defaultroutes.de systemd-nspawn[29973]: /bin/gophermoon:37: in function 'isDir'
Dez 26 19:21:29 gopher.defaultroutes.de systemd-nspawn[29973]: /bin/gophermoon:134: in main chunk
Dez 26 19:21:29 gopher.defaultroutes.de systemd-nspawn[29973]: [C]: in ?
Dez 26 19:21:29 gopher.defaultroutes.de systemd[1]: gophermoon@172-5.45.107.88:70-185.22.143.172:49828.service: main process exited, code=exited, status=1/FAILURE
Dez 26 19:21:29 gopher.defaultroutes.de systemd[1]: Unit gophermoon@172-5.45.107.88:70-185.22.143.172:49828.service entered failed state.
Dez 26 19:21:29 gopher.defaultroutes.de systemd[1]: gophermoon@172-5.45.107.88:70-185.22.143.172:49828.service failed.

A list of all Gophermoon service names and connection information.

# journalctl -o verbose -u "gophermoon@*" | grep "_SYSTEMD_UNIT" | tail
    _SYSTEMD_UNIT=gophermoon@199-5.45.107.88:70-212.111.43.252:60215.service
    _SYSTEMD_UNIT=gophermoon@200-5.45.107.88:70-212.111.43.252:47726.service
    _SYSTEMD_UNIT=gophermoon@201-5.45.107.88:70-212.111.43.252:18139.service
    _SYSTEMD_UNIT=gophermoon@202-5.45.107.88:70-212.111.43.252:14576.service
    _SYSTEMD_UNIT=gophermoon@203-5.45.107.88:70-212.111.43.252:62963.service
    _SYSTEMD_UNIT=gophermoon@204-5.45.107.88:70-212.111.43.252:21729.service
    _SYSTEMD_UNIT=gophermoon@205-5.45.107.88:70-185.22.143.172:50432.service
    _SYSTEMD_UNIT=gophermoon@206-5.45.107.88:70-185.22.143.172:50433.service
    _SYSTEMD_UNIT=gophermoon@207-5.45.107.88:70-185.22.143.172:50434.service
    _SYSTEMD_UNIT=gophermoon@208-5.45.107.88:70-185.22.143.172:50436.service

In a later blog post I will show how to parse and aggrgate the connection information for some nice statistics (available via Gopher protocol of course).

Git commit for today: https://github.com/cstrotm/gophermoon/commit/ead8b366c639034b34884b17fb5c4fb28211c012