sijms / go-ora

Pure go oracle client
MIT License
795 stars 176 forks source link

The canceling context in version 2.8.14 has a race condition issue. #552

Closed aromarom64 closed 5 months ago

aromarom64 commented 5 months ago

I came across a race condition in version 2.8.14, which occurs when the context is canceled. I've created a simple test case that consistently replicates this problem.

package main

import (
    "context"
    "database/sql"
    "fmt"
    "strings"
    "sync"
    "time"

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

func main() {
    ctx, cancel := context.WithCancel(context.Background())
    defer cancel()

    done := make(chan interface{})

    doQuery := func(ctx context.Context) ([]string, error) {
        dbURL := go_ora.BuildJDBC("user", "password", "connection", nil)
        conn, err := sql.Open("oracle", dbURL)
        if err != nil {
            return nil, err
        }
        defer conn.Close()

        err = conn.PingContext(ctx)
        if err != nil {
            return nil, err
        }

        rows, err := conn.QueryContext(ctx, "begin dbms_lock.sleep(5); end;")
        if err != nil {
            return nil, err
        }
        defer rows.Close()

        columnNames, err := rows.Columns()
        if err != nil {
            return nil, err
        }

        for rows.Next() {
        }
        return columnNames, nil
    }

    const iterations = 10
    var wg sync.WaitGroup
    wg.Add(iterations)
    doWork := func(ctx context.Context) {
        go func() {
            defer wg.Done()
            <-done
            cols, err := doQuery(ctx)
            if err != nil {
                fmt.Println(err)
                return
            }
            fmt.Println("Done", strings.Join(cols, ", "))
        }()
    }

    for i := 0; i < iterations; i++ {
        go doWork(ctx)
    }

    time.AfterFunc(3*time.Second, cancel)
    close(done)

    wg.Wait()
}
aromashchenko@arompr race1 % go run -race .
==================
WARNING: DATA RACE
Write at 0x00c0003045a0 by goroutine 25:
  github.com/sijms/go-ora/v2/network.(*Session).resetWrite()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:169 +0x1b4
  github.com/sijms/go-ora/v2/network.(*Session).ResetBuffer()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:180 +0x1b0
  github.com/sijms/go-ora/v2.(*defaultStmt).Close()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/command.go:1255 +0x17c
  github.com/sijms/go-ora/v2.(*DataSet).Close()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/data_set.go:109 +0x68
  database/sql.(*Rows).close.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3412 +0x50
  database/sql.withLock()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3530 +0x98
  database/sql.(*Rows).close()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/databa  database/sql.(*Rows).Close()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3395 +0x6c
  database/sql.(*Rows).Next()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3025 +0xfc
  main.main.func1()
      /Users/aromashchenko/race1/main.go:44 +0x448
  main.main.func2.1()
      /Users/aromashchenko/race1/main.go:56 +0xac

Previous write at 0x00c0003045a0 by goroutine 70:
  github.com/sijms/go-ora/v2/network.(*Session).writePacket()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:896 +0x140
  github.com/sijms/go-ora/v2/network.(*Session).BreakConnection()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:446 +0x1d0
  github.com/sijms/go-ora/v2/network.(*Session).StartContext.func1()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:206 +0xe4
  github.com/sijms/go-ora/v2/network.(*Session).StartContext.gowrap1()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:217 +0x54

Goroutine 25 (running) created at:
  main.main.func2()
      /Users/aromashchenko/race1/main.go:53 +0x158
  main.main.gowrap1()
      /Users/aromashchenko/race1/main.go:66 +0x54

Goroutine 70 (finished) created at:
  github.com/sijms/go-ora/v2/network.(*Session).StartContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:194 +0x2b0
  github.com/sijms/go-ora/v2.(*Connection).Ping()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/connection.go:272 +0x1e4
  database/sql.(*DB).pingDC.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:869 +0x60
  database/sql.withLock()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3530 +0x98
  database/sql.(*DB).pingDC()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:868 +0xf0
  database/sql.(*DB).PingContext()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:891 +0x11c
  main.main.func1()
      /Users/aromashchenko/race1/main.go:28 +0x190
  main.main.func2.1()
      /Users/aromashchenko/race1/main.go:56 +0xac
==================
==================
WARNING: DATA RACE
Write at 0x00c0002045a0 by goroutine 92:
  github.com/sijms/go-ora/v2/network.(*Session).resetWrite()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:169 +0x1b4
  github.com/sijms/go-ora/v2/network.(*Session).ResetBuffer()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:180 +0x1b0
  github.com/sijms/go-ora/v2.(*defaultStmt).Close()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/command.go:1255 +0x17c
  github.com/sijms/go-ora/v2.(*DataSet).Close()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/data_set.go:109 +0x68
  database/sql.(*Rows).close.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3412 +0x50
  database/sql.withLock()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3530 +0x98
  database/sql.(*Rows).close()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3411 +0x1c4
  database/sql.(*Rows).awaitDone()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3001 +0x210
  database/sql.(*Rows).initContextClose.gowrap1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:2977 +0x7c

Previous write at 0x00c0002045a0 by goroutine 86:
  github.com/sijms/go-ora/v2/network.(*Session).writePacket()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:896 +0x140
  github.com/sijms/go-ora/v2/network.(*Session).BreakConnection()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:446 +0x1d0
  github.com/sijms/go-ora/v2/network.(*Session).StartContext.func1()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:206 +0xe4
  github.com/sijms/go-ora/v2/network.(*Session).StartContext.gowrap1()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:217 +0x54

Gorout  database/sql.(*Rows).initContextClose()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:2977 +0x210
  database/sql.(*DB).queryDC()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1790 +0x74c
  database/sql.(*DB).query()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1754 +0xec
  database/sql.(*DB).QueryContext.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1732 +0x9c
  database/sql.(*DB).retry()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1566 +0x4c
  database/sql.(*DB).QueryContext()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1731 +0x104
  main.main.func1()
      /Users/aromashchenko/race1/main.go:33 +0x1bc
  main.main.func2.1()
      /Users/aromashchenko/race1/main.go:56 +0xac

Goroutine 86 (running) created at:
  github.com/sijms/go-ora/v2/network.(*Session).StartContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:194 +0x2b0
  github.com/sijms/go-ora/v2.(*Stmt).QueryContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/command.go:2325 +0x1ac
  github.com/sijms/go-ora/v2.(*Connection).QueryContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/connection.go:1093 +0xec
  database/sql.ctxDriverQuery()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/ctxutil.go:48 +0xa0
  database/sql.(*DB).queryDC.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1776 +0x1b4
  database/sql.withLock()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3530 +0x98
  database/sql.(*DB).queryDC()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1771 +0x1f8
  database/sql.(*DB).query()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1754 +0xec
  database/sql.(*DB).QueryContext.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:17  database/sql.(*DB).retry()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1566 +0x4c
  database/sql.(*DB).QueryContext()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1731 +0x104
  main.main.func1()
      /Users/aromashchenko/race1/main.go:33 +0x1bc
  main.main.func2.1()
      /Users/aromashchenko/race1/main.go:56 +0xac
==================
==================
WARNING: DATA RACE
Write at 0x00c000284ae0 by goroutine 44:
  github.com/sijms/go-ora/v2/network.(*Session).resetWrite()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:169 +0xfc
  github.com/sijms/go-ora/v2/network.(*Session).ResetBuffer()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:180 +0xf8
  github.com/sijms/go-ora/v2.(*Connection).Logoff()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/connection.go:311 +0xc4
  github.com/sijms/go-ora/v2.(*Connection).Close()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/connection.go:572 +0xdc
  database/sql.(*driverConn).finalClose.func2()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:677 +0x68
  database/sql.withLock()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3530 +0x98
  database/sql.(*driverConn).finalClose()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:675 +0x11c
  database/sql.finalCloser.finalClose-fm()
      <autogenerated>:1 +0x44
  database/sql.(*DB).Close()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:930 +0x314
  main.main.func1.deferwrap1()
      /Users/aromashchenko/race1/main.go:26 +0x34
  runtime.deferreturn()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/runtime/panic.go:602 +0x5c
  main.main.func2.1()
      /Users/aromashchenko/race1/main.go:56 +0xac

Previous write at 0x00c000284ae0 by goroutine 84:
  github.com/sijms/go-ora/v2/network.(*Session).writePacket()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:896 +0x140
  github.com/sijms/go-ora/v2/network.(*Session).BreakConnection()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:446 +0x1d0
  github.com/sijms/go-ora/v2/network.(*Session).StartContext.func1()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:206 +0xe4
  github.com/sijms/go-ora/v2/network.(*Session).StartContext.gowrap1()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:217 +0x54

Goroutine 44 (running) created at:
  main.main.func2()
      /Users/aromashchenko/race1/main.go:53 +0x158
  main.main.gowrap1()
      /Users/aromashchenko/race1/main.go:66 +0x54

Goroutine 84 (finished) created at:
  github.com/sijms/go-ora/v2/network.(*Session).StartContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/network/session.go:194 +0x2b0
  github.com/sijms/go-ora/v2.(*Stmt).QueryContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/command.go:2325 +0x1ac
  github.com/sijms/go-ora/v2.(*Connection).QueryContext()
      /Users/aromashchenko/go/pkg/mod/github.com/sijms/go-ora/v2@v2.8.14/connection.go:1093 +0xec
  database/sql.ctxDriverQuery()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/ctxutil.go:48 +0xa0
  database/sql.(*DB).queryDC.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1776 +0x1b4
  database/sql.withLock()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:3530 +0x98
  database/sql.(*DB).queryDC()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1771 +0x1f8
  database/sql.(*DB).query()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1754 +0xec
  database/sql.(*DB).QueryContext.func1()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1732 +0x9c
  database/sql.(*DB).retry()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1566 +0x4c
  database/sql.(*DB).QueryContext()
      /opt/homebrew/Cellar/go/1.22.2/libexec/src/database/sql/sql.go:1731 +0x104
  main.main.func1()
      /Users/aromashchenko/race1/main.go:33 +0x1bc
  main.main.func2.1()
      /Users/aromashchenko/race1/main.go:56 +0xac
==================
Done
Done
Done
Done
Done
Done
Done
Done
Done
Done
Found 3 data race(s)
exit status 66
aromashchenko@arompr race1 %
sijms commented 5 months ago

fixed in v2.8.15