1st signal interrupt is caught by the Tor process, and ignored by the go process

[mh-cbon]

Hi,

A small issue here regarding the signal capture and exit sequence.

Upon receiving the interrupt signal, i can see the Tor process handles it (there is a log line, and the onion respond with 0xF2). But the Go program, it is not notified, an additional signal is required to get it done.

I also tried to wait, in the hope some timeout would occur, but no luck.

I am a bit concerned by this behavior in the perspective of a service setup (but maybe I should not).

Some logs and data, stripped for clarity.

System

[mh-cbon@Host-001 bootstrap]$ uname -a
Linux Host-001 5.18.17-200.fc36.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Aug 11 14:36:06 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
[mh-cbon@Host-001 bootstrap]$ cat /etc/fedora-release
Fedora release 36 (Thirty Six)
[mh-cbon@Host-001 bootstrap]$ go version
go version go1.19 linux/amd64

require (
    github.com/cretz/bine v0.2.0
    github.com/ipsn/go-libtor v1.0.380
)

The Program output

$ go run .
  INFO[0002] upnp: found 1 clients    
  INFO[0002] upnp: configured 192.168.1.78:40003 => 80 for 10h0m0s on device http://192.168.1.254:42990/rootDesc.xml
Using embedded control connection
Starting tor with args [--DataDirectory /tmp/tor --CookieAuthentication 1 --DisableNetwork 1 --SocksPort auto -f /tmp/tor/torrc-1589576849]
Write line: PROTOCOLINFO
Aug 14 20:47:22.967 [notice] Tor 0.3.5.14-dev (git-da728e36f4579907) running on Linux with Libevent 2.2.0-alpha-dev, OpenSSL 1.1.1l-dev, Zlib 1.2.11, Liblzma N/A, and Libzstd N/A.
Aug 14 20:47:22.967 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Aug 14 20:47:22.967 [notice] Read configuration file "/tmp/tor/torrc-1589576849".
....
$568B6913AE5123EDBA304909A569AFE8F9E73C4C~OrwellianNightmare
Write line: SETEVENTS
Read line: 250 OK
  INFO[0009] bootstrap: Onion ready at http://vq7emfluv5meujjc5gzs2gad632mnxclmhxwcgkba476hlkx4srkpdyd.onion
  INFO[0011] upnp: found 1 clients    
  INFO[0011] bootstrap: Website ready at http://notshownhere/
  INFO[0011] bootstrap: static website running at http://127.0.0.1:40895/
^CAug 14 20:48:53.000 [notice] Interrupt: exiting cleanly.
^C ERROR[0409] bootstrap: Quitting...   
Closing onion vq7emfluv5meujjc5gzs2gad632mnxclmhxwcgkba476hlkx4srkpdyd.onion:80
Write line: DEL_ONION vq7emfluv5meujjc5gzs2gad632mnxclmhxwcgkba476hlkx4srkpdyd
  INFO[0409] bootstrap: accept tcp 127.0.0.1:36877: use of closed network connection
Failed closing onion: write unix @->@: write: broken pipe
Closing Tor
Write line: SIGNAL HALT
Write line: QUIT
Error while closing Tor: Unable to signal halt: write unix @->@: write: broken pipe
  INFO[0409] bootstrap: accept tcp 192.168.1.78:40003: use of closed network connection
  INFO[0412] upnp: found 1 clients    
  INFO[0412] upnp: deleted the port mapping for device http://192.168.1.254:42990/rootDesc.xml

In that log i waited like 5 minutes before giving up.

My code is super boring, I have a small func, which mostly copy paste your examples, with a small wrapper, and some calling code relying on the stdlib to capture the signal and a context to wait on.

package main

import (
    "bytes"
    "context"
    "crypto"
    "crypto/ed25519"
    "fmt"
    "net"
    "os"
    "path/filepath"

    "github.com/cretz/bine/tor"
    "github.com/hashicorp/go-multierror"
    "github.com/ipsn/go-libtor"
)

type torConfig struct {
    Enabled       bool
    RemotePort    int    `yaml:"remote-port"`
    Key           string `yaml:"key-path"`
    CreateDataDir bool   `yaml:"create-data-dir"`
    DataDir       string `yaml:"data-dir"`
    // KeyFormat  string `yaml:"key-format"` // unclear what are the storing formats.
}

func torSocket(ctx context.Context, config torConfig) (*torListener, error) {

    if !config.Enabled {
        return nil, nil
    }

    var key crypto.PrivateKey
    if keypath := config.Key; keypath != "" {
        s, err := os.Stat(keypath)
        if err != nil {
            return nil, fmt.Errorf("tor could not load the private key at %v: %v", config.Key, err)
        }
        if s.IsDir() {
            keypath = filepath.Join(keypath, "hs_ed25519_secret_key")
        }
        d, err := os.ReadFile(keypath)
        if err != nil {
            return nil, fmt.Errorf("tor could not load the private key at %v: %v", config.Key, err)
        }
        d = bytes.TrimPrefix(d, []byte("== ed25519v1-secret: type0 ==\x00\x00\x00"))
        key = ed25519.PrivateKey(d)
    }

    if config.CreateDataDir {
        err := os.MkdirAll(config.DataDir, os.ModePerm)
        if err != nil {
            return nil, err
        }
    }

    t, err := tor.Start(ctx, &tor.StartConf{
        ProcessCreator:         libtor.Creator,
        DebugWriter:            os.Stderr,
        UseEmbeddedControlConn: true,
        DataDir:                config.DataDir,
        NoHush:                 true,
    })
    if err != nil {
        return nil, fmt.Errorf("failed to start tor: %v", err)
    }

    onion, err := t.Listen(ctx, &tor.ListenConf{
        RemotePorts: []int{config.RemotePort},
        Key:         key,
        Version3:    true,
    })
    if err != nil {
        return nil, fmt.Errorf("failed to create onion service: %v", err)
    }

    return &torListener{Listener: onion, torProcess: t}, nil
}

