EOF while connecting to the server

Question

EOF while connecting to the server

Closed this issue 2 years ago · 10 comments

I received the following error in the error log emitted by this library while connecting with a server instance created using this

Error

{"level":"error","timestamp":"2022-10-10T16:47:51.717162+05:30","caller":"psql-wire@v0.2.0/wire.go:105","msg":"an unexpected error got returned while serving a client connection","error":"EOF","stacktrace":"github.com/jeroenrinzema/psql-wire.(*Server).Serve.func2\n\t/Users/kishanb/go/pkg/mod/github.com/jeroenrinzema/psql-wire@v0.2.0/wire.go:105"}

Simulation steps

Main program

import (
	"context"
	"crypto/tls"
	"fmt"
	wire "github.com/jeroenrinzema/psql-wire"
	"go.uber.org/zap"
)

func main(){
   RunPostgresRedshiftProxy()
}

func RunPostgresRedshiftProxy() error {
	server, err := wire.NewServer(wire.Logger(constructLogger()), wire.SimpleQuery(queryHandler), wire.ClientAuth(tls.NoClientCert))
	if err != nil {
		return fmt.Errorf("error while instantiating server: %w", err)
	}
	err = server.ListenAndServe("127.0.0.1:25432")
	if err != nil {
		return fmt.Errorf("error while listening: %w", err)
	}
	return nil
}

func queryHandler(ctx context.Context, query string, writer wire.DataWriter) error {
	fmt.Println(query)
	return writer.Complete("OK")
}

func constructLogger() *zap.Logger {
	productionConfig := zap.NewProductionConfig()
	productionConfig.EncoderConfig.TimeKey = "timestamp"
	productionConfig.EncoderConfig.EncodeTime = zapcore.RFC3339NanoTimeEncoder
	logger, _ := productionConfig.Build()
	return logger
}

Test program

import (
	"context"
	"fmt"
	"github.com/jackc/pgx/v4"
	"github.com/stretchr/testify/require"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"testing"
)

func Test1(t *testing.T) {
	databaseUrl := "postgres://postgres:mypassword@localhost:25432/postgres"
	conn, err := pgx.Connect(context.Background(), databaseUrl)
	require.NoError(t, err)

	t.Run("test query execution", func(t *testing.T) {
		var name string
		var weight int64
		err = conn.QueryRow(context.Background(), "select name, weight from widgets limit 1").Scan(&name, &weight)
		require.NoError(t, err)
		fmt.Println(name, weight)
	})
}

Start the server using go run
Run the above test using go test and observe the logs from the server

Answer 1 · 2022-10-10T11:31:39.000Z

Not sure if these are related, but when i try to connect to the instance via pgcli i get the following error

$ pgcli -h localhost -p 25432
connection failed: :1), port 25432 failed: could not receive data from server: Connection refused
could not send SSL negotiation packet: Connection refused

Answer 2 · 2022-10-10T12:08:29.000Z

Hi @kishaningithub, thanks for reporting this! Would you be able to set the log level of the psql server to debug and provide the full debug logs?

Answer 3 · 2022-10-10T12:18:25.000Z

These are the logs when running the above test

