diff --git a/irc.go b/irc.go index 8d11e55..a745761 100644 --- a/irc.go +++ b/irc.go @@ -21,6 +21,7 @@ package irc import ( "bufio" "bytes" + "context" "crypto/tls" "errors" "fmt" @@ -79,6 +80,10 @@ func (irc *Connection) readLoop() { irc.lastMessageMutex.Unlock() event, err := parseToEvent(msg) event.Connection = irc + event.Ctx = context.Background() + if irc.CallbackTimeout != 0 { + event.Ctx, _ = context.WithTimeout(event.Ctx, irc.CallbackTimeout) + } if err == nil { /* XXX: len(args) == 0: args should be empty */ irc.RunCallbacks(event) diff --git a/irc_callback.go b/irc_callback.go index bf361e2..4a337ca 100644 --- a/irc_callback.go +++ b/irc_callback.go @@ -1,6 +1,9 @@ package irc import ( + "fmt" + "reflect" + "runtime" "strconv" "strings" "time" @@ -127,32 +130,61 @@ func (irc *Connection) RunCallbacks(event *Event) { } irc.eventsMutex.Lock() - callbacks, ok := irc.events[event.Code] - irc.eventsMutex.Unlock() + callbacks := []func(*Event){} + eventCallbacks, ok := irc.events[event.Code] if ok { - if irc.VerboseCallbackHandler { - irc.Log.Printf("%v (%v) >> %#v\n", event.Code, len(callbacks), event) - } - - for _, callback := range callbacks { - callback(event) - } - } else if irc.VerboseCallbackHandler { - irc.Log.Printf("%v (0) >> %#v\n", event.Code, event) - } - - irc.eventsMutex.Lock() - allcallbacks, ok := irc.events["*"] - irc.eventsMutex.Unlock() - if ok { - if irc.VerboseCallbackHandler { - irc.Log.Printf("%v (0) >> %#v\n", event.Code, event) - } - - for _, callback := range allcallbacks { - callback(event) + for _, callback := range eventCallbacks { + callbacks = append(callbacks, callback) } } + allCallbacks, ok := irc.events["*"] + if ok { + for _, callback := range allCallbacks { + callbacks = append(callbacks, callback) + } + } + irc.eventsMutex.Unlock() + + if irc.VerboseCallbackHandler { + irc.Log.Printf("%v (%v) >> %#v\n", event.Code, len(callbacks), event) + } + + done := make(chan bool) + possibleLogs := []string{} + for i, callback := range callbacks { + go func(done chan bool) { + callback(event) + done <- true + }(done) + callbackName := getFunctionName(callback) + start := time.Now() + select { + case <-event.Ctx.Done(): // context timed out! + irc.Log.Printf("TIMEOUT: %s timeout expired while executing %s, abandoning remaining callbacks", irc.CallbackTimeout, callbackName) + + // If we timed out let's include context for how long each previous handler took + for _, logItem := range possibleLogs { + irc.Log.Println(logItem) + } + irc.Log.Printf("Callback %s ran for %s prior to timeout", callbackName, time.Since(start)) + if len(callbacks) > i { + for _, callback := range callbacks[i+1:] { + irc.Log.Printf("Callback %s did not run", getFunctionName(callback)) + } + } + + // At this point our context has expired and it's not safe to execute anything else, lets bail. + return + case <-done: + elapsed := time.Since(start) + logMsg := fmt.Sprintf("Callback %s took %s", getFunctionName(callback), elapsed) + possibleLogs = append(possibleLogs, logMsg) + } + } +} + +func getFunctionName(f func(*Event)) string { + return runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name() } // Set up some initial callbacks to handle the IRC/CTCP protocol. diff --git a/irc_struct.go b/irc_struct.go index 6cf44ca..e988745 100644 --- a/irc_struct.go +++ b/irc_struct.go @@ -5,6 +5,7 @@ package irc import ( + "context" "crypto/tls" "log" "net" @@ -30,6 +31,7 @@ type Connection struct { TLSConfig *tls.Config Version string Timeout time.Duration + CallbackTimeout time.Duration PingFreq time.Duration KeepAlive time.Duration Server string @@ -70,6 +72,7 @@ type Event struct { Arguments []string Tags map[string]string Connection *Connection + Ctx context.Context } // Retrieve the last message from Event arguments.