Nice Project

[jniltinho]

Hi, @wneessen

These errors appear constantly, policyd often stops working, I still don't know the reason, I've already done the tests with Golang 1.17, 1.18, 1.19,1.20 and 1.22,
I made some adjustments to Postfix.

postfix/smtpd[1270100]: warning: problem talking to server 127.0.0.1:11066: Connection timed out
postfix/smtpd[1270100]: warning: problem talking to server 127.0.0.1:11066: Connection timed out
Recipient address rejected: Server configuration problem;
Recipient address rejected: Server configuration problem;
postfix/smtpd[1272995]: warning: problem talking to server 127.0.0.1:11066: Connection timed out

I'm testing your project in an environment with a lot of email reception, I'd like to know how I can achieve this result here.
I receive many connections, it is constantly giving timeout, there is no way you can add go routines to accept a greater number of connections thus avoiding the timeout.

https://github.com/bejelith/policyd/blob/main/pkg/acceptor/acceptor_linux.go
https://github.com/d--j/go-milter

[jniltinho]

Limits

https://www.postfix.org/TUNING_README.html
https://stackoverflow.com/questions/20556224/golang-server-timeout

Linux kernel parameters can be specified in /etc/sysctl.conf or changed with sysctl commands:

fs.file-max=16384
kernel.threads-max=2048

/etc/sysctl.conf
net.core.somaxconn = 1024
net.core.netdev_max_backlog = 2048
net.ipv4.ip_local_port_range = 1024 65535
net.ipv4.tcp_max_syn_backlog = 2048
net.ipv4.tcp_fin_timeout = 20
net.ipv4.tcp_syncookies = 1
net.ipv4.tcp_timestamps = 1
net.ipv4.tcp_tw_reuse = 1
net.ipv4.tcp_rfc1337 = 1

[jniltinho]

:-(, UnixSock and TCP, Connection timed out

warning: problem talking to server private/isp-policyd: Connection timed out

[wneessen]

Hi @jniltinho,

I frankly haven't worked with PPS in a long time, so it's hard to tell out of the box, especially given that it's hard to replicate your environment. But yes, it sounds like you might be running into kernel limits here, indeed. There is also a Postfix tuning guide, not sure if you already checked that out: https://www.postfix.org/TUNING_README.html

PPS is already making use of Go routines, so I am not sure if there is optimization potential there, but I'll have a look in the next days if there is maybe something I can tweak.

[jniltinho]

I already corrected these parts of limits, I don't think that's it
I observed this behavior on a Server that I set up to test policyd in this controlled environment.
I'm looking at the code from another project to try to map out what can be improved,
I'm brushing bits into your project.
Thank you very much and sorry to disturb you.

https://github.com/bejelith/policyd/tree/main/pkg/handler

https://github.com/d--j/go-milter
https://github.com/bejelith/policyd

Hi @jniltinho,

I frankly haven't worked with PPS in a long time, so it's hard to tell out of the box, especially given that it's hard to replicate your environment. But yes, it sounds like you might be running into kernel limits here, indeed. There is also a Postfix tuning guide, not sure if you already checked that out: https://www.postfix.org/TUNING_README.html

PPS is already making use of Go routines, so I am not sure if there is optimization potential there, but I'll have a look in the next days if there is maybe something I can tweak.

[jniltinho]

clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=828128589}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=828514822}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
getpid()                                = 242163
tgkill(242163, 242167, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=828939599}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=829343858}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
getpid()                                = 242163
tgkill(242163, 242167, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=829745375}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=830147898}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
getpid()                                = 242163
tgkill(242163, 242167, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=830593585}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=830994936}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=831276444}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=831662029}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
getpid()                                = 242163
tgkill(242163, 242165, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=832145883}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=832571404}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=832889197}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=833291638}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=833542728}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=833904506}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
getpid()                                = 242163
tgkill(242163, 242167, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=834347815}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=834811074}) = 0
getpid()                                = 242163
tgkill(242163, 242168, SIGURG)          = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=835247634}) = 0
futex(0x623458, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=100000}) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=835764827}) = 0
getpid()                                = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 242163
tgkill(242163, 242168, SIGURG)          = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=840242871}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
futex(0xc000166148, FUTEX_WAKE_PRIVATE, 1) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=841760986}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=842373703}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=842488708}) = 0
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=842629371}) = 0
epoll_pwait(3, [], 128, 0, NULL, 0)     = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=842866508}) = 0
futex(0x623440, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=843088164}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=843579393}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
futex(0xc000080948, FUTEX_WAKE_PRIVATE, 1) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=844571943}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=845354563}) = 0
futex(0xc000080148, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x623458, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=845710896}) = 0
futex(0x622c80, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=847700239}) = 0
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x622c80, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=849989541}) = 0
futex(0x622c80, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=851945179}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=852114365}) = 0
futex(0xc000166148, FUTEX_WAKE_PRIVATE, 1) = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=852468794}) = 0
futex(0xc000166148, FUTEX_WAKE_PRIVATE, 1) = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=852607776}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=852671213}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=242163, si_uid=0} ---
rt_sigreturn({mask=[]})                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=852882230}) = 0
futex(0xc000166148, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x623458, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=853195648}) = 0
futex(0x623458, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=853356760}) = 0
futex(0x623458, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=853631450}) = 0
futex(0x623430, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x622c80, FUTEX_WAIT_PRIVATE, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x623458, FUTEX_WAKE_PRIVATE, 1)  = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=854173469}) = 0
futex(0x623358, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xc000080948, FUTEX_WAKE_PRIVATE, 1) = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=854564144}) = 0
nanosleep({tv_sec=0, tv_nsec=3000}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=855030592}) = 0
futex(0x622c80, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=856271060}) = 0
futex(0x622c80, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=37009, tv_nsec=857484002}) = 0

