codex-storage
/
nim-libp2p
mirror of https://github.com/codex-storage/nim-libp2p.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Less verbose traces (#112) 

* Make traces less verbose with shortHexDump utility

* Rename shortHexDump into shortLog

* Improve shortLog, add shortLog for crypto keys

* Add proper shortLog implementations in messages
This commit is contained in:
Giovanni Petrantoni 2020-03-23 15:03:36 +09:00 committed by GitHub
parent b1a34f478e
commit 0a3e4a764b
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 189 additions and 54 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

35
libp2p/crypto/crypto.nim
View File

@ -11,6 +11,7 @@
import rsa, ecnist, ed25519/ed25519, secp
import ../protobuf/minprotobuf, ../vbuffer, ../multihash, ../multicodec
import nimcrypto/[rijndael, blowfish, twofish, sha, sha2, hash, hmac, utils]
import ../utility
# This is workaround for Nim's `import` bug
export rijndael, blowfish, twofish, sha, sha2, hash, hmac, utils
@ -423,6 +424,40 @@ proc `$`*(key: PublicKey): string =
result.add($(key.skkey))
result.add(")")
func shortLog*(key: PrivateKey): string =
## Get string representation of private key ``key``.
if key.scheme == RSA:
result = ($key.rsakey).shortLog
elif key.scheme == Ed25519:
result = "Ed25519 key ("
result.add(($key.edkey).shortLog)
result.add(")")
elif key.scheme == ECDSA:
result = "Secp256r1 key ("
result.add(($key.eckey).shortLog)
result.add(")")
elif key.scheme == Secp256k1:
result = "Secp256k1 key ("
result.add(($key.skkey).shortLog)
result.add(")")
proc shortLog*(key: PublicKey): string =
## Get string representation of public key ``key``.
if key.scheme == RSA:
result = ($key.rsakey).shortLog
elif key.scheme == Ed25519:
result = "Ed25519 key ("
result.add(($key.edkey).shortLog)
result.add(")")
elif key.scheme == ECDSA:
result = "Secp256r1 key ("
result.add(($key.eckey).shortLog)
result.add(")")
elif key.scheme == Secp256k1:
result = "Secp256k1 key ("
result.add(($key.skkey).shortLog)
result.add(")")
proc `$`*(sig: Signature): string =
## Get string representation of signature ``sig``.
result = toHex(sig.data)

7
libp2p/muxers/mplex/lpchannel.nim
View File

