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

database/sql: race on QueryContext cancel #29083

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

Comments

Projects
None yet
2 participants
@DoctorQ
Copy link

DoctorQ commented Dec 3, 2018

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

This comment has been minimized.

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

This comment has been minimized.

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

@gbbr gbbr changed the title datatrace on QueryContext cancel database/sql: race on QueryContext cancel Dec 3, 2018

@methane

This comment has been minimized.

Copy link
Contributor

methane commented Dec 3, 2018

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

@DoctorQ DoctorQ closed this Dec 3, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment