go-ora ORA-01013 in v2.8.13

My application states ORA-01013 errors when accessing a prepared query. This error doesn't exist with v2.8.11

Apr 24 '24 11:04 Tommi2Day

me too ORA-01009: missing mandatory parameter didn't happen before last update in v2.8.13 when I was using v2.8.11

Apr 24 '24 16:04 rpuchadm

fixed in next release

Apr 24 '24 22:04 sijms

Just for understanding: You marked it as duplicate, but ORA-1013 "user requested cancel of current operation" is different error than ORA-1009 "missing mandantory parameter," isnt? Or is the same reason behind?

Apr 25 '24 10:04 Tommi2Day

I think it could be the same becase it is also a prepared query, let's see if next release fixes it

Apr 25 '24 12:04 rpuchadm

no, same issue mentioned here

Apr 25 '24 20:04 sijms

fixed 2.8.14

Apr 25 '24 23:04 sijms

Just for understanding: You marked it as duplicate, but ORA-1013 "user requested cancel of current operation" is different error than ORA-1009 "missing mandantory parameter," isnt? Or is the same reason behind?

@sijms I think it's different. I have this issue too now after upgrading from 2.8.11. I have a simple sql for watching db health every 15s, and context timeout is set to 5s. The new version 2.8.14 or 2.8.13 is unstable and there will be errors ORA-1013, but the old version has never been.

...
                                 selecttest:="SELECT systimestamp FROM dual"
                                 pingtmout, pingcle := context.WithTimeout(context.Background(), time.Second*time.Duration(5))
				getconn, err = srcdbtest.Connx(pingtmout)
				if err != nil {
					Zaplogger.Error("watchdog get conn failed", zap.String("driver", dstdriver),
						zap.String("dst-db-host", dsthost), zap.Int("dst-db-port", dstport),
						zap.String("dst-dbname", dstdbname), zap.Int("max-connection", maxConn), zap.Error(err))
				} else {
					_, err = getconn.ExecContext(pingtmout, selecttest)
					getconn.Close()
					if err != nil {
						Zaplogger.Error("watchdog exec failed", zap.String("driver", dstdriver),
							zap.String("dst-db-host", dsthost), zap.Int("dst-db-port", dstport),
							zap.String("dst-dbname", dstdbname), zap.Int("max-connection", maxConn), zap.Error(err))
					}
				}
...

Apr 26 '24 01:04 freeNestor

I make a testing code

package main

import (
	"context"
	"database/sql"
	"fmt"
	go_ora "github.com/sijms/go-ora/v2"
	"os"
	"time"
)

func main() {
	config, err := go_ora.ParseConfig(os.Getenv("DSN"))
	if err != nil {
		fmt.Println("can't parse DSN:", err)
		return
	}
	go_ora.RegisterConnConfig(config)
	db, err := sql.Open("oracle", "")
	if err != nil {
		fmt.Println("can't open DB:", err)
		return
	}
	defer func() {
		err := db.Close()
		if err != nil {
			fmt.Println("can't close DB:", err)
		}
	}()
	pingtmout, pingcle := context.WithTimeout(context.Background(), time.Second*time.Duration(5))
	defer pingcle()
	_, err = db.ExecContext(pingtmout, "SELECT systimestamp from dual")
	if err != nil {
		fmt.Println("can't ping DB:", err)
		return
	}

	pingtimout, pingcancel := context.WithTimeout(context.Background(), time.Second*time.Duration(5))
	defer pingcancel()
	_, err = db.ExecContext(pingtimout, "SELECT systimestamp from dual")
	if err != nil {
		fmt.Println("can't ping 2 DB:", err)
	}
}

and result is ok

Apr 26 '24 11:04 sijms

also I use the timeout context 2 times

pingtmout, pingcle := context.WithTimeout(context.Background(), time.Second*time.Duration(5))
defer pingcle()
_, err = db.ExecContext(pingtmout, "SELECT systimestamp from dual")
if err != nil {
	fmt.Println("can't ping DB:", err)
	return
}
_, err = db.ExecContext(pingtmout, "SELECT systimestamp from dual")
if err != nil {
	fmt.Println("can't ping 2 DB:", err)
}

result is ok also

Apr 26 '24 11:04 sijms

