Problems with busy_timeout with SQL lite, xorm seems to be ignoring it #1979

New Issue

ahall · 2021-07-07T15:33:07Z

ahall commented

2021-07-07 15:33:07 +00:00

Hi Lunny.

I have a program that uses SQL lite and I have a background process that is writing to SQL lite.

Then I have a CLI process that reads and writes to there. Sometimes they try to get a lock at the same time and in that case the busy timeout should make them wait for each other.

The SQLlite parameters are being passed through and I can see the driver is picking up the busy_timeout that I am passing through.

The problem is after I start a transaction and do an update on a model in the database then it fails immediately with Database locked instead of waiting for the busy wait time.

When I do this with mattn/go-sqlite3 directly and skip xorm this works perfectly, but I want to use xorm as it is very convenient to use.

This is how I construct the engine:

	dbPath := fmt.Sprintf("%s?_busy_timeout=30000", common.Cfg.DbPath)
	engine, err := xorm.NewEngine("sqlite3", dbPath)
	if err != nil {
		panic(err)
		return nil, err
	}

	engine.TZLocation = time.UTC

	myLogger := log.NewSimpleLogger(os.Stdout)
	myLogger.ShowSQL(true)
	myLogger.SetLevel(log.LOG_DEBUG)

	engine.SetLogLevel(log.LOG_DEBUG)
	engine.ShowSQL(true)
	engine.SetLogger(myLogger)

	engine.SetMaxOpenConns(1)
	engine.SetMaxIdleConns(0)

	session := Engine.NewSession()
	err := session.Begin()
	if err != nil {
		return nil, err
	}

    var device cmodels.Device
    {
        has, err := session.Where("lower(title) = lower(?) AND organization_id = ?", title, organization.Id).Get(&device)
        if err != nil {
            fmt.Printf("SQL failure: %v\n", err)
            os.Exit(1)
        }

        if !has {
            fmt.Printf("Device does not exist, nothing to update\n")
            os.Exit(1)
        }
    }

    common.Log.Debugf("About to update device")
    device.Title = "Testdude"
    _, err = session.Where("id = ?", device.Id).Cols("title").Update(device)
    if err != nil {
        sqliteErr := err.(sqlite3.Error)
        fmt.Printf("BigFix: %d\n", sqliteErr.Code)
        panic(err)
    }

    time.Sleep(1 * time.Second)
    
    
   session.Commit()

This is basically what I am doing and the .Update() is failing immediately with database locked and not waiting on the _busy_wait that SQL lite should be waiting, assuming the SQL lite driver should be blocking.

Any input would be greatly appreciated as I realise it can be a user/my error but I do not know the internals of xorm inside out.

Hi Lunny. I have a program that uses SQL lite and I have a background process that is writing to SQL lite. Then I have a CLI process that reads and writes to there. Sometimes they try to get a lock at the same time and in that case the busy timeout should make them wait for each other. The SQLlite parameters are being passed through and I can see the driver is picking up the busy_timeout that I am passing through. The problem is after I start a transaction and do an update on a model in the database then it fails immediately with Database locked instead of waiting for the busy wait time. When I do this with mattn/go-sqlite3 directly and skip xorm this works perfectly, but I want to use xorm as it is very convenient to use. This is how I construct the engine: ``` dbPath := fmt.Sprintf("%s?_busy_timeout=30000", common.Cfg.DbPath) engine, err := xorm.NewEngine("sqlite3", dbPath) if err != nil { panic(err) return nil, err } engine.TZLocation = time.UTC myLogger := log.NewSimpleLogger(os.Stdout) myLogger.ShowSQL(true) myLogger.SetLevel(log.LOG_DEBUG) engine.SetLogLevel(log.LOG_DEBUG) engine.ShowSQL(true) engine.SetLogger(myLogger) engine.SetMaxOpenConns(1) engine.SetMaxIdleConns(0) session := Engine.NewSession() err := session.Begin() if err != nil { return nil, err } var device cmodels.Device { has, err := session.Where("lower(title) = lower(?) AND organization_id = ?", title, organization.Id).Get(&device) if err != nil { fmt.Printf("SQL failure: %v\n", err) os.Exit(1) } if !has { fmt.Printf("Device does not exist, nothing to update\n") os.Exit(1) } } common.Log.Debugf("About to update device") device.Title = "Testdude" _, err = session.Where("id = ?", device.Id).Cols("title").Update(device) if err != nil { sqliteErr := err.(sqlite3.Error) fmt.Printf("BigFix: %d\n", sqliteErr.Code) panic(err) } time.Sleep(1 * time.Second) session.Commit() ``` This is basically what I am doing and the .Update() is failing immediately with database locked and not waiting on the _busy_wait that SQL lite should be waiting, assuming the SQL lite driver should be blocking. Any input would be greatly appreciated as I realise it can be a user/my error but I do not know the internals of xorm inside out.

