问题描述

压测过程中，发现数据库中某个字段（json字符串）在解析的过程中提示，json字符串不符合json格式要求，增加日志打印后，发现json打印如下：

47^A0^MTCKSGroup1773
1540984132
1540984232^D6000^F749279^K52057485773^A1^K18888881773
1540984137^A1ü4^B{"complete_code": "", "promise_delivery_time_second": 1800, "aoi_type": 1, "receive_user_money": 0, "app_id": "0", "need_invoice": 0, "user_lat": "40.014593", "user_id": 0, "pickup_code": "", "user_lng": "125.149658", "co
nfig": "", "resource_station": 10003371, "dish_type_nums": 0, "brand": "è<80><81>å¨<98>è<88><85>", "settlement_type": 1, "verify_code_type": 0, "assessment_time": 0, "shop_lng": "116.347791", "dispatch_strategy": "common", "remark": "", "
product_type": 1, "shop_la],json parser extend info failed,err:[invalid character '\x01' after top-level value

但是我们在数据库里面查到的结果却是正确的json字符串。所以我们怀疑是多线程之间使用mysql存在数据公用的问题。

猜测验证

上race工具，验证是否存在内存相互竞争问题，发现有data race

> go run -race *.go
==================
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
==================

上面的检测证明确实buffer被多个线程同时读取。

上报官方

go-sql-driver/sql
golang/go

修复

Truncate internal buffer when rows.Close() is called

目前还没合到master，我在本地按照这个pull request修改后，data trace没有出现，串数据的问题也没再出现。

问题产生原因

当使用QueryContext读取mysql数据库时，当在rows.Next过程中，context超时了，会直接退出读取过程，会自动调用defer rows.Close()，而在Close的过程中，没有处理已经读取的那部分数据，那部分数据还存在buffer里面，而当下一次的rows.Scan读取的时候，就有几率读到这部分数据，就会跟当前的数据串了。看官方的修复操作，也是强制在Close过程中把这部分数据截取丢弃掉。

database/sql从1.10开始要求rows.Close()的操作不能覆盖rows.Next使用的buffer，但是go-sql-driver/sql还没遵守这个规则，而这个问题出现的概率很低，如果不是高并发的情况一般不容易发生。

database/sql: buffers provided to Rows.Next should not be modified by