debug prints (#132)

* debug prints

* CI: enable stack traces

* Azure: better NimBinaries cache key

* CI changes

- Azure: remove Linux target
- Travis: add ARM64 target

* uglify the code in order to save 12 bytes per LPStream object

.travis.yml

@@ -1,5 +1,7 @@
 language: go
 
+dist: bionic
+
 # https://docs.travis-ci.com/user/caching/
 cache:
   directories:
@@ -15,9 +17,21 @@ go: "1.12.x"
 matrix:
   include:
     - os: linux
+      arch: amd64
+      env:
+        - NPROC=2
+      before_install:
+        - export GOPATH=$HOME/go
+    - os: linux
+      arch: arm64
+      env:
+        - NPROC=6 # Worth trying more than 2 parallel jobs: https://travis-ci.community/t/no-cache-support-on-arm64/5416/8
+        # (also used to get a different cache key than the amd64 one)
       before_install:
         - export GOPATH=$HOME/go
     - os: osx
+      env:
+        - NPROC=2
       before_install:
         - export GOPATH=$HOME/go
 
@@ -26,7 +40,7 @@ install:
   # regressions of the fast-paced Nim development while maintaining the
   # flexibility to apply patches
   - curl -O -L -s -S https://raw.githubusercontent.com/status-im/nimbus-build-system/master/scripts/build_nim.sh
-  - env MAKE="make -j2" bash build_nim.sh Nim csources dist/nimble NimBinaries
+  - env MAKE="make -j${NPROC}" bash build_nim.sh Nim csources dist/nimble NimBinaries
   - export PATH="$PWD/Nim/bin:$GOPATH/bin:$PATH"
 
   # install and build go-libp2p-daemon

azure-pipelines.yml

@@ -18,10 +18,10 @@ strategy:
     #   UCPU: amd64
     #   PLATFORM: x64
     #   TEST_LANG: cpp
-    Linux_64bit:
-      VM: 'ubuntu-16.04'
-      PLATFORM: x64
-      TEST_LANG: c
+    #Linux_64bit:
+      #VM: 'ubuntu-16.04'
+      #PLATFORM: x64
+      #TEST_LANG: c
     # Linux_cpp_64bit:
     #   VM: 'ubuntu-16.04'
     #   UCPU: amd64
@@ -53,7 +53,7 @@ steps:
   - task: CacheBeta@1
     displayName: 'cache Nim binaries'
     inputs:
-      key: NimBinaries | $(Agent.OS) | $(PLATFORM)
+      key: NimBinaries | $(Agent.OS) | $(PLATFORM) | "$(Build.SourceBranchName)" | "v3"
       path: NimBinaries
 
   - task: CacheBeta@1

libp2p.nimble

@@ -16,8 +16,8 @@ requires "nim > 0.19.4",
          "stew"
 
 proc runTest(filename: string) =
-  exec "nim --opt:speed -d:release c -r tests/" & filename
-  # rmFile "tests/" & filename
+  exec "nim c -r --opt:speed -d:debug --verbosity:0 --hints:off tests/" & filename
+  rmFile "tests/" & filename.toExe
 
 task test, "Runs the test suite":
   runTest "testnative"

libp2p/connection.nim

@@ -7,7 +7,7 @@
 ## This file may not be copied, modified, or distributed except according to
 ## those terms.
 
-import chronos, chronicles
+import chronos, chronicles, oids
 import peerinfo,
        multiaddress,
        stream/lpstream,
@@ -54,6 +54,8 @@ proc init*[T: Connection](self: var T, stream: LPStream): T =
   new self
   self.stream = stream
   self.closeEvent = newAsyncEvent()
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    self.oid = genOid()
   asyncCheck self.bindStreamClose()
 
   return self

libp2p/protocols/secure/secio.nim

@@ -6,7 +6,7 @@
 ## at your option.
 ## This file may not be copied, modified, or distributed except according to
 ## those terms.
-import chronos, chronicles
+import chronos, chronicles, oids
 import nimcrypto/[sysrand, hmac, sha2, sha, hash, rijndael, twofish, bcmode]
 import secure,
        ../../connection,
@@ -177,12 +177,15 @@ proc macCheckAndDecode(sconn: SecioConn, data: var seq[byte]): bool =
 
 method readMessage(sconn: SecioConn): Future[seq[byte]] {.async.} =
   ## Read message from channel secure connection ``sconn``.
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    logScope:
+      stream_oid = $sconn.stream.oid
   try:
     var buf = newSeq[byte](4)
     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 = buf.shortLog, length = length
+    trace "Received message header", header = buf.shortLog, length = length
     if length <= SecioMaxMessageSize:
       buf.setLen(length)
       await sconn.readExactly(addr buf[0], length)
@@ -260,6 +263,8 @@ proc newSecioConn(conn: Connection,
                           secrets.ivOpenArray(i1))
 
   result.peerInfo = PeerInfo.init(remotePubKey)
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    result.oid = genOid()
 
 proc transactMessage(conn: Connection,
                      msg: seq[byte]): Future[seq[byte]] {.async.} =

libp2p/stream/bufferstream.nim

@@ -30,7 +30,7 @@
 ## will suspend until either the amount of elements in the
 ## buffer goes below ``maxSize`` or more data becomes available.
 
-import deques, math
+import deques, math, oids
 import chronos, chronicles
 import ../stream/lpstream
 
@@ -63,6 +63,7 @@ proc requestReadBytes(s: BufferStream): Future[void] =
   ## data becomes available in the read buffer
   result = newFuture[void]()
   s.readReqs.addLast(result)
+  trace "requestReadBytes(): added a future to readReqs"
 
 proc initBufferStream*(s: BufferStream,
                        handler: WriteHandler = nil,
@@ -74,6 +75,8 @@ proc initBufferStream*(s: BufferStream,
   s.lock = newAsyncLock()
   s.writeHandler = handler
   s.closeEvent = newAsyncEvent()
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    s.oid = genOid()
 
 proc newBufferStream*(handler: WriteHandler = nil,
                       size: int = DefaultBufferSize): BufferStream =
@@ -103,6 +106,10 @@ proc pushTo*(s: BufferStream, data: seq[byte]) {.async.} =
   ## is preserved.
   ##
 
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    logScope:
+      stream_oid = $s.oid
+
   try:
     await s.lock.acquire()
     var index = 0
@@ -110,10 +117,12 @@ proc pushTo*(s: BufferStream, data: seq[byte]) {.async.} =
       while index < data.len and s.readBuf.len < s.maxSize:
         s.readBuf.addLast(data[index])
         inc(index)
+      trace "pushTo()", msg = "added " & $index & " bytes to readBuf"
 
       # resolve the next queued read request
       if s.readReqs.len > 0:
         s.readReqs.popFirst().complete()
+        trace "pushTo(): completed a readReqs future"
 
       if index >= data.len:
         return
@@ -130,6 +139,11 @@ method read*(s: BufferStream, n = -1): Future[seq[byte]] {.async.} =
   ##
   ## This procedure allocates buffer seq[byte] and return it as result.
   ##
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    logScope:
+      stream_oid = $s.oid
+
+  trace "read()", requested_bytes = n
   var size = if n > 0: n else: s.readBuf.len()
   var index = 0
 
@@ -140,6 +154,7 @@ method read*(s: BufferStream, n = -1): Future[seq[byte]] {.async.} =
     while s.readBuf.len() > 0 and index < size:
       result.add(s.popFirst())
       inc(index)
+    trace "read()", read_bytes = index
 
     if index < size:
       await s.requestReadBytes()
@@ -154,6 +169,10 @@ method readExactly*(s: BufferStream,
   ## If EOF is received and ``nbytes`` is not yet read, the procedure
   ## will raise ``LPStreamIncompleteError``.
   ##
+  when chronicles.enabledLogLevel == LogLevel.TRACE:
+    logScope:
+      stream_oid = $s.oid
+
   var buff: seq[byte]
   try:
     buff = await s.read(nbytes)

libp2p/stream/lpstream.nim

@@ -7,12 +7,15 @@
 ## This file may not be copied, modified, or distributed except according to
 ## those terms.
 
-import chronos
+import oids
+import chronicles, chronos
 
 type
   LPStream* = ref object of RootObj
     isClosed*: bool
     closeEvent*: AsyncEvent
+    when chronicles.enabledLogLevel == LogLevel.TRACE:
+      oid*: Oid
 
   LPStreamError* = object of CatchableError
   LPStreamIncompleteError* = object of LPStreamError