Closed github-actions[bot] closed 1 week ago
DST run failed for seed=19253, ticks=1000, scenario=default, store=sqlite.
Seed
19253
Scenario
default
Store
sqlite
Commit
ed7520846bdda87bcf440d55ecd14b750268c7fb
Command
go run ./... dst run --seed 19253 --ticks 1000 --scenario default --aio-store sqlite
Logs
level=INFO msg=DST seed=19253 ticks=1000 reqsPerTick=1:25 dst="DST(ids=7, idempotencyKeys=18, headers=7, data=23, tags=3, backchannel=955)" system="System(api=API(size=576, subsystems=[]), aio=AIODST(subsystems=[router sender store]), config=Config(cms=484, sbs=431, cbs=820, pbs=23, sbs=22, tbs=26, ted=5.284852451s))" level=INFO msg=DST t=0|999 id=1 req="AcquireLock(resourceId=6, executionId=2, processId=3, ttl=3014)" res="AcquireLock(status=2010, lock=Lock(resourceId=6, executionId=2, processId=3, ttl=3014, expiresAt=3014))" err=<nil> level=INFO msg=DST t=0|999 id=3 req="ReleaseLock(resourceId=2, executionId=3)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=0|999 id=4 req="ReleaseLock(resourceId=0, executionId=5)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=0|999 id=5 req="ReadPromise(id=p1)" res="ReadPromise(status=4040, promise=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=6 req="ReleaseLock(resourceId=0, executionId=0)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=0|999 id=7 req="CompletePromise(id=p2, idempotencyKey=<nil>, strict=false, state=REJECTED, value=Value(headers=map[0:1.0 1:1.1 2:1.2], data=0))" res="CompletePromise(status=4040, promise=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=8 req="SearchPromises(id=p*7, states=[REJECTED PENDING], tags=map[], limit=6, sortId=0)" res="SearchPromises(status=2000, promises=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=9 req="ReadSchedule(id=s4)" res="ReadSchedule(status=4041, schedule=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=12 req="SearchPromises(id=p*5, states=[REJECTED_CANCELED RESOLVED], tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], limit=2, sortId=0)" res="SearchPromises(status=2000, promises=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=14 req="SearchPromises(id=p*8, states=[REJECTED PENDING], tags=map[], limit=7, sortId=0)" res="SearchPromises(status=2000, promises=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=15 req="SearchPromises(id=p5*, states=[], tags=map[0:1.0 1:1.1], limit=1, sortId=0)" res="SearchPromises(status=2000, promises=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=16 req="ReleaseLock(resourceId=2, executionId=5)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=0|999 id=17 req="ReadSchedule(id=s1)" res="ReadSchedule(status=4041, schedule=<nil>)" err=<nil> level=INFO msg=DST t=0|999 id=18 req="DeleteSchedule(id=s4)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=1000|1999 id=20 req="ReadSchedule(id=s1)" res="ReadSchedule(status=4041, schedule=<nil>)" err=<nil> level=INFO msg=DST t=1000|1999 id=21 req="AcquireLock(resourceId=5, executionId=6, processId=4, ttl=5624)" res="AcquireLock(status=2010, lock=Lock(resourceId=5, executionId=6, processId=4, ttl=5624, expiresAt=6624))" err=<nil> level=INFO msg=DST t=1000|1999 id=22 req="ReleaseLock(resourceId=0, executionId=5)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=1000|1999 id=23 req="ReadPromise(id=p6)" res="ReadPromise(status=4040, promise=<nil>)" err=<nil> level=INFO msg=DST t=1000|1999 id=24 req="DeleteSchedule(id=s4)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=1000|1999 id=25 req="DeleteSchedule(id=s3)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=1000|1999 id=26 req="DeleteSchedule(id=s0)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=1000|1999 id=27 req="CreateCallback(promiseId=p1, rootPromiseId=p4, timeout=431478, recv=\"dst\")" res="CreateCallback(status=4040, promise=<nil>, callback=<nil>)" err=<nil> level=INFO msg=DST t=0|1999 id=11 req="CreateSchedule(id=s2, desc=, cron=20 * * * *, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], promiseId=s2.{{.timestamp}}, promiseTimeout=872293, promiseParam=Value(headers=map[0:3.0], data=), promiseTags=map[], idempotencyKey=<nil>)" res="CreateSchedule(status=2010, schedule=Schedule(id=s2, desc=, cron=20 * * * *, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], promiseId=s2.{{.timestamp}}, promiseTimeout=872293, promiseParam=Value(headers=map[0:3.0], data=), promiseTags=map[], lastRunTime=0, nextRunTime=1200000, idempotencyKey=<nil>, createdOn=1000))" err=<nil> level=INFO msg=DST t=2000|2999 id=28 req="CreatePromiseAndTask(promise=CreatePromise(id=p6, idempotencyKey=<nil>, strict=false, param=Value(headers=map[0:0.0 1:0.1], data=13), timeout=854297, tags=map[]), task=CreateTask(promiseId=p6, processId=p6, ttl=4827, timeout=854297, recv=\"dst\"))" res="CreatePromiseAndTask(status=4090, promise=Promise(id=p6, state=PENDING, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=559098, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0), task=<nil>)" err=<nil> level=INFO msg=DST t=2000|2999 id=29 req="CompletePromise(id=p1, idempotencyKey=<nil>, strict=true, state=RESOLVED, value=Value(headers=map[], data=))" res="CompletePromise(status=4040, promise=<nil>)" err=<nil> level=INFO msg=DST t=0|2999 id=2 req="CreateSchedule(id=s2, desc=, cron=46 * * * *, tags=map[], promiseId=s2.{{.timestamp}}, promiseTimeout=257591, promiseParam=Value(headers=map[0:5.0 1:5.1 2:5.2], data=), promiseTags=map[], idempotencyKey=10)" res="CreateSchedule(status=4091, schedule=Schedule(id=s2, desc=, cron=20 * * * *, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], promiseId=s2.{{.timestamp}}, promiseTimeout=872293, promiseParam=Value(headers=map[0:3.0], data=), promiseTags=map[], lastRunTime=0, nextRunTime=1200000, idempotencyKey=<nil>, createdOn=1000))" err=<nil> level=INFO msg=DST t=0|2999 id=0 req="CreatePromise(id=p3, idempotencyKey=9, strict=true, param=Value(headers=map[0:1.0 1:1.1 2:1.2], data=), timeout=244163, tags=map[])" res="CreatePromise(status=2010, promise=Promise(id=p3, state=PENDING, param=Value(headers=map[0:1.0 1:1.1 2:1.2], data=), value=Value(headers=map[], data=), timeout=244163, idempotencyKeyForCreate=9, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0))" err=<nil> level=INFO msg=DST t=0|2999 id=10 req="CreatePromise(id=p2, idempotencyKey=<nil>, strict=false, param=Value(headers=map[0:4.0], data=20), timeout=433089, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true])" res="CreatePromise(status=2010, promise=Promise(id=p2, state=PENDING, param=Value(headers=map[0:4.0], data=20), value=Value(headers=map[], data=), timeout=433089, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=1000, completedOn=0))" err=<nil> level=INFO msg=DST t=0|2999 id=13 req="CreatePromiseAndCallback(promise=CreatePromise(id=p6, idempotencyKey=<nil>, strict=false, param=Value(headers=map[], data=), timeout=559098, tags=map[]), callback=CreateCallback(promiseId=p6, rootPromiseId=p1, timeout=879749, recv=\"dst\"))" res="CreatePromiseAndCallback(status=2010, promise=Promise(id=p6, state=PENDING, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=559098, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0), callback=Callback(id=1, promiseId=p6, recv=\"dst\", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, createdOn=0))" err=<nil> level=INFO msg=DST t=3000|3999 id=31 req="SearchSchedules(id=s1*, tags=map[], limit=9, sortId=0)" res="SearchSchedules(status=2000, schedules=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=3000|3999 id=32 req="ReleaseLock(resourceId=0, executionId=2)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=3000|3999 id=33 req="ReleaseLock(resourceId=2, executionId=5)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=3000|3999 id=34 req="ReadPromise(id=p3)" res="ReadPromise(status=2000, promise=Promise(id=p3, state=PENDING, param=Value(headers=map[0:1.0 1:1.1 2:1.2], data=), value=Value(headers=map[], data=), timeout=244163, idempotencyKeyForCreate=9, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0))" err=<nil> level=INFO msg=DST t=4000|4999 id=36 req="DeleteSchedule(id=s2)" res="DeleteSchedule(status=2040)" err=<nil> level=INFO msg=DST t=4000|4999 id=37 req="CreatePromise(id=p3, idempotencyKey=<nil>, strict=true, param=Value(headers=map[], data=), timeout=896752, tags=map[])" res="CreatePromise(status=4090, promise=Promise(id=p3, state=PENDING, param=Value(headers=map[0:1.0 1:1.1 2:1.2], data=), value=Value(headers=map[], data=), timeout=244163, idempotencyKeyForCreate=9, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0))" err=<nil> level=INFO msg=DST t=4000|4999 id=38 req="CreatePromiseAndCallback(promise=CreatePromise(id=p2, idempotencyKey=17, strict=false, param=Value(headers=map[], data=22), timeout=801233, tags=map[]), callback=CreateCallback(promiseId=p2, rootPromiseId=p1, timeout=153343, recv=\"dst\"))" res="CreatePromiseAndCallback(status=4090, promise=Promise(id=p2, state=REJECTED, param=Value(headers=map[0:4.0], data=20), value=Value(headers=map[], data=14), timeout=433089, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=9, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=1000, completedOn=4000), callback=<nil>)" err=<nil> level=INFO msg=DST t=4000|4999 id=39 req="CreatePromiseAndTask(promise=CreatePromise(id=p6, idempotencyKey=<nil>, strict=false, param=Value(headers=map[0:6.0], data=3), timeout=628742, tags=map[]), task=CreateTask(promiseId=p6, processId=p6, ttl=1481, timeout=628742, recv=\"dst\"))" res="CreatePromiseAndTask(status=4090, promise=Promise(id=p6, state=PENDING, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=559098, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0), task=<nil>)" err=<nil> level=INFO msg=DST t=1000|4999 id=19 req="CreatePromise(id=p6, idempotencyKey=<nil>, strict=true, param=Value(headers=map[], data=15), timeout=733960, tags=map[])" res="CreatePromise(status=4090, promise=Promise(id=p6, state=PENDING, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=559098, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=0))" err=<nil> level=INFO msg=DST t=3000|4999 id=35 req="CompletePromise(id=p2, idempotencyKey=9, strict=false, state=REJECTED, value=Value(headers=map[], data=14))" res="CompletePromise(status=2010, promise=Promise(id=p2, state=REJECTED, param=Value(headers=map[0:4.0], data=20), value=Value(headers=map[], data=14), timeout=433089, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=9, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=1000, completedOn=4000))" err=<nil> level=INFO msg=DST t=5000|5999 id=42 req="ReadSchedule(id=s1)" res="ReadSchedule(status=4041, schedule=<nil>)" err=<nil> level=INFO msg=DST t=5000|5999 id=43 req="CompletePromise(id=p1, idempotencyKey=1, strict=false, state=RESOLVED, value=Value(headers=map[], data=))" res="CompletePromise(status=4040, promise=<nil>)" err=<nil> level=INFO msg=DST t=5000|5999 id=44 req="DeleteSchedule(id=s6)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=5000|5999 id=45 req="DeleteSchedule(id=s3)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=5000|5999 id=46 req="ReadPromise(id=p4)" res="ReadPromise(status=4040, promise=<nil>)" err=<nil> level=INFO msg=DST t=5000|5999 id=47 req="ReadSchedule(id=s1)" res="ReadSchedule(status=4041, schedule=<nil>)" err=<nil> level=INFO msg=DST t=5000|5999 id=48 req="SearchSchedules(id=s*7, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], limit=7, sortId=0)" res="SearchSchedules(status=2000, schedules=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=5000|5999 id=49 req="CreatePromiseAndTask(promise=CreatePromise(id=p2, idempotencyKey=<nil>, strict=true, param=Value(headers=map[], data=), timeout=165823, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true]), task=CreateTask(promiseId=p2, processId=p2, ttl=1006, timeout=165823, recv=\"dst\"))" res="CreatePromiseAndTask(status=4090, promise=Promise(id=p2, state=REJECTED, param=Value(headers=map[0:4.0], data=20), value=Value(headers=map[], data=14), timeout=433089, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=9, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=1000, completedOn=4000), task=<nil>)" err=<nil> level=INFO msg=DST t=5000|5999 id=50 req="AcquireLock(resourceId=1, executionId=1, processId=1, ttl=6885)" res="AcquireLock(status=2010, lock=Lock(resourceId=1, executionId=1, processId=1, ttl=6885, expiresAt=11885))" err=<nil> level=INFO msg=DST t=5000|5999 id=52 req="HeartbeatLocks(processId=5)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil> ... level=INFO msg=DST t=997000|997999 id=12933 req="ReleaseLock(resourceId=6, executionId=0)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=997000|997999 id=12934 req="CreateCallback(promiseId=p2, rootPromiseId=p6, timeout=997890, recv=\"dst\")" res="CreateCallback(status=2000, promise=Promise(id=p2, state=REJECTED, param=Value(headers=map[0:4.0], data=20), value=Value(headers=map[], data=14), timeout=433089, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=9, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=1000, completedOn=4000), callback=<nil>)" err=<nil> level=INFO msg=DST t=997000|997999 id=12935 req="DeleteSchedule(id=s4)" res="DeleteSchedule(status=4041)" err=<nil> level=INFO msg=DST t=997000|997999 id=12936 req="HeartbeatLocks(processId=2)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil> level=INFO msg=DST t=997000|997999 id=12937 req="CompletePromise(id=p6, idempotencyKey=1, strict=true, state=RESOLVED, value=Value(headers=map[], data=))" res="CompletePromise(status=4031, promise=Promise(id=p6, state=REJECTED, param=Value(headers=map[], data=), value=Value(headers=map[0:4.0], data=15), timeout=559098, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=1000, completedOn=19000))" err=<nil> level=INFO msg=DST t=997000|997999 id=12938 req="ReleaseLock(resourceId=6, executionId=3)" res="ReleaseLock(status=4042)" err=<nil> level=INFO msg=DST t=997000|997999 id=12940 req="SearchSchedules(id=s2*, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], limit=1, sortId=0)" res="SearchSchedules(status=2000, schedules=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=997000|997999 id=12941 req="ReadSchedule(id=s1)" res="ReadSchedule(status=2000, schedule=Schedule(id=s1, desc=, cron=53 * * * *, tags=map[], promiseId=s1.{{.timestamp}}, promiseTimeout=988711, promiseParam=Value(headers=map[], data=), promiseTags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], lastRunTime=0, nextRunTime=3180000, idempotencyKey=0, createdOn=989000))" err=<nil> level=INFO msg=DST t=997000|997999 id=12942 req="CreatePromiseAndTask(promise=CreatePromise(id=p2, idempotencyKey=<nil>, strict=false, param=Value(headers=map[], data=9), timeout=1699820, tags=map[]), task=CreateTask(promiseId=p2, processId=p2, ttl=4837, timeout=1699820, recv=\"dst\"))" res="CreatePromiseAndTask(status=4090, promise=Promise(id=p2, state=REJECTED, param=Value(headers=map[0:4.0], data=20), value=Value(headers=map[], data=14), timeout=433089, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=9, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=1000, completedOn=4000), task=<nil>)" err=<nil> level=INFO msg=DST t=997000|997999 id=12943 req="CompletePromise(id=p1, idempotencyKey=<nil>, strict=true, state=REJECTED, value=Value(headers=map[], data=12))" res="CompletePromise(status=4031, promise=Promise(id=p1, state=REJECTED, param=Value(headers=map[0:3.0], data=), value=Value(headers=map[], data=), timeout=127180, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=4000, completedOn=10000))" err=<nil> level=INFO msg=DST t=997000|997999 id=12944 req="CreatePromise(id=p4, idempotencyKey=17, strict=false, param=Value(headers=map[], data=), timeout=1294283, tags=map[])" res="CreatePromise(status=4090, promise=Promise(id=p4, state=REJECTED, param=Value(headers=map[], data=0), value=Value(headers=map[], data=2), timeout=30466, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=10, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=11000, completedOn=18000))" err=<nil> level=INFO msg=DST t=997000|997999 id=12945 req="HeartbeatLocks(processId=2)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil> level=INFO msg=DST t=997000|997999 id=12946 req="HeartbeatLocks(processId=3)" res="HeartbeatLocks(status=2000, locksAffected=1)" err=<nil> level=INFO msg=DST t=997000|997999 id=12947 req="CompletePromise(id=p1, idempotencyKey=13, strict=true, state=REJECTED_CANCELED, value=Value(headers=map[0:0.0 1:0.1], data=20))" res="CompletePromise(status=4031, promise=Promise(id=p1, state=REJECTED, param=Value(headers=map[0:3.0], data=), value=Value(headers=map[], data=), timeout=127180, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=4000, completedOn=10000))" err=<nil> level=INFO msg=DST t=997000|997999 id=12948 req="ReadSchedule(id=s6)" res="ReadSchedule(status=4041, schedule=<nil>)" err=<nil> level=INFO msg=DST t=998000|998999 id=12949 req="HeartbeatLocks(processId=0)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil> level=INFO msg=DST t=998000|998999 id=12950 req="ReadPromise(id=p1)" res="ReadPromise(status=2000, promise=Promise(id=p1, state=REJECTED, param=Value(headers=map[0:3.0], data=), value=Value(headers=map[], data=), timeout=127180, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=4000, completedOn=10000))" err=<nil> level=INFO msg=DST t=998000|998999 id=12951 req="CreatePromise(id=p4, idempotencyKey=<nil>, strict=false, param=Value(headers=map[0:5.0 1:5.1 2:5.2], data=11), timeout=1917642, tags=map[0:1.0 1:1.1])" res="CreatePromise(status=4090, promise=Promise(id=p4, state=REJECTED, param=Value(headers=map[], data=0), value=Value(headers=map[], data=2), timeout=30466, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=10, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=11000, completedOn=18000))" err=<nil> level=INFO msg=DST t=998000|998999 id=12952 req="CreatePromiseAndCallback(promise=CreatePromise(id=p1, idempotencyKey=<nil>, strict=true, param=Value(headers=map[0:4.0], data=), timeout=1265034, tags=map[]), callback=CreateCallback(promiseId=p1, rootPromiseId=p2, timeout=998215, recv=\"dst\"))" res="CreatePromiseAndCallback(status=4090, promise=Promise(id=p1, state=REJECTED, param=Value(headers=map[0:3.0], data=), value=Value(headers=map[], data=), timeout=127180, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=<nil>, tags=map[], createdOn=4000, completedOn=10000), callback=<nil>)" err=<nil> level=INFO msg=DST t=998000|998999 id=12953 req="CreateSchedule(id=s2, desc=, cron=49 * * * *, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], promiseId=s2.{{.timestamp}}, promiseTimeout=999161, promiseParam=Value(headers=map[0:3.0], data=9), promiseTags=map[], idempotencyKey=<nil>)" res="CreateSchedule(status=4091, schedule=Schedule(id=s2, desc=, cron=25 * * * *, tags=map[0:1.0 1:1.1], promiseId=s2.{{.timestamp}}, promiseTimeout=995993, promiseParam=Value(headers=map[], data=5), promiseTags=map[0:0.0 resonate:timeout:true], lastRunTime=0, nextRunTime=1500000, idempotencyKey=1, createdOn=995000))" err=<nil> level=INFO msg=DST t=998000|998999 id=12954 req="CompletePromise(id=p5, idempotencyKey=6, strict=true, state=REJECTED, value=Value(headers=map[], data=))" res="CompletePromise(status=4030, promise=Promise(id=p5, state=RESOLVED, param=Value(headers=map[], data=4), value=Value(headers=map[], data=), timeout=589012, idempotencyKeyForCreate=7, idempotencyKeyForUpdate=9, tags=map[0:1.0 1:1.1], createdOn=8000, completedOn=17000))" err=<nil> level=INFO msg=DST t=998000|998999 id=12955 req="CreateCallback(promiseId=p4, rootPromiseId=p5, timeout=998395, recv=\"dst\")" res="CreateCallback(status=2000, promise=Promise(id=p4, state=REJECTED, param=Value(headers=map[], data=0), value=Value(headers=map[], data=2), timeout=30466, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=10, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=11000, completedOn=18000), callback=<nil>)" err=<nil> level=INFO msg=DST t=998000|998999 id=12956 req="SearchPromises(id=p1*, states=[REJECTED_CANCELED PENDING], tags=map[], limit=2, sortId=0)" res="SearchPromises(status=2000, promises=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=998000|998999 id=12957 req="SearchSchedules(id=s8*, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], limit=8, sortId=0)" res="SearchSchedules(status=2000, schedules=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=997000|998999 id=12939 req="CreateSchedule(id=s6, desc=, cron=1 * * * *, tags=map[0:1.0 1:1.1], promiseId=s6.{{.timestamp}}, promiseTimeout=999148, promiseParam=Value(headers=map[0:4.0], data=), promiseTags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], idempotencyKey=9)" res="CreateSchedule(status=2010, schedule=Schedule(id=s6, desc=, cron=1 * * * *, tags=map[0:1.0 1:1.1], promiseId=s6.{{.timestamp}}, promiseTimeout=999148, promiseParam=Value(headers=map[0:4.0], data=), promiseTags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], lastRunTime=0, nextRunTime=3660000, idempotencyKey=9, createdOn=998000))" err=<nil> level=INFO msg=DST t=999000|1000999 id=12958 req="ReadSchedule(id=s6)" res="ReadSchedule(status=2000, schedule=Schedule(id=s6, desc=, cron=1 * * * *, tags=map[0:1.0 1:1.1], promiseId=s6.{{.timestamp}}, promiseTimeout=999148, promiseParam=Value(headers=map[0:4.0], data=), promiseTags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], lastRunTime=0, nextRunTime=3660000, idempotencyKey=9, createdOn=998000))" err=<nil> level=INFO msg=DST t=999000|1000999 id=12959 req="ReadPromise(id=p0)" res="ReadPromise(status=2000, promise=Promise(id=p0, state=REJECTED_CANCELED, param=Value(headers=map[0:6.0], data=), value=Value(headers=map[0:2.0 1:2.1], data=18), timeout=400840, idempotencyKeyForCreate=12, idempotencyKeyForUpdate=7, tags=map[], createdOn=5000, completedOn=19000))" err=<nil> level=INFO msg=DST t=999000|1000999 id=12960 req="SearchSchedules(id=s7*, tags=map[], limit=9, sortId=0)" res="SearchSchedules(status=2000, schedules=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=999000|1000999 id=12961 req="SearchSchedules(id=s*0, tags=map[], limit=4, sortId=0)" res="SearchSchedules(status=2000, schedules=[Schedule(id=s0, desc=, cron=30 * * * *, tags=map[0:0.0 resonate:timeout:true], promiseId=, promiseTimeout=0, promiseParam=Value(headers=map[], data=), promiseTags=map[], lastRunTime=0, nextRunTime=1800000, idempotencyKey=4, createdOn=993000)], cursor=<nil>)" err=<nil> level=INFO msg=DST t=999000|1000999 id=12962 req="ReadPromise(id=p5)" res="ReadPromise(status=2000, promise=Promise(id=p5, state=RESOLVED, param=Value(headers=map[], data=4), value=Value(headers=map[], data=), timeout=589012, idempotencyKeyForCreate=7, idempotencyKeyForUpdate=9, tags=map[0:1.0 1:1.1], createdOn=8000, completedOn=17000))" err=<nil> level=INFO msg=DST t=999000|1000999 id=12963 req="CreatePromise(id=p5, idempotencyKey=<nil>, strict=false, param=Value(headers=map[], data=9), timeout=1248906, tags=map[0:1.0 1:1.1])" res="CreatePromise(status=4090, promise=Promise(id=p5, state=RESOLVED, param=Value(headers=map[], data=4), value=Value(headers=map[], data=), timeout=589012, idempotencyKeyForCreate=7, idempotencyKeyForUpdate=9, tags=map[0:1.0 1:1.1], createdOn=8000, completedOn=17000))" err=<nil> level=INFO msg=DST t=999000|1000999 id=12964 req="SearchPromises(id=p*0, states=[REJECTED_CANCELED], tags=map[], limit=2, sortId=0)" res="SearchPromises(status=2000, promises=[Promise(id=p0, state=REJECTED_CANCELED, param=Value(headers=map[0:6.0], data=), value=Value(headers=map[0:2.0 1:2.1], data=18), timeout=400840, idempotencyKeyForCreate=12, idempotencyKeyForUpdate=7, tags=map[], createdOn=5000, completedOn=19000)], cursor=<nil>)" err=<nil> level=INFO msg=DST t=999000|1000999 id=12965 req="SearchSchedules(id=s*9, tags=map[], limit=4, sortId=0)" res="SearchSchedules(status=2000, schedules=[], cursor=<nil>)" err=<nil> level=INFO msg=DST t=999000|1000999 id=12966 req="CreatePromiseAndCallback(promise=CreatePromise(id=p4, idempotencyKey=6, strict=false, param=Value(headers=map[0:5.0 1:5.1 2:5.2], data=), timeout=1433132, tags=map[0:1.0 1:1.1]), callback=CreateCallback(promiseId=p4, rootPromiseId=p0, timeout=999625, recv=\"dst\"))" res="CreatePromiseAndCallback(status=4090, promise=Promise(id=p4, state=REJECTED, param=Value(headers=map[], data=0), value=Value(headers=map[], data=2), timeout=30466, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=10, tags=map[0:2.0 resonate:invoke:dst resonate:timeout:true], createdOn=11000, completedOn=18000), callback=<nil>)" err=<nil> Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=3, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=30466, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=11000, completedOn=0) t2: Task(id=4, processId=, state=ENQUEUED, rootPromiseId=p4, recv="dst", mesg=Mesg(type=invoke, root=p4, leaf=p4), timeout=493543, counter=2, attempt=0, ttl=0, expiresAt=30284, createdOn=11000, completedOn=0)Enqueue task invariant has been violated t1: Task(id=8, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p4), timeout=354711, counter=1, attempt=0, ttl=0, expiresAt=26284, createdOn=18000, completedOn=0) t2: Task(id=10, processId=, state=ENQUEUED, rootPromiseId=p1, recv="dst", mesg=Mesg(type=resume, root=p1, leaf=p6), timeout=879749, counter=1, attempt=0, ttl=0, expiresAt=30284, createdOn=19000, completedOn=0)level=ERROR msg="DST is non linearizable" Error: DST failed Usage: resonate dst run [flags] Flags: --seed int dst seed --ticks int number of ticks (default 1000) --timeout duration timeout (default 1h0m0s) --scenario string can be one of: default, fault, lazy (default "default") --visualization-path string porcupine visualization file path (default "dst.html") --reqs-per-tick range number of requests per tick (default 1:25) --ids range promise id set size (default 1:25) --idempotency-keys range idempotency key set size (default 1:25) --headers range promise header set size (default 1:25) --data range promise data set size (default 1:25) --tags range promise tags set size (default 1:25) --backchannel-size range backchannel size (default 1:1000) --system-url string resonate server url --system-coroutine-max-size range max concurrent coroutines (default 1:1000) --system-submission-batch-size range max submissions processed per tick (default 1:1000) --system-completion-batch-size range max completions processed per tick (default 1:1000) --system-promise-batch-size range max promises processed per iteration (default 1:100) --system-schedule-batch-size range max schedules processed per iteration (default 1:100) --system-task-batch-size range max tasks processed per iteration (default 1:100) --system-task-enqueue-delay range time delay before attempting to reenqueue tasks (default 1s:10s) --system-signal-timeout range time to wait for api/aio signal (default 1s:10s) --api-size range submission buffered channel size (default 1:1000) --api-http-enable enable subsystem --api-http-addr string http server address (default ":8001") --api-http-auth stringToString http basic auth username password pairs (default []) --api-http-timeout duration http server graceful shutdown timeout (default 10s) --api-http-task-frequency duration default task frequency (default 1m0s) --api-grpc-enable enable subsystem --api-grpc-addr string grpc server address (default ":50051") --aio-size range completion buffered channel size (default 1:1000) --aio-router-enable enable subsystem (default true) --aio-router-size int submission buffered channel size (default 100) --aio-router-workers int number of workers (default 1) --aio-sender-enable enable subsystem (default true) --aio-sender-p range probability of simulated unsuccessful request (default 0.00:1.00) --aio-store-postgres-enable enable subsystem --aio-store-postgres-size int submission buffered channel size (default 1000) --aio-store-postgres-batch-size int max submissions processed per iteration (default 1000) --aio-store-postgres-workers int number of workers (default 1) --aio-store-postgres-host string postgres host (default "localhost") --aio-store-postgres-port string postgres port (default "5432") --aio-store-postgres-username string postgres username --aio-store-postgres-password string postgres password --aio-store-postgres-database string postgres database (default "resonate_dst") --aio-store-postgres-query stringToString postgres query options (default [sslmode=disable]) --aio-store-postgres-tx-timeout duration postgres transaction timeout (default 10s) --aio-store-postgres-reset reset postgres db on shutdown (default true) --aio-store-sqlite-enable enable subsystem (default true) --aio-store-sqlite-size int submission buffered channel size (default 1000) --aio-store-sqlite-batch-size int max submissions processed per iteration (default 1000) --aio-store-sqlite-path string sqlite database path (default ":memory:") --aio-store-sqlite-tx-timeout duration sqlite transaction timeout (default 10s) --aio-store-sqlite-reset reset sqlite db on shutdown (default true) --metrics-addr string prometheus metrics server address (default ":9090") --log-level string can be one of: debug, info, warn, error (default "info") -h, --help help for run Global Flags: --config string config file (default "resonate.yml")
more details
DST Failed
DST run failed for seed=19253, ticks=1000, scenario=default, store=sqlite.
Seed
Scenario
Store
Commit
Command
Logs
more details