Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Intermittent failure TestUpdateStreamInvalidWebhookURL #182

Open
peterbroadhurst opened this issue Nov 23, 2021 · 0 comments
Open

Intermittent failure TestUpdateStreamInvalidWebhookURL #182

peterbroadhurst opened this issue Nov 23, 2021 · 0 comments

Comments

@peterbroadhurst
Copy link
Contributor

peterbroadhurst commented Nov 23, 2021 •
edited 

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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@peterbroadhurst