sum7
/
yaja
Archived
1
0
Fork 0
Code Releases Activity

add client logging + improve logging

This commit is contained in:
Martin/Geno 2018-02-11 22:03:58 +01:00
parent 654d0306cf
commit 3c13b83657
No known key found for this signature in database
GPG Key ID: F0D39A37E925E941
11 changed files with 289 additions and 161 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

15
client/auth.go
View File

@ -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

135
client/client.go
View File

@ -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 {
Protocol string // tcp tcp4 tcp6 are supported
Timeout time.Duration
conn net.Conn // connection to server
Out *xml.Encoder
In *xml.Decoder
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, "<?xml version='1.0'?>\n"+
"<stream:stream to='%s' xmlns='%s'\n"+
" xmlns:stream='%s' version='1.0'>\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("<iq> result missing <bind>")
} 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"})
}

41
client/comm.go
View File

@ -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)
}

122
client/connect.go Normal file
View File

@ -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, "<?xml version='1.0'?>\n"+
"<stream:stream to='%s' xmlns='%s'\n"+
" xmlns:stream='%s' version='1.0'>\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("<iq> result missing <bind>")
} 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"})
}

12
daemon/tester.go
View File

@ -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)
}

45
daemon/tester/bot.go
View File

@ -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])

2
daemon/tester/config.go
View File

@ -11,6 +11,8 @@ type Config struct {
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"`

20
daemon/tester/status.go
View File

@ -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
}

14
daemon/tester/tester.go
View File

@ -17,6 +17,9 @@ type Tester struct {
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++
}
}

2
messages/connection.go
View File

@ -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
}

12
messages/utils.go
View File

@ -17,6 +17,18 @@ type XMLElement struct {
InnerXML string `xml:",innerxml"`
}
func XMLStartElementToString(element *xml.StartElement) string {
if element == nil {
return "<nil>"
}
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)