[jniltinho]

Hi @wneessen

I created a Simple TCP Daemon to check if the same problem occurs, I'm not having the same problem, the stream and connections are occurring without any errors.

package main

import (
	"bufio"
	"fmt"
	"log"
	"net"
	"strings"
)

func main() {
	listener, err := net.Listen("tcp", "127.0.0.1:11066")
	if err != nil {
		fmt.Println("Error starting server:", err)
		return
	}
	defer listener.Close()

	fmt.Println("Server started. Listening 127.0.0.1:11066...")

	for {
		conn, err := listener.Accept()
		if err != nil {
			fmt.Println("Error accepting connection:", err)
			continue
		}
		go handleConnection(conn)
	}
}

func handleConnection(conn net.Conn) {
	defer conn.Close()
	fmt.Println("Client connected:", conn.RemoteAddr())
	scanner := bufio.NewScanner(conn)
	var attr = make(map[string]string)

	for scanner.Scan() {
		line := scanner.Text()
		if line == "" {
			break
		}
		parts := strings.SplitN(line, "=", 2)
		attr[parts[0]] = parts[1]
		fmt.Println(line)
	}

	if err := scanner.Err(); err != nil {
		log.Printf("Error reading from connection: %s", err)
		return
	}

	responseString := fmt.Sprintf("action=%s\n\n", "DUNNO")
	fmt.Println("Client disconnected:", attr["client_address"])
	fmt.Println("------------------------------------------------------")

	if _, err := conn.Write([]byte(responseString)); err != nil {
		log.Printf("Error writing response: %s", err)
	}
}

[wneessen]

Interesting. Out of curriosity, could you test your environment with the simple echo server that is provided with PPS? https://github.com/wneessen/postfix-policy-server/blob/main/example-code/echo-server/main.go and see if it causes the same timeouts in your high-traffic environment?

[jniltinho]

I was already testing the Echo Server a few days ago when I came across this problem, so I did a simple test with this code and it worked correctly and is still running in the environment, I already got another code for the server which is this one with the settings , now I'm going to try to mix your project's code a little with my new Server, but now I understand better how it works, because I already knew how it works with Perl, I really appreciate your project, congratulations.
I have this code to create the Server.
I even made a document in my Gist, I'm just still trying to understand the context part, whether I really need context or not.

https://medium.com/@viktordev/build-a-concurrent-tcp-server-in-go-with-graceful-shutdown-include-unit-tests-2e2d63ee2161

https://gist.github.com/jniltinho/8ff31a444c9aa44d048b747dfc4ecf91

Interesting. Out of curriosity, could you test your environment with the simple echo server that is provided with PPS? https://github.com/wneessen/postfix-policy-server/blob/main/example-code/echo-server/main.go and see if it causes the same timeouts in your high-traffic environment?

[jniltinho]