diff --git a/client/auth.go b/client/auth.go index 0e5fc5a..97d74a5 100644 --- a/client/auth.go +++ b/client/auth.go @@ -13,6 +13,7 @@ import ( ) func (client *Client) auth(password string) error { + logCTX := client.Logging.WithField("type", "auth") f, err := client.startStream() if err != nil { return err @@ -22,7 +23,7 @@ func (client *Client) auth(password string) error { challenge := &xmpp.SASLChallenge{} response := &xmpp.SASLResponse{} for _, m := range f.Mechanisms.Mechanism { - client.Logging.Debugf("try auth with '%s'", m) + logCTX.Infof("try auth with '%s'", m) if m == "SCRAM-SHA-1" { /* mechanism = m @@ -86,7 +87,7 @@ func (client *Client) auth(password string) error { if mechanism == "" { return fmt.Errorf("PLAIN authentication is not an option: %s", f.Mechanisms.Mechanism) } - client.Logging.Infof("used auth with '%s'", mechanism) + logCTX.Infof("used auth with '%s'", mechanism) element, err := client.Read() if err != nil { diff --git a/client/client.go b/client/client.go index 576d1f4..510dbc4 100644 --- a/client/client.go +++ b/client/client.go @@ -22,23 +22,20 @@ type Client struct { out *xml.Encoder in *xml.Decoder - Logging *log.Logger + Logging *log.Entry JID *xmppbase.JID - reply map[string]chan *xmpp.IQClient - - skipError bool - iq chan *xmpp.IQClient - presence chan *xmpp.PresenceClient - mesage chan *xmpp.MessageClient + SkipError bool + msg chan interface{} + reply map[string]chan *xmpp.IQClient } func NewClient(jid *xmppbase.JID, password string) (*Client, error) { client := &Client{ Protocol: "tcp", JID: jid, - Logging: log.New(), + Logging: log.New().WithField("jid", jid.String()), } return client, client.Connect(password) diff --git a/client/comm.go b/client/comm.go index 9d880c8..e5cd6a5 100644 --- a/client/comm.go +++ b/client/comm.go @@ -15,7 +15,6 @@ func (client *Client) Read() (*xml.StartElement, error) { switch nextToken.(type) { case xml.StartElement: element := nextToken.(xml.StartElement) - client.Logging.Debug("recv xml: ", xmpp.XMLStartElementToString(&element)) return &element, nil } } @@ -23,11 +22,15 @@ func (client *Client) Read() (*xml.StartElement, error) { func (client *Client) Decode(p interface{}, element *xml.StartElement) error { err := client.in.DecodeElement(p, element) if err != nil { - client.Logging.Debugf("decode failed xml: %s to: %v", xmpp.XMLStartElementToString(element), p) + return err } else { - client.Logging.Debugf("decode xml: %s to: %v with children %s", xmpp.XMLStartElementToString(element), p, xmpp.XMLChildrenString(p)) + if b, err := xml.Marshal(p); err == nil { + client.Logging.Debugf("decode %v", string(b)) + } else { + client.Logging.Debugf("decode %v", p) + } } - return err + return nil } func (client *Client) ReadDecode(p interface{}) error { element, err := client.Read() @@ -41,7 +44,7 @@ func (client *Client) ReadDecode(p interface{}) error { } err = client.Decode(iq, element) if err == nil && iq.Ping != nil { - client.Logging.Info("ReadElement: auto answer ping") + client.Logging.Info("client.ReadElement: auto answer ping") iq.Type = xmpp.IQTypeResult iq.To = iq.From iq.From = client.JID @@ -56,11 +59,15 @@ func (client *Client) ReadDecode(p interface{}) error { func (client *Client) encode(p interface{}) error { err := client.out.Encode(p) if err != nil { - client.Logging.Debugf("encode failed %v", p) + return err } else { - client.Logging.Debugf("encode %v with children %s", p, xmpp.XMLChildrenString(p)) + if b, err := xml.Marshal(p); err == nil { + client.Logging.Debugf("encode %v", string(b)) + } else { + client.Logging.Debugf("encode %v", p) + } } - return err + return nil } func (client *Client) Send(p interface{}) error { diff --git a/client/connect.go b/client/connect.go index c708a9d..9fc933d 100644 --- a/client/connect.go +++ b/client/connect.go @@ -19,6 +19,7 @@ func (client *Client) setConnection(conn net.Conn) { } func (client *Client) startStream() (*xmpp.StreamFeatures, error) { + logCTX := client.Logging.WithField("type", "stream") // XMPP-Connection _, err := fmt.Fprintf(client.conn, "\n"+ "jid is nil" + xmpp.XMLChildrenString(bind)) } diff --git a/client/start.go b/client/start.go index 139ca71..fa7a9c3 100644 --- a/client/start.go +++ b/client/start.go @@ -1,6 +1,7 @@ package client import ( + "errors" "fmt" "dev.sum7.eu/genofire/yaja/xmpp" @@ -9,10 +10,24 @@ import ( var DefaultChannelSize = 30 func (client *Client) Start() error { - client.iq = make(chan *xmpp.IQClient, DefaultChannelSize) - client.presence = make(chan *xmpp.PresenceClient, DefaultChannelSize) - client.mesage = make(chan *xmpp.MessageClient, DefaultChannelSize) - client.reply = make(map[string]chan *xmpp.IQClient) + if client.msg == nil { + client.msg = make(chan interface{}, DefaultChannelSize) + } + if client.reply == nil { + client.reply = make(map[string]chan *xmpp.IQClient) + } + + defer func() { + for id, ch := range client.reply { + delete(client.reply, id) + close(ch) + } + client.reply = nil + close(client.msg) + client.Logging.Info("client.Start: close") + }() + + client.Logging.Info("client.Start: start") for { @@ -20,6 +35,7 @@ func (client *Client) Start() error { if err != nil { return err } + client.Logging.Debugf("client.Start: recv msg %v", xmpp.XMLStartElementToString(element)) errMSG := &xmpp.StreamError{} err = client.Decode(errMSG, element) @@ -31,21 +47,29 @@ func (client *Client) Start() error { err = client.Decode(iq, element) if err == nil { if iq.Ping != nil { - client.Logging.Debug("answer ping") + client.Logging.Info("client.Start: answer ping") iq.Type = xmpp.IQTypeResult iq.To = iq.From iq.From = client.JID client.Send(iq) } else { - if client.skipError && iq.Error != nil { - continue - } if ch, ok := client.reply[iq.ID]; ok { delete(client.reply, iq.ID) - ch <- iq + //TODO is this usefull? + go func() { ch <- iq }() continue } - client.iq <- iq + if client.SkipError && iq.Error != nil { + errStr, err := errorString(iq.Error) + if err != nil { + return err + } + if errStr != "" { + client.Logging.WithField("to", iq.To.String()).Error(errStr) + } + continue + } + client.msg <- iq } continue } @@ -53,45 +77,84 @@ func (client *Client) Start() error { pres := &xmpp.PresenceClient{} err = client.Decode(pres, element) if err == nil { - if client.skipError && pres.Error != nil { + if client.SkipError && pres.Error != nil { + errStr, err := errorString(pres.Error) + if err != nil { + return err + } + if errStr != "" { + client.Logging.WithField("to", pres.To.String()).Error(errStr) + } continue } - client.presence <- pres + client.msg <- pres continue } msg := &xmpp.MessageClient{} err = client.Decode(msg, element) if err == nil { - if client.skipError && msg.Error != nil { + if client.SkipError && msg.Error != nil { + errStr, err := errorString(msg.Error) + if err != nil { + return err + } + if errStr != "" { + client.Logging.WithField("to", msg.To.String()).Error(errStr) + } continue } - client.mesage <- msg + client.msg <- msg continue } client.Logging.Warnf("unsupport xml recv: %v", element) } } - -func (client *Client) SendRecv(iq *xmpp.IQClient) *xmpp.IQClient { - if iq.ID == "" { - iq.ID = xmpp.CreateCookieString() +func errorString(e *xmpp.ErrorClient) (string, error) { + str := fmt.Sprintf("[%s] %s", e.Type, xmpp.XMLChildrenString(e)) + if e.Text != nil { + str = fmt.Sprintf("[%s] %s -> %s", e.Type, e.Text.Body, xmpp.XMLChildrenString(e)) } - ch := make(chan *xmpp.IQClient, 1) - client.reply[iq.ID] = ch - client.Send(iq) - defer close(ch) - return <-ch + if e.Type == xmpp.ErrorTypeAuth { + return "", errors.New(str) + } + if e.RemoteServerNotFound != nil { + return "", nil + } + return str, nil } -func (client *Client) RecvIQ() *xmpp.IQClient { - return <-client.iq +func (client *Client) SendRecv(sendIQ *xmpp.IQClient) (*xmpp.IQClient, error) { + if sendIQ.ID == "" { + sendIQ.ID = xmpp.CreateCookieString() + } + ch := make(chan *xmpp.IQClient) + if client.reply == nil { + return nil, errors.New("client.SendRecv: not init (run client.Start)") + } + if client.reply == nil { + client.reply = make(map[string]chan *xmpp.IQClient) + } + client.reply[sendIQ.ID] = ch + client.Send(sendIQ) + iq := <-ch + close(ch) + if iq.Error != nil { + _, err := errorString(iq.Error) + if err != nil { + return nil, err + } + } + return iq, nil } -func (client *Client) RecvPresence() *xmpp.PresenceClient { - return <-client.presence -} - -func (client *Client) RecvMessage() *xmpp.MessageClient { - return <-client.mesage +func (client *Client) Recv() (msg interface{}, more bool) { + if client == nil { + return nil, false + } + if client.msg == nil { + client.msg = make(chan interface{}, DefaultChannelSize) + } + msg, more = <-client.msg + return } diff --git a/daemon/tester.go b/daemon/tester.go index 10b15fb..ea62b05 100644 --- a/daemon/tester.go +++ b/daemon/tester.go @@ -42,12 +42,12 @@ var TesterCMD = &cobra.Command{ testerInstance.LoggingBots = configTester.LoggingBots clientLogger := log.New() clientLogger.SetLevel(configTester.LoggingClients) - testerInstance.LoggingClients = clientLogger + testerInstance.LoggingClients = clientLogger.WithField("log", "client") mainClient := &client.Client{ JID: configTester.Client.JID, Timeout: configTester.Timeout.Duration, - Logging: clientLogger, + Logging: clientLogger.WithField("jid", configTester.Client.JID.String()), } err := mainClient.Connect(configTester.Client.Password) if err != nil { diff --git a/daemon/tester/bot.go b/daemon/tester/bot.go index 26231ee..b720672 100644 --- a/daemon/tester/bot.go +++ b/daemon/tester/bot.go @@ -10,49 +10,37 @@ import ( "dev.sum7.eu/genofire/yaja/xmpp/base" ) -func (t *Tester) StartBot(status *Status) { +func (t *Tester) startBot(status *Status) { logger := log.New() logger.SetLevel(t.LoggingBots) logCTX := logger.WithFields(log.Fields{ - "type": "bot", - "jid": status.client.JID.Full(), + "log": "bot", + "jid": status.client.JID.Full(), }) + go func(status *Status) { + if err := status.client.Start(); err != nil { + status.Disconnect(err.Error()) + } else { + status.Disconnect("safe closed") + } + }(status) + logCTX.Info("start bot") + defer logCTX.Info("quit bot") for { - - element, err := status.client.Read() - if err != nil { - status.Disconnect(fmt.Sprintf("could not read any more data from socket: %s", err)) + element, more := status.client.Recv() + if !more { + logCTX.Info("could not recv msg, closed") return } + logCTX.Debugf("recv msg %v", element) - errMSG := &xmpp.StreamError{} - err = status.client.Decode(errMSG, element) - if err == nil { - status.Disconnect(fmt.Sprintf("recv stream error: %s: %s -> %s", errMSG.Text, xmpp.XMLChildrenString(errMSG.StreamErrorGroup), xmpp.XMLChildrenString(errMSG.Other))) - return - } - - iq := &xmpp.IQClient{} - err = status.client.Decode(iq, element) - if err == nil { - if iq.Ping != nil { - logCTX.Debug("answer ping") - iq.Type = xmpp.IQTypeResult - iq.To = iq.From - iq.From = status.client.JID - status.client.Send(iq) - } else { - logCTX.Warnf("recv iq unsupport: %s", xmpp.XMLChildrenString(iq)) - } - continue - } - - pres := &xmpp.PresenceClient{} - err = status.client.Decode(pres, element) - if err == nil { + switch element.(type) { + case *xmpp.PresenceClient: + pres := element.(*xmpp.PresenceClient) sender := pres.From logPres := logCTX.WithField("from", sender.Full()) - if pres.Type == xmpp.PresenceTypeSubscribe { + switch pres.Type { + case xmpp.PresenceTypeSubscribe: logPres.Debugf("recv presence subscribe") pres.Type = xmpp.PresenceTypeSubscribed pres.To = sender @@ -64,81 +52,70 @@ func (t *Tester) StartBot(status *Status) { pres.ID = "" status.client.Send(pres) logPres.Info("request also subscribe") - } else if pres.Type == xmpp.PresenceTypeSubscribed { + case xmpp.PresenceTypeSubscribed: logPres.Info("recv presence accepted subscribe") - } else if pres.Type == xmpp.PresenceTypeUnsubscribe { + case xmpp.PresenceTypeUnsubscribe: logPres.Info("recv presence remove subscribe") - } else if pres.Type == xmpp.PresenceTypeUnsubscribed { + case xmpp.PresenceTypeUnsubscribed: logPres.Info("recv presence removed subscribe") - } else if pres.Type == xmpp.PresenceTypeUnavailable { + case xmpp.PresenceTypeUnavailable: logPres.Debug("recv presence unavailable") - } else { + default: logCTX.Warnf("recv presence unsupported: %s -> %s", pres.Type, xmpp.XMLChildrenString(pres)) } - continue - } + case *xmpp.MessageClient: + msg := element.(*xmpp.MessageClient) + logMSG := logCTX.WithField("from", msg.From.Full()).WithField("msg-recv", msg.Body) + msgText := strings.SplitN(msg.Body, " ", 2) + switch msgText[0] { - msg := &xmpp.MessageClient{} - err = status.client.Decode(msg, element) - if err != nil { - logCTX.Warnf("unsupport xml recv: %s <-> %v", err, element) - continue - } - logCTX = logCTX.WithField("from", msg.From.Full()).WithField("msg-recv", msg.Body) - if msg.Error != nil { - if msg.Error.Type == "auth" { - status.Disconnect("recv msg with error not auth") - return - } - logCTX.Debugf("recv msg with error %s[%s]: %s -> %s -> %s", msg.Error.Code, msg.Error.Type, msg.Error.Text, xmpp.XMLChildrenString(msg.Error.StanzaErrorGroup), xmpp.XMLChildrenString(msg.Error.Other)) - continue + case "ping": + status.client.Send(xmpp.MessageClient{Type: msg.Type, To: msg.From, Body: "pong"}) + logMSG.Info("answer ping") - } - - msgText := strings.SplitN(msg.Body, " ", 2) - switch msgText[0] { - - case "ping": - status.client.Send(xmpp.MessageClient{Type: msg.Type, To: msg.From, Body: "pong"}) - case "admin": - if len(msgText) == 2 { - botAdmin(strings.SplitN(msgText[1], " ", 2), logCTX, status, msg.From, botAllowed(t.Admins, status.account.Admins)) - } else { - status.client.Send(xmpp.MessageClient{Type: msg.Type, To: msg.From, Body: "list, add JID-BARE, del JID-BARE"}) - } - case "disconnect": - first := true - allAdmins := "" - isAdmin := false - fromBare := msg.From - for _, jid := range botAllowed(t.Admins, status.account.Admins) { - if first { - first = false + case "admin": + if len(msgText) == 2 { + botAdmin(strings.SplitN(msgText[1], " ", 2), logMSG, status, msg.From, botAllowed(t.Admins, status.account.Admins)) } else { - allAdmins += ", " + status.client.Send(xmpp.MessageClient{Type: msg.Type, To: msg.From, Body: "list, add JID-BARE, del JID-BARE"}) + logMSG.Info("answer admin help") } - allAdmins += jid.Bare().String() - if jid.Bare().IsEqual(fromBare) { - isAdmin = true - status.client.Send(xmpp.MessageClient{Type: msg.Type, To: jid, Body: "last message, disconnect requested by " + fromBare.String()}) - + case "disconnect": + first := true + allAdmins := "" + isAdmin := false + fromBare := msg.From + for _, jid := range botAllowed(t.Admins, status.account.Admins) { + if first { + first = false + } else { + allAdmins += ", " + } + allAdmins += jid.Bare().String() + if jid.Bare().IsEqual(fromBare) { + isAdmin = true + status.client.Send(xmpp.MessageClient{Type: msg.Type, To: jid, Body: "last message, disconnect requested by " + fromBare.String()}) + } } - } - if isAdmin { - status.Disconnect(fmt.Sprintf("disconnect by admin '%s'", fromBare.String())) - return - } - status.client.Send(xmpp.MessageClient{Type: msg.Type, To: msg.From, Body: "not allowed, ask " + allAdmins}) + if isAdmin { + status.Disconnect(fmt.Sprintf("disconnect by admin '%s'", fromBare.String())) + return + } + status.client.Send(xmpp.MessageClient{Type: msg.Type, To: msg.From, Body: "not allowed, ask " + allAdmins}) + logMSG.Info("answer disconnect not allowed") - case "checkmsg": - if len(msgText) == 2 { - t.UpdateConnectionStatus(msg.From, status.client.JID, msgText[1]) - } else { - logCTX.Debug("undetect") - } + case "checkmsg": + if len(msgText) == 2 { + t.updateConnectionStatus(msg.From, status.client.JID, msgText[1]) + } else { + logMSG.Debug("undetect") + } + default: + logMSG.Debug("undetect") + } default: - logCTX.Debug("undetect") + logCTX.Debug("unhandle") } } } @@ -187,4 +164,5 @@ func botAdmin(cmd []string, log *log.Entry, status *Status, from *xmppbase.JID, } } status.client.Send(xmpp.MessageClient{Type: xmpp.MessageTypeChat, To: from, Body: msg}) + log.Infof("admin[%s]: %s", from.String(), msg) } diff --git a/daemon/tester/status.go b/daemon/tester/status.go index 3a302b9..48fceda 100644 --- a/daemon/tester/status.go +++ b/daemon/tester/status.go @@ -8,6 +8,7 @@ import ( "dev.sum7.eu/genofire/yaja/client" "dev.sum7.eu/genofire/yaja/xmpp" "dev.sum7.eu/genofire/yaja/xmpp/base" + "dev.sum7.eu/genofire/yaja/xmpp/iq" ) type Status struct { @@ -22,6 +23,8 @@ type Status struct { TLSVersion string `json:"tls_version"` IPv4 bool `json:"ipv4"` IPv6 bool `json:"ipv6"` + Software string `json:"software,omitempty"` + OS string `json:"os,omitempty"` } func NewStatus(backupClient *client.Client, acc *Account) *Status { @@ -47,13 +50,13 @@ func (s *Status) Disconnect(reason string) { } } } - s.client.Logging.Warn(reason) + s.client.Logging.Warnf("status-disconnect: %s", reason) s.client.Close() s.Login = false s.TLSVersion = "" } -func (s *Status) Update(timeout time.Duration) { +func (s *Status) update(timeout time.Duration) { if s.client == nil || !s.Login { return } @@ -61,7 +64,7 @@ func (s *Status) Update(timeout time.Duration) { c := &client.Client{ JID: s.account.JID.Bare(), Protocol: "tcp4", - Logging: s.client.Logging, + Logging: s.client.Logging.WithField("status", "ipv4"), Timeout: timeout / 2, } @@ -72,6 +75,7 @@ func (s *Status) Update(timeout time.Duration) { s.IPv4 = false } + c.Logging = s.client.Logging.WithField("status", "ipv4") c.JID = s.account.JID.Bare() c.Protocol = "tcp6" @@ -101,4 +105,32 @@ func (s *Status) Update(timeout time.Duration) { } else { s.TLSVersion = "" } + iq, err := s.client.SendRecv(&xmpp.IQClient{ + To: &xmppbase.JID{Domain: s.JID.Domain}, + Type: xmpp.IQTypeGet, + Version: &xmppiq.Version{}, + }) + if err != nil { + s.client.Logging.Errorf("status-update: %s", err.Error()) + } else if iq != nil { + if iq.Error != nil && iq.Error.ServiceUnavailable != nil { + s.Software = "unknown" + s.OS = "unknown" + } else if iq.Version != nil { + s.Software = iq.Version.Name + if iq.Version.Version != "" { + s.Software += "-" + iq.Version.Version + } + if s.Software == "" { + s.Software = "unknown" + } + s.OS = iq.Version.OS + if s.OS == "" { + s.OS = "unknown" + } + } else { + s.Software = "" + s.OS = "" + } + } } diff --git a/daemon/tester/tester.go b/daemon/tester/tester.go index c40798a..26bae86 100644 --- a/daemon/tester/tester.go +++ b/daemon/tester/tester.go @@ -17,7 +17,7 @@ type Tester struct { Accounts map[string]*Account `json:"accounts"` Status map[string]*Status `json:"-"` mux sync.Mutex - LoggingClients *log.Logger `json:"-"` + LoggingClients *log.Entry `json:"-"` LoggingBots log.Level `json:"-"` Admins []*xmppbase.JID `json:"-"` } @@ -30,7 +30,7 @@ func NewTester() *Tester { } func (t *Tester) Start(mainClient *client.Client, password string) { - + mainClient.SkipError = true t.mainClient = mainClient status := NewStatus(mainClient, &Account{ @@ -39,13 +39,13 @@ func (t *Tester) Start(mainClient *client.Client, password string) { }) status.client = mainClient status.Login = true - status.Update(t.Timeout) t.mux.Lock() defer t.mux.Unlock() t.Status[mainClient.JID.Bare().String()] = status - go t.StartBot(status) + go t.startBot(status) + status.update(t.Timeout) for _, acc := range t.Accounts { t.Connect(acc) @@ -72,9 +72,10 @@ func (t *Tester) Connect(acc *Account) { return } c := &client.Client{ - Timeout: t.Timeout, - JID: acc.JID, - Logging: t.LoggingClients, + Timeout: t.Timeout, + JID: acc.JID, + Logging: t.LoggingClients.WithField("jid", acc.JID.String()), + SkipError: true, } err := c.Connect(acc.Password) if err != nil { @@ -85,12 +86,12 @@ func (t *Tester) Connect(acc *Account) { status.client = c status.account.JID = c.JID status.JID = c.JID - status.Update(t.Timeout) - go t.StartBot(status) + go t.startBot(status) + status.update(t.Timeout) } } -func (t *Tester) UpdateConnectionStatus(from, to *xmppbase.JID, recvmsg string) { +func (t *Tester) updateConnectionStatus(from, to *xmppbase.JID, recvmsg string) { logCTX := log.WithFields(log.Fields{ "jid": to.Full(), "from": from.Full(), diff --git a/xmpp/iq/version.go b/xmpp/iq/version.go index 1d75f08..f5c4146 100644 --- a/xmpp/iq/version.go +++ b/xmpp/iq/version.go @@ -7,7 +7,7 @@ import ( // Version implements XEP-0092: Software Version - 4 type Version struct { XMLName xml.Name `xml:"jabber:iq:version query"` - Name string `xml:"name"` //required - Version string `xml:"version"` //required + Name string `xml:"name,omitempty"` //required + Version string `xml:"version,omitempty"` //required OS string `xml:"os,omitempty"` }