Skip to content
This repository has been archived by the owner on Nov 22, 2018. It is now read-only.

Race at tip #169

Closed
cznic opened this issue May 5, 2017 · 4 comments
Closed

Race at tip #169

cznic opened this issue May 5, 2017 · 4 comments
Labels

Comments

@cznic
Copy link
Owner

cznic commented May 5, 2017

@gernest Please try if you can reproduce the race.

Using 26248ea

$ go test -race -timeout 0
==================
WARNING: DATA RACE
Write at 0x00c420016870 by goroutine 22:
  github.com/cznic/ql.(*mem).Close()
      /home/jnml/src/github.com/cznic/ql/mem.go:284 +0xa2
  github.com/cznic/ql.(*DB).Close()
      /home/jnml/src/github.com/cznic/ql/ql.go:1442 +0xf7
  github.com/cznic/ql.(*driverConn).Close()
      /home/jnml/src/github.com/cznic/ql/driver.go:267 +0x3f8
  database/sql.(*driverConn).finalClose.func2()
      /home/jnml/go/src/database/sql/sql.go:440 +0x8c
  database/sql.withLock()
      /home/jnml/go/src/database/sql/sql.go:2545 +0x76
  database/sql.(*driverConn).finalClose()
      /home/jnml/go/src/database/sql/sql.go:442 +0x215
  database/sql.(finalCloser).(database/sql.finalClose)-fm()
      /home/jnml/go/src/database/sql/sql.go:537 +0x46
  database/sql.(*DB).Close()
      /home/jnml/go/src/database/sql/sql.go:644 +0x4a8
  github.com/cznic/ql.TestWhereExists()
      /home/jnml/src/github.com/cznic/ql/all_test.go:3504 +0x4b9
  testing.tRunner()
      /home/jnml/go/src/testing/testing.go:657 +0x107

Previous read at 0x00c420016870 by goroutine 28:
  github.com/cznic/ql.(*mem).Read()
      /home/jnml/src/github.com/cznic/ql/mem.go:456 +0x64
  github.com/cznic/ql.(*table).row0()
      /home/jnml/src/github.com/cznic/ql/storage.go:769 +0xe6
  github.com/cznic/ql.(*tableDefaultPlan).do()
      /home/jnml/src/github.com/cznic/ql/plan.go:2403 +0xcb
  github.com/cznic/ql.(*DB).do()
      /home/jnml/src/github.com/cznic/ql/ql.go:1474 +0x1f5
  github.com/cznic/ql.recordset.Do()
      /home/jnml/src/github.com/cznic/ql/ql.go:75 +0x96
  github.com/cznic/ql.(*recordset).Do()
      <autogenerated>:60 +0xa3
  github.com/cznic/ql.newdriverRows.func1()
      /home/jnml/src/github.com/cznic/ql/driver.go:422 +0x106

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /home/jnml/go/src/testing/testing.go:697 +0x543
  testing.runTests.func1()
      /home/jnml/go/src/testing/testing.go:882 +0xaa
  testing.tRunner()
      /home/jnml/go/src/testing/testing.go:657 +0x107
  testing.runTests()
      /home/jnml/go/src/testing/testing.go:888 +0x4e0
  testing.(*M).Run()
      /home/jnml/go/src/testing/testing.go:822 +0x1c3
  main.main()
      github.com/cznic/ql/_test/_testmain.go:346 +0x20f