lunny added the

need

test

label 2021-07-07 15:55:02 +00:00

lunny commented

2021-07-07 15:55:55 +00:00

Thanks for you reporting. I never used the parameter busy_timeout or _busy_timeout?

I will test it and investigate what's wrong.

Thanks for you reporting. I never used the parameter `busy_timeout` or `_busy_timeout`? I will test it and investigate what's wrong.

ahall commented

2021-07-07 16:00:07 +00:00

It is _busy_timeout, that is picked up by mattn/go-sqlite3.

1157a4212d/sqlite3.go (L1137)

Default busy timeout is 5 seconds see 1157a4212d/sqlite3.go (L1030).

However when doing the session.Update() it is not waiting 5 seconds, but rather just failing straight away with database locked. I cannot understand how this can happen as when I use the mattn/go-sqlite3 driver directly it waits the timeout, xorm calls into the driver, I cannot understand how it can bypass it.

when I wrap core.DB around database/sql *DB it works fine also but when using the xorm Session it starts to not work.

It is _busy_timeout, that is picked up by mattn/go-sqlite3. https://github.com/mattn/go-sqlite3/blob/1157a4212dcb650962563f67cd405794e9115b45/sqlite3.go#L1137 Default busy timeout is 5 seconds see https://github.com/mattn/go-sqlite3/blob/1157a4212dcb650962563f67cd405794e9115b45/sqlite3.go#L1030. However when doing the session.Update() it is not waiting 5 seconds, but rather just failing straight away with database locked. I cannot understand how this can happen as when I use the mattn/go-sqlite3 driver directly it waits the timeout, xorm calls into the driver, I cannot understand how it can bypass it. when I wrap core.DB around database/sql *DB it works fine also but when using the xorm Session it starts to not work.

ahall commented

2021-07-08 13:25:25 +00:00

Did you get a chance to look at this @lunny ? :).

lunny commented

2021-07-08 15:07:18 +00:00

Is it related with a transaction? Have you tried transaction with core.DB / sql.DB ?

lunny commented

2021-07-11 02:39:08 +00:00

I cannot reproduce this. Below is my test code on macOS:

package main

import (
	"fmt"
	"log"
	"time"

	_ "github.com/mattn/go-sqlite3"
	"xorm.io/xorm"
)

func main() {
	engine, err := xorm.NewEngine("sqlite3", "./data.db?_busy_timeout=30000")
	if err != nil {
		log.Fatal(err)
	}
	engine.Ping()

	type MyTable struct {
		Id   int64
		Name string
	}

	if err := engine.Sync2(new(MyTable)); err != nil {
		log.Fatal(err)
	}

	if _, err := engine.Insert(&MyTable{
		Name: "1",
	}); err != nil {
		log.Fatal(err)
	}

	sess := engine.NewSession()
	if err := sess.Begin(); err != nil {
		log.Fatal(err)
	}

	var t MyTable
	has, err := sess.ID(1).Get(&t)
	if err != nil {
		log.Fatal(err)
	}
	if !has {
		log.Fatal("records should be exist")
	}

	if _, err := sess.Where("name=?", "1").Update(&MyTable{
		Name: "2",
	}); err != nil {
		log.Fatal(err)
	}

	time.Sleep(time.Second)

	if err := sess.Commit(); err != nil {
		log.Fatal(err)
	}

	var records []MyTable
	if err := engine.Find(&records); err != nil {
		log.Fatal(err)
	}
	fmt.Printf("%#v\n", records)
}

I cannot reproduce this. Below is my test code on macOS: ```go package main import ( "fmt" "log" "time" _ "github.com/mattn/go-sqlite3" "xorm.io/xorm" ) func main() { engine, err := xorm.NewEngine("sqlite3", "./data.db?_busy_timeout=30000") if err != nil { log.Fatal(err) } engine.Ping() type MyTable struct { Id int64 Name string } if err := engine.Sync2(new(MyTable)); err != nil { log.Fatal(err) } if _, err := engine.Insert(&MyTable{ Name: "1", }); err != nil { log.Fatal(err) } sess := engine.NewSession() if err := sess.Begin(); err != nil { log.Fatal(err) } var t MyTable has, err := sess.ID(1).Get(&t) if err != nil { log.Fatal(err) } if !has { log.Fatal("records should be exist") } if _, err := sess.Where("name=?", "1").Update(&MyTable{ Name: "2", }); err != nil { log.Fatal(err) } time.Sleep(time.Second) if err := sess.Commit(); err != nil { log.Fatal(err) } var records []MyTable if err := engine.Find(&records); err != nil { log.Fatal(err) } fmt.Printf("%#v\n", records) } ```

lunny added

and removed

labels 2021-07-11 02:39:21 +00:00

Sign in to join this conversation.