Duplicate deals sent when two replications trigger at same time.
Closed this issue · 5 comments
Trevor-K-Smith commented
Describe the bug
In the example below, two crons are provided.
2022-11-26T02:00:00.962Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T02:00:00.964Z [deal_replication_worker] debug: Cron triggered (0 * * * *) - id 6379c01983982ce9b6c2fda4 - {}
Both crons are seen visually triggering in the logs. In the example, we are at the 0th minute of the hour, hence, both crons are triggering. The 0th minute cron deal is created as expected. The every 3rd cron is triggered, but no deal is created.
Later when the 3rd minute of the hour hits, the every 3rd minute cron is triggered again. Then two duplicate deals are created.
Below is logs of this situation.
2022-11-26T02:00:00.962Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T02:00:00.962Z [deal_replication_worker] info: Start replication 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T02:00:00.964Z [deal_replication_worker] debug: Cron triggered (0 * * * *) - id 6379c01983982ce9b6c2fda4 - {}
2022-11-26T02:00:00.964Z [deal_replication_worker] info: Start replication 6379c01983982ce9b6c2fda4 - {}
2022-11-26T02:00:01.462Z [deal_replication_worker] debug: SP f01910202 supports boost. - {}
2022-11-26T02:00:01.711Z [deal_replication_worker] debug: SP f01963614 supports boost. - {}
2022-11-26T02:00:02.318Z [deal_replication_worker] debug: Calculated start epoch startDelay: 20160 + currentHeight: 2370720 = 2390880 - {}
2022-11-26T02:00:04.245Z [deal_replication_worker] debug: Calculated start epoch startDelay: 20160 + currentHeight: 2370720 = 2390880 - {}
2022-11-26T02:02:01.869Z [deal_replication_worker] debug: boost deal --http-url=https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqbdiwi2irbupdbckns6ql6ezjayz5sf7dxbhs7detbpbll6xjx2ki.car --provider=f01963614 --commp=baga6ea4seaqbdiwi2irbupdbckns6ql6ezjayz5sf7dxbhs7detbpbll6xjx2ki --car-size=33675405802 --piece-size=34359738368 --payload-cid=bafybeihiigl6tpi2zqk6yegafryc77xcukwvo7rjhbndoxjgxwvu5keyaa --storage-price=0 --start-epoch=2390880 --verified=true --wallet=f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a --duration=1512000 - {}
2022-11-26T02:02:02.585Z [deal_replication_worker] info: Dealt baga6ea4seaqbdiwi2irbupdbckns6ql6ezjayz5sf7dxbhs7detbpbll6xjx2ki with f01963614 (#0), output: sent deal proposal
deal uuid: 46cff7ed-5a17-437b-81bd-c876a6b1bd80
storage provider: f01963614
client wallet: f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a
payload cid: bafybeihiigl6tpi2zqk6yegafryc77xcukwvo7rjhbndoxjgxwvu5keyaa
url: https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqbdiwi2irbupdbckns6ql6ezjayz5sf7dxbhs7detbpbll6xjx2ki.car
commp: baga6ea4seaqbdiwi2irbupdbckns6ql6ezjayz5sf7dxbhs7detbpbll6xjx2ki
start epoch: 2390880
end epoch: 3902880
provider collateral: 9.959 mFIL
- {}
2022-11-26T02:02:02.596Z [deal_replication_worker] warn: This SP f01963614 has made max deals planned (1) by the request 6379c01983982ce9b6c2fda4. - {}
2022-11-26T02:02:02.597Z [deal_replication_worker] debug: checkAndMarkCompletion 6379c01983982ce9b6c2fda4 max: 0 actual: 286 - {}
2022-11-26T02:02:02.597Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T02:02:02.597Z [deal_replication_worker] debug: Finished all files in the dataset. Checking completion. - {}
2022-11-26T02:02:02.599Z [deal_replication_worker] debug: checkAndMarkCompletion 6379c01983982ce9b6c2fda4 max: 0 actual: 286 - {}
2022-11-26T02:02:02.599Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T02:03:00.194Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T02:03:00.194Z [deal_replication_worker] info: Start replication 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T02:03:00.525Z [deal_replication_worker] debug: SP f01910202 supports boost. - {}
2022-11-26T02:03:03.414Z [deal_replication_worker] debug: Calculated start epoch startDelay: 20160 + currentHeight: 2370726 = 2390886 - {}
2022-11-26T02:03:51.699Z [deal_replication_worker] debug: boost deal --http-url=https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia.car --provider=f01910202 --commp=baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia --car-size=33675406100 --piece-size=34359738368 --payload-cid=bafybeihukkvvxxcy7kmzjizp7bdqa43d66jv6fln2aiuuqkla6pxoltvee --storage-price=0 --start-epoch=2390880 --verified=true --wallet=f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a --duration=1512000 - {}
2022-11-26T02:03:53.565Z [deal_replication_worker] debug: boost deal --http-url=https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia.car --provider=f01910202 --commp=baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia --car-size=33675406100 --piece-size=34359738368 --payload-cid=bafybeihukkvvxxcy7kmzjizp7bdqa43d66jv6fln2aiuuqkla6pxoltvee --storage-price=0 --start-epoch=2390886 --verified=true --wallet=f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a --duration=1512000 - {}
2022-11-26T02:03:55.166Z [deal_replication_worker] info: Dealt baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia with f01910202 (#0), output: sent deal proposal
deal uuid: 01908289-d619-4862-a318-ad15b53895ed
storage provider: f01910202
client wallet: f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a
payload cid: bafybeihukkvvxxcy7kmzjizp7bdqa43d66jv6fln2aiuuqkla6pxoltvee
url: https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia.car
commp: baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia
start epoch: 2390880
end epoch: 3902880
provider collateral: 9.959 mFIL
- {}
2022-11-26T02:03:55.183Z [deal_replication_worker] warn: This SP f01910202 has made max deals planned (1) by the request 6375e3a2b49cbe037304f2d9. - {}
2022-11-26T02:03:55.189Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2173 - {}
2022-11-26T02:03:55.189Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T02:03:55.189Z [deal_replication_worker] debug: Finished all files in the dataset. Checking completion. - {}
2022-11-26T02:03:55.193Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2173 - {}
2022-11-26T02:03:55.195Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T02:03:56.709Z [deal_replication_worker] info: Dealt baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia with f01910202 (#0), output: sent deal proposal
deal uuid: d4229aa3-2e42-4b0c-b122-1355be4316ca
storage provider: f01910202
client wallet: f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a
payload cid: bafybeihukkvvxxcy7kmzjizp7bdqa43d66jv6fln2aiuuqkla6pxoltvee
url: https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia.car
commp: baga6ea4seaqkx72y3gqulsjzbyjo6kxaxl7k7vnrf3qoenufzdxmvawyhkc2uia
start epoch: 2390886
end epoch: 3902886
provider collateral: 9.959 mFIL
- {}
2022-11-26T02:03:56.718Z [deal_replication_worker] warn: This SP f01910202 has made max deals planned (1) by the request 6375e3a2b49cbe037304f2d9. - {}
2022-11-26T02:03:56.721Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2174 - {}
2022-11-26T02:03:56.722Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T02:03:56.722Z [deal_replication_worker] debug: Finished all files in the dataset. Checking completion. - {}
2022-11-26T02:03:56.729Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2174 - {}
2022-11-26T02:03:56.729Z [deal_replication_worker] debug: Not yet complete - {}
Sometimes later on, its starts duplicating every deal, and ill need to restart singularity.
Version
root@Miner-01:/srv/caddy# singularity -V
2.0.0-RC4
To Reproduce
Steps to reproduce the behavior:
Set two crons to trigger same time.
Expected behavior
A clear and concise description of what you expected to happen.
Not have duplicate deals, but two uniq deals, sent out when they originally triggered.
kernelogic commented
Could you suggest how to deal with this situation if they are triggered at the same time and with the same dataset?
Not allow schedule such thing? It seems inevitable to have duplicates if triggers at the same time.
Trevor-K-Smith commented
The crons triggering at the same time are for the same dataset but different SPs.
Never in this situation am i triggering deals, for the same dataset, against the same SP.
More specifically, my cron triggers at
2022-11-26T02:00:00.962Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
but no corresponding deal was created.
3 minutes later, this cron triggers again.
2022-11-26T02:03:00.194Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
Two duplicate deals are created. It was only suppose to create one.
Correct me if i'm wrong, but i don't think how i have my crons scheduled should be an issue.
Expecting
2:00:00
(0 * * * *) - f01963614 - Deal A
(*/3 * * * *) - f01910202 - Deal B
2:03:00
(*/3 * * * *) - f01910202 - Deal C
Getting
2:00:00
(0 * * * *) - f01963614 - Deal A
(*/3 * * * *) - f01910202 - **nothing**
2:03:00
(*/3 * * * *) - f01910202 - **2x Deal B**
kernelogic commented
ya if it's for different SPs, should not have duplicate deals. I will try to find a root cause about this.
Trevor-K-Smith commented
Seems to occur occasionally without anything triggering at same time. May be unrelated to the fact another cron is triggering. Skips and then duplicates next time its hit even with single cron.
Expecting
14:33
(*/3 * * * *) - f01910202 - Deal A
14:36
(*/3 * * * *) - f01910202 - Deal B
Getting
14:33
(*/3 * * * *) - f01910202 - nothing
14:36
(*/3 * * * *) - f01910202 - 2x Deal A
Then it returns to normal until it randomly occurs again.
2022-11-26T14:33:00.464Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T14:33:00.464Z [deal_replication_worker] info: Start replication 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T14:33:02.747Z [deal_replication_worker] debug: SP f01910202 supports boost. - {}
2022-11-26T14:33:03.975Z [deal_replication_worker] debug: Calculated start epoch startDelay: 20160 + currentHeight: 2372226 = 2392386 - {}
2022-11-26T14:36:00.715Z [deal_replication_worker] debug: Cron triggered (*/3 * * * *) - id 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T14:36:00.715Z [deal_replication_worker] info: Start replication 6375e3a2b49cbe037304f2d9 - {}
2022-11-26T14:36:01.063Z [deal_replication_worker] debug: SP f01910202 supports boost. - {}
2022-11-26T14:36:02.185Z [deal_replication_worker] debug: Calculated start epoch startDelay: 20160 + currentHeight: 2372232 = 2392392 - {}
2022-11-26T14:36:06.797Z [deal_replication_worker] debug: boost deal --http-url=https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny.car --provider=f01910202 --commp=baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny --car-size=33675406001 --piece-size=34359738368 --payload-cid=bafybeidky3ajs3xo6ti7wdxzkuosrbd6w2t3ev5bnql5yrl4hhq3w4fxk4 --storage-price=0 --start-epoch=2392386 --verified=true --wallet=f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a --duration=1512000 - {}
2022-11-26T14:36:06.825Z [deal_replication_worker] debug: boost deal --http-url=https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny.car --provider=f01910202 --commp=baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny --car-size=33675406001 --piece-size=34359738368 --payload-cid=bafybeidky3ajs3xo6ti7wdxzkuosrbd6w2t3ev5bnql5yrl4hhq3w4fxk4 --storage-price=0 --start-epoch=2392392 --verified=true --wallet=f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a --duration=1512000 - {}
2022-11-26T14:36:08.620Z [deal_replication_worker] info: Dealt baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny with f01910202 (#0), output: sent deal proposal
deal uuid: 1dece66e-614d-4507-b736-c1ac0ef6bcd3
storage provider: f01910202
client wallet: f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a
payload cid: bafybeidky3ajs3xo6ti7wdxzkuosrbd6w2t3ev5bnql5yrl4hhq3w4fxk4
url: https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny.car
commp: baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny
start epoch: 2392386
end epoch: 3904386
provider collateral: 9.948 mFIL
- {}
2022-11-26T14:36:08.624Z [deal_replication_worker] warn: This SP f01910202 has made max deals planned (1) by the request 6375e3a2b49cbe037304f2d9. - {}
2022-11-26T14:36:08.627Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2420 - {}
2022-11-26T14:36:08.627Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T14:36:08.627Z [deal_replication_worker] debug: Finished all files in the dataset. Checking completion. - {}
2022-11-26T14:36:08.630Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2420 - {}
2022-11-26T14:36:08.630Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T14:36:10.312Z [deal_replication_worker] info: Dealt baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny with f01910202 (#0), output: sent deal proposal
deal uuid: 0eb4df7a-5a48-4023-bfb9-aa3135bf74c4
storage provider: f01910202
client wallet: f1bg3khvfgh6v4n37oxyoy7rzuh74r7lw77gu7z7a
payload cid: bafybeidky3ajs3xo6ti7wdxzkuosrbd6w2t3ev5bnql5yrl4hhq3w4fxk4
url: https://internal.ghostbyte.io:4443/skies_and_universes/baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny.car
commp: baga6ea4seaqdo4ek5t3uyvtuaupnosoj4z5l3v772vgpzwxwxgl7t7yypk5siny
start epoch: 2392392
end epoch: 3904392
provider collateral: 9.948 mFIL
- {}
2022-11-26T14:36:10.315Z [deal_replication_worker] warn: This SP f01910202 has made max deals planned (1) by the request 6375e3a2b49cbe037304f2d9. - {}
2022-11-26T14:36:10.318Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2421 - {}
2022-11-26T14:36:10.318Z [deal_replication_worker] debug: Not yet complete - {}
2022-11-26T14:36:10.318Z [deal_replication_worker] debug: Finished all files in the dataset. Checking completion. - {}
2022-11-26T14:36:10.322Z [deal_replication_worker] debug: checkAndMarkCompletion 6375e3a2b49cbe037304f2d9 max: 0 actual: 2421 - {}
2022-11-26T14:36:10.322Z [deal_replication_worker] debug: Not yet complete - {}
xinaxu commented
@kernelogic confirmed that this has been fixed in #179