v0.25.0 netacl and fixes
Test / test (push) Canceled after 0s
Test / e2e (push) Canceled after 0s

This commit is contained in:
lixen committed 2026-10-04 23:43:52 -04:00
1 parent 9e86d7999d
commit 4af072f4e5
30 files changed
+918 -228

No files matched your search

+12
View File
@@ -21,6 +21,7 @@ import (
"github.com/lixenwraith/logwisp/internal/chain"
"github.com/lixenwraith/logwisp/internal/config"
"github.com/lixenwraith/logwisp/internal/core"
"github.com/lixenwraith/logwisp/internal/netacl"
"github.com/lixenwraith/logwisp/internal/plugin"
"github.com/lixenwraith/logwisp/internal/session"
"github.com/lixenwraith/logwisp/internal/sink"
@@ -78,6 +79,7 @@ type HTTPSink struct {
// Authorization
auth *authz.Policy
acl *netacl.Policy
web map[string]http.Handler // GET paths of the browser files and the root
// Runtime. Stop closes flush; the broker then moves what remains of its
@@ -158,6 +160,10 @@ func NewHTTPSinkPlugin(
if err != nil {
return nil, err
}
aclPolicy, err := netacl.New(opts.ACL, opts.Host, logger, "http_sink", id)
if err != nil {
return nil, err
}
switch {
case (opts.LoginPage || opts.ViewerPage) && !authPolicy.BehindProxy():
return nil, errors.New("login_page and viewer_page apply to scram behind auth.trusted_proxies, where browsers log in; without auth or under mtls the viewer is always served")
@@ -185,6 +191,7 @@ func NewHTTPSinkPlugin(
keepalive: core.StreamKeepaliveInterval,
tlsConfig: tlsCfg,
auth: authPolicy,
acl: aclPolicy,
web: web,
}
h.lastProcessed.Store(time.Time{})
@@ -199,6 +206,7 @@ func NewHTTPSinkPlugin(
"tls", tlsCfg != nil,
"mtls", tlsCfg != nil && tlsCfg.ClientAuth == tls.RequireAndVerifyClientCert,
"auth", authPolicy.Describe(),
"acl", aclPolicy.Describe(),
"login_page", opts.LoginPage,
"viewer_page", web[chain.AuthPath+"/view"] != nil)
tlsx.LogWarnings(logger, "http_sink", id, opts.TLS, true)
@@ -244,6 +252,7 @@ func (h *HTTPSink) serve(ctx context.Context, ln net.Listener) error {
ln.Close()
return err
}
ln = h.acl.Listener(ln)
mux := http.NewServeMux()
// Method-scoped patterns: mux answers 405 with Allow header on non-GET
mux.HandleFunc(http.MethodGet+" "+exact(h.config.StreamPath), h.handleStream)
@@ -569,6 +578,7 @@ func (h *HTTPSink) handleStatus(w http.ResponseWriter, r *http.Request) {
"port": h.config.Port,
"tls": h.tlsConfig != nil,
"auth": h.auth.Describe(),
"acl": h.acl.Describe(),
"active_clients": h.activeClients.Load(),
"buffer_size": h.config.BufferSize,
"client_buffer_size": h.config.ClientBufferSize,
@@ -585,6 +595,7 @@ func (h *HTTPSink) handleStatus(w http.ResponseWriter, r *http.Request) {
"dropped_writes": h.droppedWrites.Load(),
"rejected_clients": h.rejectedClients.Load(),
"auth_rejected": h.auth.Rejected(),
"acl_denied": h.acl.Denied(),
},
}
@@ -611,6 +622,7 @@ func (h *HTTPSink) GetStats() sink.SinkStats {
},
}
maps.Copy(details, h.auth.Stats())
maps.Copy(details, h.acl.Stats())
return sink.SinkStats{
ID: h.id,
+35 -61
View File
@@ -256,8 +256,8 @@ func (t *HTTPChainSink) Start(ctx context.Context) error {
return nil
}
// Stop terminates the loop. Worst case: one in-flight request timeout plus
// one final-flush request timeout.
// Stop delivers what is queued and batched within sink.FlushBound, then ends
// the loop
func (t *HTTPChainSink) Stop() {
t.logger.Info("msg", "Stopping HTTP chain sink",
"component", "http_chain_sink",
@@ -305,49 +305,41 @@ func (t *HTTPChainSink) GetStats() sink.SinkStats {
func (t *HTTPChainSink) runLoop(ctx context.Context) {
defer t.wg.Done()
// Fold done channel into a context for request/backoff interruption
runCtx, cancel := context.WithCancel(ctx)
// Stop leaves sink.FlushBound to deliver the queue and the batch, so a
// finite input arrives whole; a request or backoff in flight then ends,
// and every later flush drops its batch at once
ctx, cancel := sink.FlushContext(ctx, t.done, t.reqTimeout)
defer cancel()
go func() {
select {
case <-t.done:
cancel()
case <-runCtx.Done():
}
}()
ticker := time.NewTicker(time.Duration(t.config.FlushIntervalMS) * time.Millisecond)
defer ticker.Stop()
for {
select {
case <-runCtx.Done():
t.finalFlush()
return
case <-ticker.C:
if t.batchCount > 0 && !t.flush(runCtx) {
t.finalFlush()
return
if t.batchCount > 0 {
t.flush(ctx)
}
case event, ok := <-t.input:
if !ok {
t.finalFlush()
return
case event := <-t.input:
if t.append(event) {
t.flush(ctx)
}
t.append(event)
if t.batchCount >= t.config.MaxBatchCount ||
int64(t.batch.Len()) >= t.config.MaxBatchBytes {
if !t.flush(runCtx) {
t.finalFlush()
return
case <-t.done:
for len(t.input) > 0 {
if t.append(<-t.input) {
t.flush(ctx)
}
}
if t.batchCount > 0 {
t.flush(ctx)
}
return
}
}
}
// append serializes one event into the pending batch
func (t *HTTPChainSink) append(event core.TransportEvent) {
// append serializes one event into the pending batch; true once it is full
func (t *HTTPChainSink) append(event core.TransportEvent) bool {
entry, synthesized := chain.EntryFromEvent(event, t.node, t.id)
if synthesized {
t.synthesized.Add(1)
@@ -358,17 +350,17 @@ func (t *HTTPChainSink) append(event core.TransportEvent) {
t.logger.Error("msg", "Failed to marshal chain entry",
"component", "http_chain_sink",
"error", err)
return
return false
}
t.batch.Write(line)
t.batch.WriteByte('\n')
t.batchCount++
return t.batchCount >= t.config.MaxBatchCount || int64(t.batch.Len()) >= t.config.MaxBatchBytes
}
// flush delivers the pending batch, retrying transient failures with backoff.
// Returns false when shutdown interrupts delivery; undelivered batch is dropped
// by finalFlush semantics (batch already consumed here).
func (t *HTTPChainSink) flush(ctx context.Context) bool {
// flush delivers the pending batch, retrying transient failures with backoff
// until shutdown drops it
func (t *HTTPChainSink) flush(ctx context.Context) {
body := bytes.Clone(t.batch.Bytes())
count := t.batchCount
t.batch.Reset()
@@ -377,8 +369,7 @@ func (t *HTTPChainSink) flush(ctx context.Context) bool {
failures := 0
for {
if failures > 0 && !t.waitBackoff(ctx, failures) {
t.droppedBatches.Add(1)
return false
break
}
transient, err := t.post(ctx, body)
if err == nil {
@@ -386,7 +377,7 @@ func (t *HTTPChainSink) flush(ctx context.Context) bool {
t.totalProcessed.Add(uint64(count))
t.lastProcessed.Store(time.Now())
t.proxy.UpdateActivity(t.session.ID)
return true
return
}
t.requestErrors.Add(1)
if !transient {
@@ -396,11 +387,10 @@ func (t *HTTPChainSink) flush(ctx context.Context) bool {
"target", t.url,
"entries", count,
"error", err)
return true
return
}
if ctx.Err() != nil {
t.droppedBatches.Add(1)
return false
break
}
failures++
t.logger.Warn("msg", "Chain batch delivery failed",
@@ -409,27 +399,11 @@ func (t *HTTPChainSink) flush(ctx context.Context) bool {
"attempt", failures,
"error", err)
}
}
// finalFlush best-effort delivers the pending batch during shutdown (single attempt)
func (t *HTTPChainSink) finalFlush() {
if t.batchCount == 0 {
return
}
fctx, cancel := context.WithTimeout(context.Background(), t.reqTimeout)
defer cancel()
count := t.batchCount
if _, err := t.post(fctx, t.batch.Bytes()); err != nil {
t.droppedBatches.Add(1)
t.logger.Warn("msg", "Final chain batch dropped on shutdown",
"component", "http_chain_sink",
"entries", count,
"error", err)
return
}
t.batchesSent.Add(1)
t.totalProcessed.Add(uint64(count))
t.droppedBatches.Add(1)
t.logger.Warn("msg", "Chain batch dropped on shutdown",
"component", "http_chain_sink",
"target", t.url,
"entries", count)
}
// post sends one NDJSON batch; transient=true marks retryable failures
+53 -2
View File
@@ -1,8 +1,10 @@
package httpchain
import (
"bytes"
"context"
"crypto/tls"
"io"
"net"
"net/http"
"net/http/httptest"
@@ -121,7 +123,8 @@ func TestRefusedTokenLogsInAgainAndDeliversOnce(t *testing.T) {
}
sink := created.(*HTTPChainSink)
sink.append(core.TransportEvent{Time: time.Now(), Payload: []byte("entry")})
if !sink.flush(t.Context()) || delivered.Load() != 1 || sink.droppedBatches.Load() != 0 {
sink.flush(t.Context())
if delivered.Load() != 1 || sink.droppedBatches.Load() != 0 {
t.Fatalf("delivered %d, dropped %d", delivered.Load(), sink.droppedBatches.Load())
}
if logins := listener.Stats()["auth_allowed"]; logins != uint64(2) {
@@ -188,7 +191,8 @@ func TestLinkOverIPv6LoopbackWithTLS(t *testing.T) {
sink.append(core.TransportEvent{Time: time.Now(), Payload: []byte("over IPv6")})
ctx, cancel := context.WithTimeout(t.Context(), 5*time.Second)
defer cancel()
if !sink.flush(ctx) || sink.droppedBatches.Load() != 0 {
sink.flush(ctx)
if sink.droppedBatches.Load() != 0 {
t.Fatalf("batch not delivered: %d request errors", sink.requestErrors.Load())
}
select {
@@ -200,3 +204,50 @@ func TestLinkOverIPv6LoopbackWithTLS(t *testing.T) {
t.Fatal("the source published nothing")
}
}
// Stop delivers what is queued and batched, so the end of a finite input
// reaches the source whole, and returns at the flush bound when the source
// stops answering.
func TestStopDeliversTheQueueWithinTheBound(t *testing.T) {
const n = 250 // three batches of the default 100
manager := session.NewManager(time.Hour)
t.Cleanup(manager.Stop)
// stop queues n entries, starts and stops a sink, and returns how long
// Stop took and how many entries an answering source received
stop := func(answering bool) (time.Duration, int64) {
var received atomic.Int64
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
body, _ := io.ReadAll(r.Body)
if !answering {
<-r.Context().Done() // the sink gave up
return
}
received.Add(int64(bytes.Count(body, []byte("\n"))))
w.WriteHeader(http.StatusNoContent)
}))
t.Cleanup(srv.Close)
_, port, _ := net.SplitHostPort(srv.Listener.Addr().String())
p, _ := strconv.ParseInt(port, 10, 64)
created, err := NewHTTPChainSinkPlugin("fwd", map[string]any{"host": "127.0.0.1", "port": p},
log.NewLogger(), session.NewProxy(manager, "fwd"))
if err != nil {
t.Fatal(err)
}
sink := created.(*HTTPChainSink)
for range n {
sink.Input() <- core.TransportEvent{Time: time.Now(), Payload: []byte("entry")}
}
if err := sink.Start(t.Context()); err != nil {
t.Fatal(err)
}
start := time.Now()
sink.Stop()
return time.Since(start), received.Load()
}
if _, got := stop(true); got != n {
t.Fatalf("the source received %d of %d entries", got, n)
}
if d, _ := stop(false); d > 3500*time.Millisecond {
t.Fatalf("Stop took %v past a 2 s flush bound", d)
}
}
+21 -3
View File
@@ -36,9 +36,9 @@ type SinkStats struct {
Details map[string]any
}
// FlushBound is how long a network sink's Stop gives its clients to take
// what is queued: write_timeout_ms, at most core.SinkFlushTimeout, which a
// reload also waits out for a client that stopped reading.
// FlushBound is how long a network sink's Stop gives what is queued to reach
// its clients or its downstream: its write or request timeout, at most
// core.SinkFlushTimeout, which a reload also waits out for a stalled peer.
func FlushBound(writeTimeout time.Duration) time.Duration {
if writeTimeout > 0 && writeTimeout < core.SinkFlushTimeout {
return writeTimeout
@@ -46,6 +46,24 @@ func FlushBound(writeTimeout time.Duration) time.Duration {
return core.SinkFlushTimeout
}
// FlushContext is ctx ending FlushBound(timeout) after done closes: a sink
// that dials runs its loop under it, so Stop leaves its queue that long.
func FlushContext(ctx context.Context, done <-chan struct{}, timeout time.Duration) (context.Context, context.CancelFunc) {
ctx, cancel := context.WithCancel(ctx)
go func() {
select {
case <-done:
select {
case <-time.After(FlushBound(timeout)):
case <-ctx.Done():
}
case <-ctx.Done():
}
cancel()
}()
return ctx, cancel
}
// Drain takes the payloads queued in input without waiting: a network sink's
// last events, which each client then writes on its own.
func Drain(input <-chan core.TransportEvent) [][]byte {
+11 -1
View File
@@ -16,6 +16,7 @@ import (
"github.com/lixenwraith/logwisp/internal/authz"
"github.com/lixenwraith/logwisp/internal/config"
"github.com/lixenwraith/logwisp/internal/core"
"github.com/lixenwraith/logwisp/internal/netacl"
"github.com/lixenwraith/logwisp/internal/plugin"
"github.com/lixenwraith/logwisp/internal/session"
"github.com/lixenwraith/logwisp/internal/sink"
@@ -74,6 +75,7 @@ type TCPSink struct {
// Authorization
auth *authz.Policy
acl *netacl.Policy
// Runtime. Stop closes flush; the broadcast loop then moves what remains
// of its input to tail and closes flushed; each writer writes its queue
@@ -149,6 +151,10 @@ func NewTCPSinkPlugin(
if err != nil {
return nil, err
}
aclPolicy, err := netacl.New(opts.ACL, opts.Host, logger, "tcp_sink", id)
if err != nil {
return nil, err
}
t := &TCPSink{
id: id,
@@ -166,6 +172,7 @@ func NewTCPSinkPlugin(
writeTimeout: time.Duration(opts.WriteTimeoutMS) * time.Millisecond,
tlsConfig: tlsCfg,
auth: authPolicy,
acl: aclPolicy,
}
t.lastProcessed.Store(time.Time{})
@@ -176,7 +183,8 @@ func NewTCPSinkPlugin(
"port", opts.Port,
"tls", tlsCfg != nil,
"mtls", tlsCfg != nil && tlsCfg.ClientAuth == tls.RequireAndVerifyClientCert,
"auth", authPolicy.Describe())
"auth", authPolicy.Describe(),
"acl", aclPolicy.Describe())
tlsx.LogWarnings(logger, "tcp_sink", id, opts.TLS, true)
authPolicy.LogStartup(logger, "tcp_sink", id, false)
return t, nil
@@ -214,6 +222,7 @@ func (t *TCPSink) listen() (net.Listener, error) {
if err != nil {
return nil, err
}
ln = t.acl.Listener(ln)
if t.tlsConfig != nil {
ln = tls.NewListener(ln, t.tlsConfig)
}
@@ -556,6 +565,7 @@ func (t *TCPSink) GetStats() sink.SinkStats {
"tls_handshake_errors": t.tlsHandshakeErrors.Load(),
}
maps.Copy(details, t.auth.Stats())
maps.Copy(details, t.acl.Stats())
return sink.SinkStats{
ID: t.id,
+38 -34
View File
@@ -219,8 +219,7 @@ func (t *TCPChainSink) Start(ctx context.Context) error {
return nil
}
// Stop terminates the forwarding loop. Worst-case latency: one write timeout
// plus one backoff wait (both interruptible or bounded).
// Stop delivers what is queued within sink.FlushBound, then ends the loop
func (t *TCPChainSink) Stop() {
t.logger.Info("msg", "Stopping TCP chain sink",
"component", "tcp_chain_sink",
@@ -273,49 +272,53 @@ func (t *TCPChainSink) runLoop(ctx context.Context) {
defer t.wg.Done()
defer t.closeConn()
// Fold done into the context, so a connect or exchange in flight ends on Stop
ctx, cancel := context.WithCancel(ctx)
// Stop leaves sink.FlushBound to deliver the queue, so a finite input
// arrives whole; a connect, exchange or link still open then ends
ctx, cancel := sink.FlushContext(ctx, t.done, t.writeTimeout)
defer cancel()
go func() {
select {
case <-t.done:
cancel()
case <-ctx.Done():
}
}()
for {
select {
case <-ctx.Done():
return
case <-t.done:
for len(t.input) > 0 {
if !t.forward(ctx, <-t.input) {
return
}
}
return
case event, ok := <-t.input:
if !ok {
case event := <-t.input:
if !t.forward(ctx, event) {
return
}
entry, synthesized := chain.EntryFromEvent(event, t.node, t.id)
if synthesized {
t.synthesized.Add(1)
}
line, err := json.Marshal(entry)
if err != nil {
// Non-transient: drop
t.logger.Error("msg", "Failed to marshal chain entry",
"component", "tcp_chain_sink",
"error", err)
continue
}
if !t.deliver(ctx, append(line, '\n')) {
return // shutdown during retry
}
t.totalProcessed.Add(1)
t.lastProcessed.Store(time.Now())
t.proxy.UpdateActivity(t.session.ID)
}
}
}
// forward delivers one event; false once shutdown ends the delivery
func (t *TCPChainSink) forward(ctx context.Context, event core.TransportEvent) bool {
entry, synthesized := chain.EntryFromEvent(event, t.node, t.id)
if synthesized {
t.synthesized.Add(1)
}
line, err := json.Marshal(entry)
if err != nil {
// Non-transient: drop
t.logger.Error("msg", "Failed to marshal chain entry",
"component", "tcp_chain_sink",
"error", err)
return true
}
if !t.deliver(ctx, append(line, '\n')) {
return false
}
t.totalProcessed.Add(1)
t.lastProcessed.Store(time.Now())
t.proxy.UpdateActivity(t.session.ID)
return true
}
// deliver writes one line, holding it across reconnects until sent or shutdown.
// Backpressure during outage propagates to the pipeline dispatch drop counter.
func (t *TCPChainSink) deliver(ctx context.Context, line []byte) bool {
@@ -399,11 +402,14 @@ func (t *TCPChainSink) connect(ctx context.Context) error {
return err
}
// A source never writes once a link is up: a line is a refusal this sink
// could not otherwise see, EOF a close. Stop writing into either.
// could not otherwise see, EOF a close. Stop writing into either. The end
// of ctx closes the link too, cutting short a write in flight.
stop := context.AfterFunc(ctx, func() { conn.Close() })
t.wg.Add(1)
go func() {
defer t.wg.Done()
err := authz.AwaitClose(r)
stop()
conn.Close()
if errors.Is(err, authz.ErrRefused) {
t.logger.Warn("msg", "Chain link refused",
@@ -450,7 +456,5 @@ func (t *TCPChainSink) waitBackoff(ctx context.Context, failures int) bool {
return true
case <-ctx.Done():
return false
case <-t.done:
return false
}
}
+71
View File
@@ -2,8 +2,10 @@ package tcpchain
import (
"bufio"
"fmt"
"net"
"strconv"
"strings"
"sync/atomic"
"testing"
"time"
@@ -66,3 +68,72 @@ func TestRefusingSourceIsRetriedWithBackoff(t *testing.T) {
t.Fatalf("%d connections in 1.5 s against a refusing source", n)
}
}
// Stop delivers what is queued, so the end of a finite input reaches the
// source whole, and returns at the flush bound when the source stops reading.
func TestStopDeliversTheQueueWithinTheBound(t *testing.T) {
const n = 2000 // of 8 KiB: more than a stalled source's socket buffers hold
padding := strings.Repeat("x", 8192)
manager := session.NewManager(time.Hour)
t.Cleanup(manager.Stop)
// stop queues n entries, starts and stops a sink, and returns how long
// Stop took and how many entries a reading source received
stop := func(reading bool) (time.Duration, int) {
ln, err := net.Listen("tcp4", "127.0.0.1:0")
if err != nil {
t.Fatal(err)
}
t.Cleanup(func() { ln.Close() })
lines := make(chan int, 1)
go func() {
conn, err := ln.Accept()
if err != nil {
return
}
defer conn.Close()
if !reading {
<-t.Context().Done()
return
}
count, scanner := -1, bufio.NewScanner(conn) // -1: the hello
scanner.Buffer(nil, 64*1024)
for scanner.Scan() {
count++
}
lines <- count
}()
_, port, _ := net.SplitHostPort(ln.Addr().String())
p, _ := strconv.ParseInt(port, 10, 64)
created, err := NewTCPChainSinkPlugin("fwd", map[string]any{
"host": "127.0.0.1", "port": p, "buffer_size": int64(n), // writes time out at 5 s
}, log.NewLogger(), session.NewProxy(manager, "fwd"))
if err != nil {
t.Fatal(err)
}
sink := created.(*TCPChainSink)
for i := range n {
sink.Input() <- core.TransportEvent{Time: time.Now(), Payload: fmt.Appendf(nil, "entry %d %s", i, padding)}
}
if err := sink.Start(t.Context()); err != nil {
t.Fatal(err)
}
start := time.Now()
sink.Stop()
d := time.Since(start)
if !reading {
return d, 0
}
select {
case got := <-lines:
return d, got
case <-time.After(5 * time.Second):
return d, 0
}
}
if _, got := stop(true); got != n {
t.Fatalf("the source received %d of %d entries", got, n)
}
if d, _ := stop(false); d > 3500*time.Millisecond {
t.Fatalf("Stop took %v past a 2 s flush bound", d)
}
}