A lot of logger.InfoFs are added. Some tweaks in configs

integration/intermediary-nodeB.json

@@ -20,6 +20,7 @@
 			"0324579f003e6b4048bae2def4365e634d8e0e3054a20fc7af49daf2a179658557"
 		],
 		"route_finder": "https://routefinder.skywire.skycoin.net/",
+		"route_finder_timeout": "60s",
 		"table": {
 			"type": "boltdb",
 			"location": "./local/nodeB/routing.db"

integration/messaging/env-vars.sh

@@ -1,19 +1,23 @@
 # This script needs to be `source`d from bash-compatible shell
-# E.g. `source ./integration/generic/env-vars.sh` or `. ./integration/generic/env-vars.sh`
-export PK_A=$(jq -r ".node.static_public_key" ./integration/generic/nodeA.json)
-export RPC_A=$(jq -r ".interfaces.rpc" ./integration/generic/nodeA.json)
+# E.g. `source ./integration/generic/env-vars.sh` or `. ./integration/messaging/env-vars.sh`
+export PK_A=$(jq -r ".node.static_public_key" ./integration/messaging/nodeA.json)
+export RPC_A=$(jq -r ".interfaces.rpc" ./integration/messaging/nodeA.json)
 export PK_B=$(jq -r ".node.static_public_key" ./integration/intermediary-nodeB.json)
 export RPC_B=$(jq -r ".interfaces.rpc" ./integration/intermediary-nodeB.json)
-export PK_C=$(jq -r ".node.static_public_key" ./integration/generic/nodeC.json)
-export RPC_C=$(jq -r ".interfaces.rpc" ./integration/generic/nodeC.json)
+export PK_C=$(jq -r ".node.static_public_key" ./integration/messaging/nodeC.json)
+export RPC_C=$(jq -r ".interfaces.rpc" ./integration/messaging/nodeC.json)
 
 export CHAT_A=http://localhost:8000/message
-export CHAT_C=http://localhost$(jq -r '.apps [] |select(.app=="skychat")| .args[1] ' ./integration/generic/nodeC.json)/message
+export CHAT_C=http://localhost$(jq -r '.apps [] |select(.app=="skychat")| .args[1] ' ./integration/messaging/nodeC.json)/message
 
 alias CLI_A='./skywire-cli --rpc $RPC_A'
 alias CLI_B='./skywire-cli --rpc $RPC_B'
 alias CLI_C='./skywire-cli --rpc $RPC_C'
 
+alias RUN_A='go run ./cmd/skywire-node ./integration/messaging/nodeA.json --tag NodeA'
+alias RUN_B='go run ./cmd/skywire-node ./integration/intermediary-nodeB.json --tag NodeB'
+alias RUN_C='go run ./cmd/skywire-node ./integration/messaging/nodeC.json --tag NodeC'
+
 echo PK_A: $PK_A
 echo PK_B: $PK_B
 echo PK_C: $PK_C

integration/messaging/nodeA.json

@@ -20,6 +20,7 @@
             "0324579f003e6b4048bae2def4365e634d8e0e3054a20fc7af49daf2a179658557"
         ],
         "route_finder": "https://routefinder.skywire.skycoin.net/",
