Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: goroutine not starting #57394

Closed
krasnovu opened this issue Dec 19, 2022 · 4 comments
Closed

runtime: goroutine not starting #57394

krasnovu opened this issue Dec 19, 2022 · 4 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge

Comments

@krasnovu
Copy link

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"
  1. Build PAM module: go build --buildmode=c-shared -o golib.so ./
  2. Build docker image sudo docker-compose build
  3. Run image container sudo docker-compose up
  4. 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!

@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Dec 19, 2022
@seankhliao
Copy link
Member

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

@seankhliao seankhliao closed this as not planned Won't fix, can't repro, duplicate, stale Dec 19, 2022
@krasnovu
Copy link
Author

@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
  1. 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
Copy link
Member

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

@krasnovu
Copy link
Author

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

@golang golang locked and limited conversation to collaborators Dec 20, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge
Projects
None yet
Development

No branches or pull requests

3 participants