DST: 32221

Question

DST: 32221

Closed this issue 2 months ago · 1 comments

DST Failed

DST run failed for seed=32221, ticks=1000000, scenario=default, store=sqlite.

Seed

Scenario

default

Store

sqlite

Commit

27dbc9c26f35f7a9a65508f73519c2d0357caf81

Command

go run ./... dst run --seed 32221 --ticks 1000000 --scenario default --aio-store sqlite

Logs

level=INFO msg=DST seed=32221 ticks=1000000 reqsPerTick=1:25 dst="DST(ids=5, idempotencyKeys=8, headers=16, data=21, tags=12, searches=6)" system="System(api=API(size=110, subsystems=[]), aio=AIODST(subsystems=[store]), config=Config(cms=554, ncs=0, sbs=399, cbs=473, sbs=307))"
level=INFO msg=DST t=0|999 tid=0 req="CompletePromise(id=3, idempotencyKey=4, strict=false, state=RESOLVED)" res="CompletePromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=0|999 tid=1 req="ReadSchedule(id=4)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=0|999 tid=2 req="ReleaseLock(resourceId=3, executionId=3)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=0|999 tid=3 req="AcquireLock(resourceId=0, executionId=2, processId=4, expiryInMilliseconds=7073246)" res="AcquireLock(status=2010, lock=Lock(resourceId=0, executionId=2, processId=4, expiryInMilliseconds=7073246, expiresAt=7073246))" err=<nil>
level=INFO msg=DST t=0|999 tid=4 req="CompletePromise(id=2, idempotencyKey=3, strict=true, state=RESOLVED)" res="CompletePromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=0|999 tid=5 req="ReadSchedule(id=4)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=0|999 tid=6 req="HeartbeatLocks(processId=4)" res="HeartbeatLocks(status=2000, locksAffected=1)" err=<nil>
level=INFO msg=DST t=0|999 tid=7 req="ReleaseLock(resourceId=4, executionId=2)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=0|999 tid=8 req="SearchPromises(id=6*, states=[REJECTED REJECTED], tags=map[], limit=5, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=1000|1999 tid=9 req="ReadPromise(id=0)" res="ReadPromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=10 req="ReadPromise(id=4)" res="ReadPromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=11 req="CompletePromise(id=1, idempotencyKey=<nil>, strict=true, state=REJECTED_CANCELED)" res="CompletePromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=12 req="HeartbeatLocks(processId=3)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=14 req="SearchPromises(id=8*, states=[PENDING REJECTED REJECTED_CANCELED], tags=map[0:11.0 1:11.1 2:11.2 resonate:timeout:true], limit=4, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=1000|1999 tid=15 req="ReadSchedule(id=1)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=17 req="HeartbeatLocks(processId=1)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=18 req="ReadSchedule(id=2)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=19 req="ReadSchedule(id=3)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=1000|1999 tid=20 req="SearchPromises(id=6*, states=[REJECTED RESOLVED REJECTED_TIMEDOUT], tags=map[0:4.0], limit=10, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=1000|1999 tid=21 req="SearchPromises(id=*0, states=[PENDING REJECTED_CANCELED], tags=map[0:4.0], limit=10, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=1000|1999 tid=22 req="SearchPromises(id=*10, states=[REJECTED_TIMEDOUT REJECTED_CANCELED], tags=map[], limit=2, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=1000|1999 tid=23 req="SearchPromises(id=6*, states=[PENDING REJECTED], tags=map[0:3.0 1:3.1], limit=2, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=25 req="SearchPromises(id=*6, states=[REJECTED], tags=map[0:4.0], limit=8, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=26 req="ReadPromise(id=0)" res="ReadPromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=27 req="HeartbeatLocks(processId=1)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=28 req="SearchPromises(id=*2, states=[PENDING REJECTED REJECTED_CANCELED], tags=map[0:4.0], limit=9, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=29 req="SearchPromises(id=0*, states=[PENDING RESOLVED REJECTED], tags=map[], limit=4, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=30 req="HeartbeatLocks(processId=1)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=32 req="SearchPromises(id=*10, states=[], tags=map[], limit=10, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=33 req="AcquireLock(resourceId=3, executionId=3, processId=3, expiryInMilliseconds=1888855)" res="AcquireLock(status=2010, lock=Lock(resourceId=3, executionId=3, processId=3, expiryInMilliseconds=1888855, expiresAt=1890855))" err=<nil>
level=INFO msg=DST t=2000|2999 tid=34 req="ReleaseLock(resourceId=3, executionId=1)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=35 req="SearchSchedules(id=*10, tags=map[], limit=2, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=37 req="SearchPromises(id=2*, states=[REJECTED_CANCELED RESOLVED], tags=map[0:4.0], limit=10, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=38 req="SearchSchedules(id=*6, tags=map[0:0.0 1:0.1 2:0.2 resonate:timeout:true], limit=7, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=2000|2999 tid=40 req="DeleteSchedule(id=2)" res="DeleteSchedule(status=4042)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=41 req="ReleaseLock(resourceId=3, executionId=4)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=42 req="CompletePromise(id=3, idempotencyKey=<nil>, strict=true, state=REJECTED)" res="CompletePromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=43 req="ReadSchedule(id=1)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=2000|2999 tid=44 req="SearchSchedules(id=*0, tags=map[0:3.0 1:3.1], limit=8, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=1000|2999 tid=13 req="CreatePromise(id=2, idempotencyKey=<nil>, strict=false, timeout=624525762)" res="CreatePromise(status=2010, promise=Promise(id=2, state=PENDING, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=3000|3999 tid=45 req="AcquireLock(resourceId=1, executionId=1, processId=3, expiryInMilliseconds=582495)" res="AcquireLock(status=2010, lock=Lock(resourceId=1, executionId=1, processId=3, expiryInMilliseconds=582495, expiresAt=585495))" err=<nil>
level=INFO msg=DST t=3000|3999 tid=46 req="CompletePromise(id=1, idempotencyKey=7, strict=false, state=RESOLVED)" res="CompletePromise(status=4040, promise=<nil>)" err=<nil>
level=INFO msg=DST t=3000|3999 tid=47 req="AcquireLock(resourceId=3, executionId=0, processId=1, expiryInMilliseconds=466750)" res="AcquireLock(status=4034, lock=<nil>)" err=<nil>
level=INFO msg=DST t=3000|3999 tid=48 req="DeleteSchedule(id=1)" res="DeleteSchedule(status=2040)" err=<nil>
level=INFO msg=DST t=3000|3999 tid=49 req="AcquireLock(resourceId=1, executionId=3, processId=2, expiryInMilliseconds=1396179)" res="AcquireLock(status=4034, lock=<nil>)" err=<nil>
level=INFO msg=DST t=3000|3999 tid=50 req="HeartbeatLocks(processId=4)" res="HeartbeatLocks(status=2000, locksAffected=1)" err=<nil>
level=INFO msg=DST t=3000|3999 tid=51 req="ReadPromise(id=2)" res="ReadPromise(status=2000, promise=Promise(id=2, state=PENDING, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=2000|3999 tid=24 req="CreateSchedule(id=2, idempotencyKey=<nil>, description=, cron=59 * * * *)" res="CreateSchedule(status=2010, schedule=Schedule(id=2, description=, cron=59 * * * *, tags=map[], promiseId=2.{{.timestamp}}, promiseTimeout=919881429, promiseParam=Value(headers=map[0:2.0], data=), promiseTags=map[0:0.0 1:0.1 2:0.2 resonate:timeout:true], lastRunTime=0, nextRunTime=3540000, idempotencyKey=<nil>, createdOn=3000))" err=<nil>
level=INFO msg=DST t=2000|3999 tid=31 req="CreatePromise(id=0, idempotencyKey=<nil>, strict=false, timeout=670687378)" res="CreatePromise(status=2010, promise=Promise(id=0, state=PENDING, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=670687378, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[]))" err=<nil>

...

level=INFO msg=DST t=577899000|577899999 tid=7222854 req="ReadPromise(id=2)" res="ReadPromise(status=2000, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577899000|577899999 tid=7222855 req="ReadPromise(id=4)" res="ReadPromise(status=2000, promise=Promise(id=4, state=REJECTED_CANCELED, param=Value(headers=map[0:8.0], data=6), value=Value(headers=map[0:5.0], data=), timeout=799144918, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[]))" err=<nil>
level=INFO msg=DST t=577900000|577900999 tid=7222856 req="ReadPromise(id=3)" res="ReadPromise(status=2000, promise=Promise(id=3, state=REJECTED, param=Value(headers=map[0:3.0 1:3.1], data=), value=Value(headers=map[0:9.0 1:9.1], data=2), timeout=673297170, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=5, tags=map[]))" err=<nil>
level=INFO msg=DST t=577900000|577900999 tid=7222857 req="CompletePromise(id=2, idempotencyKey=2, strict=true, state=REJECTED_CANCELED)" res="CompletePromise(status=4031, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577900000|577900999 tid=7222858 req="ReadSchedule(id=4)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=577900000|577900999 tid=7222859 req="ReadSchedule(id=3)" res="ReadSchedule(status=2000, schedule=Schedule(id=3, description=, cron=13 * * * *, tags=map[0:3.0 1:3.1], promiseId=3.{{.timestamp}}, promiseTimeout=765915734, promiseParam=Value(headers=map[], data=), promiseTags=map[0:4.0], lastRunTime=0, nextRunTime=580380000, idempotencyKey=5, createdOn=577893000))" err=<nil>
level=INFO msg=DST t=577900000|577900999 tid=7222860 req="AcquireLock(resourceId=4, executionId=2, processId=1, expiryInMilliseconds=2326570)" res="AcquireLock(status=4034, lock=<nil>)" err=<nil>
level=INFO msg=DST t=577900000|577900999 tid=7222861 req="SearchPromises(id=*0, states=[REJECTED_TIMEDOUT PENDING], tags=map[], limit=1, sortId=67)" res="SearchPromises(status=2000, cursor=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJOZXh0Ijp7ImlkIjoiKjAiLCJzdGF0ZXMiOlsiUkVKRUNURURfVElNRURPVVQiLCJQRU5ESU5HIl0sInRhZ3MiOnt9LCJsaW1pdCI6MSwic29ydElkIjo2Nn19.Q6QJ5-kl7c0g_v6vTqHedcICrOENFkq-Rp_L3y94xFI, promises=[Promise(id=4.114000000, state=REJECTED_TIMEDOUT, param=Value(headers=map[0:1.0], data=), value=Value(headers=map[], data=), timeout=241811497, idempotencyKeyForCreate=4.114000000, idempotencyKeyForUpdate=<nil>, tags=map[0:3.0 1:3.1 resonate:invocation:true resonate:schedule:4])])" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222862 req="SearchSchedules(id=*2, tags=map[], limit=10, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222864 req="SearchSchedules(id=2*, tags=map[], limit=8, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222866 req="HeartbeatLocks(processId=3)" res="HeartbeatLocks(status=2000, locksAffected=1)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222867 req="SearchPromises(id=10*, states=[RESOLVED RESOLVED], tags=map[resonate:timeout:true], limit=7, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222868 req="ReleaseLock(resourceId=4, executionId=1)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222869 req="CreateSchedule(id=3, idempotencyKey=<nil>, description=, cron=23 * * * *)" res="CreateSchedule(status=4091, schedule=Schedule(id=3, description=, cron=13 * * * *, tags=map[0:3.0 1:3.1], promiseId=3.{{.timestamp}}, promiseTimeout=765915734, promiseParam=Value(headers=map[], data=), promiseTags=map[0:4.0], lastRunTime=0, nextRunTime=580380000, idempotencyKey=5, createdOn=577893000))" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222870 req="CompletePromise(id=3, idempotencyKey=<nil>, strict=false, state=REJECTED_CANCELED)" res="CompletePromise(status=4031, promise=Promise(id=3, state=REJECTED, param=Value(headers=map[0:3.0 1:3.1], data=), value=Value(headers=map[0:9.0 1:9.1], data=2), timeout=673297170, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=5, tags=map[]))" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222871 req="ReadPromise(id=2)" res="ReadPromise(status=2000, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222872 req="ReadSchedule(id=1)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222873 req="ReleaseLock(resourceId=2, executionId=3)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222874 req="ReleaseLock(resourceId=1, executionId=2)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222875 req="ReleaseLock(resourceId=4, executionId=2)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222876 req="HeartbeatLocks(processId=1)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222877 req="CompletePromise(id=0, idempotencyKey=<nil>, strict=true, state=RESOLVED)" res="CompletePromise(status=4031, promise=Promise(id=0, state=REJECTED, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=670687378, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=4, tags=map[]))" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222878 req="CompletePromise(id=4, idempotencyKey=0, strict=true, state=RESOLVED)" res="CompletePromise(status=4032, promise=Promise(id=4, state=REJECTED_CANCELED, param=Value(headers=map[0:8.0], data=6), value=Value(headers=map[0:5.0], data=), timeout=799144918, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[]))" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222880 req="AcquireLock(resourceId=4, executionId=2, processId=1, expiryInMilliseconds=2151354)" res="AcquireLock(status=4034, lock=<nil>)" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222881 req="SearchPromises(id=0*, states=[REJECTED], tags=map[0:3.0 1:3.1], limit=1, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=577901000|577901999 tid=7222882 req="ReadPromise(id=1)" res="ReadPromise(status=2000, promise=Promise(id=1, state=RESOLVED, param=Value(headers=map[0:3.0 1:3.1], data=), value=Value(headers=map[0:3.0 1:3.1], data=), timeout=599952550, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=3, tags=map[]))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222884 req="ReleaseLock(resourceId=3, executionId=2)" res="ReleaseLock(status=4043)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222885 req="HeartbeatLocks(processId=1)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222886 req="SearchPromises(id=2*, states=[RESOLVED], tags=map[], limit=7, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[Promise(id=2.262740000, state=RESOLVED, param=Value(headers=map[0:9.0 1:9.1], data=), value=Value(headers=map[], data=), timeout=558191522, idempotencyKeyForCreate=2.262740000, idempotencyKeyForUpdate=<nil>, tags=map[0:9.0 resonate:invocation:true resonate:schedule:2 resonate:timeout:true]) Promise(id=2.145500000, state=RESOLVED, param=Value(headers=map[0:12.0 1:12.1 2:12.2], data=13), value=Value(headers=map[], data=), timeout=440585521, idempotencyKeyForCreate=2.145500000, idempotencyKeyForUpdate=<nil>, tags=map[resonate:invocation:true resonate:schedule:2 resonate:timeout:true]) Promise(id=2.141120000, state=RESOLVED, param=Value(headers=map[0:13.0 1:13.1], data=1), value=Value(headers=map[], data=), timeout=317891123, idempotencyKeyForCreate=2.141120000, idempotencyKeyForUpdate=<nil>, tags=map[resonate:invocation:true resonate:schedule:2 resonate:timeout:true]) Promise(id=2.121920000, state=RESOLVED, param=Value(headers=map[0:15.0 1:15.1], data=), value=Value(headers=map[], data=), timeout=524950133, idempotencyKeyForCreate=2.121920000, idempotencyKeyForUpdate=<nil>, tags=map[0:9.0 resonate:invocation:true resonate:schedule:2 resonate:timeout:true]) Promise(id=2.75660000, state=RESOLVED, param=Value(headers=map[0:0.0 1:0.1 2:0.2], data=), value=Value(headers=map[], data=), timeout=545803046, idempotencyKeyForCreate=2.75660000, idempotencyKeyForUpdate=<nil>, tags=map[resonate:invocation:true resonate:schedule:2 resonate:timeout:true]) Promise(id=2.58980000, state=RESOLVED, param=Value(headers=map[0:15.0 1:15.1], data=17), value=Value(headers=map[], data=), timeout=343017717, idempotencyKeyForCreate=2.58980000, idempotencyKeyForUpdate=<nil>, tags=map[resonate:invocation:true resonate:schedule:2 resonate:timeout:true])])" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222888 req="SearchSchedules(id=10*, tags=map[], limit=6, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222889 req="ReadSchedule(id=4)" res="ReadSchedule(status=4042, schedule=<nil>)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222890 req="CompletePromise(id=1, idempotencyKey=3, strict=true, state=REJECTED_CANCELED)" res="CompletePromise(status=4030, promise=Promise(id=1, state=RESOLVED, param=Value(headers=map[0:3.0 1:3.1], data=), value=Value(headers=map[0:3.0 1:3.1], data=), timeout=599952550, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=3, tags=map[]))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222891 req="AcquireLock(resourceId=0, executionId=0, processId=4, expiryInMilliseconds=1994582)" res="AcquireLock(status=4034, lock=<nil>)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222892 req="AcquireLock(resourceId=4, executionId=0, processId=0, expiryInMilliseconds=1290475)" res="AcquireLock(status=2010, lock=Lock(resourceId=4, executionId=0, processId=0, expiryInMilliseconds=1290475, expiresAt=579192475))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222893 req="ReadPromise(id=0)" res="ReadPromise(status=2000, promise=Promise(id=0, state=REJECTED, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=670687378, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=4, tags=map[]))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222894 req="SearchPromises(id=2*, states=[PENDING REJECTED_TIMEDOUT], tags=map[], limit=2, sortId=187)" res="SearchPromises(status=2000, cursor=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJOZXh0Ijp7ImlkIjoiMioiLCJzdGF0ZXMiOlsiUEVORElORyIsIlJFSkVDVEVEX1RJTUVET1VUIl0sInRhZ3MiOnt9LCJsaW1pdCI6Miwic29ydElkIjoxNTh9fQ.9KL11MY8oAlBJn-wa5EPJDGtq1i_E5Q351JshKPghJ0, promises=[Promise(id=2.278580000, state=PENDING, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=16), value=Value(headers=map[], data=), timeout=1056786659, idempotencyKeyForCreate=2.278580000, idempotencyKeyForUpdate=<nil>, tags=map[resonate:invocation:true resonate:schedule:2 resonate:timeout:true]) Promise(id=2.239580000, state=PENDING, param=Value(headers=map[0:8.0], data=7), value=Value(headers=map[], data=), timeout=829534643, idempotencyKeyForCreate=2.239580000, idempotencyKeyForUpdate=<nil>, tags=map[resonate:invocation:true resonate:schedule:2])])" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222895 req="CompletePromise(id=2, idempotencyKey=<nil>, strict=true, state=RESOLVED)" res="CompletePromise(status=4031, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222896 req="ReadPromise(id=2)" res="ReadPromise(status=2000, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222897 req="DeleteSchedule(id=3)" res="DeleteSchedule(status=2040)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222898 req="CompletePromise(id=3, idempotencyKey=<nil>, strict=true, state=RESOLVED)" res="CompletePromise(status=4031, promise=Promise(id=3, state=REJECTED, param=Value(headers=map[0:3.0 1:3.1], data=), value=Value(headers=map[0:9.0 1:9.1], data=2), timeout=673297170, idempotencyKeyForCreate=4, idempotencyKeyForUpdate=5, tags=map[]))" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222899 req="DeleteSchedule(id=4)" res="DeleteSchedule(status=4042)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222900 req="HeartbeatLocks(processId=4)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=577902000|577902999 tid=7222901 req="ReadPromise(id=4)" res="ReadPromise(status=2000, promise=Promise(id=4, state=REJECTED_CANCELED, param=Value(headers=map[0:8.0], data=6), value=Value(headers=map[0:5.0], data=), timeout=799144918, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[]))" err=<nil>
level=INFO msg=DST t=577901000|577902999 tid=7222863 req="CreateSchedule(id=0, idempotencyKey=<nil>, description=, cron=54 * * * *)" res="CreateSchedule(status=2010, schedule=Schedule(id=0, description=, cron=54 * * * *, tags=map[], promiseId=0.{{.timestamp}}, promiseTimeout=931710232, promiseParam=Value(headers=map[], data=9), promiseTags=map[0:6.0], lastRunTime=0, nextRunTime=579240000, idempotencyKey=<nil>, createdOn=577902000))" err=<nil>
level=INFO msg=DST t=577901000|577902999 tid=7222883 req="CreateSchedule(id=2, idempotencyKey=2, description=, cron=56 * * * *)" res="CreateSchedule(status=2010, schedule=Schedule(id=2, description=, cron=56 * * * *, tags=map[0:6.0], promiseId=2.{{.timestamp}}, promiseTimeout=950428772, promiseParam=Value(headers=map[], data=), promiseTags=map[resonate:timeout:true], lastRunTime=0, nextRunTime=579360000, idempotencyKey=2, createdOn=577902000))" err=<nil>
level=INFO msg=DST t=577903000|577903999 tid=7222902 req="CreatePromise(id=2, idempotencyKey=<nil>, strict=true, timeout=685782649)" res="CreatePromise(status=4090, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577903000|577903999 tid=7222903 req="SearchPromises(id=4*, states=[], tags=map[], limit=9, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=577901000|577903999 tid=7222865 req="CreateSchedule(id=0, idempotencyKey=<nil>, description=, cron=3 * * * *)" res="CreateSchedule(status=4091, schedule=Schedule(id=0, description=, cron=54 * * * *, tags=map[], promiseId=0.{{.timestamp}}, promiseTimeout=931710232, promiseParam=Value(headers=map[], data=9), promiseTags=map[0:6.0], lastRunTime=0, nextRunTime=579240000, idempotencyKey=<nil>, createdOn=577902000))" err=<nil>
level=INFO msg=DST t=577901000|577903999 tid=7222879 req="CreateSchedule(id=0, idempotencyKey=1, description=, cron=23 * * * *)" res="CreateSchedule(status=4091, schedule=Schedule(id=0, description=, cron=54 * * * *, tags=map[], promiseId=0.{{.timestamp}}, promiseTimeout=931710232, promiseParam=Value(headers=map[], data=9), promiseTags=map[0:6.0], lastRunTime=0, nextRunTime=579240000, idempotencyKey=<nil>, createdOn=577902000))" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222904 req="DeleteSchedule(id=4)" res="DeleteSchedule(status=4042)" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222905 req="SearchSchedules(id=*8, tags=map[0:0.0 1:0.1 2:0.2 resonate:timeout:true], limit=10, sortId=<nil>)" res="SearchSchedules(status=2000, cursor=<nil>, schedules=[])" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222906 req="HeartbeatLocks(processId=4)" res="HeartbeatLocks(status=2000, locksAffected=0)" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222907 req="AcquireLock(resourceId=3, executionId=2, processId=4, expiryInMilliseconds=5758005)" res="AcquireLock(status=4034, lock=<nil>)" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222908 req="DeleteSchedule(id=4)" res="DeleteSchedule(status=4042)" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222909 req="DeleteSchedule(id=1)" res="DeleteSchedule(status=4042)" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222910 req="SearchPromises(id=2*, states=[REJECTED REJECTED_CANCELED RESOLVED], tags=map[0:7.0 1:7.1 2:7.2], limit=10, sortId=<nil>)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222911 req="CreatePromise(id=2, idempotencyKey=<nil>, strict=false, timeout=758250169)" res="CreatePromise(status=4090, promise=Promise(id=2, state=REJECTED, param=Value(headers=map[0:6.0 1:6.1 2:6.2], data=), value=Value(headers=map[0:4.0 1:4.1], data=), timeout=624525762, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=<nil>, tags=map[resonate:timeout:true]))" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222912 req="DeleteSchedule(id=1)" res="DeleteSchedule(status=4042)" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222913 req="SearchPromises(id=2*, states=[REJECTED REJECTED_TIMEDOUT REJECTED_CANCELED RESOLVED], tags=map[], limit=4, sortId=1)" res="SearchPromises(status=2000, cursor=<nil>, promises=[])" err=<nil>
level=INFO msg=DST t=577904000|577904999 tid=7222914 req="CreatePromise(id=0, idempotencyKey=<nil>, strict=false, timeout=932596621)" res="CreatePromise(status=4090, promise=Promise(id=0, state=REJECTED, param=Value(headers=map[], data=), value=Value(headers=map[], data=), timeout=670687378, idempotencyKeyForCreate=<nil>, idempotencyKeyForUpdate=4, tags=map[]))" err=<nil>
level=INFO msg=DST t=577902000|577904999 tid=7222887 req="CreateSchedule(id=2, idempotencyKey=6, description=, cron=46 * * * *)" res="CreateSchedule(status=4091, schedule=Schedule(id=2, description=, cron=56 * * * *, tags=map[0:6.0], promiseId=2.{{.timestamp}}, promiseTimeout=950428772, promiseParam=Value(headers=map[], data=), promiseTags=map[resonate:timeout:true], lastRunTime=0, nextRunTime=579360000, idempotencyKey=2, createdOn=577902000))" err=<nil>
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
level=ERROR msg="failed store execution" err="tx failed: sql: transaction has already been committed or rolled back, unable to rollback: sql: transaction has already been committed or rolled back"
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x96ab24]

goroutine 1 [running]:
github.com/resonatehq/resonate/internal/aio.(*aioDST).Enqueue.func1(0x0, {0x10fa100, 0xc483c7b500})
	github.com/resonatehq/resonate/internal/aio/aio_dst.go:92 +0x24
github.com/resonatehq/resonate/internal/kernel/bus.(*CQE[...]).Invoke(...)
	github.com/resonatehq/resonate/internal/kernel/bus/bus.go:35
github.com/resonatehq/gocoro/pkg/scheduler.(*Scheduler[...]).RunUntilBlocked(0x110e100, 0x22722550, {0xc483c62d00, 0xd, 0xffffffffffffffff})
	github.com/resonatehq/gocoro/pkg/scheduler/scheduler.go:71 +0x9d
github.com/resonatehq/resonate/internal/kernel/system.(*System).Tick(0xc0000f56c0, 0x22722550, 0x0, 0x0)
	github.com/resonatehq/resonate/internal/kernel/system/system.go:158 +0x957
github.com/resonatehq/resonate/test/dst.(*DST).Run(0xc0000130e0, 0xc0000f9260, {0x1108a10, 0xc0000c0dc0}, {0xf84623?, 0x3?}, 0xc0000f56c0)
	github.com/resonatehq/resonate/test/dst/dst.go:143 +0x1188
github.com/resonatehq/resonate/cmd/dst.RunDSTCmd.func1(0xc0000aaf00?, {0xf8515e?, 0x4?, 0xf85162?})
	github.com/resonatehq/resonate/cmd/dst/run.go:153 +0x1536
github.com/spf13/cobra.(*Command).execute(0xc000300c08, {0xc0000f0600, 0x8, 0x8})
	github.com/spf13/cobra/command.go:985 +0xaca
github.com/spf13/cobra.(*Command).ExecuteC(0x17051c0)
	github.com/spf13/cobra/command.go:1117 +0x3ff
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra/command.go:1041
github.com/resonatehq/resonate/cmd.Execute()
	github.com/resonatehq/resonate/cmd/root.go:73 +0x1a
main.main()
	github.com/resonatehq/resonate/main.go:8 +0xf

more details

Answer 1 · 2024-07-25T15:53:02.000Z

The run exceeded some resource limit and thanks to a cascading affect exposed a bug that occurs only when errors are returned from the aio subsystems. To fix this issue we have:

Removed a reference to a possible nil value. Completion can be nil, use submission for the metrics
Re-added fault injection to DST.