Hung connection to vertica

[misikch]

Hi! Can anybody help with understaning problem? I've got code like in examples:

	connDB, err := sql.Open("vertica", dwhConnection)
	if err != nil {
		return fmt.Errorf("failed to connect to dwh: %w", err)
	}
	defer connDB.Close()

	vCtx := vertigo.NewVerticaContext(context.Background())
	// Only keep 40,000 rows in memory at once.
	if err = vCtx.SetInMemoryResultRowLimit(40000); err != nil {
		return fmt.Errorf("failed to setup vertica context 'in memory row limit' param: %w", err)
	}

	if err = connDB.PingContext(vCtx); err != nil {
		return fmt.Errorf("failed to ping dwh vertica database: %w", err)
	}

set env VERTICA_SQL_GO_LOG_LEVEL=1 to debug connection:

Dec  8 22:35:08.397069 DEBUG connection: Established socket connection to vertica-proxy:5435
Dec  8 22:35:08.397491 DEBUG connection: -> Startup (packet): ProtocolVersion:00030009, DriverName='vertica-sql-go', DriverVersion='1.2.0', UserName='*******', Database='DWH', SessionID='vertica-sql-go-1.2.0-7362-1638992108', ClientPID=7362
Dec  8 22:35:08.444401 DEBUG connection: <- Authentication: 3, extraAuthData 0 byte(s)
Dec  8 22:35:08.444528 DEBUG connection: -> Password: *********
Dec  8 22:35:08.507618 DEBUG connection: <- Authentication: 0, extraAuthData 0 byte(s)
Dec  8 22:35:08.523473 DEBUG connection: <- ParameterStatus: client_locale='en_US@collation=binary'
Dec  8 22:35:08.523540 DEBUG connection: <- ParameterStatus: client_label='vertica-sql-go-1.2.0-7362-1638992108'
Dec  8 22:35:08.523576 DEBUG connection: <- ParameterStatus: server_version='v9.2.1-5'
Dec  8 22:35:08.523618 DEBUG connection: <- ParameterStatus: long_string_types='on'
Dec  8 22:35:08.523648 DEBUG connection: <- ParameterStatus: protocol_version='196616'
Dec  8 22:35:08.523676 DEBUG connection: <- ParameterStatus: standard_conforming_strings='on'
Dec  8 22:35:08.523710 DEBUG connection: <- KeyData: BackendPID=15975925, CancelKey=320BD015'
Dec  8 22:35:08.523746 DEBUG connection: <- Notice: (7) notice(s)
Dec  8 22:35:08.523779 DEBUG connection: <- ReadyForQuery: TransactionState='I'
Dec  8 22:35:08.523842 DEBUG stmt: stmt.QueryContextRaw(): select now()::timestamptz
Dec  8 22:35:08.523986 DEBUG connection: -> Query: Query='select now()::timestamptz'
Dec  8 22:35:08.573319 DEBUG connection: <- RowDesc: 1 column(s)
Dec  8 22:35:08.573379 DEBUG connection: <- Cmd Completed: 
Dec  8 22:35:08.573404 DEBUG connection: <- ReadyForQuery: TransactionState='T'
Dec  8 22:35:08.573424 DEBUG connection: Setting server timezone offset to +03
Dec  8 22:35:08.573524 DEBUG connection: -> Parse: PreparedName='S736216389921082019727887', Command='select 1 as test', NumArgs=0
Dec  8 22:35:08.573587 DEBUG connection: -> Describe: TargetType=S, TargetName='S736216389921082019727887'
Dec  8 22:35:08.573614 DEBUG connection: -> Flush
Dec  8 22:35:08.622399 DEBUG connection: <- ParseComplete
Dec  8 22:35:08.622474 DEBUG connection: <- ParameterDesc: 0 parameter(s) described: []
Dec  8 22:35:08.622516 DEBUG connection: <- RowDesc: 1 column(s)
Dec  8 22:35:08.622623 DEBUG connection: -> Close: TargetType=S, TargetName='S736216389921082019727887'
Dec  8 22:35:08.622677 DEBUG connection: -> Flush
Dec  8 22:35:08.622724 DEBUG connection: <- Cmd Description: tag=SELECT, hasRewrite=false, rewrite=''

So, thats it) after that nothing else happens

[sitingren]

The regular workflow should have a DEBUG connection: <- CloseComplete line at the end of such log file. Looks like the server doesn't send a CloseComplete message to the client.

One suspicious thing in this log file is that after the session is created there is an additional Notice message. Unfortunately the go client currently doesn't implement notice reading. Therefore please try to modify the source code msgs/benoticemsg.go and print the notice, or connect with vsql to see if there are any notice pop up after login.

[huebnerr]

I should make an enhancement to print out the Notice messages if running at log level 0.