From 54142b2173e07c493659bd280420360cbe87284c Mon Sep 17 00:00:00 2001 From: Jeromy Date: Sun, 28 Sep 2014 00:13:07 -0700 Subject: [PATCH] update logging in multiple packages --- blockservice/blockservice.go | 15 +++++---- fuse/ipns/ipns_unix.go | 56 ++++++++++++++++++++++++++++------ fuse/readonly/readonly_unix.go | 17 ++++++----- routing/dht/dht.go | 30 +++++++++--------- routing/dht/routing.go | 10 +++--- util/util.go | 2 +- 6 files changed, 85 insertions(+), 45 deletions(-) diff --git a/blockservice/blockservice.go b/blockservice/blockservice.go index 1fbbfcb44..51a6e0014 100644 --- a/blockservice/blockservice.go +++ b/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 } } diff --git a/fuse/ipns/ipns_unix.go b/fuse/ipns/ipns_unix.go index 7c24f716c..b15ee11e9 100644 --- a/fuse/ipns/ipns_unix.go +++ b/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: + } +} diff --git a/fuse/readonly/readonly_unix.go b/fuse/readonly/readonly_unix.go index 54eac2bbc..1fa7bfb0d 100644 --- a/fuse/readonly/readonly_unix.go +++ b/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 { diff --git a/routing/dht/dht.go b/routing/dht/dht.go index f9f52b108..4e844ecd6 100644 --- a/routing/dht/dht.go +++ b/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 } diff --git a/routing/dht/routing.go b/routing/dht/routing.go index c1b85cefa..d1f50afb8 100644 --- a/routing/dht/routing.go +++ b/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 diff --git a/util/util.go b/util/util.go index f2ce35a34..b33960471 100644 --- a/util/util.go +++ b/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)