+        "route_finder_timeout": "60s",
 		"table": {
 			"type": "boltdb",
 			"location": "./local/nodeA/routing.db"
@@ -37,6 +38,7 @@
     "trusted_nodes": [],
     "manager_nodes": [],
     "apps_path": "./apps",
+    "shutdown_timeout": "30s",
     "local_path": "./local/nodeA",
     "log_level": "info",
     "interfaces": {

integration/messaging/nodeC.json

@@ -20,6 +20,7 @@
 			"0324579f003e6b4048bae2def4365e634d8e0e3054a20fc7af49daf2a179658557"
 		],
 		"route_finder": "https://routefinder.skywire.skycoin.net/",
+		"route_finder_timeout": "60s",
 		"table": {
 			"type": "boltdb",
 			"location": "./local/nodeC/routing.db"
@@ -37,6 +38,7 @@
 		"trusted_nodes": [],
 		"manager_nodes": [],
 		"apps_path": "./apps",
+		"shutdown_timeout": "30s",
 		"local_path": "./local/nodeC",
 		"log_level": "info",
 		"interfaces": {

integration/proxy/env-vars.sh

@@ -11,6 +11,10 @@ alias CLI_A='./skywire-cli --rpc $RPC_A'
 alias CLI_B='./skywire-cli --rpc $RPC_B'
 alias CLI_C='./skywire-cli --rpc $RPC_C'
 
+alias RUN_A='go run ./cmd/skywire-node ./integration/messaging/nodeA.json --tag NodeA'
+alias RUN_B='go run ./cmd/skywire-node ./integration/intermediary-nodeB.json --tag NodeB'
+alias RUN_C='go run ./cmd/skywire-node ./integration/messaging/nodeC.json --tag NodeC'
+
 echo PK_A: $PK_A
 echo PK_B: $PK_B
 echo PK_C: $PK_C

integration/ssh/env-vars.sh

@@ -11,6 +11,10 @@ alias CLI_A='./skywire-cli --rpc $RPC_A'
 alias CLI_B='./skywire-cli --rpc $RPC_B'
 alias CLI_C='./skywire-cli --rpc $RPC_C'
 
+alias RUN_A='go run ./cmd/skywire-node ./integration/messaging/nodeA.json --tag NodeA'
+alias RUN_B='go run ./cmd/skywire-node ./integration/intermediary-nodeB.json --tag NodeB'
+alias RUN_C='go run ./cmd/skywire-node ./integration/messaging/nodeC.json --tag NodeC'
+
 echo PK_A: $PK_A
 echo PK_B: $PK_B
 echo PK_C: $PK_C

integration/test-messaging.sh

@@ -1,4 +1,4 @@
 #!/usr/bin/env bash
 source ./integration/generic/env-vars.sh
-curl --data  {'"recipient":"'$PK_A'", "message":"Hello Joe!"}' -X POST  $CHAT_C  
+# curl --data  {'"recipient":"'$PK_A'", "message":"Hello Joe!"}' -X POST  $CHAT_C  
 curl --data  {'"recipient":"'$PK_C'", "message":"Hello Mike!"}' -X POST  $CHAT_A

pkg/messaging/channel.go

@@ -54,6 +54,7 @@ func newChannel(initiator bool, secKey cipher.SecKey, remote cipher.PubKey, link
 		readChan: make(chan []byte),
 		doneChan: make(chan struct{}),
 		noise:    noiseInstance,
+		deadline: time.Time{},
 	}, nil
 }
 

pkg/messaging/factory.go

@@ -26,9 +26,9 @@ var (
 	// ErrRejected indicates that ChannelOpen frame was rejected by remote server.
 	ErrRejected = errors.New("rejected")
 	// ErrChannelClosed indicates that underlying channel is being closed and writes are prohibited.
-	ErrChannelClosed = errors.New("channel closed")
+	ErrChannelClosed = errors.New("messaging channel closed")
 	// ErrDeadlineExceeded indicates that read/write operation failed due to timeout.
-	ErrDeadlineExceeded = errors.New("deadline exceeded")
+	ErrDeadlineExceeded = errors.New("deadline exceeded in messaging")
 	// ErrClientClosed indicates that client is closed and not accepting new connections.
 	ErrClientClosed = errors.New("client closed")
 )

pkg/transport/handshake.go

@@ -22,55 +22,64 @@ func (handshake settlementHandshake) Do(tm *Manager, tr Transport, timeout time.
 	case <-done:
 		return entry, err
 	case <-time.After(timeout):
-		return nil, errors.New("deadline exceeded")
+		tm.Logger.Infof("handshake.Do timeout exceeded for value: %v", timeout)
+		return nil, errors.New("deadline exceeded on handshake")
 	}
 }
 
 func settlementInitiatorHandshake(public bool) settlementHandshake {
 	return func(tm *Manager, tr Transport) (*Entry, error) {
+		tm.Logger.Info("Entering settlementInitiatorHandshake")
 		entry := &Entry{
 			ID:       MakeTransportID(tr.Edges()[0], tr.Edges()[1], tr.Type(), public),
 			EdgeKeys: tr.Edges(),
 			Type:     tr.Type(),
 			Public:   public,
 		}
 
+		remote, ok := tm.Remote(tr.Edges())
+		if !ok {
+			return nil, errors.New("configured PubKey not found in edges")
+		}
+
+		tm.Logger.Infof("settlementInitiatorHandshake: NewSignedEntry with %v", remote)
 		sEntry, ok := NewSignedEntry(entry, tm.config.PubKey, tm.config.SecKey)
 		if !ok {
 			return nil, errors.New("error creating signed entry")
 		}
+		tm.Logger.Info("settlementInitiatorHandshake: validateSignedEntry")
 		if err := validateSignedEntry(sEntry, tr, tm.config.PubKey); err != nil {
 			return nil, fmt.Errorf("settlementInitiatorHandshake NewSignedEntry: %s\n sEntry: %v", err, sEntry)
 		}
-
+		tm.Logger.Info("settlementInitiatorHandshake: json.NewEncoder.Encode")
 		if err := json.NewEncoder(tr).Encode(sEntry); err != nil {
 			return nil, fmt.Errorf("write: %s", err)
 		}
 
+		tm.Logger.Info("settlementInitiatorHandshake: json.NewDecoder")
 		respSEntry := &SignedEntry{}
 		if err := json.NewDecoder(tr).Decode(respSEntry); err != nil {
 			return nil, fmt.Errorf("read: %s", err)
 		}
 
 		//  Verifying remote signature
-		remote, ok := tm.Remote(tr.Edges())
-		if !ok {
-			return nil, errors.New("configured PubKey not found in edges")
-		}
+
+		tm.Logger.Info("settlementInitiatorHandshake: verifySig")
 		if err := verifySig(respSEntry, remote); err != nil {
 			return nil, err
 		}
-
+		tm.Logger.Info("settlementInitiatorHandshake: tm.walkEntries")
 		newEntry := tm.walkEntries(func(e *Entry) bool { return *e == *respSEntry.Entry }) == nil
 		if newEntry {
 			tm.addEntry(entry)
 		}
-
+		tm.Logger.Info("Exiting settlementInitiatorHandshake")
 		return respSEntry.Entry, nil
 	}
 }
 
 func settlementResponderHandshake(tm *Manager, tr Transport) (*Entry, error) {
+	tm.Logger.Info("Entering settlementResponderHandshake")
 	sEntry := &SignedEntry{}
 	if err := json.NewDecoder(tr).Decode(sEntry); err != nil {
 		return nil, fmt.Errorf("read: %s", err)
@@ -91,6 +100,7 @@ func settlementResponderHandshake(tm *Manager, tr Transport) (*Entry, error) {
 
 	newEntry := tm.walkEntries(func(e *Entry) bool { return *e == *sEntry.Entry }) == nil
 
+	tm.Logger.Info("Entering settlementResponderHandshake: DiscoveryClient.UpdateStatuses/RegisterTransports")
 	var err error
 	if sEntry.Entry.Public {
 		if !newEntry {
@@ -104,14 +114,15 @@ func settlementResponderHandshake(tm *Manager, tr Transport) (*Entry, error) {
 		return nil, fmt.Errorf("entry set: %s", err)
 	}
 
+	tm.Logger.Info("Entering settlementResponderHandshake: json.NewEncoder(tr).Encode")
 	if err := json.NewEncoder(tr).Encode(sEntry); err != nil {
 		return nil, fmt.Errorf("write: %s", err)
 	}
 
 	if newEntry {
 		tm.addEntry(sEntry.Entry)
 	}
-
+	tm.Logger.Info("Exiting settlementResponderHandshake")
 	return sEntry.Entry, nil
 }