It's weird in my environment. Can you use below code to test? I also paste my environment info below. go-ora: 2.8.14 go version to build: 1.22.2 build arch: linux-amd64 os: centos 7.8 oracle: 19c

package main

import (
	"context"
	"fmt"
	"time"

	"github.com/jmoiron/sqlx"
	go_ora "github.com/sijms/go-ora/v2"
)

func main() {
	options := map[string]string{
		"TIMEOUT":            "60",
		"CONNECTION TIMEOUT": "5",
	}
	dsn := go_ora.BuildUrl(host, 1521, "orcldb", "test", "pass", options)

	conn, err := sqlx.Open("oracle", dsn)
	if err != nil {
		fmt.Printf("failed: %v\n", err)
		return
	}
	conn.SetMaxIdleConns(2)
	conn.SetMaxOpenConns(2)
	defer func() {
		err = conn.Close()
		if err != nil {
			fmt.Println("can't close db:", err)
		}
	}()

	selecttest := "SELECT systimestamp FROM dual"
	for {
		pingtmout, pingcle := context.WithTimeout(context.Background(), time.Second*time.Duration(5))
		getdur := time.Now().Local()
		getconn, err := conn.Connx(pingtmout)
		if err != nil {
			fmt.Println("can't get conn:", err)
		} else {
			execst := time.Now().Local()
			_, err = getconn.ExecContext(pingtmout, selecttest)
			getconn.Close()
			if err != nil {
				fmt.Println(time.Now().Local(), " ping db failed: ", err, " getdura: ", execst.Sub(getdur), " execdur: ", time.Since(execst))
			} else {
				fmt.Println(time.Now().Local(), " ping db succeeded, getdura: ", execst.Sub(getdur), " execdur: ", time.Since(execst))
			}
		}
		pingcle()
		time.Sleep(time.Second * 5)
	}
}

my test result is not ok:

Apr 28 '24 07:04 freeNestor

you use Connection timeout = 60 and Timeout = 5 they are same parameter

Apr 28 '24 12:04 sijms

output

2024-04-28 15:34:19.424186 +0300 +03  ping db succeeded, getdura:  831.739ms  execdur:  98.159ms
2024-04-28 15:34:24.530289 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  104.891ms
2024-04-28 15:34:29.630483 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  98.743ms
2024-04-28 15:34:34.722144 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  90.692ms
2024-04-28 15:34:39.825108 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  102.512ms
2024-04-28 15:34:44.918666 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  93.249ms
2024-04-28 15:34:50.015942 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  96.829ms
2024-04-28 15:34:55.112127 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  95.9ms
2024-04-28 15:35:00.235455 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  122.728ms
2024-04-28 15:35:05.329036 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  93.175ms
2024-04-28 15:35:10.424502 +0300 +03  ping db succeeded, getdura:  21µs  execdur:  94.886ms
2024-04-28 15:35:15.521778 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  96.694ms
2024-04-28 15:35:20.6209 +0300 +03  ping db succeeded, getdura:  8µs  execdur:  98.624ms
2024-04-28 15:35:25.721061 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  98.833ms
2024-04-28 15:35:30.856921 +0300 +03  ping db succeeded, getdura:  55µs  execdur:  134.451ms
2024-04-28 15:35:35.954974 +0300 +03  ping db succeeded, getdura:  23µs  execdur:  97.512ms
2024-04-28 15:35:41.049324 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  92.95ms
2024-04-28 15:35:46.14955 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  98.742ms
2024-04-28 15:35:51.246783 +0300 +03  ping db succeeded, getdura:  58µs  execdur:  96.099ms
2024-04-28 15:35:56.33884 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  91.394ms
2024-04-28 15:36:01.441155 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  102.118ms

Apr 28 '24 12:04 sijms

after setting timeout=5

