Crashes semaphore when 2 tasks has same time

[fatihusta]

Task1: 0 0,8,16 * * * Task2: 0 0,8,16 * * *

Apr 12 00:00:00 semaphore semaphore[368518]: panic: Connection schedule already exists
Apr 12 00:00:00 semaphore semaphore[368518]: goroutine 23 [running]:
Apr 12 00:00:00 semaphore semaphore[368518]: github.com/ansible-semaphore/semaphore/db/bolt.(*BoltDb).Connect(0xc0001918c0, {0xb9cbfe, 0x8})
Apr 12 00:00:00 semaphore semaphore[368518]:         /home/runner/work/semaphore/semaphore/db/bolt/BoltDb.go:85 +0x3c5
Apr 12 00:00:00 semaphore semaphore[368518]: github.com/ansible-semaphore/semaphore/services/schedules.ScheduleRunner.Run({0x0?, 0x0?, 0xc0000974a0?})
Apr 12 00:00:00 semaphore semaphore[368518]:         /home/runner/work/semaphore/semaphore/services/schedules/pool.go:56 +0xaa
Apr 12 00:00:00 semaphore semaphore[368518]: github.com/robfig/cron/v3.(*Cron).startJob.func1()
Apr 12 00:00:00 semaphore semaphore[368518]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:312 +0x6a
Apr 12 00:00:00 semaphore semaphore[368518]: created by github.com/robfig/cron/v3.(*Cron).startJob
Apr 12 00:00:00 semaphore semaphore[368518]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:310 +0xad
Apr 12 00:00:00 semaphore systemd[1]: semaphore.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 12 00:00:00 semaphore systemd[1]: semaphore.service: Failed with result 'exit-code'.
Apr 12 00:00:00 semaphore systemd[1]: semaphore.service: Consumed 1.733s CPU time.
Apr 12 00:00:03 semaphore systemd[1]: semaphore.service: Scheduled restart job, restart counter is at 22.
Apr 12 00:00:03 semaphore systemd[1]: Stopped Ansible Semaphore.
Apr 12 00:00:03 semaphore systemd[1]: semaphore.service: Consumed 1.733s CPU time.
Apr 12 00:00:03 semaphore systemd[1]: Started Ansible Semaphore.
Apr 12 00:00:03 semaphore semaphore[371629]: BoltDB /var/lib/semaphore/database.boltdb
Apr 12 00:00:03 semaphore semaphore[371629]: Tmp Path (projects home) /tmp/semaphore
Apr 12 00:00:03 semaphore semaphore[371629]: Semaphore v2.8.89
Apr 12 00:00:03 semaphore semaphore[371629]: Interface 127.0.0.1
Apr 12 00:00:03 semaphore semaphore[371629]: Port :3000
Apr 12 00:00:03 semaphore semaphore[371629]: Server is running
Apr 12 08:00:00 semaphore semaphore[371629]: panic: Connection schedule already exists
Apr 12 08:00:00 semaphore semaphore[371629]: goroutine 49 [running]:
Apr 12 08:00:00 semaphore semaphore[371629]: github.com/ansible-semaphore/semaphore/db/bolt.(*BoltDb).Connect(0xc0001918c0, {0xb9cbfe, 0x8})
Apr 12 08:00:00 semaphore semaphore[371629]:         /home/runner/work/semaphore/semaphore/db/bolt/BoltDb.go:85 +0x3c5
Apr 12 08:00:00 semaphore semaphore[371629]: github.com/ansible-semaphore/semaphore/services/schedules.ScheduleRunner.Run({0x0?, 0x0?, 0xc0000974a0?})
Apr 12 08:00:00 semaphore semaphore[371629]:         /home/runner/work/semaphore/semaphore/services/schedules/pool.go:56 +0xaa
Apr 12 08:00:00 semaphore semaphore[371629]: github.com/robfig/cron/v3.(*Cron).startJob.func1()
Apr 12 08:00:00 semaphore semaphore[371629]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:312 +0x6a
Apr 12 08:00:00 semaphore semaphore[371629]: created by github.com/robfig/cron/v3.(*Cron).startJob
Apr 12 08:00:00 semaphore semaphore[371629]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:310 +0xad
Apr 12 08:00:00 semaphore systemd[1]: semaphore.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 12 08:00:00 semaphore systemd[1]: semaphore.service: Failed with result 'exit-code'.
Apr 12 08:00:00 semaphore systemd[1]: semaphore.service: Consumed 1.390s CPU time.
Apr 12 08:00:03 semaphore systemd[1]: semaphore.service: Scheduled restart job, restart counter is at 23.
Apr 12 08:00:03 semaphore systemd[1]: Stopped Ansible Semaphore.
Apr 12 08:00:03 semaphore systemd[1]: semaphore.service: Consumed 1.390s CPU time.

