github.com/viacoin/blockbook@v0.3.2-0.20200124170434-77b4f2555a4b/server/socketio_log_test.go (about) 1 // +build integration 2 3 package server 4 5 import ( 6 "bufio" 7 "crypto/tls" 8 "encoding/json" 9 "flag" 10 "os" 11 "reflect" 12 "sort" 13 "strings" 14 "testing" 15 "time" 16 17 "github.com/gorilla/websocket" 18 "github.com/juju/errors" 19 "github.com/martinboehm/golang-socketio" 20 "github.com/martinboehm/golang-socketio/transport" 21 ) 22 23 var ( 24 // verifier functionality 25 verifylog = flag.String("verifylog", "", "path to logfile containing socket.io requests/responses") 26 wsurl = flag.String("wsurl", "", "URL of socket.io interface to verify") 27 newSocket = flag.Bool("newsocket", false, "Create new socket.io connection for each request") 28 ) 29 30 type verifyStats struct { 31 Count int 32 SuccessCount int 33 TotalLogNs int64 34 TotalBlockbookNs int64 35 } 36 37 type logMessage struct { 38 ID int `json:"id"` 39 Et int64 `json:"et"` 40 Res json.RawMessage `json:"res"` 41 Req json.RawMessage `json:"req"` 42 } 43 44 type logRequestResponse struct { 45 Request, Response json.RawMessage 46 LogElapsedTime int64 47 } 48 49 func getStat(m string, stats map[string]*verifyStats) *verifyStats { 50 s, ok := stats[m] 51 if !ok { 52 s = &verifyStats{} 53 stats[m] = s 54 } 55 return s 56 } 57 58 func unmarshalResponses(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, bbResponse interface{}, logResponse interface{}) error { 59 err := json.Unmarshal([]byte(bbResStr), bbResponse) 60 if err != nil { 61 t.Log(id, ": error unmarshal BB request ", err) 62 return err 63 } 64 err = json.Unmarshal([]byte(lrs.Response), logResponse) 65 if err != nil { 66 t.Log(id, ": error unmarshal log request ", err) 67 return err 68 } 69 return nil 70 } 71 72 func getFullAddressHistory(addr []string, rr addrOpts, ws *gosocketio.Client) (*resultGetAddressHistory, error) { 73 rr.From = 0 74 rr.To = 100000000 75 rq := map[string]interface{}{ 76 "method": "getAddressHistory", 77 "params": []interface{}{ 78 addr, 79 rr, 80 }, 81 } 82 rrq, err := json.Marshal(rq) 83 if err != nil { 84 return nil, err 85 } 86 res, err := ws.Ack("message", json.RawMessage(rrq), time.Second*30) 87 if err != nil { 88 return nil, err 89 } 90 bbResponse := resultGetAddressHistory{} 91 err = json.Unmarshal([]byte(res), &bbResponse) 92 if err != nil { 93 return nil, err 94 } 95 return &bbResponse, nil 96 } 97 98 func equalTx(logTx resTx, bbTx resTx) error { 99 if logTx.Hash != bbTx.Hash { 100 return errors.Errorf("Different Hash bb: %v log: %v", bbTx.Hash, logTx.Hash) 101 } 102 if logTx.Hex != bbTx.Hex { 103 return errors.Errorf("Different Hex bb: %v log: %v", bbTx.Hex, logTx.Hex) 104 } 105 if logTx.BlockTimestamp != bbTx.BlockTimestamp && logTx.BlockTimestamp != 0 { 106 return errors.Errorf("Different BlockTimestamp bb: %v log: %v", bbTx.BlockTimestamp, logTx.BlockTimestamp) 107 } 108 if logTx.FeeSatoshis != bbTx.FeeSatoshis { 109 return errors.Errorf("Different FeeSatoshis bb: %v log: %v", bbTx.FeeSatoshis, logTx.FeeSatoshis) 110 } 111 if logTx.Height != bbTx.Height && logTx.Height != -1 { 112 return errors.Errorf("Different Height bb: %v log: %v", bbTx.Height, logTx.Height) 113 } 114 if logTx.InputSatoshis != bbTx.InputSatoshis { 115 return errors.Errorf("Different InputSatoshis bb: %v log: %v", bbTx.InputSatoshis, logTx.InputSatoshis) 116 } 117 if logTx.Locktime != bbTx.Locktime { 118 return errors.Errorf("Different Locktime bb: %v log: %v", bbTx.Locktime, logTx.Locktime) 119 } 120 if logTx.OutputSatoshis != bbTx.OutputSatoshis { 121 return errors.Errorf("Different OutputSatoshis bb: %v log: %v", bbTx.OutputSatoshis, logTx.OutputSatoshis) 122 } 123 if logTx.Version != bbTx.Version { 124 return errors.Errorf("Different Version bb: %v log: %v", bbTx.Version, logTx.Version) 125 } 126 if len(logTx.Inputs) != len(bbTx.Inputs) { 127 return errors.Errorf("Different number of Inputs bb: %v log: %v", len(bbTx.Inputs), len(logTx.Inputs)) 128 } 129 // blockbook parses bech addresses, it is ok for bitcore to return nil address and blockbook parsed address 130 for i := range logTx.Inputs { 131 if logTx.Inputs[i].Satoshis != bbTx.Inputs[i].Satoshis || 132 (bbTx.Inputs[i].Address == nil && logTx.Inputs[i].Address != bbTx.Inputs[i].Address) || 133 (logTx.Inputs[i].Address != nil && *logTx.Inputs[i].Address != *bbTx.Inputs[i].Address) || 134 logTx.Inputs[i].OutputIndex != bbTx.Inputs[i].OutputIndex || 135 logTx.Inputs[i].Sequence != bbTx.Inputs[i].Sequence { 136 return errors.Errorf("Different Inputs bb: %+v log: %+v", bbTx.Inputs, logTx.Inputs) 137 } 138 } 139 if len(logTx.Outputs) != len(bbTx.Outputs) { 140 return errors.Errorf("Different number of Outputs bb: %v log: %v", len(bbTx.Outputs), len(logTx.Outputs)) 141 } 142 // blockbook parses bech addresses, it is ok for bitcore to return nil address and blockbook parsed address 143 for i := range logTx.Outputs { 144 if logTx.Outputs[i].Satoshis != bbTx.Outputs[i].Satoshis || 145 (bbTx.Outputs[i].Address == nil && logTx.Outputs[i].Address != bbTx.Outputs[i].Address) || 146 (logTx.Outputs[i].Address != nil && *logTx.Outputs[i].Address != *bbTx.Outputs[i].Address) { 147 return errors.Errorf("Different Outputs bb: %+v log: %+v", bbTx.Outputs, logTx.Outputs) 148 } 149 } 150 return nil 151 } 152 153 func equalAddressHistoryItem(logItem addressHistoryItem, bbItem addressHistoryItem) error { 154 if err := equalTx(logItem.Tx, bbItem.Tx); err != nil { 155 return err 156 } 157 if !reflect.DeepEqual(logItem.Addresses, bbItem.Addresses) { 158 return errors.Errorf("Different Addresses bb: %v log: %v", bbItem.Addresses, logItem.Addresses) 159 } 160 if logItem.Satoshis != bbItem.Satoshis { 161 return errors.Errorf("Different Satoshis bb: %v log: %v", bbItem.Satoshis, logItem.Satoshis) 162 } 163 return nil 164 } 165 166 func verifyGetAddressHistory(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, stat *verifyStats, ws *gosocketio.Client, bbRequest map[string]json.RawMessage) { 167 bbResponse := resultGetAddressHistory{} 168 logResponse := resultGetAddressHistory{} 169 var bbFullResponse *resultGetAddressHistory 170 if err := unmarshalResponses(t, id, lrs, bbResStr, &bbResponse, &logResponse); err != nil { 171 return 172 } 173 // parse request to check params 174 addr, rr, err := unmarshalGetAddressRequest(bbRequest["params"]) 175 if err != nil { 176 t.Log(id, ": getAddressHistory error unmarshal BB request ", err) 177 return 178 } 179 // mempool transactions are not comparable 180 if !rr.QueryMempoolOnly { 181 if (logResponse.Result.TotalCount != bbResponse.Result.TotalCount) || 182 len(logResponse.Result.Items) != len(bbResponse.Result.Items) { 183 t.Log("getAddressHistory", id, "mismatch bb:", bbResponse.Result.TotalCount, len(bbResponse.Result.Items), 184 "log:", logResponse.Result.TotalCount, len(logResponse.Result.Items)) 185 return 186 } 187 if logResponse.Result.TotalCount > 0 { 188 for i, logItem := range logResponse.Result.Items { 189 bbItem := bbResponse.Result.Items[i] 190 if err = equalAddressHistoryItem(logItem, bbItem); err != nil { 191 // if multiple addresses are specified, BlockBook returns transactions in different order 192 // which causes problems in paged responses 193 // we have to get all transactions from blockbook and check that they are in the logged response 194 var err1 error 195 if bbFullResponse == nil { 196 bbFullResponse, err1 = getFullAddressHistory(addr, rr, ws) 197 if err1 != nil { 198 t.Log("getFullAddressHistory error", err) 199 return 200 } 201 if bbFullResponse.Result.TotalCount != logResponse.Result.TotalCount { 202 t.Log("getFullAddressHistory count mismatch", bbFullResponse.Result.TotalCount, logResponse.Result.TotalCount) 203 return 204 } 205 } 206 found := false 207 for _, bbFullItem := range bbFullResponse.Result.Items { 208 err1 = equalAddressHistoryItem(logItem, bbFullItem) 209 if err1 == nil { 210 found = true 211 break 212 } 213 if err1.Error()[:14] != "Different Hash" { 214 t.Log(err1) 215 } 216 } 217 if !found { 218 t.Log("getAddressHistory", id, "addresses", addr, "mismatch ", err) 219 return 220 } 221 } 222 } 223 } 224 } 225 stat.SuccessCount++ 226 } 227 228 func verifyGetInfo(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, stat *verifyStats) { 229 bbResponse := resultGetInfo{} 230 logResponse := resultGetInfo{} 231 if err := unmarshalResponses(t, id, lrs, bbResStr, &bbResponse, &logResponse); err != nil { 232 return 233 } 234 if logResponse.Result.Blocks <= bbResponse.Result.Blocks && 235 logResponse.Result.Testnet == bbResponse.Result.Testnet && 236 logResponse.Result.Network == bbResponse.Result.Network { 237 stat.SuccessCount++ 238 } else { 239 t.Log("getInfo", id, "mismatch bb:", bbResponse.Result.Blocks, bbResponse.Result.Testnet, bbResponse.Result.Network, 240 "log:", logResponse.Result.Blocks, logResponse.Result.Testnet, logResponse.Result.Network) 241 } 242 } 243 244 func verifyGetBlockHeader(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, stat *verifyStats) { 245 bbResponse := resultGetBlockHeader{} 246 logResponse := resultGetBlockHeader{} 247 if err := unmarshalResponses(t, id, lrs, bbResStr, &bbResponse, &logResponse); err != nil { 248 return 249 } 250 if logResponse.Result.Hash == bbResponse.Result.Hash { 251 stat.SuccessCount++ 252 } else { 253 t.Log("getBlockHeader", id, "mismatch bb:", bbResponse.Result.Hash, 254 "log:", logResponse.Result.Hash) 255 } 256 } 257 258 func verifyEstimateSmartFee(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, stat *verifyStats) { 259 bbResponse := resultEstimateSmartFee{} 260 logResponse := resultEstimateSmartFee{} 261 if err := unmarshalResponses(t, id, lrs, bbResStr, &bbResponse, &logResponse); err != nil { 262 return 263 } 264 // it is not possible to compare fee directly, it changes over time, 265 // verify that the BB fee is in a reasonable range 266 if bbResponse.Result > 0 && bbResponse.Result < .1 { 267 stat.SuccessCount++ 268 } else { 269 t.Log("estimateSmartFee", id, "mismatch bb:", bbResponse.Result, 270 "log:", logResponse.Result) 271 } 272 } 273 274 func verifySendTransaction(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, stat *verifyStats) { 275 bbResponse := resultSendTransaction{} 276 logResponse := resultSendTransaction{} 277 if err := unmarshalResponses(t, id, lrs, bbResStr, &bbResponse, &logResponse); err != nil { 278 return 279 } 280 bbResponseError := resultError{} 281 err := json.Unmarshal([]byte(bbResStr), &bbResponseError) 282 if err != nil { 283 t.Log(id, ": error unmarshal resultError ", err) 284 return 285 } 286 // it is not possible to repeat sendTransaction, expect error 287 if bbResponse.Result == "" && bbResponseError.Error.Message != "" { 288 stat.SuccessCount++ 289 } else { 290 t.Log("sendTransaction", id, "problem:", bbResponse.Result, bbResponseError) 291 } 292 } 293 294 func verifyGetDetailedTransaction(t *testing.T, id int, lrs *logRequestResponse, bbResStr string, stat *verifyStats) { 295 bbResponse := resultGetDetailedTransaction{} 296 logResponse := resultGetDetailedTransaction{} 297 if err := unmarshalResponses(t, id, lrs, bbResStr, &bbResponse, &logResponse); err != nil { 298 return 299 } 300 if err := equalTx(logResponse.Result, bbResponse.Result); err != nil { 301 t.Log("getDetailedTransaction", id, err) 302 return 303 } 304 stat.SuccessCount++ 305 } 306 307 func verifyMessage(t *testing.T, ws *gosocketio.Client, id int, lrs *logRequestResponse, stats map[string]*verifyStats) { 308 req := make(map[string]json.RawMessage) 309 err := json.Unmarshal(lrs.Request, &req) 310 if err != nil { 311 t.Log(id, ": error unmarshal request ", err) 312 return 313 } 314 method := strings.Trim(string(req["method"]), "\"") 315 if method == "" { 316 t.Log(id, ": there is no method specified in request") 317 return 318 } 319 // send the message to blockbook 320 start := time.Now() 321 res, err := ws.Ack("message", lrs.Request, time.Second*30) 322 if err != nil { 323 t.Log(id, ",", method, ": ws.Ack error ", err) 324 getStat("ackError", stats).Count++ 325 return 326 } 327 ts := time.Since(start).Nanoseconds() 328 stat := getStat(method, stats) 329 stat.Count++ 330 stat.TotalLogNs += lrs.LogElapsedTime 331 stat.TotalBlockbookNs += ts 332 switch method { 333 case "getAddressHistory": 334 verifyGetAddressHistory(t, id, lrs, res, stat, ws, req) 335 case "getBlockHeader": 336 verifyGetBlockHeader(t, id, lrs, res, stat) 337 case "getDetailedTransaction": 338 verifyGetDetailedTransaction(t, id, lrs, res, stat) 339 case "getInfo": 340 verifyGetInfo(t, id, lrs, res, stat) 341 case "estimateSmartFee": 342 verifyEstimateSmartFee(t, id, lrs, res, stat) 343 case "sendTransaction": 344 verifySendTransaction(t, id, lrs, res, stat) 345 // case "getAddressTxids": 346 // case "estimateFee": 347 // case "getMempoolEntry": 348 default: 349 t.Log(id, ",", method, ": unknown/unverified method", method) 350 } 351 } 352 353 func connectSocketIO(t *testing.T) *gosocketio.Client { 354 tr := transport.GetDefaultWebsocketTransport() 355 tr.WebsocketDialer = websocket.Dialer{ 356 TLSClientConfig: &tls.Config{InsecureSkipVerify: true}, 357 } 358 ws, err := gosocketio.Dial(*wsurl, tr) 359 if err != nil { 360 t.Fatal("Dial error ", err) 361 return nil 362 } 363 return ws 364 } 365 366 func Test_VerifyLog(t *testing.T) { 367 if *verifylog == "" || *wsurl == "" { 368 t.Skip("skipping test, flags verifylog or wsurl not specified") 369 } 370 t.Log("Verifying log", *verifylog, "against service", *wsurl) 371 var ws *gosocketio.Client 372 if !*newSocket { 373 ws = connectSocketIO(t) 374 defer ws.Close() 375 } 376 file, err := os.Open(*verifylog) 377 if err != nil { 378 t.Fatal("File read error", err) 379 return 380 } 381 defer file.Close() 382 scanner := bufio.NewScanner(file) 383 buf := make([]byte, 1<<25) 384 scanner.Buffer(buf, 1<<25) 385 scanner.Split(bufio.ScanLines) 386 line := 0 387 stats := make(map[string]*verifyStats) 388 pairs := make(map[int]*logRequestResponse, 0) 389 for scanner.Scan() { 390 line++ 391 msg := logMessage{} 392 err := json.Unmarshal(scanner.Bytes(), &msg) 393 if err != nil { 394 t.Log("Line ", line, ": json error ", err) 395 continue 396 } 397 lrs, exists := pairs[msg.ID] 398 if !exists { 399 lrs = &logRequestResponse{} 400 pairs[msg.ID] = lrs 401 } 402 if msg.Req != nil { 403 if lrs.Request != nil { 404 t.Log("Line ", line, ": duplicate request with id ", msg.ID) 405 continue 406 } 407 lrs.Request = msg.Req 408 } else if msg.Res != nil { 409 if lrs.Response != nil { 410 t.Log("Line ", line, ": duplicate response with id ", msg.ID) 411 continue 412 } 413 lrs.Response = msg.Res 414 lrs.LogElapsedTime = msg.Et 415 } 416 if lrs.Request != nil && lrs.Response != nil { 417 if *newSocket { 418 ws = connectSocketIO(t) 419 } 420 verifyMessage(t, ws, msg.ID, lrs, stats) 421 if *newSocket { 422 ws.Close() 423 } 424 delete(pairs, msg.ID) 425 } 426 } 427 var keys []string 428 for k := range stats { 429 keys = append(keys, k) 430 } 431 failures := 0 432 sort.Strings(keys) 433 t.Log("Processed", line, "lines") 434 for _, k := range keys { 435 s := stats[k] 436 failures += s.Count - s.SuccessCount 437 t.Log("Method:", k, "\tCount:", s.Count, "\tSuccess:", s.SuccessCount, 438 "\tTime log:", s.TotalLogNs, "\tTime BB:", s.TotalBlockbookNs, 439 "\tTime BB/log", float64(s.TotalBlockbookNs)/float64(s.TotalLogNs)) 440 } 441 if failures != 0 { 442 t.Error("Number of failures:", failures) 443 } 444 }