diff --git a/channels/eventModel.go b/channels/eventModel.go index 05e31b5366c5a5adfba730381eedbe16a8fd1f04..cab0ef936d50696483c9b93ca164c4a5dbfc098f 100644 --- a/channels/eventModel.go +++ b/channels/eventModel.go @@ -9,6 +9,7 @@ package channels import ( "crypto/ed25519" + "encoding/base64" "errors" "fmt" "github.com/golang/protobuf/proto" @@ -297,6 +298,10 @@ func (e *events) receiveTextMessage(channelID *id.ID, if len(txt.ReplyMessageID) == cryptoChannel.MessageIDLen { var replyTo cryptoChannel.MessageID copy(replyTo[:], txt.ReplyMessageID) + tag := makeChaDebugTag(channelID, pubKey, content, SendReplyTag) + jww.INFO.Printf("[%s]UserListener - Received reply from %s "+ + "to %s", tag, base64.StdEncoding.EncodeToString(pubKey), + base64.StdEncoding.EncodeToString(txt.ReplyMessageID)) return e.model.ReceiveReply(channelID, messageID, replyTo, nickname, txt.Text, pubKey, codeset, timestamp, lease, round, Text, status) @@ -311,6 +316,11 @@ func (e *events) receiveTextMessage(channelID *id.ID, } } + tag := makeChaDebugTag(channelID, pubKey, content, SendMessageTag) + jww.INFO.Printf("[%s]UserListener - Received message from %s "+ + "to %s", tag, base64.StdEncoding.EncodeToString(pubKey), + base64.StdEncoding.EncodeToString(txt.ReplyMessageID)) + return e.model.ReceiveMessage(channelID, messageID, nickname, txt.Text, pubKey, codeset, timestamp, lease, round, Text, status) } @@ -349,6 +359,12 @@ func (e *events) receiveReaction(channelID *id.ID, if react.ReactionMessageID != nil && len(react.ReactionMessageID) == cryptoChannel.MessageIDLen { var reactTo cryptoChannel.MessageID copy(reactTo[:], react.ReactionMessageID) + + tag := makeChaDebugTag(channelID, pubKey, content, SendReactionTag) + jww.INFO.Printf("[%s]UserListener - Received reaction from %s "+ + "to %s", tag, base64.StdEncoding.EncodeToString(pubKey), + base64.StdEncoding.EncodeToString(react.ReactionMessageID)) + return e.model.ReceiveReaction(channelID, messageID, reactTo, nickname, react.Reaction, pubKey, codeset, timestamp, lease, round, Reaction, status) } else { diff --git a/channels/interface.go b/channels/interface.go index 5b24bca2e089895463c3ddf30dd5457448a7790b..b7d5445ced2690ef80a77ca0b30f087f814de43f 100644 --- a/channels/interface.go +++ b/channels/interface.go @@ -55,8 +55,7 @@ type Manager interface { // it will always be possible to send a payload of 802 bytes at minimum // Them meaning of validUntil depends on the use case. SendGeneric(channelID *id.ID, messageType MessageType, - msg []byte, validUntil time.Duration, msgDigest string, - params cmix.CMIXParams) ( + msg []byte, validUntil time.Duration, params cmix.CMIXParams) ( cryptoChannel.MessageID, rounds.Round, ephemeral.Id, error) // SendAdminGeneric is used to send a raw message over a channel encrypted @@ -66,7 +65,7 @@ type Manager interface { // return an error. The message must be at most 510 bytes long. SendAdminGeneric(privKey rsa.PrivateKey, channelID *id.ID, messageType MessageType, msg []byte, validUntil time.Duration, - msgDigest string, params cmix.CMIXParams) (cryptoChannel.MessageID, + params cmix.CMIXParams) (cryptoChannel.MessageID, rounds.Round, ephemeral.Id, error) // SendMessage is used to send a formatted message over a channel. diff --git a/channels/manager.go b/channels/manager.go index 5517ffa9bb147bb403a8b6a02e9afe3ed2e35fb7..02ee3d44bf8f71acbfe8996259bba18e6a5128fe 100644 --- a/channels/manager.go +++ b/channels/manager.go @@ -89,6 +89,8 @@ func NewManager(identity cryptoChannel.PrivateIdentity, kv *versioned.KV, // Prefix the kv with the username so multiple can be run storageTag := getStorageTag(identity.PubKey) + jww.INFO.Printf("NewManager(ID:%s-%s, tag:%s)", identity.Codename, + identity.PubKey, storageTag) kv = kv.Prefix(storageTag) if err := storeIdentity(kv, identity); err != nil { @@ -110,6 +112,8 @@ func NewManager(identity cryptoChannel.PrivateIdentity, kv *versioned.KV, func LoadManager(storageTag string, kv *versioned.KV, net Client, rng *fastRNG.StreamGenerator, modelBuilder EventModelBuilder) (Manager, error) { + jww.INFO.Printf("LoadManager(tag:%s)", storageTag) + // Prefix the kv with the username so multiple can be run kv = kv.Prefix(storageTag) @@ -155,6 +159,7 @@ func setupManager(identity cryptoChannel.PrivateIdentity, kv *versioned.KV, // JoinChannel joins the given channel. It will fail if the channel has already // been joined. func (m *manager) JoinChannel(channel *cryptoBroadcast.Channel) error { + jww.INFO.Printf("JoinChannel(%s[%s])", channel.Name, channel.ReceptionID) err := m.addChannel(channel) if err != nil { return err @@ -168,6 +173,7 @@ func (m *manager) JoinChannel(channel *cryptoBroadcast.Channel) error { // LeaveChannel leaves the given channel. It will return an error if the channel // was not previously joined. func (m *manager) LeaveChannel(channelID *id.ID) error { + jww.INFO.Printf("LeaveChannel(%s)", channelID) err := m.removeChannel(channelID) if err != nil { return err @@ -188,6 +194,7 @@ func (m *manager) GetChannels() []*id.ID { // GetChannel returns the underlying cryptographic structure for a given channel. func (m *manager) GetChannel(chID *id.ID) (*cryptoBroadcast.Channel, error) { + jww.INFO.Printf("GetChannel %s", chID) jc, err := m.getChannel(chID) if err != nil { return nil, err @@ -202,7 +209,7 @@ func (m *manager) GetChannel(chID *id.ID) (*cryptoBroadcast.Channel, error) { // underlying state tracking for message pickup for the channel, causing all // messages to be re-retrieved from the network func (m *manager) ReplayChannel(chID *id.ID) error { - jww.INFO.Printf("Replaying messages on channel %s", chID) + jww.INFO.Printf("ReplayChannel(%s)", chID) m.mux.RLock() defer m.mux.RUnlock() @@ -243,6 +250,7 @@ func (m *manager) GetIdentity() cryptoChannel.Identity { // ExportPrivateIdentity encrypts and exports the private identity to a portable // string. func (m *manager) ExportPrivateIdentity(password string) ([]byte, error) { + jww.INFO.Printf("ExportPrivateIdentity()") rng := m.rng.GetStream() defer rng.Close() return m.me.Export(password, rng) diff --git a/channels/send.go b/channels/send.go index a40dc5760a7987a23c1d3cb273e43ed451410d46..0e508d4cc6d6c952554d90849541ba6514f46463 100644 --- a/channels/send.go +++ b/channels/send.go @@ -29,6 +29,9 @@ import ( const ( cmixChannelTextVersion = 0 cmixChannelReactionVersion = 0 + SendMessageTag = "ChMessage" + SendReplyTag = "ChReply" + SendReactionTag = "ChReaction" ) // The size of the nonce used in the message ID. @@ -41,15 +44,14 @@ const messageNonceSize = 4 // possible to define the largest payload that can be sent, but // it will always be possible to send a payload of 802 bytes at minimum func (m *manager) SendGeneric(channelID *id.ID, messageType MessageType, - msg []byte, validUntil time.Duration, msgDigest string, - params cmix.CMIXParams) ( + msg []byte, validUntil time.Duration, params cmix.CMIXParams) ( cryptoChannel.MessageID, rounds.Round, ephemeral.Id, error) { // Note: We log sends on exit, and append what happened to the message // this cuts down on clutter in the log. - sendPrint := fmt.Sprintf("[ChanSend] Sending %s ch %s type %d at %s - "+ - "contentsHash %d", msgDigest, channelID, messageType, - netTime.Now(), hashMsg(msg)) + sendPrint := fmt.Sprintf("[%s] Sending ch %s type %d at %s", + params.DebugTag, channelID, messageType, + netTime.Now()) defer jww.INFO.Println(sendPrint) //find the channel @@ -144,8 +146,6 @@ func (m *manager) SendGeneric(channelID *id.ID, messageType MessageType, } sendPrint += fmt.Sprintf(", broadcasting message %s", netTime.Now()) - params.DebugTag = fmt.Sprintf("%s-ChanSend-%s", params.DebugTag, - msgDigest) r, ephid, err := ch.broadcast.BroadcastWithAssembler(assemble, params) if err != nil { sendPrint += fmt.Sprintf(", broadcast failed %s, %s", @@ -174,8 +174,15 @@ func (m *manager) SendGeneric(channelID *id.ID, messageType MessageType, // return an error. The message must be at most 510 bytes long. func (m *manager) SendAdminGeneric(privKey rsa.PrivateKey, channelID *id.ID, messageType MessageType, msg []byte, validUntil time.Duration, - msgDigest string, params cmix.CMIXParams) (cryptoChannel.MessageID, - rounds.Round, ephemeral.Id, error) { + params cmix.CMIXParams) (cryptoChannel.MessageID, rounds.Round, + ephemeral.Id, error) { + + // Note: We log sends on exit, and append what happened to the message + // this cuts down on clutter in the log. + sendPrint := fmt.Sprintf("[%s] Admin sending ch %s type %d at %s", + params.DebugTag, channelID, messageType, + netTime.Now()) + defer jww.INFO.Println(sendPrint) //find the channel ch, err := m.getChannel(channelID) @@ -232,27 +239,34 @@ func (m *manager) SendAdminGeneric(privKey rsa.PrivateKey, channelID *id.ID, return chMsgSerial, nil } + sendPrint += fmt.Sprintf(", pending send %s", netTime.Now()) uuid, err := m.st.denotePendingAdminSend(channelID, chMsg) if err != nil { + sendPrint += fmt.Sprintf(", pending send failed %s", + err.Error()) return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err } - params.DebugTag = fmt.Sprintf("%s-ChanSendAdmin-%s", params.DebugTag, - msgDigest) + sendPrint += fmt.Sprintf(", broadcasting message %s", netTime.Now()) r, ephid, err := ch.broadcast.BroadcastRSAToPublicWithAssembler(privKey, assemble, params) if err != nil { + sendPrint += fmt.Sprintf(", broadcast failed %s, %s", + netTime.Now(), err.Error()) errDenote := m.st.failedSend(uuid) if errDenote != nil { + sendPrint += fmt.Sprintf(", failed to denote failed "+ + "broadcast: %s", err.Error()) jww.ERROR.Printf("Failed to update for a failed send to "+ "%s: %+v", channelID, err) } return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err } - + sendPrint += fmt.Sprintf(", broadcast succeeded %s, success!", + netTime.Now()) err = m.st.send(uuid, msgId, r) if err != nil { - return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err + sendPrint += fmt.Sprintf(", broadcast failed: %s ", err.Error()) } return msgId, r, ephid, err } @@ -264,8 +278,8 @@ func (m *manager) SendAdminGeneric(privKey rsa.PrivateKey, channelID *id.ID, func (m *manager) SendMessage(channelID *id.ID, msg string, validUntil time.Duration, params cmix.CMIXParams) ( cryptoChannel.MessageID, rounds.Round, ephemeral.Id, error) { - msgDigest := MakeChanMsgDigest(channelID, Text, []byte(msg)) - jww.INFO.Printf("SendMessage(%s)", msgDigest) + tag := makeChaDebugTag(channelID, m.me.PubKey, []byte(msg), SendMessageTag) + jww.INFO.Printf("[%s]SendMessage(%s)", tag, channelID) txt := &CMIXChannelText{ Version: cmixChannelTextVersion, @@ -273,13 +287,15 @@ func (m *manager) SendMessage(channelID *id.ID, msg string, ReplyMessageID: nil, } + params = params.SetDebugTag(tag) + txtMarshaled, err := proto.Marshal(txt) if err != nil { return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err } return m.SendGeneric(channelID, Text, txtMarshaled, validUntil, - msgDigest, params) + params) } // SendReply is used to send a formatted message over a channel. @@ -292,21 +308,23 @@ func (m *manager) SendReply(channelID *id.ID, msg string, replyTo cryptoChannel.MessageID, validUntil time.Duration, params cmix.CMIXParams) (cryptoChannel.MessageID, rounds.Round, ephemeral.Id, error) { - msgDigest := MakeChanMsgDigest(channelID, Text, []byte(msg)) - jww.INFO.Printf("SendReply(%s to %s)", msgDigest, replyTo) + tag := makeChaDebugTag(channelID, m.me.PubKey, []byte(msg), SendReplyTag) + jww.INFO.Printf("[%s]SendReply(%s, to %s)", tag, channelID, replyTo) txt := &CMIXChannelText{ Version: cmixChannelTextVersion, Text: msg, ReplyMessageID: replyTo[:], } + params = params.SetDebugTag(tag) + txtMarshaled, err := proto.Marshal(txt) if err != nil { return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err } return m.SendGeneric(channelID, Text, txtMarshaled, validUntil, - msgDigest, params) + params) } // SendReaction is used to send a reaction to a message over a channel. @@ -316,8 +334,8 @@ func (m *manager) SendReply(channelID *id.ID, msg string, func (m *manager) SendReaction(channelID *id.ID, reaction string, reactTo cryptoChannel.MessageID, params cmix.CMIXParams) ( cryptoChannel.MessageID, rounds.Round, ephemeral.Id, error) { - msgDigest := MakeChanMsgDigest(channelID, Reaction, []byte(reaction)) - jww.INFO.Printf("SendReaction(%s, to %s)", msgDigest, reactTo) + tag := makeChaDebugTag(channelID, m.me.PubKey, []byte(reaction), SendReactionTag) + jww.INFO.Printf("[%s]SendReply(%s, to %s)", tag, channelID, reactTo) if err := ValidateReaction(reaction); err != nil { return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err @@ -329,28 +347,28 @@ func (m *manager) SendReaction(channelID *id.ID, reaction string, ReactionMessageID: reactTo[:], } + params = params.SetDebugTag(tag) + reactMarshaled, err := proto.Marshal(react) if err != nil { return cryptoChannel.MessageID{}, rounds.Round{}, ephemeral.Id{}, err } return m.SendGeneric(channelID, Reaction, reactMarshaled, ValidForever, - msgDigest, params) + params) } -func hashMsg(msg []byte) []byte { - h, _ := blake2b.New256(nil) - h.Write(msg) - return h.Sum(nil) -} - -// makeMsgdDigest is a debug helper that creates non-unique msg identifier +// makeChaDebugTag is a debug helper that creates non-unique msg identifier // This is set as the debug tag on messages and enables some level // of tracing a message (if it's contents/chan/type are unique) -func MakeChanMsgDigest(channelID *id.ID, messageType MessageType, - msg []byte) string { - data := fmt.Sprintf("ChanSend_%s-%s-%s", channelID, messageType, msg) +func makeChaDebugTag(channelID *id.ID, id ed25519.PublicKey, + msg []byte, baseTag string) string { + h, _ := blake2b.New256(nil) - h.Write([]byte(data)) - return base64.RawStdEncoding.EncodeToString(h.Sum(nil)) + h.Write(channelID[:]) + h.Write(msg) + h.Write(id) + + tripcode := base64.RawStdEncoding.EncodeToString(h.Sum(nil))[:12] + return fmt.Sprintf("%s-%s", baseTag, tripcode) } diff --git a/channels/send_test.go b/channels/send_test.go index 079dfd1bd5da184e13bfc9c325a367778966f255..7c3205115a1947cf3f5a20b81d79f794959d57dd 100644 --- a/channels/send_test.go +++ b/channels/send_test.go @@ -196,7 +196,6 @@ func TestSendGeneric(t *testing.T) { messageType, msg, validUntil, - "", *params) if err != nil { t.Logf("ERROR %v", err) @@ -287,7 +286,7 @@ func TestAdminGeneric(t *testing.T) { } messageId, roundId, ephemeralId, err := m.SendAdminGeneric(priv, - ch.ReceptionID, messageType, msg, validUntil, "", + ch.ReceptionID, messageType, msg, validUntil, cmix.GetDefaultCMIXParams()) if err != nil { t.Fatalf("Failed to SendAdminGeneric: %v", err) diff --git a/cmix/params.go b/cmix/params.go index ff6418328203b2b728b62c0a96bf4101e9b6d686..3ef813f0d9ca6e7903696f83cb6fea72e62a7962 100644 --- a/cmix/params.go +++ b/cmix/params.go @@ -10,6 +10,7 @@ package cmix import ( "encoding/base64" "encoding/json" + "fmt" "time" "gitlab.com/elixxir/client/cmix/message" @@ -300,6 +301,18 @@ func (p *CMIXParams) UnmarshalJSON(data []byte) error { return nil } +// SetDebugTag appends the debug tag if one already exists, +// otherwise it just used the new debug tag +func (p CMIXParams) SetDebugTag(newTag string) CMIXParams { + if p.DebugTag != DefaultDebugTag { + p.DebugTag = fmt.Sprintf("%s-%s", p.DebugTag, newTag) + } else { + p.DebugTag = newTag + } + + return p +} + // NodeMap represents a map of nodes and whether they have been // blacklisted. This is designed for use with CMIXParams.BlacklistedNodes type NodeMap map[id.ID]bool