Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

database/sql: race on QueryContext cancel #29083

Closed
DoctorQ opened this issue Dec 3, 2018 · 3 comments
Closed

database/sql: race on QueryContext cancel #29083

DoctorQ opened this issue Dec 3, 2018 · 3 comments
Labels
FrozenDueToAge

Comments

@DoctorQ
Copy link

DoctorQ commented Dec 3, 2018 •
edited by gbbr

What version of Go are you using (go version)?

$ go version
go version go1.11.2 linux/amd64

Does this issue reproduce with the latest release?

YES

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GOARCH="amd64"
GOBIN="/home/doctorq/go-dev/bin"
GOCACHE="/home/doctorq/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/doctorq/go-dev"
GOPROXY=""
GORACE=""
GOROOT="/home/doctorq/soft/go"
GOTMPDIR=""
GOTOOLDIR="/home/doctorq/soft/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build492619730=/tmp/go-build -gno-record-gcc-switches"

What did you do?

use QueryContext, context cancellation when rows.Next

func (p *MysqlAdapter) OrderQuery(ctx context.Context, sqlStr string) ([]map[string]string, error) {
	begin := tool.GetCurrentMsTime()
	sqlCtx, cancel := context.WithTimeout(context.Background(), time.Duration(p.queryTimeout)*time.Millisecond)
	defer cancel()
	rows, err := p.orderClient.QueryContext(sqlCtx, sqlStr)
	//rows, err := p.orderClient.Query(sqlStr)
	end := tool.GetCurrentMsTime()
	cost := end - begin
	log.Infof(ctx, "loc order mysql query cost:[%dms]", cost)
	if err != nil {
		return nil, errors.Wrapf(err, "")
	}
	
	return p.ParserRows(ctx, rows)
}
func (p *MysqlAdapter) ParserRows(ctx context.Context, rows *sql.Rows) ([]map[string]string, error) {
	if rows == nil {
		errStr := "rows is nil"
		return nil, errors.New(errStr)
	}
	defer rows.Close()
	columns, err := rows.Columns()
	if err != nil {
		return nil, errors.Wrapf(err, "")
	}
	count := len(columns)
	values := make([]sql.RawBytes, count)
	scans := make([]interface{}, count)
	for i, _ := range columns {
		scans[i] = &values[i]
	}

	begin := tool.GetCurrentMsTime()
	var syncMaps []map[string]string
	
	for rows.Next() {
		if err := rows.Scan(scans...); err != nil { 
			return nil, errors.Wrapf(err, "mysql scan failed")
		}
		syncMap := make(map[string]string)
		for k, v := range values {
			key := columns[k]
			syncMap[key] = string(v)
		}
		
		syncMaps = append(syncMaps, syncMap)
	}

	end := tool.GetCurrentMsTime()
	log.Infof(ctx, "row size:[%d],cost:[%dms]", len(syncMaps), end-begin)
	return syncMaps, nil
}

What did you expect to see?

no datatrace

What did you see instead?

==================
WARNING: DATA RACE
Write at 0x00c000e2fa98 by goroutine 218:
  internal/race.WriteRange()
      /home/doctorq/soft/go/src/internal/race/race.go:49 +0x42
  syscall.Read()
      /home/doctorq/soft/go/src/syscall/syscall_unix.go:175 +0x9a
  internal/poll.(*FD).Read()
      /home/doctorq/soft/go/src/internal/poll/fd_unix.go:165 +0x194
  net.(*netFD).Read()
      /home/doctorq/soft/go/src/net/fd_unix.go:202 +0x65
  net.(*conn).Read()
      /home/doctorq/soft/go/src/net/net.go:177 +0xa0
  net.(*TCPConn).Read()
      <autogenerated>:1 +0x69
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*buffer).fill()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/buffer.go:68 +0x1a5
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*buffer).readNext()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/buffer.go:97 +0x1bf
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*mysqlConn).readPacket()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/packets.go:67 +0x25d
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*mysqlConn).readUntilEOF()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/packets.go:786 +0x45
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*mysqlRows).Close()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql/rows.go:116 +0x186
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/go-sql-driver/mysql.(*textRows).Close()
      <autogenerated>:1 +0x43
  database/sql.(*Rows).close.func1()
      /home/doctorq/soft/go/src/database/sql/sql.go:2968 +0x70
  database/sql.withLock()
      /home/doctorq/soft/go/src/database/sql/sql.go:3076 +0x74
  database/sql.(*Rows).close()
      /home/doctorq/soft/go/src/database/sql/sql.go:2967 +0x192
  database/sql.(*Rows).awaitDone()
      /home/doctorq/soft/go/src/database/sql/sql.go:2631 +0x12d