@ -13,7 +13,8 @@ import types,
nimcrypto/utils,
../../stream/bufferstream,
../../stream/lpstream,
../../connection
../../connection,
../../utility
logScope:
topic = "MplexChannel"
@ -53,7 +54,7 @@ proc newChannel*(id: uint,
let chan = result
proc writeHandler(data: seq[byte]): Future[void] {.async.} =
# writes should happen in sequence
trace "sending data ", data = data.toHex(),
trace "sending data ", data = data.shortLog,
id = chan.id,
initiator = chan.initiator
@ -100,7 +101,7 @@ proc pushTo*(s: LPChannel, data: seq[byte]): Future[void] =
retFuture.fail(newLPStreamEOFError())
return retFuture
trace "pushing data to channel", data = data.toHex(),
trace "pushing data to channel", data = data.shortLog,
id = s.id,
initiator = s.initiator

3
libp2p/muxers/mplex/mplex.nim
View File

@ -16,6 +16,7 @@ import chronos, chronicles
import ../muxer,
../../connection,
../../stream/lpstream,
../../utility,
coder,
types,
lpchannel
@ -69,7 +70,7 @@ method handle*(m: Mplex) {.async, gcsafe.} =
let (id, msgType, data) = await m.connection.readMsg()
trace "read message from connection", id = id,
msgType = msgType,
data = data
data = data.shortLog
let initiator = bool(ord(msgType) and 1)
var channel: LPChannel
if MessageType(msgType) != MessageType.New:

5
libp2p/protocols/identify.nim
View File

@ -15,7 +15,8 @@ import ../protobuf/minprotobuf,
../peer,
../crypto/crypto,
../multiaddress,
../protocols/protocol
../protocols/protocol,
../utility
logScope:
topic = "identify"
@ -69,7 +70,7 @@ proc decodeMsg*(buf: seq[byte]): IdentifyInfo =
result.pubKey = none(PublicKey)
var pubKey: PublicKey
if pb.getValue(1, pubKey) > 0:
trace "read public key from message", pubKey = $pubKey
trace "read public key from message", pubKey = ($pubKey).shortLog
result.pubKey = some(pubKey)
result.addrs = newSeq[MultiAddress]()

5
libp2p/protocols/pubsub/floodsub.nim
View File

@ -16,7 +16,8 @@ import pubsub,
../../crypto/crypto,
../../connection,
../../peerinfo,
../../peer
../../peer,
../../utility
logScope:
topic = "FloodSub"
@ -118,7 +119,7 @@ method publish*(f: FloodSub,
let msg = newMessage(f.peerInfo, data, topic)
var sent: seq[Future[void]]
for p in f.floodsub[topic]:
trace "publishing message", name = topic, peer = p, data = data
trace "publishing message", name = topic, peer = p, data = data.shortLog
sent.add(f.peers[p].send(@[RPCMsg(messages: @[msg])]))
await allFutures(sent)

4
libp2p/protocols/pubsub/pubsub.nim
View File

@ -70,9 +70,9 @@ method rpcHandler*(p: PubSub,
peer: PubSubPeer,
rpcMsgs: seq[RPCMsg]) {.async, base.} =
## handle rpc messages
trace "processing RPC message", peer = peer.id, msg = $rpcMsgs
trace "processing RPC message", peer = peer.id, msgs = rpcMsgs.len
for m in rpcMsgs: # for all RPC messages
trace "processing messages", msg = $rpcMsgs
trace "processing messages", msg = m.shortLog
if m.subscriptions.len > 0: # if there are any subscriptions
for s in m.subscriptions: # subscribe/unsubscribe the peer for each topic
p.subscribeTopic(s.topic, s.subscribe, peer.id)

9
libp2p/protocols/pubsub/pubsubpeer.nim
View File

@ -16,7 +16,8 @@ import rpc/[messages, message, protobuf],
../../connection,
../../stream/lpstream,
../../crypto/crypto,
../../protobuf/minprotobuf
../../protobuf/minprotobuf,
../../utility
logScope:
topic = "PubSubPeer"
@ -52,13 +53,13 @@ proc handle*(p: PubSubPeer, conn: Connection) {.async.} =
trace "waiting for data", peer = p.id, closed = conn.closed
let data = await conn.readLp()
let hexData = data.toHex()
trace "read data from peer", peer = p.id, data = hexData
trace "read data from peer", peer = p.id, data = data.shortLog
if $hexData.hash in p.recvdRpcCache:
trace "message already received, skipping", peer = p.id
continue
let msg = decodeRpcMsg(data)
trace "decoded msg from peer", peer = p.id, msg = $msg
trace "decoded msg from peer", peer = p.id, msg = msg.shortLog
await p.handler(p, @[msg])
p.recvdRpcCache.put($hexData.hash)
except CatchableError as exc:
@ -83,7 +84,7 @@ proc send*(p: PubSubPeer, msgs: seq[RPCMsg]) {.async.} =
continue
proc sendToRemote() {.async.} =
trace "sending encoded msgs to peer", peer = p.id, encoded = encodedHex
trace "sending encoded msgs to peer", peer = p.id, encoded = encoded.buffer.shortLog
await p.sendConn.writeLp(encoded.buffer)
p.sentRpcCache.put($encodedHex.hash)

56
libp2p/protocols/pubsub/rpc/messages.nim
View File

@ -7,7 +7,8 @@
## This file may not be copied, modified, or distributed except according to
## those terms.
import options
import options, sequtils
import ../../../utility
type
SubOpts* = object
@ -45,3 +46,56 @@ type
subscriptions*: seq[SubOpts]
messages*: seq[Message]
control*: Option[ControlMessage]
func shortLog*(s: ControlIHave): auto =
(
topicID: s.topicID.shortLog,
messageIDs: mapIt(s.messageIDs, it.shortLog)
)
func shortLog*(s: ControlIWant): auto =
(
messageIDs: mapIt(s.messageIDs, it.shortLog)
)
func shortLog*(s: ControlGraft): auto =
(
topicID: s.topicID.shortLog
)
func shortLog*(s: ControlPrune): auto =
(
topicID: s.topicID.shortLog
)
func shortLog*(c: ControlMessage): auto =
(
ihave: mapIt(c.ihave, it.shortLog),
iwant: mapIt(c.iwant, it.shortLog),
graft: mapIt(c.graft, it.shortLog),
prune: mapIt(c.prune, it.shortLog)
)
func shortLog*(msg: Message): auto =
(
fromPeer: msg.fromPeer.shortLog,
data: msg.data.shortLog,
seqno: msg.seqno.shortLog,
topicIDs: $msg.topicIDs,
signature: msg.signature.shortLog,
key: msg.key.shortLog
)
func shortLog*(m: RPCMsg): auto =
if m.control.isSome:
(
subscriptions: m.subscriptions,
messages: mapIt(m.messages, it.shortLog),
control: m.control.get().shortLog
)
else:
(
subscriptions: m.subscriptions,
messages: mapIt(m.messages, it.shortLog),
control: ControlMessage().shortLog
)

17
libp2p/protocols/pubsub/rpc/protobuf.nim
View File

@ -12,13 +12,14 @@ import chronicles
import messages,
../../../protobuf/minprotobuf,
../../../crypto/crypto,
../../../peer
../../../peer,
../../../utility
proc encodeGraft*(graft: ControlGraft, pb: var ProtoBuffer) {.gcsafe.} =
pb.write(initProtoField(1, graft.topicID))
proc decodeGraft*(pb: var ProtoBuffer): seq[ControlGraft] {.gcsafe.} =
trace "decoding graft msg", buffer = pb.buffer.toHex()
trace "decoding graft msg", buffer = pb.buffer.shortLog
while true:
var topic: string
if pb.getString(1, topic) < 0:
@ -185,15 +186,15 @@ proc decodeMessages*(pb: var ProtoBuffer): seq[Message] {.gcsafe.} =
var msg: Message
if pb.getBytes(1, msg.fromPeer) < 0:
break
trace "read message field", fromPeer = msg.fromPeer
trace "read message field", fromPeer = msg.fromPeer.shortLog
if pb.getBytes(2, msg.data) < 0:
break
trace "read message field", data = msg.data
trace "read message field", data = msg.data.shortLog
if pb.getBytes(3, msg.seqno) < 0:
break
trace "read message field", seqno = msg.seqno
trace "read message field", seqno = msg.seqno.shortLog
var topic: string
while true:
@ -204,16 +205,16 @@ proc decodeMessages*(pb: var ProtoBuffer): seq[Message] {.gcsafe.} =
topic = ""
discard pb.getBytes(5, msg.signature)
trace "read message field", signature = msg.signature
trace "read message field", signature = msg.signature.shortLog
discard pb.getBytes(6, msg.key)
trace "read message field", key = msg.key
trace "read message field", key = msg.key.shortLog
result.add(msg)
proc encodeRpcMsg*(msg: RPCMsg): ProtoBuffer {.gcsafe.} =
result = initProtoBuffer()
trace "encoding msg: ", msg = $msg
trace "encoding msg: ", msg = msg.shortLog
if msg.subscriptions.len > 0:
var subs = initProtoBuffer()

9
libp2p/protocols/secure/noise.nim
View File

@ -16,6 +16,7 @@ import ../../connection
import ../../peer
import ../../peerinfo
import ../../protobuf/minprotobuf
import ../../utility
import secure,
../../crypto/[crypto, chacha20poly1305, curve25519, hkdf],
../../stream/bufferstream
@ -118,7 +119,7 @@ proc encryptWithAd(state: var CipherState, ad, data: openarray[byte]): seq[byte]
if state.n > NonceMax:
raise newException(NoiseNonceMaxError, "Noise max nonce value reached")
result &= tag
trace "encryptWithAd", tag = byteutils.toHex(tag), data = byteutils.toHex(result), nonce = state.n - 1
trace "encryptWithAd", tag = byteutils.toHex(tag), data = result.shortLog, nonce = state.n - 1
proc decryptWithAd(state: var CipherState, ad, data: openarray[byte]): seq[byte] =
var
@ -129,7 +130,7 @@ proc decryptWithAd(state: var CipherState, ad, data: openarray[byte]): seq[byte]
np[] = state.n
result = data[0..(data.high - ChaChaPolyTag.len)]
ChaChaPoly.decrypt(state.k, nonce, tagOut, result, ad)
trace "decryptWithAd", tagIn = byteutils.toHex(tagIn), tagOut=byteutils.toHex(tagOut), nonce = state.n
trace "decryptWithAd", tagIn = tagIn.shortLog, tagOut = tagOut.shortLog, nonce = state.n
if tagIn != tagOut:
error "decryptWithAd failed", data = byteutils.toHex(data)
raise newException(NoiseDecryptTagError, "decryptWithAd failed tag authentication.")
@ -150,7 +151,7 @@ proc mixKey(ss: var SymmetricState, ikm: ChaChaPolyKey) =
sha256.hkdf(ss.ck, ikm, [], temp_keys)
ss.ck = temp_keys[0]
ss.cs = CipherState(k: temp_keys[1])
trace "mixKey", key = ss.cs.k
trace "mixKey", key = ss.cs.k.shortLog
proc mixHash(ss: var SymmetricState; data: openarray[byte]) =
var ctx: sha256
@ -158,7 +159,7 @@ proc mixHash(ss: var SymmetricState; data: openarray[byte]) =
ctx.update(ss.h.data)
ctx.update(data)
ss.h = ctx.finish()
trace "mixHash", hash = ss.h.data
trace "mixHash", hash = ss.h.data.shortLog
# We might use this for other handshake patterns/tokens
proc mixKeyAndHash(ss: var SymmetricState; ikm: openarray[byte]) {.used.} =

51
libp2p/protocols/secure/secio.nim
View File

@ -15,7 +15,8 @@ import secure,
../../crypto/crypto,
../../crypto/ecnist,
../../protobuf/minprotobuf,
../../peer
../../peer,
../../utility
export hmac, sha2, sha, hash, rijndael, bcmode
logScope:
@ -181,16 +182,16 @@ method readMessage(sconn: SecioConn): Future[seq[byte]] {.async.} =
await sconn.readExactly(addr buf[0], 4)
let length = (int(buf[0]) shl 24) or (int(buf[1]) shl 16) or
(int(buf[2]) shl 8) or (int(buf[3]))
trace "Recieved message header", header = toHex(buf), length = length
trace "Recieved message header", header = buf.shortLog, length = length
if length <= SecioMaxMessageSize:
buf.setLen(length)
await sconn.readExactly(addr buf[0], length)
trace "Received message body", length = length,
buffer = toHex(buf)
buffer = buf.shortLog
if sconn.macCheckAndDecode(buf):
result = buf
else:
trace "Message MAC verification failed", buf = toHex(buf)
trace "Message MAC verification failed", buf = buf.shortLog
else:
trace "Received message header size is more then allowed",
length = length, allowed_length = SecioMaxMessageSize
@ -213,7 +214,7 @@ method writeMessage(sconn: SecioConn, message: seq[byte]) {.async.} =
msg[1] = byte((length shr 16) and 0xFF)
msg[2] = byte((length shr 8) and 0xFF)
msg[3] = byte(length and 0xFF)
trace "Writing message", message = toHex(msg)
trace "Writing message", message = msg.shortLog
try:
await sconn.write(msg)
except AsyncStreamWriteError:
@ -236,12 +237,12 @@ proc newSecioConn(conn: Connection,
let i0 = if order < 0: 1 else: 0
let i1 = if order < 0: 0 else: 1
trace "Writer credentials", mackey = toHex(secrets.macOpenArray(i0)),
enckey = toHex(secrets.keyOpenArray(i0)),
iv = toHex(secrets.ivOpenArray(i0))
trace "Reader credentials", mackey = toHex(secrets.macOpenArray(i1)),
enckey = toHex(secrets.keyOpenArray(i1)),
iv = toHex(secrets.ivOpenArray(i1))
trace "Writer credentials", mackey = secrets.macOpenArray(i0).shortLog,
enckey = secrets.keyOpenArray(i0).shortLog,
iv = secrets.ivOpenArray(i0).shortLog
trace "Reader credentials", mackey = secrets.macOpenArray(i1).shortLog,
enckey = secrets.keyOpenArray(i1).shortLog,
iv = secrets.ivOpenArray(i1).shortLog
result.writerMac.init(hash, secrets.macOpenArray(i0))
result.readerMac.init(hash, secrets.macOpenArray(i1))
result.writerCoder.init(cipher, secrets.keyOpenArray(i0),
@ -255,18 +256,18 @@ proc transactMessage(conn: Connection,
msg: seq[byte]): Future[seq[byte]] {.async.} =
var buf = newSeq[byte](4)
try:
trace "Sending message", message = toHex(msg), length = len(msg)
trace "Sending message", message = msg.shortLog, length = len(msg)
await conn.write(msg)
await conn.readExactly(addr buf[0], 4)
let length = (int(buf[0]) shl 24) or (int(buf[1]) shl 16) or
(int(buf[2]) shl 8) or (int(buf[3]))
trace "Recieved message header", header = toHex(buf), length = length
trace "Recieved message header", header = buf.shortLog, length = length
if length <= SecioMaxMessageSize:
buf.setLen(length)
await conn.readExactly(addr buf[0], length)
trace "Received message body", conn = $conn,
length = length,
buff = buf
buff = buf.shortLog
result = buf
else:
trace "Received size of message exceed limits", conn = $conn,
@ -309,7 +310,7 @@ method handshake*(s: Secio, conn: Connection, initiator: bool = false): Future[S
trace "Local proposal", schemes = SecioExchanges,
ciphers = SecioCiphers,
hashes = SecioHashes,
pubkey = toHex(localBytesPubkey),
pubkey = localBytesPubkey.shortLog,
peer = localPeerId
var answer = await transactMessage(conn, request)
@ -324,7 +325,7 @@ method handshake*(s: Secio, conn: Connection, initiator: bool = false): Future[S
raise newException(SecioError, "Remote proposal decoding failed")
if not remotePubkey.init(remoteBytesPubkey):
trace "Remote public key incorrect or corrupted", pubkey = remoteBytesPubkey
trace "Remote public key incorrect or corrupted", pubkey = remoteBytesPubkey.shortLog
raise newException(SecioError, "Remote public key incorrect or corrupted")
remotePeerId = PeerID.init(remotePubkey)
@ -334,7 +335,7 @@ method handshake*(s: Secio, conn: Connection, initiator: bool = false): Future[S
remoteNonce)
trace "Remote proposal", schemes = remoteExchanges, ciphers = remoteCiphers,
hashes = remoteHashes,
pubkey = toHex(remoteBytesPubkey), order = order,
pubkey = remoteBytesPubkey.shortLog, order = order,
peer = remotePeerId
let scheme = selectBest(order, SecioExchanges, remoteExchanges)
@ -364,7 +365,7 @@ method handshake*(s: Secio, conn: Connection, initiator: bool = false): Future[S
raise newException(SecioError, "Remote exchange decoding failed")
if not remoteESignature.init(remoteEBytesSig):
trace "Remote signature incorrect or corrupted", signature = toHex(remoteEBytesSig)
trace "Remote signature incorrect or corrupted", signature = remoteEBytesSig.shortLog
raise newException(SecioError, "Remote signature incorrect or corrupted")
var remoteCorpus = answer & request[4..^1] & remoteEBytesPubkey
@ -389,15 +390,15 @@ method handshake*(s: Secio, conn: Connection, initiator: bool = false): Future[S
seckeyScheme = ekeypair.seckey.scheme
raise newException(SecioError, "Shared secret could not be created")
trace "Shared secret calculated", secret = toHex(secret)
trace "Shared secret calculated", secret = secret.shortLog
var keys = stretchKeys(cipher, hash, secret)
trace "Authenticated encryption parameters",
iv0 = toHex(keys.ivOpenArray(0)), key0 = toHex(keys.keyOpenArray(0)),
mac0 = toHex(keys.macOpenArray(0)),
iv1 = toHex(keys.ivOpenArray(1)), key1 = toHex(keys.keyOpenArray(1)),
mac1 = toHex(keys.macOpenArray(1))
iv0 = toHex(keys.ivOpenArray(0)), key0 = keys.keyOpenArray(0).shortLog,
mac0 = keys.macOpenArray(0).shortLog,
iv1 = keys.ivOpenArray(1).shortLog, key1 = keys.keyOpenArray(1).shortLog,
mac1 = keys.macOpenArray(1).shortLog
# Perform Nonce exchange over encrypted channel.
@ -407,8 +408,8 @@ method handshake*(s: Secio, conn: Connection, initiator: bool = false): Future[S
var res = await secioConn.readMessage()
if res != @localNonce:
trace "Nonce verification failed", receivedNonce = toHex(res),
localNonce = toHex(localNonce)
trace "Nonce verification failed", receivedNonce = res.shortLog,
localNonce = localNonce.shortLog
raise newException(CatchableError, "Nonce verification failed")
else:
trace "Secure handshake succeeded"

5
libp2p/protocols/secure/secure.nim
View File

@ -14,7 +14,8 @@ import ../protocol,
../../stream/bufferstream,
../../crypto/crypto,
../../connection,
../../peerinfo
../../peerinfo,
../../utility
type
Secure* = ref object of LPProtocol # base type for secure managers
@ -50,7 +51,7 @@ proc readLoop(sconn: SecureConn, stream: BufferStream) {.async.} =
proc handleConn*(s: Secure, conn: Connection, initiator: bool = false): Future[Connection] {.async, gcsafe.} =
var sconn = await s.handshake(conn, initiator)
proc writeHandler(data: seq[byte]) {.async, gcsafe.} =
trace "sending encrypted bytes", bytes = data.toHex()
trace "sending encrypted bytes", bytes = data.shortLog
await sconn.writeMessage(data)
var stream = newBufferStream(writeHandler)

37
libp2p/utility.nim Normal file
View File

@ -0,0 +1,37 @@
## Nim-LibP2P
## Copyright (c) 2020 Status Research & Development GmbH
## Licensed under either of
## * Apache License, version 2.0, ([LICENSE-APACHE](LICENSE-APACHE))
## * MIT license ([LICENSE-MIT](LICENSE-MIT))
## at your option.
## This file may not be copied, modified, or distributed except according to
## those terms.
import stew/byteutils
const
ShortDumpMax = 12
func shortLog*(item: openarray[byte]): string =
if item.len <= ShortDumpMax:
result = item.toHex()
else:
const
split = ShortDumpMax div 2
dumpLen = (ShortDumpMax * 2) + 3
result = newStringOfCap(dumpLen)
result &= item.toOpenArray(0, split - 1).toHex()
result &= "..."
result &= item.toOpenArray(item.len - split, item.high).toHex()
func shortLog*(item: string): string =
if item.len <= ShortDumpMax:
result = item
else:
const
split = ShortDumpMax div 2
dumpLen = ShortDumpMax + 3
result = newStringOfCap(dumpLen)
result &= item[0..<split]
result &= "..."
result &= item[(item.len - split)..item.high]