runtime: goroutine not starting

[krasnovu]

What version of Go are you using (go version)?

$ go version
go version go1.19.4 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOENV="/home/user/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/user/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/user/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.19.4"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/user/projects/pam/go.mod"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3159640698=/tmp/go-build -gno-record-gcc-switches"

What did you do?

First of all sorry for my english.
I wrote PAM module on Golang, but when I connect by ssh, pam starts and module stuck. Stuck on http package in dialConnFor which is called as a goroutine in line transport.go.

Minimal project for reproduce issue:

1. May be you need install pam dev package
   sudo apt install libpam0g-dev
2. Create files:

main.go

package main

/*
#include <security/pam_modules.h>
typedef const char cchar_t;
*/
import "C"
import (
	"log"
	"time"
)

func main() {
    // for check output in simple `go run main.go`
	pam_sm_authenticate(nil, 0, 0, nil)
}

//export pam_sm_authenticate
func pam_sm_authenticate(pamh *C.pam_handle_t, flags C.int, argc C.int, argv **C.cchar_t) C.int {
	log.Printf("golib.so: begin")
	defer log.Printf("golib.so: end")

	log.Printf("golib.so: before start goroutine")
	go func() {
		log.Printf("golib.so: goroutine begin")
		defer log.Printf("golib.so: goroutine end")

		for i := 0; i < 5; i++ {
			log.Printf("golib.so: from goroutine: %d", i)
			time.Sleep(10 * time.Millisecond)
		}
	}()
	log.Printf("golib.so: after start goroutine")

	for i := 0; i < 5; i++ {
		//runtime.Gosched()
		log.Printf("golib.so: from method: %d", i)
		time.Sleep(10 * time.Millisecond)
	}

	return C.PAM_SUCCESS
}

Dockerfile

FROM ubuntu:22.04

RUN apt-get -qq update \
    && apt-get -yqq install openssh-server \
    && apt-get -yqq clean \
    && mkdir /var/run/sshd

RUN sed -i "s/#Port 22/Port 2222/" /etc/ssh/sshd_config \
    && sed -i "s/KbdInteractiveAuthentication no/KbdInteractiveAuthentication yes/" /etc/ssh/sshd_config \
    && sed -i "s/#LogLevel INFO/LogLevel DEBUG3/" /etc/ssh/sshd_config \
    && sed -i "1 i\auth optional golib.so" /etc/pam.d/common-auth

ENTRYPOINT ["/usr/sbin/sshd", "-D", "-e"]

docker-compose.yml

version: '3.3'

services:
  pam:
    build:
      context: .
    container_name: golib
    volumes:
      - "./:/usr/lib/security"
      - "/etc/timezone:/etc/timezone:ro"
      - "/etc/localtime:/etc/localtime:ro"
    network_mode: "host"

3. Build PAM module: go build --buildmode=c-shared -o golib.so ./
4. Build docker image sudo docker-compose build
5. Run image container sudo docker-compose up
6. In second terminal trying connect ssh -p 2222 any@localhost

What did you expect to see?

2022/12/18 20:42:22 golib.so: begin
2022/12/18 20:42:22 golib.so: before start goroutine
2022/12/18 20:42:22 golib.so: after start goroutine
2022/12/18 20:42:22 golib.so: from method: 0
2022/12/18 20:42:22 golib.so: goroutine begin
2022/12/18 20:42:22 golib.so: from goroutine: 0
2022/12/18 20:42:22 golib.so: from method: 1
2022/12/18 20:42:22 golib.so: from goroutine: 1
2022/12/18 20:42:22 golib.so: from goroutine: 2
2022/12/18 20:42:22 golib.so: from method: 2
2022/12/18 20:42:22 golib.so: from method: 3
2022/12/18 20:42:22 golib.so: from goroutine: 3
2022/12/18 20:42:22 golib.so: from goroutine: 4
2022/12/18 20:42:22 golib.so: from method: 4
2022/12/18 20:42:22 golib.so: end

What did you see instead?

First terminal:

go build --buildmode=c-shared -o golib.so ./
sudo docker-compose build
sudo docker-compose up

Output:

[...skipped...]
Starting golib ... done
Attaching to golib
golib  | debug3: oom_adjust_setup
golib  | debug1: Set /proc/self/oom_score_adj from 0 to -1000
golib  | debug2: fd 3 setting O_NONBLOCK
golib  | debug1: Bind to port 2222 on 0.0.0.0.
golib  | Server listening on 0.0.0.0 port 2222.
golib  | debug2: fd 4 setting O_NONBLOCK
golib  | debug3: sock_set_v6only: set socket 4 IPV6_V6ONLY
golib  | debug1: Bind to port 2222 on ::.
golib  | Server listening on :: port 2222.

Then, in second terminal try connect to container:

ssh -p 2222 any@localhost

In first terminal you can see logs from go module and stucking, then sshd (or pam) timeout message:

[...skipped...]
golib  | debug3: monitor_read: checking request 106
golib  | debug3: mm_answer_pam_query
golib  | debug3: PAM: sshpam_query entering
golib  | debug3: ssh_msg_recv entering
golib  | 2022/12/19 19:43:09 golib.so: begin
golib  | 2022/12/19 19:43:09 golib.so: before start goroutine
golib  | 2022/12/19 19:43:09 golib.so: after start goroutine
golib  | 2022/12/19 19:43:09 golib.so: from method: 0
golib  | Timeout before authentication for 127.0.0.1 port 58588

Help me please, why goroutine not starting?

I was looking for issues with the same keywords and this might be issue #44176?

p.s.
socketpair
call ssh_msg_recv
debug3: ssh_msg_recv entering

Thank you for your attention!

[seankhliao]

This is an unsynchronized program, there is no guarantee on goroutine scheduling ordering or execution before program exit.
It would appear to be unrelated to any issue you may have with net/http code.

Unlike many projects, the Go project does not use GitHub Issues for general discussion or asking questions. GitHub Issues are used for tracking bugs and proposals only.

For questions please refer to https://github.com/golang/go/wiki/Questions

[krasnovu]

@seankhliao, no, no, I think You are inattentive. If the problem was in the simple synchronization of goroutines, then we would see the following output:

2022/12/19 20:42:22 golib.so: from method: 0
2022/12/19 20:42:22 golib.so: from method: 1
2022/12/19 20:42:22 golib.so: from method: 2
2022/12/19 20:42:22 golib.so: from method: 3
2022/12/19 20:42:22 golib.so: from method: 4
2022/12/19 20:42:22 golib.so: end

There is also the main loop, which should work in the method, regardless of the goroutines. And pay attention to the last message defer log.Printf("golib.so: end")

If you don't like my simple example, here are two more with a similar problem. The first with goroutine synchronization, the second with http package.

1. With goroutine synchronization

main.go

package main

/*
#include <security/pam_modules.h>
typedef const char cchar_t;
*/
import "C"
import (
	"log"
	"sync"
)

func main() {}

//export pam_sm_authenticate
func pam_sm_authenticate(pamh *C.pam_handle_t, flags C.int, argc C.int, argv **C.cchar_t) C.int {
	log.Printf("golib.so: begin")
	defer log.Printf("golib.so: end")

	var wg sync.WaitGroup
	wg.Add(1)

	go func(wg *sync.WaitGroup) {
		log.Printf("golib.so: this message will not be printed")
		wg.Done()
	}(&wg)

	wg.Wait()

	return C.PAM_SUCCESS
}

Output:

golib  | 2022/12/20 08:55:42 golib.so: begin
golib  | Timeout before authentication for 127.0.0.1 port 58616

2. With http package

main.go

package main

/*
#include <security/pam_modules.h>
typedef const char cchar_t;
*/
import "C"
import (
	"log"
	"net/http"
	"time"
)

func main() {}

//export pam_sm_authenticate
func pam_sm_authenticate(pamh *C.pam_handle_t, flags C.int, argc C.int, argv **C.cchar_t) C.int {
	log.Printf("golib.so: begin")
	defer log.Printf("golib.so: end")

	client := http.Client{
		Timeout: 1 * time.Second,
	}
	client.Get("http://github.com")

	log.Printf("golib.so: this message will not be printed")

	return C.PAM_SUCCESS
}

Please, don't tell me to check the network settings!
The same output:

golib  | 2022/12/20 09:14:02 golib.so: begin
golib  | Timeout before authentication for 127.0.0.1 port 58624

Trouble starting goroutine, ssh somehow breaks golang goroutine scheduler. But I dont know how.

[seankhliao]

then probably ssh is opening the module, then forking, which breaks see #15538

[krasnovu]

Thanks @seankhliao! This information helped in understanding the cause of the problem! 🙏