From fe103c3299d1f32dc4e82def69456ed71ed2e242 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Mon, 18 Nov 2024 09:34:38 +0100 Subject: [PATCH 1/7] Added debug logs to relevant mutex logs to see if any of them never unlocks --- internal/daemon/adminAgents.go | 4 ++++ internal/daemon/adminEvents.go | 4 ++++ internal/daemon/agentpool.go | 8 ++++++++ internal/daemon/daemon.go | 10 ++++++++++ internal/daemon/eventExercises.go | 6 ++++++ internal/daemon/eventLabs.go | 16 ++++++++++++++-- internal/daemon/eventWebsocket.go | 4 ++++ internal/daemon/eventpool.go | 8 ++++++++ 8 files changed, 58 insertions(+), 2 deletions(-) diff --git a/internal/daemon/adminAgents.go b/internal/daemon/adminAgents.go index e972d66..206e4d3 100644 --- a/internal/daemon/adminAgents.go +++ b/internal/daemon/adminAgents.go @@ -384,8 +384,10 @@ func (d *daemon) reconnectAgent(c *gin.Context) { d.agentPool.addAgent(agentForPool) d.eventpool.M.RLock() + log.Debug().Msg("Read lock on eventpool, adminAgents.go: 386") for _, event := range d.eventpool.Events { event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, adminAgents.go: 389") for _, lab := range event.Labs { if lab.ParentAgent.Name == agentForPool.Name { @@ -393,8 +395,10 @@ func (d *daemon) reconnectAgent(c *gin.Context) { } } event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, adminAgents.go: 397") } d.eventpool.M.RUnlock() + log.Debug().Msg("Read unlock on eventpool, adminAgents.go: 400") c.JSON(http.StatusOK, APIResponse{Status: "OK"}) return diff --git a/internal/daemon/adminEvents.go b/internal/daemon/adminEvents.go index 6680551..239c304 100644 --- a/internal/daemon/adminEvents.go +++ b/internal/daemon/adminEvents.go @@ -339,10 +339,12 @@ func (d *daemon) getEvents(c *gin.Context) { event, err := d.eventpool.GetEvent(dbEvent.Tag) if err == nil { event.M.RLock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Read lock on event, adminEvents.go: 341") for _, lab := range event.Labs { labs = append(labs, lab) } event.M.RUnlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Read unlock on event, adminEvents.go: 346") } } @@ -393,10 +395,12 @@ func (d *daemon) getEvents(c *gin.Context) { event, err := d.eventpool.GetEvent(dbEvent.Tag) if err == nil { event.M.RLock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Read lock on event, adminEvents.go: 397") for _, lab := range event.Labs { labs = append(labs, lab) } event.M.RUnlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Read unlock on event, adminEvents.go: 402") } } diff --git a/internal/daemon/agentpool.go b/internal/daemon/agentpool.go index bb9f87b..4aae7cd 100644 --- a/internal/daemon/agentpool.go +++ b/internal/daemon/agentpool.go @@ -114,8 +114,10 @@ func (ap *AgentPool) connectToMonitoringStream(routineCtx context.Context, a *Ag } event.UnassignedVpnLabs <- agentLab event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, agentpool.go: 116") event.Labs[l.Tag] = agentLab event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, agentpool.go: 119") saveState(eventPool, statePath) continue } @@ -131,8 +133,10 @@ func (ap *AgentPool) connectToMonitoringStream(routineCtx context.Context, a *Ag } event.UnassignedBrowserLabs <- agentLab event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, agentpool.go: 135") event.Labs[l.Tag] = agentLab event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, agentpool.go: 138") saveState(eventPool, statePath) continue } @@ -728,8 +732,10 @@ func (d *daemon) agentReconnectionRoutine(ticker *time.Ticker) { d.agentPool.addAgent(agentForPool) d.eventpool.M.RLock() + log.Debug().Msg("Read Lock on eventpool, agentpool.go: 734") for _, event := range d.eventpool.Events { event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, agentpool.go: 737") for _, lab := range event.Labs { if lab.ParentAgent.Name == agentForPool.Name { @@ -737,8 +743,10 @@ func (d *daemon) agentReconnectionRoutine(ticker *time.Ticker) { } } event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, agentpool.go: 745") } d.eventpool.M.RUnlock() + log.Debug().Msg("Read Unlock on eventpool, agentpool.go: 748") } } } diff --git a/internal/daemon/daemon.go b/internal/daemon/daemon.go index 9e9e4ad..af54db1 100644 --- a/internal/daemon/daemon.go +++ b/internal/daemon/daemon.go @@ -363,12 +363,15 @@ func (d *daemon) labExpiryRoutine() { for { time.Sleep(1 * time.Second) d.eventpool.M.RLock() + log.Debug().Msg("Read Lock on eventpool, daemon.go: 365") for _, event := range d.eventpool.Events { var wg sync.WaitGroup anyLabsClosed := false event.M.RLock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Read Lock on event, daemon.go: 370") for _, team := range event.Teams { team.M.RLock() + log.Debug().Str("team", team.Username).Msg("Read Lock on team, daemon.go: 373") if team.Lab != nil { if time.Now().After(team.Lab.ExpiresAtTime) { if team.Lab.Conn != nil { @@ -378,11 +381,15 @@ func (d *daemon) labExpiryRoutine() { defer wg.Done() defer func() { event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, daemon.go: 383") delete(event.Labs, team.Lab.LabInfo.Tag) event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, daemon.go: 386") team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, daemon.go: 388") team.Lab = nil team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, daemon.go: 391") saveState(d.eventpool, d.conf.StatePath) sendCommandToTeam(team, updateTeam) }() @@ -399,14 +406,17 @@ func (d *daemon) labExpiryRoutine() { } } team.M.RUnlock() + log.Debug().Str("team", team.Username).Msg("Read unlock on team, daemon.go: 408") } event.M.RUnlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Read unlock on event, daemon.go: 411") wg.Wait() if anyLabsClosed { broadCastCommandToEventTeams(event, updateEventInfo) } } d.eventpool.M.RUnlock() + log.Debug().Msg("Read unlock on eventpool, daemon.go: 418") } } diff --git a/internal/daemon/eventExercises.go b/internal/daemon/eventExercises.go index 3801d82..d5709a2 100644 --- a/internal/daemon/eventExercises.go +++ b/internal/daemon/eventExercises.go @@ -363,10 +363,12 @@ func (d *daemon) startExerciseInLab(c *gin.Context) { return } team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventExercises.go: 365") team.Status = RunningExerciseCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventExercises.go: 370") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) @@ -503,10 +505,12 @@ func (d *daemon) stopExercise(c *gin.Context) { return } team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventExercises.go: 507") team.Status = RunningExerciseCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventExercises.go: 512") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) @@ -561,10 +565,12 @@ func (d *daemon) resetExercise(c *gin.Context) { return } team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventExercises.go: 567") team.Status = RunningExerciseCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventExercises.go: 572") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) diff --git a/internal/daemon/eventLabs.go b/internal/daemon/eventLabs.go index d696cf0..b0f780f 100644 --- a/internal/daemon/eventLabs.go +++ b/internal/daemon/eventLabs.go @@ -184,7 +184,11 @@ func (d *daemon) closeLab(c *gin.Context) { } team.M.Lock() - defer team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 186") + defer func(team *Team) { + team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 189") + }(team) if team.Lab == nil { log.Debug().Str("team", team.Username).Msg("lab not found for team") @@ -195,8 +199,10 @@ func (d *daemon) closeLab(c *gin.Context) { defer saveState(d.eventpool, d.conf.StatePath) event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventLabs.go: 201") delete(event.Labs, team.Lab.LabInfo.Tag) event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 204") if team.Lab.Conn != nil { if err := team.Lab.close(); err != nil { log.Error().Err(err).Str("team", team.Username).Msg("Error closing lab for team") @@ -226,7 +232,11 @@ func (d *daemon) cancelLabConfigurationRequest(c *gin.Context) { } team.M.Lock() - defer team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 234") + defer func(team *Team) { + team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 237") + }(team) if team.Status == InQueue { team.Status = Idle @@ -393,10 +403,12 @@ func (d *daemon) resetVm(c *gin.Context) { } team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 405") team.Status = RunningVmCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 410") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) diff --git a/internal/daemon/eventWebsocket.go b/internal/daemon/eventWebsocket.go index 8a00a9c..d119086 100644 --- a/internal/daemon/eventWebsocket.go +++ b/internal/daemon/eventWebsocket.go @@ -64,17 +64,21 @@ func (d *daemon) eventWebsocket(c *gin.Context) { wsId := uuid.New().String() team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventWebsocket.go: 66") if team.ActiveWebsocketConnections == nil { team.ActiveWebsocketConnections = make(map[string]*websocket.Conn) } team.ActiveWebsocketConnections[wsId] = ws team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventWebsocket.go: 72") defer func(ws *websocket.Conn, team *Team, wsId string) { log.Debug().Msg("closing connection") team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventWebsocket.go: 77") delete(team.ActiveWebsocketConnections, wsId) team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventWebsocket.go: 81") ws.Close() }(ws, team, wsId) diff --git a/internal/daemon/eventpool.go b/internal/daemon/eventpool.go index 7b0bd44..b6cb321 100644 --- a/internal/daemon/eventpool.go +++ b/internal/daemon/eventpool.go @@ -164,8 +164,10 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l } log.Info().Msg("No more teams waiting for labs closing abunadant lab") event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventpool.go: 166") delete(event.Labs, lab.LabInfo.Tag) event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventpool.go: 169") saveState(eventPool, statePath) if err := lab.close(); err != nil { log.Error().Err(err).Msg("error closing lab no longer needed") @@ -178,11 +180,13 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l team := e.Value.(*Team) team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventpool.go: 182") lab.IsAssigned = true lab.ExpiresAtTime = time.Now().Add(labExpiry * time.Minute) team.Lab = lab team.Status = Idle team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventpool.go: 188") sendCommandToTeam(team, updateTeam) saveState(eventPool, statePath) @@ -210,8 +214,10 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l } log.Info().Msg("No more teams waiting for labs closing abunadant lab") event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventpool.go: 216") delete(event.Labs, lab.LabInfo.Tag) event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventpool.go: 219") saveState(eventPool, statePath) if err := lab.close(); err != nil { log.Error().Err(err).Msg("error closing lab no longer needed") @@ -225,11 +231,13 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l team := e.Value.(*Team) team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventpool.go: 233") lab.IsAssigned = true lab.ExpiresAtTime = time.Now().Add(labExpiry * time.Minute) team.Lab = lab team.Status = Idle team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventpool.go: 239") sendCommandToTeam(team, updateTeam) saveState(eventPool, statePath) From dcec7f6e5ad3396b6688e44bb7e457f007d5779c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Mon, 18 Nov 2024 22:35:37 +0100 Subject: [PATCH 2/7] Added a timeout to close lab --- internal/daemon/agentpool.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/internal/daemon/agentpool.go b/internal/daemon/agentpool.go index 4aae7cd..7d8dbe8 100644 --- a/internal/daemon/agentpool.go +++ b/internal/daemon/agentpool.go @@ -595,14 +595,15 @@ func (agentLab *AgentLab) updateLabInfo() { } func (agentLab *AgentLab) close() error { - ctx := context.Background() + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() if agentLab.Conn == nil { return errors.New("connection in agentLab is nil") } agentClient := aproto.NewAgentClient(agentLab.Conn) _, err := agentClient.CloseLab(ctx, &aproto.CloseLabRequest{LabTag: agentLab.LabInfo.Tag}) if err != nil { - log.Error().Err(err).Msg("error updating lab info") + log.Error().Err(err).Msg("error closing lab") return err } return nil From 51e8e783223f18824e14953f05d95e39a7830f28 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Mon, 18 Nov 2024 22:36:26 +0100 Subject: [PATCH 3/7] Tried to prevent deadlock by getting all events then iterating so the lock is only for getting the initial list of events --- internal/daemon/daemon.go | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/internal/daemon/daemon.go b/internal/daemon/daemon.go index af54db1..33b02fe 100644 --- a/internal/daemon/daemon.go +++ b/internal/daemon/daemon.go @@ -362,9 +362,8 @@ func (d *daemon) labExpiryRoutine() { log.Info().Msg("[lab-expiry-routine] starting routine") for { time.Sleep(1 * time.Second) - d.eventpool.M.RLock() - log.Debug().Msg("Read Lock on eventpool, daemon.go: 365") - for _, event := range d.eventpool.Events { + events := d.eventpool.GetAllEvents() + for _, event := range events { var wg sync.WaitGroup anyLabsClosed := false event.M.RLock() @@ -415,8 +414,6 @@ func (d *daemon) labExpiryRoutine() { broadCastCommandToEventTeams(event, updateEventInfo) } } - d.eventpool.M.RUnlock() - log.Debug().Msg("Read unlock on eventpool, daemon.go: 418") } } From 0fbcf137ceafaa1b8f94b867e096d74f2b4b1f62 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Wed, 20 Nov 2024 14:04:55 +0100 Subject: [PATCH 4/7] Running the close lab function in a go routine to prevent it blocking the mutex lock --- internal/daemon/eventLabs.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/internal/daemon/eventLabs.go b/internal/daemon/eventLabs.go index b0f780f..51061f9 100644 --- a/internal/daemon/eventLabs.go +++ b/internal/daemon/eventLabs.go @@ -204,9 +204,11 @@ func (d *daemon) closeLab(c *gin.Context) { event.M.Unlock() log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 204") if team.Lab.Conn != nil { - if err := team.Lab.close(); err != nil { - log.Error().Err(err).Str("team", team.Username).Msg("Error closing lab for team") - } + go func(team *Team) { + if err := team.Lab.close(); err != nil { + log.Error().Err(err).Str("team", team.Username).Msg("Error closing lab for team") + } + }(team) } team.Lab = nil sendCommandToTeam(team, updateTeam) From 36ae0456edd1969ecf13173412aa86cd4796754b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Wed, 20 Nov 2024 17:25:58 +0100 Subject: [PATCH 5/7] Yet another fix --- internal/daemon/eventLabs.go | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/internal/daemon/eventLabs.go b/internal/daemon/eventLabs.go index 51061f9..25949bf 100644 --- a/internal/daemon/eventLabs.go +++ b/internal/daemon/eventLabs.go @@ -183,11 +183,15 @@ func (d *daemon) closeLab(c *gin.Context) { return } + event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventLabs.go: 186") team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 186") + log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 188") defer func(team *Team) { team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 189") + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 191") + event.M.Unlock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 193") }(team) if team.Lab == nil { @@ -198,11 +202,8 @@ func (d *daemon) closeLab(c *gin.Context) { defer saveState(d.eventpool, d.conf.StatePath) - event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventLabs.go: 201") delete(event.Labs, team.Lab.LabInfo.Tag) - event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 204") + if team.Lab.Conn != nil { go func(team *Team) { if err := team.Lab.close(); err != nil { @@ -405,12 +406,12 @@ func (d *daemon) resetVm(c *gin.Context) { } team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 405") + log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 408") team.Status = RunningVmCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 410") + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 413") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) From 02770a4fe9eee501b5f46192129c4cade0216eb2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Wed, 20 Nov 2024 21:34:46 +0100 Subject: [PATCH 6/7] Realized it was probably caused by calling the mutex locks in the wrong order --- internal/daemon/eventLabs.go | 38 +++++++++++++++++------------------- 1 file changed, 18 insertions(+), 20 deletions(-) diff --git a/internal/daemon/eventLabs.go b/internal/daemon/eventLabs.go index 25949bf..a05e339 100644 --- a/internal/daemon/eventLabs.go +++ b/internal/daemon/eventLabs.go @@ -183,36 +183,34 @@ func (d *daemon) closeLab(c *gin.Context) { return } - event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventLabs.go: 186") - team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 188") - defer func(team *Team) { - team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 191") - event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 193") - }(team) - - if team.Lab == nil { + teamLab := team.GetLab() + if teamLab == nil { log.Debug().Str("team", team.Username).Msg("lab not found for team") c.JSON(http.StatusNotFound, APIResponse{Status: "lab not found"}) return } - defer saveState(d.eventpool, d.conf.StatePath) - - delete(event.Labs, team.Lab.LabInfo.Tag) - if team.Lab.Conn != nil { - go func(team *Team) { + go func(team *Team, event *Event) { + defer func() { + event.M.Lock() + log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventLabs.go: 195") + delete(event.Labs, team.Lab.LabInfo.Tag) + event.M.Unlock() + log.Debug().Str("eclearventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 198") + team.M.Lock() + log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 200") + team.Lab = nil + team.M.Unlock() + log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 203") + saveState(d.eventpool, d.conf.StatePath) + sendCommandToTeam(team, updateTeam) + }() if err := team.Lab.close(); err != nil { log.Error().Err(err).Str("team", team.Username).Msg("Error closing lab for team") } - }(team) + }(team, event) } - team.Lab = nil - sendCommandToTeam(team, updateTeam) c.JSON(http.StatusOK, APIResponse{Status: "OK"}) } From ae5303bc997db9ef42fb7c7daeb75cec90af0c96 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mikkel=20H=C3=B8st=20Christiansen?= Date: Mon, 25 Nov 2024 11:36:44 +0100 Subject: [PATCH 7/7] Removed mutex lock logs --- internal/daemon/adminAgents.go | 4 ---- internal/daemon/adminEvents.go | 4 ---- internal/daemon/agentpool.go | 8 -------- internal/daemon/daemon.go | 8 -------- internal/daemon/eventExercises.go | 6 ------ internal/daemon/eventLabs.go | 8 -------- internal/daemon/eventWebsocket.go | 4 ---- internal/daemon/eventpool.go | 8 -------- 8 files changed, 50 deletions(-) diff --git a/internal/daemon/adminAgents.go b/internal/daemon/adminAgents.go index 206e4d3..e972d66 100644 --- a/internal/daemon/adminAgents.go +++ b/internal/daemon/adminAgents.go @@ -384,10 +384,8 @@ func (d *daemon) reconnectAgent(c *gin.Context) { d.agentPool.addAgent(agentForPool) d.eventpool.M.RLock() - log.Debug().Msg("Read lock on eventpool, adminAgents.go: 386") for _, event := range d.eventpool.Events { event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, adminAgents.go: 389") for _, lab := range event.Labs { if lab.ParentAgent.Name == agentForPool.Name { @@ -395,10 +393,8 @@ func (d *daemon) reconnectAgent(c *gin.Context) { } } event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, adminAgents.go: 397") } d.eventpool.M.RUnlock() - log.Debug().Msg("Read unlock on eventpool, adminAgents.go: 400") c.JSON(http.StatusOK, APIResponse{Status: "OK"}) return diff --git a/internal/daemon/adminEvents.go b/internal/daemon/adminEvents.go index 239c304..6680551 100644 --- a/internal/daemon/adminEvents.go +++ b/internal/daemon/adminEvents.go @@ -339,12 +339,10 @@ func (d *daemon) getEvents(c *gin.Context) { event, err := d.eventpool.GetEvent(dbEvent.Tag) if err == nil { event.M.RLock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Read lock on event, adminEvents.go: 341") for _, lab := range event.Labs { labs = append(labs, lab) } event.M.RUnlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Read unlock on event, adminEvents.go: 346") } } @@ -395,12 +393,10 @@ func (d *daemon) getEvents(c *gin.Context) { event, err := d.eventpool.GetEvent(dbEvent.Tag) if err == nil { event.M.RLock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Read lock on event, adminEvents.go: 397") for _, lab := range event.Labs { labs = append(labs, lab) } event.M.RUnlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Read unlock on event, adminEvents.go: 402") } } diff --git a/internal/daemon/agentpool.go b/internal/daemon/agentpool.go index 7d8dbe8..05dade9 100644 --- a/internal/daemon/agentpool.go +++ b/internal/daemon/agentpool.go @@ -114,10 +114,8 @@ func (ap *AgentPool) connectToMonitoringStream(routineCtx context.Context, a *Ag } event.UnassignedVpnLabs <- agentLab event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, agentpool.go: 116") event.Labs[l.Tag] = agentLab event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, agentpool.go: 119") saveState(eventPool, statePath) continue } @@ -133,10 +131,8 @@ func (ap *AgentPool) connectToMonitoringStream(routineCtx context.Context, a *Ag } event.UnassignedBrowserLabs <- agentLab event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, agentpool.go: 135") event.Labs[l.Tag] = agentLab event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, agentpool.go: 138") saveState(eventPool, statePath) continue } @@ -733,10 +729,8 @@ func (d *daemon) agentReconnectionRoutine(ticker *time.Ticker) { d.agentPool.addAgent(agentForPool) d.eventpool.M.RLock() - log.Debug().Msg("Read Lock on eventpool, agentpool.go: 734") for _, event := range d.eventpool.Events { event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, agentpool.go: 737") for _, lab := range event.Labs { if lab.ParentAgent.Name == agentForPool.Name { @@ -744,10 +738,8 @@ func (d *daemon) agentReconnectionRoutine(ticker *time.Ticker) { } } event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, agentpool.go: 745") } d.eventpool.M.RUnlock() - log.Debug().Msg("Read Unlock on eventpool, agentpool.go: 748") } } } diff --git a/internal/daemon/daemon.go b/internal/daemon/daemon.go index 33b02fe..970d192 100644 --- a/internal/daemon/daemon.go +++ b/internal/daemon/daemon.go @@ -367,10 +367,8 @@ func (d *daemon) labExpiryRoutine() { var wg sync.WaitGroup anyLabsClosed := false event.M.RLock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Read Lock on event, daemon.go: 370") for _, team := range event.Teams { team.M.RLock() - log.Debug().Str("team", team.Username).Msg("Read Lock on team, daemon.go: 373") if team.Lab != nil { if time.Now().After(team.Lab.ExpiresAtTime) { if team.Lab.Conn != nil { @@ -380,15 +378,11 @@ func (d *daemon) labExpiryRoutine() { defer wg.Done() defer func() { event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, daemon.go: 383") delete(event.Labs, team.Lab.LabInfo.Tag) event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, daemon.go: 386") team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, daemon.go: 388") team.Lab = nil team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, daemon.go: 391") saveState(d.eventpool, d.conf.StatePath) sendCommandToTeam(team, updateTeam) }() @@ -405,10 +399,8 @@ func (d *daemon) labExpiryRoutine() { } } team.M.RUnlock() - log.Debug().Str("team", team.Username).Msg("Read unlock on team, daemon.go: 408") } event.M.RUnlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Read unlock on event, daemon.go: 411") wg.Wait() if anyLabsClosed { broadCastCommandToEventTeams(event, updateEventInfo) diff --git a/internal/daemon/eventExercises.go b/internal/daemon/eventExercises.go index d5709a2..3801d82 100644 --- a/internal/daemon/eventExercises.go +++ b/internal/daemon/eventExercises.go @@ -363,12 +363,10 @@ func (d *daemon) startExerciseInLab(c *gin.Context) { return } team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventExercises.go: 365") team.Status = RunningExerciseCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventExercises.go: 370") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) @@ -505,12 +503,10 @@ func (d *daemon) stopExercise(c *gin.Context) { return } team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventExercises.go: 507") team.Status = RunningExerciseCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventExercises.go: 512") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) @@ -565,12 +561,10 @@ func (d *daemon) resetExercise(c *gin.Context) { return } team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventExercises.go: 567") team.Status = RunningExerciseCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventExercises.go: 572") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) diff --git a/internal/daemon/eventLabs.go b/internal/daemon/eventLabs.go index a05e339..b2de075 100644 --- a/internal/daemon/eventLabs.go +++ b/internal/daemon/eventLabs.go @@ -194,15 +194,11 @@ func (d *daemon) closeLab(c *gin.Context) { go func(team *Team, event *Event) { defer func() { event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventLabs.go: 195") delete(event.Labs, team.Lab.LabInfo.Tag) event.M.Unlock() - log.Debug().Str("eclearventTag", event.Config.Tag).Msg("Unlock on event, eventLabs.go: 198") team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 200") team.Lab = nil team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 203") saveState(d.eventpool, d.conf.StatePath) sendCommandToTeam(team, updateTeam) }() @@ -233,10 +229,8 @@ func (d *daemon) cancelLabConfigurationRequest(c *gin.Context) { } team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 234") defer func(team *Team) { team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 237") }(team) if team.Status == InQueue { @@ -404,12 +398,10 @@ func (d *daemon) resetVm(c *gin.Context) { } team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventLabs.go: 408") team.Status = RunningVmCommand defer func(team *Team) { team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventLabs.go: 413") sendCommandToTeam(team, updateTeam) }(team) sendCommandToTeam(team, updateTeam) diff --git a/internal/daemon/eventWebsocket.go b/internal/daemon/eventWebsocket.go index d119086..8a00a9c 100644 --- a/internal/daemon/eventWebsocket.go +++ b/internal/daemon/eventWebsocket.go @@ -64,21 +64,17 @@ func (d *daemon) eventWebsocket(c *gin.Context) { wsId := uuid.New().String() team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventWebsocket.go: 66") if team.ActiveWebsocketConnections == nil { team.ActiveWebsocketConnections = make(map[string]*websocket.Conn) } team.ActiveWebsocketConnections[wsId] = ws team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventWebsocket.go: 72") defer func(ws *websocket.Conn, team *Team, wsId string) { log.Debug().Msg("closing connection") team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventWebsocket.go: 77") delete(team.ActiveWebsocketConnections, wsId) team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventWebsocket.go: 81") ws.Close() }(ws, team, wsId) diff --git a/internal/daemon/eventpool.go b/internal/daemon/eventpool.go index b6cb321..7b0bd44 100644 --- a/internal/daemon/eventpool.go +++ b/internal/daemon/eventpool.go @@ -164,10 +164,8 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l } log.Info().Msg("No more teams waiting for labs closing abunadant lab") event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventpool.go: 166") delete(event.Labs, lab.LabInfo.Tag) event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventpool.go: 169") saveState(eventPool, statePath) if err := lab.close(); err != nil { log.Error().Err(err).Msg("error closing lab no longer needed") @@ -180,13 +178,11 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l team := e.Value.(*Team) team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventpool.go: 182") lab.IsAssigned = true lab.ExpiresAtTime = time.Now().Add(labExpiry * time.Minute) team.Lab = lab team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventpool.go: 188") sendCommandToTeam(team, updateTeam) saveState(eventPool, statePath) @@ -214,10 +210,8 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l } log.Info().Msg("No more teams waiting for labs closing abunadant lab") event.M.Lock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Lock on event, eventpool.go: 216") delete(event.Labs, lab.LabInfo.Tag) event.M.Unlock() - log.Debug().Str("eventTag", event.Config.Tag).Msg("Unlock on event, eventpool.go: 219") saveState(eventPool, statePath) if err := lab.close(); err != nil { log.Error().Err(err).Msg("error closing lab no longer needed") @@ -231,13 +225,11 @@ func (event *Event) startQueueHandlers(eventPool *EventPool, statePath string, l team := e.Value.(*Team) team.M.Lock() - log.Debug().Str("team", team.Username).Msg("Lock on team, eventpool.go: 233") lab.IsAssigned = true lab.ExpiresAtTime = time.Now().Add(labExpiry * time.Minute) team.Lab = lab team.Status = Idle team.M.Unlock() - log.Debug().Str("team", team.Username).Msg("Unlock on team, eventpool.go: 239") sendCommandToTeam(team, updateTeam) saveState(eventPool, statePath)