{"level":"info","timestamp":"2022-10-10T17:47:32.9397+05:30","caller":"psql-wire@v0.2.0/wire.go:77","msg":"serving incoming connections","addr":"127.0.0.1:25432"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.911696+05:30","caller":"psql-wire@v0.2.0/wire.go:115","msg":"serving a new client connection"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.920193+05:30","caller":"psql-wire@v0.2.0/handshake.go:137","msg":"attempting to upgrade the client to a TLS connection"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.920349+05:30","caller":"psql-wire@v0.2.0/handshake.go:140","msg":"no TLS certificates available continuing with a insecure connection"}
{"level":"error","timestamp":"2022-10-10T17:47:38.920971+05:30","caller":"psql-wire@v0.2.0/wire.go:105","msg":"an unexpected error got returned while serving a client connection","error":"EOF","stacktrace":"github.com/jeroenrinzema/psql-wire.(*Server).Serve.func2\n\t/Users/kishanb/go/pkg/mod/github.com/jeroenrinzema/psql-wire@v0.2.0/wire.go:105"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.92127+05:30","caller":"psql-wire@v0.2.0/wire.go:115","msg":"serving a new client connection"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.922459+05:30","caller":"psql-wire@v0.2.0/wire.go:126","msg":"handshake successfull, validating authentication"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.92265+05:30","caller":"psql-wire@v0.2.0/handshake.go:68","msg":"reading client parameters"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.922663+05:30","caller":"psql-wire@v0.2.0/handshake.go:86","msg":"client parameter","key":"user","value":"postgres"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.922674+05:30","caller":"psql-wire@v0.2.0/handshake.go:86","msg":"client parameter","key":"database","value":"postgres"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.922688+05:30","caller":"psql-wire@v0.2.0/auth.go:33","msg":"authenticating client connection"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.922776+05:30","caller":"psql-wire@v0.2.0/wire.go:139","msg":"connection authenticated, writing server parameters"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.92279+05:30","caller":"psql-wire@v0.2.0/handshake.go:102","msg":"writing server parameters"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.923495+05:30","caller":"psql-wire@v0.2.0/handshake.go:113","msg":"server parameter","key":"is_superuser","value":"off"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.923584+05:30","caller":"psql-wire@v0.2.0/handshake.go:113","msg":"server parameter","key":"session_authorization","value":"postgres"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.923599+05:30","caller":"psql-wire@v0.2.0/handshake.go:113","msg":"server parameter","key":"server_encoding","value":"UTF8"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.923617+05:30","caller":"psql-wire@v0.2.0/handshake.go:113","msg":"server parameter","key":"client_encoding","value":"UTF8"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.923633+05:30","caller":"psql-wire@v0.2.0/command.go:35","msg":"ready for query... starting to consume commands"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.923982+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":58,"type":"P"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.924032+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":16,"type":"D"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.924052+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":4,"type":"S"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.924095+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":22,"type":"B"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.924166+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":6,"type":"D"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.924197+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":9,"type":"E"}
{"level":"debug","timestamp":"2022-10-10T17:47:38.924218+05:30","caller":"psql-wire@v0.2.0/command.go:61","msg":"incoming command","length":4,"type":"S"}

Answer 4 · 2022-10-10T12:19:22.000Z

When running the pgcli command pgcli -h localhost -p 25432 there are no logs from the server

Answer 5 · 2022-10-10T12:22:32.000Z

It seems the pgcli client is using the extended query protocol. I am currently working on supporting extended queries (#17). Would you be able to checkout the draft PR I opened recently (#16) and see if this resolves your issue?

Answer 6 · 2022-10-10T13:03:08.000Z

@jeroenrinzema I checked out the feat/extended-queries branch in this repo and ran the example examples/simple/main.go and i got the same error when connecting via pgcli.

Let me know if i am doing any incorrect steps, i am happy to test this out. :-)

Screenshot

Answer 7 · 2022-10-10T15:12:43.000Z

@kishaningithub Would you be able to send me the debug logs using the feat/extended-queries branch? I am not fully supporting the extended query protocol (parameters still have to be implemented). This could be the reason to why the client is unable to connect to the server.

Answer 8 · 2022-10-13T13:05:25.000Z

Somehow the SSL issue seems to have magically disappeared (no clue why). In extended-queries branch now when i am getting a different error

Screenshot

Logs

➜  psql-wire git:(feat/extended-queries) ✗ go run examples/simple/main.go
2022/10/13 18:27:41 PostgreSQL server is up and running at [127.0.0.1:5432]
{"level":"info","timestamp":"2022-10-13T18:27:41.548997+05:30","caller":"psql-wire/wire.go:88","msg":"serving incoming connections","addr":"127.0.0.1:5432"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.525565+05:30","caller":"psql-wire/wire.go:126","msg":"serving a new client connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.602734+05:30","caller":"psql-wire/handshake.go:137","msg":"attempting to upgrade the client to a TLS connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.602848+05:30","caller":"psql-wire/handshake.go:140","msg":"no TLS certificates available continuing with a insecure connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603017+05:30","caller":"psql-wire/wire.go:137","msg":"handshake successfull, validating authentication"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603033+05:30","caller":"psql-wire/handshake.go:68","msg":"reading client parameters"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603038+05:30","caller":"psql-wire/handshake.go:86","msg":"client parameter","key":"user","value":"kishanb"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603044+05:30","caller":"psql-wire/handshake.go:86","msg":"client parameter","key":"database","value":"kishanb"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603047+05:30","caller":"psql-wire/handshake.go:86","msg":"client parameter","key":"application_name","value":"pgcli"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.60305+05:30","caller":"psql-wire/auth.go:33","msg":"authenticating client connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603075+05:30","caller":"psql-wire/wire.go:150","msg":"connection authenticated, writing server parameters"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.60308+05:30","caller":"psql-wire/handshake.go:102","msg":"writing server parameters"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603085+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"session_authorization","value":"kishanb"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603097+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"server_encoding","value":"UTF8"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603103+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"client_encoding","value":"UTF8"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603113+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"is_superuser","value":"off"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603121+05:30","caller":"psql-wire/command.go:38","msg":"ready for query... starting to consume commands"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603642+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":13,"type":"Q"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.603649+05:30","caller":"psql-wire/command.go:164","msg":"incoming query","query":"SELECT 1"}
2022/10/13 18:27:51 incoming SQL query: SELECT 1
{"level":"debug","timestamp":"2022-10-13T18:27:51.605418+05:30","caller":"psql-wire/wire.go:126","msg":"serving a new client connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.619433+05:30","caller":"psql-wire/handshake.go:137","msg":"attempting to upgrade the client to a TLS connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.619465+05:30","caller":"psql-wire/handshake.go:140","msg":"no TLS certificates available continuing with a insecure connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.62188+05:30","caller":"psql-wire/wire.go:137","msg":"handshake successfull, validating authentication"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621888+05:30","caller":"psql-wire/handshake.go:68","msg":"reading client parameters"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621891+05:30","caller":"psql-wire/handshake.go:86","msg":"client parameter","key":"user","value":"kishanb"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621896+05:30","caller":"psql-wire/handshake.go:86","msg":"client parameter","key":"database","value":"kishanb"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621901+05:30","caller":"psql-wire/handshake.go:86","msg":"client parameter","key":"application_name","value":"pgcli"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621904+05:30","caller":"psql-wire/auth.go:33","msg":"authenticating client connection"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621913+05:30","caller":"psql-wire/wire.go:150","msg":"connection authenticated, writing server parameters"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621916+05:30","caller":"psql-wire/handshake.go:102","msg":"writing server parameters"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621921+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"session_authorization","value":"kishanb"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621927+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"server_encoding","value":"UTF8"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621933+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"client_encoding","value":"UTF8"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.62194+05:30","caller":"psql-wire/handshake.go:113","msg":"server parameter","key":"is_superuser","value":"off"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.621945+05:30","caller":"psql-wire/command.go:38","msg":"ready for query... starting to consume commands"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.622316+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":13,"type":"Q"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.622326+05:30","caller":"psql-wire/command.go:164","msg":"incoming query","query":"SELECT 1"}
2022/10/13 18:27:51 incoming SQL query: SELECT 1
{"level":"debug","timestamp":"2022-10-13T18:27:51.622674+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":57,"type":"Q"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.622685+05:30","caller":"psql-wire/command.go:164","msg":"incoming query","query":"\n        SELECT * FROM unnest(current_schemas(true))"}
2022/10/13 18:27:51 incoming SQL query:
        SELECT * FROM unnest(current_schemas(true))
{"level":"debug","timestamp":"2022-10-13T18:27:51.622882+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":89,"type":"Q"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.622891+05:30","caller":"psql-wire/command.go:164","msg":"incoming query","query":"\n        SELECT  nspname\n        FROM    pg_catalog.pg_namespace\n        ORDER BY 1 "}
2022/10/13 18:27:51 incoming SQL query:
        SELECT  nspname
        FROM    pg_catalog.pg_namespace
        ORDER BY 1
{"level":"debug","timestamp":"2022-10-13T18:27:51.623449+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":282,"type":"P"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.623456+05:30","caller":"psql-wire/command.go:208","msg":"incoming query","query":"\n        SELECT  n.nspname schema_name,\n                c.relname table_name\n        FROM    pg_catalog.pg_class c\n                LEFT JOIN pg_catalog.pg_namespace n\n                    ON n.oid = c.relnamespace\n        WHERE   c.relkind = ANY($1)\n        ORDER BY 1,2;","name":""}
{"level":"debug","timestamp":"2022-10-13T18:27:51.623469+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":27,"type":"B"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.623472+05:30","caller":"psql-wire/command.go:262","msg":"reading parameters","length":1}
0 <nil>
1 <nil>
7 <nil>
[] <nil>
31602 <nil>
11376 <nil>
{"level":"debug","timestamp":"2022-10-13T18:27:51.623488+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":6,"type":"D"}
Describe Message:
[80] <nil>
 <nil>
{"level":"debug","timestamp":"2022-10-13T18:27:51.623499+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":9,"type":"E"}
{"level":"debug","timestamp":"2022-10-13T18:27:51.623501+05:30","caller":"psql-wire/command.go:294","msg":"executing","name":""}
2022/10/13 18:27:51 incoming SQL query:
        SELECT  n.nspname schema_name,
                c.relname table_name
        FROM    pg_catalog.pg_class c
                LEFT JOIN pg_catalog.pg_namespace n
                    ON n.oid = c.relnamespace
        WHERE   c.relkind = ANY($1)
        ORDER BY 1,2;
{"level":"debug","timestamp":"2022-10-13T18:27:51.623529+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":4,"type":"S"}
{"level":"debug","timestamp":"2022-10-13T18:28:09.218496+05:30","caller":"psql-wire/command.go:64","msg":"incoming command","length":4,"type":"X"}
{"level":"error","timestamp":"2022-10-13T18:28:09.218605+05:30","caller":"psql-wire/wire.go:116","msg":"an unexpected error got returned while serving a client connection","error":"write tcp 127.0.0.1:5432->127.0.0.1:59117: use of closed network connection","stacktrace":"github.com/jeroenrinzema/psql-wire.(*Server).Serve.func2\n\t/Users/kishanb/Programming/Personal/psql-wire/wire.go:116"}

Answer 9 · 2022-10-18T07:40:11.000Z

Perfect! I see that extended query protocol is working. I will try to finish the parameter support in order to merge these changes into main.

Answer 10 · 2022-10-19T13:18:33.000Z

Closing the issue as the fix is released