2024-04-28 20:41:06.973845 +0300 +03  ping db succeeded, getdura:  663.595ms  execdur:  67.603ms
2024-04-28 20:41:12.048339 +0300 +03  ping db succeeded, getdura:  26µs  execdur:  73.874ms
2024-04-28 20:41:17.140386 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  90.811ms
2024-04-28 20:41:22.205758 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  64.161ms
2024-04-28 20:41:27.278699 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  71.883ms
2024-04-28 20:41:32.352729 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  72.821ms
2024-04-28 20:41:37.420044 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  66.082ms
2024-04-28 20:41:42.489153 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  67.869ms
2024-04-28 20:41:47.556788 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  67.139ms
2024-04-28 20:41:52.625404 +0300 +03  ping db succeeded, getdura:  5µs  execdur:  68.234ms
2024-04-28 20:41:57.715214 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  88.633ms
2024-04-28 20:42:02.801801 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  85.607ms
2024-04-28 20:42:07.876024 +0300 +03  ping db succeeded, getdura:  4µs  execdur:  73.037ms
2024-04-28 20:42:12.945687 +0300 +03  ping db succeeded, getdura:  6µs  execdur:  68.559ms

Apr 28 '24 17:04 sijms

you use Connection timeout = 60 and Timeout = 5 they are same parameter

How to achieve different timeout about connect timeout and session read timeout? BTW, the key is that it returns error before context timeout period from my test output, and 2.8.11 is ok in the same environment, this confuses me. You should test multiple times and watch a while, sometimes error occurs frequently, sometimes less.

as you can see from below shot, I print the context.Err(), it returns nil, so context is not timeout actually.

Apr 29 '24 00:04 freeNestor

For me 2.8.14 was not solving the problem. ORA-1013 still appears regardless of the timeout (before was 3s with 2.8.11, now i set 10s). Do i am missing a new timeout parameter to set?

I am connecting like this dbh, err = sqlx.Open(driver, source) if err != nil { return nil, err } // Create a context with timeout, using the empty // context.Background() as the parent. ctx, cancel := context.WithTimeout(context.Background(), time.Duration(timeout)*time.Second) defer cancel() // Use this when testing the connection pool. if err = dbh.PingContext(ctx); err != nil { log.Debugf("DB Connect returned error= %s", err) return nil, err }

This works fine. Afterwards i am creating a prepared Query // PrepareSQL parses a sql for a given connection and returns statement handler func PrepareSQL(dbh *sqlx.DB, mySQL string) (stmt *sqlx.Stmt, err error) { log.Debugf("PrepareSql entered") ok, t := common.CheckType(dbh, "*sqlx.DB") if !ok { err = fmt.Errorf("invalid dbh %s", t) return } stmt, err = dbh.Preparex(mySQL) if err != nil { err = fmt.Errorf("prepare failed:%s (%s)", err, mySQL) } return } and execute it here func SelectStmt(stmt *sqlx.Stmt, args ...any) (rows *sqlx.Rows, err error) { log.Debugf("QueryStmt entered") ok, t := common.CheckType(stmt, "*sqlx.Stmt") if !ok { err = fmt.Errorf("invalid stmt %s", t) return } log.Debugf("Parameter values: %v", args...) rows, err = stmt.Queryx(args...) return }

Result: time="Mon, 29 Apr 2024 17:53:13 CEST" level=debug msg="successfully connected to myuser@mydb" time="Mon, 29 Apr 2024 17:53:13 CEST" level=debug msg="Connected to mydb" time="Mon, 29 Apr 2024 17:53:13 CEST" level=debug msg="PrepareSql entered" time="Mon, 29 Apr 2024 17:53:13 CEST" level=debug msg="Check Repo for user test" time="Mon, 29 Apr 2024 17:53:13 CEST" level=debug msg="QueryStmt entered" time="Mon, 29 Apr 2024 17:53:13 CEST" level=debug msg="Parameter values: test" time="Mon, 29 Apr 2024 17:53:13 CEST" level=warning msg="repo query failed for test:ORA-01013: User requested cancel of current operation.

Apr 29 '24 16:04 Tommi2Day

the code after format:

// context.Background() as the parent. 
ctx, cancel := context.WithTimeout(context.Background(), time.Duration(timeout)*time.Second) 
defer cancel() 
// Use this when testing the connection pool. 
if err = dbh.PingContext(ctx); err != nil { 
	log.Debugf("DB Connect returned error= %s", err) return nil, err 
}

// This works fine. Afterwards i am creating a prepared Query

