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

Issue processing ack on first batch #104

Open
nguyer opened this issue Nov 13, 2023 · 2 comments
Open

Issue processing ack on first batch #104

nguyer opened this issue Nov 13, 2023 · 2 comments
Labels
bug Something isn't working

Comments

@nguyer
Copy link
Contributor

nguyer commented Nov 13, 2023

Description

I have observed that FireFly Core and EVMConnect have trouble communicating the very first batch/ack after FireFly Core restarts. EVMConnect thinks that the WebSocket client disconnects right after dispatching the batch, but it receives the ack from FireFly Core right after that, but it's too late because it's already marked the attempt as failed, so it tries again. FireFly Core correctly discards the duplicate event and ack's it again. The cycle repeats and finally succeeds the third time.

Steps to reproduce

  • Create a new FireFly stack and run a few transactions that will result in a batch pin
  • docker restart your FireFly core container
  • Do another transaction from the other FireFly node
  • Observe the silliness in the logs

FireFly Core Log

[2023-11-13T21:37:56.254Z]  INFO Received 'BatchPin(address,uint256,string,bytes32,bytes32,string,bytes32[])' message on '018bca9d-3db0-2954-6f22-fd607a447bcd' ethmsgidx=0 pid=1 proto=ethereum role=event-loop
[2023-11-13T21:37:56.256Z]  INFO -> BatchPinComplete batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea txn=000000000011/000000/000000 signingIdentity=0xbe4558b906b86d50303a7333ce30cc0a827e5ab0 ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.256Z] DEBUG SQL-> begin dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.257Z] DEBUG SQL<- begin dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.257Z] DEBUG SQL-> query transactions dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.258Z] DEBUG SQL<- query transactions dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.258Z] DEBUG Transaction 'e9795f95-cb76-4919-b811-1abd5de45f9e' not found dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.260Z] DEBUG SQL-> insert transactions dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.265Z] DEBUG SQL<- insert transactions sequences=[9] dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.266Z] DEBUG SQL-> insert messages dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.267Z] DEBUG SQL<- insert messages sequences=[9] dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.268Z] DEBUG SQL-> insert pins dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.269Z] DEBUG SQL<- insert pins sequences=[9] dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.269Z] DEBUG SQL-> query batches dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.270Z] DEBUG SQL<- query batches dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.270Z] DEBUG Batch 'cee7ef66-ade5-4e91-b050-72d2ba47b6ea' not found dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.271Z] DEBUG SQL-> insert operations dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.271Z] DEBUG SQL<- insert operations sequences=[11] dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.272Z] DEBUG SQL-> insert events dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.272Z] DEBUG SQL<- insert events sequences=[23] dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.272Z] DEBUG SQL-> commit dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.277Z] DEBUG SQL<- commit dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.277Z] DEBUG Triggering creation event for pin 9 dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.278Z] DEBUG Dispatched download operation sharedstorage_download_batch/b2a259d5-cad6-482d-b4fd-a2815c6b75ca (attempts=0) to worker pool ns=default pid=1
[2023-11-13T21:37:56.279Z]  INFO Executing sharedstorage_download_batch operation b2a259d5-cad6-482d-b4fd-a2815c6b75ca via handler SharedStorageDownloadManager downloadworker=dw_004 ns=default pid=1
[2023-11-13T21:37:56.279Z]  INFO Emitted blockchain_event_received event 35d97248-6d2f-40f0-ba6e-30cd8c3c7004 for default:6dd3b13e-3691-4046-a72f-87dc2fa1fd24 (correlator=,topic=ff_batch_pin) dbtx=rHyfZcdL ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.280Z] DEBUG Woken for trigger on event ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.281Z]  INFO <- BatchPinComplete batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea txn=000000000011/000000/000000 signingIdentity=0xbe4558b906b86d50303a7333ce30cc0a827e5ab0 ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.282Z] DEBUG SQL-> query pins ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.286Z] DEBUG ==> GET http://ipfs_0:8080/ipfs/QmZ4K97suaSiTRVdCr41H7oDA8v3F76bGEm59ZPWU9zWuL breq=pYzgLoxs pid=1 sharedstorage=ipfs
[2023-11-13T21:37:56.286Z] DEBUG SQL<- query pins ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.289Z] DEBUG SQL-> begin dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.289Z] DEBUG SQL<- begin dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.290Z] DEBUG SQL-> query batches dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.290Z] DEBUG SQL<- query batches dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.291Z] DEBUG Batch 'cee7ef66-ade5-4e91-b050-72d2ba47b6ea' not found dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.291Z] DEBUG Pin 0000000009 batch unavailable: batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea pinIndex=0 hash=37a8eec1ce19687d132fe29051dca629d164e2c4958ba141d5f4133a33f0688f masked=false dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.291Z] DEBUG SQL-> commit dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.292Z] DEBUG SQL<- commit dbtx=EJ4xaM57 ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.292Z] DEBUG SQL-> begin dbtx=fud7Fp6I ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.293Z] DEBUG SQL<- begin dbtx=fud7Fp6I ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.293Z] DEBUG SQL-> update offsets dbtx=fud7Fp6I ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.294Z] DEBUG SQL<- update offsets affected=1 dbtx=fud7Fp6I ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.294Z] DEBUG SQL-> commit dbtx=fud7Fp6I ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.297Z] DEBUG SQL<- commit dbtx=fud7Fp6I ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.297Z] DEBUG Event polling offset committed 9 ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.311Z] DEBUG <== GET http://ipfs_0:8080/ipfs/QmZ4K97suaSiTRVdCr41H7oDA8v3F76bGEm59ZPWU9zWuL [200] (25.01ms) breq=pYzgLoxs pid=1 sharedstorage=ipfs
[2023-11-13T21:37:56.311Z]  INFO IPFS retrieved QmZ4K97suaSiTRVdCr41H7oDA8v3F76bGEm59ZPWU9zWuL downloadworker=dw_004 ns=default pid=1
[2023-11-13T21:37:56.313Z]  INFO Shared storage batch downloaded from ipfs 'QmZ4K97suaSiTRVdCr41H7oDA8v3F76bGEm59ZPWU9zWuL' id=cee7ef66-ade5-4e91-b050-72d2ba47b6ea (len=1207) ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.314Z] DEBUG SQL-> begin dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.314Z] DEBUG SQL<- begin dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.315Z] DEBUG SQL-> insert batches dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.316Z] DEBUG SQL<- insert batches sequences=[9] dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.318Z] DEBUG SQL-> query identities dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.318Z] DEBUG SQL<- query identities dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.319Z] DEBUG Resolved DID 'did:firefly:node/node_87e8a8' to identity: aea46100-eaa8-45e8-a926-1734c88092e1 / did:firefly:node/node_87e8a8 (err=<nil>) dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.320Z] DEBUG SQL-> insert data dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.320Z] DEBUG SQL<- insert data sequences=[9] dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.321Z] DEBUG SQL-> insert messages dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.322Z] DEBUG SQL<- insert messages sequences=[9] dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.322Z] DEBUG SQL-> insert messages_data dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.322Z] DEBUG SQL<- insert messages_data sequences=[9] dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.323Z] DEBUG Cached batch cee7ef66-ade5-4e91-b050-72d2ba47b6ea/38b4cb0bab6d8d6c1e0c8f62dfcdebd6c58f86d941de983c4beac312da3d6d3a ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.323Z] DEBUG SQL-> commit dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.326Z] DEBUG SQL<- commit dbtx=sd8qPk9U ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.327Z] DEBUG Notifying batch manager of rewind to 8 ns=default pid=1 role=batchmgr
[2023-11-13T21:37:56.327Z] DEBUG Added to message cache: 8f5508eb-2027-4473-94ce-97a42423a199 (topics=1,pins=0)
[2023-11-13T21:37:56.327Z] DEBUG Queuing rewind for batch cee7ef66-ade5-4e91-b050-72d2ba47b6ea ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.328Z] DEBUG ipfs updating operation default:b2a259d5-cad6-482d-b4fd-a2815c6b75ca status=Succeeded ns=default pid=1
[2023-11-13T21:37:56.328Z] DEBUG SQL-> query messages ns=default pid=1 role=batchmgr
[2023-11-13T21:37:56.328Z] DEBUG SQL-> begin dbtx=4BR7oOXw ns=default pid=1
[2023-11-13T21:37:56.329Z] DEBUG SQL<- query messages ns=default pid=1 role=batchmgr
[2023-11-13T21:37:56.329Z] DEBUG Read 0 records from offset -1. filtered=0 fullPage=false ns=default pid=1 role=batchmgr
[2023-11-13T21:37:56.330Z] DEBUG SQL<- begin dbtx=4BR7oOXw ns=default pid=1
[2023-11-13T21:37:56.331Z] DEBUG SQL-> update operations dbtx=4BR7oOXw ns=default pid=1
[2023-11-13T21:37:56.333Z] DEBUG SQL<- update operations affected=1 dbtx=4BR7oOXw ns=default pid=1
[2023-11-13T21:37:56.333Z] DEBUG SQL-> commit dbtx=4BR7oOXw ns=default pid=1
[2023-11-13T21:37:56.335Z] DEBUG SQL<- commit dbtx=4BR7oOXw ns=default pid=1
[2023-11-13T21:37:56.515Z]  INFO Received 'BatchPin(address,uint256,string,bytes32,bytes32,string,bytes32[])' message on '018bca9d-3db0-2954-6f22-fd607a447bcd' ethmsgidx=0 pid=1 proto=ethereum role=event-loop
[2023-11-13T21:37:56.516Z]  INFO -> BatchPinComplete batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea txn=000000000011/000000/000000 signingIdentity=0xbe4558b906b86d50303a7333ce30cc0a827e5ab0 ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.517Z] DEBUG SQL-> begin dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.517Z] DEBUG SQL<- begin dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.519Z] DEBUG SQL-> insert messages dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.525Z] ERROR SQL insert failed: UNIQUE constraint failed: blockchainevents.namespace, blockchainevents.protocol_id sql=[ INSERT INTO blockchainevents (id,source,namespace,name,protocol_id,listener_id,output,info,timestamp,tx_type,tx_id,tx_blockchain_id) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12) ]: UNIQUE constraint failed: blockchainevents.namespace, blockchainevents.protocol_id dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.526Z] DEBUG SQL-> query blockchainevents dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.527Z] DEBUG SQL<- query blockchainevents dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.529Z] DEBUG Ignoring duplicate blockchain event 000000000011/000000/000000 dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.529Z] DEBUG SQL-> insert pins dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.529Z] ERROR SQL insert failed: UNIQUE constraint failed: pins.namespace, pins.hash, pins.batch_id, pins.idx sql=[ INSERT INTO pins (namespace,masked,hash,batch_id,batch_hash,idx,signer,dispatched,created) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ]: UNIQUE constraint failed: pins.namespace, pins.hash, pins.batch_id, pins.idx dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.530Z]  WARN Batch insert of pins failed - assuming replay and performing upserts: FF00177: Database insert failed: UNIQUE constraint failed: pins.namespace, pins.hash, pins.batch_id, pins.idx dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.530Z] DEBUG SQL-> query pins dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.531Z] DEBUG SQL<- query pins dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.531Z] DEBUG Existing pin returned at sequence 9 dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.531Z] DEBUG Batch cache hit cee7ef66-ade5-4e91-b050-72d2ba47b6ea/38b4cb0bab6d8d6c1e0c8f62dfcdebd6c58f86d941de983c4beac312da3d6d3a ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.531Z] DEBUG SQL-> commit dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.531Z] DEBUG SQL<- commit dbtx=GPs_0O4P ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.531Z]  INFO <- BatchPinComplete batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea txn=000000000011/000000/000000 signingIdentity=0xbe4558b906b86d50303a7333ce30cc0a827e5ab0 ns=default pid=1 role=event-manager
[2023-11-13T21:37:56.542Z] DEBUG Woken for trigger on event ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.543Z] DEBUG SQL-> query pins ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.544Z] DEBUG SQL<- query pins ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.595Z] DEBUG SQL-> begin dbtx=lp_7xqKW ns=default pid=1 role=aggregator-rewind
[2023-11-13T21:37:56.597Z] DEBUG SQL<- begin dbtx=lp_7xqKW ns=default pid=1 role=aggregator-rewind
[2023-11-13T21:37:56.597Z] DEBUG SQL-> commit dbtx=lp_7xqKW ns=default pid=1 role=aggregator-rewind
[2023-11-13T21:37:56.597Z] DEBUG SQL<- commit dbtx=lp_7xqKW ns=default pid=1 role=aggregator-rewind
[2023-11-13T21:37:56.598Z] DEBUG Woken for trigger on event ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.600Z] DEBUG SQL-> query pins ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.601Z] DEBUG SQL<- query pins ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.602Z] DEBUG Aggregator popped rewind to pin 8 for batch cee7ef66-ade5-4e91-b050-72d2ba47b6ea ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.602Z]  INFO Event polling rewind to: 8 ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.602Z] DEBUG SQL-> query pins ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.602Z] DEBUG SQL<- query pins ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.603Z] DEBUG SQL-> begin dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.603Z] DEBUG SQL<- begin dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.603Z] DEBUG Batch cache hit cee7ef66-ade5-4e91-b050-72d2ba47b6ea/38b4cb0bab6d8d6c1e0c8f62dfcdebd6c58f86d941de983c4beac312da3d6d3a ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.603Z] DEBUG Aggregating pin 0000000009 batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea msg=8f5508eb-2027-4473-94ce-97a42423a199 pinIndex=0 msgBaseIndex=0 hash=37a8eec1ce19687d132fe29051dca629d164e2c4958ba141d5f4133a33f0688f masked=false dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.604Z] DEBUG Cache hit for message 8f5508eb-2027-4473-94ce-97a42423a199 dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.604Z] DEBUG SQL-> query pins dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.605Z] DEBUG SQL<- query pins dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.605Z] DEBUG Attempt dispatch msg=8f5508eb-2027-4473-94ce-97a42423a199 broadcastContexts=[37a8eec1ce19687d132fe29051dca629d164e2c4958ba141d5f4133a33f0688f] privatePins= dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.606Z] DEBUG SQL-> query verifiers dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.606Z] DEBUG SQL<- query verifiers dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.607Z] DEBUG SQL-> query identities dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.607Z] DEBUG SQL<- query identities dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.609Z] DEBUG SQL-> begin dbtx=4LiU6EXp ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.609Z] DEBUG Marking message dispatched batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea msg=8f5508eb-2027-4473-94ce-97a42423a199 firstIndex=0 topics=1 pins= dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.610Z] DEBUG SQL-> update pins dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.611Z] DEBUG SQL<- update pins affected=1 dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.612Z] DEBUG Cache hit for message 8f5508eb-2027-4473-94ce-97a42423a199 dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.612Z] DEBUG SQL-> update messages dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.613Z] DEBUG SQL<- update messages affected=1 dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.613Z] DEBUG SQL-> insert events dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.614Z] DEBUG SQL<- insert events sequences=[24] dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.614Z] DEBUG SQL-> commit dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.616Z] DEBUG SQL<- commit dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.616Z]  INFO Emitted message_confirmed event 0eee89d2-d88f-41a3-9c40-9fd6ee28c6ff for default:8f5508eb-2027-4473-94ce-97a42423a199 (correlator=,topic=default) dbtx=TZpWdB_E ns=default pid=1 role=aggregator
[2023-11-13T21:37:56.616Z] DEBUG SQL<- begin dbtx=4LiU6EXp ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.617Z] DEBUG SQL-> update offsets dbtx=4LiU6EXp ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.617Z] DEBUG SQL<- update offsets affected=1 dbtx=4LiU6EXp ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.617Z] DEBUG SQL-> commit dbtx=4LiU6EXp ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.617Z] DEBUG SQL<- commit dbtx=4LiU6EXp ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:56.617Z] DEBUG Event polling offset committed 9 ns=default pid=1 role=ep[default:ff_aggregator]
[2023-11-13T21:37:57.019Z]  INFO Received 'BatchPin(address,uint256,string,bytes32,bytes32,string,bytes32[])' message on '018bca9d-3db0-2954-6f22-fd607a447bcd' ethmsgidx=0 pid=1 proto=ethereum role=event-loop
[2023-11-13T21:37:57.025Z]  INFO -> BatchPinComplete batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea txn=000000000011/000000/000000 signingIdentity=0xbe4558b906b86d50303a7333ce30cc0a827e5ab0 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.025Z] DEBUG SQL-> begin dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.026Z] DEBUG SQL<- begin dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.027Z] DEBUG SQL-> insert messages dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.031Z] ERROR SQL insert failed: UNIQUE constraint failed: blockchainevents.namespace, blockchainevents.protocol_id sql=[ INSERT INTO blockchainevents (id,source,namespace,name,protocol_id,listener_id,output,info,timestamp,tx_type,tx_id,tx_blockchain_id) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12) ]: UNIQUE constraint failed: blockchainevents.namespace, blockchainevents.protocol_id dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.037Z] DEBUG SQL-> query blockchainevents dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.041Z] DEBUG SQL<- query blockchainevents dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.042Z] DEBUG Ignoring duplicate blockchain event 000000000011/000000/000000 dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.042Z] DEBUG SQL-> insert pins dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.042Z] ERROR SQL insert failed: UNIQUE constraint failed: pins.namespace, pins.hash, pins.batch_id, pins.idx sql=[ INSERT INTO pins (namespace,masked,hash,batch_id,batch_hash,idx,signer,dispatched,created) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) ]: UNIQUE constraint failed: pins.namespace, pins.hash, pins.batch_id, pins.idx dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.042Z]  WARN Batch insert of pins failed - assuming replay and performing upserts: FF00177: Database insert failed: UNIQUE constraint failed: pins.namespace, pins.hash, pins.batch_id, pins.idx dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.043Z] DEBUG SQL-> query pins dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.043Z] DEBUG SQL<- query pins dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.043Z] DEBUG Existing pin returned at sequence 9 dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.043Z] DEBUG Batch cache hit cee7ef66-ade5-4e91-b050-72d2ba47b6ea/38b4cb0bab6d8d6c1e0c8f62dfcdebd6c58f86d941de983c4beac312da3d6d3a ns=default pid=1 role=aggregator
[2023-11-13T21:37:57.043Z] DEBUG SQL-> commit dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.043Z] DEBUG SQL<- commit dbtx=4sjBmA55 ns=default pid=1 role=event-manager
[2023-11-13T21:37:57.044Z]  INFO <- BatchPinComplete batch=cee7ef66-ade5-4e91-b050-72d2ba47b6ea txn=000000000011/000000/000000 signingIdentity=0xbe4558b906b86d50303a7333ce30cc0a827e5ab0 ns=default pid=1 role=event-manager

