UPNP + hairpin probing

alert/log.go

@@ -6,10 +6,6 @@ import (
 
 var log = logging.MustGetLogger("alert")
 
-func init() {
-	logging.SetFormatter(logging.MustStringFormatter("[%{level:.1s}] %{message}"))
-}
-
 func SetAlertLogger(l *logging.Logger) {
 	log = l
 }

cmd/daemon.go

@@ -117,7 +117,7 @@ func daemon() {
 
 	// Create & start node
 	n := NewNode()
-	l := p2p.NewDefaultListener("tcp", config.Config.LAddr)
+	l := p2p.NewDefaultListener("tcp", config.Config.LAddr, false)
 	n.AddListener(l)
 	n.Start()
 

cmd/gen_account.go

@@ -24,4 +24,5 @@ Account Private Key: %X
 		base64.StdEncoding.EncodeToString(BinaryBytes(privAccount.PubKey)),
 		privAccount.PrivKey,
 		base64.StdEncoding.EncodeToString(BinaryBytes(privAccount.PrivKey)))
+
 }

cmd/log.go

@@ -2,15 +2,6 @@ package main
 
 import (
 	"github.com/op/go-logging"
-	"os"
 )
 
 var log = logging.MustGetLogger("main")
-
-func init() {
-	// Customize the output format
-	logging.SetFormatter(logging.MustStringFormatter("[%{level:.4s}] %{time:2006-01-02T15:04:05} %{shortfile:-20s} %{message}"))
-	logBackend := logging.NewLogBackend(os.Stderr, "", 0)
-	logBackend.Color = true
-	logging.SetBackend(logBackend)
-}

cmd/main.go

@@ -20,6 +20,7 @@ Commands:
     daemon        Run the tendermint node daemon
     gen_account   Generate new account keypair
     gen_validator Generate new validator keypair
+    probe_upnp    Test UPnP functionality
 	
 tendermint --help for command options`)
 		return
@@ -32,5 +33,7 @@ tendermint --help for command options`)
 		gen_account()
 	case "gen_validator":
 		gen_validator()
+	case "probe_upnp":
+		probe_upnp()
 	}
 }

cmd/probe_upnp.go

@@ -0,0 +1,24 @@
+package main
+
+import (
+	"encoding/json"
+	"fmt"
+
+	"github.com/tendermint/tendermint/p2p/upnp"
+)
+
+func probe_upnp() {
+
+	capabilities, err := upnp.Probe()
+	if err != nil {
+		fmt.Println("Probe failed: %v", err)
+	} else {
+		fmt.Println("Probe success!")
+		jsonBytes, err := json.Marshal(capabilities)
+		if err != nil {
+			panic(err)
+		}
+		fmt.Println(string(jsonBytes))
+	}
+
+}

common/logging.go

