firefly-ethconnect icon indicating copy to clipboard operation
firefly-ethconnect copied to clipboard

Published 20 hours ago • verified publisher icon hyperledger

Intermittent failure TestUpdateStreamInvalidWebhookURL

Open peterbroadhurst opened this issue 3 years ago • 0 comments 

2021-11-23T05:25:39.1160458Z === RUN   TestUpdateStreamInvalidWebhookURL
2021-11-23T05:25:39.1161372Z     submanager_test.go:54: tmpdir/create: /tmp/fly050519160
2021-11-23T05:25:39.1162700Z time="2021-11-23T05:25:38Z" level=debug msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Begin batch dispatcher loop, current batch length: 0"
2021-11-23T05:25:39.1164927Z time="2021-11-23T05:25:38Z" level=info msg="Created subscription ID:sb-656816c5-98d2-427b-50cf-0a03adb7e743 name:mySubName topic:0x063e04f28cb50f8e287e51b090fb7178b81cdc973d06858573c0a273133cfe1c"
2021-11-23T05:25:39.1166671Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_blockNumber call=1"
2021-11-23T05:25:39.1168452Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): initial block height for event stream (latest block): 0"
2021-11-23T05:25:39.1170108Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_blockNumber call=2"
2021-11-23T05:25:39.1171843Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): restarting. Head=0 Position=0 Gap=0 (catchup threshold: 250)"
2021-11-23T05:25:39.1173418Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_newFilter call=3"
2021-11-23T05:25:39.1175132Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Marking filter stale=false, current sub filter stale=true"
2021-11-23T05:25:39.1178415Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): created filter from block 0: 0x0 - {Addresses:[0x167F57A13A9C35ff92f0649d2be0e52b4f8AC3ca] Topics:[[0x063e04f28cb50f8e287e51b090fb7178b81cdc973d06858573c0a273133cfe1c]]}"
2021-11-23T05:25:39.1181095Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743: Checkpoint updated due to stale sub filter: 0"
2021-11-23T05:25:39.1182314Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_getFilterLogs call=4"
2021-11-23T05:25:39.1184019Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): received 2 events (eth_getFilterLogs)"
2021-11-23T05:25:39.1186588Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Dispatching event. Address=0x14c2D07516b7678597068F81d91b3124471703E8 BlockNumber=150665 TxIndex=0x0"
2021-11-23T05:25:39.1189357Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Dispatching event. Address=0x14c2D07516b7678597068F81d91b3124471703E8 BlockNumber=150665 TxIndex=0x0"
2021-11-23T05:25:39.1191342Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: New batch length 1"
2021-11-23T05:25:39.1192847Z time="2021-11-23T05:25:38Z" level=debug msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Begin batch dispatcher loop, current batch length: 0"
2021-11-23T05:25:39.1194281Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: New batch length 1"
2021-11-23T05:25:39.1195868Z time="2021-11-23T05:25:38Z" level=debug msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Begin batch dispatcher loop, current batch length: 0"
2021-11-23T05:25:39.1197728Z time="2021-11-23T05:25:38Z" level=debug msg="Storing checkpoint cp-es-07b17239-1d96-4da8-419e-b2d3dbc2defa: {\n  \"sb-656816c5-98d2-427b-50cf-0a03adb7e743\": 0\n}"
2021-11-23T05:25:39.1199560Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Batch 1 initiated with 1 events. FirstBlock=150665 LastBlock=150665"
2021-11-23T05:25:39.1201221Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: POST --> http://127.0.0.1:35221 [127.0.0.1] (attempt=1)"
2021-11-23T05:25:39.1202785Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: POST <-- http://127.0.0.1:35221 [200] ok=true"
2021-11-23T05:25:39.1204171Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Response body: "
2021-11-23T05:25:39.1205436Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743: HWM: 150666"
2021-11-23T05:25:39.1207014Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Batch 2 initiated with 1 events. FirstBlock=150665 LastBlock=150665"
2021-11-23T05:25:39.1222985Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: POST --> http://127.0.0.1:35221 [127.0.0.1] (attempt=1)"
2021-11-23T05:25:39.1224938Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: POST <-- http://127.0.0.1:35221 [200] ok=true"
2021-11-23T05:25:39.1226853Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Response body: "
2021-11-23T05:25:39.1228366Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743: HWM: 150666"
2021-11-23T05:25:39.1229707Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_getFilterChanges call=5"
2021-11-23T05:25:39.1231709Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): received 1 events (eth_getFilterChanges)"
2021-11-23T05:25:39.1234791Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Dispatching event. Address=0x14c2D07516b7678597068F81d91b3124471703E8 BlockNumber=150721 TxIndex=0x0"
2021-11-23T05:25:39.1237599Z time="2021-11-23T05:25:38Z" level=debug msg="Storing checkpoint cp-es-07b17239-1d96-4da8-419e-b2d3dbc2defa: {\n  \"sb-656816c5-98d2-427b-50cf-0a03adb7e743\": 150666\n}"
2021-11-23T05:25:39.1239455Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: New batch length 1"
2021-11-23T05:25:39.1242918Z time="2021-11-23T05:25:38Z" level=debug msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Begin batch dispatcher loop, current batch length: 0"
2021-11-23T05:25:39.1244622Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Batch 3 initiated with 1 events. FirstBlock=150721 LastBlock=150721"
2021-11-23T05:25:39.1246307Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: POST --> http://127.0.0.1:35221 [127.0.0.1] (attempt=1)"
2021-11-23T05:25:39.1247893Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Update event stream"
2021-11-23T05:25:39.1249452Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Notified of an ongoing stream update, existing event poller"
2021-11-23T05:25:39.1251518Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Marking filter stale=true, current sub filter stale=false"
2021-11-23T05:25:39.1253133Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_uninstallFilter call=6"
2021-11-23T05:25:39.1254972Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Uninstalled filter. ok=false (%!s(<nil>))"
2021-11-23T05:25:39.1256945Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Notified of an ongoing stream update, not waiting for new events"
2021-11-23T05:25:39.1258568Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: POST <-- http://127.0.0.1:35221 [200] ok=true"
2021-11-23T05:25:39.1259979Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Response body: "
2021-11-23T05:25:39.1261228Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743: HWM: 150722"
2021-11-23T05:25:39.1262724Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Notified of an ongoing stream update, existing batch processor"
2021-11-23T05:25:39.1264590Z time="2021-11-23T05:25:38Z" level=debug msg="Loaded checkpoint cp-es-07b17239-1d96-4da8-419e-b2d3dbc2defa: {\n  \"sb-656816c5-98d2-427b-50cf-0a03adb7e743\": 150666\n}"
2021-11-23T05:25:39.1267927Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): checkpoint restored block height for event stream: 150666"
2021-11-23T05:25:39.1269546Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_blockNumber call=7"
2021-11-23T05:25:39.1271347Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): restarting. Head=0 Position=150666 Gap=-150666 (catchup threshold: 250)"
2021-11-23T05:25:39.1272948Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_newFilter call=8"
2021-11-23T05:25:39.1274585Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Marking filter stale=false, current sub filter stale=true"
2021-11-23T05:25:39.1277625Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): created filter from block 150666: 0x0 - {Addresses:[0x167F57A13A9C35ff92f0649d2be0e52b4f8AC3ca] Topics:[[0x063e04f28cb50f8e287e51b090fb7178b81cdc973d06858573c0a273133cfe1c]]}"
2021-11-23T05:25:39.1280137Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743: Checkpoint updated due to stale sub filter: 150666"
2021-11-23T05:25:39.1281273Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_getFilterLogs call=9"
2021-11-23T05:25:39.1282849Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): received 2 events (eth_getFilterLogs)"
2021-11-23T05:25:39.1285568Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Dispatching event. Address=0x14c2D07516b7678597068F81d91b3124471703E8 BlockNumber=150665 TxIndex=0x0"
2021-11-23T05:25:39.1288359Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Unsubscribing existing filter (deleting=true)"
2021-11-23T05:25:39.1290721Z time="2021-11-23T05:25:38Z" level=debug msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Marking filter stale=true, current sub filter stale=false"
2021-11-23T05:25:39.1292340Z time="2021-11-23T05:25:38Z" level=info msg="UT eth_uninstallFilter call=10"
2021-11-23T05:25:39.1293990Z time="2021-11-23T05:25:38Z" level=info msg="sb-656816c5-98d2-427b-50cf-0a03adb7e743:Changed(address,int64,string,bytes32,string): Uninstalled filter. ok=false (%!s(<nil>))"
2021-11-23T05:25:39.1295899Z time="2021-11-23T05:25:38Z" level=debug msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Begin batch dispatcher loop, current batch length: 0"
2021-11-23T05:25:39.1297458Z time="2021-11-23T05:25:38Z" level=info msg="es-07b17239-1d96-4da8-419e-b2d3dbc2defa: Notified of an ongoing stream update, not waiting for new events"
2021-11-23T05:25:39.1298352Z panic: send on closed channel
2021-11-23T05:25:39.1298674Z 
2021-11-23T05:25:39.1299152Z goroutine 571 [running]:
2021-11-23T05:25:39.1300168Z github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).handleEvent(...)
2021-11-23T05:25:39.1301781Z 	/home/runner/work/firefly-ethconnect/firefly-ethconnect/ethconnect/internal/events/eventstream.go:315
2021-11-23T05:25:39.1303443Z github.com/hyperledger/firefly-ethconnect/internal/events.(*logProcessor).processLogEntry(0xc00033a9a0, 0xc000037a40, 0x54, 0xc00008afd0, 0x0, 0x3, 0x3)
2021-11-23T05:25:39.1305111Z 	/home/runner/work/firefly-ethconnect/firefly-ethconnect/ethconnect/internal/events/logprocessor.go:179 +0xabd
2021-11-23T05:25:39.1306778Z github.com/hyperledger/firefly-ethconnect/internal/events.(*subscription).processLogs(0xc000285400, 0xe22548, 0xc000210960, 0xd4f4a9, 0x11, 0xc00020ad00, 0x2, 0x4)
2021-11-23T05:25:39.1308429Z 	/home/runner/work/firefly-ethconnect/firefly-ethconnect/ethconnect/internal/events/subscription.go:318 +0x129
2021-11-23T05:25:39.1310030Z github.com/hyperledger/firefly-ethconnect/internal/events.(*subscription).processNewEvents(0xc000285400, 0xe22580, 0xc000210960, 0x0, 0x0)
2021-11-23T05:25:39.1311659Z 	/home/runner/work/firefly-ethconnect/firefly-ethconnect/ethconnect/internal/events/subscription.go:342 +0x396
2021-11-23T05:25:39.1313122Z github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).eventPoller(0xc0000d8240)
2021-11-23T05:25:39.1314645Z 	/home/runner/work/firefly-ethconnect/firefly-ethconnect/ethconnect/internal/events/eventstream.go:437 +0x305
2021-11-23T05:25:39.1316288Z created by github.com/hyperledger/firefly-ethconnect/internal/events.(*eventStream).startEventHandlers
2021-11-23T05:25:39.1317853Z 	/home/runner/work/firefly-ethconnect/firefly-ethconnect/ethconnect/internal/events/eventstream.go:207 +0xc5
2021-11-23T05:25:39.1319149Z FAIL	github.com/hyperledger/firefly-ethconnect/internal/events	0.678s

peterbroadhurst avatar Nov 23 '21 05:11 peterbroadhurst