Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

refactor(pinmfs): log error if pre-existing pin failed #8056

Merged
merged 2 commits into from
May 17, 2021
Merged

refactor(pinmfs): log error if pre-existing pin failed #8056

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
98c3865
pinmfs: log error if pin failed
BogdanStirbat Apr 6, 2021
3b4c615
refactor: log pre-existing remote mfs pins
lidel Apr 23, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
34 changes: 20 additions & 14 deletions cmd/ipfs/pinmfs.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -138,9 +138,9 @@ func pinAllMFS(ctx context.Context, node pinMFSNode, cfg *config.Config, rootCid
for svcName_, svcConfig_ := range cfg.Pinning.RemoteServices {
// skip services where MFS is not enabled
svcName, svcConfig := svcName_, svcConfig_
mfslog.Debugf("pinning considering service %s for mfs pinning", svcName)
mfslog.Debugf("pinning MFS root considering service %q", svcName)
if !svcConfig.Policies.MFS.Enable {
mfslog.Debugf("pinning service %s is not enabled", svcName)
mfslog.Debugf("pinning service %q is not enabled", svcName)
ch <- lastPin{}
continue
}
Expand All @@ -153,7 +153,7 @@ func pinAllMFS(ctx context.Context, node pinMFSNode, cfg *config.Config, rootCid
repinInterval, err = time.ParseDuration(svcConfig.Policies.MFS.RepinInterval)
if err != nil {
select {
case errCh <- fmt.Errorf("remote pinning service %s has invalid MFS.RepinInterval (%v)", svcName, err):
case errCh <- fmt.Errorf("remote pinning service %q has invalid MFS.RepinInterval (%v)", svcName, err):
case <-ctx.Done():
}
ch <- lastPin{}
Expand All @@ -165,20 +165,20 @@ func pinAllMFS(ctx context.Context, node pinMFSNode, cfg *config.Config, rootCid
if last, ok := lastPins[svcName]; ok {
if last.ServiceConfig == svcConfig && (last.CID == rootCid || time.Since(last.Time) < repinInterval) {
if last.CID == rootCid {
mfslog.Debugf("pinning MFS root to %s: pin for %s exists since %s, skipping", svcName, rootCid, last.Time.String())
mfslog.Debugf("pinning MFS root to %q: pin for %q exists since %s, skipping", svcName, rootCid, last.Time.String())
} else {
mfslog.Debugf("pinning MFS root to %s: skipped due to MFS.RepinInterval=%s (remaining: %s)", svcName, repinInterval.String(), (repinInterval - time.Since(last.Time)).String())
mfslog.Debugf("pinning MFS root to %q: skipped due to MFS.RepinInterval=%s (remaining: %s)", svcName, repinInterval.String(), (repinInterval - time.Since(last.Time)).String())
}
ch <- lastPin{}
continue
}
}

mfslog.Debugf("pinning MFS root %s to %s", rootCid, svcName)
mfslog.Debugf("pinning MFS root %q to %q", rootCid, svcName)
go func() {
if r, err := pinMFS(ctx, node, rootCid, svcName, svcConfig); err != nil {
select {
case errCh <- fmt.Errorf("pinning MFS root %s to %s (%v)", rootCid, svcName, err):
case errCh <- fmt.Errorf("pinning MFS root %q to %q (%v)", rootCid, svcName, err):
case <-ctx.Done():
}
ch <- lastPin{}
Expand Down Expand Up @@ -212,12 +212,18 @@ func pinMFS(
pinStatuses := []pinclient.Status{pinclient.StatusQueued, pinclient.StatusPinning, pinclient.StatusPinned, pinclient.StatusFailed}
lsPinCh, lsErrCh := c.Ls(ctx, pinclient.PinOpts.FilterName(pinName), pinclient.PinOpts.FilterStatus(pinStatuses...))
existingRequestID := "" // is there any pre-existing MFS pin with pinName (for any CID)?
alreadyPinned := false // is CID for current MFS already pinned?
pinning := false // is CID for current MFS already being pinned?
pinTime := time.Now().UTC()
pinStatusMsg := "pinning to %q: received pre-existing %q status for %q (requestid=%q)"
for ps := range lsPinCh {
existingRequestID = ps.GetRequestId()
if ps.GetPin().GetCid() == cid && ps.GetStatus() == pinclient.StatusFailed {
mfslog.Errorf(pinStatusMsg, svcName, pinclient.StatusFailed, cid, existingRequestID)
} else {
mfslog.Debugf(pinStatusMsg, svcName, ps.GetStatus(), ps.GetPin().GetCid(), existingRequestID)
}
Comment on lines +220 to +224
Copy link
Member

@lidel lidel Apr 23, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the only real change in this PR, everything else is just my opportunistic cleanup of already existing debug logs :)

👉 error log level is used only when failure is for the current MFS root CID, everything else is logged to debug:

2021-04-23--23-24-06

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't this a bit awkward since if your node is offline and you start mutating MFS your log will fill up with errors?

Copy link
Member

@lidel lidel May 17, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, pinning is lazy atm, so service will return queued status and then try to pin it for some time (eg. Pinata won't return failed until N hours passed without any new bytes found).

In practice, the ERROR added in this PR is only printed once, when you restart node.
Main value here is improved logs when ipfs log level remotepinning/mfs debug is set.

if ps.GetPin().GetCid() == cid && ps.GetStatus() != pinclient.StatusFailed {
alreadyPinned = true
pinning = true
pinTime = ps.GetCreated().UTC()
break
}
Expand All @@ -228,9 +234,9 @@ func pinMFS(
return lastPin{}, fmt.Errorf("error while listing remote pins: %v", err)
}

// CID of the current MFS root is already pinned, nothing to do
if alreadyPinned {
mfslog.Debugf("pinning MFS to %s: pin for %s exists since %s, skipping", svcName, cid, pinTime.String())
// CID of the current MFS root is already being pinned, nothing to do
if pinning {
mfslog.Debugf("pinning MFS to %q: pin for %q exists since %s, skipping", svcName, cid, pinTime.String())
return lastPin{Time: pinTime, ServiceName: svcName, ServiceConfig: svcConfig, CID: cid}, nil
}

Expand All @@ -250,13 +256,13 @@ func pinMFS(

// Create or replace pin for MFS root
if existingRequestID != "" {
mfslog.Debugf("pinning to %s: replacing existing MFS root pin with %s", svcName, cid)
mfslog.Debugf("pinning to %q: replacing existing MFS root pin with %q", svcName, cid)
_, err := c.Replace(ctx, existingRequestID, cid, addOpts...)
if err != nil {
return lastPin{}, err
}
} else {
mfslog.Debugf("pinning to %s: creating a new MFS root pin for %s", svcName, cid)
mfslog.Debugf("pinning to %q: creating a new MFS root pin for %q", svcName, cid)
_, err := c.Add(ctx, cid, addOpts...)
if err != nil {
return lastPin{}, err
Expand Down
4 changes: 2 additions & 2 deletions cmd/ipfs/pinmfs_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ import (

config "github.com/ipfs/go-ipfs-config"
ipld "github.com/ipfs/go-ipld-format"
"github.com/ipfs/go-merkledag"
merkledag "github.com/ipfs/go-merkledag"
"github.com/libp2p/go-libp2p-core/host"
peer "github.com/libp2p/go-libp2p-core/peer"
)
Expand Down Expand Up @@ -149,7 +149,7 @@ func TestPinMFSService(t *testing.T) {
},
},
}
testPinMFSServiceWithError(t, cfg_invalid_interval, "remote pinning service invalid_interval has invalid MFS.RepinInterval")
testPinMFSServiceWithError(t, cfg_invalid_interval, "remote pinning service \"invalid_interval\" has invalid MFS.RepinInterval")
testPinMFSServiceWithError(t, cfg_valid_unnamed, "error while listing remote pins: empty response from remote pinning service")
testPinMFSServiceWithError(t, cfg_valid_named, "error while listing remote pins: empty response from remote pinning service")
}
Expand Down