@@ -11,10 +11,10 @@ var Log = logging.MustGetLogger("main")
 
 func init() {
 	// Customize the output format
-	logging.SetFormatter(logging.MustStringFormatter("▶ %{level:.1s} 0x%{id:x} %{message}"))
+	logging.SetFormatter(logging.MustStringFormatter("[%{level:.4s}] %{shortfile:-20s} %{message}"))
 
 	// Setup one stdout and one syslog backend.
-	logBackend := logging.NewLogBackend(os.Stderr, "", stdlog.LstdFlags|stdlog.Lshortfile)
+	logBackend := logging.NewLogBackend(os.Stderr, "", stdlog.LstdFlags)
 	logBackend.Color = true
 
 	syslogBackend, err := logging.NewSyslogBackend("")

consensus/log.go

@@ -6,10 +6,6 @@ import (
 
 var log = logging.MustGetLogger("consensus")
 
-func init() {
-	logging.SetFormatter(logging.MustStringFormatter("[%{level:.1s}] %{message}"))
-}
-
 func SetConsensusLogger(l *logging.Logger) {
 	log = l
 }

p2p/connection.go

@@ -163,7 +163,7 @@ func (c *MConnection) Send(chId byte, msg interface{}) bool {
 		return false
 	}
 
-	log.Debug("[%X][%v] Send: %v", chId, c, msg)
+	log.Debug("[%X] Send to %v: %v", chId, c, msg)
 
 	// Send message to channel.
 	channel, ok := c.channelsIdx[chId]
@@ -190,7 +190,7 @@ func (c *MConnection) TrySend(chId byte, msg interface{}) bool {
 		return false
 	}
 
-	log.Debug("[%X][%v] TrySend: %v", chId, c, msg)
+	log.Debug("[%X] TrySend to %v: %v", chId, c, msg)
 
 	// Send message to channel.
 	channel, ok := c.channelsIdx[chId]

p2p/listener.go

@@ -46,7 +46,7 @@ func splitHostPort(addr string) (host string, port int) {
 	return host, port
 }
 
-func NewDefaultListener(protocol string, lAddr string) Listener {
+func NewDefaultListener(protocol string, lAddr string, requireUPNPHairpin bool) Listener {
 	// Local listen IP & port
 	lAddrIP, lAddrPort := splitHostPort(lAddr)
 
@@ -61,12 +61,23 @@ func NewDefaultListener(protocol string, lAddr string) Listener {
 
 	// Determine external address...
 	var extAddr *NetAddress
+
 	// If the lAddrIP is INADDR_ANY, try UPnP
-	if false {
-		if lAddrIP == "" || lAddrIP == "0.0.0.0" {
-			extAddr = getUPNPExternalAddress(lAddrPort, listenerPort)
+	if lAddrIP == "" || lAddrIP == "0.0.0.0" {
+		if requireUPNPHairpin {
+			upnpCapabilities, err := upnp.Probe()
+			if err != nil {
+				log.Warning("Failed to probe UPNP: %v", err)
+				goto SKIP_UPNP
+			}
+			if !upnpCapabilities.Hairpin {
+				goto SKIP_UPNP
+			}
 		}
+		extAddr = getUPNPExternalAddress(lAddrPort, listenerPort)
 	}
+SKIP_UPNP:
+
 	// Otherwise just use the local address...
 	if extAddr == nil {
 		extAddr = getNaiveExternalAddress(listenerPort)

p2p/log.go

@@ -6,11 +6,6 @@ import (
 
 var log = logging.MustGetLogger("p2p")
 
-func init() {
-	logging.SetFormatter(logging.MustStringFormatter("[%{level:.1s}] %{message}"))
-	logging.SetLevel(logging.DEBUG, "p2p")
-}
-
 func SetP2PLogger(l *logging.Logger) {
 	log = l
 }

p2p/switch_test.go

@@ -75,7 +75,7 @@ func makeSwitchPair(t testing.TB, reactorsGenerator func() []Reactor) (*Switch,
 	s2 := NewSwitch(reactorsGenerator())
 
 	// Create a listener for s1
-	l := NewDefaultListener("tcp", ":8001")
+	l := NewDefaultListener("tcp", ":8001", true)
 
 	// Dial the listener & add the connection to s2.
 	lAddr := l.ExternalAddress()

p2p/upnp/log.go

@@ -0,0 +1,11 @@
+package upnp
+
+import (
+	"github.com/op/go-logging"
+)
+
+var log = logging.MustGetLogger("upnp")
+
+func SetUPNPLogger(l *logging.Logger) {
+	log = l
+}

p2p/upnp/probe.go

@@ -0,0 +1,109 @@
+package upnp
+
+import (
+	"errors"
+	"fmt"
+	"net"
+	"time"
+)
+
+type UPNPCapabilities struct {
+	PortMapping bool
+	Hairpin     bool
+}
+
+func makeUPNPListener(intPort int, extPort int) (NAT, net.Listener, net.IP, error) {
+	nat, err := Discover()
+	if err != nil {
+		return nil, nil, nil, errors.New(fmt.Sprintf("NAT upnp could not be discovered: %v", err))
+	}
+	log.Debug("ourIP: %v", nat.(*upnpNAT).ourIP)
+
+	ext, err := nat.GetExternalAddress()
+	if err != nil {
+		return nat, nil, nil, errors.New(fmt.Sprintf("External address error: %v", err))
+	}
+	log.Debug("External address: %v", ext)
+
+	port, err := nat.AddPortMapping("tcp", extPort, intPort, "Tendermint UPnP Probe", 0)
+	if err != nil {
+		return nat, nil, ext, errors.New(fmt.Sprintf("Port mapping error: %v", err))
+	}
+	log.Debug("Port mapping mapped: %v", port)
+
+	// also run the listener, open for all remote addresses.
+	listener, err := net.Listen("tcp", fmt.Sprintf(":%v", intPort))
+	if err != nil {
+		return nat, nil, ext, errors.New(fmt.Sprintf("Error establishing listener: %v", err))
+	}
+	return nat, listener, ext, nil
+}
+
+func testHairpin(listener net.Listener, extAddr string) (supportsHairpin bool) {
+	// Listener
+	go func() {
+		inConn, err := listener.Accept()
+		if err != nil {
+			log.Info("Listener.Accept() error: %v", err)
+			return
+		}
+		log.Debug("Accepted incoming connection: %v -> %v", inConn.LocalAddr(), inConn.RemoteAddr())
+		buf := make([]byte, 1024)
+		n, err := inConn.Read(buf)
+		if err != nil {
+			log.Info("Incoming connection read error: %v", err)
+			return
+		}
+		log.Debug("Incoming connection read %v bytes: %X", n, buf)
+		if string(buf) == "test data" {
+			supportsHairpin = true
+			return
+		}
+	}()
+
+	// Establish outgoing
+	outConn, err := net.Dial("tcp", extAddr)
+	if err != nil {
+		log.Info("Outgoing connection dial error: %v", err)
+		return
+	}
+
+	n, err := outConn.Write([]byte("test data"))
+	if err != nil {
+		log.Info("Outgoing connection write error: %v", err)
+		return
+	}
+	log.Debug("Outgoing connection wrote %v bytes", n)
+
+	// Wait for data receipt
+	time.Sleep(1 * time.Second)
+	return
+}
+
+func Probe() (caps UPNPCapabilities, err error) {
+	log.Debug("Probing for UPnP!")
+
+	intPort, extPort := 8001, 8001
+
+	nat, listener, ext, err := makeUPNPListener(intPort, extPort)
+	if err != nil {
+		return
+	}
+	caps.PortMapping = true
+
+	// Deferred cleanup
+	defer func() {
+		err = nat.DeletePortMapping("tcp", intPort, extPort)
+		if err != nil {
+			log.Warning("Port mapping delete error: %v", err)
+		}
+		listener.Close()
+	}()
+
+	supportsHairpin := testHairpin(listener, fmt.Sprintf("%v:%v", ext, extPort))
+	if supportsHairpin {
+		caps.Hairpin = true
+	}
+
+	return
+}

p2p/upnp/upnp.go

@@ -349,6 +349,9 @@ func (n *upnpNAT) AddPortMapping(protocol string, externalPort, internalPort int
 
 	// TODO: check response to see if the port was forwarded
 	// log.Println(message, response)
+	// JAE:
+	// body, err := ioutil.ReadAll(response.Body)
+	// fmt.Println(string(body), err)
 	mappedExternalPort = externalPort
 	_ = response
 	return

p2p/upnp/upnp_test.go

@@ -1,51 +0,0 @@
-package upnp
-
-import (
-	"net"
-	"testing"
-	"time"
-)
-
-/*
-This is a manual test.
-TODO: set up or find a service to probe open ports.
-*/
-func _TestUPNP(t *testing.T) {
-	t.Log("hello!")
-
-	nat, err := Discover()
-	if err != nil {
-		t.Fatalf("NAT upnp could not be discovered: %v", err)
-	}
-
-	t.Log("ourIP: ", nat.(*upnpNAT).ourIP)
-
-	ext, err := nat.GetExternalAddress()
-	if err != nil {
-		t.Fatalf("External address error: %v", err)
-	}
-	t.Logf("External address: %v", ext)
-
-	port, err := nat.AddPortMapping("tcp", 8001, 8001, "testing", 0)
-	if err != nil {
-		t.Fatalf("Port mapping error: %v", err)
-	}
-	t.Logf("Port mapping mapped: %v", port)
-
-	// also run the listener, open for all remote addresses.
-	listener, err := net.Listen("tcp", ":8001")
-	if err != nil {
-		panic(err)
-	}
-
-	// now sleep for 10 seconds
-	time.Sleep(10 * time.Second)
-
-	err = nat.DeletePortMapping("tcp", 8001, 8001)
-	if err != nil {
-		t.Fatalf("Port mapping delete error: %v", err)
-	}
-	t.Logf("Port mapping deleted")
-
-	listener.Close()
-}

rpc/log.go

@@ -6,10 +6,6 @@ import (
 
 var log = logging.MustGetLogger("rpc")
 
-func init() {
-	logging.SetFormatter(logging.MustStringFormatter("[%{level:.1s}] %{message}"))
-}
-
 func SetRPCLogger(l *logging.Logger) {
 	log = l
 }

state/log.go

@@ -6,10 +6,6 @@ import (
 
 var log = logging.MustGetLogger("state")
 
-func init() {
-	logging.SetFormatter(logging.MustStringFormatter("[%{level:.1s}] %{message}"))
-}
-
 func SetStateLogger(l *logging.Logger) {
 	log = l
 }