From 3c13b836570c05455040aad40d6a60f3032be10c Mon Sep 17 00:00:00 2001 From: Martin/Geno Date: Sun, 11 Feb 2018 22:03:58 +0100 Subject: [PATCH] add client logging + improve logging --- client/auth.go | 15 +++-- client/client.go | 139 ++++++++-------------------------------- client/comm.go | 41 ++++++++---- client/connect.go | 122 +++++++++++++++++++++++++++++++++++ daemon/tester.go | 12 +++- daemon/tester/bot.go | 45 ++++++++++--- daemon/tester/config.go | 18 +++--- daemon/tester/status.go | 20 ++++-- daemon/tester/tester.go | 24 ++++--- messages/connection.go | 2 +- messages/utils.go | 12 ++++ 11 files changed, 289 insertions(+), 161 deletions(-) create mode 100644 client/connect.go diff --git a/client/auth.go b/client/auth.go index 3c38474..136a7fa 100644 --- a/client/auth.go +++ b/client/auth.go @@ -22,6 +22,7 @@ func (client *Client) auth(password string) error { challenge := &messages.SASLChallenge{} response := &messages.SASLResponse{} for _, m := range f.Mechanisms.Mechanism { + client.Logging.Debugf("try auth with '%s'", m) if m == "SCRAM-SHA-1" { /* mechanism = m @@ -33,10 +34,10 @@ func (client *Client) auth(password string) error { if m == "DIGEST-MD5" { mechanism = m // Digest-MD5 authentication - client.Out.Encode(&messages.SASLAuth{ + client.Send(&messages.SASLAuth{ Mechanism: m, }) - if err := client.ReadElement(challenge); err != nil { + if err := client.ReadDecode(challenge); err != nil { return err } b, err := base64.StdEncoding.DecodeString(challenge.Body) @@ -65,7 +66,7 @@ func (client *Client) auth(password string) error { "\", nc=" + nonceCount + ", qop=" + qop + ", digest-uri=\"" + digestURI + "\", response=" + digest + ", charset=" + charset response.Body = base64.StdEncoding.EncodeToString([]byte(message)) - client.Out.Encode(response) + client.Send(response) break } if m == "PLAIN" { @@ -74,7 +75,7 @@ func (client *Client) auth(password string) error { raw := "\x00" + client.JID.Local + "\x00" + password enc := make([]byte, base64.StdEncoding.EncodedLen(len(raw))) base64.StdEncoding.Encode(enc, []byte(raw)) - client.Out.Encode(&messages.SASLAuth{ + client.Send(&messages.SASLAuth{ Mechanism: "PLAIN", Body: string(enc), }) @@ -85,15 +86,17 @@ func (client *Client) auth(password string) error { if mechanism == "" { return fmt.Errorf("PLAIN authentication is not an option: %s", f.Mechanisms.Mechanism) } + client.Logging.Info("used auth with '%s'", mechanism) + element, err := client.Read() if err != nil { return err } fail := messages.SASLFailure{} - if err := client.In.DecodeElement(&fail, element); err == nil { + if err := client.Decode(&fail, element); err == nil { return errors.New(messages.XMLChildrenString(fail) + " : " + fail.Body) } - if err := client.In.DecodeElement(&messages.SASLSuccess{}, element); err != nil { + if err := client.Decode(&messages.SASLSuccess{}, element); err != nil { return errors.New("auth failed - with unexpected answer") } return nil diff --git a/client/client.go b/client/client.go index b731595..109674e 100644 --- a/client/client.go +++ b/client/client.go @@ -3,32 +3,41 @@ package client import ( "crypto/tls" "encoding/xml" - "errors" "fmt" "net" "strings" "time" - "dev.sum7.eu/genofire/yaja/messages" + log "github.com/sirupsen/logrus" + "dev.sum7.eu/genofire/yaja/model" ) // Client holds XMPP connection opitons type Client struct { - conn net.Conn // connection to server - Out *xml.Encoder - In *xml.Decoder + Protocol string // tcp tcp4 tcp6 are supported + Timeout time.Duration + conn net.Conn // connection to server + out *xml.Encoder + in *xml.Decoder + + Logging *log.Logger JID *model.JID } func NewClient(jid *model.JID, password string) (*Client, error) { - return NewClientProtocolDuration(jid, password, "tcp", 0) -} + client := &Client{ + Protocol: "tcp", + JID: jid, + Logging: log.New(), + } + return client, client.Connect(password) -func NewClientProtocolDuration(jid *model.JID, password string, proto string, timeout time.Duration) (*Client, error) { - _, srvEntries, err := net.LookupSRV("xmpp-client", "tcp", jid.Domain) - addr := jid.Domain + ":5222" +} +func (client *Client) Connect(password string) error { + _, srvEntries, err := net.LookupSRV("xmpp-client", "tcp", client.JID.Domain) + addr := client.JID.Domain + ":5222" if err == nil && len(srvEntries) > 0 { bestSrv := srvEntries[0] for _, srv := range srvEntries { @@ -42,23 +51,20 @@ func NewClientProtocolDuration(jid *model.JID, password string, proto string, ti if len(a) == 1 { addr += ":5222" } - conn, err := net.DialTimeout(proto, addr, timeout) - if err != nil { - return nil, err + if client.Protocol == "" { + client.Protocol = "tcp" } - client := &Client{ - conn: conn, - In: xml.NewDecoder(conn), - Out: xml.NewEncoder(conn), - - JID: jid, + conn, err := net.DialTimeout(client.Protocol, addr, client.Timeout) + client.setConnection(conn) + if err != nil { + return err } if err = client.connect(password); err != nil { client.Close() - return nil, err + return err } - return client, nil + return nil } // Close closes the XMPP connection @@ -68,94 +74,3 @@ func (c *Client) Close() error { } return nil } - -func (client *Client) startStream() (*messages.StreamFeatures, error) { - // XMPP-Connection - _, err := fmt.Fprintf(client.conn, "\n"+ - "\n", - model.XMLEscape(client.JID.Domain), messages.NSClient, messages.NSStream) - if err != nil { - return nil, err - } - element, err := client.Read() - if err != nil { - return nil, err - } - if element.Name.Space != messages.NSStream || element.Name.Local != "stream" { - return nil, errors.New("is not stream") - } - f := &messages.StreamFeatures{} - if err := client.ReadElement(f); err != nil { - return nil, err - } - return f, nil -} - -func (client *Client) connect(password string) error { - if _, err := client.startStream(); err != nil { - return err - } - if err := client.Out.Encode(&messages.TLSStartTLS{}); err != nil { - return err - } - - var p messages.TLSProceed - if err := client.ReadElement(&p); err != nil { - return err - } - // Change tcp to tls - tlsconn := tls.Client(client.conn, &tls.Config{ - ServerName: client.JID.Domain, - }) - client.conn = tlsconn - client.In = xml.NewDecoder(client.conn) - client.Out = xml.NewEncoder(client.conn) - - if err := tlsconn.Handshake(); err != nil { - return err - } - if err := tlsconn.VerifyHostname(client.JID.Domain); err != nil { - return err - } - if err := client.auth(password); err != nil { - return err - } - - if _, err := client.startStream(); err != nil { - return err - } - // bind to resource - bind := &messages.Bind{} - if client.JID.Resource != "" { - bind.Resource = client.JID.Resource - } - if err := client.Out.Encode(&messages.IQClient{ - Type: messages.IQTypeSet, - From: client.JID, - To: model.NewJID(client.JID.Domain), - Bind: bind, - }); err != nil { - return err - } - - var iq messages.IQClient - if err := client.ReadElement(&iq); err != nil { - return err - } - if iq.Error != nil { - if iq.Error.ServiceUnavailable == nil { - return errors.New(fmt.Sprintf("recv error on iq>bind: %s[%s]: %s -> %s -> %s", iq.Error.Code, iq.Error.Type, iq.Error.Text, messages.XMLChildrenString(iq.Error.StanzaErrorGroup), messages.XMLChildrenString(iq.Error.Other))) - } - } else if iq.Bind == nil { - return errors.New(" result missing ") - } else if iq.Bind.JID != nil { - client.JID.Local = iq.Bind.JID.Local - client.JID.Domain = iq.Bind.JID.Domain - client.JID.Resource = iq.Bind.JID.Resource - } else { - return errors.New(messages.XMLChildrenString(iq.Other)) - } - // set status - return client.Send(&messages.PresenceClient{Show: messages.PresenceShowXA, Status: "online"}) -} diff --git a/client/comm.go b/client/comm.go index 63b6154..2f5ec24 100644 --- a/client/comm.go +++ b/client/comm.go @@ -2,26 +2,34 @@ package client import ( "encoding/xml" - "log" "dev.sum7.eu/genofire/yaja/messages" ) func (client *Client) Read() (*xml.StartElement, error) { for { - nextToken, err := client.In.Token() + nextToken, err := client.in.Token() if err != nil { return nil, err } switch nextToken.(type) { case xml.StartElement: element := nextToken.(xml.StartElement) + client.Logging.Debug("recv xml: ", messages.XMLStartElementToString(&element)) return &element, nil } } } - -func (client *Client) ReadElement(p interface{}) 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", messages.XMLStartElementToString(element), p) + } else { + client.Logging.Debugf("decode xml: %s to: %v with children %s", messages.XMLStartElementToString(element), p, messages.XMLChildrenString(p)) + } + return err +} +func (client *Client) ReadDecode(p interface{}) error { element, err := client.Read() if err != nil { return err @@ -31,36 +39,45 @@ func (client *Client) ReadElement(p interface{}) error { if !ok { iq = &messages.IQClient{} } - err = client.In.DecodeElement(iq, element) + err = client.Decode(iq, element) if err == nil && iq.Ping != nil { - log.Println("answer ping") + client.Logging.Info("ReadElement: auto answer ping") iq.Type = messages.IQTypeResult iq.To = iq.From iq.From = client.JID - client.Out.Encode(iq) + client.Send(iq) return nil } if ok { return err } - return client.In.DecodeElement(p, element) + return client.Decode(p, element) +} +func (client *Client) encode(p interface{}) error { + err := client.out.Encode(p) + if err != nil { + client.Logging.Debugf("encode failed %v", p) + } else { + client.Logging.Debugf("encode %v with children %s", p, messages.XMLChildrenString(p)) + } + return err } func (client *Client) Send(p interface{}) error { msg, ok := p.(*messages.MessageClient) if ok { msg.From = client.JID - return client.Out.Encode(msg) + return client.encode(msg) } iq, ok := p.(*messages.IQClient) if ok { iq.From = client.JID - return client.Out.Encode(iq) + return client.encode(iq) } pc, ok := p.(*messages.PresenceClient) if ok { pc.From = client.JID - return client.Out.Encode(pc) + return client.encode(pc) } - return client.Out.Encode(p) + return client.encode(p) } diff --git a/client/connect.go b/client/connect.go new file mode 100644 index 0000000..f6a7c33 --- /dev/null +++ b/client/connect.go @@ -0,0 +1,122 @@ +package client + +import ( + "crypto/tls" + "encoding/xml" + "errors" + "fmt" + "net" + + "dev.sum7.eu/genofire/yaja/messages" + "dev.sum7.eu/genofire/yaja/model" +) + +func (client *Client) setConnection(conn net.Conn) { + client.conn = conn + client.in = xml.NewDecoder(client.conn) + client.out = xml.NewEncoder(client.conn) +} + +func (client *Client) startStream() (*messages.StreamFeatures, error) { + // XMPP-Connection + _, err := fmt.Fprintf(client.conn, "\n"+ + "\n", + model.XMLEscape(client.JID.Domain), messages.NSClient, messages.NSStream) + if err != nil { + return nil, err + } + element, err := client.Read() + if err != nil { + return nil, err + } + if element.Name.Space != messages.NSStream || element.Name.Local != "stream" { + return nil, errors.New("is not stream") + } + f := &messages.StreamFeatures{} + if err := client.ReadDecode(f); err != nil { + return nil, err + } + debug := "stream start >" + if f.StartTLS != nil { + debug += " tls" + } + debug += " mechanism(" + for _, m := range f.Mechanisms.Mechanism { + debug += m + } + debug += ")" + if f.Bind != nil { + debug += " bind" + } + client.Logging.Info(debug) + return f, nil +} + +func (client *Client) connect(password string) error { + if _, err := client.startStream(); err != nil { + return err + } + if err := client.Send(&messages.TLSStartTLS{}); err != nil { + return err + } + + var p messages.TLSProceed + if err := client.ReadDecode(&p); err != nil { + return err + } + // Change tcp to tls + tlsconn := tls.Client(client.conn, &tls.Config{ + ServerName: client.JID.Domain, + }) + client.setConnection(tlsconn) + + if err := tlsconn.Handshake(); err != nil { + return err + } + if err := tlsconn.VerifyHostname(client.JID.Domain); err != nil { + return err + } + if err := client.auth(password); err != nil { + return err + } + + if _, err := client.startStream(); err != nil { + return err + } + // bind to resource + bind := &messages.Bind{} + if client.JID.Resource != "" { + bind.Resource = client.JID.Resource + } + if err := client.Send(&messages.IQClient{ + Type: messages.IQTypeSet, + To: model.NewJID(client.JID.Domain), + Bind: bind, + }); err != nil { + return err + } + + var iq messages.IQClient + if err := client.ReadDecode(&iq); err != nil { + return err + } + if iq.Error != nil { + if iq.Error.ServiceUnavailable == nil { + return errors.New(fmt.Sprintf("recv error on iq>bind: %s[%s]: %s -> %s -> %s", iq.Error.Code, iq.Error.Type, iq.Error.Text, messages.XMLChildrenString(iq.Error.StanzaErrorGroup), messages.XMLChildrenString(iq.Error.Other))) + } else { + client.Logging.Warn("connected without setting resource with bind after auth: service-unavailable") + } + } else if iq.Bind == nil { + return errors.New(" result missing ") + } else if iq.Bind.JID != nil { + client.JID.Local = iq.Bind.JID.Local + client.JID.Domain = iq.Bind.JID.Domain + client.JID.Resource = iq.Bind.JID.Resource + client.Logging.Info("set resource by server bind") + } else { + return errors.New(messages.XMLChildrenString(iq.Other)) + } + // set status + return client.Send(&messages.PresenceClient{Show: messages.PresenceShowXA, Status: "online"}) +} diff --git a/daemon/tester.go b/daemon/tester.go index cc54e24..20a143e 100644 --- a/daemon/tester.go +++ b/daemon/tester.go @@ -38,8 +38,18 @@ var TesterCMD = &cobra.Command{ if err := file.ReadJSON(configTester.AccountsPath, testerInstance); err != nil { log.Warn("unable to load state file:", err) } + testerInstance.Admins = configTester.Admins + testerInstance.LoggingBots = configTester.LoggingBots + clientLogger := log.New() + clientLogger.SetLevel(configTester.LoggingClients) + testerInstance.LoggingClients = clientLogger - mainClient, err := client.NewClientProtocolDuration(configTester.Client.JID, configTester.Client.Password, "tcp", configTester.Timeout.Duration) + mainClient := &client.Client{ + JID: configTester.Client.JID, + Timeout: configTester.Timeout.Duration, + Logging: clientLogger, + } + err := mainClient.Connect(configTester.Client.Password) if err != nil { log.Fatal("unable to connect with main jabber client: ", err) } diff --git a/daemon/tester/bot.go b/daemon/tester/bot.go index aa1aa53..5cbdb59 100644 --- a/daemon/tester/bot.go +++ b/daemon/tester/bot.go @@ -9,8 +9,13 @@ import ( ) 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(), + }) for { - logCTX := log.WithField("jid", status.client.JID.Full()) element, err := status.client.Read() if err != nil { @@ -21,7 +26,7 @@ func (t *Tester) StartBot(status *Status) { } errMSG := &messages.StreamError{} - err = status.client.In.DecodeElement(errMSG, element) + err = status.client.Decode(errMSG, element) if err == nil { logCTX.Errorf("recv stream error: %s: %s", errMSG.Text, messages.XMLChildrenString(errMSG.Any)) status.client.Close() @@ -30,14 +35,14 @@ func (t *Tester) StartBot(status *Status) { } iq := &messages.IQClient{} - err = status.client.In.DecodeElement(iq, element) + err = status.client.Decode(iq, element) if err == nil { if iq.Ping != nil { logCTX.Debug("answer ping") iq.Type = messages.IQTypeResult iq.To = iq.From iq.From = status.client.JID - status.client.Out.Encode(iq) + status.client.Send(iq) } else { logCTX.Warnf("recv iq unsupport: %s", messages.XMLChildrenString(iq)) } @@ -45,7 +50,7 @@ func (t *Tester) StartBot(status *Status) { } pres := &messages.PresenceClient{} - err = status.client.In.DecodeElement(pres, element) + err = status.client.Decode(pres, element) if err == nil { sender := pres.From logPres := logCTX.WithField("from", sender.Full()) @@ -54,12 +59,12 @@ func (t *Tester) StartBot(status *Status) { pres.Type = messages.PresenceTypeSubscribed pres.To = sender pres.From = nil - status.client.Out.Encode(pres) + status.client.Send(pres) logPres.Debugf("accept new subscribe") pres.Type = messages.PresenceTypeSubscribe pres.ID = "" - status.client.Out.Encode(pres) + status.client.Send(pres) logPres.Info("request also subscribe") } else if pres.Type == messages.PresenceTypeSubscribed { logPres.Info("recv presence accepted subscribe") @@ -76,7 +81,7 @@ func (t *Tester) StartBot(status *Status) { } msg := &messages.MessageClient{} - err = status.client.In.DecodeElement(msg, element) + err = status.client.Decode(msg, element) if err != nil { logCTX.Warnf("unsupport xml recv: %s <-> %v", err, element) continue @@ -100,6 +105,30 @@ func (t *Tester) StartBot(status *Status) { case "ping": status.client.Send(messages.MessageClient{Type: msg.Type, To: msg.From, Body: "pong"}) + case "disconnect": + first := true + allAdmins := "" + isAdmin := false + for _, jid := range t.Admins { + if first { + first = false + } else { + allAdmins += ", " + } + allAdmins += jid.Bare() + if jid.Bare() == msg.From.Bare() { + isAdmin = true + status.client.Send(messages.MessageClient{Type: msg.Type, To: jid, Body: "last message, disconnect requested by " + msg.From.Bare()}) + + } + } + if isAdmin { + status.Login = false + status.client.Close() + return + } + status.client.Send(messages.MessageClient{Type: msg.Type, To: msg.From, Body: "not allowed, ask " + allAdmins}) + case "checkmsg": if len(msgText) == 2 { t.UpdateConnectionStatus(msg.From, status.client.JID, msgText[1]) diff --git a/daemon/tester/config.go b/daemon/tester/config.go index 819612d..2540dbb 100644 --- a/daemon/tester/config.go +++ b/daemon/tester/config.go @@ -7,14 +7,16 @@ import ( ) type Config struct { - TLSDir string `toml:"tlsdir"` - AccountsPath string `toml:"accounts_path"` - OutputPath string `toml:"output_path"` - Logging log.Level `toml:"logging"` - Timeout duration.Duration `toml:"timeout"` - Interval duration.Duration `toml:"interval"` - Admins []*model.JID `toml:"admins"` - Client struct { + TLSDir string `toml:"tlsdir"` + AccountsPath string `toml:"accounts_path"` + OutputPath string `toml:"output_path"` + Logging log.Level `toml:"logging"` + LoggingClients log.Level `toml:"logging_clients"` + LoggingBots log.Level `toml:"logging_bots"` + Timeout duration.Duration `toml:"timeout"` + Interval duration.Duration `toml:"interval"` + Admins []*model.JID `toml:"admins"` + Client struct { JID *model.JID `toml:"jid"` Password string `toml:"password"` } `toml:"client"` diff --git a/daemon/tester/status.go b/daemon/tester/status.go index 66c36cd..da051a9 100644 --- a/daemon/tester/status.go +++ b/daemon/tester/status.go @@ -38,16 +38,26 @@ func (s *Status) Update(timeout time.Duration) { return } - bareJID := model.NewJID(s.account.JID.Bare()) - if client, err := client.NewClientProtocolDuration(bareJID, s.account.Password, "tcp4", timeout/2); err == nil { + c := &client.Client{ + JID: model.NewJID(s.account.JID.Bare()), + Protocol: "tcp4", + Logging: s.client.Logging, + Timeout: timeout / 2, + } + + if err := c.Connect(s.account.Password); err == nil { s.IPv4 = true - client.Close() + c.Close() } else { s.IPv4 = false } - if client, err := client.NewClientProtocolDuration(bareJID, s.account.Password, "tcp6", timeout/2); err == nil { + + c.JID = model.NewJID(s.account.JID.Bare()) + c.Protocol = "tcp6" + + if err := c.Connect(s.account.Password); err == nil { s.IPv6 = true - client.Close() + c.Close() } else { s.IPv6 = false } diff --git a/daemon/tester/tester.go b/daemon/tester/tester.go index cec0c4b..de56364 100644 --- a/daemon/tester/tester.go +++ b/daemon/tester/tester.go @@ -12,11 +12,14 @@ import ( ) type Tester struct { - mainClient *client.Client - Timeout time.Duration `json:"-"` - Accounts map[string]*Account `json:"accounts"` - Status map[string]*Status `json:"-"` - mux sync.Mutex + mainClient *client.Client + Timeout time.Duration `json:"-"` + Accounts map[string]*Account `json:"accounts"` + Status map[string]*Status `json:"-"` + mux sync.Mutex + LoggingClients *log.Logger `json:"-"` + LoggingBots log.Level `json:"-"` + Admins []*model.JID `json:"-"` } func NewTester() *Tester { @@ -68,7 +71,12 @@ func (t *Tester) Connect(acc *Account) { logCTX.Warn("is already loggedin") return } - c, err := client.NewClientProtocolDuration(acc.JID, acc.Password, "tcp", t.Timeout) + c := &client.Client{ + Timeout: t.Timeout, + JID: acc.JID, + Logging: t.LoggingClients, + } + err := c.Connect(acc.Password) if err != nil { logCTX.Warnf("could not connect client: %s", err) } else { @@ -143,7 +151,7 @@ func (t *Tester) CheckStatus() { logCTXTo = logCTXTo.WithField("msg-old", msg) own.Connections[jid] = false if ok, exists := own.Connections[jid]; !exists || ok { - logCTXTo.Warn("could not recv msg") + logCTXTo.Info("could not recv msg") } else { logCTXTo.Debug("could not recv msg") } @@ -157,7 +165,7 @@ func (t *Tester) CheckStatus() { To: s.JID, }) own.MessageForConnection[s.JID.Bare()] = msg - logCTXTo.Info("test send") + logCTXTo.Debug("test send") send++ } } diff --git a/messages/connection.go b/messages/connection.go index ba3b7d7..39924ad 100644 --- a/messages/connection.go +++ b/messages/connection.go @@ -11,7 +11,7 @@ type StreamFeatures struct { XMLName xml.Name `xml:"http://etherx.jabber.org/streams features"` StartTLS *TLSStartTLS Mechanisms SASLMechanisms - Bind Bind + Bind *Bind Session bool } diff --git a/messages/utils.go b/messages/utils.go index 7cf8d0b..30d7728 100644 --- a/messages/utils.go +++ b/messages/utils.go @@ -17,6 +17,18 @@ type XMLElement struct { InnerXML string `xml:",innerxml"` } +func XMLStartElementToString(element *xml.StartElement) string { + if element == nil { + return "" + } + debug := fmt.Sprintf("<%s xmlns=\"%s\"", element.Name.Local, element.Name.Space) + for _, attr := range element.Attr { + debug = fmt.Sprintf("%s %s=\"%s\"", debug, attr.Name, attr.Value) + } + debug += ">" + return debug +} + func XMLChildrenString(o interface{}) (result string) { first := true val := reflect.ValueOf(o)