[nliechti]

We are also having trouble with the embeded BoltDB with the same error. But not only limited to parallel execution, it happens unpredictable with cron jobs and manually triggered jobs.

[fiftin]

Hi @fatihusta , @nliechti thank for the reporting. I will try to reproduce.

[myownhost]

@fiftin, I can reproduce this in my environment. When I schedule tasks to start at the same time, I get the following error in the log and the second task does not start:

panic: Connection schedule already exists
time="2023-08-16T08:45:36+02:00" level=info msg="Release resource locker with TaskRunner 2147483062"
goroutine 54 [running]:
github.com/ansible-semaphore/semaphore/db/bolt.(*BoltDb).Connect(0xc000103920, {0xb9cbfe, 0x8})
#011/home/runner/work/semaphore/semaphore/db/bolt/BoltDb.go:85 +0x3c5
github.com/ansible-semaphore/semaphore/services/schedules.ScheduleRunner.Run({0x0?, 0x0?, 0xc000031a70?})
#011/home/runner/work/semaphore/semaphore/services/schedules/pool.go:56 +0xaa
github.com/robfig/cron/v3.(*Cron).startJob.func1()
#011/home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:312 +0x6a
created by github.com/robfig/cron/v3.(*Cron).startJob
#011/home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:310 +0xad

[ziouf]

This is still an issue for me

