Repository: pingcap/tidb-lightning
Pull request #201 (2019-07-02 21:22:03)

Improve errors and logs on syntax error / conversion failure
<!--
Thank you for contributing to TiDB-Lightning! Please read the [CONTRIBUTING](https://github.com/pingcap/tidb-lightning/blob/master/CONTRIBUTING.md) document **BEFORE** filing this PR.
-->

### What problem does this PR solve? <!--add issue link with summary if exists-->

[TOOL-1355]

1. When the parser encountered a syntax error, limit the content printed out to be 256 characters or less, to avoid flooding the log file.
2. Stop logging the entire row when a CAST AS failed, instead only log the affected value.
3. Replaced some `errors.Trace` by `errors.Annotatef` to indicate the error's provenance.

### What is changed and how it works?


### Check List <!--REMOVE the items that are not applicable-->

Tests <!-- At least one of them must be included. -->

 - Unit test

Side effects

Related changes



kennytm: /run-all-tests
kennytm: /run-all-tests
kennytm: PTAL @july2993 @csuzhangxc @GregoryIan 
kennytm: /run-all-tests

FYI @csuzhangxc  I've added one commit 04e2d111431c5a4dee78154d2c42744b3bb843ed to reduce the "missing checkpoint file" log from Warn level to Info level so DBAs won't think it is a serious bad issue.

PTAL @leoppro 
leoppro: LGTM
kennytm: /run-all-tests

kennytm: @leoppro @csuzhangxc Could either one of you approve the PR? Thanks.

Patch:
diff --git a/lightning/checkpoints/checkpoints.go b/lightning/checkpoints/checkpoints.go
index 063cab9..621eb85 100644
--- a/lightning/checkpoints/checkpoints.go
+++ b/lightning/checkpoints/checkpoints.go
@@ -746,7 +746,7 @@ func NewFileCheckpointsDB(path string) *FileCheckpointsDB {
 	if err == nil {
 		cpdb.checkpoints.Unmarshal(content)
 	} else {
-		log.L().Warn("open checkpoint file failed, going to create a new one",
+		log.L().Info("open checkpoint file failed, going to create a new one",
 			zap.String("path", path),
 			log.ShortError(err),
 		)
diff --git a/lightning/kv/sql2kv.go b/lightning/kv/sql2kv.go
index d8ccbb6..85a8029 100644
--- a/lightning/kv/sql2kv.go
+++ b/lightning/kv/sql2kv.go
@@ -76,8 +76,7 @@ var kindStr = [...]string{
 
 // MarshalLogArray implements the zapcore.ArrayMarshaler interface
 func (row rowArrayMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error {
-	for i, datum := range row {
-		index := i
+	for _, datum := range row {
 		kind := datum.Kind()
 		var str string
 		var err error
@@ -95,7 +94,6 @@ func (row rowArrayMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error
 			}
 		}
 		encoder.AppendObject(zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
-			enc.AddInt("col", index)
 			enc.AddString("kind", kindStr[kind])
 			enc.AddString("val", str)
 			return nil
@@ -104,14 +102,26 @@ func (row rowArrayMarshaler) MarshalLogArray(encoder zapcore.ArrayEncoder) error
 	return nil
 }
 
-func logKVConvertFailed(logger log.Logger, row []types.Datum, j int, colInfo *model.ColumnInfo, err error) {
+func logKVConvertFailed(logger log.Logger, row []types.Datum, j int, colInfo *model.ColumnInfo, err error) error {
+	var original types.Datum
+	if j < len(row) {
+		original = row[j]
+		row = row[j : j+1]
+	}
+
 	logger.Error("kv convert failed",
-		zap.Array("originalRow", rowArrayMarshaler(row)),
+		zap.Array("original", rowArrayMarshaler(row)),
 		zap.Int("originalCol", j),
 		zap.String("colName", colInfo.Name.O),
 		zap.Stringer("colType", &colInfo.FieldType),
 		log.ShortError(err),
 	)
+
+	return errors.Annotatef(
+		err,
+		"failed to cast `%v` as %s for column `%s` (#%d)",
+		original.GetValue(), &colInfo.FieldType, colInfo.Name.O, j+1,
+	)
 }
 
 // Encode a row of data into KV pairs.
@@ -150,8 +160,7 @@ func (kvcodec *TableKVEncoder) Encode(
 			value, err = table.GetColDefaultValue(kvcodec.se, col.ToInfo())
 		}
 		if err != nil {
-			logKVConvertFailed(logger, row, j, col.ToInfo(), err)
-			return nil, errors.Trace(err)
+			return nil, logKVConvertFailed(logger, row, j, col.ToInfo(), err)
 		}
 		record = append(record, value)
 	}
@@ -164,8 +173,7 @@ func (kvcodec *TableKVEncoder) Encode(
 			value, err = types.NewIntDatum(rowID), nil
 		}
 		if err != nil {
-			logKVConvertFailed(logger, row, j, extraHandleColumnInfo, err)
-			return nil, errors.Trace(err)
+			return nil, logKVConvertFailed(logger, row, j, extraHandleColumnInfo, err)
 		}
 		record = append(record, value)
 	}
diff --git a/lightning/mydump/csv_parser.rl b/lightning/mydump/csv_parser.rl
index ac3e721..059b7a0 100644
--- a/lightning/mydump/csv_parser.rl
+++ b/lightning/mydump/csv_parser.rl
@@ -10,9 +10,7 @@ package mydump
 import (
 	"io"
 
-	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/errors"
-	"go.uber.org/zap"
 )
 
 %%{
@@ -82,10 +80,7 @@ func (parser *CSVParser) lex() (csvToken, []byte, error) {
 		%% write exec;
 
 		if cs == %%{ write error; }%% {
-			log.L().Error("syntax error",
-				zap.Int64("pos", parser.pos),
-				zap.ByteString("content", data),
-			)
+			parser.logSyntaxError()
 			return csvTokNil, nil, errors.New("syntax error")
 		}
 
diff --git a/lightning/mydump/csv_parser_generated.go b/lightning/mydump/csv_parser_generated.go
index 201acfd..8176aa3 100644
--- a/lightning/mydump/csv_parser_generated.go
+++ b/lightning/mydump/csv_parser_generated.go
@@ -13,17 +13,15 @@ package mydump
 import (
 	"io"
 
-	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/errors"
-	"go.uber.org/zap"
 )
 
 
-//.... lightning/mydump/csv_parser.rl:59
+//.... lightning/mydump/csv_parser.rl:57
 
 
 
-//.... tmp_parser.go:26
+//.... tmp_parser.go:24
 const csv_parser_start int = 8
 const csv_parser_first_final int = 8
 const csv_parser_error int = 0
@@ -31,7 +29,7 @@ const csv_parser_error int = 0
 const csv_parser_en_main int = 8
 
 
-//.... lightning/mydump/csv_parser.rl:62
+//.... lightning/mydump/csv_parser.rl:60
 
 func (parser *CSVParser) lex() (csvToken, []byte, error) {
 	var delim byte
@@ -42,7 +40,7 @@ func (parser *CSVParser) lex() (csvToken, []byte, error) {
 
 	var cs, ts, te, act, p int
 	
-//.... tmp_parser.go:45
+//.... tmp_parser.go:43
 	{
 	cs = csv_parser_start
 	ts = 0
@@ -50,7 +48,7 @@ func (parser *CSVParser) lex() (csvToken, []byte, error) {
 	act = 0
 	}
 
-//.... lightning/mydump/csv_parser.rl:72
+//.... lightning/mydump/csv_parser.rl:70
 
 	for {
 		data := parser.buf
@@ -62,7 +60,7 @@ func (parser *CSVParser) lex() (csvToken, []byte, error) {
 		}
 
 		
-//.... tmp_parser.go:65
+//.... tmp_parser.go:63
 	{
 	var _widec int16
 	if p == pe {
@@ -142,7 +140,7 @@ tr0:
 	
 	goto st8
 tr14:
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 p = (te) - 1
 {
 		consumedToken = csvTokField
@@ -150,7 +148,7 @@ p = (te) - 1
 	}
 	goto st8
 tr17:
-//.... lightning/mydump/csv_parser.rl:42
+//.... lightning/mydump/csv_parser.rl:40
 te = p+1
 {
 		consumedToken = csvTokSep
@@ -158,7 +156,7 @@ te = p+1
 	}
 	goto st8
 tr23:
-//.... lightning/mydump/csv_parser.rl:52
+//.... lightning/mydump/csv_parser.rl:50
 te = p
 p--
 {
@@ -167,7 +165,7 @@ p--
 	}
 	goto st8
 tr24:
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 te = p
 p--
 {
@@ -176,7 +174,7 @@ p--
 	}
 	goto st8
 tr25:
-//.... lightning/mydump/csv_parser.rl:42
+//.... lightning/mydump/csv_parser.rl:40
 te = p
 p--
 {
@@ -198,7 +196,7 @@ act = 0
 //.... NONE:1
 ts = p
 
-//.... tmp_parser.go:201
+//.... tmp_parser.go:199
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -369,7 +367,7 @@ tr1:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st10
 	st10:
@@ -377,7 +375,7 @@ act = 2;
 			goto _test_eof10
 		}
 	st_case_10:
-//.... tmp_parser.go:380
+//.... tmp_parser.go:378
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -629,7 +627,7 @@ tr3:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st11
 	st11:
@@ -637,7 +635,7 @@ act = 2;
 			goto _test_eof11
 		}
 	st_case_11:
-//.... tmp_parser.go:640
+//.... tmp_parser.go:638
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 11:
@@ -677,7 +675,7 @@ tr4:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st12
 	st12:
@@ -685,7 +683,7 @@ act = 2;
 			goto _test_eof12
 		}
 	st_case_12:
-//.... tmp_parser.go:688
+//.... tmp_parser.go:686
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -846,7 +844,7 @@ tr8:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st13
 	st13:
@@ -854,7 +852,7 @@ act = 2;
 			goto _test_eof13
 		}
 	st_case_13:
-//.... tmp_parser.go:857
+//.... tmp_parser.go:855
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -1164,7 +1162,7 @@ tr6:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st14
 	st14:
@@ -1172,7 +1170,7 @@ act = 2;
 			goto _test_eof14
 		}
 	st_case_14:
-//.... tmp_parser.go:1175
+//.... tmp_parser.go:1173
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 11:
@@ -1228,7 +1226,7 @@ tr18:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:42
+//.... lightning/mydump/csv_parser.rl:40
 act = 1;
 	goto st15
 	st15:
@@ -1236,7 +1234,7 @@ act = 1;
 			goto _test_eof15
 		}
 	st_case_15:
-//.... tmp_parser.go:1239
+//.... tmp_parser.go:1237
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -1546,7 +1544,7 @@ tr9:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st16
 	st16:
@@ -1554,7 +1552,7 @@ act = 2;
 			goto _test_eof16
 		}
 	st_case_16:
-//.... tmp_parser.go:1557
+//.... tmp_parser.go:1555
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -1926,7 +1924,7 @@ tr11:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st18
 	st18:
@@ -1934,7 +1932,7 @@ act = 2;
 			goto _test_eof18
 		}
 	st_case_18:
-//.... tmp_parser.go:1937
+//.... tmp_parser.go:1935
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -2244,7 +2242,7 @@ tr13:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st20
 	st20:
@@ -2252,7 +2250,7 @@ act = 2;
 			goto _test_eof20
 		}
 	st_case_20:
-//.... tmp_parser.go:2255
+//.... tmp_parser.go:2253
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -2407,7 +2405,7 @@ tr10:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st21
 	st21:
@@ -2415,7 +2413,7 @@ act = 2;
 			goto _test_eof21
 		}
 	st_case_21:
-//.... tmp_parser.go:2418
+//.... tmp_parser.go:2416
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -2547,7 +2545,7 @@ tr12:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/csv_parser.rl:47
+//.... lightning/mydump/csv_parser.rl:45
 act = 2;
 	goto st22
 	st22:
@@ -2555,7 +2553,7 @@ act = 2;
 			goto _test_eof22
 		}
 	st_case_22:
-//.... tmp_parser.go:2558
+//.... tmp_parser.go:2556
 		_widec = int16(data[p])
 		switch {
 		case data[p] < 14:
@@ -2939,13 +2937,10 @@ act = 2;
 	_out: {}
 	}
 
-//.... lightning/mydump/csv_parser.rl:83
+//.... lightning/mydump/csv_parser.rl:81
 
 		if cs == 0 {
-			log.L().Error("syntax error",
-				zap.Int64("pos", parser.pos),
-				zap.ByteString("content", data),
-			)
+			parser.logSyntaxError()
 			return csvTokNil, nil, errors.New("syntax error")
 		}
 
diff --git a/lightning/mydump/parser.go b/lightning/mydump/parser.go
index f4addff..219ff78 100644
--- a/lightning/mydump/parser.go
+++ b/lightning/mydump/parser.go
@@ -25,9 +25,11 @@ import (
 	"github.com/pingcap/errors"
 	"github.com/pingcap/parser/mysql"
 	"github.com/pingcap/tidb-lightning/lightning/config"
+	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/tidb-lightning/lightning/metric"
 	"github.com/pingcap/tidb-lightning/lightning/worker"
 	"github.com/pingcap/tidb/types"
+	"go.uber.org/zap"
 )
 
 type blockParser struct {
@@ -48,6 +50,9 @@ type blockParser struct {
 	remainBuf *bytes.Buffer
 	appendBuf *bytes.Buffer
 	ioWorkers *worker.Pool
+
+	// the Logger associated with this parser for reporting failure
+	Logger log.Logger
 }
 
 func makeBlockParser(reader io.Reader, blockBufSize int64, ioWorkers *worker.Pool) blockParser {
@@ -57,6 +62,7 @@ func makeBlockParser(reader io.Reader, blockBufSize int64, ioWorkers *worker.Poo
 		remainBuf: &bytes.Buffer{},
 		appendBuf: &bytes.Buffer{},
 		ioWorkers: ioWorkers,
+		Logger:    log.L(),
 	}
 }
 
@@ -144,6 +150,17 @@ func (parser *blockParser) Columns() []string {
 	return parser.columns
 }
 
+func (parser *blockParser) logSyntaxError() {
+	content := parser.buf
+	if len(content) > 256 {
+		content = content[:256]
+	}
+	parser.Logger.Error("syntax error",
+		zap.Int64("pos", parser.pos),
+		zap.ByteString("content", content),
+	)
+}
+
 type token byte
 
 const (
diff --git a/lightning/mydump/parser.rl b/lightning/mydump/parser.rl
index 6e377ca..1ad090d 100644
--- a/lightning/mydump/parser.rl
+++ b/lightning/mydump/parser.rl
@@ -23,9 +23,7 @@ package mydump
 import (
 	"io"
 
-	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/errors"
-	"go.uber.org/zap"
 )
 
 %%{
@@ -156,10 +154,7 @@ func (parser *ChunkParser) lex() (token, []byte, error) {
 		%% write exec;
 
 		if cs == %%{ write error; }%% {
-			log.L().Error("syntax error",
-				zap.Int64("pos", parser.pos),
-				zap.ByteString("content", data),
-			)
+			parser.logSyntaxError()
 			return tokNil, nil, errors.New("syntax error")
 		}
 
diff --git a/lightning/mydump/parser_generated.go b/lightning/mydump/parser_generated.go
index 386abbd..0d20eec 100644
--- a/lightning/mydump/parser_generated.go
+++ b/lightning/mydump/parser_generated.go
@@ -26,17 +26,15 @@ package mydump
 import (
 	"io"
 
-	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/errors"
-	"go.uber.org/zap"
 )
 
 
-//.... lightning/mydump/parser.rl:139
+//.... lightning/mydump/parser.rl:137
 
 
 
-//.... tmp_parser.go:39
+//.... tmp_parser.go:37
 const chunk_parser_start int = 21
 const chunk_parser_first_final int = 21
 const chunk_parser_error int = 0
@@ -44,12 +42,12 @@ const chunk_parser_error int = 0
 const chunk_parser_en_main int = 21
 
 
-//.... lightning/mydump/parser.rl:142
+//.... lightning/mydump/parser.rl:140
 
 func (parser *ChunkParser) lex() (token, []byte, error) {
 	var cs, ts, te, act, p int
 	
-//.... tmp_parser.go:52
+//.... tmp_parser.go:50
 	{
 	cs = chunk_parser_start
 	ts = 0
@@ -57,7 +55,7 @@ func (parser *ChunkParser) lex() (token, []byte, error) {
 	act = 0
 	}
 
-//.... lightning/mydump/parser.rl:146
+//.... lightning/mydump/parser.rl:144
 
 	for {
 		data := parser.buf
@@ -69,7 +67,7 @@ func (parser *ChunkParser) lex() (token, []byte, error) {
 		}
 
 		
-//.... tmp_parser.go:72
+//.... tmp_parser.go:70
 	{
 	var _widec int16
 	if p == pe {
@@ -271,12 +269,12 @@ tr4:
 	
 	goto st21
 tr10:
-//.... lightning/mydump/parser.rl:70
+//.... lightning/mydump/parser.rl:68
 te = p+1
 
 	goto st21
 tr11:
-//.... lightning/mydump/parser.rl:132
+//.... lightning/mydump/parser.rl:130
 p = (te) - 1
 {
 		consumedToken = tokUnquoted
@@ -284,7 +282,7 @@ p = (te) - 1
 	}
 	goto st21
 tr12:
-//.... lightning/mydump/parser.rl:112
+//.... lightning/mydump/parser.rl:110
 te = p+1
 {
 		consumedToken = tokBinString
@@ -292,7 +290,7 @@ te = p+1
 	}
 	goto st21
 tr21:
-//.... lightning/mydump/parser.rl:107
+//.... lightning/mydump/parser.rl:105
 te = p+1
 {
 		consumedToken = tokHexString
@@ -300,7 +298,7 @@ te = p+1
 	}
 	goto st21
 tr28:
-//.... lightning/mydump/parser.rl:72
+//.... lightning/mydump/parser.rl:70
 te = p+1
 {
 		consumedToken = tokRowBegin
@@ -308,7 +306,7 @@ te = p+1
 	}
 	goto st21
 tr29:
-//.... lightning/mydump/parser.rl:77
+//.... lightning/mydump/parser.rl:75
 te = p+1
 {
 		consumedToken = tokRowEnd
@@ -316,7 +314,7 @@ te = p+1
 	}
 	goto st21
 tr42:
-//.... lightning/mydump/parser.rl:122
+//.... lightning/mydump/parser.rl:120
 te = p
 p--
 {
@@ -325,7 +323,7 @@ p--
 	}
 	goto st21
 tr43:
-//.... lightning/mydump/parser.rl:117
+//.... lightning/mydump/parser.rl:115
 te = p
 p--
 {
@@ -334,7 +332,7 @@ p--
 	}
 	goto st21
 tr44:
-//.... lightning/mydump/parser.rl:132
+//.... lightning/mydump/parser.rl:130
 te = p
 p--
 {
@@ -343,13 +341,13 @@ p--
 	}
 	goto st21
 tr46:
-//.... lightning/mydump/parser.rl:70
+//.... lightning/mydump/parser.rl:68
 te = p
 p--
 
 	goto st21
 tr48:
-//.... lightning/mydump/parser.rl:102
+//.... lightning/mydump/parser.rl:100
 te = p
 p--
 {
@@ -358,7 +356,7 @@ p--
 	}
 	goto st21
 tr79:
-//.... lightning/mydump/parser.rl:127
+//.... lightning/mydump/parser.rl:125
 te = p
 p--
 {
@@ -380,7 +378,7 @@ act = 0
 //.... NONE:1
 ts = p
 
-//.... tmp_parser.go:383
+//.... tmp_parser.go:381
 		switch data[p] {
 		case 32:
 			goto tr10
@@ -452,35 +450,35 @@ tr25:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:132
+//.... lightning/mydump/parser.rl:130
 act = 14;
 	goto st22
 tr62:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:97
+//.... lightning/mydump/parser.rl:95
 act = 7;
 	goto st22
 tr65:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:87
+//.... lightning/mydump/parser.rl:85
 act = 5;
 	goto st22
 tr68:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:92
+//.... lightning/mydump/parser.rl:90
 act = 6;
 	goto st22
 tr78:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:82
+//.... lightning/mydump/parser.rl:80
 act = 4;
 	goto st22
 	st22:
@@ -488,7 +486,7 @@ act = 4;
 			goto _test_eof22
 		}
 	st_case_22:
-//.... tmp_parser.go:491
+//.... tmp_parser.go:489
 		switch data[p] {
 		case 32:
 			goto tr4
@@ -574,7 +572,7 @@ tr1:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:122
+//.... lightning/mydump/parser.rl:120
 act = 12;
 	goto st23
 	st23:
@@ -582,7 +580,7 @@ act = 12;
 			goto _test_eof23
 		}
 	st_case_23:
-//.... tmp_parser.go:585
+//.... tmp_parser.go:583
 		if data[p] == 34 {
 			goto st2
 		}
@@ -680,7 +678,7 @@ tr6:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:117
+//.... lightning/mydump/parser.rl:115
 act = 11;
 	goto st24
 	st24:
@@ -688,7 +686,7 @@ act = 11;
 			goto _test_eof24
 		}
 	st_case_24:
-//.... tmp_parser.go:691
+//.... tmp_parser.go:689
 		if data[p] == 39 {
 			goto st5
 		}
@@ -900,14 +898,14 @@ tr49:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:132
+//.... lightning/mydump/parser.rl:130
 act = 14;
 	goto st30
 tr51:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:112
+//.... lightning/mydump/parser.rl:110
 act = 10;
 	goto st30
 	st30:
@@ -915,7 +913,7 @@ act = 10;
 			goto _test_eof30
 		}
 	st_case_30:
-//.... tmp_parser.go:918
+//.... tmp_parser.go:916
 		switch data[p] {
 		case 32:
 			goto tr4
@@ -947,14 +945,14 @@ tr50:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:132
+//.... lightning/mydump/parser.rl:130
 act = 14;
 	goto st31
 tr52:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:107
+//.... lightning/mydump/parser.rl:105
 act = 9;
 	goto st31
 	st31:
@@ -962,7 +960,7 @@ act = 9;
 			goto _test_eof31
 		}
 	st_case_31:
-//.... tmp_parser.go:965
+//.... tmp_parser.go:963
 		switch data[p] {
 		case 32:
 			goto tr4
@@ -1010,7 +1008,7 @@ te = p+1
 			goto _test_eof32
 		}
 	st_case_32:
-//.... tmp_parser.go:1013
+//.... tmp_parser.go:1011
 		switch data[p] {
 		case 32:
 			goto tr44
@@ -1728,7 +1726,7 @@ te = p+1
 			goto _test_eof54
 		}
 	st_case_54:
-//.... tmp_parser.go:1731
+//.... tmp_parser.go:1729
 		switch data[p] {
 		case 32:
 			goto st11
@@ -2009,7 +2007,7 @@ te = p+1
 			goto _test_eof60
 		}
 	st_case_60:
-//.... tmp_parser.go:2012
+//.... tmp_parser.go:2010
 		switch data[p] {
 		case 32:
 			goto tr44
@@ -2069,7 +2067,7 @@ tr24:
 //.... NONE:1
 te = p+1
 
-//.... lightning/mydump/parser.rl:127
+//.... lightning/mydump/parser.rl:125
 act = 13;
 	goto st61
 	st61:
@@ -2077,7 +2075,7 @@ act = 13;
 			goto _test_eof61
 		}
 	st_case_61:
-//.... tmp_parser.go:2080
+//.... tmp_parser.go:2078
 		if data[p] == 96 {
 			goto st20
 		}
@@ -2264,13 +2262,10 @@ act = 13;
 	_out: {}
 	}
 
-//.... lightning/mydump/parser.rl:157
+//.... lightning/mydump/parser.rl:155
 
 		if cs == 0 {
-			log.L().Error("syntax error",
-				zap.Int64("pos", parser.pos),
-				zap.ByteString("content", data),
-			)
+			parser.logSyntaxError()
 			return tokNil, nil, errors.New("syntax error")
 		}
 
diff --git a/lightning/restore/restore.go b/lightning/restore/restore.go
index 43f4eed..25330ed 100644
--- a/lightning/restore/restore.go
+++ b/lightning/restore/restore.go
@@ -1611,7 +1611,7 @@ outside:
 		case io.EOF:
 			break outside
 		default:
-			err = errors.Trace(err)
+			err = errors.Annotatef(err, "in file %s at offset %d", &cr.chunk.Key, newOffset)
 			return
 		}
 
@@ -1629,7 +1629,7 @@ outside:
 
 		if encodeErr != nil {
 			// error is already logged inside kvEncoder.Encode(), just propagate up directly.
-			err = encodeErr
+			err = errors.Annotatef(encodeErr, "in file %s at offset %d", &cr.chunk.Key, newOffset)
 			return
 		}
 


Test patch:
diff --git a/lightning/kv/sql2kv_test.go b/lightning/kv/sql2kv_test.go
index 43b5cf2..b4bdbe5 100644
--- a/lightning/kv/sql2kv_test.go
+++ b/lightning/kv/sql2kv_test.go
@@ -38,10 +38,10 @@ func (s *kvSuite) TestMarshal(c *C) {
 	err := encoder.AddArray("test", rowArrayMarshaler{types.NewStringDatum("1"), nullDatum, minNotNull, types.MaxValueDatum()})
 	c.Assert(err, IsNil)
 	c.Assert(encoder.Fields["test"], DeepEquals, []interface{}{
-		map[string]interface{}{"col": 0, "kind": "string", "val": "1"},
-		map[string]interface{}{"col": 1, "kind": "null", "val": "NULL"},
-		map[string]interface{}{"col": 2, "kind": "min", "val": "-inf"},
-		map[string]interface{}{"col": 3, "kind": "max", "val": "+inf"},
+		map[string]interface{}{"kind": "string", "val": "1"},
+		map[string]interface{}{"kind": "null", "val": "NULL"},
+		map[string]interface{}{"kind": "min", "val": "-inf"},
+		map[string]interface{}{"kind": "max", "val": "+inf"},
 	})
 
 	invalid := types.Datum{}
@@ -49,7 +49,7 @@ func (s *kvSuite) TestMarshal(c *C) {
 	err = encoder.AddArray("bad-test", rowArrayMarshaler{minNotNull, invalid})
 	c.Assert(err, ErrorMatches, "cannot convert.*")
 	c.Assert(encoder.Fields["bad-test"], DeepEquals, []interface{}{
-		map[string]interface{}{"col": 0, "kind": "min", "val": "-inf"},
+		map[string]interface{}{"kind": "min", "val": "-inf"},
 	})
 }
 
@@ -75,7 +75,7 @@ func (s *kvSuite) TestEncode(c *C) {
 	// Strict mode
 	strictMode := NewTableKVEncoder(tbl, mysql.ModeStrictAllTables)
 	pairs, err := strictMode.Encode(logger, rows, 1, []int{0, 1})
-	c.Assert(err, ErrorMatches, ".*overflows tinyint")
+	c.Assert(err, ErrorMatches, "failed to cast `10000000` as tinyint\\(4\\) for column `c1` \\(#1\\):.*overflows tinyint")
 	c.Assert(pairs, IsNil)
 
 	rowsWithPk := []types.Datum{
@@ -83,7 +83,7 @@ func (s *kvSuite) TestEncode(c *C) {
 		types.NewStringDatum("invalid-pk"),
 	}
 	pairs, err = strictMode.Encode(logger, rowsWithPk, 2, []int{0, 1})
-	c.Assert(err, ErrorMatches, ".*Data Truncated")
+	c.Assert(err, ErrorMatches, "failed to cast `invalid-pk` as bigint\\(20\\) for column `_tidb_rowid`.*Data Truncated")
 
 	rowsWithPk2 := []types.Datum{
 		types.NewIntDatum(1),
diff --git a/lightning/log/log_test.go b/lightning/log/log_test.go
index 4edee10..4fe11cb 100644
--- a/lightning/log/log_test.go
+++ b/lightning/log/log_test.go
@@ -18,6 +18,7 @@ import (
 
 	. "github.com/pingcap/check"
 	"github.com/pingcap/tidb-lightning/lightning/log"
+	"go.uber.org/zap"
 )
 
 func TestLog(t *testing.T) {
@@ -38,3 +39,12 @@ func (s *logSuite) TestConfigAdjust(c *C) {
 	c.Assert(err, ErrorMatches, "can't use directory as log file name")
 	log.L().Named("xx")
 }
+
+func (s *logSuite) TestTestLogger(c *C) {
+	logger, buffer := log.MakeTestLogger()
+	logger.Warn("the message", zap.Int("number", 123456), zap.Ints("array", []int{7, 8, 9}))
+	c.Assert(
+		buffer.Stripped(), Equals,
+		`{"$lvl":"WARN","$msg":"the message","number":123456,"array":[7,8,9]}`,
+	)
+}
diff --git a/lightning/log/testlogger.go b/lightning/log/testlogger.go
new file mode 100644
index 0000000..c0c8ee2
--- /dev/null
+++ b/lightning/log/testlogger.go
@@ -0,0 +1,36 @@
+// Copyright 2019 PingCAP, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package log
+
+import (
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest"
+)
+
+// MakeTestLogger creates a Logger instance which produces JSON logs.
+func MakeTestLogger() (Logger, *zaptest.Buffer) {
+	buffer := new(zaptest.Buffer)
+	logger := zap.New(zapcore.NewCore(
+		zapcore.NewJSONEncoder(zapcore.EncoderConfig{
+			LevelKey:       "$lvl",
+			MessageKey:     "$msg",
+			EncodeLevel:    zapcore.CapitalLevelEncoder,
+			EncodeDuration: zapcore.StringDurationEncoder,
+		}),
+		buffer,
+		zap.DebugLevel,
+	))
+	return Logger{Logger: logger}, buffer
+}
diff --git a/lightning/mydump/csv_parser_test.go b/lightning/mydump/csv_parser_test.go
index 56a321e..9e509b7 100644
--- a/lightning/mydump/csv_parser_test.go
+++ b/lightning/mydump/csv_parser_test.go
@@ -9,9 +9,11 @@ import (
 	. "github.com/pingcap/check"
 	"github.com/pingcap/errors"
 	"github.com/pingcap/tidb-lightning/lightning/config"
+	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/tidb-lightning/lightning/mydump"
 	"github.com/pingcap/tidb-lightning/lightning/worker"
 	"github.com/pingcap/tidb/types"
+	"go.uber.org/zap/zaptest"
 )
 
 var _ = Suite(&testMydumpCSVParserSuite{})
@@ -1134,3 +1136,23 @@ func (s *testMydumpCSVParserSuite) TestReadError(c *C) {
 	parser := mydump.NewCSVParser(&cfg, &errorReader{}, config.ReadBlockSize, s.ioWorkers)
 	c.Assert(parser.ReadRow(), ErrorMatches, "fake read error")
 }
+
+// TestSyntaxErrorLog checks that a syntax error won't dump huge strings into the log.
+func (s *testMydumpCSVParserSuite) TestSyntaxErrorLog(c *C) {
+	cfg := config.CSVConfig{
+		Separator: "\t",
+		Delimiter: "'",
+	}
+
+	tc := strings.NewReader("x'" + strings.Repeat("y", 50000))
+	parser := mydump.NewCSVParser(&cfg, tc, 50000, s.ioWorkers)
+	var buffer *zaptest.Buffer
+	parser.Logger, buffer = log.MakeTestLogger()
+	c.Assert(parser.ReadRow(), ErrorMatches, "syntax error.*")
+	c.Assert(parser.Logger.Sync(), IsNil)
+
+	c.Assert(
+		buffer.Stripped(), Equals,
+		`{"$lvl":"ERROR","$msg":"syntax error","pos":1,"content":"'`+strings.Repeat("y", 255)+`"}`,
+	)
+}
diff --git a/lightning/restore/restore_test.go b/lightning/restore/restore_test.go
index cc4ca74..7812aca 100644
--- a/lightning/restore/restore_test.go
+++ b/lightning/restore/restore_test.go
@@ -34,6 +34,7 @@ import (
 	"github.com/pingcap/tidb-lightning/lightning/common"
 	"github.com/pingcap/tidb-lightning/lightning/config"
 	"github.com/pingcap/tidb-lightning/lightning/kv"
+	"github.com/pingcap/tidb-lightning/lightning/log"
 	"github.com/pingcap/tidb-lightning/lightning/mydump"
 	"github.com/pingcap/tidb-lightning/lightning/verification"
 	"github.com/pingcap/tidb-lightning/lightning/worker"
@@ -99,7 +100,7 @@ func (s *restoreSuite) TestNewTableRestoreFailure(c *C) {
 }
 
 func (s *restoreSuite) TestErrorSummaries(c *C) {
-	logger, buffer := makeTestLogger()
+	logger, buffer := log.MakeTestLogger()
 
 	es := makeErrorSummaries(logger)
 	es.record("first", errors.New("a1 error"), CheckpointStatusAnalyzed)
@@ -724,6 +725,20 @@ func (s *chunkRestoreSuite) TestEncodeLoopCanceled(c *C) {
 	c.Assert(kvsCh, HasLen, 0)
 }
 
+func (s *chunkRestoreSuite) TestEncodeLoopForcedError(c *C) {
+	ctx := context.Background()
+	kvsCh := make(chan deliveredKVs, 2)
+	deliverCompleteCh := make(chan deliverResult)
+	kvEncoder := kv.NewTableKVEncoder(s.tr.encTable, s.cfg.TiDB.SQLMode)
+
+	// close the chunk so reading it will result in the "file already closed" error.
+	s.cr.parser.Close()
+
+	_, _, err := s.cr.encodeLoop(ctx, kvsCh, s.tr, s.tr.logger, kvEncoder, deliverCompleteCh)
+	c.Assert(err, ErrorMatches, `in file .*/db.table.2.sql:0 at offset 0:.*file already closed`)
+	c.Assert(kvsCh, HasLen, 0)
+}
+
 func (s *chunkRestoreSuite) TestEncodeLoopDeliverErrored(c *C) {
 	ctx := context.Background()
 	kvsCh := make(chan deliveredKVs)
diff --git a/lightning/restore/testlogger_test.go b/lightning/restore/testlogger_test.go
deleted file mode 100644
index a499ec8..0000000
--- a/lightning/restore/testlogger_test.go
+++ /dev/null
@@ -1,24 +0,0 @@
-package restore
-
-import (
-	"github.com/pingcap/tidb-lightning/lightning/log"
-	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
-	"go.uber.org/zap/zaptest"
-)
-
-// makeTestLogger creates a Logger instance which produces JSON logs.
-func makeTestLogger() (log.Logger, *zaptest.Buffer) {
-	buffer := new(zaptest.Buffer)
-	logger := zap.New(zapcore.NewCore(
-		zapcore.NewJSONEncoder(zapcore.EncoderConfig{
-			LevelKey:       "$lvl",
-			MessageKey:     "$msg",
-			EncodeLevel:    zapcore.CapitalLevelEncoder,
-			EncodeDuration: zapcore.StringDurationEncoder,
-		}),
-		buffer,
-		zap.DebugLevel,
-	))
-	return log.Logger{Logger: logger}, buffer
-}
diff --git a/tests/sqlmode/run.sh b/tests/sqlmode/run.sh
index afde939..4e3c93e 100755
--- a/tests/sqlmode/run.sh
+++ b/tests/sqlmode/run.sh
@@ -54,4 +54,4 @@ run_lightning on
 [ $? -ne 0 ] || exit 1
 set -e
 
-grep -q '\["kv convert failed"\].*\[originalRow=.*col=1,kind=uint64,val=9.*\].*\[originalCol=1\] \[colName=a\] \[colType="timestamp BINARY"\]' "$TEST_DIR/sqlmode-error.log"
+grep -q '\["kv convert failed"\].*\[original=.*kind=uint64,val=9.*\] \[originalCol=1\] \[colName=a\] \[colType="timestamp BINARY"\]' "$TEST_DIR/sqlmode-error.log"