lots of logging

blocks/blocks.go

@@ -1,6 +1,8 @@
 package blocks
 
 import (
+	"fmt"
+
 	mh "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multihash"
 	u "github.com/jbenet/go-ipfs/util"
 )
@@ -20,3 +22,7 @@ func NewBlock(data []byte) *Block {
 func (b *Block) Key() u.Key {
 	return u.Key(b.Multihash)
 }
+
+func (b *Block) String() string {
+	return fmt.Sprintf("[Block %s]", b.Key())
+}

blockservice/blockservice.go

@@ -52,7 +52,7 @@ func (s *BlockService) AddBlock(b *blocks.Block) (u.Key, error) {
 // GetBlock retrieves a particular block from the service,
 // Getting it from the datastore using the key (hash).
 func (s *BlockService) GetBlock(ctx context.Context, k u.Key) (*blocks.Block, error) {
-	log.Debug("BlockService GetBlock: '%s'", k)
+	log.Debugf("BlockService GetBlock: '%s'", k)
 	datai, err := s.Datastore.Get(k.DsKey())
 	if err == nil {
 		log.Debug("Blockservice: Got data in datastore.")

crypto/spipe/handshake.go

@@ -53,7 +53,7 @@ func (s *SecurePipe) handshake() error {
 		return err
 	}
 
-	log.Debug("handshake: %s <--> %s", s.local, s.remote)
+	log.Debugf("handshake: %s <--> %s", s.local, s.remote)
 	myPubKey, err := s.local.PubKey().Bytes()
 	if err != nil {
 		return err
@@ -105,7 +105,7 @@ func (s *SecurePipe) handshake() error {
 	if err != nil {
 		return err
 	}
-	log.Debug("%s Remote Peer Identified as %s", s.local, s.remote)
+	log.Debugf("%s Remote Peer Identified as %s", s.local, s.remote)
 
 	exchange, err := selectBest(SupportedExchanges, proposeResp.GetExchanges())
 	if err != nil {
@@ -209,7 +209,7 @@ func (s *SecurePipe) handshake() error {
 		return fmt.Errorf("Negotiation failed, got: %s", resp2)
 	}
 
-	log.Debug("%s handshake: Got node id: %s", s.local, s.remote)
+	log.Debugf("%s handshake: Got node id: %s", s.local, s.remote)
 	return nil
 }
 

exchange/bitswap/bitswap.go

@@ -135,7 +135,6 @@ func (bs *bitswap) ReceiveMessage(ctx context.Context, p peer.Peer, incoming bsm
 	peer.Peer, bsmsg.BitSwapMessage) {
 	log.Debugf("ReceiveMessage from %v", p.Key())
 	log.Debugf("Message wantlist: %v", incoming.Wantlist())
-	log.Debugf("Message blockset: %v", incoming.Blocks())
 
 	if p == nil {
 		log.Error("Received message from nil peer!")

exchange/bitswap/network/net_message_adapter.go

@@ -4,6 +4,7 @@ import (
 	"errors"
 
 	context "github.com/jbenet/go-ipfs/Godeps/_workspace/src/code.google.com/p/go.net/context"
+	"github.com/jbenet/go-ipfs/util"
 
 	bsmsg "github.com/jbenet/go-ipfs/exchange/bitswap/message"
 	inet "github.com/jbenet/go-ipfs/net"
@@ -11,6 +12,8 @@ import (
 	peer "github.com/jbenet/go-ipfs/peer"
 )
 
+var log = util.Logger("net_message_adapter")
+
 // NetMessageAdapter wraps a NetMessage network service
 func NetMessageAdapter(s inet.Service, n inet.Network, r Receiver) Adapter {
 	adapter := impl{
@@ -60,6 +63,7 @@ func (adapter *impl) HandleMessage(
 		return nil
 	}
 
+	log.Debugf("Message size: %d", len(outgoing.Data()))
 	return outgoing
 }
 

net/conn/conn.go

@@ -21,7 +21,7 @@ const (
 	ChanBuffer = 10
 
 	// MaxMessageSize is the size of the largest single message
-	MaxMessageSize = 1 << 20 // 1 MB
+	MaxMessageSize = 1 << 22 // 4 MB
 
 	// HandshakeTimeout for when nodes first connect
 	HandshakeTimeout = time.Second * 5
@@ -97,6 +97,17 @@ func (c *singleConn) close() error {
 	return err
 }
 
+func (c *singleConn) GetError() error {
+	select {
+	case err := <-c.msgio.incoming.ErrChan:
+		return err
+	case err := <-c.msgio.outgoing.ErrChan:
+		return err
+	default:
+		return nil
+	}
+}
+
 // ID is an identifier unique to this connection.
 func (c *singleConn) ID() string {
 	return ID(c)

net/conn/handshake.go

@@ -46,7 +46,7 @@ func Handshake1(ctx context.Context, c Conn) error {
 			return fmt.Errorf("could not decode remote version: %q", err)
 		}
 
-		log.Debug("Received remote version (%s) from %s", remoteH, rpeer)
+		log.Debugf("Received remote version (%s) from %s", remoteH, rpeer)
 	}
 
 	if err := handshake.Handshake1Compatible(localH, remoteH); err != nil {

net/conn/interface.go

@@ -37,6 +37,8 @@ type Conn interface {
 	// Out returns a writable message channel
 	Out() chan<- []byte
 
+	GetError() error
+
 	// Close ends the connection
 	// Close() error  -- already in ContextCloser
 }

net/conn/multiconn.go

@@ -198,6 +198,10 @@ func (c *MultiConn) fanInSingle(child Conn) {
 		case m, more := <-child.In(): // receiving data
 			if !more {
 				log.Infof("%s in channel closed", child)
+				err := c.GetError()
+				if err != nil {
+					log.Errorf("Found error on connection: %s", err)
+				}
 				return // closed
 			}
 			i++
@@ -209,7 +213,7 @@ func (c *MultiConn) fanInSingle(child Conn) {
 
 // close is the internal close function, called by ContextCloser.Close
 func (c *MultiConn) close() error {
-	log.Debug("%s closing Conn with %s", c.local, c.remote)
+	log.Debugf("%s closing Conn with %s", c.local, c.remote)
 
 	// get connections
 	c.RLock()
@@ -291,3 +295,13 @@ func (c *MultiConn) In() <-chan []byte {
 func (c *MultiConn) Out() chan<- []byte {
 	return c.duplex.Out
 }
+
+func (c *MultiConn) GetError() error {
+	for _, sub := range c.conns {
+		err := sub.GetError()
+		if err != nil {
+			return err
+		}
+	}
+	return nil
+}

net/conn/secure_conn.go

@@ -134,3 +134,7 @@ func (c *secureConn) In() <-chan []byte {
 func (c *secureConn) Out() chan<- []byte {
 	return c.secure.Out
 }
+
+func (c *secureConn) GetError() error {
+	return c.insecure.GetError()
+}

net/swarm/conn.go

@@ -154,6 +154,9 @@ func (s *Swarm) fanOut() {
 				log.Infof("%s outgoing channel closed", s)
 				return
 			}
+			if len(msg.Data()) >= conn.MaxMessageSize {
+				log.Critical("Attempted to send message bigger than max size.")
+			}
 
 			s.connsLock.RLock()
 			c, found := s.conns[msg.Peer().Key()]
@@ -167,7 +170,7 @@ func (s *Swarm) fanOut() {
 			}
 
 			i++
-			//log.Debugf("%s sent message to %s (%d)", s.local, msg.Peer(), i)
+			log.Debugf("%s sent message to %s (%d)", s.local, msg.Peer(), i)
 			// queue it in the connection's buffer
 			c.Out() <- msg.Data()
 		}
@@ -206,7 +209,7 @@ func (s *Swarm) fanInSingle(c conn.Conn) {
 				return // channel closed.
 			}
 			i++
-			//log.Debugf("%s received message from %s (%d)", s.local, c.RemotePeer(), i)
+			log.Debugf("%s received message from %s (%d)", s.local, c.RemotePeer(), i)
 			s.Incoming <- msg.New(c.RemotePeer(), data)
 		}
 	}

routing/dht/handlers.go

@@ -145,7 +145,7 @@ func (dht *IpfsDHT) handleGetProviders(p peer.Peer, pmes *pb.Message) (*pb.Messa
 	resp := pb.NewMessage(pmes.GetType(), pmes.GetKey(), pmes.GetClusterLevel())
 
 	// check if we have this value, to add ourselves as provider.
-	log.Debugf("handling GetProviders: '%s'", pmes.GetKey())
+	log.Debugf("handling GetProviders: '%s'", u.Key(pmes.GetKey()))
 	dsk := u.Key(pmes.GetKey()).DsKey()
 	has, err := dht.datastore.Has(dsk)
 	if err != nil && err != ds.ErrNotFound {