Previous read at 0x00c000e2fa9f by goroutine 61:
  runtime.slicebytetostring()
      /home/doctorq/soft/go/src/runtime/string.go:75 +0x0
  gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlAdapter).ParserRows()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_adapter.go:102 +0x32d
  gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlAdapter).OrderQuery()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_adapter.go:73 +0x36a
  gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlProxy).GetOrderInfoByOrderId()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_proxy.go:111 +0x1c6c
  gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetOrderByOrderId()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:32 +0xa8
  gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetUndistributedOrder()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:82 +0x159
  gitlab.sftcwl.com/dispatch/data/handler/service.(*GetOrder).Access()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/service/get_order.go:35 +0x3dc
  gitlab.sftcwl.com/dispatch/data/handler.(*DataServiceHandler).GetOrderDetail()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/DataService_handler.go:45 +0xba
  gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2725 +0xa1
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:31 +0x2d3
  gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter.UnaryServerInterceptor.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter/perfcounter.go:58 +0x127
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34 +0x1d9
  gitlab.sftcwl.com/dispatch/data/framework/interceptor/header.UnaryServerInterceptor.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/header/header.go:74 +0x33e
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:39 +0x33d
  gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2727 +0x1d8
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).processUnaryRPC()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1026 +0xa8b
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleStream()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1252 +0x1384
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:699 +0xac

Goroutine 218 (running) created at:
  database/sql.(*Rows).initContextClose()
      /home/doctorq/soft/go/src/database/sql/sql.go:2615 +0xf9
  database/sql.(*DB).queryDC()
      /home/doctorq/soft/go/src/database/sql/sql.go:1555 +0x9cf
  database/sql.(*DB).query()
      /home/doctorq/soft/go/src/database/sql/sql.go:1519 +0x182
  database/sql.(*DB).QueryContext()
      /home/doctorq/soft/go/src/database/sql/sql.go:1496 +0xe6
  gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/golang-lib-inner/xmysql.(*Client).QueryContext()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/golang-lib-inner/xmysql/client.go:190 +0xb1
  gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlAdapter).OrderQuery()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_adapter.go:61 +0x19b
  gitlab.sftcwl.com/dispatch/data/handler/db.(*MysqlProxy).GetOrderInfoByOrderId()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/db/mysql_proxy.go:111 +0x1c6c
  gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetOrderByOrderId()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:32 +0xa8
  gitlab.sftcwl.com/dispatch/data/handler/proxy.(*OrderProxy).GetUndistributedOrder()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/proxy/order.go:82 +0x159
  gitlab.sftcwl.com/dispatch/data/handler/service.(*GetOrder).Access()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/service/get_order.go:35 +0x3dc
  gitlab.sftcwl.com/dispatch/data/handler.(*DataServiceHandler).GetOrderDetail()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/handler/DataService_handler.go:45 +0xba
  gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2725 +0xa1
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:31 +0x2d3
  gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter.UnaryServerInterceptor.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/perfcounter/perfcounter.go:58 +0x127
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34 +0x1d9
  gitlab.sftcwl.com/dispatch/data/framework/interceptor/header.UnaryServerInterceptor.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/framework/interceptor/header/header.go:74 +0x33e
  gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:39 +0x33d
  gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto._DataService_GetOrderDetail_Handler()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/gitlab.sftcwl.com/dispatch/util/proto/data.pb.go:2727 +0x1d8
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).processUnaryRPC()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1026 +0xa8b
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleStream()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:1252 +0x1384
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:699 +0xac

Goroutine 61 (running) created at:
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams.func1()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:697 +0xb8
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport/http2_server.go:432 +0x14cb
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/internal/transport/http2_server.go:472 +0x37a
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).serveStreams()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:695 +0x170
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleRawConn.func2()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:649 +0x53
  gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc.(*Server).handleRawConn.func3()
      /home/doctorq/go-dev/src/gitlab.sftcwl.com/dispatch/data/vendor/google.golang.org/grpc/server.go:657 +0x34
==================
@methane
Copy link
Contributor

methane commented Dec 3, 2018

I think it's design bug of QueryContext().

Caller goroutine will use []byte returned by rows.Scan() at any time.
Rows.initContextClose start go rs.awaitDone(ctx, txctx) which calls rows.close() from other goroutine.

I think rows.Scan() should check cancellation. Not another goroutine.

@methane
Copy link
Contributor

methane commented Dec 3, 2018

I found this is duplicate of #23519.

I didn't know rows.Close() must use another receive buffer used by rows.Next().
651ddbd

@methane methane mentioned this issue Dec 3, 2018
Closed
@gbbr gbbr changed the title datatrace on QueryContext cancel database/sql: race on QueryContext cancel Dec 3, 2018
@methane
Copy link
Contributor

methane commented Dec 3, 2018

Please close this. Each database driver including mysql should follow 651ddbd change.

@DoctorQ DoctorQ closed this as completed Dec 3, 2018
@golang golang locked and limited conversation to collaborators Dec 3, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@methane @DoctorQ @gopherbot