Goroutine 28 (finished) created at:
  github.com/cznic/ql.newdriverRows()
      /home/jnml/src/github.com/cznic/ql/driver.go:430 +0x13d
  github.com/cznic/ql.newDriverMultiRows()
      /home/jnml/src/github.com/cznic/ql/driver.go:524 +0x67
  github.com/cznic/ql.driverQuery()
      /home/jnml/src/github.com/cznic/ql/driver.go:379 +0x1e0
  github.com/cznic/ql.(*driverStmt).Query()
      /home/jnml/src/github.com/cznic/ql/driver.go:592 +0x10c
  database/sql.ctxDriverStmtQuery()
      /home/jnml/go/src/database/sql/ctxutil.go:95 +0x1e9
  database/sql.rowsiFromStatement()
      /home/jnml/go/src/database/sql/sql.go:2002 +0x283
  database/sql.(*Stmt).QueryContext()
      /home/jnml/go/src/database/sql/sql.go:1949 +0x2a3
  database/sql.(*Stmt).QueryRowContext()
      /home/jnml/go/src/database/sql/sql.go:2021 +0x80
  database/sql.(*Stmt).QueryRow()
      /home/jnml/go/src/database/sql/sql.go:2040 +0x82
  github.com/cznic/ql.TestWhereExists.func1()
      /home/jnml/src/github.com/cznic/ql/all_test.go:3486 +0x11f
==================
==================
WARNING: DATA RACE
Write at 0x00c420018730 by goroutine 22:
  github.com/cznic/ql.(*DB).Close()
      /home/jnml/src/github.com/cznic/ql/ql.go:1443 +0x14a
  github.com/cznic/ql.(*driverConn).Close()
      /home/jnml/src/github.com/cznic/ql/driver.go:267 +0x3f8
  database/sql.(*driverConn).finalClose.func2()
      /home/jnml/go/src/database/sql/sql.go:440 +0x8c
  database/sql.withLock()
      /home/jnml/go/src/database/sql/sql.go:2545 +0x76
  database/sql.(*driverConn).finalClose()
      /home/jnml/go/src/database/sql/sql.go:442 +0x215
  database/sql.(finalCloser).(database/sql.finalClose)-fm()
      /home/jnml/go/src/database/sql/sql.go:537 +0x46
  database/sql.(*DB).Close()
      /home/jnml/go/src/database/sql/sql.go:644 +0x4a8
  github.com/cznic/ql.TestWhereExists()
      /home/jnml/src/github.com/cznic/ql/all_test.go:3504 +0x4b9
  testing.tRunner()
      /home/jnml/go/src/testing/testing.go:657 +0x107

Previous read at 0x00c420018730 by goroutine 28:
  github.com/cznic/ql.(*table).row0()
      /home/jnml/src/github.com/cznic/ql/storage.go:769 +0x6b
  github.com/cznic/ql.(*tableDefaultPlan).do()
      /home/jnml/src/github.com/cznic/ql/plan.go:2403 +0xcb
  github.com/cznic/ql.(*DB).do()
      /home/jnml/src/github.com/cznic/ql/ql.go:1474 +0x1f5
  github.com/cznic/ql.recordset.Do()
      /home/jnml/src/github.com/cznic/ql/ql.go:75 +0x96
  github.com/cznic/ql.(*recordset).Do()
      <autogenerated>:60 +0xa3
  github.com/cznic/ql.newdriverRows.func1()
      /home/jnml/src/github.com/cznic/ql/driver.go:422 +0x106

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /home/jnml/go/src/testing/testing.go:697 +0x543
  testing.runTests.func1()
      /home/jnml/go/src/testing/testing.go:882 +0xaa
  testing.tRunner()
      /home/jnml/go/src/testing/testing.go:657 +0x107
  testing.runTests()
      /home/jnml/go/src/testing/testing.go:888 +0x4e0
  testing.(*M).Run()
      /home/jnml/go/src/testing/testing.go:822 +0x1c3
  main.main()
      github.com/cznic/ql/_test/_testmain.go:346 +0x20f