type torListener struct {
    net.Listener
    torProcess *tor.Tor
}

func (t *torListener) URL() string {
    if t.Listener == nil {
        return ""
    }
    return "http://" + t.Listener.(*tor.OnionService).ID + ".onion"
}

func (t *torListener) Close() (out error) {
    if t.Listener != nil {
        if err := t.Listener.Close(); err != nil {
            out = multierror.Append(out, err)
        }
    }
    if t.torProcess != nil {
        if err := t.torProcess.Close(); err != nil {
            out = multierror.Append(out, err)
        }
    }
    return
}

The caller code is like

// some pile of things here.

    ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt)
    defer stop()

// some pile of things here.

    torln, err := torSocket(context.Background(), config.Tor)
    if err != nil {
        Logger.Errorf("tor not set up: %v", err)
    } else if torln != nil {
        Logger.Infof("Onion ready at %v", torln.URL())
        defer torln.Close()
    }

// some pile of things here.

    <-ctx.Done()
    Logger.Error("Quitting...")

// return,return,return

originally posted at https://github.com/cretz/bine/issues/68

[mh-cbon]

Hi again,

I have done testing a service using systemd, and it definitely hangs.

While waiting for the stop event to finish,

$ systemctl --user status bootstrap.service
● bootstrap.service - Bootstrap website
     Loaded: loaded (/home/mh-cbon/.config/systemd/user/bootstrap.service; enabled; vendor preset: disabled)
     Active: deactivating (stop-sigterm) since Sun 2022-08-14 22:13:34 CEST; 25s ago
   Main PID: 81085 (bootstrap)
      Tasks: 10 (limit: 18894)
     Memory: 22.9M
        CPU: 2.855s
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/bootstrap.service
             └─ 81085 /home/mh-cbon/mon-blog/bootstrap/bootstrap

août 14 22:13:16 Host-001 bootstrap[81085]: Read line: 650 HS_DESC UPLOADED zvsyv4co2jkargvjr2hyhaxjdlcivcramlnxy34xp2geap7ckhnaddyd UNKNOWN $3417F1F24A7CA4033DB514610321A1A9F4>
août 14 22:13:16 Host-001 bootstrap[81085]: Read line: 650 HS_DESC UPLOADED zvsyv4co2jkargvjr2hyhaxjdlcivcramlnxy34xp2geap7ckhnaddyd UNKNOWN $0AE25E26120B6866F548A0FCCF087A1F76>
août 14 22:13:16 Host-001 bootstrap[81085]: Write line: SETEVENTS
août 14 22:13:16 Host-001 bootstrap[81085]: Read line: 250 OK
août 14 22:13:16 Host-001 bootstrap[81085]:   INFO[0010] bootstrap: Onion ready at http://zvsyv4co2jkargvjr2hyhaxjdlcivcramlnxy34xp2geap7ckhnaddyd.onion
août 14 22:13:18 Host-001 bootstrap[81085]:   INFO[0013] upnp: found 1 clients
août 14 22:13:18 Host-001 bootstrap[81085]:   INFO[0013] bootstrap: Website ready at http://muarf/
août 14 22:13:18 Host-001 bootstrap[81085]:   INFO[0013] bootstrap: static website running at http://127.0.0.1:33853/
août 14 22:13:34 Host-001 bootstrap[81085]: Aug 14 22:13:34.000 [notice] Catching signal TERM, exiting cleanly.
août 14 22:13:34 Host-001 systemd[1499]: Stopping bootstrap.service - Bootstrap hugo website...

Later some timeout occurred, thus, i will configure it low.

$ systemctl --user status bootstrap.service
× bootstrap.service - Bootstrap hugo website
     Loaded: loaded (/home/mh-cbon/.config/systemd/user/bootstrap.service; enabled; vendor preset: disabled)
     Active: failed (Result: timeout) since Sun 2022-08-14 22:15:04 CEST; 15s ago
    Process: 81085 ExecStart=/home/mh-cbon/mon-blog/bootstrap/bootstrap (code=killed, signal=KILL)
   Main PID: 81085 (code=killed, signal=KILL)
        CPU: 2.875s

août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: State 'stop-sigterm' timed out. Killing.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Killing process 81085 (bootstrap) with signal SIGKILL.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Killing process 81087 (bootstrap) with signal SIGKILL.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Killing process 81090 (n/a) with signal SIGKILL.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Killing process 81095 (n/a) with signal SIGKILL.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Killing process 81160 (n/a) with signal SIGKILL.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Main process exited, code=killed, status=9/KILL
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Failed with result 'timeout'.
août 14 22:15:04 Host-001 systemd[1499]: Stopped bootstrap.service - Bootstrap hugo website.
août 14 22:15:04 Host-001 systemd[1499]: bootstrap.service: Consumed 2.875s CPU time.

Using the systemd directive under the System block TimeoutStopSec=5 it works oki-sh, the stop command does not hang.