update logging in multiple packages

blockservice/blockservice.go

@@ -7,12 +7,15 @@ import (
 	context "github.com/jbenet/go-ipfs/Godeps/_workspace/src/code.google.com/p/go.net/context"
 	ds "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/datastore.go"
 	mh "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multihash"
+	"github.com/op/go-logging"
 
 	blocks "github.com/jbenet/go-ipfs/blocks"
 	exchange "github.com/jbenet/go-ipfs/exchange"
 	u "github.com/jbenet/go-ipfs/util"
 )
 
+var log = logging.MustGetLogger("blockservice")
+
 // BlockService is a block datastore.
 // It uses an internal `datastore.Datastore` instance to store values.
 type BlockService struct {
@@ -26,7 +29,7 @@ func NewBlockService(d ds.Datastore, rem exchange.Interface) (*BlockService, err
 		return nil, fmt.Errorf("BlockService requires valid datastore")
 	}
 	if rem == nil {
-		u.DErr("Caution: blockservice running in local (offline) mode.\n")
+		log.Warning("blockservice running in local (offline) mode.")
 	}
 	return &BlockService{Datastore: d, Remote: rem}, nil
 }
@@ -35,7 +38,7 @@ func NewBlockService(d ds.Datastore, rem exchange.Interface) (*BlockService, err
 func (s *BlockService) AddBlock(b *blocks.Block) (u.Key, error) {
 	k := b.Key()
 	dsk := ds.NewKey(string(k))
-	u.DOut("storing [%s] in datastore\n", k.Pretty())
+	log.Debug("storing [%s] in datastore", k.Pretty())
 	// TODO(brian): define a block datastore with a Put method which accepts a
 	// block parameter
 	err := s.Datastore.Put(dsk, b.Data)
@@ -52,11 +55,11 @@ 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(k u.Key) (*blocks.Block, error) {
-	u.DOut("BlockService GetBlock: '%s'\n", k.Pretty())
+	log.Debug("BlockService GetBlock: '%s'", k.Pretty())
 	dsk := ds.NewKey(string(k))
 	datai, err := s.Datastore.Get(dsk)
 	if err == nil {
-		u.DOut("Blockservice: Got data in datastore.\n")
+		log.Debug("Blockservice: Got data in datastore.")
 		bdata, ok := datai.([]byte)
 		if !ok {
 			return nil, fmt.Errorf("data associated with %s is not a []byte", k)
@@ -66,7 +69,7 @@ func (s *BlockService) GetBlock(k u.Key) (*blocks.Block, error) {
 			Data:      bdata,
 		}, nil
 	} else if err == ds.ErrNotFound && s.Remote != nil {
-		u.DOut("Blockservice: Searching bitswap.\n")
+		log.Debug("Blockservice: Searching bitswap.")
 		ctx, _ := context.WithTimeout(context.TODO(), 5*time.Second)
 		blk, err := s.Remote.Block(ctx, k)
 		if err != nil {
@@ -74,7 +77,7 @@ func (s *BlockService) GetBlock(k u.Key) (*blocks.Block, error) {
 		}
 		return blk, nil
 	} else {
-		u.DOut("Blockservice GetBlock: Not found.\n")
+		log.Debug("Blockservice GetBlock: Not found.")
 		return nil, u.ErrNotFound
 	}
 }

fuse/ipns/ipns_unix.go

@@ -79,7 +79,9 @@ func CreateRoot(n *core.IpfsNode, keys []ci.PrivKey, ipfsroot string) (*Root, er
 
 		pointsTo, err := n.Namesys.Resolve(name)
 		if err != nil {
-			log.Warning("Could not resolve value for local ipns entry")
+			log.Warning("Could not resolve value for local ipns entry, providing empty dir")
+			nd.Nd = &mdag.Node{Data: mdag.FolderPBData()}
+			root.LocalDirs[name] = nd
 			continue
 		}
 
@@ -147,16 +149,16 @@ func (s *Root) Lookup(name string, intr fs.Intr) (fs.Node, fuse.Error) {
 	log.Debug("ipns: Falling back to resolution for [%s].", name)
 	resolved, err := s.Ipfs.Namesys.Resolve(name)
 	if err != nil {
-		log.Error("ipns: namesys resolve error: %s", err)
+		log.Warning("ipns: namesys resolve error: %s", err)
 		return nil, fuse.ENOENT
 	}
 
-	return &Link{s.IpfsRoot + "/" + u.Key(resolved).Pretty()}, nil
+	return &Link{s.IpfsRoot + "/" + resolved}, nil
 }
 
 // ReadDir reads a particular directory. Disallowed for root.
 func (r *Root) ReadDir(intr fs.Intr) ([]fuse.Dirent, fuse.Error) {
-	u.DOut("Read Root.\n")
+	log.Debug("Read Root.")
 	listing := []fuse.Dirent{
 		fuse.Dirent{
 			Name: "local",
@@ -255,7 +257,7 @@ func (n *Node) makeChild(name string, node *mdag.Node) *Node {
 
 // ReadDir reads the link structure as directory entries
 func (s *Node) ReadDir(intr fs.Intr) ([]fuse.Dirent, fuse.Error) {
-	u.DOut("Node ReadDir\n")
+	log.Debug("Node ReadDir")
 	entries := make([]fuse.Dirent, len(s.Nd.Links))
 	for i, link := range s.Nd.Links {
 		n := link.Name
@@ -370,10 +372,8 @@ func (n *Node) Fsync(req *fuse.FsyncRequest, intr fs.Intr) fuse.Error {
 
 func (n *Node) Mkdir(req *fuse.MkdirRequest, intr fs.Intr) (fs.Node, fuse.Error) {
 	log.Debug("Got mkdir request!")
-	dagnd := new(mdag.Node)
-	dagnd.Data = mdag.FolderPBData()
+	dagnd := &mdag.Node{Data: mdag.FolderPBData()}
 	n.Nd.AddNodeLink(req.Name, dagnd)
-	n.changed = true
 
 	child := &Node{
 		Ipfs: n.Ipfs,
@@ -386,6 +386,7 @@ func (n *Node) Mkdir(req *fuse.MkdirRequest, intr fs.Intr) (fs.Node, fuse.Error)
 		child.nsRoot = n.nsRoot
 	}
 
+	n.changed = true
 	n.updateTree()
 
 	return child, nil
@@ -404,8 +405,9 @@ func (n *Node) Open(req *fuse.OpenRequest, resp *fuse.OpenResponse, intr fs.Intr
 
 func (n *Node) Create(req *fuse.CreateRequest, resp *fuse.CreateResponse, intr fs.Intr) (fs.Node, fs.Handle, fuse.Error) {
 	log.Debug("Got create request: %s", req.Name)
-	nd := new(mdag.Node)
-	nd.Data = mdag.FilePBData(nil)
+
+	// New 'empty' file
+	nd := &mdag.Node{Data: mdag.FilePBData(nil)}
 	child := n.makeChild(req.Name, nd)
 
 	err := n.Nd.AddNodeLink(req.Name, nd)
@@ -545,3 +547,37 @@ func (l *Link) Readlink(req *fuse.ReadlinkRequest, intr fs.Intr) (string, fuse.E
 	log.Debug("ReadLink: %s", l.Target)
 	return l.Target, nil
 }
+
+type Republisher struct {
+	Timeout time.Duration
+	Publish chan struct{}
+	node    *Node
+}
+
+func NewRepublisher(n *Node, tout time.Duration) *Republisher {
+	return &Republisher{
+		Timeout: tout,
+		Publish: make(chan struct{}),
+		node:    n,
+	}
+}
+
+func (np *Republisher) Run() {
+	for _ := range np.Publish {
+		timer := time.After(np.Timeout)
+		for {
+			select {
+			case <-timer:
+				//Do the publish!
+				err := np.node.updateTree()
+				if err != nil {
+					log.Critical("updateTree error: %s", err)
+				}
+				goto done
+			case <-np.Publish:
+				timer = time.After(np.Timeout)
+			}
+		}
+	done:
+	}
+}

fuse/readonly/readonly_unix.go

@@ -21,8 +21,11 @@ import (
 	core "github.com/jbenet/go-ipfs/core"
 	mdag "github.com/jbenet/go-ipfs/merkledag"
 	u "github.com/jbenet/go-ipfs/util"
+	"github.com/op/go-logging"
 )
 
+var log = logging.MustGetLogger("ipfs")
+
 // FileSystem is the readonly Ipfs Fuse Filesystem.
 type FileSystem struct {
 	Ipfs *core.IpfsNode
@@ -50,7 +53,7 @@ func (*Root) Attr() fuse.Attr {
 
 // Lookup performs a lookup under this node.
 func (s *Root) Lookup(name string, intr fs.Intr) (fs.Node, fuse.Error) {
-	u.DOut("Root Lookup: '%s'\n", name)
+	log.Debug("Root Lookup: '%s'", name)
 	switch name {
 	case "mach_kernel", ".hidden", "._.":
 		// Just quiet some log noise on OS X.
@@ -68,7 +71,7 @@ func (s *Root) Lookup(name string, intr fs.Intr) (fs.Node, fuse.Error) {
 
 // ReadDir reads a particular directory. Disallowed for root.
 func (*Root) ReadDir(intr fs.Intr) ([]fuse.Dirent, fuse.Error) {
-	u.DOut("Read Root.\n")
+	log.Debug("Read Root.")
 	return nil, fuse.EPERM
 }
 
@@ -87,16 +90,14 @@ func (s *Node) loadData() error {
 
 // Attr returns the attributes of a given node.
 func (s *Node) Attr() fuse.Attr {
-	u.DOut("Node attr.\n")
+	log.Debug("Node attr.")
 	if s.cached == nil {
 		s.loadData()
 	}
 	switch s.cached.GetType() {
 	case mdag.PBData_Directory:
-		u.DOut("this is a directory.\n")
 		return fuse.Attr{Mode: os.ModeDir | 0555}
 	case mdag.PBData_File, mdag.PBData_Raw:
-		u.DOut("this is a file.\n")
 		size, _ := s.Nd.Size()
 		return fuse.Attr{
 			Mode:   0444,
@@ -111,7 +112,7 @@ func (s *Node) Attr() fuse.Attr {
 
 // Lookup performs a lookup under this node.
 func (s *Node) Lookup(name string, intr fs.Intr) (fs.Node, fuse.Error) {
-	u.DOut("Lookup '%s'\n", name)
+	log.Debug("Lookup '%s'", name)
 	nd, err := s.Ipfs.Resolver.ResolveLinks(s.Nd, []string{name})
 	if err != nil {
 		// todo: make this error more versatile.
@@ -123,7 +124,7 @@ func (s *Node) Lookup(name string, intr fs.Intr) (fs.Node, fuse.Error) {
 
 // ReadDir reads the link structure as directory entries
 func (s *Node) ReadDir(intr fs.Intr) ([]fuse.Dirent, fuse.Error) {
-	u.DOut("Node ReadDir\n")
+	log.Debug("Node ReadDir")
 	entries := make([]fuse.Dirent, len(s.Nd.Links))
 	for i, link := range s.Nd.Links {
 		n := link.Name
@@ -193,7 +194,7 @@ func Mount(ipfs *core.IpfsNode, fpath string) error {
 // Unmount attempts to unmount the provided FUSE mount point, forcibly
 // if necessary.
 func Unmount(point string) error {
-	fmt.Printf("Unmounting %s...\n", point)
+	log.Info("Unmounting %s...", point)
 
 	var cmd *exec.Cmd
 	switch runtime.GOOS {

routing/dht/dht.go

@@ -77,7 +77,7 @@ func NewDHT(p *peer.Peer, ps peer.Peerstore, net inet.Network, sender inet.Sende
 
 // Connect to a new peer at the given address, ping and add to the routing table
 func (dht *IpfsDHT) Connect(ctx context.Context, npeer *peer.Peer) (*peer.Peer, error) {
-	u.DOut("Connect to new peer: %s\n", npeer.ID.Pretty())
+	log.Debug("Connect to new peer: %s\n", npeer.ID.Pretty())
 
 	// TODO(jbenet,whyrusleeping)
 	//
@@ -132,7 +132,7 @@ func (dht *IpfsDHT) HandleMessage(ctx context.Context, mes msg.NetMessage) msg.N
 	dht.Update(mPeer)
 
 	// Print out diagnostic
-	u.DOut("[peer: %s] Got message type: '%s' [from = %s]\n",
+	log.Debug("[peer: %s] Got message type: '%s' [from = %s]\n",
 		dht.self.ID.Pretty(),
 		Message_MessageType_name[int32(pmes.GetType())], mPeer.ID.Pretty())
 
@@ -177,7 +177,7 @@ func (dht *IpfsDHT) sendRequest(ctx context.Context, p *peer.Peer, pmes *Message
 	start := time.Now()
 
 	// Print out diagnostic
-	u.DOut("[peer: %s] Sent message type: '%s' [to = %s]\n",
+	log.Debug("[peer: %s] Sent message type: '%s' [to = %s]\n",
 		dht.self.ID.Pretty(),
 		Message_MessageType_name[int32(pmes.GetType())], p.ID.Pretty())
 
@@ -224,7 +224,7 @@ func (dht *IpfsDHT) putProvider(ctx context.Context, p *peer.Peer, key string) e
 		return err
 	}
 
-	u.DOut("[%s] putProvider: %s for %s\n", dht.self.ID.Pretty(), p.ID.Pretty(), key)
+	log.Debug("[%s] putProvider: %s for %s", dht.self.ID.Pretty(), p.ID.Pretty(), key)
 	if *rpmes.Key != *pmes.Key {
 		return errors.New("provider not added correctly")
 	}
@@ -240,10 +240,10 @@ func (dht *IpfsDHT) getValueOrPeers(ctx context.Context, p *peer.Peer,
 		return nil, nil, err
 	}
 
-	u.DOut("pmes.GetValue() %v\n", pmes.GetValue())
+	log.Debug("pmes.GetValue() %v", pmes.GetValue())
 	if value := pmes.GetValue(); value != nil {
 		// Success! We were given the value
-		u.DOut("getValueOrPeers: got value\n")
+		log.Debug("getValueOrPeers: got value")
 		return value, nil, nil
 	}
 
@@ -253,7 +253,7 @@ func (dht *IpfsDHT) getValueOrPeers(ctx context.Context, p *peer.Peer,
 		if err != nil {
 			return nil, nil, err
 		}
-		u.DOut("getValueOrPeers: get from providers\n")
+		log.Debug("getValueOrPeers: get from providers")
 		return val, nil, nil
 	}
 
@@ -266,7 +266,7 @@ func (dht *IpfsDHT) getValueOrPeers(ctx context.Context, p *peer.Peer,
 
 		addr, err := ma.NewMultiaddr(pb.GetAddr())
 		if err != nil {
-			u.PErr("%v\n", err.Error())
+			log.Error("%v", err.Error())
 			continue
 		}
 
@@ -281,11 +281,11 @@ func (dht *IpfsDHT) getValueOrPeers(ctx context.Context, p *peer.Peer,
 	}
 
 	if len(peers) > 0 {
-		u.DOut("getValueOrPeers: peers\n")
+		u.DOut("getValueOrPeers: peers")
 		return nil, peers, nil
 	}
 
-	u.DOut("getValueOrPeers: u.ErrNotFound\n")
+	log.Warning("getValueOrPeers: u.ErrNotFound")
 	return nil, nil, u.ErrNotFound
 }
 
@@ -307,13 +307,13 @@ func (dht *IpfsDHT) getFromPeerList(ctx context.Context, key u.Key,
 	for _, pinfo := range peerlist {
 		p, err := dht.ensureConnectedToPeer(pinfo)
 		if err != nil {
-			u.DErr("getFromPeers error: %s\n", err)
+			log.Error("getFromPeers error: %s", err)
 			continue
 		}
 
 		pmes, err := dht.getValueSingle(ctx, p, key, level)
 		if err != nil {
-			u.DErr("getFromPeers error: %s\n", err)
+			log.Error("getFromPeers error: %s\n", err)
 			continue
 		}
 
@@ -348,7 +348,7 @@ func (dht *IpfsDHT) putLocal(key u.Key, value []byte) error {
 // Update signals to all routingTables to Update their last-seen status
 // on the given peer.
 func (dht *IpfsDHT) Update(p *peer.Peer) {
-	u.DOut("updating peer: [%s] latency = %f\n", p.ID.Pretty(), p.GetLatency().Seconds())
+	log.Debug("updating peer: [%s] latency = %f\n", p.ID.Pretty(), p.GetLatency().Seconds())
 	removedCount := 0
 	for _, route := range dht.routingTables {
 		removed := route.Update(p)
@@ -404,7 +404,7 @@ func (dht *IpfsDHT) addProviders(key u.Key, peers []*Message_Peer) []*peer.Peer
 			continue
 		}
 
-		u.DOut("[%s] adding provider: %s for %s", dht.self.ID.Pretty(), p, key)
+		log.Debug("[%s] adding provider: %s for %s", dht.self.ID.Pretty(), p, key)
 
 		// Dont add outselves to the list
 		if p.ID.Equal(dht.self.ID) {
@@ -439,7 +439,7 @@ func (dht *IpfsDHT) betterPeerToQuery(pmes *Message) *peer.Peer {
 
 	// == to self? nil
 	if closer.ID.Equal(dht.self.ID) {
-		u.DOut("Attempted to return self! this shouldnt happen...\n")
+		log.Error("Attempted to return self! this shouldnt happen...")
 		return nil
 	}
 

routing/dht/routing.go

@@ -86,7 +86,7 @@ func (dht *IpfsDHT) GetValue(ctx context.Context, key u.Key) ([]byte, error) {
 		return nil, err
 	}
 
-	u.DOut("[%s] GetValue %v %v\n", dht.self.ID.Pretty(), key, result.value)
+	log.Debug("GetValue %v %v", key, result.value)
 	if result.value == nil {
 		return nil, u.ErrNotFound
 	}
@@ -189,7 +189,7 @@ func (dht *IpfsDHT) addPeerListAsync(k u.Key, peers []*Message_Peer, ps *peerSet
 // FindProviders searches for peers who can provide the value for given key.
 func (dht *IpfsDHT) FindProviders(ctx context.Context, key u.Key) ([]*peer.Peer, error) {
 	// get closest peer
-	u.DOut("Find providers for: '%s'\n", key.Pretty())
+	log.Debug("Find providers for: '%s'", key.Pretty())
 	p := dht.routingTables[0].NearestPeer(kb.ConvertKey(key))
 	if p == nil {
 		return nil, nil
@@ -333,17 +333,17 @@ func (dht *IpfsDHT) findPeerMultiple(ctx context.Context, id peer.ID) (*peer.Pee
 // Ping a peer, log the time it took
 func (dht *IpfsDHT) Ping(ctx context.Context, p *peer.Peer) error {
 	// Thoughts: maybe this should accept an ID and do a peer lookup?
-	u.DOut("[%s] ping %s start\n", dht.self.ID.Pretty(), p.ID.Pretty())
+	log.Info("ping %s start", p.ID.Pretty())
 
 	pmes := newMessage(Message_PING, "", 0)
 	_, err := dht.sendRequest(ctx, p, pmes)
-	u.DOut("[%s] ping %s end (err = %s)\n", dht.self.ID.Pretty(), p.ID.Pretty(), err)
+	log.Info("ping %s end (err = %s)", p.ID.Pretty(), err)
 	return err
 }
 
 func (dht *IpfsDHT) getDiagnostic(ctx context.Context) ([]*diagInfo, error) {
 
-	u.DOut("Begin Diagnostic")
+	log.Info("Begin Diagnostic")
 	peers := dht.routingTables[0].NearestPeers(kb.ConvertPeerID(dht.self.ID), 10)
 	var out []*diagInfo
 

util/util.go

@@ -14,7 +14,7 @@ import (
 	"github.com/op/go-logging"
 )
 
-var format = "%{color}%{time} %{shortfile} %{level}: %{color:reset}%{message}"
+var format = "%{color}%{time:01-02 15:04:05.9999} %{shortfile} %{level}: %{color:reset}%{message}"
 
 func init() {
 	backend := logging.NewLogBackend(os.Stderr, "", 0)