Goroutine 28 (finished) created at:
  github.com/cznic/ql.newdriverRows()
      /home/jnml/src/github.com/cznic/ql/driver.go:430 +0x13d
  github.com/cznic/ql.newDriverMultiRows()
      /home/jnml/src/github.com/cznic/ql/driver.go:524 +0x67
  github.com/cznic/ql.driverQuery()
      /home/jnml/src/github.com/cznic/ql/driver.go:379 +0x1e0
  github.com/cznic/ql.(*driverStmt).Query()
      /home/jnml/src/github.com/cznic/ql/driver.go:592 +0x10c
  database/sql.ctxDriverStmtQuery()
      /home/jnml/go/src/database/sql/ctxutil.go:95 +0x1e9
  database/sql.rowsiFromStatement()
      /home/jnml/go/src/database/sql/sql.go:2002 +0x283
  database/sql.(*Stmt).QueryContext()
      /home/jnml/go/src/database/sql/sql.go:1949 +0x2a3
  database/sql.(*Stmt).QueryRowContext()
      /home/jnml/go/src/database/sql/sql.go:2021 +0x80
  database/sql.(*Stmt).QueryRow()
      /home/jnml/go/src/database/sql/sql.go:2040 +0x82
  github.com/cznic/ql.TestWhereExists.func1()
      /home/jnml/src/github.com/cznic/ql/all_test.go:3486 +0x11f
==================
--- FAIL: TestWhereExists (0.01s)
	testing.go:610: race detected during execution of test
FAIL
exit status 1
FAIL	github.com/cznic/ql	89.349s
$ 
@cznic cznic added the bug label May 5, 2017
@gernest
Copy link
Collaborator

gernest commented May 5, 2017

@cznic It looks like I forgot to add -race let me bisect this.

@cznic
Copy link
Owner Author

cznic commented May 5, 2017

Thank you 👍

PS: I'm to blame, do you remember? ;-)

@gernest
Copy link
Collaborator

gernest commented May 5, 2017

haha! I remember! 😄 Still you noticed it. I think we should have CI (travis/drone) to automate this. So we can run with -race on every PR.

@gernest
Copy link
Collaborator

gernest commented May 5, 2017

@cznic I have traced the issue back to 324177d that is because it is the last point where the below test case pass.

It seems it can be triggered by this test case

func TestWhereExists(t *testing.T) {
	RegisterMemDriver()
	db, err := sql.Open("ql-mem", "")
	if err != nil {
		t.Fatal(err)
	}
	defer db.Close()
	tx, err := db.Begin()
	if err != nil {
		t.Fatal(err)
	}
	tx.Exec(`
BEGIN TRANSACTION;
 	CREATE TABLE t (i int);
 	CREATE TABLE s (i int);
	 INSERT INTO t VALUES (0);
	 INSERT INTO t VALUES (1);
	 INSERT INTO t VALUES (2);
	 INSERT INTO t VALUES (3);
	 INSERT INTO t VALUES (4);
	 INSERT INTO t VALUES (5);
	 
	 INSERT INTO s VALUES (2);
COMMIT;
	`)
	err = tx.Commit()
	if err != nil {
		t.Fatal(err)
	}
	s, err := db.Prepare(`
	select * from t  where  exists (select * from s where i==$1);
	`)
	if err != nil {
		t.Fatal(err)
	}
	defer s.Close()
	var wg sync.WaitGroup
	for i := 0; i < 5; i++ {
		go func(id int, wait *sync.WaitGroup) {
			var c int
			err := s.QueryRow(id).Scan(&c)
			if id == 2 {
				if err != nil {
					t.Error(err)
				}
				if id == 2 && c != 5 {
					t.Errorf("expected %d got %d", id, c)
				}
			} else {
				if err != sql.ErrNoRows {
					t.Errorf("expected %v got %v", sql.ErrNoRows, err)
				}
			}
			wait.Done()
		}(i, &wg)
		wg.Add(1)
	}
	wg.Wait()
}

While II'm checking where might the map access happen. Can you please look into this test case just in case I missed something?

I have a feeling this is related to #150` and the test case just uncovered it

gernest added a commit to gernest/ql that referenced this issue May 5, 2017
gernest added a commit to gernest/ql that referenced this issue May 5, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests

2 participants