refactor(pinmfs): log error if pre-existing pin failed (#8056)
* pinmfs: log error if pin failed * refactor: log pre-existing remote mfs pins This cleans up debug logging and ensures we use %q for data read from remote services. We log pre-existing pins for MFS root and print ERROR if pin for current root has status "failed", otherwise, we log to debug. Co-authored-by: Marcin Rataj <lidel@lidel.org> (cherry picked from commit 075cc8f35674bb30388faa7a3e73099a649cecf6)
Bogdan Stirbat committed
May 17, 2021 at 19:13 UTC
7881e518d6ea49065cae6aaf5b8e100f22ff3731
2 files changed
+22
-16
cmd/ipfs/pinmfs.go
+20
-14
@@ -138,9 +138,9 @@ func pinAllMFS(ctx context.Context, node pinMFSNode, cfg *config.Config, rootCid
138
for svcName_, svcConfig_ := range cfg.Pinning.RemoteServices {
139
// skip services where MFS is not enabled
140
svcName, svcConfig := svcName_, svcConfig_
141
- mfslog.Debugf("pinning considering service %s for mfs pinning", svcName)
141
+ mfslog.Debugf("pinning MFS root considering service %q", svcName)
142
if !svcConfig.Policies.MFS.Enable {
143
- mfslog.Debugf("pinning service %s is not enabled", svcName)
143
+ mfslog.Debugf("pinning service %q is not enabled", svcName)
144
ch <- lastPin{}
145
continue
146
}
@@ -153,7 +153,7 @@ func pinAllMFS(ctx context.Context, node pinMFSNode, cfg *config.Config, rootCid
153
repinInterval, err = time.ParseDuration(svcConfig.Policies.MFS.RepinInterval)
154
if err != nil {
155
select {
156
- case errCh <- fmt.Errorf("remote pinning service %s has invalid MFS.RepinInterval (%v)", svcName, err):
156
+ case errCh <- fmt.Errorf("remote pinning service %q has invalid MFS.RepinInterval (%v)", svcName, err):
157
case <-ctx.Done():
158
}
159
ch <- lastPin{}
@@ -165,20 +165,20 @@ func pinAllMFS(ctx context.Context, node pinMFSNode, cfg *config.Config, rootCid
165
if last, ok := lastPins[svcName]; ok {
166
if last.ServiceConfig == svcConfig && (last.CID == rootCid || time.Since(last.Time) < repinInterval) {
167
if last.CID == rootCid {
168
- mfslog.Debugf("pinning MFS root to %s: pin for %s exists since %s, skipping", svcName, rootCid, last.Time.String())
168
+ mfslog.Debugf("pinning MFS root to %q: pin for %q exists since %s, skipping", svcName, rootCid, last.Time.String())
169
} else {
170
- mfslog.Debugf("pinning MFS root to %s: skipped due to MFS.RepinInterval=%s (remaining: %s)", svcName, repinInterval.String(), (repinInterval - time.Since(last.Time)).String())
170
+ mfslog.Debugf("pinning MFS root to %q: skipped due to MFS.RepinInterval=%s (remaining: %s)", svcName, repinInterval.String(), (repinInterval - time.Since(last.Time)).String())
171
}
172
ch <- lastPin{}
173
continue
174
}
175
}
176
177
- mfslog.Debugf("pinning MFS root %s to %s", rootCid, svcName)
177
+ mfslog.Debugf("pinning MFS root %q to %q", rootCid, svcName)
178
go func() {
179
if r, err := pinMFS(ctx, node, rootCid, svcName, svcConfig); err != nil {
180
select {
181
- case errCh <- fmt.Errorf("pinning MFS root %s to %s (%v)", rootCid, svcName, err):
181
+ case errCh <- fmt.Errorf("pinning MFS root %q to %q (%v)", rootCid, svcName, err):
182
case <-ctx.Done():
183
}
184
ch <- lastPin{}
@@ -212,12 +212,18 @@ func pinMFS(
212
pinStatuses := []pinclient.Status{pinclient.StatusQueued, pinclient.StatusPinning, pinclient.StatusPinned, pinclient.StatusFailed}
213
lsPinCh, lsErrCh := c.Ls(ctx, pinclient.PinOpts.FilterName(pinName), pinclient.PinOpts.FilterStatus(pinStatuses...))
214
existingRequestID := "" // is there any pre-existing MFS pin with pinName (for any CID)?
215
- alreadyPinned := false // is CID for current MFS already pinned?
215
+ pinning := false // is CID for current MFS already being pinned?
216
pinTime := time.Now().UTC()
217
+ pinStatusMsg := "pinning to %q: received pre-existing %q status for %q (requestid=%q)"
218
for ps := range lsPinCh {
219
existingRequestID = ps.GetRequestId()
220
+ if ps.GetPin().GetCid() == cid && ps.GetStatus() == pinclient.StatusFailed {
221
+ mfslog.Errorf(pinStatusMsg, svcName, pinclient.StatusFailed, cid, existingRequestID)
222
+ } else {
223
+ mfslog.Debugf(pinStatusMsg, svcName, ps.GetStatus(), ps.GetPin().GetCid(), existingRequestID)
224
+ }
225
if ps.GetPin().GetCid() == cid && ps.GetStatus() != pinclient.StatusFailed {
220
- alreadyPinned = true
226
+ pinning = true
227
pinTime = ps.GetCreated().UTC()
228
break
229
}
@@ -228,9 +234,9 @@ func pinMFS(
234
return lastPin{}, fmt.Errorf("error while listing remote pins: %v", err)
235
}
236
231
- // CID of the current MFS root is already pinned, nothing to do
232
- if alreadyPinned {
233
- mfslog.Debugf("pinning MFS to %s: pin for %s exists since %s, skipping", svcName, cid, pinTime.String())
237
+ // CID of the current MFS root is already being pinned, nothing to do
238
+ if pinning {
239
+ mfslog.Debugf("pinning MFS to %q: pin for %q exists since %s, skipping", svcName, cid, pinTime.String())
240
return lastPin{Time: pinTime, ServiceName: svcName, ServiceConfig: svcConfig, CID: cid}, nil
241
}
242
@@ -250,13 +256,13 @@ func pinMFS(
256
257
// Create or replace pin for MFS root
258
if existingRequestID != "" {
253
- mfslog.Debugf("pinning to %s: replacing existing MFS root pin with %s", svcName, cid)
259
+ mfslog.Debugf("pinning to %q: replacing existing MFS root pin with %q", svcName, cid)
260
_, err := c.Replace(ctx, existingRequestID, cid, addOpts...)
261
if err != nil {
262
return lastPin{}, err
263
}
264
} else {
259
- mfslog.Debugf("pinning to %s: creating a new MFS root pin for %s", svcName, cid)
265
+ mfslog.Debugf("pinning to %q: creating a new MFS root pin for %q", svcName, cid)
266
_, err := c.Add(ctx, cid, addOpts...)
267
if err != nil {
268
return lastPin{}, err
cmd/ipfs/pinmfs_test.go
+2
-2
@@ -9,7 +9,7 @@ import (
9
10
config "github.com/ipfs/go-ipfs-config"
11
ipld "github.com/ipfs/go-ipld-format"
12
- "github.com/ipfs/go-merkledag"
12
+ merkledag "github.com/ipfs/go-merkledag"
13
"github.com/libp2p/go-libp2p-core/host"
14
peer "github.com/libp2p/go-libp2p-core/peer"
15
)
@@ -149,7 +149,7 @@ func TestPinMFSService(t *testing.T) {
149
},
150
},
151
}
152
- testPinMFSServiceWithError(t, cfg_invalid_interval, "remote pinning service invalid_interval has invalid MFS.RepinInterval")
152
+ testPinMFSServiceWithError(t, cfg_invalid_interval, "remote pinning service \"invalid_interval\" has invalid MFS.RepinInterval")
153
testPinMFSServiceWithError(t, cfg_valid_unnamed, "error while listing remote pins: empty response from remote pinning service")
154
testPinMFSServiceWithError(t, cfg_valid_named, "error while listing remote pins: empty response from remote pinning service")
155
}