Nov 05 00:00:00 ansible semaphore[38994]: panic: Connection schedule already exists
Nov 05 00:00:00 ansible semaphore[38994]: goroutine 395 [running]:
Nov 05 00:00:00 ansible semaphore[38994]: github.com/ansible-semaphore/semaphore/db/bolt.(*BoltDb).Connect(0xc0000348d0, {0xbfba9c, 0x8})
Nov 05 00:00:00 ansible semaphore[38994]:         /home/runner/work/semaphore/semaphore/db/bolt/BoltDb.go:86 +0x3f3
Nov 05 00:00:00 ansible semaphore[38994]: github.com/ansible-semaphore/semaphore/services/schedules.ScheduleRunner.Run({0xc0000f6580?, 0xc0000f6570?, 0xc0000>
Nov 05 00:00:00 ansible semaphore[38994]:         /home/runner/work/semaphore/semaphore/services/schedules/SchedulePool.go:56 +0xaa
Nov 05 00:00:00 ansible semaphore[38994]: github.com/robfig/cron/v3.(*Cron).startJob.func1()
Nov 05 00:00:00 ansible semaphore[38994]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:312 +0x6a
Nov 05 00:00:00 ansible semaphore[38994]: created by github.com/robfig/cron/v3.(*Cron).startJob
Nov 05 00:00:00 ansible semaphore[38994]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:310 +0xad

v2.9.37 with BoltDB

@fiftin

[canlot]

I managed to find the issue, if 2 or more jobs are scheduled at the same time the cron scheduler executes ScheduleRunner 2 times one after the other and if Bolt database beeing used, second db "schedule" connection fails beeing created because only 1 connection allowed at the same time. I managed to sove the issue by locking a variable at start of the schedule at function Run that is called from cron and unlock it at the end:

package schedules

import (
    "sync"

    log "github.com/Sirupsen/logrus"
    "github.com/ansible-semaphore/semaphore/db"
    "github.com/ansible-semaphore/semaphore/lib"
    "github.com/ansible-semaphore/semaphore/services/tasks"
    "github.com/robfig/cron/v3"
)

type ScheduleRunner struct {
    projectID  int
    scheduleID int
    pool       *SchedulePool
}

var singleConnectionStoreLocker sync.Locker

func (r ScheduleRunner) tryUpdateScheduleCommitHash(schedule db.Schedule) (updated bool, err error) {
    repo, err := r.pool.store.GetRepository(schedule.ProjectID, *schedule.RepositoryID)
    if err != nil {
        return
    }

    err = repo.SSHKey.DeserializeSecret()
    if err != nil {
        return
    }

    remoteHash, err := lib.GitRepository{
        Logger:     nil,
        TemplateID: schedule.TemplateID,
        Repository: repo,
        Client:     lib.CreateDefaultGitClient(),
    }.GetLastRemoteCommitHash()

    if err != nil {
        return
    }

    if schedule.LastCommitHash != nil && remoteHash == *schedule.LastCommitHash {
        return
    }

    err = r.pool.store.SetScheduleCommitHash(schedule.ProjectID, schedule.ID, remoteHash)
    if err != nil {
        return
    }

    updated = true
    return
}

func (r ScheduleRunner) Run() {
    if !r.pool.store.PermanentConnection() {
        singleConnectionStoreLocker.Lock()
        log.Print("singleConnectStoreLocker locked")
        r.pool.store.Connect("schedule")
        log.Print("SCHEDULERUNNER: Store connected: schedule")
        defer log.Print("singleConnectStoreLocker unlocked")
        defer singleConnectionStoreLocker.Unlock()
        defer log.Print("SCHEDULERUNNER: Store closed: schedule")
        defer r.pool.store.Close("schedule")
    }

    schedule, err := r.pool.store.GetSchedule(r.projectID, r.scheduleID)
    if err != nil {
        log.Error(err)
        return
    }

    if schedule.RepositoryID != nil {
        var updated bool
        updated, err = r.tryUpdateScheduleCommitHash(schedule)
        if err != nil {
            log.Error(err)
            return
        }
        if !updated {
            return
        }
    }

    _, err = r.pool.taskPool.AddTask(db.Task{
        TemplateID: schedule.TemplateID,
        ProjectID:  schedule.ProjectID,
    }, nil, schedule.ProjectID)

    if err != nil {
        log.Error(err)
    }
}

type SchedulePool struct {
    cron     *cron.Cron
    locker   sync.Locker
    store    db.Store
    taskPool *tasks.TaskPool
}

func (p *SchedulePool) init() {
    p.cron = cron.New()
    p.locker = &sync.Mutex{}
}

func (p *SchedulePool) Refresh() {
    defer p.locker.Unlock()

    schedules, err := p.store.GetSchedules()

    if err != nil {
        log.Error(err)
        return
    }

    p.locker.Lock()
    p.clear()
    for _, schedule := range schedules {
        _, err := p.addRunner(ScheduleRunner{
            projectID:  schedule.ProjectID,
            scheduleID: schedule.ID,
            pool:       p,
        }, schedule.CronFormat)
        if err != nil {
            log.Error(err)
        }
    }
}

func (p *SchedulePool) addRunner(runner ScheduleRunner, cronFormat string) (int, error) {
    id, err := p.cron.AddJob(cronFormat, runner)

    if err != nil {
        return 0, err
    }

    return int(id), nil
}

func (p *SchedulePool) Run() {
    p.cron.Run()
}

func (p *SchedulePool) clear() {
    runners := p.cron.Entries()
    for _, r := range runners {
        p.cron.Remove(r.ID)
    }
}

func (p *SchedulePool) Destroy() {
    defer p.locker.Unlock()
    p.locker.Lock()
    p.cron.Stop()
    p.clear()
    p.cron = nil
}

func CreateSchedulePool(store db.Store, taskPool *tasks.TaskPool) SchedulePool {
    pool := SchedulePool{
        store:    store,
        taskPool: taskPool,
    }
    singleConnectionStoreLocker = &sync.Mutex{}
    pool.init()
    pool.Refresh()
    return pool
}

func ValidateCronFormat(cronFormat string) error {
    _, err := cron.ParseStandard(cronFormat)
    return err
}

@fiftin there are propably better solutions for this but it's a start and as far i can tell not disturbing things.

[jojoob]

This bug is fixed since Feb 10. See the referenced commit above. And I just verified it on my own instance. After I upgraded to v2.9.75 I'm not able to reproduce the bug any more!

[fatihusta]

I still have this issue.

semaphore version
v2.9.64

May 21 12:00:00 semaphore semaphore[3287470]: panic: Connection schedule 6 already exists
May 21 12:00:00 semaphore semaphore[3287470]: goroutine 60699 [running]:
May 21 12:00:00 semaphore semaphore[3287470]: github.com/ansible-semaphore/semaphore/db/bolt.(*BoltDb).Connect(0xc0001c1b30, {0xc009e8a0d0, 0xa})
May 21 12:00:00 semaphore semaphore[3287470]:         /home/runner/work/semaphore/semaphore/db/bolt/BoltDb.go:86 +0x3b4
May 21 12:00:00 semaphore semaphore[3287470]: github.com/ansible-semaphore/semaphore/services/schedules.ScheduleRunner.Run({0x1e67a40?, 0xc0048e0dc0?, 0xc0064b6f90?})
May 21 12:00:00 semaphore semaphore[3287470]:         /home/runner/work/semaphore/semaphore/services/schedules/SchedulePool.go:57 +0xc3
May 21 12:00:00 semaphore semaphore[3287470]: github.com/robfig/cron/v3.(*Cron).startJob.func1()
May 21 12:00:00 semaphore semaphore[3287470]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:312 +0x5b
May 21 12:00:00 semaphore semaphore[3287470]: created by github.com/robfig/cron/v3.(*Cron).startJob in goroutine 7
May 21 12:00:00 semaphore semaphore[3287470]:         /home/runner/work/semaphore/semaphore/vendor/github.com/robfig/cron/v3/cron.go:310 +0xa5