EVMConnect Log

[2023-11-13T21:37:55.749Z]  INFO evmconnect: Listener 018bca9d-3db0-2954-6f22-fd607a447bcd detected event '000000000011/000000/000000' eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:55.749Z] DEBUG evmconnect: RPC[000000314] --> eth_getBlockByHash eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:55.750Z] DEBUG evmconnect: ==> POST http://geth:8545 breq=u14UYn6v
[2023-11-13T21:37:55.751Z] DEBUG evmconnect: <== POST http://geth:8545 [200] (1.26ms) breq=u14UYn6v
[2023-11-13T21:37:55.751Z]  INFO evmconnect: RPC[000000314] <-- eth_getBlockByHash [200] OK (1.36ms) eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:55.751Z] DEBUG evmconnect: Detected event 000000000011/000000/000000/B=0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd/L=018bca9d-3db0-2954-6f22-fd607a447bcd eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:55.751Z] DEBUG evmconnect: 018bca9d-3db0-2954-6f22-fd607a447bcd event detected: 000000000011/000000/000000/B=0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd/L=018bca9d-3db0-2954-6f22-fd607a447bcd eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:55.751Z] DEBUG evmconnect: 018bca9d-3db0-2954-6f22-fd607a447bcd '0x1d50c57ff2661b277ee57e28006ea9fb5980d5fb:BatchPin(address,uint256,string,bytes32,bytes32,string,bytes32[])' event confirmed: 000000000011/000000/000000/B=0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd/L=018bca9d-3db0-2954-6f22-fd607a447bcd eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:55.754Z] DEBUG evmconnect: ChainHead=10 eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:55.754Z] DEBUG evmconnect: RPC[000000315] --> eth_getFilterChanges eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:55.754Z] DEBUG evmconnect: ==> POST http://geth:8545 breq=aZP9UCKm
[2023-11-13T21:37:55.755Z] DEBUG evmconnect: <== POST http://geth:8545 [200] (1.27ms) breq=aZP9UCKm
[2023-11-13T21:37:55.755Z]  INFO evmconnect: RPC[000000315] <-- eth_getFilterChanges [200] OK (1.43ms) eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:55.800Z] DEBUG evmconnect: RPC[000000316] --> eth_getFilterChanges role=blocklistener
[2023-11-13T21:37:55.800Z] DEBUG evmconnect: ==> POST http://geth:8545 breq=mhXX2ygL
[2023-11-13T21:37:55.810Z] DEBUG evmconnect: <== POST http://geth:8545 [200] (9.90ms) breq=mhXX2ygL
[2023-11-13T21:37:55.811Z]  INFO evmconnect: RPC[000000316] <-- eth_getFilterChanges [200] OK (10.65ms) role=blocklistener
[2023-11-13T21:37:55.811Z] DEBUG evmconnect: Added block 11 / 0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd parent=0x8407403080132ab82d3a05563340bde71ae35676f0fdc2bd658e4f9a869a4ad3 to in-memory canonical chain (new length=9) role=blocklistener
[2023-11-13T21:37:55.811Z] DEBUG evmconnect: Received block event: [0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd] eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:55.812Z] DEBUG evmconnect: Received block event: [0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd]
[2023-11-13T21:37:55.812Z] DEBUG evmconnect: New block notifications [0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd] role=confirmations_receipts
[2023-11-13T21:37:55.812Z] DEBUG evmconnect: Downloaded block header by hash: 11 / 0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd parent=0x8407403080132ab82d3a05563340bde71ae35676f0fdc2bd658e4f9a869a4ad3 role=confirmations_receipts
[2023-11-13T21:37:55.812Z] DEBUG evmconnect: Transactions mined in block 11 / 0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd: [0x3ac225876936fa56065223492215851205d54a387fd6f6ae74ce313f4cf2647e] role=confirmations_receipts
[2023-11-13T21:37:55.812Z] DEBUG evmconnect: Received block event: [0x1c575c7e74045a6df06555311ee296a40dcb4289b6d5f20d7b61ee09d801d6bd] eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.252Z]  INFO evmconnect: Batch 9 dispatched (len=1) eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.253Z]  INFO evmconnect: WebSocket event batch 9 delivery failed (len=1): FF21037: WebSocket '622f8f20-5ddc-4ef9-8267-f3c1cd384a4c' closed eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.253Z] ERROR evmconnect: Batch 9 attempt 1 failed. err=FF21037: WebSocket '622f8f20-5ddc-4ef9-8267-f3c1cd384a4c' closed eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.253Z] ERROR evmconnect: action attempt 1: FF21037: WebSocket '622f8f20-5ddc-4ef9-8267-f3c1cd384a4c' closed eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.285Z] DEBUG evmconnect: Received WebSocket ack for batch 9 on topic '0' wsc=3c57b303-cd51-4587-876b-128967fbadda
[2023-11-13T21:37:56.509Z]  INFO evmconnect: Batch 9 dispatched (len=1) eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.510Z]  INFO evmconnect: WebSocket event batch 9 delivery failed (len=1): FF21037: WebSocket '622f8f20-5ddc-4ef9-8267-f3c1cd384a4c' closed eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.510Z] ERROR evmconnect: Batch 9 attempt 2 failed. err=FF21037: WebSocket '622f8f20-5ddc-4ef9-8267-f3c1cd384a4c' closed eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.510Z] ERROR evmconnect: action attempt 2: FF21037: WebSocket '622f8f20-5ddc-4ef9-8267-f3c1cd384a4c' closed eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.532Z] DEBUG evmconnect: Received WebSocket ack for batch 9 on topic '0' wsc=3c57b303-cd51-4587-876b-128967fbadda
[2023-11-13T21:37:56.759Z] DEBUG evmconnect: ChainHead=11 eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:56.760Z] DEBUG evmconnect: RPC[000000317] --> eth_getFilterChanges eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:56.760Z] DEBUG evmconnect: ==> POST http://geth:8545 breq=VxrS3YM1
[2023-11-13T21:37:56.761Z] DEBUG evmconnect: ChainHead=11 eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.761Z] DEBUG evmconnect: RPC[000000318] --> eth_getFilterChanges eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.761Z] DEBUG evmconnect: ==> POST http://geth:8545 breq=pnl2UhhP
[2023-11-13T21:37:56.777Z] DEBUG evmconnect: <== POST http://geth:8545 [200] (16.37ms) breq=pnl2UhhP
[2023-11-13T21:37:56.777Z]  INFO evmconnect: RPC[000000318] <-- eth_getFilterChanges [200] OK (16.56ms) eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:56.777Z] DEBUG evmconnect: <== POST http://geth:8545 [200] (17.38ms) breq=VxrS3YM1
[2023-11-13T21:37:56.778Z]  INFO evmconnect: RPC[000000317] <-- eth_getFilterChanges [200] OK (17.88ms) eventstream=018bca9d-3ebd-51d5-8244-0f40d8f7b558
[2023-11-13T21:37:56.813Z] DEBUG evmconnect: RPC[000000319] --> eth_getFilterChanges role=blocklistener
[2023-11-13T21:37:56.814Z] DEBUG evmconnect: ==> POST http://geth:8545 breq=B4jKd4dz
[2023-11-13T21:37:56.818Z] DEBUG evmconnect: <== POST http://geth:8545 [200] (3.96ms) breq=B4jKd4dz
[2023-11-13T21:37:56.818Z]  INFO evmconnect: RPC[000000319] <-- eth_getFilterChanges [200] OK (4.43ms) role=blocklistener
[2023-11-13T21:37:57.014Z]  INFO evmconnect: Batch 9 dispatched (len=1) eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:57.015Z]  INFO evmconnect: Batch 9 acknowledged eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:57.015Z]  INFO evmconnect: WebSocket event batch 9 complete (len=1) eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:57.015Z] DEBUG evmconnect: Wrote checkpoints_0/018bca9d-3d87-dcea-348d-95e455785e47 eventstream=018bca9d-3d87-dcea-348d-95e455785e47
[2023-11-13T21:37:57.044Z] DEBUG evmconnect: Received WebSocket ack for batch 9 on topic '0' wsc=3c57b303-cd51-4587-876b-128967fbadda
[2023-11-13T21:37:57.781Z] DEBUG evmconnect: ChainHead=11 eventstream=018bca9d-3d87-dcea-348d-95e455785e47
@nguyer nguyer added the bug Something isn't working label Nov 13, 2023
@Philip-21
Copy link

Philip-21 commented Feb 21, 2024 •
edited
Loading

@nguyer I tried various transactions with my node, but i didn't see the logs generated above.

@Philip-21
Copy link

I would like to work on this issue if its still open .

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@nguyer @Philip-21