From f7380fc295f1ede992d19c2aefb833308e7a2aec Mon Sep 17 00:00:00 2001 From: Martin Mahner Date: Mon, 14 Apr 2014 13:50:32 -0400 Subject: [PATCH 01/76] Endpoint cleanup. --- common/queue.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/common/queue.go b/common/queue.go index 736cb07..2f2fc0b 100644 --- a/common/queue.go +++ b/common/queue.go @@ -86,9 +86,9 @@ type RedisQueue struct { } func NewRedisQueue() Queue { - redisUrlString := os.Getenv("QUEUE_URL") + redisUrlString := os.Getenv("REDIS_PLUGIN_QUEUE_URL") if redisUrlString == "" { - glog.Fatal("QUEUE_URL cannot be empty.\nexport QUEUE_URL=redis://host:port/db_number") + glog.Fatal("REDIS_PLUGIN_QUEUE_URL cannot be empty.\nexport REDIS_PLUGIN_QUEUE_URL=redis://host:port/db_number") } redisUrl, err := url.Parse(redisUrlString) if err != nil { From aee04067477b70ea333eb74001482d39bbe40a14 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 15 Apr 2014 19:30:49 +0200 Subject: [PATCH 02/76] Adding some more logging to follow the restarting process --- botbot.go | 3 +++ network/irc/irc.go | 3 +++ 2 files changed, 6 insertions(+) diff --git a/botbot.go b/botbot.go index 93c8c15..f9a92bf 100644 --- a/botbot.go +++ b/botbot.go @@ -120,6 +120,9 @@ func (self *BotBot) mainLoop() { // - WRITE : Send message to server // - REFRESH: Reload plugin configuration func (self *BotBot) handleCommand(cmd string, args string) { + if glog.V(2) { + glog.Infoln("HandleCommand:", cmd) + } switch cmd { case "WRITE": parts := strings.SplitN(args, " ", 3) diff --git a/network/irc/irc.go b/network/irc/irc.go index 60552a9..eb350c8 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -275,6 +275,9 @@ func (self *ircBot) updateNick(newNick, newPass string) { func (self *ircBot) updateChannels(newChannels []string) { if isEqual(newChannels, self.channels) { + if glog.V(2) { + glog.Infoln("Channels comparison is equals for bot: ", self.nick) + } return } From 7a7bfec8c488b2105524330a42160437831f9e34 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 15 Apr 2014 20:34:24 +0200 Subject: [PATCH 03/76] Fixing a race condition between redis and postgres when we try to REFRESH --- network/network.go | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/network/network.go b/network/network.go index 0332769..867fe70 100644 --- a/network/network.go +++ b/network/network.go @@ -37,6 +37,14 @@ func (self *NetworkManager) GetUserByChatbotId(id int) string { // Connect to networks / start chatbots. Loads chatbot configuration from DB. func (self *NetworkManager) RefreshChatbots() { + if glog.V(2) { + glog.Infoln("Entering in NetworkManager.RefreshChatbots") + } + + // Sleeping before refreshing chatbots to make sure that the change made + // made it into postgres. This illustrate the fact that redis is faster + // than postgres + time.Sleep(1 * time.Second) botConfigs := self.storage.BotConfig() @@ -52,9 +60,15 @@ func (self *NetworkManager) RefreshChatbots() { current = self.chatbots[id] if current == nil { // Create + if glog.V(2) { + glog.Infoln("Connect the bot with the following config:", config) + } self.chatbots[id] = self.Connect(config) } else { // Update + if glog.V(2) { + glog.Infoln("Update the bot with the following config:", config) + } self.chatbots[id].Update(config) } @@ -74,6 +88,10 @@ func (self *NetworkManager) RefreshChatbots() { delete(self.chatbots, currId) } } + if glog.V(2) { + glog.Infoln("Exiting NetworkManager.RefreshChatbots") + } + } func (self *NetworkManager) Connect(config *common.BotConfig) common.ChatBot { From ba447d8f3f088a5735a205691896c013e5568f58 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 16 Apr 2014 17:30:55 +0200 Subject: [PATCH 04/76] A more graceful channel update --- common/common.go | 21 ++++++++++----- common/storage.go | 15 ++++++----- network/irc/irc.go | 59 ++++++++++++++++++++++++++--------------- network/irc/irc_test.go | 19 ++++++++----- 4 files changed, 74 insertions(+), 40 deletions(-) diff --git a/common/common.go b/common/common.go index f69d08d..8d30467 100644 --- a/common/common.go +++ b/common/common.go @@ -2,6 +2,7 @@ package common import ( "io" + "strings" ) // Interface all bots must implement @@ -15,11 +16,19 @@ type ChatBot interface { // Configuration for a 'chatbot', which is what clients pay for type BotConfig struct { - Id int - Config map[string]string + Id int + Config map[string]string + Channels []*Channel +} + +// Configuration for a channel +type Channel struct { + Id int + Name string + Pwd string + Fingerprint string +} - // Normally this array is names of the channels to join - // but if the channel has a password, the string is " " - // That means we can pass the string straight to JOIN and it works - Channels []string +func (cc *Channel) Credential() string { + return strings.TrimSpace(cc.Name + " " + cc.Pwd) } diff --git a/common/storage.go b/common/storage.go index 19ea13f..6499aaa 100644 --- a/common/storage.go +++ b/common/storage.go @@ -30,8 +30,8 @@ func NewMockStorage(serverPort string) Storage { "nick": "test", "password": "testxyz", "server": "127.0.0.1:" + serverPort} - channels := make([]string, 0) - channels = append(channels, "#unit") + channels := make([]*Channel, 0) + channels = append(channels, &Channel{Id: 1, Name: "#unit", Fingerprint: "5876HKJGYUT"}) botConf := &BotConfig{Id: 1, Config: conf, Channels: channels} return &MockStorage{botConfs: []*BotConfig{botConf}} @@ -104,23 +104,26 @@ func (self *PostgresStorage) BotConfig() []*BotConfig { config := &BotConfig{ Id: chatbotId, Config: confMap, - Channels: make([]string, 0), + Channels: make([]*Channel, 0), } configs = append(configs, config) } for i := range configs { config := configs[i] - rows, err = self.db.Query("SELECT id, name, password FROM bots_channel WHERE is_active=true and chatbot_id=$1", config.Id) + rows, err = self.db.Query("SELECT id, name, password, fingerprint FROM bots_channel WHERE is_active=true and chatbot_id=$1", config.Id) if err != nil { glog.Fatal("Error running:", err) } var channelId int var channelName string var channelPwd string + var channelFingerprint string for rows.Next() { - rows.Scan(&channelId, &channelName, &channelPwd) - config.Channels = append(config.Channels, channelName+" "+channelPwd) + rows.Scan(&channelId, &channelName, &channelPwd, &channelFingerprint) + config.Channels = append(config.Channels, + &Channel{Id: channelId, Name: channelName, + Pwd: channelPwd, Fingerprint: channelFingerprint}) } glog.Infoln("config.Channel:", config.Channels) } diff --git a/network/irc/irc.go b/network/irc/irc.go index eb350c8..0b872a6 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -10,7 +10,6 @@ package irc import ( "bufio" - "bytes" "crypto/tls" "crypto/x509" "io" @@ -40,7 +39,7 @@ type ircBot struct { password string serverPass string fromServer chan *line.Line - channels []string + channels []*common.Channel isRunning bool isConnecting bool isAuthenticating bool @@ -227,7 +226,7 @@ func isIPMatch(hostname string, connIP string) bool { // Update bot configuration. Called when webapp changes a chatbot's config. func (self *ircBot) Update(config *common.BotConfig) { - isNewServer := self.updateServer(config.Config) + isNewServer := self.updateServer(config) if isNewServer { // If the server changed, we've already done nick and channel changes too return @@ -238,9 +237,9 @@ func (self *ircBot) Update(config *common.BotConfig) { } // Update the IRC server we're connected to -func (self *ircBot) updateServer(config map[string]string) bool { +func (self *ircBot) updateServer(config *common.BotConfig) bool { - addr := config["server"] + addr := config.Config["server"] if addr == self.address { return false } @@ -251,9 +250,9 @@ func (self *ircBot) updateServer(config map[string]string) bool { time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped self.address = addr - self.nick = config["nick"] - self.password = config["password"] - self.channels = splitChannels(config["rooms"]) + self.nick = config.Config["nick"] + self.password = config.Config["password"] + self.channels = config.Channels self.init() @@ -272,8 +271,7 @@ func (self *ircBot) updateNick(newNick, newPass string) { } // Update the channels based on new configuration, leaving old ones and joining new ones -func (self *ircBot) updateChannels(newChannels []string) { - +func (self *ircBot) updateChannels(newChannels []*common.Channel) { if isEqual(newChannels, self.channels) { if glog.V(2) { glog.Infoln("Channels comparison is equals for bot: ", self.nick) @@ -284,14 +282,14 @@ func (self *ircBot) updateChannels(newChannels []string) { // PART old ones for _, channel := range self.channels { if !isIn(channel, newChannels) { - self.part(channel) + self.part(channel.Credential()) } } // JOIN new ones for _, channel := range newChannels { if !isIn(channel, self.channels) { - self.join(channel) + self.join(channel.Credential()) } } @@ -301,7 +299,7 @@ func (self *ircBot) updateChannels(newChannels []string) { // Join channels func (self *ircBot) JoinAll() { for _, channel := range self.channels { - self.join(channel) + self.join(channel.Credential()) } } @@ -507,7 +505,7 @@ func (self *ircBot) sendShutdown() { Content: ""} for _, channel := range self.channels { - shutLine.Channel = channel + shutLine.Channel = channel.Credential() self.fromServer <- shutLine } } @@ -671,14 +669,33 @@ func toUnicode(data []byte) string { } // Are a and b equal? -func isEqual(a, b []string) bool { - ja := strings.Join(a, ",") - jb := strings.Join(b, ",") - return bytes.Equal([]byte(ja), []byte(jb)) +func isEqual(a, b []*common.Channel) (flag bool) { + for _, a_cc := range a { + flag = false + for _, b_cc := range b { + if a_cc.Fingerprint == b_cc.Fingerprint { + flag = true + break + } + } + if flag == false { + return flag + } + } + return true } // Is a in b? container must be sorted -func isIn(a string, container []string) bool { - index := sort.SearchStrings(container, a) - return index < len(container) && container[index] == a +func isIn(a *common.Channel, container []*common.Channel) (flag bool) { + flag = false + for _, c_cc := range container { + if a.Fingerprint == c_cc.Fingerprint { + flag = true + break + } + } + if flag == false { + return flag + } + return true } diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index c163a80..0adbad7 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -10,8 +10,8 @@ import ( "github.com/BotBotMe/botbot-bot/line" ) -const ( - NEW_CHANNEL = "#unitnew" +var ( + NEW_CHANNEL = common.Channel{Name: "#unitnew", Fingerprint: "new-channel-uuid"} ) func TestParseLine_welcome(t *testing.T) { @@ -174,6 +174,8 @@ func TestFlood(t *testing.T) { fromServer := make(chan *line.Line) receivedCounter := make(chan bool) mockSocket := MockSocket{counter: receivedCounter} + channels := make([]*common.Channel, 1) + channels = append(channels, &common.Channel{Name: "test", Fingerprint: "uuid-string"}) chatbot := &ircBot{ id: 99, @@ -182,7 +184,7 @@ func TestFlood(t *testing.T) { realname: "Unit Test", password: "test", fromServer: fromServer, - channels: []string{"test"}, + channels: channels, socket: &mockSocket, isRunning: true, } @@ -215,6 +217,9 @@ func TestUpdate(t *testing.T) { fromServer := make(chan *line.Line) mockSocket := MockSocket{counter: nil} + channels := make([]*common.Channel, 0, 2) + channel := common.Channel{Name: "#test", Fingerprint: "uuid-string"} + channels = append(channels, &channel) chatbot := &ircBot{ id: 99, @@ -223,7 +228,7 @@ func TestUpdate(t *testing.T) { realname: "Unit Test", password: "test", fromServer: fromServer, - channels: []string{"#test"}, + channels: channels, socket: &mockSocket, sendQueue: make(chan []byte, 100), isRunning: true, @@ -233,7 +238,7 @@ func TestUpdate(t *testing.T) { conf := map[string]string{ "nick": "test", "password": "testxyz", "server": "localhost"} - channels := []string{"#test", NEW_CHANNEL} + channels = append(channels, &NEW_CHANNEL) newConfig := &common.BotConfig{Id: 1, Config: conf, Channels: channels} chatbot.Update(newConfig) @@ -252,7 +257,7 @@ func TestUpdate(t *testing.T) { cmd = strings.TrimSpace(cmd) - if cmd == "JOIN "+NEW_CHANNEL { + if cmd == "JOIN "+NEW_CHANNEL.Credential() { isFound = true break } @@ -263,7 +268,7 @@ func TestUpdate(t *testing.T) { } if !isFound { - t.Error("Expected JOIN " + NEW_CHANNEL) + t.Error("Expected JOIN " + NEW_CHANNEL.Credential()) } } From 72deaddb849292b1a9f3962d94aae3a149418871 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 16 Apr 2014 18:41:47 +0200 Subject: [PATCH 05/76] Move the sleep to avoid the race condition from botbot-bot to botbot-web --- network/network.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/network/network.go b/network/network.go index 867fe70..6887f20 100644 --- a/network/network.go +++ b/network/network.go @@ -41,11 +41,6 @@ func (self *NetworkManager) RefreshChatbots() { glog.Infoln("Entering in NetworkManager.RefreshChatbots") } - // Sleeping before refreshing chatbots to make sure that the change made - // made it into postgres. This illustrate the fact that redis is faster - // than postgres - time.Sleep(1 * time.Second) - botConfigs := self.storage.BotConfig() var current common.ChatBot From c31b3537a6ad89d4da6f062af3b0cfb0ad41d796 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 16 Apr 2014 21:23:12 +0200 Subject: [PATCH 06/76] golint --- network/network.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/network/network.go b/network/network.go index 6887f20..7735174 100644 --- a/network/network.go +++ b/network/network.go @@ -40,7 +40,6 @@ func (self *NetworkManager) RefreshChatbots() { if glog.V(2) { glog.Infoln("Entering in NetworkManager.RefreshChatbots") } - botConfigs := self.storage.BotConfig() var current common.ChatBot @@ -74,7 +73,7 @@ func (self *NetworkManager) RefreshChatbots() { active.Sort() numActive := len(active) - for currId, _ := range self.chatbots { + for currId := range self.chatbots { if active.Search(currId) == numActive { // if currId not in active: glog.Infoln("Stopping chatbot: ", currId) From 1085310e4decfb4e75407b8b178cbcb3d1a8cf58 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 22 Apr 2014 00:28:30 +0200 Subject: [PATCH 07/76] swap the posgresql driver to a better maintain repo. Set the application_name to bot instead of empty string. --- common/storage.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/common/storage.go b/common/storage.go index 6499aaa..ca45bd1 100644 --- a/common/storage.go +++ b/common/storage.go @@ -5,8 +5,8 @@ import ( "os" "time" - "github.com/bmizerany/pq" "github.com/golang/glog" + "github.com/lib/pq" ) // Storage. Wraps the database @@ -66,7 +66,7 @@ func NewPostgresStorage() *PostgresStorage { if err != nil { glog.Fatal("Could not read database string", err) } - db, err := sql.Open("postgres", dataSource+" sslmode=disable") + db, err := sql.Open("postgres", dataSource+" sslmode=disable fallback_application_name=bot") if err != nil { glog.Fatal("Could not connect to database.", err) } From 9cecd760e32498fe4e8f3f7eeb581bca0e609c02 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 22 Apr 2014 02:11:10 +0200 Subject: [PATCH 08/76] Explicitely setting a MaxOpenConns and MaxIdleConns for the postgesql driver --- common/storage.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/common/storage.go b/common/storage.go index ca45bd1..98a1180 100644 --- a/common/storage.go +++ b/common/storage.go @@ -71,6 +71,12 @@ func NewPostgresStorage() *PostgresStorage { glog.Fatal("Could not connect to database.", err) } + // The following 2 lines mitigate the leak of postgresql connection leak + // explicitly setting a maximum number of postgresql connections + db.SetMaxOpenConns(5) + // explicitly setting a maximum number of Idle postgresql connections + db.SetMaxIdleConns(2) + return &PostgresStorage{db} } From e6386730d850f18b214da61eb6768ab37224bf43 Mon Sep 17 00:00:00 2001 From: Martin Mahner Date: Tue, 22 Apr 2014 15:07:57 +0200 Subject: [PATCH 09/76] Use redisDB number too. --- common/queue.go | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/common/queue.go b/common/queue.go index 2f2fc0b..feee8b6 100644 --- a/common/queue.go +++ b/common/queue.go @@ -5,6 +5,8 @@ import ( "net/url" "os" "time" + "strconv" + "strings" "github.com/golang/glog" "github.com/monnand/goredis" @@ -94,7 +96,13 @@ func NewRedisQueue() Queue { if err != nil { glog.Fatal("Could not read Redis string", err) } - redisQueue := goredis.Client{Addr: redisUrl.Host} + + redisDb, err := strconv.Atoi(strings.TrimLeft(redisUrl.Path, "/")) + if err != nil { + glog.Fatal("Could not read Redis path", err) + } + + redisQueue := goredis.Client{Addr: redisUrl.Host, Db: redisDb} s := RedisQueue{queue: &redisQueue} s.waitForRedis() return &s From c7e33dd27ba28c1290b782245c08f96ac36a24a2 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 23 Apr 2014 14:29:33 +0200 Subject: [PATCH 10/76] Build go against 1.2 and tip since we are now using some of the newer feature. --- .travis.yml | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.travis.yml b/.travis.yml index 89ae482..7c37c5b 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,7 +1,8 @@ language: go go: - - 1.1 + - 1.2 + - tip install: - go get github.com/BotBotMe/botbot-bot From 1bb0ea148f0e0f97730fb259b4a0fffeffdd3b56 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Fri, 16 May 2014 16:00:29 +0200 Subject: [PATCH 11/76] Reduce the time between ping from 5 min to 10s. Try to reconnect after 30s without messages from the server. --- common/common.go | 4 ++++ network/irc/irc.go | 17 +++++++++-------- network/network.go | 2 +- 3 files changed, 14 insertions(+), 9 deletions(-) diff --git a/common/common.go b/common/common.go index 8d30467..478218e 100644 --- a/common/common.go +++ b/common/common.go @@ -32,3 +32,7 @@ type Channel struct { func (cc *Channel) Credential() string { return strings.TrimSpace(cc.Name + " " + cc.Pwd) } + +func (cc *Channel) String() string { + return cc.Name +} diff --git a/network/irc/irc.go b/network/irc/irc.go index 0b872a6..cb979ef 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -44,7 +44,7 @@ type ircBot struct { isConnecting bool isAuthenticating bool sendQueue chan []byte - monitorChan chan string + monitorChan chan struct{} } func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot { @@ -64,7 +64,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot serverPass: config.Config["server_password"], // PASS password fromServer: fromServer, channels: config.Channels, - monitorChan: make(chan string), + monitorChan: make(chan struct{}), isRunning: true, } @@ -82,7 +82,7 @@ func (self *ircBot) monitor() { for self.isRunning { select { case <-self.monitorChan: - case <-time.After(time.Minute * 10): + case <-time.After(time.Second * 30): glog.Infoln("IRC monitoring KO ; Trying to reconnect.") self.Close() self.Connect() @@ -90,11 +90,11 @@ func (self *ircBot) monitor() { } } -// Ping the server every 5 min to keep the connection open +// Ping the server every 10 sec to keep the connection open func (self *ircBot) pinger() { i := 0 for self.isRunning { - <-time.After(time.Minute * 5) + <-time.After(time.Second * 10) i = i + 1 self.SendRaw("PING " + strconv.Itoa(i)) } @@ -130,7 +130,8 @@ func (self *ircBot) init() { self.SendRaw("PING Bonjour") } -// Connect to the server +// Connect to the server. Here we keep trying every 10 seconds until we manage +// to Dial to the server. func (self *ircBot) Connect() { if self.socket != nil { @@ -172,7 +173,7 @@ func (self *ircBot) Connect() { } glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err) - time.Sleep(1 * time.Second) + time.Sleep(10 * time.Second) } self.socket = socket @@ -426,7 +427,7 @@ func (self *ircBot) listen() { func (self *ircBot) act(theLine *line.Line) { // Send the command on the monitorChan - self.monitorChan <- theLine.Command + self.monitorChan <- struct{}{} // As soon as we receive a message from the server, complete initiatization if self.isConnecting { diff --git a/network/network.go b/network/network.go index 7735174..4e03445 100644 --- a/network/network.go +++ b/network/network.go @@ -90,7 +90,7 @@ func (self *NetworkManager) RefreshChatbots() { func (self *NetworkManager) Connect(config *common.BotConfig) common.ChatBot { - glog.Infoln("Creating chatbot: %+v\n", config) + glog.Infoln("Creating chatbot,", config) return irc.NewBot(config, self.fromServer) } From 1e752dd3af54c2c4301845d05d14ccc417022086 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 18 May 2014 12:11:49 +0200 Subject: [PATCH 12/76] ref #15. re architecture the ircBot.monitor() to reconnect if there is long period (15 min) of inactivity. --- network/irc/irc.go | 333 ++++++++++++++++++++++++++------------------- network/network.go | 2 +- 2 files changed, 192 insertions(+), 143 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index cb979ef..c95d454 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -12,11 +12,13 @@ import ( "bufio" "crypto/tls" "crypto/x509" + "fmt" "io" "net" "sort" "strconv" "strings" + "sync" "time" "unicode/utf8" @@ -31,6 +33,7 @@ const ( ) type ircBot struct { + sync.Mutex id int address string socket io.ReadWriteCloser @@ -45,6 +48,8 @@ type ircBot struct { isAuthenticating bool sendQueue chan []byte monitorChan chan struct{} + pingResponse chan struct{} + reconnectChan chan struct{} } func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot { @@ -56,85 +61,120 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot } chatbot := &ircBot{ - id: config.Id, - address: config.Config["server"], - nick: config.Config["nick"], - realname: realname, - password: config.Config["password"], // NickServ password - serverPass: config.Config["server_password"], // PASS password - fromServer: fromServer, - channels: config.Channels, - monitorChan: make(chan struct{}), - isRunning: true, - } - - chatbot.init() + id: config.Id, + address: config.Config["server"], + nick: config.Config["nick"], + realname: realname, + password: config.Config["password"], // NickServ password + serverPass: config.Config["server_password"], // PASS password + fromServer: fromServer, + channels: config.Channels, + monitorChan: make(chan struct{}), + pingResponse: make(chan struct{}), + reconnectChan: make(chan struct{}), + isRunning: true, + } + + chatbot.Init() return chatbot } -func (self *ircBot) GetUser() string { - return self.nick + +func (bot *ircBot) GetUser() string { + return bot.nick +} + +func (bot *ircBot) String() string { + return fmt.Sprintf("%s on %s", bot.nick, bot.address) } // Monitor that we are still connected to the IRC server // should run in go-routine -func (self *ircBot) monitor() { - for self.isRunning { +// If no message is received during 60 actively ping ircBot. +// If ircBot does not reply try to reconnect +// If ircBot replied 15 (maxPongWithoutMessage) but we are still not getting +// messages there is probably something wrong so we are going to try to +// reconnect. +func (bot *ircBot) monitor() { + // TODO maxPongWithoutMessage should probably be a field of ircBot + maxPongWithoutMessage := 15 + pongCounter := 0 + for bot.IsRunning() { + if pongCounter > maxPongWithoutMessage { + glog.Infoln("More than maxPongWithoutMessage pong without message.") + bot.reconnect() + } select { - case <-self.monitorChan: - case <-time.After(time.Second * 30): - glog.Infoln("IRC monitoring KO ; Trying to reconnect.") - self.Close() - self.Connect() + case <-bot.monitorChan: + pongCounter = 0 + if glog.V(2) { + glog.Infoln("Message received from the server") + } + case <-time.After(time.Second * 60): + glog.Infoln("Ping the ircBot server", bot) + bot.ping() + select { + case <-bot.pingResponse: + pongCounter += 1 + if glog.V(2) { + glog.Infoln("Pong from ircBot server", bot) + } + case <-time.After(time.Second * 10): + glog.Infoln("No pong from ircBot server", bot) + glog.Infoln("IRC monitoring KO.") + bot.reconnect() + } } } } -// Ping the server every 10 sec to keep the connection open -func (self *ircBot) pinger() { - i := 0 - for self.isRunning { - <-time.After(time.Second * 10) - i = i + 1 - self.SendRaw("PING " + strconv.Itoa(i)) - } +// reconnect the ircBot +func (bot *ircBot) reconnect() { + glog.Infoln("Trying to reconnect.") + bot.Close() + time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped + bot.Init() + +} + +// Ping the server to the connection open +func (bot *ircBot) ping() { + // TODO increment number + bot.SendRaw("PING 1") } // Connect to the IRC server and start listener -func (self *ircBot) init() { +func (bot *ircBot) Init() { - self.isConnecting = true - self.isAuthenticating = false + bot.isConnecting = true + bot.isAuthenticating = false - self.Connect() + bot.Connect() // Listen for incoming messages in background thread - go self.listen() + go bot.listen() // Monitor that we are still getting incoming messages in a background thread - go self.monitor() - - // Pinger that Ping the server every 5 min - go self.pinger() + go bot.monitor() // Listen for outgoing messages (rate limited) in background thread - if self.sendQueue == nil { - self.sendQueue = make(chan []byte, 256) + if bot.sendQueue == nil { + bot.sendQueue = make(chan []byte, 256) } - go self.sender() + go bot.sender() - if self.serverPass != "" { - self.SendRaw("PASS " + self.serverPass) + if bot.serverPass != "" { + bot.SendRaw("PASS " + bot.serverPass) } - self.SendRaw("PING Bonjour") + bot.SendRaw("PING Bonjour") } // Connect to the server. Here we keep trying every 10 seconds until we manage // to Dial to the server. -func (self *ircBot) Connect() { +func (bot *ircBot) Connect() { - if self.socket != nil { + if bot.socket != nil { // socket already set, unit tests need this return } @@ -143,9 +183,9 @@ func (self *ircBot) Connect() { var err error for { - glog.Infoln("Connecting to IRC server: ", self.address) + glog.Infoln("Connecting to IRC server: ", bot.address) - socket, err = tls.Dial("tcp", self.address, nil) // Always try TLS first + socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first if err == nil { glog.Infoln("Connected: TLS secure") break @@ -157,7 +197,7 @@ func (self *ircBot) Connect() { if ok { // Certificate might not match. This happens on irc.cloudfront.net insecure := &tls.Config{InsecureSkipVerify: true} - socket, err = tls.Dial("tcp", self.address, insecure) + socket, err = tls.Dial("tcp", bot.address, insecure) if err == nil && isCertValid(socket.(*tls.Conn)) { glog.Infoln("Connected: TLS with awkward certificate") @@ -165,7 +205,7 @@ func (self *ircBot) Connect() { } } - socket, err = net.Dial("tcp", self.address) + socket, err = net.Dial("tcp", bot.address) if err == nil { glog.Infoln("Connected: Plain text insecure") @@ -176,7 +216,7 @@ func (self *ircBot) Connect() { time.Sleep(10 * time.Second) } - self.socket = socket + bot.socket = socket } /* Check that the TLS connection's certficate can be applied to this connection. @@ -225,148 +265,146 @@ func isIPMatch(hostname string, connIP string) bool { } // Update bot configuration. Called when webapp changes a chatbot's config. -func (self *ircBot) Update(config *common.BotConfig) { +func (bot *ircBot) Update(config *common.BotConfig) { - isNewServer := self.updateServer(config) + isNewServer := bot.updateServer(config) if isNewServer { // If the server changed, we've already done nick and channel changes too return } - self.updateNick(config.Config["nick"], config.Config["password"]) - self.updateChannels(config.Channels) + bot.updateNick(config.Config["nick"], config.Config["password"]) + bot.updateChannels(config.Channels) } // Update the IRC server we're connected to -func (self *ircBot) updateServer(config *common.BotConfig) bool { +func (bot *ircBot) updateServer(config *common.BotConfig) bool { addr := config.Config["server"] - if addr == self.address { + if addr == bot.address { return false } - glog.Infoln("Changing IRC server from ", self.address, " to ", addr) + glog.Infoln("Changing IRC server from ", bot.address, " to ", addr) - self.Close() + bot.Close() time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped - self.address = addr - self.nick = config.Config["nick"] - self.password = config.Config["password"] - self.channels = config.Channels + bot.address = addr + bot.nick = config.Config["nick"] + bot.password = config.Config["password"] + bot.channels = config.Channels - self.init() + bot.Init() return true } // Update the nickname we're registered under, if needed -func (self *ircBot) updateNick(newNick, newPass string) { - if newNick == self.nick { +func (bot *ircBot) updateNick(newNick, newPass string) { + if newNick == bot.nick { return } - self.nick = newNick - self.password = newPass - self.setNick() + bot.nick = newNick + bot.password = newPass + bot.setNick() } // Update the channels based on new configuration, leaving old ones and joining new ones -func (self *ircBot) updateChannels(newChannels []*common.Channel) { - if isEqual(newChannels, self.channels) { +func (bot *ircBot) updateChannels(newChannels []*common.Channel) { + if isEqual(newChannels, bot.channels) { if glog.V(2) { - glog.Infoln("Channels comparison is equals for bot: ", self.nick) + glog.Infoln("Channels comparison is equals for bot: ", bot.nick) } return } // PART old ones - for _, channel := range self.channels { + for _, channel := range bot.channels { if !isIn(channel, newChannels) { - self.part(channel.Credential()) + bot.part(channel.Credential()) } } // JOIN new ones for _, channel := range newChannels { - if !isIn(channel, self.channels) { - self.join(channel.Credential()) + if !isIn(channel, bot.channels) { + bot.join(channel.Credential()) } } - self.channels = newChannels + bot.channels = newChannels } // Join channels -func (self *ircBot) JoinAll() { - for _, channel := range self.channels { - self.join(channel.Credential()) +func (bot *ircBot) JoinAll() { + for _, channel := range bot.channels { + bot.join(channel.Credential()) } } // Join an IRC channel -func (self *ircBot) join(channel string) { - self.SendRaw("JOIN " + channel) +func (bot *ircBot) join(channel string) { + bot.SendRaw("JOIN " + channel) } // Leave an IRC channel -func (self *ircBot) part(channel string) { - self.SendRaw("PART " + channel) +func (bot *ircBot) part(channel string) { + bot.SendRaw("PART " + channel) } // Send a regular (non-system command) IRC message -func (self *ircBot) Send(channel, msg string) { +func (bot *ircBot) Send(channel, msg string) { fullmsg := "PRIVMSG " + channel + " :" + msg - self.SendRaw(fullmsg) + bot.SendRaw(fullmsg) } // Send message down socket. Add \n at end first. -func (self *ircBot) SendRaw(msg string) { - self.sendQueue <- []byte(msg + "\n") +func (bot *ircBot) SendRaw(msg string) { + bot.sendQueue <- []byte(msg + "\n") } // Tell the irc server who we are - we can't do anything until this is done. -func (self *ircBot) login() { +func (bot *ircBot) login() { - self.isAuthenticating = true + bot.isAuthenticating = true // We use the botname as the 'realname', because bot's don't have real names! - self.SendRaw("USER " + self.nick + " 0 * :" + self.realname) + bot.SendRaw("USER " + bot.nick + " 0 * :" + bot.realname) - self.setNick() + bot.setNick() } -// Tell the network our nick -func (self *ircBot) setNick() { - self.SendRaw("NICK " + self.nick) +// Tell the network our +func (bot *ircBot) setNick() { + bot.SendRaw("NICK " + bot.nick) } // Tell NickServ our password -func (self *ircBot) sendPassword() { - self.Send("NickServ", "identify "+self.password) +func (bot *ircBot) sendPassword() { + bot.Send("NickServ", "identify "+bot.password) } // Actually really send message to the server. Implements rate limiting. // Should run in go-routine. -func (self *ircBot) sender() { +func (bot *ircBot) sender() { var data []byte var twoSeconds = time.Second * 2 var err error - for self.isRunning { + for bot.IsRunning() { - data = <-self.sendQueue + data = <-bot.sendQueue if glog.V(1) { - glog.Infoln("[RAW"+strconv.Itoa(self.id)+"] -->", string(data)) + glog.Infoln("[RAW"+strconv.Itoa(bot.id)+"] -->", string(data)) } - _, err = self.socket.Write(data) + _, err = bot.socket.Write(data) if err != nil { - self.isRunning = false glog.Errorln("Error writing to socket", err) - glog.Infoln("Stopping chatbot. Monitor can restart it.") - self.Close() + bot.Close() } // Rate limit to one message every 2 seconds @@ -377,14 +415,14 @@ func (self *ircBot) sender() { // Listen for incoming messages. Parse them and put on channel. // Should run in go-routine -func (self *ircBot) listen() { +func (bot *ircBot) listen() { var contentData []byte var content string var err error - bufRead := bufio.NewReader(self.socket) - for self.isRunning { + bufRead := bufio.NewReader(bot.socket) + for bot.IsRunning() { contentData, err = bufRead.ReadBytes('\n') if err != nil { @@ -392,13 +430,13 @@ func (self *ircBot) listen() { if ok && netErr.Timeout() == true { continue - } else if !self.isRunning { + } else if !bot.IsRunning() { // Close() wants us to stop return } else { glog.Errorln("Lost IRC server connection. ", err) - self.Close() + bot.Close() return } } @@ -410,13 +448,13 @@ func (self *ircBot) listen() { content = toUnicode(contentData) if glog.V(1) { - glog.Infoln("[RAW" + strconv.Itoa(self.id) + "]" + content) + glog.Infoln("[RAW" + strconv.Itoa(bot.id) + "]" + content) } theLine, err := parseLine(content) if err == nil { - theLine.ChatBotId = self.id - self.act(theLine) + theLine.ChatBotId = bot.id + bot.act(theLine) } else { glog.Errorln("Invalid line:", content) } @@ -424,20 +462,27 @@ func (self *ircBot) listen() { } } -func (self *ircBot) act(theLine *line.Line) { +func (bot *ircBot) act(theLine *line.Line) { + // Notify the monitor goroutine that we receive a PONG + if theLine.Command == "PONG" { + if glog.V(2) { + glog.Infoln("Sending the signal in bot.pingResponse") + } + bot.pingResponse <- struct{}{} + return + } - // Send the command on the monitorChan - self.monitorChan <- struct{}{} + // Send the heartbeat to the monitoring goroutine via monitorChan + bot.monitorChan <- struct{}{} // As soon as we receive a message from the server, complete initiatization - if self.isConnecting { - self.isConnecting = false - self.login() + if bot.isConnecting { + bot.isConnecting = false + bot.login() return } // NickServ interactions - isNickServ := strings.Contains(theLine.User, "NickServ") // freenode, coldfront @@ -453,12 +498,12 @@ func (self *ircBot) act(theLine *line.Line) { if isNickServ { if isAskingForPW { - self.sendPassword() + bot.sendPassword() return } else if isConfirm { - self.isAuthenticating = false - self.JoinAll() + bot.isAuthenticating = false + bot.JoinAll() return } } @@ -466,48 +511,52 @@ func (self *ircBot) act(theLine *line.Line) { // After USER / NICK is accepted, join all the channels, // assuming we don't need to identify with NickServ - if self.isAuthenticating && len(self.password) == 0 { - self.isAuthenticating = false - self.JoinAll() + if bot.isAuthenticating && len(bot.password) == 0 { + bot.isAuthenticating = false + bot.JoinAll() return } if theLine.Command == "PING" { // Reply, and send message on to client - self.SendRaw("PONG " + theLine.Content) + bot.SendRaw("PONG " + theLine.Content) } else if theLine.Command == "VERSION" { versionMsg := "NOTICE " + theLine.User + " :\u0001VERSION " + VERSION + "\u0001\n" - self.SendRaw(versionMsg) + bot.SendRaw(versionMsg) } - self.fromServer <- theLine + bot.fromServer <- theLine } -func (self *ircBot) IsRunning() bool { - return self.isRunning +func (bot *ircBot) IsRunning() bool { + bot.Lock() + defer bot.Unlock() + return bot.isRunning } -func (self *ircBot) Close() error { - self.sendShutdown() - self.isRunning = false - return self.socket.Close() +// Close ircBot +func (bot *ircBot) Close() error { + bot.Lock() + defer bot.Unlock() + bot.isRunning = false + bot.sendShutdown() + return bot.socket.Close() } // Send a non-standard SHUTDOWN message to the plugins // This allows them to know that this channel is offline -func (self *ircBot) sendShutdown() { - +func (bot *ircBot) sendShutdown() { shutLine := &line.Line{ Command: "SHUTDOWN", Received: time.Now().UTC().Format(time.RFC3339Nano), - ChatBotId: self.id, - User: self.nick, + ChatBotId: bot.id, + User: bot.nick, Raw: "", Content: ""} - for _, channel := range self.channels { + for _, channel := range bot.channels { shutLine.Channel = channel.Credential() - self.fromServer <- shutLine + bot.fromServer <- shutLine } } diff --git a/network/network.go b/network/network.go index 4e03445..0aadc0b 100644 --- a/network/network.go +++ b/network/network.go @@ -90,7 +90,7 @@ func (self *NetworkManager) RefreshChatbots() { func (self *NetworkManager) Connect(config *common.BotConfig) common.ChatBot { - glog.Infoln("Creating chatbot,", config) + glog.Infoln("Creating chatbot as:,", config) return irc.NewBot(config, self.fromServer) } From 792c7f1de22db3d8e9843c593763b6083e5e8427 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 18 May 2014 13:40:38 +0200 Subject: [PATCH 13/76] ref #15. Fix a potential race condition in the NetworkManager --- network/irc/irc.go | 6 ++--- network/network.go | 64 +++++++++++++++++++++++++++------------------- 2 files changed, 40 insertions(+), 30 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index c95d454..1f1426d 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -33,7 +33,7 @@ const ( ) type ircBot struct { - sync.Mutex + sync.RWMutex id int address string socket io.ReadWriteCloser @@ -529,8 +529,8 @@ func (bot *ircBot) act(theLine *line.Line) { } func (bot *ircBot) IsRunning() bool { - bot.Lock() - defer bot.Unlock() + bot.RLock() + defer bot.RUnlock() return bot.isRunning } diff --git a/network/network.go b/network/network.go index 0aadc0b..eaf01e7 100644 --- a/network/network.go +++ b/network/network.go @@ -2,6 +2,7 @@ package network import ( "sort" + "sync" "time" "github.com/golang/glog" @@ -12,6 +13,7 @@ import ( ) type NetworkManager struct { + sync.RWMutex chatbots map[int]common.ChatBot fromServer chan *line.Line storage common.Storage @@ -30,17 +32,23 @@ func NewNetworkManager(storage common.Storage, fromServer chan *line.Line) *Netw return netMan } +func (nm *NetworkManager) IsRunning() bool { + nm.RLock() + defer nm.RUnlock() + return nm.isRunning +} + // Get the User for a ChatbotId -func (self *NetworkManager) GetUserByChatbotId(id int) string { - return self.getChatbotById(id).GetUser() +func (nm *NetworkManager) GetUserByChatbotId(id int) string { + return nm.getChatbotById(id).GetUser() } // Connect to networks / start chatbots. Loads chatbot configuration from DB. -func (self *NetworkManager) RefreshChatbots() { +func (nm *NetworkManager) RefreshChatbots() { if glog.V(2) { glog.Infoln("Entering in NetworkManager.RefreshChatbots") } - botConfigs := self.storage.BotConfig() + botConfigs := nm.storage.BotConfig() var current common.ChatBot var id int @@ -51,19 +59,19 @@ func (self *NetworkManager) RefreshChatbots() { id = config.Id active = append(active, id) - current = self.chatbots[id] + current = nm.chatbots[id] if current == nil { // Create if glog.V(2) { glog.Infoln("Connect the bot with the following config:", config) } - self.chatbots[id] = self.Connect(config) + nm.chatbots[id] = nm.Connect(config) } else { // Update if glog.V(2) { glog.Infoln("Update the bot with the following config:", config) } - self.chatbots[id].Update(config) + nm.chatbots[id].Update(config) } } @@ -73,13 +81,13 @@ func (self *NetworkManager) RefreshChatbots() { active.Sort() numActive := len(active) - for currId := range self.chatbots { + for currId := range nm.chatbots { if active.Search(currId) == numActive { // if currId not in active: glog.Infoln("Stopping chatbot: ", currId) - self.chatbots[currId].Close() - delete(self.chatbots, currId) + nm.chatbots[currId].Close() + delete(nm.chatbots, currId) } } if glog.V(2) { @@ -88,23 +96,23 @@ func (self *NetworkManager) RefreshChatbots() { } -func (self *NetworkManager) Connect(config *common.BotConfig) common.ChatBot { +func (nm *NetworkManager) Connect(config *common.BotConfig) common.ChatBot { glog.Infoln("Creating chatbot as:,", config) - return irc.NewBot(config, self.fromServer) + return irc.NewBot(config, nm.fromServer) } -func (self *NetworkManager) Send(chatbotId int, channel, msg string) { - self.chatbots[chatbotId].Send(channel, msg) +func (nm *NetworkManager) Send(chatbotId int, channel, msg string) { + nm.chatbots[chatbotId].Send(channel, msg) } // Check out chatbots are alive, recreating them if not. Run this in go-routine. -func (self *NetworkManager) MonitorChatbots() { +func (nm *NetworkManager) MonitorChatbots() { - for self.isRunning { - for id, bot := range self.chatbots { + for nm.IsRunning() { + for id, bot := range nm.chatbots { if !bot.IsRunning() { - self.restart(id) + nm.restart(id) } } time.Sleep(1 * time.Second) @@ -112,12 +120,12 @@ func (self *NetworkManager) MonitorChatbots() { } // get a chatbot by id -func (self *NetworkManager) getChatbotById(id int) common.ChatBot { - return self.chatbots[id] +func (nm *NetworkManager) getChatbotById(id int) common.ChatBot { + return nm.chatbots[id] } // Restart a chatbot -func (self *NetworkManager) restart(botId int) { +func (nm *NetworkManager) restart(botId int) { glog.Infoln("Restarting bot ", botId) @@ -125,7 +133,7 @@ func (self *NetworkManager) restart(botId int) { // Find configuration for this bot - botConfigs := self.storage.BotConfig() + botConfigs := nm.storage.BotConfig() for _, botConf := range botConfigs { if botConf.Id == botId { config = botConf @@ -135,17 +143,19 @@ func (self *NetworkManager) restart(botId int) { if config == nil { glog.Infoln("Could not find configuration for bot ", botId, ". Bot will not run.") - delete(self.chatbots, botId) + delete(nm.chatbots, botId) return } - self.chatbots[botId] = self.Connect(config) + nm.chatbots[botId] = nm.Connect(config) } // Stop all bots -func (self *NetworkManager) Shutdown() { - self.isRunning = false - for _, bot := range self.chatbots { +func (nm *NetworkManager) Shutdown() { + nm.Lock() + nm.isRunning = false + for _, bot := range nm.chatbots { bot.Close() } + nm.Unlock() } From cbdefe8666055b2d55e0c0b00a948239ae61ade8 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 18 May 2014 14:14:47 +0200 Subject: [PATCH 14/76] ref #15. Fix another race condition reported by the runtime. --- network/network.go | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/network/network.go b/network/network.go index eaf01e7..af1f5fd 100644 --- a/network/network.go +++ b/network/network.go @@ -45,6 +45,8 @@ func (nm *NetworkManager) GetUserByChatbotId(id int) string { // Connect to networks / start chatbots. Loads chatbot configuration from DB. func (nm *NetworkManager) RefreshChatbots() { + nm.Lock() + nm.Unlock() if glog.V(2) { glog.Infoln("Entering in NetworkManager.RefreshChatbots") } @@ -77,7 +79,6 @@ func (nm *NetworkManager) RefreshChatbots() { } // Stop old ones - active.Sort() numActive := len(active) @@ -103,7 +104,9 @@ func (nm *NetworkManager) Connect(config *common.BotConfig) common.ChatBot { } func (nm *NetworkManager) Send(chatbotId int, channel, msg string) { + nm.RLock() nm.chatbots[chatbotId].Send(channel, msg) + nm.RUnlock() } // Check out chatbots are alive, recreating them if not. Run this in go-routine. @@ -121,6 +124,8 @@ func (nm *NetworkManager) MonitorChatbots() { // get a chatbot by id func (nm *NetworkManager) getChatbotById(id int) common.ChatBot { + nm.RLock() + defer nm.RUnlock() return nm.chatbots[id] } @@ -147,7 +152,9 @@ func (nm *NetworkManager) restart(botId int) { return } + nm.Lock() nm.chatbots[botId] = nm.Connect(config) + nm.Unlock() } // Stop all bots From 988592a5b69a41c13319626612e727bf36627ad2 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 18 May 2014 21:55:27 +0200 Subject: [PATCH 15/76] ref #15. Reduce the verbosity of the log and improve its readability --- network/irc/irc.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 1f1426d..a367481 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -101,14 +101,14 @@ func (bot *ircBot) monitor() { pongCounter := 0 for bot.IsRunning() { if pongCounter > maxPongWithoutMessage { - glog.Infoln("More than maxPongWithoutMessage pong without message.") + glog.Infoln("More than maxPongWithoutMessage pong without message for", bot) bot.reconnect() } select { case <-bot.monitorChan: pongCounter = 0 if glog.V(2) { - glog.Infoln("Message received from the server") + glog.Infoln("Message received from the server for", bot) } case <-time.After(time.Second * 60): glog.Infoln("Ping the ircBot server", bot) @@ -116,7 +116,7 @@ func (bot *ircBot) monitor() { select { case <-bot.pingResponse: pongCounter += 1 - if glog.V(2) { + if glog.V(1) { glog.Infoln("Pong from ircBot server", bot) } case <-time.After(time.Second * 10): @@ -447,7 +447,7 @@ func (bot *ircBot) listen() { content = toUnicode(contentData) - if glog.V(1) { + if glog.V(2) { glog.Infoln("[RAW" + strconv.Itoa(bot.id) + "]" + content) } From b9f1f88ce7f63d1d796ff76dd54e3c0150942695 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 18 May 2014 22:05:57 +0200 Subject: [PATCH 16/76] refs #15. Improved the logging before reconnecting --- network/irc/irc.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index a367481..6cde4b9 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -130,7 +130,7 @@ func (bot *ircBot) monitor() { // reconnect the ircBot func (bot *ircBot) reconnect() { - glog.Infoln("Trying to reconnect.") + glog.Infoln("Trying to reconnect", bot) bot.Close() time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.Init() From 0bc1136a60256a1f2724ff5daaf7a292f64fb02b Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 18 May 2014 22:49:55 +0200 Subject: [PATCH 17/76] refs #15. give a grace period of 3 missed reply to Ping. --- network/irc/irc.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 6cde4b9..8b9e750 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -102,6 +102,7 @@ func (bot *ircBot) monitor() { for bot.IsRunning() { if pongCounter > maxPongWithoutMessage { glog.Infoln("More than maxPongWithoutMessage pong without message for", bot) + glog.Infoln("IRC monitoring KO", bot) bot.reconnect() } select { @@ -121,8 +122,9 @@ func (bot *ircBot) monitor() { } case <-time.After(time.Second * 10): glog.Infoln("No pong from ircBot server", bot) - glog.Infoln("IRC monitoring KO.") - bot.reconnect() + // Do not kill the server on the first missed PONG + // 3 chances 15/5 + pongCounter += 5 } } } From 1e2b522ea88f27f757e257c8bbcf4fa6eea7c03b Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 19 May 2014 00:00:56 +0200 Subject: [PATCH 18/76] ref #15. Increase maxPongWithoutMessage from 15 to 150 to only rejoin silent network every 150 min. This should be configurable per chat bot --- network/irc/irc.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 8b9e750..9db511b 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -97,7 +97,7 @@ func (bot *ircBot) String() string { // reconnect. func (bot *ircBot) monitor() { // TODO maxPongWithoutMessage should probably be a field of ircBot - maxPongWithoutMessage := 15 + maxPongWithoutMessage := 150 pongCounter := 0 for bot.IsRunning() { if pongCounter > maxPongWithoutMessage { @@ -112,7 +112,7 @@ func (bot *ircBot) monitor() { glog.Infoln("Message received from the server for", bot) } case <-time.After(time.Second * 60): - glog.Infoln("Ping the ircBot server", bot) + glog.Infoln("Ping the ircBot server", pongCounter, bot) bot.ping() select { case <-bot.pingResponse: From 13ca9c4ec6c14e64f19cab539a6e2d33e0fb326f Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 19 May 2014 22:15:55 +0200 Subject: [PATCH 19/76] Improve the error loging to know which bot cannot write the the socket. Try to reconnect this bot instead of just calling bot.Close() --- network/irc/irc.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 9db511b..20511f0 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -405,8 +405,8 @@ func (bot *ircBot) sender() { _, err = bot.socket.Write(data) if err != nil { - glog.Errorln("Error writing to socket", err) - bot.Close() + glog.Errorln("Error writing to socket to", bot, ": ", err) + bot.reconnect() } // Rate limit to one message every 2 seconds From 30cbab6ce08e3a972ffdc6c133cd36eceb02a5ea Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 19 May 2014 22:49:20 +0200 Subject: [PATCH 20/76] Reconnect a bit more aggresively when the server do not respond to ping --- network/irc/irc.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 20511f0..d739369 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -123,8 +123,7 @@ func (bot *ircBot) monitor() { case <-time.After(time.Second * 10): glog.Infoln("No pong from ircBot server", bot) // Do not kill the server on the first missed PONG - // 3 chances 15/5 - pongCounter += 5 + pongCounter += 15 } } } From e4ba11a76fdf581e347c89c2ecd3213f9e988a31 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 29 May 2014 11:39:50 +0200 Subject: [PATCH 21/76] Add expvar and export some stats for each bots --- main.go | 6 ++++++ network/irc/irc.go | 22 +++++++++++++++++++--- 2 files changed, 25 insertions(+), 3 deletions(-) diff --git a/main.go b/main.go index 854de4d..a0b2a57 100644 --- a/main.go +++ b/main.go @@ -1,7 +1,10 @@ package main import ( + _ "expvar" "flag" + "log" + "net/http" "os" "os/signal" "syscall" @@ -32,6 +35,9 @@ func main() { // Start the main loop go botbot.mainLoop() + // Start and http server to serve the stats from expvar + log.Fatal(http.ListenAndServe(":3030", nil)) + // Trap stop signal (Ctrl-C, kill) to exit kill := make(chan os.Signal) signal.Notify(kill, syscall.SIGINT, syscall.SIGKILL, syscall.SIGTERM) diff --git a/network/irc/irc.go b/network/irc/irc.go index d739369..e404f86 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -12,6 +12,7 @@ import ( "bufio" "crypto/tls" "crypto/x509" + "expvar" "fmt" "io" "net" @@ -50,6 +51,7 @@ type ircBot struct { monitorChan chan struct{} pingResponse chan struct{} reconnectChan chan struct{} + stats *expvar.Map } func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot { @@ -73,8 +75,15 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot pingResponse: make(chan struct{}), reconnectChan: make(chan struct{}), isRunning: true, + stats: expvar.NewMap(fmt.Sprintf("%s_%s", config.Config["nick"], config.Config["server"])), } + chatbot.stats.Add("channels", 0) + chatbot.stats.Add("messages", 0) + chatbot.stats.Add("ping", 0) + chatbot.stats.Add("pong", 0) + chatbot.stats.Add("missed_ping", 0) + chatbot.stats.Add("restart", 0) chatbot.Init() return chatbot @@ -116,11 +125,13 @@ func (bot *ircBot) monitor() { bot.ping() select { case <-bot.pingResponse: + bot.stats.Add("pong", 1) pongCounter += 1 if glog.V(1) { glog.Infoln("Pong from ircBot server", bot) } case <-time.After(time.Second * 10): + bot.stats.Add("missed_ping", 1) glog.Infoln("No pong from ircBot server", bot) // Do not kill the server on the first missed PONG pongCounter += 15 @@ -132,6 +143,7 @@ func (bot *ircBot) monitor() { // reconnect the ircBot func (bot *ircBot) reconnect() { glog.Infoln("Trying to reconnect", bot) + bot.stats.Add("restart", 1) bot.Close() time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.Init() @@ -141,6 +153,7 @@ func (bot *ircBot) reconnect() { // Ping the server to the connection open func (bot *ircBot) ping() { // TODO increment number + bot.stats.Add("ping", 1) bot.SendRaw("PING 1") } @@ -348,11 +361,13 @@ func (bot *ircBot) JoinAll() { // Join an IRC channel func (bot *ircBot) join(channel string) { bot.SendRaw("JOIN " + channel) + bot.stats.Add("channels", 1) } // Leave an IRC channel func (bot *ircBot) part(channel string) { bot.SendRaw("PART " + channel) + bot.stats.Add("channels", -1) } // Send a regular (non-system command) IRC message @@ -392,7 +407,7 @@ func (bot *ircBot) sendPassword() { func (bot *ircBot) sender() { var data []byte - var twoSeconds = time.Second * 2 + var tempo = time.Second * 1 var err error for bot.IsRunning() { @@ -407,10 +422,11 @@ func (bot *ircBot) sender() { glog.Errorln("Error writing to socket to", bot, ": ", err) bot.reconnect() } + bot.stats.Add("messages", 1) - // Rate limit to one message every 2 seconds + // Rate limit to one message every tempo // https://github.com/BotBotMe/botbot-bot/issues/2 - time.Sleep(twoSeconds) + time.Sleep(tempo) } } From 1ea5830b69b2664b183fbf840b705ed3931c0fac Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 29 May 2014 14:29:19 +0200 Subject: [PATCH 22/76] Change the naming of the stats for each bots --- network/irc/irc.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index e404f86..cd12a6c 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -75,7 +75,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot pingResponse: make(chan struct{}), reconnectChan: make(chan struct{}), isRunning: true, - stats: expvar.NewMap(fmt.Sprintf("%s_%s", config.Config["nick"], config.Config["server"])), + stats: expvar.NewMap(fmt.Sprintf("%s_%d", config.Config["nick"], config.Id)), } chatbot.stats.Add("channels", 0) From 79376d05142bb18a15bfa4264d37af9cb2969f9a Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 29 May 2014 15:08:40 +0200 Subject: [PATCH 23/76] Remove the nick from the stats name because it seems to upset graphite --- network/irc/irc.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index cd12a6c..e601bb6 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -75,7 +75,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot pingResponse: make(chan struct{}), reconnectChan: make(chan struct{}), isRunning: true, - stats: expvar.NewMap(fmt.Sprintf("%s_%d", config.Config["nick"], config.Id)), + stats: expvar.NewMap(fmt.Sprintf("%d", config.Id)), } chatbot.stats.Add("channels", 0) From c087d41a3708b0640cd53e427cb5f2642ee9667a Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Fri, 30 May 2014 19:19:04 +0200 Subject: [PATCH 24/76] Taking advantage of the new server_identifier to push the stats to graphite. --- common/storage.go | 36 ++++++++++++++++-------- network/irc/irc.go | 62 +++++++++++++++++++++-------------------- network/irc/irc_test.go | 47 +++++++++++++++++-------------- 3 files changed, 82 insertions(+), 63 deletions(-) diff --git a/common/storage.go b/common/storage.go index 98a1180..40fed17 100644 --- a/common/storage.go +++ b/common/storage.go @@ -87,24 +87,28 @@ func (self *PostgresStorage) BotConfig() []*BotConfig { configs := make([]*BotConfig, 0) - sql := "SELECT id, server, server_password, nick, password, real_name FROM bots_chatbot WHERE is_active=true" + sql := "SELECT id, server, server_password, nick, password, real_name, server_identifier FROM bots_chatbot WHERE is_active=true" rows, err = self.db.Query(sql) if err != nil { glog.Fatal("Error running: ", sql, " ", err) } + defer rows.Close() var chatbotId int - var server, server_password, nick, password, real_name []byte + var server, server_password, nick, password, real_name, server_identifier []byte for rows.Next() { - rows.Scan(&chatbotId, &server, &server_password, &nick, &password, &real_name) + rows.Scan( + &chatbotId, &server, &server_password, &nick, &password, + &real_name, &server_identifier) confMap := map[string]string{ - "server": string(server), - "server_password": string(server_password), - "nick": string(nick), - "password": string(password), - "realname": string(real_name), + "server": string(server), + "server_password": string(server_password), + "nick": string(nick), + "password": string(password), + "realname": string(real_name), + "server_identifier": string(server_identifier), } config := &BotConfig{ @@ -114,17 +118,24 @@ func (self *PostgresStorage) BotConfig() []*BotConfig { } configs = append(configs, config) + glog.Infoln("config.Id:", config.Id) } + channelStmt, err := self.db.Prepare("SELECT id, name, password, fingerprint FROM bots_channel WHERE is_active=true and chatbot_id=$1") + if err != nil { + glog.Fatal("[Error] Error while preparing the statements to retrieve the channel:", err) + } + defer channelStmt.Close() + for i := range configs { config := configs[i] - rows, err = self.db.Query("SELECT id, name, password, fingerprint FROM bots_channel WHERE is_active=true and chatbot_id=$1", config.Id) + rows, err = channelStmt.Query(config.Id) if err != nil { glog.Fatal("Error running:", err) } + defer rows.Close() + var channelId int - var channelName string - var channelPwd string - var channelFingerprint string + var channelName, channelPwd, channelFingerprint string for rows.Next() { rows.Scan(&channelId, &channelName, &channelPwd, &channelFingerprint) config.Channels = append(config.Channels, @@ -196,6 +207,7 @@ func (self *PostgresStorage) channelId(name string) (int, error) { if err != nil { return -1, err } + defer rows.Close() rows.Next() rows.Scan(&channelId) diff --git a/network/irc/irc.go b/network/irc/irc.go index e601bb6..68bb81d 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -35,23 +35,24 @@ const ( type ircBot struct { sync.RWMutex - id int - address string - socket io.ReadWriteCloser - nick string - realname string - password string - serverPass string - fromServer chan *line.Line - channels []*common.Channel - isRunning bool - isConnecting bool - isAuthenticating bool - sendQueue chan []byte - monitorChan chan struct{} - pingResponse chan struct{} - reconnectChan chan struct{} - stats *expvar.Map + id int + address string + socket io.ReadWriteCloser + nick string + realname string + password string + serverPass string + server_identifier string + fromServer chan *line.Line + channels []*common.Channel + isRunning bool + isConnecting bool + isAuthenticating bool + sendQueue chan []byte + monitorChan chan struct{} + pingResponse chan struct{} + reconnectChan chan struct{} + stats *expvar.Map } func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot { @@ -63,19 +64,20 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot } chatbot := &ircBot{ - id: config.Id, - address: config.Config["server"], - nick: config.Config["nick"], - realname: realname, - password: config.Config["password"], // NickServ password - serverPass: config.Config["server_password"], // PASS password - fromServer: fromServer, - channels: config.Channels, - monitorChan: make(chan struct{}), - pingResponse: make(chan struct{}), - reconnectChan: make(chan struct{}), - isRunning: true, - stats: expvar.NewMap(fmt.Sprintf("%d", config.Id)), + id: config.Id, + address: config.Config["server"], + nick: config.Config["nick"], + realname: realname, + password: config.Config["password"], // NickServ password + serverPass: config.Config["server_password"], // PASS password + server_identifier: config.Config["server_identifier"], + fromServer: fromServer, + channels: config.Channels, + monitorChan: make(chan struct{}), + pingResponse: make(chan struct{}), + reconnectChan: make(chan struct{}), + isRunning: true, + stats: expvar.NewMap(config.Config["server_identifier"]), } chatbot.stats.Add("channels", 0) diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 0adbad7..fd5689f 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -1,6 +1,7 @@ package irc import ( + "expvar" "strconv" "strings" "testing" @@ -178,17 +179,19 @@ func TestFlood(t *testing.T) { channels = append(channels, &common.Channel{Name: "test", Fingerprint: "uuid-string"}) chatbot := &ircBot{ - id: 99, - address: "localhost", - nick: "test", - realname: "Unit Test", - password: "test", - fromServer: fromServer, - channels: channels, - socket: &mockSocket, - isRunning: true, - } - chatbot.init() + id: 99, + address: "localhost", + nick: "test", + realname: "Unit Test", + password: "test", + server_identifier: "localhost.test", + fromServer: fromServer, + channels: channels, + socket: &mockSocket, + isRunning: true, + stats: expvar.NewMap("localhost.test"), + } + chatbot.Init() startTime := time.Now() @@ -222,16 +225,18 @@ func TestUpdate(t *testing.T) { channels = append(channels, &channel) chatbot := &ircBot{ - id: 99, - address: "localhost", - nick: "test", - realname: "Unit Test", - password: "test", - fromServer: fromServer, - channels: channels, - socket: &mockSocket, - sendQueue: make(chan []byte, 100), - isRunning: true, + id: 99, + address: "localhost", + nick: "test", + realname: "Unit Test", + password: "test", + server_identifier: "localhost.test1", + fromServer: fromServer, + channels: channels, + socket: &mockSocket, + sendQueue: make(chan []byte, 100), + isRunning: true, + stats: expvar.NewMap("localhost.test1"), } // Rate limiting requires a go-routine to actually do the sending go chatbot.sender() From e191e8a0b09be5b0a1169eed400d5796f51f88af Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 1 Jun 2014 11:18:23 +0200 Subject: [PATCH 25/76] Added an expvar to count the received messages from IRC --- network/irc/irc.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/network/irc/irc.go b/network/irc/irc.go index 68bb81d..a604d09 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -82,6 +82,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot chatbot.stats.Add("channels", 0) chatbot.stats.Add("messages", 0) + chatbot.stats.Add("received_messages", 0) chatbot.stats.Add("ping", 0) chatbot.stats.Add("pong", 0) chatbot.stats.Add("missed_ping", 0) @@ -472,6 +473,7 @@ func (bot *ircBot) listen() { theLine, err := parseLine(content) if err == nil { + bot.stats.Add("received_messages", 1) theLine.ChatBotId = bot.id bot.act(theLine) } else { From ca09d03e9d72f2f0351e39e343c3c8a93c3398ad Mon Sep 17 00:00:00 2001 From: yml Date: Fri, 6 Jun 2014 14:26:27 +0200 Subject: [PATCH 26/76] Update README.md --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 7efa624..50735bd 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,6 @@ [![Build Status](https://travis-ci.org/BotBotMe/botbot-bot.png)](https://travis-ci.org/BotBotMe/botbot-bot) -The bot used in botbot.me. To install: +The bot used in botbot.me is a Go (1.2) program. To install: go get github.com/BotBotMe/botbot-bot From aff63d37aace88035c4a7620f3c46aa977dfc10d Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Fri, 6 Jun 2014 17:27:32 +0200 Subject: [PATCH 27/76] Added a goroutine that collect the channels every bot is connected to and expose it as expvar. --- network/irc/irc.go | 181 ++++++++++++++++++++++++---------------- network/irc/irc_test.go | 46 +++++----- 2 files changed, 130 insertions(+), 97 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index a604d09..f1638ef 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -17,7 +17,6 @@ import ( "io" "net" "sort" - "strconv" "strings" "sync" "time" @@ -30,31 +29,34 @@ import ( ) const ( - VERSION = "botbotme v0.2" + // VERSION of the botbot-bot + VERSION = "botbot v0.3.0" + RPL_WHOISCHANNELS = "319" ) type ircBot struct { sync.RWMutex - id int - address string - socket io.ReadWriteCloser - nick string - realname string - password string - serverPass string - server_identifier string - fromServer chan *line.Line - channels []*common.Channel - isRunning bool - isConnecting bool - isAuthenticating bool - sendQueue chan []byte - monitorChan chan struct{} - pingResponse chan struct{} - reconnectChan chan struct{} - stats *expvar.Map -} - + id int + address string + socket io.ReadWriteCloser + nick string + realname string + password string + serverPass string + serverIdentifier string + channels []*common.Channel + isRunning bool + isConnecting bool + isAuthenticating bool + sendQueue chan []byte + fromServer chan *line.Line + monitorChan chan struct{} + pingResponse chan struct{} + reconnectChan chan struct{} + stats *expvar.Map +} + +// NewBot create an irc instance of ChatBot func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot { // realname is set to config["realname"] or config["nick"] @@ -64,22 +66,24 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot } chatbot := &ircBot{ - id: config.Id, - address: config.Config["server"], - nick: config.Config["nick"], - realname: realname, - password: config.Config["password"], // NickServ password - serverPass: config.Config["server_password"], // PASS password - server_identifier: config.Config["server_identifier"], - fromServer: fromServer, - channels: config.Channels, - monitorChan: make(chan struct{}), - pingResponse: make(chan struct{}), - reconnectChan: make(chan struct{}), - isRunning: true, - stats: expvar.NewMap(config.Config["server_identifier"]), - } - + id: config.Id, + address: config.Config["server"], + nick: config.Config["nick"], + realname: realname, + password: config.Config["password"], // NickServ password + serverPass: config.Config["server_password"], // PASS password + serverIdentifier: config.Config["server_identifier"], + fromServer: fromServer, + channels: config.Channels, + monitorChan: make(chan struct{}), + pingResponse: make(chan struct{}), + reconnectChan: make(chan struct{}), + isRunning: true, + } + + chatbot.stats = expvar.NewMap(chatbot.serverIdentifier) + + // Initialize the counter for the exported variable chatbot.stats.Add("channels", 0) chatbot.stats.Add("messages", 0) chatbot.stats.Add("received_messages", 0) @@ -87,8 +91,9 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot chatbot.stats.Add("pong", 0) chatbot.stats.Add("missed_ping", 0) chatbot.stats.Add("restart", 0) - chatbot.Init() + chatbot.stats.Add("reply_whoischannels", 0) + chatbot.Init() return chatbot } @@ -103,16 +108,17 @@ func (bot *ircBot) String() string { // Monitor that we are still connected to the IRC server // should run in go-routine // If no message is received during 60 actively ping ircBot. -// If ircBot does not reply try to reconnect -// If ircBot replied 15 (maxPongWithoutMessage) but we are still not getting -// messages there is probably something wrong so we are going to try to -// reconnect. +// If ircBot does not reply maxPingWithoutResponse times try to reconnect +// If ircBot does not replymaxPongWithoutMessage but we are still not getting +// messages there is probably something wrong try to reconnect. func (bot *ircBot) monitor() { // TODO maxPongWithoutMessage should probably be a field of ircBot + maxPingWithoutResponse := 3 maxPongWithoutMessage := 150 pongCounter := 0 + missed_ping := 0 for bot.IsRunning() { - if pongCounter > maxPongWithoutMessage { + if pongCounter > maxPongWithoutMessage || missed_ping > maxPingWithoutResponse { glog.Infoln("More than maxPongWithoutMessage pong without message for", bot) glog.Infoln("IRC monitoring KO", bot) bot.reconnect() @@ -129,35 +135,39 @@ func (bot *ircBot) monitor() { select { case <-bot.pingResponse: bot.stats.Add("pong", 1) - pongCounter += 1 + pongCounter++ if glog.V(1) { glog.Infoln("Pong from ircBot server", bot) } case <-time.After(time.Second * 10): bot.stats.Add("missed_ping", 1) glog.Infoln("No pong from ircBot server", bot) - // Do not kill the server on the first missed PONG - pongCounter += 15 + missed_ping++ + } } } } +func (bot *ircBot) whoisCollector() { + for bot.IsRunning() { + select { + case <-time.After(time.Minute * 1): + bot.Whois() + } + } +} + // reconnect the ircBot func (bot *ircBot) reconnect() { glog.Infoln("Trying to reconnect", bot) bot.stats.Add("restart", 1) - bot.Close() + err := bot.Close() + if err != nil { + glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + } time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.Init() - -} - -// Ping the server to the connection open -func (bot *ircBot) ping() { - // TODO increment number - bot.stats.Add("ping", 1) - bot.SendRaw("PING 1") } // Connect to the IRC server and start listener @@ -174,6 +184,9 @@ func (bot *ircBot) Init() { // Monitor that we are still getting incoming messages in a background thread go bot.monitor() + // Poll the the bot server to know to which channels we are connected + go bot.whoisCollector() + // Listen for outgoing messages (rate limited) in background thread if bot.sendQueue == nil { bot.sendQueue = make(chan []byte, 256) @@ -250,12 +263,11 @@ func isCertValid(conn *tls.Conn) bool { // Cert has single name, the usual case return isIPMatch(cert.Subject.CommonName, connAddr) - } else { - // Cert has several valid names - for _, certname := range cert.DNSNames { - if isIPMatch(certname, connAddr) { - return true - } + } + // Cert has several valid names + for _, certname := range cert.DNSNames { + if isIPMatch(certname, connAddr) { + return true } } @@ -304,7 +316,10 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { glog.Infoln("Changing IRC server from ", bot.address, " to ", addr) - bot.Close() + err := bot.Close() + if err != nil { + glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + } time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.address = addr @@ -361,6 +376,18 @@ func (bot *ircBot) JoinAll() { } } +// Ping the server to the connection open +func (bot *ircBot) ping() { + // TODO increment number + bot.stats.Add("ping", 1) + bot.SendRaw("PING 1") +} + +// Whois is used to query information about the bot +func (bot *ircBot) Whois() { + bot.SendRaw("WHOIS " + bot.nick) +} + // Join an IRC channel func (bot *ircBot) join(channel string) { bot.SendRaw("JOIN " + channel) @@ -417,7 +444,7 @@ func (bot *ircBot) sender() { data = <-bot.sendQueue if glog.V(1) { - glog.Infoln("[RAW"+strconv.Itoa(bot.id)+"] -->", string(data)) + glog.Infoln("[RAW", bot, "] -->", string(data)) } _, err = bot.socket.Write(data) @@ -456,7 +483,10 @@ func (bot *ircBot) listen() { } else { glog.Errorln("Lost IRC server connection. ", err) - bot.Close() + err := bot.Close() + if err != nil { + glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + } return } } @@ -468,7 +498,7 @@ func (bot *ircBot) listen() { content = toUnicode(contentData) if glog.V(2) { - glog.Infoln("[RAW" + strconv.Itoa(bot.id) + "]" + content) + glog.Infoln("[RAW", bot.String(), "]"+content) } theLine, err := parseLine(content) @@ -544,6 +574,10 @@ func (bot *ircBot) act(theLine *line.Line) { } else if theLine.Command == "VERSION" { versionMsg := "NOTICE " + theLine.User + " :\u0001VERSION " + VERSION + "\u0001\n" bot.SendRaw(versionMsg) + } else if theLine.Command == RPL_WHOISCHANNELS { + glog.Infoln("[Info] reply_whoischannels -- len:", + len(strings.Split(theLine.Content, " ")), "content:", theLine.Content) + bot.stats.Add("reply_whoischannels", int64(len(strings.Split(theLine.Content, " ")))) } bot.fromServer <- theLine @@ -588,8 +622,7 @@ func (bot *ircBot) sendShutdown() { // Split a string into sorted array of strings: // e.g. "#bob, #alice" becomes ["#alice", "#bob"] func splitChannels(rooms string) []string { - - var channels []string = make([]string, 0) + var channels = make([]string, 0) for _, s := range strings.Split(rooms, ",") { channels = append(channels, strings.TrimSpace(s)) } @@ -741,10 +774,10 @@ func toUnicode(data []byte) string { // Are a and b equal? func isEqual(a, b []*common.Channel) (flag bool) { - for _, a_cc := range a { + for _, aCc := range a { flag = false - for _, b_cc := range b { - if a_cc.Fingerprint == b_cc.Fingerprint { + for _, bCc := range b { + if aCc.Fingerprint == bCc.Fingerprint { flag = true break } @@ -757,10 +790,10 @@ func isEqual(a, b []*common.Channel) (flag bool) { } // Is a in b? container must be sorted -func isIn(a *common.Channel, container []*common.Channel) (flag bool) { +func isIn(a *common.Channel, channels []*common.Channel) (flag bool) { flag = false - for _, c_cc := range container { - if a.Fingerprint == c_cc.Fingerprint { + for _, cc := range channels { + if a.Fingerprint == cc.Fingerprint { flag = true break } diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index fd5689f..bb01761 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -179,17 +179,17 @@ func TestFlood(t *testing.T) { channels = append(channels, &common.Channel{Name: "test", Fingerprint: "uuid-string"}) chatbot := &ircBot{ - id: 99, - address: "localhost", - nick: "test", - realname: "Unit Test", - password: "test", - server_identifier: "localhost.test", - fromServer: fromServer, - channels: channels, - socket: &mockSocket, - isRunning: true, - stats: expvar.NewMap("localhost.test"), + id: 99, + address: "localhost", + nick: "test", + realname: "Unit Test", + password: "test", + serverIdentifier: "localhost.test", + fromServer: fromServer, + channels: channels, + socket: &mockSocket, + isRunning: true, + stats: expvar.NewMap("localhost.test"), } chatbot.Init() @@ -225,18 +225,18 @@ func TestUpdate(t *testing.T) { channels = append(channels, &channel) chatbot := &ircBot{ - id: 99, - address: "localhost", - nick: "test", - realname: "Unit Test", - password: "test", - server_identifier: "localhost.test1", - fromServer: fromServer, - channels: channels, - socket: &mockSocket, - sendQueue: make(chan []byte, 100), - isRunning: true, - stats: expvar.NewMap("localhost.test1"), + id: 99, + address: "localhost", + nick: "test", + realname: "Unit Test", + password: "test", + serverIdentifier: "localhost.test1", + fromServer: fromServer, + channels: channels, + socket: &mockSocket, + sendQueue: make(chan []byte, 100), + isRunning: true, + stats: expvar.NewMap("localhost.test1"), } // Rate limiting requires a go-routine to actually do the sending go chatbot.sender() From aa66850e4a7b8ccec55634dbe52e6e1b4d26cd04 Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Tue, 17 Jun 2014 08:23:06 -0400 Subject: [PATCH 28/76] Added defer before unlock --- network/network.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/network/network.go b/network/network.go index af1f5fd..051a4cb 100644 --- a/network/network.go +++ b/network/network.go @@ -46,7 +46,7 @@ func (nm *NetworkManager) GetUserByChatbotId(id int) string { // Connect to networks / start chatbots. Loads chatbot configuration from DB. func (nm *NetworkManager) RefreshChatbots() { nm.Lock() - nm.Unlock() + defer nm.Unlock() if glog.V(2) { glog.Infoln("Entering in NetworkManager.RefreshChatbots") } From 11f5442f9aa917ff3077037291aef685316614d7 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 17 Jun 2014 20:09:08 +0200 Subject: [PATCH 29/76] Fix an issue on the method comparing the channels. --- network/irc/irc.go | 25 +++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index f1638ef..29ab9ba 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -774,19 +774,24 @@ func toUnicode(data []byte) string { // Are a and b equal? func isEqual(a, b []*common.Channel) (flag bool) { - for _, aCc := range a { - flag = false - for _, bCc := range b { - if aCc.Fingerprint == bCc.Fingerprint { - flag = true - break + if len(a) == len(b) { + for _, aCc := range a { + flag = false + for _, bCc := range b { + aCc.Name, aCc.Fingerprint, "==", bCc.Name, bCc.Fingerprint) + if aCc.Fingerprint == bCc.Fingerprint { + flag = true + break + } + } + if flag == false { + return flag } } - if flag == false { - return flag - } + return true + } else { + return false } - return true } // Is a in b? container must be sorted From 9a464e24706291783260a1e560c978f541e9d699 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 17 Jun 2014 20:25:06 +0200 Subject: [PATCH 30/76] Oups this line should have been deleted in my previous commit --- network/irc/irc.go | 1 - 1 file changed, 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 29ab9ba..7af76e4 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -778,7 +778,6 @@ func isEqual(a, b []*common.Channel) (flag bool) { for _, aCc := range a { flag = false for _, bCc := range b { - aCc.Name, aCc.Fingerprint, "==", bCc.Name, bCc.Fingerprint) if aCc.Fingerprint == bCc.Fingerprint { flag = true break From ce577dd2313e3bd64c2b7833aa6f2b5728c42f6d Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 19 Jun 2014 12:34:09 +0200 Subject: [PATCH 31/76] Fix a bunch of races in the test suite. Added a Field on the ircBot struct to store the rateLimit. --- common/mock.go | 22 ++++++++++++++++------ common/queue.go | 26 +++++++++++++++++--------- main_test.go | 11 ++++++++--- network/irc/irc.go | 7 ++++--- network/irc/irc_test.go | 27 ++++++++++++++++++++------- 5 files changed, 65 insertions(+), 28 deletions(-) diff --git a/common/mock.go b/common/mock.go index 343e606..25b2967 100644 --- a/common/mock.go +++ b/common/mock.go @@ -3,6 +3,7 @@ package common import ( "bufio" "net" + "sync" "testing" ) @@ -11,6 +12,7 @@ import ( */ type MockIRCServer struct { + sync.RWMutex Port string Message string Got []string @@ -24,11 +26,17 @@ func NewMockIRCServer(msg, port string) *MockIRCServer { } } -func (self *MockIRCServer) Run(t *testing.T) { +func (srv *MockIRCServer) GotLength() int { + srv.RLock() + defer srv.RUnlock() + return len(srv.Got) +} + +func (srv *MockIRCServer) Run(t *testing.T) { - listener, err := net.Listen("tcp", ":"+self.Port) + listener, err := net.Listen("tcp", ":"+srv.Port) if err != nil { - t.Error("Error starting mock server on "+self.Port, err) + t.Error("Error starting mock server on "+srv.Port, err) return } @@ -48,8 +56,8 @@ func (self *MockIRCServer) Run(t *testing.T) { conn.Write([]byte(":wolfe.freenode.net 001 graham_king :Welcome to the freenode Internet Relay Chat Network graham_king\n")) // This should get sent to plugins - conn.Write([]byte(":yml!~yml@li148-151.members.linode.com PRIVMSG #unit :" + self.Message + "\n")) - //conn.Write([]byte("test: " + self.Message + "\n")) + conn.Write([]byte(":yml!~yml@li148-151.members.linode.com PRIVMSG #unit :" + srv.Message + "\n")) + //conn.Write([]byte("test: " + srv.Message + "\n")) var derr error var data []byte @@ -61,7 +69,9 @@ func (self *MockIRCServer) Run(t *testing.T) { // Client closed connection break } - self.Got = append(self.Got, string(data)) + srv.Lock() + srv.Got = append(srv.Got, string(data)) + srv.Unlock() } } diff --git a/common/queue.go b/common/queue.go index feee8b6..c64558f 100644 --- a/common/queue.go +++ b/common/queue.go @@ -4,9 +4,10 @@ import ( "net" "net/url" "os" - "time" "strconv" "strings" + "sync" + "time" "github.com/golang/glog" "github.com/monnand/goredis" @@ -40,6 +41,7 @@ type Queue interface { // Simplistic Queue implementation used by the test suite type MockQueue struct { + sync.RWMutex Got map[string][]string ReadChannel chan string } @@ -51,23 +53,29 @@ func NewMockQueue() *MockQueue { } } -func (self *MockQueue) Publish(queue string, message []byte) error { - self.Got[queue] = append(self.Got[queue], string(message)) +func (mq *MockQueue) Publish(queue string, message []byte) error { + mq.Lock() + defer mq.Unlock() + mq.Got[queue] = append(mq.Got[queue], string(message)) return nil } -func (self *MockQueue) Rpush(key string, val []byte) error { - self.Got[key] = append(self.Got[key], string(val)) +func (mq *MockQueue) Rpush(key string, val []byte) error { + mq.Lock() + defer mq.Unlock() + mq.Got[key] = append(mq.Got[key], string(val)) return nil } -func (self *MockQueue) Blpop(keys []string, timeoutsecs uint) (*string, []byte, error) { - val := <-self.ReadChannel +func (mq *MockQueue) Blpop(keys []string, timeoutsecs uint) (*string, []byte, error) { + val := <-mq.ReadChannel return &keys[0], []byte(val), nil } -func (self *MockQueue) Llen(key string) (int, error) { - return len(self.Got), nil +func (mq *MockQueue) Llen(key string) (int, error) { + mq.RLock() + defer mq.RUnlock() + return len(mq.Got), nil } func (self *MockQueue) Ltrim(key string, start int, end int) error { diff --git a/main_test.go b/main_test.go index df0c0d8..7fc7f23 100644 --- a/main_test.go +++ b/main_test.go @@ -1,10 +1,11 @@ package main import ( - "github.com/BotBotMe/botbot-bot/common" "strings" "testing" "time" + + "github.com/BotBotMe/botbot-bot/common" ) const ( @@ -36,7 +37,11 @@ func TestBotBotIRC(t *testing.T) { queue.ReadChannel <- "WRITE 1 #unit I am a plugin response" waitForServer(server, 6) - checkContains(queue.Got["q"], TEST_MSG, t) + queue.RLock() + q := queue.Got["q"] + queue.RUnlock() + + checkContains(q, TEST_MSG, t) // Check IRC server expectations @@ -68,7 +73,7 @@ func TestBotBotIRC(t *testing.T) { func waitForServer(target *common.MockIRCServer, val int) { tries := 0 - for len(target.Got) < val && tries < 30 { + for target.GotLength() < val && tries < 30 { time.Sleep(200 * time.Millisecond) tries++ } diff --git a/network/irc/irc.go b/network/irc/irc.go index 7af76e4..05ff3cf 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -44,6 +44,7 @@ type ircBot struct { password string serverPass string serverIdentifier string + rateLimit time.Duration // Duration used to rate limit send channels []*common.Channel isRunning bool isConnecting bool @@ -73,6 +74,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot password: config.Config["password"], // NickServ password serverPass: config.Config["server_password"], // PASS password serverIdentifier: config.Config["server_identifier"], + rateLimit: time.Second, fromServer: fromServer, channels: config.Channels, monitorChan: make(chan struct{}), @@ -141,8 +143,8 @@ func (bot *ircBot) monitor() { } case <-time.After(time.Second * 10): bot.stats.Add("missed_ping", 1) - glog.Infoln("No pong from ircBot server", bot) missed_ping++ + glog.Infoln("No pong from ircBot server", bot, "missed", missed_ping) } } @@ -437,7 +439,6 @@ func (bot *ircBot) sendPassword() { func (bot *ircBot) sender() { var data []byte - var tempo = time.Second * 1 var err error for bot.IsRunning() { @@ -456,7 +457,7 @@ func (bot *ircBot) sender() { // Rate limit to one message every tempo // https://github.com/BotBotMe/botbot-bot/issues/2 - time.Sleep(tempo) + time.Sleep(bot.rateLimit) } } diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index bb01761..3cd9e43 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -4,6 +4,7 @@ import ( "expvar" "strconv" "strings" + "sync" "testing" "time" @@ -146,27 +147,38 @@ func TestParseLine_353(t *testing.T) { // Dummy implementation of ReadWriteCloser type MockSocket struct { + sync.RWMutex received []string counter chan bool } -func (self *MockSocket) Write(data []byte) (int, error) { - self.received = append(self.received, string(data)) - if self.counter != nil { - self.counter <- true +func (sock *MockSocket) Write(data []byte) (int, error) { + sock.Lock() + defer sock.Unlock() + sock.received = append(sock.received, string(data)) + if sock.counter != nil { + sock.counter <- true } return len(data), nil } -func (self *MockSocket) Read(into []byte) (int, error) { +func (sock *MockSocket) Read(into []byte) (int, error) { + sock.RLock() + defer sock.RUnlock() time.Sleep(time.Second) // Prevent busy loop return 0, nil } -func (self *MockSocket) Close() error { +func (sock *MockSocket) Close() error { return nil } +func (sock *MockSocket) receivedLength() int { + sock.RLock() + defer sock.RUnlock() + return len(sock.received) +} + // Test sending messages too fast func TestFlood(t *testing.T) { @@ -185,6 +197,7 @@ func TestFlood(t *testing.T) { realname: "Unit Test", password: "test", serverIdentifier: "localhost.test", + rateLimit: time.Second, fromServer: fromServer, channels: channels, socket: &mockSocket, @@ -251,7 +264,7 @@ func TestUpdate(t *testing.T) { // Wait a bit for i := 0; i < 10; i++ { time.Sleep(time.Second / 3) - if len(mockSocket.received) >= 1 { + if mockSocket.receivedLength() >= 1 { break } } From ebbbda0ac184cc37aae7bbc4e5932877c383b1a4 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 19 Jun 2014 13:26:29 +0200 Subject: [PATCH 32/76] Use my protected method GotLength() instead of directly taking the lenght --- main_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/main_test.go b/main_test.go index 7fc7f23..b041a26 100644 --- a/main_test.go +++ b/main_test.go @@ -45,8 +45,8 @@ func TestBotBotIRC(t *testing.T) { // Check IRC server expectations - if len(server.Got) != 6 { - t.Fatal("Expected exactly 6 IRC messages from the bot. Got ", len(server.Got)) + if server.GotLength() != 6 { + t.Fatal("Expected exactly 6 IRC messages from the bot. Got ", server.GotLength()) } expect := []string{"PING", "USER", "NICK", "NickServ", "JOIN", "PRIVMSG"} From 0af55d51c3bc2b8877114ec62476566f0557dc21 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 19 Jun 2014 14:04:22 +0200 Subject: [PATCH 33/76] Continue to fix race condition in the test suite --- main_test.go | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/main_test.go b/main_test.go index b041a26..1430197 100644 --- a/main_test.go +++ b/main_test.go @@ -13,6 +13,13 @@ const ( TEST_MSG = "q: Something new" ) +func GetQueueLength(queue *common.MockQueue) int { + queue.RLock() + q := queue.Got["q"] + queue.RUnlock() + return len(q) +} + // A serious integration test for BotBot. // This covers BotBot, the IRC code, and the dispatcher. func TestBotBotIRC(t *testing.T) { @@ -61,19 +68,21 @@ func TestBotBotIRC(t *testing.T) { botbot.shutdown() tries := 0 - for len(queue.Got["q"]) < 4 && tries < 20 { - time.Sleep(50 * time.Millisecond) + for GetQueueLength(queue) < 4 && tries < 20 { + time.Sleep(100 * time.Millisecond) tries++ } + queue.RLock() checkContains(queue.Got["q"], "SHUTDOWN", t) + queue.RUnlock() } // Block until len(target.Get) is at least val, or timeout func waitForServer(target *common.MockIRCServer, val int) { tries := 0 - for target.GotLength() < val && tries < 30 { + for target.GotLength() < val && tries < 60 { time.Sleep(200 * time.Millisecond) tries++ } From b39692bf1d80be5b0d9ff28816e9b85d1c6ae2ae Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 19 Jun 2014 15:36:47 +0200 Subject: [PATCH 34/76] Increate the number of tries before belling out --- main_test.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/main_test.go b/main_test.go index 1430197..eac5633 100644 --- a/main_test.go +++ b/main_test.go @@ -68,8 +68,8 @@ func TestBotBotIRC(t *testing.T) { botbot.shutdown() tries := 0 - for GetQueueLength(queue) < 4 && tries < 20 { - time.Sleep(100 * time.Millisecond) + for GetQueueLength(queue) < 4 && tries < 100 { + time.Sleep(50 * time.Millisecond) tries++ } @@ -82,8 +82,8 @@ func TestBotBotIRC(t *testing.T) { func waitForServer(target *common.MockIRCServer, val int) { tries := 0 - for target.GotLength() < val && tries < 60 { - time.Sleep(200 * time.Millisecond) + for target.GotLength() < val && tries < 100 { + time.Sleep(50 * time.Millisecond) tries++ } } From 79286be801726a8cba289ca1c5baca3f59b8ef0d Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 19 Jun 2014 15:42:45 +0200 Subject: [PATCH 35/76] An even larger number of tries to support slow server --- main_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/main_test.go b/main_test.go index eac5633..6e00508 100644 --- a/main_test.go +++ b/main_test.go @@ -68,7 +68,7 @@ func TestBotBotIRC(t *testing.T) { botbot.shutdown() tries := 0 - for GetQueueLength(queue) < 4 && tries < 100 { + for GetQueueLength(queue) < 4 && tries < 200 { time.Sleep(50 * time.Millisecond) tries++ } @@ -82,7 +82,7 @@ func TestBotBotIRC(t *testing.T) { func waitForServer(target *common.MockIRCServer, val int) { tries := 0 - for target.GotLength() < val && tries < 100 { + for target.GotLength() < val && tries < 200 { time.Sleep(50 * time.Millisecond) tries++ } From 59801dc6a069df35832d13b2c794b4c2695a5b69 Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Thu, 19 Jun 2014 12:46:24 -0400 Subject: [PATCH 36/76] Fixing mock irc server to handle tls connect correctly. --- common/mock.go | 53 ++++++++++++++++++++++++++++---------------------- 1 file changed, 30 insertions(+), 23 deletions(-) diff --git a/common/mock.go b/common/mock.go index 343e606..dfaa162 100644 --- a/common/mock.go +++ b/common/mock.go @@ -32,36 +32,43 @@ func (self *MockIRCServer) Run(t *testing.T) { return } - // Accept a single connection - conn, lerr := listener.Accept() - if lerr != nil { - t.Error("Error on IRC server on Accept. ", err) - } + for { + conn, lerr := listener.Accept() + // If create a new connection throw the old data away + // This can happen if a client trys to connect with tls + // Got will store the handshake data. The cient will try + // connect with a plaintext connect after the tls fails. + self.Got = make([]string, 0) - // First message triggers BotBot to send USER and NICK messages - conn.Write([]byte(":hybrid7.debian.local NOTICE AUTH :*** Looking up your hostname...\n")) + if lerr != nil { + t.Error("Error on IRC server on Accept. ", err) + } - // Ask for NickServ auth, and pretend we got it - conn.Write([]byte(":NickServ!NickServ@services. NOTICE graham_king :This nickname is registered. Please choose a different nickname, or identify via /msg NickServ identify \n")) - conn.Write([]byte(":NickServ!NickServ@services. NOTICE graham_king :You are now identified for graham_king.\n")) + // First message triggers BotBot to send USER and NICK messages + conn.Write([]byte(":hybrid7.debian.local NOTICE AUTH :*** Looking up your hostname...\n")) - conn.Write([]byte(":wolfe.freenode.net 001 graham_king :Welcome to the freenode Internet Relay Chat Network graham_king\n")) + // Ask for NickServ auth, and pretend we got it + conn.Write([]byte(":NickServ!NickServ@services. NOTICE graham_king :This nickname is registered. Please choose a different nickname, or identify via /msg NickServ identify \n")) + conn.Write([]byte(":NickServ!NickServ@services. NOTICE graham_king :You are now identified for graham_king.\n")) - // This should get sent to plugins - conn.Write([]byte(":yml!~yml@li148-151.members.linode.com PRIVMSG #unit :" + self.Message + "\n")) - //conn.Write([]byte("test: " + self.Message + "\n")) + conn.Write([]byte(":wolfe.freenode.net 001 graham_king :Welcome to the freenode Internet Relay Chat Network graham_king\n")) - var derr error - var data []byte + // This should get sent to plugins + conn.Write([]byte(":yml!~yml@li148-151.members.linode.com PRIVMSG #unit :" + self.Message + "\n")) + //conn.Write([]byte("test: " + self.Message + "\n")) - bufRead := bufio.NewReader(conn) - for { - data, derr = bufRead.ReadBytes('\n') - if derr != nil { - // Client closed connection - break + var derr error + var data []byte + + bufRead := bufio.NewReader(conn) + for { + data, derr = bufRead.ReadBytes('\n') + if derr != nil { + // Client closed connection + break + } + self.Got = append(self.Got, string(data)) } - self.Got = append(self.Got, string(data)) } } From 1e338c9e10092b0ede762ffb7c2d7686b97b61ed Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Fri, 20 Jun 2014 22:07:49 +0200 Subject: [PATCH 37/76] improve the ChatBot expvar stats --- network/irc/irc.go | 79 +++++++++++++++++++++++++++++------------ network/irc/irc_test.go | 3 -- 2 files changed, 57 insertions(+), 25 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 05ff3cf..cdda838 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -34,6 +34,27 @@ const ( RPL_WHOISCHANNELS = "319" ) +type chatBotStats struct { + sync.Mutex + m map[string]*expvar.Map +} + +func (s chatBotStats) GetOrCreate(identifier string) (*expvar.Map, bool) { + s.Lock() + defer s.Unlock() + chatbotStats, ok := s.m[identifier] + if !ok { + chatbotStats = expvar.NewMap(identifier) + s.m[identifier] = chatbotStats + } + return chatbotStats, ok + +} + +var ( + BotStats = chatBotStats{m: make(map[string]*expvar.Map)} +) + type ircBot struct { sync.RWMutex id int @@ -54,7 +75,6 @@ type ircBot struct { monitorChan chan struct{} pingResponse chan struct{} reconnectChan chan struct{} - stats *expvar.Map } // NewBot create an irc instance of ChatBot @@ -83,17 +103,19 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot isRunning: true, } - chatbot.stats = expvar.NewMap(chatbot.serverIdentifier) + chatbotStats, ok := BotStats.GetOrCreate(chatbot.serverIdentifier) // Initialize the counter for the exported variable - chatbot.stats.Add("channels", 0) - chatbot.stats.Add("messages", 0) - chatbot.stats.Add("received_messages", 0) - chatbot.stats.Add("ping", 0) - chatbot.stats.Add("pong", 0) - chatbot.stats.Add("missed_ping", 0) - chatbot.stats.Add("restart", 0) - chatbot.stats.Add("reply_whoischannels", 0) + if !ok { + chatbotStats.Add("channels", 0) + chatbotStats.Add("messages", 0) + chatbotStats.Add("received_messages", 0) + chatbotStats.Add("ping", 0) + chatbotStats.Add("pong", 0) + chatbotStats.Add("missed_ping", 0) + chatbotStats.Add("restart", 0) + chatbotStats.Add("reply_whoischannels", 0) + } chatbot.Init() return chatbot @@ -103,6 +125,11 @@ func (bot *ircBot) GetUser() string { return bot.nick } +func (bot *ircBot) GetStats() *expvar.Map { + stats, _ := BotStats.GetOrCreate(bot.serverIdentifier) + return stats +} + func (bot *ircBot) String() string { return fmt.Sprintf("%s on %s", bot.nick, bot.address) } @@ -110,11 +137,12 @@ func (bot *ircBot) String() string { // Monitor that we are still connected to the IRC server // should run in go-routine // If no message is received during 60 actively ping ircBot. -// If ircBot does not reply maxPingWithoutResponse times try to reconnect -// If ircBot does not replymaxPongWithoutMessage but we are still not getting -// messages there is probably something wrong try to reconnect. +// If ircBot does not ly maxPingWithoutResponse times try to reconnect +// If ircBot does replymaxPongWithoutMessage but we are still not getting +// is probably something wrong try to reconnect. func (bot *ircBot) monitor() { // TODO maxPongWithoutMessage should probably be a field of ircBot + botStats := bot.GetStats() maxPingWithoutResponse := 3 maxPongWithoutMessage := 150 pongCounter := 0 @@ -136,13 +164,13 @@ func (bot *ircBot) monitor() { bot.ping() select { case <-bot.pingResponse: - bot.stats.Add("pong", 1) + botStats.Add("pong", 1) pongCounter++ if glog.V(1) { glog.Infoln("Pong from ircBot server", bot) } case <-time.After(time.Second * 10): - bot.stats.Add("missed_ping", 1) + botStats.Add("missed_ping", 1) missed_ping++ glog.Infoln("No pong from ircBot server", bot, "missed", missed_ping) @@ -163,7 +191,8 @@ func (bot *ircBot) whoisCollector() { // reconnect the ircBot func (bot *ircBot) reconnect() { glog.Infoln("Trying to reconnect", bot) - bot.stats.Add("restart", 1) + botStats := bot.GetStats() + botStats.Add("restart", 1) err := bot.Close() if err != nil { glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) @@ -381,7 +410,8 @@ func (bot *ircBot) JoinAll() { // Ping the server to the connection open func (bot *ircBot) ping() { // TODO increment number - bot.stats.Add("ping", 1) + botStats := bot.GetStats() + botStats.Add("ping", 1) bot.SendRaw("PING 1") } @@ -393,13 +423,15 @@ func (bot *ircBot) Whois() { // Join an IRC channel func (bot *ircBot) join(channel string) { bot.SendRaw("JOIN " + channel) - bot.stats.Add("channels", 1) + botStats := bot.GetStats() + botStats.Add("channels", 1) } // Leave an IRC channel func (bot *ircBot) part(channel string) { bot.SendRaw("PART " + channel) - bot.stats.Add("channels", -1) + botStats := bot.GetStats() + botStats.Add("channels", -1) } // Send a regular (non-system command) IRC message @@ -453,7 +485,8 @@ func (bot *ircBot) sender() { glog.Errorln("Error writing to socket to", bot, ": ", err) bot.reconnect() } - bot.stats.Add("messages", 1) + botStats := bot.GetStats() + botStats.Add("messages", 1) // Rate limit to one message every tempo // https://github.com/BotBotMe/botbot-bot/issues/2 @@ -504,7 +537,8 @@ func (bot *ircBot) listen() { theLine, err := parseLine(content) if err == nil { - bot.stats.Add("received_messages", 1) + botStats := bot.GetStats() + botStats.Add("received_messages", 1) theLine.ChatBotId = bot.id bot.act(theLine) } else { @@ -578,7 +612,8 @@ func (bot *ircBot) act(theLine *line.Line) { } else if theLine.Command == RPL_WHOISCHANNELS { glog.Infoln("[Info] reply_whoischannels -- len:", len(strings.Split(theLine.Content, " ")), "content:", theLine.Content) - bot.stats.Add("reply_whoischannels", int64(len(strings.Split(theLine.Content, " ")))) + botStats := bot.GetStats() + botStats.Add("reply_whoischannels", int64(len(strings.Split(theLine.Content, " ")))) } bot.fromServer <- theLine diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 3cd9e43..4e21bf9 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -1,7 +1,6 @@ package irc import ( - "expvar" "strconv" "strings" "sync" @@ -202,7 +201,6 @@ func TestFlood(t *testing.T) { channels: channels, socket: &mockSocket, isRunning: true, - stats: expvar.NewMap("localhost.test"), } chatbot.Init() @@ -249,7 +247,6 @@ func TestUpdate(t *testing.T) { socket: &mockSocket, sendQueue: make(chan []byte, 100), isRunning: true, - stats: expvar.NewMap("localhost.test1"), } // Rate limiting requires a go-routine to actually do the sending go chatbot.sender() From f3a15cb7c6fa0bb8f22f035946cd763e60e11ff4 Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Sat, 21 Jun 2014 05:49:40 -0400 Subject: [PATCH 38/76] Enable pprof --- main.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/main.go b/main.go index a0b2a57..9bf049f 100644 --- a/main.go +++ b/main.go @@ -11,6 +11,8 @@ import ( "github.com/BotBotMe/botbot-bot/common" "github.com/golang/glog" + _ "net/http/pprof" + ) const ( From f4c1d333b80f4f8a88c8a3fd6c1e9a9873022236 Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Sat, 21 Jun 2014 06:34:34 -0400 Subject: [PATCH 39/76] Add a .gitignore --- .gitignore | 1 + 1 file changed, 1 insertion(+) create mode 100644 .gitignore diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..4c49bd7 --- /dev/null +++ b/.gitignore @@ -0,0 +1 @@ +.env From b5f8157b59648db9c9ea8efe9ad60d55bb3d88af Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Sat, 21 Jun 2014 06:38:15 -0400 Subject: [PATCH 40/76] Move to a buffered channel till we refactor monitor() --- network/irc/irc.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 05ff3cf..d58b5ea 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -78,7 +78,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot fromServer: fromServer, channels: config.Channels, monitorChan: make(chan struct{}), - pingResponse: make(chan struct{}), + pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock reconnectChan: make(chan struct{}), isRunning: true, } From 1daf637c399f178b65f1ed13ffda1cf4f8880e32 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 23 Jun 2014 12:46:33 +0200 Subject: [PATCH 41/76] Itermediary changeset this is an improvement over the exisiting code base but there is still some edge cases when trying to reconnect bot.reconnect() --- botbot.go | 3 +- common/common.go | 2 +- network/irc/irc.go | 209 ++++++++++++++++++++++------------------ network/irc/irc_test.go | 2 - network/network.go | 26 ++--- 5 files changed, 131 insertions(+), 111 deletions(-) diff --git a/botbot.go b/botbot.go index f9a92bf..7bad1d0 100644 --- a/botbot.go +++ b/botbot.go @@ -35,7 +35,8 @@ func NewBotBot(storage common.Storage, queue common.Queue) *BotBot { netMan := network.NewNetworkManager(storage, fromServer) netMan.RefreshChatbots() - go netMan.MonitorChatbots() + // TODO (yml) We might be able to get rid of this goroutine + //go netMan.MonitorChatbots() dis := dispatch.NewDispatcher(queue) diff --git a/common/common.go b/common/common.go index 478218e..52d6ffb 100644 --- a/common/common.go +++ b/common/common.go @@ -10,7 +10,7 @@ type ChatBot interface { io.Closer Send(channel, msg string) Update(config *BotConfig) - IsRunning() bool + //IsRunning() bool GetUser() string } diff --git a/network/irc/irc.go b/network/irc/irc.go index 626b92a..e430918 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -67,7 +67,6 @@ type ircBot struct { serverIdentifier string rateLimit time.Duration // Duration used to rate limit send channels []*common.Channel - isRunning bool isConnecting bool isAuthenticating bool sendQueue chan []byte @@ -75,6 +74,7 @@ type ircBot struct { monitorChan chan struct{} pingResponse chan struct{} reconnectChan chan struct{} + closing chan struct{} } // NewBot create an irc instance of ChatBot @@ -86,6 +86,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot realname = config.Config["nick"] } + // Initialize the bot. chatbot := &ircBot{ id: config.Id, address: config.Config["server"], @@ -100,7 +101,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock reconnectChan: make(chan struct{}), - isRunning: true, + closing: make(chan struct{}), } chatbotStats, ok := BotStats.GetOrCreate(chatbot.serverIdentifier) @@ -141,47 +142,61 @@ func (bot *ircBot) String() string { // If ircBot does replymaxPongWithoutMessage but we are still not getting // is probably something wrong try to reconnect. func (bot *ircBot) monitor() { - // TODO maxPongWithoutMessage should probably be a field of ircBot + var pingTimeout <-chan time.Time + reconnect := make(chan struct{}) botStats := bot.GetStats() + // TODO maxPongWithoutMessage should probably be a field of ircBot maxPingWithoutResponse := 3 maxPongWithoutMessage := 150 pongCounter := 0 missed_ping := 0 - for bot.IsRunning() { - if pongCounter > maxPongWithoutMessage || missed_ping > maxPingWithoutResponse { - glog.Infoln("More than maxPongWithoutMessage pong without message for", bot) + for { + select { + case <-bot.closing: + break + case <-reconnect: glog.Infoln("IRC monitoring KO", bot) bot.reconnect() - } - select { case <-bot.monitorChan: pongCounter = 0 + // Deactivate the pingTimeout case + pingTimeout = nil if glog.V(2) { - glog.Infoln("Message received from the server for", bot) + glog.Infoln("[Info] Message received from the server for", bot) } case <-time.After(time.Second * 60): - glog.Infoln("Ping the ircBot server", pongCounter, bot) - bot.ping() - select { - case <-bot.pingResponse: - botStats.Add("pong", 1) - pongCounter++ - if glog.V(1) { - glog.Infoln("Pong from ircBot server", bot) - } - case <-time.After(time.Second * 10): - botStats.Add("missed_ping", 1) - missed_ping++ - glog.Infoln("No pong from ircBot server", bot, "missed", missed_ping) - + glog.Infoln("[Info] Ping the ircBot server", pongCounter, bot) + botStats.Add("ping", 1) + bot.SendRaw("PING 1") + // Activate the ping timeout case + pingTimeout = time.After(time.Second * 10) + case <-bot.pingResponse: + botStats.Add("pong", 1) + pongCounter++ + if glog.V(1) { + glog.Infoln("[Info] Pong from ircBot server", bot) + } + if pongCounter > maxPongWithoutMessage { + close(reconnect) + } + case <-pingTimeout: + // Deactivate the pingTimeout case + pingTimeout = nil + botStats.Add("missed_ping", 1) + missed_ping++ + glog.Infoln("[Info] No pong from ircBot server", bot, "missed", missed_ping) + if missed_ping > maxPingWithoutResponse { + close(reconnect) } } } } func (bot *ircBot) whoisCollector() { - for bot.IsRunning() { + for { select { + case <-bot.closing: + return case <-time.After(time.Minute * 1): bot.Whois() } @@ -203,7 +218,9 @@ func (bot *ircBot) reconnect() { // Connect to the IRC server and start listener func (bot *ircBot) Init() { - + bot.Lock() + defer bot.Unlock() + bot.closing = make(chan struct{}) bot.isConnecting = true bot.isAuthenticating = false @@ -351,7 +368,8 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { if err != nil { glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) } - time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped + // TODO (yml) remove + // time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.address = addr bot.nick = config.Config["nick"] @@ -407,14 +425,6 @@ func (bot *ircBot) JoinAll() { } } -// Ping the server to the connection open -func (bot *ircBot) ping() { - // TODO increment number - botStats := bot.GetStats() - botStats.Add("ping", 1) - bot.SendRaw("PING 1") -} - // Whois is used to query information about the bot func (bot *ircBot) Whois() { bot.SendRaw("WHOIS " + bot.nick) @@ -469,28 +479,38 @@ func (bot *ircBot) sendPassword() { // Actually really send message to the server. Implements rate limiting. // Should run in go-routine. func (bot *ircBot) sender() { - - var data []byte var err error + reconnect := make(chan struct{}) + botStats := bot.GetStats() - for bot.IsRunning() { + for { + select { + case <-bot.closing: + // TODO(yml): may be we should have a grace period to let the bot + // a chance to send the message in the buffer + return + case <-reconnect: + bot.reconnect() + // Rate limit to one message every tempo + // // https://github.com/BotBotMe/botbot-bot/issues/2 + case <-time.After(bot.rateLimit): + select { + case data := <-bot.sendQueue: - data = <-bot.sendQueue - if glog.V(1) { - glog.Infoln("[RAW", bot, "] -->", string(data)) - } + if glog.V(1) { + glog.Infoln("[RAW", bot, "] -->", string(data)) + } - _, err = bot.socket.Write(data) - if err != nil { - glog.Errorln("Error writing to socket to", bot, ": ", err) - bot.reconnect() + _, err = bot.socket.Write(data) + if err != nil { + glog.Errorln("[Error] Error writing to socket to", bot, ": ", err) + close(reconnect) + } + botStats.Add("messages", 1) + default: + // Do not block waiting for message to send + } } - botStats := bot.GetStats() - botStats.Add("messages", 1) - - // Rate limit to one message every tempo - // https://github.com/BotBotMe/botbot-bot/issues/2 - time.Sleep(bot.rateLimit) } } @@ -503,48 +523,48 @@ func (bot *ircBot) listen() { var err error bufRead := bufio.NewReader(bot.socket) - for bot.IsRunning() { - contentData, err = bufRead.ReadBytes('\n') + for { + select { + case <-bot.closing: + return + default: + contentData, err = bufRead.ReadBytes('\n') + + if err != nil { + netErr, ok := err.(net.Error) + if ok && netErr.Timeout() == true { + continue + } else { + glog.Errorln("Lost IRC server connection. ", err) + err := bot.Close() + if err != nil { + glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + } + return + } + } - if err != nil { - netErr, ok := err.(net.Error) - if ok && netErr.Timeout() == true { + if len(contentData) == 0 { continue - - } else if !bot.IsRunning() { - // Close() wants us to stop - return - - } else { - glog.Errorln("Lost IRC server connection. ", err) - err := bot.Close() - if err != nil { - glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) - } - return } - } - if len(contentData) == 0 { - continue - } + content = toUnicode(contentData) - content = toUnicode(contentData) + if glog.V(2) { + glog.Infoln("[RAW", bot.String(), "]"+content) + } - if glog.V(2) { - glog.Infoln("[RAW", bot.String(), "]"+content) - } + theLine, err := parseLine(content) + if err == nil { + botStats := bot.GetStats() + botStats.Add("received_messages", 1) + theLine.ChatBotId = bot.id + bot.act(theLine) + } else { + glog.Errorln("Invalid line:", content) + } - theLine, err := parseLine(content) - if err == nil { - botStats := bot.GetStats() - botStats.Add("received_messages", 1) - theLine.ChatBotId = bot.id - bot.act(theLine) - } else { - glog.Errorln("Invalid line:", content) } - } } @@ -619,17 +639,16 @@ func (bot *ircBot) act(theLine *line.Line) { bot.fromServer <- theLine } -func (bot *ircBot) IsRunning() bool { - bot.RLock() - defer bot.RUnlock() - return bot.isRunning -} - // Close ircBot func (bot *ircBot) Close() error { - bot.Lock() - defer bot.Unlock() - bot.isRunning = false + // Send a signal to all goroutine to return + select { + case <-bot.closing: + glog.Infoln("[Info] already bot.closing is already closed closed") + default: + close(bot.closing) + } + bot.sendShutdown() return bot.socket.Close() } @@ -637,6 +656,8 @@ func (bot *ircBot) Close() error { // Send a non-standard SHUTDOWN message to the plugins // This allows them to know that this channel is offline func (bot *ircBot) sendShutdown() { + bot.Lock() + defer bot.Unlock() shutLine := &line.Line{ Command: "SHUTDOWN", Received: time.Now().UTC().Format(time.RFC3339Nano), diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 4e21bf9..5b9fb33 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -200,7 +200,6 @@ func TestFlood(t *testing.T) { fromServer: fromServer, channels: channels, socket: &mockSocket, - isRunning: true, } chatbot.Init() @@ -246,7 +245,6 @@ func TestUpdate(t *testing.T) { channels: channels, socket: &mockSocket, sendQueue: make(chan []byte, 100), - isRunning: true, } // Rate limiting requires a go-routine to actually do the sending go chatbot.sender() diff --git a/network/network.go b/network/network.go index 051a4cb..3c0968b 100644 --- a/network/network.go +++ b/network/network.go @@ -3,7 +3,6 @@ package network import ( "sort" "sync" - "time" "github.com/golang/glog" @@ -109,18 +108,19 @@ func (nm *NetworkManager) Send(chatbotId int, channel, msg string) { nm.RUnlock() } -// Check out chatbots are alive, recreating them if not. Run this in go-routine. -func (nm *NetworkManager) MonitorChatbots() { - - for nm.IsRunning() { - for id, bot := range nm.chatbots { - if !bot.IsRunning() { - nm.restart(id) - } - } - time.Sleep(1 * time.Second) - } -} +// TODO(yml) find out if this is needed since we deal with it at the IRC level +// // Check out chatbots are alive, recreating them if not. Run this in go-routine. +// func (nm *NetworkManager) MonitorChatbots() { +// +// for nm.IsRunning() { +// for id, bot := range nm.chatbots { +// if !bot.IsRunning() { +// nm.restart(id) +// } +// } +// time.Sleep(1 * time.Second) +// } +// } // get a chatbot by id func (nm *NetworkManager) getChatbotById(id int) common.ChatBot { From 85f4f7c126fabe017a7b64b5dfa9cfdca1a97252 Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Mon, 23 Jun 2014 08:15:55 -0400 Subject: [PATCH 42/76] Break out read socket in to its goroutine --- network/irc/irc.go | 80 +++++++++++++++++++++++++++------------------- 1 file changed, 47 insertions(+), 33 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index e430918..2ac00f1 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -197,7 +197,7 @@ func (bot *ircBot) whoisCollector() { select { case <-bot.closing: return - case <-time.After(time.Minute * 1): + case <-time.After(time.Minute * 5): bot.Whois() } } @@ -514,46 +514,51 @@ func (bot *ircBot) sender() { } } -// Listen for incoming messages. Parse them and put on channel. -// Should run in go-routine -func (bot *ircBot) listen() { - - var contentData []byte - var content string - var err error +// Read from the socket +func (bot *ircBot) readSocket(input chan string) { bufRead := bufio.NewReader(bot.socket) for { - select { - case <-bot.closing: - return - default: - contentData, err = bufRead.ReadBytes('\n') - - if err != nil { - netErr, ok := err.(net.Error) - if ok && netErr.Timeout() == true { - continue - } else { - glog.Errorln("Lost IRC server connection. ", err) - err := bot.Close() - if err != nil { - glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) - } - return - } - } + contentData, err := bufRead.ReadBytes('\n') - if len(contentData) == 0 { + if err != nil { + netErr, ok := err.(net.Error) + if ok && netErr.Timeout() == true { continue + } else { + glog.Errorln("Lost IRC server connection. ", err) + bot.reconnect() + return } + } - content = toUnicode(contentData) + if len(contentData) == 0 { + continue + } - if glog.V(2) { - glog.Infoln("[RAW", bot.String(), "]"+content) - } + content := toUnicode(contentData) + + if glog.V(2) { + glog.Infoln("[RAW", bot.String(), "]"+content) + } + input <- content + } +} + + +// Listen for incoming messages. Parse them and put on channel. +// Should run in go-routine +func (bot *ircBot) listen() { + input := make(chan string) + + go bot.readSocket(input) + + for { + select { + case <-bot.closing: + return + case content := <- input: theLine, err := parseLine(content) if err == nil { botStats := bot.GetStats() @@ -646,16 +651,25 @@ func (bot *ircBot) Close() error { case <-bot.closing: glog.Infoln("[Info] already bot.closing is already closed closed") default: + glog.Infoln("[Info] Closing bot.") close(bot.closing) } bot.sendShutdown() - return bot.socket.Close() + + glog.Infoln("[Info] Closing bot socket.") + var err error + if bot.socket != nil { + err = bot.socket.Close() + bot.socket = nil + } + return err } // Send a non-standard SHUTDOWN message to the plugins // This allows them to know that this channel is offline func (bot *ircBot) sendShutdown() { + glog.Infoln("[Info] Sending Shutdown command") bot.Lock() defer bot.Unlock() shutLine := &line.Line{ From f6f313ca8da2e7ce8ae320ff9305e594013814f6 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 23 Jun 2014 14:52:40 +0200 Subject: [PATCH 43/76] Linting. Fix a panic when tring to write a closed bot.socket --- network/irc/irc.go | 31 +++++++++++++++++++------------ 1 file changed, 19 insertions(+), 12 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 2ac00f1..1bb65d1 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -30,7 +30,8 @@ import ( const ( // VERSION of the botbot-bot - VERSION = "botbot v0.3.0" + VERSION = "botbot v0.3.0" + // IRC command code from the spec RPL_WHOISCHANNELS = "319" ) @@ -52,6 +53,7 @@ func (s chatBotStats) GetOrCreate(identifier string) (*expvar.Map, bool) { } var ( + // BotStats hold the reference to the expvar.Map for each ircBot instance BotStats = chatBotStats{m: make(map[string]*expvar.Map)} ) @@ -149,7 +151,7 @@ func (bot *ircBot) monitor() { maxPingWithoutResponse := 3 maxPongWithoutMessage := 150 pongCounter := 0 - missed_ping := 0 + missedPing := 0 for { select { case <-bot.closing: @@ -182,10 +184,10 @@ func (bot *ircBot) monitor() { case <-pingTimeout: // Deactivate the pingTimeout case pingTimeout = nil - botStats.Add("missed_ping", 1) - missed_ping++ - glog.Infoln("[Info] No pong from ircBot server", bot, "missed", missed_ping) - if missed_ping > maxPingWithoutResponse { + botStats.Add("missedPing", 1) + missedPing++ + glog.Infoln("[Info] No pong from ircBot server", bot, "missed", missedPing) + if missedPing > maxPingWithoutResponse { close(reconnect) } } @@ -253,7 +255,7 @@ func (bot *ircBot) Init() { func (bot *ircBot) Connect() { if bot.socket != nil { - // socket already set, unit tests need this + glog.Infoln("[Info] bot.socket already set, do not attempt to Connect") return } @@ -496,6 +498,11 @@ func (bot *ircBot) sender() { case <-time.After(bot.rateLimit): select { case data := <-bot.sendQueue: + if bot.socket == nil { + // socket does not exist + glog.Infoln("[Info] the socket does not exist, exit listen goroutine") + return + } if glog.V(1) { glog.Infoln("[RAW", bot, "] -->", string(data)) @@ -546,11 +553,11 @@ func (bot *ircBot) readSocket(input chan string) { } } - // Listen for incoming messages. Parse them and put on channel. // Should run in go-routine func (bot *ircBot) listen() { input := make(chan string) + botStats := bot.GetStats() go bot.readSocket(input) @@ -558,10 +565,9 @@ func (bot *ircBot) listen() { select { case <-bot.closing: return - case content := <- input: + case content := <-input: theLine, err := parseLine(content) if err == nil { - botStats := bot.GetStats() botStats.Add("received_messages", 1) theLine.ChatBotId = bot.id bot.act(theLine) @@ -574,6 +580,8 @@ func (bot *ircBot) listen() { } func (bot *ircBot) act(theLine *line.Line) { + bot.Lock() + defer bot.Unlock() // Notify the monitor goroutine that we receive a PONG if theLine.Command == "PONG" { if glog.V(2) { @@ -859,9 +867,8 @@ func isEqual(a, b []*common.Channel) (flag bool) { } } return true - } else { - return false } + return false } // Is a in b? container must be sorted From 18b94d32f01cd2ca5bbb007e01340e0482616d31 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 23 Jun 2014 15:57:35 +0200 Subject: [PATCH 44/76] Better connect --- network/irc/irc.go | 54 +++++++++++++++++++++++++--------------------- 1 file changed, 29 insertions(+), 25 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 1bb65d1..b7e01ec 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -254,6 +254,7 @@ func (bot *ircBot) Init() { // to Dial to the server. func (bot *ircBot) Connect() { + // TODO (yml) remove eventually if bot.socket != nil { glog.Infoln("[Info] bot.socket already set, do not attempt to Connect") return @@ -261,42 +262,45 @@ func (bot *ircBot) Connect() { var socket net.Conn var err error + connectTimeout := time.After(0) for { - glog.Infoln("Connecting to IRC server: ", bot.address) + select { + case <-bot.closing: + return + case <-connectTimeout: + glog.Infoln("Connecting to IRC server: ", bot.address) - socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first - if err == nil { - glog.Infoln("Connected: TLS secure") - break - } + bot.socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first + if err == nil { + glog.Infoln("Connected: TLS secure") + return + } - glog.Infoln("Could not connect using TLS because: ", err) + glog.Infoln("Could not connect using TLS because: ", err) - _, ok := err.(x509.HostnameError) - if ok { - // Certificate might not match. This happens on irc.cloudfront.net - insecure := &tls.Config{InsecureSkipVerify: true} - socket, err = tls.Dial("tcp", bot.address, insecure) + _, ok := err.(x509.HostnameError) + if ok { + // Certificate might not match. This happens on irc.cloudfront.net + insecure := &tls.Config{InsecureSkipVerify: true} + bot.socket, err = tls.Dial("tcp", bot.address, insecure) - if err == nil && isCertValid(socket.(*tls.Conn)) { - glog.Infoln("Connected: TLS with awkward certificate") - break + if err == nil && isCertValid(socket.(*tls.Conn)) { + glog.Infoln("Connected: TLS with awkward certificate") + return + } } - } - socket, err = net.Dial("tcp", bot.address) + bot.socket, err = net.Dial("tcp", bot.address) - if err == nil { - glog.Infoln("Connected: Plain text insecure") - break + if err == nil { + glog.Infoln("Connected: Plain text insecure") + return + } + glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err) + connectTimeout = time.After(5 * time.Second) } - - glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err) - time.Sleep(10 * time.Second) } - - bot.socket = socket } /* Check that the TLS connection's certficate can be applied to this connection. From df6576af68cb51243de2b9fe53725f3953f98f24 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 23 Jun 2014 16:19:05 +0200 Subject: [PATCH 45/76] Reinitialized the missedPing to 0 --- network/irc/irc.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index b7e01ec..8a76b3a 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -161,6 +161,7 @@ func (bot *ircBot) monitor() { bot.reconnect() case <-bot.monitorChan: pongCounter = 0 + missedPing = 0 // Deactivate the pingTimeout case pingTimeout = nil if glog.V(2) { @@ -184,7 +185,7 @@ func (bot *ircBot) monitor() { case <-pingTimeout: // Deactivate the pingTimeout case pingTimeout = nil - botStats.Add("missedPing", 1) + botStats.Add("missed_ping", 1) missedPing++ glog.Infoln("[Info] No pong from ircBot server", bot, "missed", missedPing) if missedPing > maxPingWithoutResponse { From d2aa03065efe275c05584389a10cb84d7ae7fcef Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Mon, 23 Jun 2014 10:42:25 -0400 Subject: [PATCH 46/76] Fixing monitoring, and backoff. --- network/irc/irc.go | 28 ++++++++++++++++++---------- 1 file changed, 18 insertions(+), 10 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index b7e01ec..330be11 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -155,7 +155,7 @@ func (bot *ircBot) monitor() { for { select { case <-bot.closing: - break + return case <-reconnect: glog.Infoln("IRC monitoring KO", bot) bot.reconnect() @@ -222,6 +222,8 @@ func (bot *ircBot) reconnect() { func (bot *ircBot) Init() { bot.Lock() defer bot.Unlock() + + glog.Infoln("Init bot", bot) bot.closing = make(chan struct{}) bot.isConnecting = true bot.isAuthenticating = false @@ -255,13 +257,17 @@ func (bot *ircBot) Init() { func (bot *ircBot) Connect() { // TODO (yml) remove eventually - if bot.socket != nil { - glog.Infoln("[Info] bot.socket already set, do not attempt to Connect") - return - } + // if bot.socket != nil { + // glog.Infoln("[Info] bot.socket already set, do not attempt to Connect") + // return + // } + + var ( + socket net.Conn + err error + counter int + ) - var socket net.Conn - var err error connectTimeout := time.After(0) for { @@ -269,6 +275,7 @@ func (bot *ircBot) Connect() { case <-bot.closing: return case <-connectTimeout: + counter++ glog.Infoln("Connecting to IRC server: ", bot.address) bot.socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first @@ -297,8 +304,9 @@ func (bot *ircBot) Connect() { glog.Infoln("Connected: Plain text insecure") return } - glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err) - connectTimeout = time.After(5 * time.Second) + delay := 5 * counter + glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err, "in", delay, "seonds") + connectTimeout = time.After(time.Duration(delay) * time.Second) } } } @@ -669,9 +677,9 @@ func (bot *ircBot) Close() error { bot.sendShutdown() - glog.Infoln("[Info] Closing bot socket.") var err error if bot.socket != nil { + glog.Infoln("[Info] Closing bot socket.") err = bot.socket.Close() bot.socket = nil } From 3c884e52843429c7654a272d9e75f60146bd4770 Mon Sep 17 00:00:00 2001 From: Vitaly Babiy Date: Mon, 23 Jun 2014 11:34:02 -0400 Subject: [PATCH 47/76] Fixing formatting --- network/irc/irc.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index d9a3e49..82298af 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -31,7 +31,7 @@ import ( const ( // VERSION of the botbot-bot VERSION = "botbot v0.3.0" - // IRC command code from the spec + // RPL_WHOISCHANNELS IRC command code from the spec RPL_WHOISCHANNELS = "319" ) @@ -264,8 +264,8 @@ func (bot *ircBot) Connect() { // } var ( - socket net.Conn - err error + socket net.Conn + err error counter int ) From 0225b08aaba1d78a0132ed696bfa97b01e7236a1 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 24 Jun 2014 17:22:22 +0200 Subject: [PATCH 48/76] reverted the changes that aim to change the log library. --- network/irc/irc.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 82298af..1f937bc 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -264,7 +264,6 @@ func (bot *ircBot) Connect() { // } var ( - socket net.Conn err error counter int ) @@ -293,7 +292,7 @@ func (bot *ircBot) Connect() { insecure := &tls.Config{InsecureSkipVerify: true} bot.socket, err = tls.Dial("tcp", bot.address, insecure) - if err == nil && isCertValid(socket.(*tls.Conn)) { + if err == nil && isCertValid(bot.socket.(*tls.Conn)) { glog.Infoln("Connected: TLS with awkward certificate") return } @@ -306,7 +305,7 @@ func (bot *ircBot) Connect() { return } delay := 5 * counter - glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err, "in", delay, "seonds") + glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err, "in", delay, "seconds") connectTimeout = time.After(time.Duration(delay) * time.Second) } } From d67f8d7e67ff3debe17bef06ca9be41fa9a42b07 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 00:52:51 +0200 Subject: [PATCH 49/76] move the goroutine to read socket in a more logical place where we are sure that the bot.socket has been properly initialized --- network/irc/irc.go | 41 ++++++++++++++++++----------------------- 1 file changed, 18 insertions(+), 23 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 1f937bc..a92b80b 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -77,6 +77,7 @@ type ircBot struct { pingResponse chan struct{} reconnectChan chan struct{} closing chan struct{} + receive chan string } // NewBot create an irc instance of ChatBot @@ -104,6 +105,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock reconnectChan: make(chan struct{}), closing: make(chan struct{}), + receive: make(chan string), } chatbotStats, ok := BotStats.GetOrCreate(chatbot.serverIdentifier) @@ -257,52 +259,49 @@ func (bot *ircBot) Init() { // to Dial to the server. func (bot *ircBot) Connect() { - // TODO (yml) remove eventually - // if bot.socket != nil { - // glog.Infoln("[Info] bot.socket already set, do not attempt to Connect") - // return - // } - var ( err error counter int ) + connected := make(chan struct{}) connectTimeout := time.After(0) for { select { case <-bot.closing: return + case <-connected: + go bot.readSocket() + return case <-connectTimeout: counter++ + connectTimeout = nil glog.Infoln("Connecting to IRC server: ", bot.address) bot.socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first if err == nil { glog.Infoln("Connected: TLS secure") - return - } - - glog.Infoln("Could not connect using TLS because: ", err) - - _, ok := err.(x509.HostnameError) - if ok { + close(connected) + continue + } else if _, ok := err.(x509.HostnameError); ok { + glog.Infoln("Could not connect using TLS because: ", err) // Certificate might not match. This happens on irc.cloudfront.net insecure := &tls.Config{InsecureSkipVerify: true} bot.socket, err = tls.Dial("tcp", bot.address, insecure) if err == nil && isCertValid(bot.socket.(*tls.Conn)) { glog.Infoln("Connected: TLS with awkward certificate") - return + close(connected) + continue } } bot.socket, err = net.Dial("tcp", bot.address) - if err == nil { glog.Infoln("Connected: Plain text insecure") - return + close(connected) + continue } delay := 5 * counter glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err, "in", delay, "seconds") @@ -534,7 +533,7 @@ func (bot *ircBot) sender() { } // Read from the socket -func (bot *ircBot) readSocket(input chan string) { +func (bot *ircBot) readSocket() { bufRead := bufio.NewReader(bot.socket) for { @@ -561,23 +560,19 @@ func (bot *ircBot) readSocket(input chan string) { glog.Infoln("[RAW", bot.String(), "]"+content) } - input <- content + bot.receive <- content } } // Listen for incoming messages. Parse them and put on channel. // Should run in go-routine func (bot *ircBot) listen() { - input := make(chan string) botStats := bot.GetStats() - - go bot.readSocket(input) - for { select { case <-bot.closing: return - case content := <-input: + case content := <-bot.receive: theLine, err := parseLine(content) if err == nil { botStats.Add("received_messages", 1) From 6d3e35bed7576f4119505879d79197ade1260795 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 10:13:26 +0200 Subject: [PATCH 50/76] Move the goroutine whoiscollector and into monitor --- network/irc/irc.go | 60 +++++++++++++++++++--------------------------- 1 file changed, 24 insertions(+), 36 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index a92b80b..db8068c 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -169,6 +169,8 @@ func (bot *ircBot) monitor() { if glog.V(2) { glog.Infoln("[Info] Message received from the server for", bot) } + case <-time.After(time.Minute * 5): + bot.Whois() case <-time.After(time.Second * 60): glog.Infoln("[Info] Ping the ircBot server", pongCounter, bot) botStats.Add("ping", 1) @@ -197,17 +199,6 @@ func (bot *ircBot) monitor() { } } -func (bot *ircBot) whoisCollector() { - for { - select { - case <-bot.closing: - return - case <-time.After(time.Minute * 5): - bot.Whois() - } - } -} - // reconnect the ircBot func (bot *ircBot) reconnect() { glog.Infoln("Trying to reconnect", bot) @@ -239,9 +230,6 @@ func (bot *ircBot) Init() { // Monitor that we are still getting incoming messages in a background thread go bot.monitor() - // Poll the the bot server to know to which channels we are connected - go bot.whoisCollector() - // Listen for outgoing messages (rate limited) in background thread if bot.sendQueue == nil { bot.sendQueue = make(chan []byte, 256) @@ -499,8 +487,6 @@ func (bot *ircBot) sender() { for { select { case <-bot.closing: - // TODO(yml): may be we should have a grace period to let the bot - // a chance to send the message in the buffer return case <-reconnect: bot.reconnect() @@ -526,7 +512,7 @@ func (bot *ircBot) sender() { } botStats.Add("messages", 1) default: - // Do not block waiting for message to send + continue } } } @@ -537,30 +523,32 @@ func (bot *ircBot) readSocket() { bufRead := bufio.NewReader(bot.socket) for { - contentData, err := bufRead.ReadBytes('\n') + select { + case <-bot.closing: + return + default: + contentData, err := bufRead.ReadBytes('\n') + if err != nil { + netErr, ok := err.(net.Error) + if ok && netErr.Timeout() == true { + continue + } else { + glog.Errorln("Lost IRC server connection. ", err) + bot.reconnect() + return + } + } - if err != nil { - netErr, ok := err.(net.Error) - if ok && netErr.Timeout() == true { + if len(contentData) == 0 { continue - } else { - glog.Errorln("Lost IRC server connection. ", err) - bot.reconnect() - return } - } - if len(contentData) == 0 { - continue - } - - content := toUnicode(contentData) - - if glog.V(2) { - glog.Infoln("[RAW", bot.String(), "]"+content) + content := toUnicode(contentData) + if glog.V(2) { + glog.Infoln("[RAW", bot.String(), "]"+content) + } + bot.receive <- content } - - bot.receive <- content } } From 51b6acb033b64e1d857dc356e821f778b6739ad4 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 16:35:09 +0200 Subject: [PATCH 51/76] Continue to clean up irc.go. Fix a panic when the bot try to reconnect after 4 missed ping. --- network/irc/irc.go | 54 +++++++++++++++++++++++++--------------------- network/network.go | 5 ++++- 2 files changed, 33 insertions(+), 26 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index db8068c..ea0621c 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -75,7 +75,6 @@ type ircBot struct { fromServer chan *line.Line monitorChan chan struct{} pingResponse chan struct{} - reconnectChan chan struct{} closing chan struct{} receive chan string } @@ -103,7 +102,6 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot channels: config.Channels, monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - reconnectChan: make(chan struct{}), closing: make(chan struct{}), receive: make(chan string), } @@ -136,6 +134,9 @@ func (bot *ircBot) GetStats() *expvar.Map { } func (bot *ircBot) String() string { + // TODO understand why the Lock prevent the bot form joining + //bot.RLock() + //defer bot.RUnlock() return fmt.Sprintf("%s on %s", bot.nick, bot.address) } @@ -533,8 +534,7 @@ func (bot *ircBot) readSocket() { if ok && netErr.Timeout() == true { continue } else { - glog.Errorln("Lost IRC server connection. ", err) - bot.reconnect() + glog.Errorln("[Info] An Error occured while reading from bot.socket ", err) return } } @@ -647,34 +647,38 @@ func (bot *ircBot) act(theLine *line.Line) { bot.fromServer <- theLine } -// Close ircBot -func (bot *ircBot) Close() error { +// Close ircBot and bot.socket +func (bot *ircBot) Close() (err error) { // Send a signal to all goroutine to return - select { - case <-bot.closing: - glog.Infoln("[Info] already bot.closing is already closed closed") - default: - glog.Infoln("[Info] Closing bot.") - close(bot.closing) - } - - bot.sendShutdown() - - var err error - if bot.socket != nil { - glog.Infoln("[Info] Closing bot socket.") - err = bot.socket.Close() - bot.socket = nil + for { + select { + case <-bot.closing: + glog.Infoln("[Info] bot.closing is already closed") + return err + default: + glog.Infoln("[Info] Closing bot.") + bot.sendShutdown() + close(bot.closing) + if bot.socket != nil { + glog.Infoln("[Info] Closing bot.socket.") + err = bot.socket.Close() + if err != nil { + glog.Infoln("[Error] An error occured while Closing bot.socket", bot, ": ", err) + } + bot.Lock() + bot.socket = nil + bot.Unlock() + } + } } - return err } // Send a non-standard SHUTDOWN message to the plugins // This allows them to know that this channel is offline func (bot *ircBot) sendShutdown() { - glog.Infoln("[Info] Sending Shutdown command") - bot.Lock() - defer bot.Unlock() + bot.RLock() + defer bot.RUnlock() + glog.Infoln("[Info] Logging Shutdown command in the channels monitored by:", bot) shutLine := &line.Line{ Command: "SHUTDOWN", Received: time.Now().UTC().Format(time.RFC3339Nano), diff --git a/network/network.go b/network/network.go index 3c0968b..600eb1f 100644 --- a/network/network.go +++ b/network/network.go @@ -162,7 +162,10 @@ func (nm *NetworkManager) Shutdown() { nm.Lock() nm.isRunning = false for _, bot := range nm.chatbots { - bot.Close() + err := bot.Close() + if err != nil { + glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + } } nm.Unlock() } From 5421ff1255757e385c57de628f49eb666f01a014 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 16:47:58 +0200 Subject: [PATCH 52/76] Return from the monitor goroutine when we send the reconnect --- network/irc/irc.go | 1 + 1 file changed, 1 insertion(+) diff --git a/network/irc/irc.go b/network/irc/irc.go index ea0621c..178387e 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -162,6 +162,7 @@ func (bot *ircBot) monitor() { case <-reconnect: glog.Infoln("IRC monitoring KO", bot) bot.reconnect() + return case <-bot.monitorChan: pongCounter = 0 missedPing = 0 From 52fb8752b69469ff0d4af6a3e2df5bb0ca8032cd Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 18:08:47 +0200 Subject: [PATCH 53/76] Fxing TestFlood and added a work around to force glog to log the test suite. --- common/mock.go | 35 ++++++++++++++++++++ network/irc/irc.go | 8 ++++- network/irc/irc_test.go | 73 +++++++++++++++++------------------------ 3 files changed, 73 insertions(+), 43 deletions(-) diff --git a/common/mock.go b/common/mock.go index 1fd375f..9a9eb36 100644 --- a/common/mock.go +++ b/common/mock.go @@ -5,8 +5,43 @@ import ( "net" "sync" "testing" + "time" ) +// MockSocket is a dummy implementation of ReadWriteCloser +type MockSocket struct { + sync.RWMutex + Received []string + Counter chan bool +} + +func (sock MockSocket) Write(data []byte) (int, error) { + sock.Lock() + defer sock.Unlock() + sock.Received = append(sock.Received, string(data)) + if sock.Counter != nil { + sock.Counter <- true + } + return len(data), nil +} + +func (sock MockSocket) Read(into []byte) (int, error) { + sock.RLock() + defer sock.RUnlock() + time.Sleep(time.Second) // Prevent busy loop + return 0, nil +} + +func (sock MockSocket) Close() error { + return nil +} + +func (sock *MockSocket) ReceivedLength() int { + sock.RLock() + defer sock.RUnlock() + return len(sock.Received) +} + /* * Mock IRC server */ diff --git a/network/irc/irc.go b/network/irc/irc.go index 178387e..afb9436 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -267,7 +267,13 @@ func (bot *ircBot) Connect() { case <-connectTimeout: counter++ connectTimeout = nil - glog.Infoln("Connecting to IRC server: ", bot.address) + glog.Infoln("[Info] Connecting to IRC server: ", bot.address) + if _, ok := bot.socket.(common.MockSocket); ok { + // The test suite take advantage of this special case by crafting a bot that provides its own mocksocket implementation. + glog.Infoln("[Info] This message should only ever be seen while running the test suite") + close(connected) + continue + } bot.socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first if err == nil { diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 5b9fb33..9519034 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -1,9 +1,9 @@ package irc import ( + "flag" "strconv" "strings" - "sync" "testing" "time" @@ -15,7 +15,15 @@ var ( NEW_CHANNEL = common.Channel{Name: "#unitnew", Fingerprint: "new-channel-uuid"} ) +// setGlogFlags walk around a glog issue and force it to log to stderr. +// It need to be called at the beginning of each test. +func setGlogFlags() { + flag.Set("alsologtostderr", "true") + flag.Set("V", "3") +} + func TestParseLine_welcome(t *testing.T) { + setGlogFlags() line1 := ":barjavel.freenode.net 001 graham_king :Welcome to the freenode Internet Relay Chat Network graham_king" line, err := parseLine(line1) @@ -33,6 +41,7 @@ func TestParseLine_welcome(t *testing.T) { } func TestParseLine_privmsg(t *testing.T) { + setGlogFlags() line1 := ":rnowak!~rnowak@q.ovron.com PRIVMSG #linode :totally" line, err := parseLine(line1) @@ -58,6 +67,7 @@ func TestParseLine_privmsg(t *testing.T) { } func TestParseLine_pm(t *testing.T) { + setGlogFlags() line1 := ":graham_king!graham_kin@i.love.debian.org PRIVMSG botbotme :hello" line, err := parseLine(line1) @@ -78,6 +88,7 @@ func TestParseLine_pm(t *testing.T) { } func TestParseLine_list(t *testing.T) { + setGlogFlags() line1 := ":oxygen.oftc.net 322 graham_king #linode 412 :Linode Community Support | http://www.linode.com/ | Linodes in Asia-Pacific! - http://bit.ly/ooBzhV" line, err := parseLine(line1) @@ -103,6 +114,7 @@ func TestParseLine_list(t *testing.T) { } func TestParseLine_quit(t *testing.T) { + setGlogFlags() line1 := ":nicolaslara!~nicolasla@c83-250-0-151.bredband.comhem.se QUIT :" line, err := parseLine(line1) if err != nil { @@ -114,6 +126,7 @@ func TestParseLine_quit(t *testing.T) { } func TestParseLine_part(t *testing.T) { + setGlogFlags() line1 := ":nicolaslara!~nicolasla@c83-250-0-151.bredband.comhem.se PART #lincolnloop-internal" line, err := parseLine(line1) if err != nil { @@ -128,6 +141,7 @@ func TestParseLine_part(t *testing.T) { } func TestParseLine_353(t *testing.T) { + setGlogFlags() line1 := ":hybrid7.debian.local 353 botbot = #test :@botbot graham_king" line, err := parseLine(line1) if err != nil { @@ -144,54 +158,21 @@ func TestParseLine_353(t *testing.T) { } } -// Dummy implementation of ReadWriteCloser -type MockSocket struct { - sync.RWMutex - received []string - counter chan bool -} - -func (sock *MockSocket) Write(data []byte) (int, error) { - sock.Lock() - defer sock.Unlock() - sock.received = append(sock.received, string(data)) - if sock.counter != nil { - sock.counter <- true - } - return len(data), nil -} - -func (sock *MockSocket) Read(into []byte) (int, error) { - sock.RLock() - defer sock.RUnlock() - time.Sleep(time.Second) // Prevent busy loop - return 0, nil -} - -func (sock *MockSocket) Close() error { - return nil -} - -func (sock *MockSocket) receivedLength() int { - sock.RLock() - defer sock.RUnlock() - return len(sock.received) -} - // Test sending messages too fast func TestFlood(t *testing.T) { + setGlogFlags() NUM := 5 fromServer := make(chan *line.Line) receivedCounter := make(chan bool) - mockSocket := MockSocket{counter: receivedCounter} + mockSocket := common.MockSocket{Counter: receivedCounter} channels := make([]*common.Channel, 1) channels = append(channels, &common.Channel{Name: "test", Fingerprint: "uuid-string"}) chatbot := &ircBot{ id: 99, - address: "localhost", + address: "fakehost", nick: "test", realname: "Unit Test", password: "test", @@ -199,7 +180,11 @@ func TestFlood(t *testing.T) { rateLimit: time.Second, fromServer: fromServer, channels: channels, - socket: &mockSocket, + socket: mockSocket, + monitorChan: make(chan struct{}), + pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock + closing: make(chan struct{}), + receive: make(chan string), } chatbot.Init() @@ -227,9 +212,10 @@ func TestFlood(t *testing.T) { // Test joining additional channels func TestUpdate(t *testing.T) { + setGlogFlags() fromServer := make(chan *line.Line) - mockSocket := MockSocket{counter: nil} + mockSocket := common.MockSocket{Counter: nil} channels := make([]*common.Channel, 0, 2) channel := common.Channel{Name: "#test", Fingerprint: "uuid-string"} channels = append(channels, &channel) @@ -243,7 +229,7 @@ func TestUpdate(t *testing.T) { serverIdentifier: "localhost.test1", fromServer: fromServer, channels: channels, - socket: &mockSocket, + socket: mockSocket, sendQueue: make(chan []byte, 100), } // Rate limiting requires a go-routine to actually do the sending @@ -259,14 +245,14 @@ func TestUpdate(t *testing.T) { // Wait a bit for i := 0; i < 10; i++ { time.Sleep(time.Second / 3) - if mockSocket.receivedLength() >= 1 { + if mockSocket.ReceivedLength() >= 1 { break } } // Expect a JOIN of NEW_CHANNEL but NOT a JOIN on #test (because already in there) isFound := false - for _, cmd := range mockSocket.received { + for _, cmd := range mockSocket.Received { cmd = strings.TrimSpace(cmd) @@ -286,6 +272,7 @@ func TestUpdate(t *testing.T) { } func TestToUnicodeUTF8(t *testing.T) { + setGlogFlags() msg := "ελληνικά" result := toUnicode([]byte(msg)) if result != msg { @@ -294,6 +281,7 @@ func TestToUnicodeUTF8(t *testing.T) { } func TestToUnicodeLatin1(t *testing.T) { + setGlogFlags() msg := "âôé" latin1_bytes := []byte{0xe2, 0xf4, 0xe9} result := toUnicode(latin1_bytes) @@ -303,6 +291,7 @@ func TestToUnicodeLatin1(t *testing.T) { } func TestSplitChannels(t *testing.T) { + setGlogFlags() input := "#aone, #btwo, #cthree" result := splitChannels(input) if len(result) != 3 || result[2] != "#cthree" { From 74512b5d3c04d95d1678dc788acdf80fae6798b7 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 18:27:36 +0200 Subject: [PATCH 54/76] Fix a race condition that is expose when running irc_test. --- network/irc/irc.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/network/irc/irc.go b/network/irc/irc.go index afb9436..c4dd056 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -129,6 +129,8 @@ func (bot *ircBot) GetUser() string { } func (bot *ircBot) GetStats() *expvar.Map { + bot.Lock() + defer bot.Unlock() stats, _ := BotStats.GetOrCreate(bot.serverIdentifier) return stats } From a171f3189fc49ee3cd6a6ee0bada7517272ac6d3 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 23:39:01 +0200 Subject: [PATCH 55/76] Fix the test suite --- common/mock.go | 24 +++++++++++--------- network/irc/irc.go | 36 ++++++++++++++++++++++++----- network/irc/irc_test.go | 50 ++++++++++++++++++----------------------- 3 files changed, 66 insertions(+), 44 deletions(-) diff --git a/common/mock.go b/common/mock.go index 9a9eb36..52de493 100644 --- a/common/mock.go +++ b/common/mock.go @@ -6,22 +6,26 @@ import ( "sync" "testing" "time" + + "github.com/golang/glog" ) // MockSocket is a dummy implementation of ReadWriteCloser type MockSocket struct { sync.RWMutex - Received []string Counter chan bool + Receiver chan string } func (sock MockSocket) Write(data []byte) (int, error) { - sock.Lock() - defer sock.Unlock() - sock.Received = append(sock.Received, string(data)) + glog.Infoln("[Debug]: Starting MockSocket.Write of:", string(data)) if sock.Counter != nil { sock.Counter <- true } + if sock.Receiver != nil { + sock.Receiver <- string(data) + } + return len(data), nil } @@ -33,15 +37,15 @@ func (sock MockSocket) Read(into []byte) (int, error) { } func (sock MockSocket) Close() error { + if sock.Receiver != nil { + close(sock.Receiver) + } + if sock.Counter != nil { + close(sock.Counter) + } return nil } -func (sock *MockSocket) ReceivedLength() int { - sock.RLock() - defer sock.RUnlock() - return len(sock.Received) -} - /* * Mock IRC server */ diff --git a/network/irc/irc.go b/network/irc/irc.go index c4dd056..e89fe29 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -357,9 +357,11 @@ func (bot *ircBot) Update(config *common.BotConfig) { isNewServer := bot.updateServer(config) if isNewServer { + glog.Infoln("[Info] the config is from a new server.") // If the server changed, we've already done nick and channel changes too return } + glog.Infoln("[Info] bot.Update -- It is not a new server.") bot.updateNick(config.Config["nick"], config.Config["password"]) bot.updateChannels(config.Channels) @@ -373,7 +375,7 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { return false } - glog.Infoln("Changing IRC server from ", bot.address, " to ", addr) + glog.Infoln("[Info] Changing IRC server from ", bot.address, " to ", addr) err := bot.Close() if err != nil { @@ -394,9 +396,14 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { // Update the nickname we're registered under, if needed func (bot *ircBot) updateNick(newNick, newPass string) { + bot.Lock() + defer bot.Unlock() + glog.Infoln("[Info] Starting bot.updateNick()") if newNick == bot.nick { + glog.Infoln("[Info] bot.updateNick() -- the nick has not changed so return") return } + glog.Infoln("[Info] bot.updateNick() -- set the new nick") bot.nick = newNick bot.password = newPass @@ -405,16 +412,23 @@ func (bot *ircBot) updateNick(newNick, newPass string) { // Update the channels based on new configuration, leaving old ones and joining new ones func (bot *ircBot) updateChannels(newChannels []*common.Channel) { + glog.Infoln("[Info] Starting bot.updateChannels") + glog.Infoln("[Debug] newChannels: ", newChannels) + glog.Infoln("[Debug] bot.channels: ", bot.channels) + bot.RLock() + if isEqual(newChannels, bot.channels) { if glog.V(2) { glog.Infoln("Channels comparison is equals for bot: ", bot.nick) } return } + glog.Infoln("[Info] The channels the bot is connected need to be updated") // PART old ones for _, channel := range bot.channels { if !isIn(channel, newChannels) { + glog.Infoln("[Info] Parting new channel: ", channel.Credential()) bot.part(channel.Credential()) } } @@ -422,11 +436,20 @@ func (bot *ircBot) updateChannels(newChannels []*common.Channel) { // JOIN new ones for _, channel := range newChannels { if !isIn(channel, bot.channels) { + glog.Infoln("[Info] Joining new channel: ", channel.Credential()) bot.join(channel.Credential()) + glog.Infoln("[DEBUG] After join") } } - + bot.RUnlock() + glog.Infoln("[Debug] before Lock") + bot.Lock() + glog.Infoln("[Debug] after Lock") bot.channels = newChannels + glog.Infoln("[Debug] before Unlock") + bot.Unlock() + glog.Infoln("[Debug] after Unlock") + } // Join channels @@ -444,8 +467,7 @@ func (bot *ircBot) Whois() { // Join an IRC channel func (bot *ircBot) join(channel string) { bot.SendRaw("JOIN " + channel) - botStats := bot.GetStats() - botStats.Add("channels", 1) + glog.Infoln("[Debug] Exiting bot.join") } // Leave an IRC channel @@ -464,6 +486,7 @@ func (bot *ircBot) Send(channel, msg string) { // Send message down socket. Add \n at end first. func (bot *ircBot) SendRaw(msg string) { bot.sendQueue <- []byte(msg + "\n") + glog.Infoln("[Debug] Exiting bot.SendRaw") } // Tell the irc server who we are - we can't do anything until this is done. @@ -493,7 +516,7 @@ func (bot *ircBot) sender() { var err error reconnect := make(chan struct{}) botStats := bot.GetStats() - + glog.Infoln("[Debug] Starting the sender") for { select { case <-bot.closing: @@ -505,6 +528,7 @@ func (bot *ircBot) sender() { case <-time.After(bot.rateLimit): select { case data := <-bot.sendQueue: + glog.Infoln("[Debug] Pulled data from bot.sendQueue chan:", string(data)) if bot.socket == nil { // socket does not exist glog.Infoln("[Info] the socket does not exist, exit listen goroutine") @@ -514,7 +538,7 @@ func (bot *ircBot) sender() { if glog.V(1) { glog.Infoln("[RAW", bot, "] -->", string(data)) } - + glog.Infoln("[Debug] Going to write to bot.socket") _, err = bot.socket.Write(data) if err != nil { glog.Errorln("[Error] Error writing to socket to", bot, ": ", err) diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 9519034..3df5a2a 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -9,6 +9,7 @@ import ( "github.com/BotBotMe/botbot-bot/common" "github.com/BotBotMe/botbot-bot/line" + "github.com/golang/glog" ) var ( @@ -185,6 +186,7 @@ func TestFlood(t *testing.T) { pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock closing: make(chan struct{}), receive: make(chan string), + sendQueue: make(chan []byte, 256), } chatbot.Init() @@ -196,14 +198,13 @@ func TestFlood(t *testing.T) { } // Wait for them to 'arrive' at the socket - for numGot := 0; numGot < NUM; numGot++ { + for numGot := 0; numGot <= NUM; numGot++ { <-receivedCounter } elapsed := int64(time.Since(startTime)) - // NUM messages should take at least ((NUM-1) / 4) seconds (max 4 msgs second) - expected := int64((NUM-1)/4) * int64(time.Second) + expected := int64((NUM-1)/4) * int64(chatbot.rateLimit) if elapsed < expected { t.Error("Flood prevention did not work") } @@ -213,9 +214,11 @@ func TestFlood(t *testing.T) { // Test joining additional channels func TestUpdate(t *testing.T) { setGlogFlags() + glog.Infoln("[DEBUG] starting TestUpdate") fromServer := make(chan *line.Line) - mockSocket := common.MockSocket{Counter: nil} + receiver := make(chan string, 10) + mockSocket := common.MockSocket{Receiver: receiver} channels := make([]*common.Channel, 0, 2) channel := common.Channel{Name: "#test", Fingerprint: "uuid-string"} channels = append(channels, &channel) @@ -230,42 +233,33 @@ func TestUpdate(t *testing.T) { fromServer: fromServer, channels: channels, socket: mockSocket, - sendQueue: make(chan []byte, 100), + rateLimit: time.Second, + monitorChan: make(chan struct{}), + pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock + closing: make(chan struct{}), + receive: make(chan string), + sendQueue: make(chan []byte, 256), } - // Rate limiting requires a go-routine to actually do the sending - go chatbot.sender() - + chatbot.Init() conf := map[string]string{ "nick": "test", "password": "testxyz", "server": "localhost"} channels = append(channels, &NEW_CHANNEL) newConfig := &common.BotConfig{Id: 1, Config: conf, Channels: channels} + // TODO (yml) there is probably better than sleeping but we need to wait + // until chatbot is fully ready + time.Sleep(time.Second * 2) chatbot.Update(newConfig) - - // Wait a bit - for i := 0; i < 10; i++ { - time.Sleep(time.Second / 3) - if mockSocket.ReceivedLength() >= 1 { - break - } - } - - // Expect a JOIN of NEW_CHANNEL but NOT a JOIN on #test (because already in there) isFound := false - for _, cmd := range mockSocket.Received { - - cmd = strings.TrimSpace(cmd) - - if cmd == "JOIN "+NEW_CHANNEL.Credential() { + for received := range mockSocket.Receiver { + glog.Infoln("[DEBUG] received", received) + if strings.TrimSpace(received) == "JOIN "+NEW_CHANNEL.Credential() { isFound = true - break - } - - if cmd == "JOIN #test" { + close(mockSocket.Receiver) + } else if received == "JOIN #test" { t.Error("Should not rejoin channels already in, can cause flood") } } - if !isFound { t.Error("Expected JOIN " + NEW_CHANNEL.Credential()) } From 0e6dd3a07a51fd80ea24d68e5de1fb3fe621e38e Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 25 Jun 2014 23:44:10 +0200 Subject: [PATCH 56/76] Tells travis that it should also run the tests for the sub packages --- .travis.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.travis.yml b/.travis.yml index 7c37c5b..719367c 100644 --- a/.travis.yml +++ b/.travis.yml @@ -7,4 +7,4 @@ go: install: - go get github.com/BotBotMe/botbot-bot -script: go test github.com/BotBotMe/botbot-bot +script: go test github.com/BotBotMe/botbot-bot/... From a44b98ee724d1d19a92fe53f4a289979b1cf8133 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sat, 28 Jun 2014 17:36:12 +0200 Subject: [PATCH 57/76] Deactivate the pingTimeout case if we get a response. --- network/irc/irc.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/network/irc/irc.go b/network/irc/irc.go index e89fe29..eb7137b 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -182,6 +182,8 @@ func (bot *ircBot) monitor() { // Activate the ping timeout case pingTimeout = time.After(time.Second * 10) case <-bot.pingResponse: + // deactivate the case waiting for a pingTimeout because we got a response + pingTimeout = nil botStats.Add("pong", 1) pongCounter++ if glog.V(1) { From e03945a8451b53100088c9c7fa827f3536b329b5 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sat, 28 Jun 2014 17:45:12 +0200 Subject: [PATCH 58/76] Fix another race in the MockIRCServer implementation. --- common/mock.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/common/mock.go b/common/mock.go index 52de493..cd3c0e7 100644 --- a/common/mock.go +++ b/common/mock.go @@ -85,7 +85,9 @@ func (srv *MockIRCServer) Run(t *testing.T) { // This can happen if a client trys to connect with tls // Got will store the handshake data. The cient will try // connect with a plaintext connect after the tls fails. + srv.Lock() srv.Got = make([]string, 0) + srv.Unlock() if lerr != nil { t.Error("Error on IRC server on Accept. ", err) From f4aeb20b0b4c491da26e31ac8bd5d2ae8dba8de6 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sat, 28 Jun 2014 18:30:26 +0200 Subject: [PATCH 59/76] Cleanup the logging statement use Errorln for error and V(3) for the debug statements --- common/mock.go | 2 +- network/irc/irc.go | 40 ++++++++++++++-------------------------- network/network.go | 2 +- 3 files changed, 16 insertions(+), 28 deletions(-) diff --git a/common/mock.go b/common/mock.go index cd3c0e7..4da8732 100644 --- a/common/mock.go +++ b/common/mock.go @@ -18,7 +18,7 @@ type MockSocket struct { } func (sock MockSocket) Write(data []byte) (int, error) { - glog.Infoln("[Debug]: Starting MockSocket.Write of:", string(data)) + glog.V(3).Infoln("[Debug]: Starting MockSocket.Write of:", string(data)) if sock.Counter != nil { sock.Counter <- true } diff --git a/network/irc/irc.go b/network/irc/irc.go index eb7137b..7463829 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -170,9 +170,6 @@ func (bot *ircBot) monitor() { missedPing = 0 // Deactivate the pingTimeout case pingTimeout = nil - if glog.V(2) { - glog.Infoln("[Info] Message received from the server for", bot) - } case <-time.After(time.Minute * 5): bot.Whois() case <-time.After(time.Second * 60): @@ -212,7 +209,7 @@ func (bot *ircBot) reconnect() { botStats.Add("restart", 1) err := bot.Close() if err != nil { - glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + glog.Errorln("An error occured while Closing the bot", bot, ": ", err) } time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.Init() @@ -341,13 +338,13 @@ func isIPMatch(hostname string, connIP string) bool { addrs, err := net.LookupIP(hostname) if err != nil { - glog.Errorln("Error DNS lookup of "+hostname+": ", err) + glog.Errorln("Error DNS lookup of ", hostname, ": ", err) return false } for _, ip := range addrs { if ip.String() == connIP { - glog.Infoln("Accepting certificate anyway. " + hostname + " has same IP as connection") + glog.Infoln("Accepting certificate anyway. ", hostname, " has same IP as connection") return true } } @@ -381,7 +378,7 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { err := bot.Close() if err != nil { - glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + glog.Errorln("An error occured while Closing the bot", bot, ": ", err) } // TODO (yml) remove // time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped @@ -415,9 +412,8 @@ func (bot *ircBot) updateNick(newNick, newPass string) { // Update the channels based on new configuration, leaving old ones and joining new ones func (bot *ircBot) updateChannels(newChannels []*common.Channel) { glog.Infoln("[Info] Starting bot.updateChannels") - glog.Infoln("[Debug] newChannels: ", newChannels) - glog.Infoln("[Debug] bot.channels: ", bot.channels) bot.RLock() + glog.V(3).Infoln("[Debug] newChannels: ", newChannels, "bot.channels:", bot.channels) if isEqual(newChannels, bot.channels) { if glog.V(2) { @@ -425,7 +421,7 @@ func (bot *ircBot) updateChannels(newChannels []*common.Channel) { } return } - glog.Infoln("[Info] The channels the bot is connected need to be updated") + glog.Infoln("[Info] The channels the bot is connected to need to be updated") // PART old ones for _, channel := range bot.channels { @@ -444,14 +440,9 @@ func (bot *ircBot) updateChannels(newChannels []*common.Channel) { } } bot.RUnlock() - glog.Infoln("[Debug] before Lock") bot.Lock() - glog.Infoln("[Debug] after Lock") bot.channels = newChannels - glog.Infoln("[Debug] before Unlock") bot.Unlock() - glog.Infoln("[Debug] after Unlock") - } // Join channels @@ -469,7 +460,6 @@ func (bot *ircBot) Whois() { // Join an IRC channel func (bot *ircBot) join(channel string) { bot.SendRaw("JOIN " + channel) - glog.Infoln("[Debug] Exiting bot.join") } // Leave an IRC channel @@ -488,7 +478,6 @@ func (bot *ircBot) Send(channel, msg string) { // Send message down socket. Add \n at end first. func (bot *ircBot) SendRaw(msg string) { bot.sendQueue <- []byte(msg + "\n") - glog.Infoln("[Debug] Exiting bot.SendRaw") } // Tell the irc server who we are - we can't do anything until this is done. @@ -515,10 +504,10 @@ func (bot *ircBot) sendPassword() { // Actually really send message to the server. Implements rate limiting. // Should run in go-routine. func (bot *ircBot) sender() { + glog.V(2).Infoln("Starting the sender for", bot) var err error reconnect := make(chan struct{}) botStats := bot.GetStats() - glog.Infoln("[Debug] Starting the sender") for { select { case <-bot.closing: @@ -530,20 +519,19 @@ func (bot *ircBot) sender() { case <-time.After(bot.rateLimit): select { case data := <-bot.sendQueue: - glog.Infoln("[Debug] Pulled data from bot.sendQueue chan:", string(data)) + glog.V(3).Infoln("[Debug]", bot, " Pulled data from bot.sendQueue chan:", string(data)) if bot.socket == nil { // socket does not exist - glog.Infoln("[Info] the socket does not exist, exit listen goroutine") + glog.Infoln(bot, "the socket does not exist, exit listen goroutine") return } - if glog.V(1) { + if glog.V(2) { glog.Infoln("[RAW", bot, "] -->", string(data)) } - glog.Infoln("[Debug] Going to write to bot.socket") _, err = bot.socket.Write(data) if err != nil { - glog.Errorln("[Error] Error writing to socket to", bot, ": ", err) + glog.Errorln("Error writing to socket to", bot, ": ", err) close(reconnect) } botStats.Add("messages", 1) @@ -569,7 +557,7 @@ func (bot *ircBot) readSocket() { if ok && netErr.Timeout() == true { continue } else { - glog.Errorln("[Info] An Error occured while reading from bot.socket ", err) + glog.Errorln("An Error occured while reading from bot.socket ", err) return } } @@ -580,7 +568,7 @@ func (bot *ircBot) readSocket() { content := toUnicode(contentData) if glog.V(2) { - glog.Infoln("[RAW", bot.String(), "]"+content) + glog.Infoln("[RAW", bot, "] <--", content) } bot.receive <- content } @@ -698,7 +686,7 @@ func (bot *ircBot) Close() (err error) { glog.Infoln("[Info] Closing bot.socket.") err = bot.socket.Close() if err != nil { - glog.Infoln("[Error] An error occured while Closing bot.socket", bot, ": ", err) + glog.Errorln("An error occured while Closing bot.socket", bot, ": ", err) } bot.Lock() bot.socket = nil diff --git a/network/network.go b/network/network.go index 600eb1f..1bbb490 100644 --- a/network/network.go +++ b/network/network.go @@ -164,7 +164,7 @@ func (nm *NetworkManager) Shutdown() { for _, bot := range nm.chatbots { err := bot.Close() if err != nil { - glog.Infoln("[Error] An error occured while Closing the bot", bot, ": ", err) + glog.Errorln("An error occured while Closing the bot", bot, ": ", err) } } nm.Unlock() From aa0aae5924234f0f371b87644fe715a34a6f2427 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sat, 28 Jun 2014 20:46:35 +0200 Subject: [PATCH 60/76] Be stingy with the lock and take the smalest lock possible and release it as soon as possible instead of taking it for a complete method --- network/irc/irc.go | 32 ++++++++++++++++++++++---------- network/network.go | 9 ++++++--- 2 files changed, 28 insertions(+), 13 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 7463829..c714bae 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -136,9 +136,8 @@ func (bot *ircBot) GetStats() *expvar.Map { } func (bot *ircBot) String() string { - // TODO understand why the Lock prevent the bot form joining - //bot.RLock() - //defer bot.RUnlock() + bot.RLock() + defer bot.RUnlock() return fmt.Sprintf("%s on %s", bot.nick, bot.address) } @@ -217,13 +216,13 @@ func (bot *ircBot) reconnect() { // Connect to the IRC server and start listener func (bot *ircBot) Init() { - bot.Lock() - defer bot.Unlock() glog.Infoln("Init bot", bot) + bot.Lock() bot.closing = make(chan struct{}) bot.isConnecting = true bot.isAuthenticating = false + bot.Unlock() bot.Connect() @@ -234,14 +233,18 @@ func (bot *ircBot) Init() { go bot.monitor() // Listen for outgoing messages (rate limited) in background thread + bot.Lock() if bot.sendQueue == nil { bot.sendQueue = make(chan []byte, 256) } + bot.Unlock() go bot.sender() + bot.Lock() if bot.serverPass != "" { bot.SendRaw("PASS " + bot.serverPass) } + bot.Unlock() bot.SendRaw("PING Bonjour") } @@ -598,8 +601,6 @@ func (bot *ircBot) listen() { } func (bot *ircBot) act(theLine *line.Line) { - bot.Lock() - defer bot.Unlock() // Notify the monitor goroutine that we receive a PONG if theLine.Command == "PONG" { if glog.V(2) { @@ -612,9 +613,14 @@ func (bot *ircBot) act(theLine *line.Line) { // Send the heartbeat to the monitoring goroutine via monitorChan bot.monitorChan <- struct{}{} + bot.RLock() + isConnecting := bot.isConnecting + bot.RUnlock() // As soon as we receive a message from the server, complete initiatization - if bot.isConnecting { + if isConnecting { + bot.Lock() bot.isConnecting = false + bot.Unlock() bot.login() return } @@ -639,7 +645,9 @@ func (bot *ircBot) act(theLine *line.Line) { return } else if isConfirm { + bot.Lock() bot.isAuthenticating = false + bot.Unlock() bot.JoinAll() return } @@ -647,9 +655,13 @@ func (bot *ircBot) act(theLine *line.Line) { // After USER / NICK is accepted, join all the channels, // assuming we don't need to identify with NickServ - - if bot.isAuthenticating && len(bot.password) == 0 { + bot.RLock() + shouldIdentify := bot.isAuthenticating && len(bot.password) == 0 + bot.RUnlock() + if shouldIdentify { + bot.Lock() bot.isAuthenticating = false + bot.Unlock() bot.JoinAll() return } diff --git a/network/network.go b/network/network.go index 1bbb490..239792d 100644 --- a/network/network.go +++ b/network/network.go @@ -44,8 +44,6 @@ func (nm *NetworkManager) GetUserByChatbotId(id int) string { // Connect to networks / start chatbots. Loads chatbot configuration from DB. func (nm *NetworkManager) RefreshChatbots() { - nm.Lock() - defer nm.Unlock() if glog.V(2) { glog.Infoln("Entering in NetworkManager.RefreshChatbots") } @@ -60,13 +58,17 @@ func (nm *NetworkManager) RefreshChatbots() { id = config.Id active = append(active, id) + nm.RLock() current = nm.chatbots[id] + nm.RUnlock() if current == nil { // Create if glog.V(2) { glog.Infoln("Connect the bot with the following config:", config) } + nm.Lock() nm.chatbots[id] = nm.Connect(config) + nm.Unlock() } else { // Update if glog.V(2) { @@ -80,7 +82,7 @@ func (nm *NetworkManager) RefreshChatbots() { // Stop old ones active.Sort() numActive := len(active) - + nm.Lock() for currId := range nm.chatbots { if active.Search(currId) == numActive { // if currId not in active: @@ -90,6 +92,7 @@ func (nm *NetworkManager) RefreshChatbots() { delete(nm.chatbots, currId) } } + nm.Unlock() if glog.V(2) { glog.Infoln("Exiting NetworkManager.RefreshChatbots") } From 30174430d86cfc480379028e19e99f91ddc84c36 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sat, 28 Jun 2014 22:06:39 +0200 Subject: [PATCH 61/76] Continue reduce time spent locking. --- network/irc/irc.go | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index c714bae..57f0fdb 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -522,8 +522,11 @@ func (bot *ircBot) sender() { case <-time.After(bot.rateLimit): select { case data := <-bot.sendQueue: - glog.V(3).Infoln("[Debug]", bot, " Pulled data from bot.sendQueue chan:", string(data)) - if bot.socket == nil { + glog.V(3).Infoln(bot, " Pulled data from bot.sendQueue chan:", string(data)) + bot.RLock() + nilSocket := bot.socket == nil + bot.RUnlock() + if nilSocket { // socket does not exist glog.Infoln(bot, "the socket does not exist, exit listen goroutine") return @@ -532,7 +535,9 @@ func (bot *ircBot) sender() { if glog.V(2) { glog.Infoln("[RAW", bot, "] -->", string(data)) } + bot.RLock() _, err = bot.socket.Write(data) + bot.RUnlock() if err != nil { glog.Errorln("Error writing to socket to", bot, ": ", err) close(reconnect) @@ -711,8 +716,6 @@ func (bot *ircBot) Close() (err error) { // Send a non-standard SHUTDOWN message to the plugins // This allows them to know that this channel is offline func (bot *ircBot) sendShutdown() { - bot.RLock() - defer bot.RUnlock() glog.Infoln("[Info] Logging Shutdown command in the channels monitored by:", bot) shutLine := &line.Line{ Command: "SHUTDOWN", @@ -722,10 +725,12 @@ func (bot *ircBot) sendShutdown() { Raw: "", Content: ""} + bot.RLock() for _, channel := range bot.channels { shutLine.Channel = channel.Credential() bot.fromServer <- shutLine } + bot.RUnlock() } /* From 6d54ac9629a731b33880f4ef294329efc79fa322 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 29 Jun 2014 01:01:04 +0200 Subject: [PATCH 62/76] Remove bot.closing from the ircBot struct. I explictely pass around a quit chan struct{} this reduce the number of place where I need to lock --- network/irc/irc.go | 82 ++++++++++++++++++++--------------------- network/irc/irc_test.go | 2 - 2 files changed, 39 insertions(+), 45 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 57f0fdb..6cd82fa 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -75,7 +75,6 @@ type ircBot struct { fromServer chan *line.Line monitorChan chan struct{} pingResponse chan struct{} - closing chan struct{} receive chan string } @@ -102,7 +101,6 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot channels: config.Channels, monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - closing: make(chan struct{}), receive: make(chan string), } @@ -147,7 +145,7 @@ func (bot *ircBot) String() string { // If ircBot does not ly maxPingWithoutResponse times try to reconnect // If ircBot does replymaxPongWithoutMessage but we are still not getting // is probably something wrong try to reconnect. -func (bot *ircBot) monitor() { +func (bot *ircBot) monitor(quit chan struct{}) { var pingTimeout <-chan time.Time reconnect := make(chan struct{}) botStats := bot.GetStats() @@ -158,11 +156,11 @@ func (bot *ircBot) monitor() { missedPing := 0 for { select { - case <-bot.closing: + case <-quit: return case <-reconnect: glog.Infoln("IRC monitoring KO", bot) - bot.reconnect() + bot.reconnect(quit) return case <-bot.monitorChan: pongCounter = 0 @@ -202,14 +200,20 @@ func (bot *ircBot) monitor() { } // reconnect the ircBot -func (bot *ircBot) reconnect() { +func (bot *ircBot) reconnect(quit chan struct{}) { glog.Infoln("Trying to reconnect", bot) botStats := bot.GetStats() botStats.Add("restart", 1) - err := bot.Close() - if err != nil { - glog.Errorln("An error occured while Closing the bot", bot, ": ", err) + select { + case <-quit: + glog.Infoln("[Info] chan quit is already closed") + default: + err := bot.Close() + if err != nil { + glog.Errorln("An error occured while Closing the bot", bot, ": ", err) + } } + time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.Init() } @@ -219,18 +223,18 @@ func (bot *ircBot) Init() { glog.Infoln("Init bot", bot) bot.Lock() - bot.closing = make(chan struct{}) + quit := make(chan struct{}) bot.isConnecting = true bot.isAuthenticating = false bot.Unlock() - bot.Connect() + bot.Connect(quit) // Listen for incoming messages in background thread - go bot.listen() + go bot.listen(quit) // Monitor that we are still getting incoming messages in a background thread - go bot.monitor() + go bot.monitor(quit) // Listen for outgoing messages (rate limited) in background thread bot.Lock() @@ -238,7 +242,7 @@ func (bot *ircBot) Init() { bot.sendQueue = make(chan []byte, 256) } bot.Unlock() - go bot.sender() + go bot.sender(quit) bot.Lock() if bot.serverPass != "" { @@ -251,7 +255,7 @@ func (bot *ircBot) Init() { // Connect to the server. Here we keep trying every 10 seconds until we manage // to Dial to the server. -func (bot *ircBot) Connect() { +func (bot *ircBot) Connect(quit chan struct{}) { var ( err error @@ -263,10 +267,10 @@ func (bot *ircBot) Connect() { for { select { - case <-bot.closing: + case <-quit: return case <-connected: - go bot.readSocket() + go bot.readSocket(quit) return case <-connectTimeout: counter++ @@ -506,17 +510,17 @@ func (bot *ircBot) sendPassword() { // Actually really send message to the server. Implements rate limiting. // Should run in go-routine. -func (bot *ircBot) sender() { +func (bot *ircBot) sender(quit chan struct{}) { glog.V(2).Infoln("Starting the sender for", bot) var err error reconnect := make(chan struct{}) botStats := bot.GetStats() for { select { - case <-bot.closing: + case <-quit: return case <-reconnect: - bot.reconnect() + bot.reconnect(quit) // Rate limit to one message every tempo // // https://github.com/BotBotMe/botbot-bot/issues/2 case <-time.After(bot.rateLimit): @@ -551,12 +555,12 @@ func (bot *ircBot) sender() { } // Read from the socket -func (bot *ircBot) readSocket() { +func (bot *ircBot) readSocket(quit chan struct{}) { bufRead := bufio.NewReader(bot.socket) for { select { - case <-bot.closing: + case <-quit: return default: contentData, err := bufRead.ReadBytes('\n') @@ -585,11 +589,11 @@ func (bot *ircBot) readSocket() { // Listen for incoming messages. Parse them and put on channel. // Should run in go-routine -func (bot *ircBot) listen() { +func (bot *ircBot) listen(quit chan struct{}) { botStats := bot.GetStats() for { select { - case <-bot.closing: + case <-quit: return case content := <-bot.receive: theLine, err := parseLine(content) @@ -690,27 +694,19 @@ func (bot *ircBot) act(theLine *line.Line) { // Close ircBot and bot.socket func (bot *ircBot) Close() (err error) { // Send a signal to all goroutine to return - for { - select { - case <-bot.closing: - glog.Infoln("[Info] bot.closing is already closed") - return err - default: - glog.Infoln("[Info] Closing bot.") - bot.sendShutdown() - close(bot.closing) - if bot.socket != nil { - glog.Infoln("[Info] Closing bot.socket.") - err = bot.socket.Close() - if err != nil { - glog.Errorln("An error occured while Closing bot.socket", bot, ": ", err) - } - bot.Lock() - bot.socket = nil - bot.Unlock() - } + glog.Infoln("[Info] Closing bot.") + bot.sendShutdown() + if bot.socket != nil { + glog.Infoln("[Info] Closing bot.socket.") + err = bot.socket.Close() + if err != nil { + glog.Errorln("An error occured while Closing bot.socket", bot, ": ", err) } + bot.Lock() + bot.socket = nil + bot.Unlock() } + return err } // Send a non-standard SHUTDOWN message to the plugins diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 3df5a2a..b6a2f25 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -184,7 +184,6 @@ func TestFlood(t *testing.T) { socket: mockSocket, monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - closing: make(chan struct{}), receive: make(chan string), sendQueue: make(chan []byte, 256), } @@ -236,7 +235,6 @@ func TestUpdate(t *testing.T) { rateLimit: time.Second, monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - closing: make(chan struct{}), receive: make(chan string), sendQueue: make(chan []byte, 256), } From 26b699428ef793faa16e4bd59ebede730cf97f2a Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Sun, 29 Jun 2014 01:14:28 +0200 Subject: [PATCH 63/76] Fix the last known race when the bot get disconnected for more than 4 min --- network/irc/irc.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 6cd82fa..60434a4 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -713,6 +713,7 @@ func (bot *ircBot) Close() (err error) { // This allows them to know that this channel is offline func (bot *ircBot) sendShutdown() { glog.Infoln("[Info] Logging Shutdown command in the channels monitored by:", bot) + bot.RLock() shutLine := &line.Line{ Command: "SHUTDOWN", Received: time.Now().UTC().Format(time.RFC3339Nano), @@ -721,7 +722,6 @@ func (bot *ircBot) sendShutdown() { Raw: "", Content: ""} - bot.RLock() for _, channel := range bot.channels { shutLine.Channel = channel.Credential() bot.fromServer <- shutLine From 69ad07c5821ee1825f03259f729cb6bccb90fcb8 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 30 Jun 2014 10:29:19 +0200 Subject: [PATCH 64/76] Merge sender and listen into a single goroutine ListenAndSend --- network/irc/irc.go | 139 +++++++++++++++++++-------------------------- 1 file changed, 60 insertions(+), 79 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 60434a4..c0da489 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -102,6 +102,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock receive: make(chan string), + sendQueue: make(chan []byte, 256), } chatbotStats, ok := BotStats.GetOrCreate(chatbot.serverIdentifier) @@ -199,6 +200,62 @@ func (bot *ircBot) monitor(quit chan struct{}) { } } +// ListenAndSend receive incoming messages parse them and send response +// to the server. It implements rate limiting. +// Should run in go-routine. +func (bot *ircBot) ListenAndSend(quit chan struct{}) { + glog.V(2).Infoln("Starting the sender for", bot) + var err error + reconnect := make(chan struct{}) + botStats := bot.GetStats() + for { + select { + case <-quit: + return + case <-reconnect: + bot.reconnect(quit) + case content := <-bot.receive: + theLine, err := parseLine(content) + if err == nil { + botStats.Add("received_messages", 1) + theLine.ChatBotId = bot.id + bot.act(theLine) + } else { + glog.Errorln("Invalid line:", content) + } + // Rate limit to one message every tempo + // // https://github.com/BotBotMe/botbot-bot/issues/2 + case <-time.After(bot.rateLimit): + select { + case data := <-bot.sendQueue: + glog.V(3).Infoln(bot, " Pulled data from bot.sendQueue chan:", string(data)) + bot.RLock() + nilSocket := bot.socket == nil + bot.RUnlock() + if nilSocket { + // socket does not exist + glog.Infoln(bot, "the socket does not exist, exit listen goroutine") + return + } + + if glog.V(2) { + glog.Infoln("[RAW", bot, "] -->", string(data)) + } + bot.RLock() + _, err = bot.socket.Write(data) + bot.RUnlock() + if err != nil { + glog.Errorln("Error writing to socket to", bot, ": ", err) + close(reconnect) + } + botStats.Add("messages", 1) + default: + continue + } + } + } +} + // reconnect the ircBot func (bot *ircBot) reconnect(quit chan struct{}) { glog.Infoln("Trying to reconnect", bot) @@ -231,24 +288,16 @@ func (bot *ircBot) Init() { bot.Connect(quit) // Listen for incoming messages in background thread - go bot.listen(quit) + go bot.ListenAndSend(quit) // Monitor that we are still getting incoming messages in a background thread go bot.monitor(quit) - // Listen for outgoing messages (rate limited) in background thread - bot.Lock() - if bot.sendQueue == nil { - bot.sendQueue = make(chan []byte, 256) - } - bot.Unlock() - go bot.sender(quit) - - bot.Lock() + bot.RLock() if bot.serverPass != "" { bot.SendRaw("PASS " + bot.serverPass) } - bot.Unlock() + bot.RUnlock() bot.SendRaw("PING Bonjour") } @@ -508,52 +557,6 @@ func (bot *ircBot) sendPassword() { bot.Send("NickServ", "identify "+bot.password) } -// Actually really send message to the server. Implements rate limiting. -// Should run in go-routine. -func (bot *ircBot) sender(quit chan struct{}) { - glog.V(2).Infoln("Starting the sender for", bot) - var err error - reconnect := make(chan struct{}) - botStats := bot.GetStats() - for { - select { - case <-quit: - return - case <-reconnect: - bot.reconnect(quit) - // Rate limit to one message every tempo - // // https://github.com/BotBotMe/botbot-bot/issues/2 - case <-time.After(bot.rateLimit): - select { - case data := <-bot.sendQueue: - glog.V(3).Infoln(bot, " Pulled data from bot.sendQueue chan:", string(data)) - bot.RLock() - nilSocket := bot.socket == nil - bot.RUnlock() - if nilSocket { - // socket does not exist - glog.Infoln(bot, "the socket does not exist, exit listen goroutine") - return - } - - if glog.V(2) { - glog.Infoln("[RAW", bot, "] -->", string(data)) - } - bot.RLock() - _, err = bot.socket.Write(data) - bot.RUnlock() - if err != nil { - glog.Errorln("Error writing to socket to", bot, ": ", err) - close(reconnect) - } - botStats.Add("messages", 1) - default: - continue - } - } - } -} - // Read from the socket func (bot *ircBot) readSocket(quit chan struct{}) { @@ -587,28 +590,6 @@ func (bot *ircBot) readSocket(quit chan struct{}) { } } -// Listen for incoming messages. Parse them and put on channel. -// Should run in go-routine -func (bot *ircBot) listen(quit chan struct{}) { - botStats := bot.GetStats() - for { - select { - case <-quit: - return - case content := <-bot.receive: - theLine, err := parseLine(content) - if err == nil { - botStats.Add("received_messages", 1) - theLine.ChatBotId = bot.id - bot.act(theLine) - } else { - glog.Errorln("Invalid line:", content) - } - - } - } -} - func (bot *ircBot) act(theLine *line.Line) { // Notify the monitor goroutine that we receive a PONG if theLine.Command == "PONG" { From 6dd12e3c686a29e6d631ff63ba390b70165f738b Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 30 Jun 2014 12:01:04 +0200 Subject: [PATCH 65/76] Fix a deadlock when several gorountines try to get the botstats. --- network/irc/irc.go | 28 +++++++++++++++++----------- 1 file changed, 17 insertions(+), 11 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index c0da489..ab9fc1f 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -36,20 +36,21 @@ const ( ) type chatBotStats struct { - sync.Mutex + sync.RWMutex m map[string]*expvar.Map } func (s chatBotStats) GetOrCreate(identifier string) (*expvar.Map, bool) { - s.Lock() - defer s.Unlock() + s.RLock() chatbotStats, ok := s.m[identifier] + s.RUnlock() if !ok { chatbotStats = expvar.NewMap(identifier) + s.Lock() s.m[identifier] = chatbotStats + s.Unlock() } return chatbotStats, ok - } var ( @@ -128,8 +129,6 @@ func (bot *ircBot) GetUser() string { } func (bot *ircBot) GetStats() *expvar.Map { - bot.Lock() - defer bot.Unlock() stats, _ := BotStats.GetOrCreate(bot.serverIdentifier) return stats } @@ -149,7 +148,6 @@ func (bot *ircBot) String() string { func (bot *ircBot) monitor(quit chan struct{}) { var pingTimeout <-chan time.Time reconnect := make(chan struct{}) - botStats := bot.GetStats() // TODO maxPongWithoutMessage should probably be a field of ircBot maxPingWithoutResponse := 3 maxPongWithoutMessage := 150 @@ -172,6 +170,7 @@ func (bot *ircBot) monitor(quit chan struct{}) { bot.Whois() case <-time.After(time.Second * 60): glog.Infoln("[Info] Ping the ircBot server", pongCounter, bot) + botStats := bot.GetStats() botStats.Add("ping", 1) bot.SendRaw("PING 1") // Activate the ping timeout case @@ -179,6 +178,7 @@ func (bot *ircBot) monitor(quit chan struct{}) { case <-bot.pingResponse: // deactivate the case waiting for a pingTimeout because we got a response pingTimeout = nil + botStats := bot.GetStats() botStats.Add("pong", 1) pongCounter++ if glog.V(1) { @@ -190,6 +190,7 @@ func (bot *ircBot) monitor(quit chan struct{}) { case <-pingTimeout: // Deactivate the pingTimeout case pingTimeout = nil + botStats := bot.GetStats() botStats.Add("missed_ping", 1) missedPing++ glog.Infoln("[Info] No pong from ircBot server", bot, "missed", missedPing) @@ -207,7 +208,6 @@ func (bot *ircBot) ListenAndSend(quit chan struct{}) { glog.V(2).Infoln("Starting the sender for", bot) var err error reconnect := make(chan struct{}) - botStats := bot.GetStats() for { select { case <-quit: @@ -217,6 +217,7 @@ func (bot *ircBot) ListenAndSend(quit chan struct{}) { case content := <-bot.receive: theLine, err := parseLine(content) if err == nil { + botStats := bot.GetStats() botStats.Add("received_messages", 1) theLine.ChatBotId = bot.id bot.act(theLine) @@ -248,6 +249,7 @@ func (bot *ircBot) ListenAndSend(quit chan struct{}) { glog.Errorln("Error writing to socket to", bot, ": ", err) close(reconnect) } + botStats := bot.GetStats() botStats.Add("messages", 1) default: continue @@ -451,17 +453,21 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { // Update the nickname we're registered under, if needed func (bot *ircBot) updateNick(newNick, newPass string) { - bot.Lock() - defer bot.Unlock() glog.Infoln("[Info] Starting bot.updateNick()") - if newNick == bot.nick { + + bot.RLock() + nick := bot.nick + bot.RUnlock() + if newNick == nick { glog.Infoln("[Info] bot.updateNick() -- the nick has not changed so return") return } glog.Infoln("[Info] bot.updateNick() -- set the new nick") + bot.Lock() bot.nick = newNick bot.password = newPass + bot.Unlock() bot.setNick() } From 9ab1f491f75b2637328da9eea17b9f6964fc3aab Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 30 Jun 2014 16:19:12 +0200 Subject: [PATCH 66/76] Double the number of Max open connections to postgres --- common/storage.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common/storage.go b/common/storage.go index 40fed17..2e005cd 100644 --- a/common/storage.go +++ b/common/storage.go @@ -73,7 +73,7 @@ func NewPostgresStorage() *PostgresStorage { // The following 2 lines mitigate the leak of postgresql connection leak // explicitly setting a maximum number of postgresql connections - db.SetMaxOpenConns(5) + db.SetMaxOpenConns(10) // explicitly setting a maximum number of Idle postgresql connections db.SetMaxIdleConns(2) From 1ba3ff6f2f26674385db5b7bc46a64353da97da5 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Mon, 30 Jun 2014 18:40:33 +0200 Subject: [PATCH 67/76] Reduce the time where we are locking the bot in the bot.updateNick --- network/irc/irc.go | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index ab9fc1f..48dfef4 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -475,9 +475,12 @@ func (bot *ircBot) updateNick(newNick, newPass string) { func (bot *ircBot) updateChannels(newChannels []*common.Channel) { glog.Infoln("[Info] Starting bot.updateChannels") bot.RLock() - glog.V(3).Infoln("[Debug] newChannels: ", newChannels, "bot.channels:", bot.channels) + channels := bot.channels + bot.RUnlock() + + glog.V(3).Infoln("[Debug] newChannels: ", newChannels, "bot.channels:", channels) - if isEqual(newChannels, bot.channels) { + if isEqual(newChannels, channels) { if glog.V(2) { glog.Infoln("Channels comparison is equals for bot: ", bot.nick) } @@ -486,7 +489,7 @@ func (bot *ircBot) updateChannels(newChannels []*common.Channel) { glog.Infoln("[Info] The channels the bot is connected to need to be updated") // PART old ones - for _, channel := range bot.channels { + for _, channel := range channels { if !isIn(channel, newChannels) { glog.Infoln("[Info] Parting new channel: ", channel.Credential()) bot.part(channel.Credential()) @@ -495,13 +498,11 @@ func (bot *ircBot) updateChannels(newChannels []*common.Channel) { // JOIN new ones for _, channel := range newChannels { - if !isIn(channel, bot.channels) { + if !isIn(channel, channels) { glog.Infoln("[Info] Joining new channel: ", channel.Credential()) bot.join(channel.Credential()) - glog.Infoln("[DEBUG] After join") } } - bot.RUnlock() bot.Lock() bot.channels = newChannels bot.Unlock() From abce29cf975ff16c2ac799e2ccfdbd06939659b7 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 1 Jul 2014 09:47:50 +0200 Subject: [PATCH 68/76] Temporary remove self.recordUserCounts() from the code base because I think it is leaking postgres connection --- botbot.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/botbot.go b/botbot.go index 7bad1d0..ac4e031 100644 --- a/botbot.go +++ b/botbot.go @@ -74,7 +74,9 @@ func (self *BotBot) listen(queueName string) { func (self *BotBot) mainLoop() { - go self.recordUserCounts() + // TODO (yml) comment out self.recordUserCounts because I think it is + // leaking postgres connection. + //go self.recordUserCounts() var busCommand string var args string From 3205be5c996ffc5df8f598e0dcf315ae36c16d7d Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 1 Jul 2014 10:44:46 +0200 Subject: [PATCH 69/76] nothing --- botbot.go | 1 - 1 file changed, 1 deletion(-) diff --git a/botbot.go b/botbot.go index ac4e031..a851035 100644 --- a/botbot.go +++ b/botbot.go @@ -73,7 +73,6 @@ func (self *BotBot) listen(queueName string) { } func (self *BotBot) mainLoop() { - // TODO (yml) comment out self.recordUserCounts because I think it is // leaking postgres connection. //go self.recordUserCounts() From c7909d651b3d830d28db40c29c3e3bf4e82cb32c Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Tue, 1 Jul 2014 11:45:55 +0200 Subject: [PATCH 70/76] nothing --- botbot.go | 1 - 1 file changed, 1 deletion(-) diff --git a/botbot.go b/botbot.go index a851035..9988d36 100644 --- a/botbot.go +++ b/botbot.go @@ -81,7 +81,6 @@ func (self *BotBot) mainLoop() { var args string for { select { - case serverLine, ok := <-self.fromServer: if !ok { // Channel is closed, we're offline. Stop. From 21edbcb401465cef7d2261199c2a7f693d7f764b Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 2 Jul 2014 10:12:03 +0200 Subject: [PATCH 71/76] move ircBot.init() to a not exported name. --- network/irc/irc.go | 8 ++++---- network/irc/irc_test.go | 4 ++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 48dfef4..4719661 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -120,7 +120,7 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot chatbotStats.Add("reply_whoischannels", 0) } - chatbot.Init() + chatbot.init() return chatbot } @@ -274,11 +274,11 @@ func (bot *ircBot) reconnect(quit chan struct{}) { } time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped - bot.Init() + bot.init() } // Connect to the IRC server and start listener -func (bot *ircBot) Init() { +func (bot *ircBot) init() { glog.Infoln("Init bot", bot) bot.Lock() @@ -446,7 +446,7 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { bot.password = config.Config["password"] bot.channels = config.Channels - bot.Init() + bot.init() return true } diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index b6a2f25..dad33f2 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -187,7 +187,7 @@ func TestFlood(t *testing.T) { receive: make(chan string), sendQueue: make(chan []byte, 256), } - chatbot.Init() + chatbot.init() startTime := time.Now() @@ -238,7 +238,7 @@ func TestUpdate(t *testing.T) { receive: make(chan string), sendQueue: make(chan []byte, 256), } - chatbot.Init() + chatbot.init() conf := map[string]string{ "nick": "test", "password": "testxyz", "server": "localhost"} channels = append(channels, &NEW_CHANNEL) From fbbeb8529c1927cd8b4ec1e7139cd2c643d3cc68 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 2 Jul 2014 10:24:10 +0200 Subject: [PATCH 72/76] Move Connect and ListenAndSend to not exported name. --- network/irc/irc.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/network/irc/irc.go b/network/irc/irc.go index 4719661..3d48ad0 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -201,10 +201,10 @@ func (bot *ircBot) monitor(quit chan struct{}) { } } -// ListenAndSend receive incoming messages parse them and send response +// listenAndSend receive incoming messages parse them and send response // to the server. It implements rate limiting. // Should run in go-routine. -func (bot *ircBot) ListenAndSend(quit chan struct{}) { +func (bot *ircBot) listenAndSend(quit chan struct{}) { glog.V(2).Infoln("Starting the sender for", bot) var err error reconnect := make(chan struct{}) @@ -287,10 +287,10 @@ func (bot *ircBot) init() { bot.isAuthenticating = false bot.Unlock() - bot.Connect(quit) + bot.connect(quit) // Listen for incoming messages in background thread - go bot.ListenAndSend(quit) + go bot.listenAndSend(quit) // Monitor that we are still getting incoming messages in a background thread go bot.monitor(quit) @@ -304,9 +304,9 @@ func (bot *ircBot) init() { bot.SendRaw("PING Bonjour") } -// Connect to the server. Here we keep trying every 10 seconds until we manage +// connect to the server. Here we keep trying every 10 seconds until we manage // to Dial to the server. -func (bot *ircBot) Connect(quit chan struct{}) { +func (bot *ircBot) connect(quit chan struct{}) { var ( err error From d4591bfd3bab10746b27a1f1793e1a5586c35441 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 2 Jul 2014 13:38:45 +0200 Subject: [PATCH 73/76] Spring cleanup. Reduce the surface of ircBot. Move ircBot.connect() outside the ircBot.init() to make testing easier and less hackish. ircBot.init() now takes a conn as argument. --- main_test.go | 1 + network/irc/irc.go | 212 +++++++++++++++------------------------- network/irc/irc_test.go | 10 +- 3 files changed, 83 insertions(+), 140 deletions(-) diff --git a/main_test.go b/main_test.go index 6e00508..72adbfd 100644 --- a/main_test.go +++ b/main_test.go @@ -33,6 +33,7 @@ func TestBotBotIRC(t *testing.T) { // Start a Mock IRC server, and gather writes to it server := common.NewMockIRCServer(TEST_MSG, SERVER_PORT) go server.Run(t) + time.Sleep(time.Second) // Run BotBot botbot := NewBotBot(storage, queue) diff --git a/network/irc/irc.go b/network/irc/irc.go index 3d48ad0..27af987 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -1,7 +1,7 @@ // IRC server connection // // Connecting to an IRC server goes like this: -// 1. Connect to the socket. Wait for a response (anything will do). +// 1. Connect to the conn. Wait for a response (anything will do). // 2. Send USER and NICK. Wait for a response (anything). // 2.5 If we have a password, wait for NickServ to ask for it, and to confirm authentication // 3. JOIN channels @@ -62,7 +62,6 @@ type ircBot struct { sync.RWMutex id int address string - socket io.ReadWriteCloser nick string realname string password string @@ -74,9 +73,8 @@ type ircBot struct { isAuthenticating bool sendQueue chan []byte fromServer chan *line.Line - monitorChan chan struct{} pingResponse chan struct{} - receive chan string + closing chan struct{} } // NewBot create an irc instance of ChatBot @@ -100,10 +98,9 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot rateLimit: time.Second, fromServer: fromServer, channels: config.Channels, - monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - receive: make(chan string), sendQueue: make(chan []byte, 256), + closing: make(chan struct{}), } chatbotStats, ok := BotStats.GetOrCreate(chatbot.serverIdentifier) @@ -120,7 +117,8 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot chatbotStats.Add("reply_whoischannels", 0) } - chatbot.init() + conn := chatbot.connect() + chatbot.init(conn) return chatbot } @@ -139,13 +137,13 @@ func (bot *ircBot) String() string { return fmt.Sprintf("%s on %s", bot.nick, bot.address) } -// Monitor that we are still connected to the IRC server +// monitor that we are still connected to the IRC server // should run in go-routine // If no message is received during 60 actively ping ircBot. -// If ircBot does not ly maxPingWithoutResponse times try to reconnect +// If ircBot does not reply maxPingWithoutResponse times try to reconnect // If ircBot does replymaxPongWithoutMessage but we are still not getting // is probably something wrong try to reconnect. -func (bot *ircBot) monitor(quit chan struct{}) { +func (bot *ircBot) listenSendMonitor(quit chan struct{}, receive chan string, conn io.ReadWriteCloser) { var pingTimeout <-chan time.Time reconnect := make(chan struct{}) // TODO maxPongWithoutMessage should probably be a field of ircBot @@ -153,6 +151,9 @@ func (bot *ircBot) monitor(quit chan struct{}) { maxPongWithoutMessage := 150 pongCounter := 0 missedPing := 0 + whoisTimerChan := time.After(time.Minute * 5) + + botStats := bot.GetStats() for { select { case <-quit: @@ -160,17 +161,11 @@ func (bot *ircBot) monitor(quit chan struct{}) { case <-reconnect: glog.Infoln("IRC monitoring KO", bot) bot.reconnect(quit) - return - case <-bot.monitorChan: - pongCounter = 0 - missedPing = 0 - // Deactivate the pingTimeout case - pingTimeout = nil - case <-time.After(time.Minute * 5): + case <-whoisTimerChan: bot.Whois() + whoisTimerChan = time.After(time.Minute * 5) case <-time.After(time.Second * 60): glog.Infoln("[Info] Ping the ircBot server", pongCounter, bot) - botStats := bot.GetStats() botStats.Add("ping", 1) bot.SendRaw("PING 1") // Activate the ping timeout case @@ -178,7 +173,6 @@ func (bot *ircBot) monitor(quit chan struct{}) { case <-bot.pingResponse: // deactivate the case waiting for a pingTimeout because we got a response pingTimeout = nil - botStats := bot.GetStats() botStats.Add("pong", 1) pongCounter++ if glog.V(1) { @@ -190,70 +184,43 @@ func (bot *ircBot) monitor(quit chan struct{}) { case <-pingTimeout: // Deactivate the pingTimeout case pingTimeout = nil - botStats := bot.GetStats() botStats.Add("missed_ping", 1) missedPing++ glog.Infoln("[Info] No pong from ircBot server", bot, "missed", missedPing) if missedPing > maxPingWithoutResponse { close(reconnect) } - } - } -} - -// listenAndSend receive incoming messages parse them and send response -// to the server. It implements rate limiting. -// Should run in go-routine. -func (bot *ircBot) listenAndSend(quit chan struct{}) { - glog.V(2).Infoln("Starting the sender for", bot) - var err error - reconnect := make(chan struct{}) - for { - select { - case <-quit: - return - case <-reconnect: - bot.reconnect(quit) - case content := <-bot.receive: + case content := <-receive: theLine, err := parseLine(content) if err == nil { - botStats := bot.GetStats() botStats.Add("received_messages", 1) + bot.RLock() theLine.ChatBotId = bot.id + bot.RUnlock() bot.act(theLine) + pongCounter = 0 + missedPing = 0 + // Deactivate the pingTimeout case + pingTimeout = nil + } else { glog.Errorln("Invalid line:", content) } // Rate limit to one message every tempo // // https://github.com/BotBotMe/botbot-bot/issues/2 - case <-time.After(bot.rateLimit): - select { - case data := <-bot.sendQueue: - glog.V(3).Infoln(bot, " Pulled data from bot.sendQueue chan:", string(data)) - bot.RLock() - nilSocket := bot.socket == nil - bot.RUnlock() - if nilSocket { - // socket does not exist - glog.Infoln(bot, "the socket does not exist, exit listen goroutine") - return - } - - if glog.V(2) { - glog.Infoln("[RAW", bot, "] -->", string(data)) - } - bot.RLock() - _, err = bot.socket.Write(data) - bot.RUnlock() - if err != nil { - glog.Errorln("Error writing to socket to", bot, ": ", err) - close(reconnect) - } - botStats := bot.GetStats() - botStats.Add("messages", 1) - default: - continue + case data := <-bot.sendQueue: + glog.V(3).Infoln(bot, " Pulled data from bot.sendQueue chan:", string(data)) + if glog.V(2) { + glog.Infoln("[RAW", bot, "] -->", string(data)) + } + _, err := conn.Write(data) + if err != nil { + glog.Errorln("Error writing to conn to", bot, ": ", err) + close(reconnect) } + botStats.Add("messages", 1) + time.Sleep(bot.rateLimit) + } } } @@ -263,37 +230,41 @@ func (bot *ircBot) reconnect(quit chan struct{}) { glog.Infoln("Trying to reconnect", bot) botStats := bot.GetStats() botStats.Add("restart", 1) - select { - case <-quit: - glog.Infoln("[Info] chan quit is already closed") - default: - err := bot.Close() - if err != nil { - glog.Errorln("An error occured while Closing the bot", bot, ": ", err) - } + err := bot.Close() + if err != nil { + glog.Errorln("An error occured while Closing the bot", bot, ": ", err) } time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped - bot.init() + conn := bot.connect() + bot.init(conn) } // Connect to the IRC server and start listener -func (bot *ircBot) init() { - +func (bot *ircBot) init(conn io.ReadWriteCloser) { glog.Infoln("Init bot", bot) - bot.Lock() + quit := make(chan struct{}) - bot.isConnecting = true - bot.isAuthenticating = false - bot.Unlock() + receive := make(chan string) - bot.connect(quit) + go bot.readSocket(quit, receive, conn) // Listen for incoming messages in background thread - go bot.listenAndSend(quit) + go bot.listenSendMonitor(quit, receive, conn) - // Monitor that we are still getting incoming messages in a background thread - go bot.monitor(quit) + go func(bot *ircBot, conn io.Closer) { + for { + select { + case <-bot.closing: + err := conn.Close() + if err != nil { + glog.Errorln("An error occured while closing the conn of", bot, err) + } + close(quit) + return + } + } + }(bot, conn) bot.RLock() if bot.serverPass != "" { @@ -306,58 +277,48 @@ func (bot *ircBot) init() { // connect to the server. Here we keep trying every 10 seconds until we manage // to Dial to the server. -func (bot *ircBot) connect(quit chan struct{}) { +func (bot *ircBot) connect() (conn io.ReadWriteCloser) { var ( err error counter int ) - connected := make(chan struct{}) connectTimeout := time.After(0) + bot.Lock() + bot.isConnecting = true + bot.isAuthenticating = false + bot.Unlock() + for { select { - case <-quit: - return - case <-connected: - go bot.readSocket(quit) - return case <-connectTimeout: counter++ connectTimeout = nil glog.Infoln("[Info] Connecting to IRC server: ", bot.address) - if _, ok := bot.socket.(common.MockSocket); ok { - // The test suite take advantage of this special case by crafting a bot that provides its own mocksocket implementation. - glog.Infoln("[Info] This message should only ever be seen while running the test suite") - close(connected) - continue - } - - bot.socket, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first + conn, err = tls.Dial("tcp", bot.address, nil) // Always try TLS first if err == nil { glog.Infoln("Connected: TLS secure") - close(connected) - continue + return conn } else if _, ok := err.(x509.HostnameError); ok { glog.Infoln("Could not connect using TLS because: ", err) // Certificate might not match. This happens on irc.cloudfront.net insecure := &tls.Config{InsecureSkipVerify: true} - bot.socket, err = tls.Dial("tcp", bot.address, insecure) + conn, err = tls.Dial("tcp", bot.address, insecure) - if err == nil && isCertValid(bot.socket.(*tls.Conn)) { + if err == nil && isCertValid(conn.(*tls.Conn)) { glog.Infoln("Connected: TLS with awkward certificate") - close(connected) - continue + return conn } } - bot.socket, err = net.Dial("tcp", bot.address) + conn, err = net.Dial("tcp", bot.address) if err == nil { glog.Infoln("Connected: Plain text insecure") - close(connected) - continue + return conn } + // TODO (yml) At some point we might want to panic delay := 5 * counter glog.Infoln("IRC Connect error. Will attempt to re-connect. ", err, "in", delay, "seconds") connectTimeout = time.After(time.Duration(delay) * time.Second) @@ -438,15 +399,14 @@ func (bot *ircBot) updateServer(config *common.BotConfig) bool { if err != nil { glog.Errorln("An error occured while Closing the bot", bot, ": ", err) } - // TODO (yml) remove - // time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped bot.address = addr bot.nick = config.Config["nick"] bot.password = config.Config["password"] bot.channels = config.Channels - bot.init() + conn := bot.connect() + bot.init(conn) return true } @@ -538,7 +498,7 @@ func (bot *ircBot) Send(channel, msg string) { bot.SendRaw(fullmsg) } -// Send message down socket. Add \n at end first. +// Send message down conn. Add \n at end first. func (bot *ircBot) SendRaw(msg string) { bot.sendQueue <- []byte(msg + "\n") } @@ -564,10 +524,10 @@ func (bot *ircBot) sendPassword() { bot.Send("NickServ", "identify "+bot.password) } -// Read from the socket -func (bot *ircBot) readSocket(quit chan struct{}) { +// Read from the conn +func (bot *ircBot) readSocket(quit chan struct{}, receive chan string, conn io.ReadWriteCloser) { - bufRead := bufio.NewReader(bot.socket) + bufRead := bufio.NewReader(conn) for { select { case <-quit: @@ -579,7 +539,7 @@ func (bot *ircBot) readSocket(quit chan struct{}) { if ok && netErr.Timeout() == true { continue } else { - glog.Errorln("An Error occured while reading from bot.socket ", err) + glog.Errorln("An Error occured while reading from bot.conn ", err) return } } @@ -592,7 +552,7 @@ func (bot *ircBot) readSocket(quit chan struct{}) { if glog.V(2) { glog.Infoln("[RAW", bot, "] <--", content) } - bot.receive <- content + receive <- content } } } @@ -607,9 +567,6 @@ func (bot *ircBot) act(theLine *line.Line) { return } - // Send the heartbeat to the monitoring goroutine via monitorChan - bot.monitorChan <- struct{}{} - bot.RLock() isConnecting := bot.isConnecting bot.RUnlock() @@ -679,21 +636,12 @@ func (bot *ircBot) act(theLine *line.Line) { bot.fromServer <- theLine } -// Close ircBot and bot.socket +// Close ircBot func (bot *ircBot) Close() (err error) { // Send a signal to all goroutine to return glog.Infoln("[Info] Closing bot.") bot.sendShutdown() - if bot.socket != nil { - glog.Infoln("[Info] Closing bot.socket.") - err = bot.socket.Close() - if err != nil { - glog.Errorln("An error occured while Closing bot.socket", bot, ": ", err) - } - bot.Lock() - bot.socket = nil - bot.Unlock() - } + close(bot.closing) return err } diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index dad33f2..2e3d77d 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -181,13 +181,10 @@ func TestFlood(t *testing.T) { rateLimit: time.Second, fromServer: fromServer, channels: channels, - socket: mockSocket, - monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - receive: make(chan string), sendQueue: make(chan []byte, 256), } - chatbot.init() + chatbot.init(mockSocket) startTime := time.Now() @@ -231,14 +228,11 @@ func TestUpdate(t *testing.T) { serverIdentifier: "localhost.test1", fromServer: fromServer, channels: channels, - socket: mockSocket, rateLimit: time.Second, - monitorChan: make(chan struct{}), pingResponse: make(chan struct{}, 10), // HACK: This is to avoid the current deadlock - receive: make(chan string), sendQueue: make(chan []byte, 256), } - chatbot.init() + chatbot.init(mockSocket) conf := map[string]string{ "nick": "test", "password": "testxyz", "server": "localhost"} channels = append(channels, &NEW_CHANNEL) From 8fe417b7002199a79479cd07f8288fc6eead40ce Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 2 Jul 2014 15:54:48 +0200 Subject: [PATCH 74/76] The reconnect is done at the networkmanager level. More cleanup --- botbot.go | 3 +-- common/common.go | 2 +- main_test.go | 7 +++++- network/irc/irc.go | 59 ++++++++++++++++++++++++---------------------- network/network.go | 25 ++++++++++---------- 5 files changed, 51 insertions(+), 45 deletions(-) diff --git a/botbot.go b/botbot.go index 9988d36..07fc36c 100644 --- a/botbot.go +++ b/botbot.go @@ -35,8 +35,7 @@ func NewBotBot(storage common.Storage, queue common.Queue) *BotBot { netMan := network.NewNetworkManager(storage, fromServer) netMan.RefreshChatbots() - // TODO (yml) We might be able to get rid of this goroutine - //go netMan.MonitorChatbots() + go netMan.MonitorChatbots() dis := dispatch.NewDispatcher(queue) diff --git a/common/common.go b/common/common.go index 52d6ffb..478218e 100644 --- a/common/common.go +++ b/common/common.go @@ -10,7 +10,7 @@ type ChatBot interface { io.Closer Send(channel, msg string) Update(config *BotConfig) - //IsRunning() bool + IsRunning() bool GetUser() string } diff --git a/main_test.go b/main_test.go index 72adbfd..ce66612 100644 --- a/main_test.go +++ b/main_test.go @@ -6,6 +6,7 @@ import ( "time" "github.com/BotBotMe/botbot-bot/common" + "github.com/golang/glog" ) const ( @@ -31,7 +32,10 @@ func TestBotBotIRC(t *testing.T) { queue := common.NewMockQueue() // Start a Mock IRC server, and gather writes to it + glog.Infoln("[Debug] before common.NewMockIRCServer") + server := common.NewMockIRCServer(TEST_MSG, SERVER_PORT) + glog.Infoln("[Debug] After common.NewMockIRCServer") go server.Run(t) time.Sleep(time.Second) @@ -81,9 +85,10 @@ func TestBotBotIRC(t *testing.T) { // Block until len(target.Get) is at least val, or timeout func waitForServer(target *common.MockIRCServer, val int) { - + glog.Infoln("[Debug] waitForServer:") tries := 0 for target.GotLength() < val && tries < 200 { + glog.Infoln("[Debug] target.Got:", target.Got) time.Sleep(50 * time.Millisecond) tries++ } diff --git a/network/irc/irc.go b/network/irc/irc.go index 27af987..eb5d2f4 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -54,7 +54,7 @@ func (s chatBotStats) GetOrCreate(identifier string) (*expvar.Map, bool) { } var ( - // BotStats hold the reference to the expvar.Map for each ircBot instance + // BotStats hold the references to the expvar.Map for each ircBot instance BotStats = chatBotStats{m: make(map[string]*expvar.Map)} ) @@ -71,6 +71,7 @@ type ircBot struct { channels []*common.Channel isConnecting bool isAuthenticating bool + isClosed bool sendQueue chan []byte fromServer chan *line.Line pingResponse chan struct{} @@ -79,7 +80,6 @@ type ircBot struct { // NewBot create an irc instance of ChatBot func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot { - // realname is set to config["realname"] or config["nick"] realname := config.Config["realname"] if realname == "" { @@ -122,32 +122,41 @@ func NewBot(config *common.BotConfig, fromServer chan *line.Line) common.ChatBot return chatbot } +// GetUser returns the bot.nick func (bot *ircBot) GetUser() string { + bot.RLock() + defer bot.RUnlock() return bot.nick } +// IsRunning the isRunning field +func (bot *ircBot) IsRunning() bool { + bot.RLock() + defer bot.RUnlock() + return !bot.isClosed +} + +// GetStats returns the expvar.Map for this bot func (bot *ircBot) GetStats() *expvar.Map { stats, _ := BotStats.GetOrCreate(bot.serverIdentifier) return stats } +// String returns the string representation of the bot func (bot *ircBot) String() string { bot.RLock() defer bot.RUnlock() return fmt.Sprintf("%s on %s", bot.nick, bot.address) } -// monitor that we are still connected to the IRC server -// should run in go-routine -// If no message is received during 60 actively ping ircBot. -// If ircBot does not reply maxPingWithoutResponse times try to reconnect -// If ircBot does replymaxPongWithoutMessage but we are still not getting -// is probably something wrong try to reconnect. +// listenSendMonitor is the main goroutine of the ircBot it listens to the conn +// send response to irc via the conn and it check that the conn is healthy if +// it is not it try to reconnect. func (bot *ircBot) listenSendMonitor(quit chan struct{}, receive chan string, conn io.ReadWriteCloser) { var pingTimeout <-chan time.Time reconnect := make(chan struct{}) // TODO maxPongWithoutMessage should probably be a field of ircBot - maxPingWithoutResponse := 3 + maxPingWithoutResponse := 1 // put it back to 3 maxPongWithoutMessage := 150 pongCounter := 0 missedPing := 0 @@ -159,8 +168,13 @@ func (bot *ircBot) listenSendMonitor(quit chan struct{}, receive chan string, co case <-quit: return case <-reconnect: - glog.Infoln("IRC monitoring KO", bot) - bot.reconnect(quit) + glog.Infoln("IRC monitoring KO shutting down", bot) + botStats.Add("restart", 1) + err := bot.Close() + if err != nil { + glog.Errorln("An error occured while Closing the bot", bot, ": ", err) + } + return case <-whoisTimerChan: bot.Whois() whoisTimerChan = time.After(time.Minute * 5) @@ -225,22 +239,8 @@ func (bot *ircBot) listenSendMonitor(quit chan struct{}, receive chan string, co } } -// reconnect the ircBot -func (bot *ircBot) reconnect(quit chan struct{}) { - glog.Infoln("Trying to reconnect", bot) - botStats := bot.GetStats() - botStats.Add("restart", 1) - err := bot.Close() - if err != nil { - glog.Errorln("An error occured while Closing the bot", bot, ": ", err) - } - - time.Sleep(1 * time.Second) // Wait for timeout to be sure listen has stopped - conn := bot.connect() - bot.init(conn) -} - -// Connect to the IRC server and start listener +// init initializes the conn to the ircServer and start all the gouroutines +// requires to run ircBot func (bot *ircBot) init(conn io.ReadWriteCloser) { glog.Infoln("Init bot", bot) @@ -539,7 +539,7 @@ func (bot *ircBot) readSocket(quit chan struct{}, receive chan string, conn io.R if ok && netErr.Timeout() == true { continue } else { - glog.Errorln("An Error occured while reading from bot.conn ", err) + glog.Errorln("An Error occured while reading from conn ", err) return } } @@ -642,6 +642,9 @@ func (bot *ircBot) Close() (err error) { glog.Infoln("[Info] Closing bot.") bot.sendShutdown() close(bot.closing) + bot.Lock() + bot.isClosed = true + bot.Unlock() return err } diff --git a/network/network.go b/network/network.go index 239792d..3d346f0 100644 --- a/network/network.go +++ b/network/network.go @@ -3,6 +3,7 @@ package network import ( "sort" "sync" + "time" "github.com/golang/glog" @@ -111,19 +112,17 @@ func (nm *NetworkManager) Send(chatbotId int, channel, msg string) { nm.RUnlock() } -// TODO(yml) find out if this is needed since we deal with it at the IRC level -// // Check out chatbots are alive, recreating them if not. Run this in go-routine. -// func (nm *NetworkManager) MonitorChatbots() { -// -// for nm.IsRunning() { -// for id, bot := range nm.chatbots { -// if !bot.IsRunning() { -// nm.restart(id) -// } -// } -// time.Sleep(1 * time.Second) -// } -// } +// Check out chatbots are alive, recreating them if not. Run this in go-routine. +func (nm *NetworkManager) MonitorChatbots() { + for nm.IsRunning() { + for id, bot := range nm.chatbots { + if !bot.IsRunning() { + nm.restart(id) + } + } + time.Sleep(1 * time.Second) + } +} // get a chatbot by id func (nm *NetworkManager) getChatbotById(id int) common.ChatBot { From 7e94c1c55fca80a8f429a00ea8c169717053301d Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Wed, 2 Jul 2014 19:14:50 +0200 Subject: [PATCH 75/76] I have commited the integration test because I can't figure out how to drop the first tls connection that is establish by the ircBot.connect --- main_test.go | 121 ++++++++++++++++++++++++++------------------------- 1 file changed, 62 insertions(+), 59 deletions(-) diff --git a/main_test.go b/main_test.go index ce66612..93d389b 100644 --- a/main_test.go +++ b/main_test.go @@ -21,67 +21,70 @@ func GetQueueLength(queue *common.MockQueue) int { return len(q) } +// TODO (yml) this test is broken because ircBot establish first a tls conn +// we need to find a better way to handle this. + // A serious integration test for BotBot. // This covers BotBot, the IRC code, and the dispatcher. -func TestBotBotIRC(t *testing.T) { - - // Create a mock storage with configuration in it - storage := common.NewMockStorage(SERVER_PORT) - - // Create a mock queue to gather BotBot output - queue := common.NewMockQueue() - - // Start a Mock IRC server, and gather writes to it - glog.Infoln("[Debug] before common.NewMockIRCServer") - - server := common.NewMockIRCServer(TEST_MSG, SERVER_PORT) - glog.Infoln("[Debug] After common.NewMockIRCServer") - go server.Run(t) - time.Sleep(time.Second) - - // Run BotBot - botbot := NewBotBot(storage, queue) - go botbot.listen("testcmds") - go botbot.mainLoop() - waitForServer(server, 5) - - // Test sending a reply - should probably be separate test - queue.ReadChannel <- "WRITE 1 #unit I am a plugin response" - waitForServer(server, 6) - - queue.RLock() - q := queue.Got["q"] - queue.RUnlock() - - checkContains(q, TEST_MSG, t) - - // Check IRC server expectations - - if server.GotLength() != 6 { - t.Fatal("Expected exactly 6 IRC messages from the bot. Got ", server.GotLength()) - } - - expect := []string{"PING", "USER", "NICK", "NickServ", "JOIN", "PRIVMSG"} - for i := 0; i < 5; i++ { - if !strings.Contains(string(server.Got[i]), expect[i]) { - t.Error("Line ", i, " did not contain ", expect[i], ". It is: ", server.Got[i]) - } - } - - // test shutdown - should probably be separate test - - botbot.shutdown() - - tries := 0 - for GetQueueLength(queue) < 4 && tries < 200 { - time.Sleep(50 * time.Millisecond) - tries++ - } - - queue.RLock() - checkContains(queue.Got["q"], "SHUTDOWN", t) - queue.RUnlock() -} +// func TestBotBotIRC(t *testing.T) { +// +// // Create a mock storage with configuration in it +// storage := common.NewMockStorage(SERVER_PORT) +// +// // Create a mock queue to gather BotBot output +// queue := common.NewMockQueue() +// +// // Start a Mock IRC server, and gather writes to it +// glog.Infoln("[Debug] before common.NewMockIRCServer") +// +// server := common.NewMockIRCServer(TEST_MSG, SERVER_PORT) +// glog.Infoln("[Debug] After common.NewMockIRCServer") +// go server.Run(t) +// time.Sleep(time.Second) +// +// // Run BotBot +// botbot := NewBotBot(storage, queue) +// go botbot.listen("testcmds") +// go botbot.mainLoop() +// waitForServer(server, 5) +// +// // Test sending a reply - should probably be separate test +// queue.ReadChannel <- "WRITE 1 #unit I am a plugin response" +// waitForServer(server, 6) +// +// queue.RLock() +// q := queue.Got["q"] +// queue.RUnlock() +// +// checkContains(q, TEST_MSG, t) +// +// // Check IRC server expectations +// +// if server.GotLength() != 6 { +// t.Fatal("Expected exactly 6 IRC messages from the bot. Got ", server.GotLength()) +// } +// +// expect := []string{"PING", "USER", "NICK", "NickServ", "JOIN", "PRIVMSG"} +// for i := 0; i < 5; i++ { +// if !strings.Contains(string(server.Got[i]), expect[i]) { +// t.Error("Line ", i, " did not contain ", expect[i], ". It is: ", server.Got[i]) +// } +// } +// +// // test shutdown - should probably be separate test +// +// botbot.shutdown() +// +// tries := 0 +// for GetQueueLength(queue) < 4 && tries < 200 { +// time.Sleep(50 * time.Millisecond) +// tries++ +// } +// +// queue.RLock() +// checkContains(queue.Got["q"], "SHUTDOWN", t) +// queue.RUnlock() +// } // Block until len(target.Get) is at least val, or timeout func waitForServer(target *common.MockIRCServer, val int) { From c89f71add61c24649b845a6d34ddbb2f4b627d54 Mon Sep 17 00:00:00 2001 From: Yann Malet Date: Thu, 3 Jul 2014 10:22:18 +0200 Subject: [PATCH 76/76] Fix the main integration test by using tls.Listen --- certs/README.md | 12 ++++ certs/cert.pem | 18 +++++ certs/key.pem | 27 ++++++++ common/mock.go | 25 +++++-- main_test.go | 144 ++++++++++++++++++++++------------------ network/irc/irc.go | 15 ++++- network/irc/irc_test.go | 32 ++++----- 7 files changed, 181 insertions(+), 92 deletions(-) create mode 100644 certs/README.md create mode 100644 certs/cert.pem create mode 100644 certs/key.pem diff --git a/certs/README.md b/certs/README.md new file mode 100644 index 0000000..443a8e6 --- /dev/null +++ b/certs/README.md @@ -0,0 +1,12 @@ +The certs included in this repo has been with `generate_cert` from the GO +standard library. + +``` +generate_cert -ca=true -duration=8760h0m0s -host="127.0.0.1" -start-date="Jan 1 15:04:05 2014" +``` + +The generate_cert can be build like this + +``` +go build $GOROOT/src/pkg/crypto/tls/generate_cert.go +``` diff --git a/certs/cert.pem b/certs/cert.pem new file mode 100644 index 0000000..8971977 --- /dev/null +++ b/certs/cert.pem @@ -0,0 +1,18 @@ +-----BEGIN CERTIFICATE----- +MIIC8zCCAd2gAwIBAgIQLlTIDFFPizKZzJKC6j/k4jALBgkqhkiG9w0BAQswEjEQ +MA4GA1UEChMHQWNtZSBDbzAeFw0xNDAxMDExNTA0MDVaFw0xNTAxMDExNTA0MDVa +MBIxEDAOBgNVBAoTB0FjbWUgQ28wggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEK +AoIBAQDMVw4BGI1GsAdye8rqiSUS/gOI1oGpdbHO/B99xxXib9VvqFx3pT4WkQdd +OqAni7X4K4Td/3MBQ/K+Wy982wxR3pCHCWRxZ6iDQi/TPMRqP8hSufTyRd/QA+bj +UEXUh4Orq3VthIq0i4TjML9rC14pJy/ldb80clHLoVdx2uz3t52k0VZS1QMwLLpW +l3khpjO7ICUsdfFda+oMbroQPlgSEg69QcBLmwTuxJ7Y2PRVK6nWU/2+fGKQQXGT +PA9jU/zHt/7voUA9I1zXM1s7e1ExRbD4MFlaLwUo0qlbLL0dsIFURiJh3fBvgum/ +T7NQRvEJQQFx25S6/zyxn1VwKcVbAgMBAAGjSTBHMA4GA1UdDwEB/wQEAwIApDAT +BgNVHSUEDDAKBggrBgEFBQcDATAPBgNVHRMBAf8EBTADAQH/MA8GA1UdEQQIMAaH +BH8AAAEwCwYJKoZIhvcNAQELA4IBAQA8YZJmhOwIYEhUzObwQQzcJY3ZrUN7AiEc +sQnFaqOmzrtP0SDjWPlMITXeHV84Zw5+taIv1OQ3IyG9z+BPgIAkHQYVuVILrYOU +nVGs9bxdcrhKLwKVXEUoRsa+FY3NG8r7HTO+jYveXoXBjqA3NT7CmlJ3QtJJiCD/ +5S5u1KwfAZQ7xcrigBxTyRSpR/m0APGDGqrf5mKUcQVkGF9RIEDWOuCoqr1He9GZ +ba6HNYeEQrsdooazi9xbR2bk6F0Wa2Pt4YpS5Zy3KVuhxwbo43houwifhjF23MM/ +4DmoVl1copKHf/dMSsiDbGDeF2g/Z6Q2X790ijDOnxkOEbpjyuHP +-----END CERTIFICATE----- diff --git a/certs/key.pem b/certs/key.pem new file mode 100644 index 0000000..3ee2821 --- /dev/null +++ b/certs/key.pem @@ -0,0 +1,27 @@ +-----BEGIN RSA PRIVATE KEY----- +MIIEpAIBAAKCAQEAzFcOARiNRrAHcnvK6oklEv4DiNaBqXWxzvwffccV4m/Vb6hc +d6U+FpEHXTqgJ4u1+CuE3f9zAUPyvlsvfNsMUd6QhwlkcWeog0Iv0zzEaj/IUrn0 +8kXf0APm41BF1IeDq6t1bYSKtIuE4zC/awteKScv5XW/NHJRy6FXcdrs97edpNFW +UtUDMCy6Vpd5IaYzuyAlLHXxXWvqDG66ED5YEhIOvUHAS5sE7sSe2Nj0VSup1lP9 +vnxikEFxkzwPY1P8x7f+76FAPSNc1zNbO3tRMUWw+DBZWi8FKNKpWyy9HbCBVEYi +Yd3wb4Lpv0+zUEbxCUEBcduUuv88sZ9VcCnFWwIDAQABAoIBAQDGY07JaZjgJE9W +qzGa+4PvKIct93Tznb0ABHBeoUdyDLngKkl8MAZTyoKn1R9gxZfqVfYtwrFZbSrj +/YvhYJpZcghH0qqeH9HPfhcIs1rO/RX0m25hOc3OG7uyvmDNsrP3nAPqTGCOYVan +bNCrkOHeeplZ4jO9K7CWTxKjC7Y92V1EL1IW1H3NU7z+6gA/r5JRUhrSljR37sja +RIc3kBPqfo+qlwTSQ8m9A8dKVQro6Lj8xzSUxwZbDRV83GJDQS0UWDRZEbxO/6Oq +xNp6LEeFjjgI4CpKtPogGkOrcrOTRlZt4Y0bFaEYmKjsMepUIBmf7rbT/C9dfJKc +76YzTnnBAoGBANCBB43/jJuOyvwVM+n7mn0/dRBhnioe0ffONu0EXKx42JFUZ2hf +nnFbFQDjQU5EJDyWmz7gRSbcWXOBdrLwhLfqgOs4NBO9IYfw8tCjFfvLieo1cC1g +k++qfxQWSGlLOqLHmH89a2Zo+n6E2bVHZeEPLtx9BaKsDu/JjtFcn8bpAoGBAPrj +M9RvY0tpPcfmoBch3LYseGLPonbVJLOea2xOyQRgUuzSD8rfcoKL9HrmLGV1jP7b +dUamOle+1gOIjMN/NDTULnbU3of9Jpg7sM4QN58Ae2VVheJiP7vQ3mQMVGQFNjZn +PqkHsX8SrSufjJPXXZpyEB8eoncEOHrEXCSY98ejAoGAUKTXSzDALZp5IC8DOUi7 +ZB4bJQ7coeXxyCrWS64YOg0zlmJS7KevHKDh6sn7BE6OxXBq81LC7FjlsCsuwd8N +NiVZX6EJY2kPgwjKoa+yXQVIfnHUxXhJP7VuGVLVBwS11Sfl77DNzXplCHJR0i+f +VAEPWvBwMY7i6BPJTWjJ06ECgYB+PuoL0ekzP0f5WVHhkgaQHRyPDFCCX4rSX7tK +ivKYIyhXRvTvbzUd//MMDNr2SwqiDCidXnQpRzxGFuZOUaohk0u2PDOmVnqfTBoR +9xMmDYYKXdi7LBlKFzZxPcsRcZXwFk/vmpF0kh9VvjltA4h0eUUng7DZFuSc0kZT +nC3C5QKBgQCfg1NASP4WsANzaLABzfDKbQ23pxb9eqBWGVESEPhzUoqiTZ0rSDl4 +5oY7Dx9RGIJxPQWoG3nxjAK3GnlArUEJf4S/YMFmOX0naXp4HW4RxODPNoxnaQG0 +NfDb7xAuQNgY2F5T9dK02EPJ0tamsJbvHxVZLm1eiU2HPcK1ZurRfw== +-----END RSA PRIVATE KEY----- diff --git a/common/mock.go b/common/mock.go index 4da8732..93bfc5f 100644 --- a/common/mock.go +++ b/common/mock.go @@ -2,7 +2,9 @@ package common import ( "bufio" - "net" + "crypto/tls" + "flag" + "log" "sync" "testing" "time" @@ -10,6 +12,13 @@ import ( "github.com/golang/glog" ) +// SetGlogFlags walk around a glog issue and force it to log to stderr. +// It need to be called at the beginning of each test. +func SetGlogFlags() { + flag.Set("alsologtostderr", "true") + flag.Set("V", "3") +} + // MockSocket is a dummy implementation of ReadWriteCloser type MockSocket struct { sync.RWMutex @@ -72,8 +81,13 @@ func (srv *MockIRCServer) GotLength() int { } func (srv *MockIRCServer) Run(t *testing.T) { - - listener, err := net.Listen("tcp", ":"+srv.Port) + // Use the certs generated with generate_certs + cert, err := tls.LoadX509KeyPair("certs/cert.pem", "certs/key.pem") + if err != nil { + log.Fatalf("server: loadkeys: %s", err) + } + config := tls.Config{Certificates: []tls.Certificate{cert}} + listener, err := tls.Listen("tcp", "127.0.0.1:"+srv.Port, &config) if err != nil { t.Error("Error starting mock server on "+srv.Port, err) return @@ -95,16 +109,13 @@ func (srv *MockIRCServer) Run(t *testing.T) { // First message triggers BotBot to send USER and NICK messages conn.Write([]byte(":hybrid7.debian.local NOTICE AUTH :*** Looking up your hostname...\n")) - // Ask for NickServ auth, and pretend we got it conn.Write([]byte(":NickServ!NickServ@services. NOTICE graham_king :This nickname is registered. Please choose a different nickname, or identify via /msg NickServ identify \n")) conn.Write([]byte(":NickServ!NickServ@services. NOTICE graham_king :You are now identified for graham_king.\n")) - conn.Write([]byte(":wolfe.freenode.net 001 graham_king :Welcome to the freenode Internet Relay Chat Network graham_king\n")) - // This should get sent to plugins conn.Write([]byte(":yml!~yml@li148-151.members.linode.com PRIVMSG #unit :" + srv.Message + "\n")) - //conn.Write([]byte("test: " + srv.Message + "\n")) + conn.Write([]byte("test: " + srv.Message + "\n")) var derr error var data []byte diff --git a/main_test.go b/main_test.go index 93d389b..a5131a2 100644 --- a/main_test.go +++ b/main_test.go @@ -26,79 +26,97 @@ func GetQueueLength(queue *common.MockQueue) int { // A serious integration test for BotBot. // This covers BotBot, the IRC code, and the dispatcher. -// func TestBotBotIRC(t *testing.T) { -// -// // Create a mock storage with configuration in it -// storage := common.NewMockStorage(SERVER_PORT) -// -// // Create a mock queue to gather BotBot output -// queue := common.NewMockQueue() -// -// // Start a Mock IRC server, and gather writes to it -// glog.Infoln("[Debug] before common.NewMockIRCServer") -// -// server := common.NewMockIRCServer(TEST_MSG, SERVER_PORT) -// glog.Infoln("[Debug] After common.NewMockIRCServer") -// go server.Run(t) -// time.Sleep(time.Second) -// -// // Run BotBot -// botbot := NewBotBot(storage, queue) -// go botbot.listen("testcmds") -// go botbot.mainLoop() -// waitForServer(server, 5) -// -// // Test sending a reply - should probably be separate test -// queue.ReadChannel <- "WRITE 1 #unit I am a plugin response" -// waitForServer(server, 6) -// -// queue.RLock() -// q := queue.Got["q"] -// queue.RUnlock() -// -// checkContains(q, TEST_MSG, t) -// -// // Check IRC server expectations -// -// if server.GotLength() != 6 { -// t.Fatal("Expected exactly 6 IRC messages from the bot. Got ", server.GotLength()) -// } -// -// expect := []string{"PING", "USER", "NICK", "NickServ", "JOIN", "PRIVMSG"} -// for i := 0; i < 5; i++ { -// if !strings.Contains(string(server.Got[i]), expect[i]) { -// t.Error("Line ", i, " did not contain ", expect[i], ". It is: ", server.Got[i]) -// } -// } -// -// // test shutdown - should probably be separate test -// -// botbot.shutdown() -// -// tries := 0 -// for GetQueueLength(queue) < 4 && tries < 200 { -// time.Sleep(50 * time.Millisecond) -// tries++ -// } -// -// queue.RLock() -// checkContains(queue.Got["q"], "SHUTDOWN", t) -// queue.RUnlock() -// } +func TestBotBotIRC(t *testing.T) { + common.SetGlogFlags() + + // Create a mock storage with configuration in it + storage := common.NewMockStorage(SERVER_PORT) + + // Create a mock queue to gather BotBot output + queue := common.NewMockQueue() + + // Start a Mock IRC server, and gather writes to it + server := common.NewMockIRCServer(TEST_MSG, SERVER_PORT) + go server.Run(t) + + // Run BotBot + time.Sleep(time.Second) // Sleep of one second to avoid the 5s backoff + botbot := NewBotBot(storage, queue) + go botbot.listen("testcmds") + go botbot.mainLoop() + waitForServer(server, 4) + + // this sleep allow us to keep the answer in the right order + time.Sleep(time.Second) + // Test sending a reply - should probably be separate test + queue.ReadChannel <- "WRITE 1 #unit I am a plugin response" + waitForServer(server, 6) + + tries := 0 + queue.RLock() + q := queue.Got["q"] + queue.RUnlock() + + for len(q) < 4 && tries < 4 { + queue.RLock() + q = queue.Got["q"] + queue.RUnlock() + + glog.V(4).Infoln("[Debug] queue.Got[\"q\"]", len(q), "/", 4, q) + time.Sleep(time.Second) + tries++ + } + checkContains(q, TEST_MSG, t) + + // Check IRC server expectations + + if server.GotLength() != 6 { + t.Fatal("Expected exactly 6 IRC messages from the bot. Got ", server.GotLength()) + } + + glog.Infoln("[Debug] server.Got", server.Got) + expect := []string{"PING", "USER", "NICK", "NickServ", "JOIN", "PRIVMSG"} + for i := 0; i < 5; i++ { + if !strings.Contains(string(server.Got[i]), expect[i]) { + t.Error("Line ", i, " did not contain ", expect[i], ". It is: ", server.Got[i]) + } + } + + // test shutdown - should probably be separate test + + botbot.shutdown() + + tries = 0 + val := 5 + for len(q) < val && tries < val { + queue.RLock() + q = queue.Got["q"] + queue.RUnlock() + glog.V(4).Infoln("[Debug] queue.Got[\"q\"]", len(q), "/", val, q) + time.Sleep(time.Second) + tries++ + } + + queue.RLock() + checkContains(queue.Got["q"], "SHUTDOWN", t) + queue.RUnlock() +} // Block until len(target.Get) is at least val, or timeout func waitForServer(target *common.MockIRCServer, val int) { - glog.Infoln("[Debug] waitForServer:") tries := 0 - for target.GotLength() < val && tries < 200 { - glog.Infoln("[Debug] target.Got:", target.Got) - time.Sleep(50 * time.Millisecond) + for target.GotLength() < val && tries < val*3 { + time.Sleep(time.Millisecond * 500) + glog.V(4).Infoln("[Debug] val", target.GotLength(), "/", val, " target.Got:", target.Got) tries++ } + glog.Infoln("[Debug] waitForServer val", target.GotLength(), "/", val, " target.Got:", target.Got) + } // Check that "val" is in one of the strings in "arr". t.Error if not. func checkContains(arr []string, val string, t *testing.T) { + glog.Infoln("[Debug] checkContains", val, "in", arr) isFound := false for _, item := range arr { diff --git a/network/irc/irc.go b/network/irc/irc.go index eb5d2f4..617df2a 100644 --- a/network/irc/irc.go +++ b/network/irc/irc.go @@ -302,15 +302,26 @@ func (bot *ircBot) connect() (conn io.ReadWriteCloser) { glog.Infoln("Connected: TLS secure") return conn } else if _, ok := err.(x509.HostnameError); ok { - glog.Infoln("Could not connect using TLS because: ", err) + glog.Errorln("Could not connect using TLS because: ", err) // Certificate might not match. This happens on irc.cloudfront.net insecure := &tls.Config{InsecureSkipVerify: true} conn, err = tls.Dial("tcp", bot.address, insecure) if err == nil && isCertValid(conn.(*tls.Conn)) { - glog.Infoln("Connected: TLS with awkward certificate") + glog.Errorln("Connected: TLS with awkward certificate") return conn } + } else if _, ok := err.(x509.UnknownAuthorityError); ok { + glog.Errorln("x509.UnknownAuthorityError : ", err) + insecure := &tls.Config{InsecureSkipVerify: true} + conn, err = tls.Dial("tcp", bot.address, insecure) + if err == nil { + glog.Infoln("Connected: TLS with an x509.UnknownAuthorityError", err) + return conn + } + } else { + glog.Errorln("Could not establish a tls connection", err) + } conn, err = net.Dial("tcp", bot.address) diff --git a/network/irc/irc_test.go b/network/irc/irc_test.go index 2e3d77d..7e548dd 100644 --- a/network/irc/irc_test.go +++ b/network/irc/irc_test.go @@ -1,7 +1,6 @@ package irc import ( - "flag" "strconv" "strings" "testing" @@ -16,15 +15,8 @@ var ( NEW_CHANNEL = common.Channel{Name: "#unitnew", Fingerprint: "new-channel-uuid"} ) -// setGlogFlags walk around a glog issue and force it to log to stderr. -// It need to be called at the beginning of each test. -func setGlogFlags() { - flag.Set("alsologtostderr", "true") - flag.Set("V", "3") -} - func TestParseLine_welcome(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":barjavel.freenode.net 001 graham_king :Welcome to the freenode Internet Relay Chat Network graham_king" line, err := parseLine(line1) @@ -42,7 +34,7 @@ func TestParseLine_welcome(t *testing.T) { } func TestParseLine_privmsg(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":rnowak!~rnowak@q.ovron.com PRIVMSG #linode :totally" line, err := parseLine(line1) @@ -68,7 +60,7 @@ func TestParseLine_privmsg(t *testing.T) { } func TestParseLine_pm(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":graham_king!graham_kin@i.love.debian.org PRIVMSG botbotme :hello" line, err := parseLine(line1) @@ -89,7 +81,7 @@ func TestParseLine_pm(t *testing.T) { } func TestParseLine_list(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":oxygen.oftc.net 322 graham_king #linode 412 :Linode Community Support | http://www.linode.com/ | Linodes in Asia-Pacific! - http://bit.ly/ooBzhV" line, err := parseLine(line1) @@ -115,7 +107,7 @@ func TestParseLine_list(t *testing.T) { } func TestParseLine_quit(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":nicolaslara!~nicolasla@c83-250-0-151.bredband.comhem.se QUIT :" line, err := parseLine(line1) if err != nil { @@ -127,7 +119,7 @@ func TestParseLine_quit(t *testing.T) { } func TestParseLine_part(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":nicolaslara!~nicolasla@c83-250-0-151.bredband.comhem.se PART #lincolnloop-internal" line, err := parseLine(line1) if err != nil { @@ -142,7 +134,7 @@ func TestParseLine_part(t *testing.T) { } func TestParseLine_353(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() line1 := ":hybrid7.debian.local 353 botbot = #test :@botbot graham_king" line, err := parseLine(line1) if err != nil { @@ -161,7 +153,7 @@ func TestParseLine_353(t *testing.T) { // Test sending messages too fast func TestFlood(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() NUM := 5 @@ -209,7 +201,7 @@ func TestFlood(t *testing.T) { // Test joining additional channels func TestUpdate(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() glog.Infoln("[DEBUG] starting TestUpdate") fromServer := make(chan *line.Line) @@ -258,7 +250,7 @@ func TestUpdate(t *testing.T) { } func TestToUnicodeUTF8(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() msg := "ελληνικά" result := toUnicode([]byte(msg)) if result != msg { @@ -267,7 +259,7 @@ func TestToUnicodeUTF8(t *testing.T) { } func TestToUnicodeLatin1(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() msg := "âôé" latin1_bytes := []byte{0xe2, 0xf4, 0xe9} result := toUnicode(latin1_bytes) @@ -277,7 +269,7 @@ func TestToUnicodeLatin1(t *testing.T) { } func TestSplitChannels(t *testing.T) { - setGlogFlags() + common.SetGlogFlags() input := "#aone, #btwo, #cthree" result := splitChannels(input) if len(result) != 3 || result[2] != "#cthree" {