goroutines and tcp errors

[Virtual-Machine]

Full disclosure I may have something misconfigured with postgres.

max_connections on db = 1000

My understanding is that once you get the db object from the db.Open() that it is a connection pool, and it can be safely used inside goroutines for concurrent access.

However the below minimal example does one of 3 things on my machine.

1. Very rarely it runs to completion as expected.
2. Most often it fails with : "read tcp [::1]:port->[::1]:5432: read: connection reset by peer"
3. Rarely it fails with "write tcp [::1]:port->[::1]:5432: write: broken pipe"

Lowering the goroutines int variable increases the reliability, raising it makes failure a guarantee.
The number of records that prints to the terminal before an error changes each time I run a given binary.

package main

import (
	"database/sql"
	"fmt"
	_ "github.com/lib/pq"
	"os"
)

func main() {
	// Connect to db
	connStr := "postgres://@localhost/test?sslmode=disable"
	db, err := sql.Open("postgres", connStr)
	if err != nil {
		panic(err.Error())
	}
	defer db.Close()

	err = db.Ping()
	if err != nil {
		panic(err.Error())
	}

	goroutines := 300

	// Channel to syncronize goroutines
	channel := make(chan int, goroutines)

	// Generate goroutines to select records and interate them
	for i := 0; i < goroutines; i++ {
		go func(j int) {
			rows, err := db.Query("select name, age from contacts where age = $1", j)
			if err != nil {
				fmt.Println(err)
				os.Exit(-1)
			}
			var name string
			var age int
			for rows.Next() {
				err := rows.Scan(&name, &age)
				if err != nil {
					fmt.Println(err)
					os.Exit(-1)
				}
			}
			fmt.Println(name, age)
			err = rows.Err()
			if err != nil {
				fmt.Println(err)
				os.Exit(-1)
			}
			rows.Close()
			channel <- 0
		}(i)
	}

	// Wait for goroutines to finish
	for i := 0; i < goroutines; i++ {
		<-channel
	}
}

[cbandy]

When it fails, what is in the PostgreSQL (server) logs?

[Virtual-Machine]

Let me know if you want me to enable more detailed logging or enable another logging option, this is what I see in the log around the time of a pipe breaking:

2018-03-20 14:02:18.853 EDT [16753] LOCATION:  shmem_exit, ipc.c:259
2018-03-20 14:02:18.853 EDT [16753] DEBUG:  00000: proc_exit(-1): 0 callbacks to make
2018-03-20 14:02:18.853 EDT [16753] LOCATION:  proc_exit_prepare, ipc.c:188
2018-03-20 14:02:18.853 EDT [16504] DEBUG:  00000: forked new backend, pid=16756 socket=12
2018-03-20 14:02:18.853 EDT [16504] LOCATION:  BackendStartup, postmaster.c:4099
2018-03-20 14:02:18.853 EDT [16754] DEBUG:  00000: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2018-03-20 14:02:18.853 EDT [16754] LOCATION:  ShowTransactionStateRec, xact.c:5020
2018-03-20 14:02:18.854 EDT [16754] LOG:  08006: could not send data to client: Broken pipe
2018-03-20 14:02:18.854 EDT [16754] LOCATION:  internal_flush, pqcomm.c:1464
2018-03-20 14:02:18.854 EDT [16754] FATAL:  08006: connection to client lost

[dharmjit]

Hi, I am also facing the same issue. Random broken pipe errors. Is there any work around for this.

[gnuletik]

@dharmjit See #871 (comment) for workarounds.