// PrepareSQL parses a sql for a given connection and returns statement handler 
func PrepareSQL(dbh *sqlx.DB, mySQL string) (stmt *sqlx.Stmt, err error) { 
	log.Debugf("PrepareSql entered") 
	ok, t := common.CheckType(dbh, "*sqlx.DB") 
	if !ok { 
		err = fmt.Errorf("invalid dbh %s", t) 
		return 
	} 
	stmt, err = dbh.Preparex(mySQL) 
	if err != nil { 
		err = fmt.Errorf("prepare failed:%s (%s)", err, mySQL) 
	} 
	return 
}
// and execute it here
func SelectStmt(stmt *sqlx.Stmt, args ...any) (rows *sqlx.Rows, err error) { 
	log.Debugf("QueryStmt entered") 
	ok, t := common.CheckType(stmt, "*sqlx.Stmt") 
	if !ok { 
		err = fmt.Errorf("invalid stmt %s", t) 
		return 
	} 
	log.Debugf("Parameter values: %v", args...) 
	rows, err = stmt.Queryx(args...) 
	return 
}

May 02 '24 15:05 sijms

I make an example code that use sqlx timeout in connection string = 3

package main

import (
	"context"
	"fmt"
	"github.com/jmoiron/sqlx"
	_ "github.com/sijms/go-ora/v2"
	go_ora "github.com/sijms/go-ora/v2"
	"os"
	"time"
)

func main() {
	db, err := sqlx.Open("oracle", os.Getenv("DSN"))
	if err != nil {
		fmt.Println("can't connect: ", err)
		return
	}
	ctx, cancel := context.WithTimeout(context.Background(), time.Duration(3)*time.Second)
	defer cancel()
	err = db.PingContext(ctx)
	if err != nil {
		fmt.Println("can't ping: ", err)
		return
	}
	stmt, err := db.Preparex("BEGIN SELECT systimestamp INTO :1 FROM dual; END;")
	if err != nil {
		fmt.Println("can't prepare: ", err)
		return
	}
	defer func() {
		err = stmt.Close()
		if err != nil {
			fmt.Println("can't close: ", err)
		}
	}()
	var result time.Time
	_, err = stmt.Exec(go_ora.Out{Dest: &result})
	if err != nil {
		fmt.Println("can't query: ", err)
		return
	}
	fmt.Println("result: ", result)
}

output

result:  2024-05-02 15:08:46.206119 +0000 UTC

May 02 '24 15:05 sijms

this is the code which will produce the error

package main

import (
	"context"
	"database/sql"
	"fmt"
	_ "github.com/sijms/go-ora/v2"
	"net"
	"os"
	"time"
)

func dbLock(conn *sql.DB) error {
	execCtx, execCancel := context.WithTimeout(context.Background(), 3*time.Second)
	defer execCancel()
	_, err := conn.ExecContext(execCtx, "begin DBMS_LOCK.sleep(5); end;")
	if err != nil {
		if err, ok := err.(*net.OpError); ok {
			if err.Timeout() {
				fmt.Println("timeout occur")
			}
		}
		return err
	}
	return nil
}

func main() {
	db, err := sql.Open("oracle", os.Getenv("DSN"))
	if err != nil {
		fmt.Println("cannot connect to oracle db: ", err)
		return
	}
	defer func() {
		err := db.Close()
		if err != nil {
			fmt.Println("cannot close db: ", err)
		}
	}()
	err = db.Ping()
	if err != nil {
		fmt.Println("cannot ping db: ", err)
		return
	}
	err = dbLock(db)
	if err != nil {
		fmt.Println("db lock failed: ", err)
	}
	var result time.Time
	_, err = db.Exec("BEGIN SELECT systimestamp INTO :1 FROM dual; END;", sql.Out{Dest: &result})
	if err != nil {
		fmt.Println("cannot execute query: ", err)
		return
	}
	fmt.Println("result: ", result)
}

May 03 '24 22:05 sijms

I find the cause of the issue

May 04 '24 09:05 sijms

you can test last commit for confirmation

May 04 '24 11:05 sijms

ok, I'll test it on my first working day and back here.

May 04 '24 14:05 freeNestor

test latest commit several times, this error disappears.

May 06 '24 03:05 freeNestor

fixed 2.8.16

May 06 '24 05:05 sijms

i can confirm rel 2.8.16 solved my issue

May 08 '24 18:05 Tommi2Day

go-ora go-ora copied to clipboard

ORA-01013 in v2.8.13

go-ora
go-ora copied to clipboard