Logging non-fatal async errors

[btc]

I wish to propose a pattern for logging the non-fatal errors that occur in asynchronous operations.

Context exposes an error logging method:

func (ctx *u.IPFSContext) LogError(err error) {
// may be implemented synchronously
}

The interface extends the golang Context:

type IPFSContext interface {
  context.Context
  LogError(err error)
}

Now async actors can get information back out to parent without modifying control flow or confusing the caller/callee contract!

func asyncWork(ctx u.IPFSContext, in <-chan rawData) {
  for raw := <- in {
    val, err := transform(raw)
    if err != nil {
      ctx.LogError(err)
      continue
    }
    doThingsWith(val)
  }
}

the context creator can listen for errors:

func (ctx *context.IPFSContext) Errs() <-chan error {
  // return a channel of errors
}

The pattern is analogous to the way children listen on Done()

  ctx := context.New(context.Background())
  go asyncWork(ctx, ch)
  for {
    select {
      case err <-ctx.Errs():
        u.DOut(err)
    }
  }

Thoughts? @jbenet @whyrusleeping

[jbenet]

@perfmode i like it. a lot. that way the callee can decide too whether/when to cancel via ctx.

Can we implement the retrieval of Errs over the context Value? that way the IPFSContext is just a context + an additional interface.

[btc]

Can we implement the retrieval of Errs over the context Value? that way the IPFSContext is just a context + an additional interface.

Great idea. I think we can use the setters and getters on the default context to accomplish this!

[btc]

I'm going to hack something together real quick and report back with progress.

[whyrusleeping]

I really like the idea of tying logging to a context. If we can add different levels of logging to this interface as well I would be quite happy

[btc]

I really like the idea of tying logging to a context. If we can add different levels of logging to this interface as well I would be quite happy

What levels do you have in mind?

[whyrusleeping]

Traditionally I like trace, info warn and error.

[whyrusleeping]

(I know that's slightly out of the range of logging errors though)

[jbenet]

Yeah, maybe we can have both errors and broader logging on it.

// given some Logger we decide to use, add it to the context and then:

type IpfsContext interface {
  context.Context
  Errs() chan error
  Logger() *Logger
}

// send an error:
ctx.Errs()<- err
// or, as btc suggested above
ctx.Error(err)

// get the logger:
ctx.Logger().Errorf("There was an error: %v", err)
ctx.Logger().Warning("Just what do you think you're doing, Dave?")

[jbenet]

We should use a logger that has both:

{Info, Warn, Error, ...}{,f}(...)

where Af() does fmt for you.

[btc]

@jbenet definitely prefer a synchronous interface (even if implemented with buffered channel)

Re: logger... The context can embed a logger like so:

type IpfsContext interface {
  context.Context
  Error(error)
  Logger
}

Because the caller may use the error to modify control flow, it's important to keep the error reporting and general logging separate (even if the error is also logged).

Mmm. How about this interface then.

func (ctx *u.IPFSContext) LogError(lvl LogLevel, err error) {
}

[jbenet]

definitely prefer a synchronous interface (even if implemented with buffered channel)

👍

The context can embed a logger like so:

Don't think you can add variables into the interface-- oh the Logger is an interface itself.

How about this interface then.

👎 on LogLevel that always gets really messy. The explicit different functions are not many and are nicer to use, i think

[whyrusleeping]

Agreed on explicit functions.

[btc]

SGTM. I'm going to punt on logging (at first). Will implement error
handling portion and submit for review.

[whyrusleeping]

As a side note to this. I really want to start using contexts everywhere.

[jbenet]

[btc]

use case: parent neglects child

Parent (caller) is not interested in errors.

so: Errors reported by child (async actor) should go to /dev/null.

use case: parent is late

Parent (caller) starts listening to errors some time after dispatching the goroutine.

so: Errors received up until that point should be buffered.

challenge: never block the child

In both cases, it is desirable to uphold a contract that the child will never be blocked on error logging. Violation of this contract introduces potentially tricky deadlock issues.

implementation non-options

Due to constraints imposed by the neglected use case, at the time of instantiation of the context, the context must be informed that the parent never intends to retrieve errors. Otherwise we are forced to choose between:

If the parent has not yet decided to start listening on the channel, we can do a few different things once the child starts logging errors:

a. let errors accumulate in a buffer, blocking the child (violates contract)
b. drop them on the floor (can't allow this. parent might be late)
c. errors are collected by a mediator in a goroutine. the mediator accepts values from child and forwards them to parent, potentially allowing them to accumulate in a slice. This is a complex implementation which introduces potential resource leakage. Note that there is no way to garbage-collect the mediator without changing the Context's contract.

edit: A finalizer can be used to perform garbage collection in the case of option c.

http://golang.org/pkg/runtime/#SetFinalizer

potential solution

This can be solved by having default behavior where the client can log errors but they go to /dev/null.

If the parent is actually interested in receiving the errors, it can instantiate a context with error reporting like so:

ctx, errs := context.WithErrorLog(ctx)

This is in the same style as the golang Context factory methods:

context.WithCancel(...)
context.WithDeadline(...)
context.WithTimeout(...)

RFC

@jbenet @whyrusleeping @mappum

I believe this is a sensible solution to the problem. If you have any thoughts on the matter, I would love to hear them.

[whyrusleeping]

I don't believe that errors should ever be sent to /dev/null (or equivalent). All information is useful. If an error is expected, it should be checked and handled explicitly.

[btc]

Perhaps the term /dev/null was misleading. To clarify: I merely mean to call attention to cases where parents aren't interested in doing anything with the errors reported by the child.

Perhaps there's a way to force parents to acknowledge errors, but it's dangerous to block children when their reported errors are ignored.

[jbenet]

@perfmode understand the constraints. I think though that the intuition is right. Should by default silence errors that the child goroutine thinks may be being heard. Silencing should be explicit. Parent should only be able to neglect by doing so explicitly like:

func silenceErrors(ctx) {
  for {
    select {
    case <-ctx.Errs(): // discard error.
    case <-ctx.Done():
      return 
    }
  }
}

go doSomething(ctx)
go silenceErrors(ctx)

I think it's fine if the child ends up blocking if the parent doesn't consume the errors.

[jbenet]

@perfmode btw there is some complexity to be considered when it's not just parent -> child, but there's a whole tree in between, with potentially many children at different levels logging.

[jbenet]

on that last point, i think it should work symmetrical to Done. i.e. calling:

ctx2, errs := context.WithErrorLog(ctx1)

captures all errors from ctx2 and downward into errs, but they don't leak up into ctx1

[btc]

Thanks for the feedback guys! Contexts are about the go from good to great! Looking forward to integrating logging functionality.

context.WithErrorLog(...) is implemented and the PR is ready for review. Please have a look at:

#68

---

@jbenet re: error notifications not leaking up tree. I agree. Implemented and tested.

https://github.com/jbenet/go-ipfs/blob/ipfs-context/util/context/context_test.go#L34

@whyrusleeping I agree it's best to explicitly handle errors generated by children. Implemented WithErrorLog so that parents are required to acknowledge the errors of their descendants.

@perfmode understand the constraints. I think though that the intuition is right. Should by default silence errors that the child goroutine thinks may be being heard. Silencing should be explicit.

@jbenet It's not clear to me what you mean here. Despite not being able to parse these statements, I think we're actually on the same page. If, in the implementation, I missed the point you're making, please let me know.

[whyrusleeping]

@jbenet @perfmode Would you two say this one is closed?

[jbenet]

I think we still need to go through and replace some output with calling logger.—
Sent from Mailbox

On Sun, Oct 5, 2014 at 7:58 PM, Jeromy Johnson notifications@github.com
wrote:

@jbenet @perfmode Would you two say this one is closed?

Reply to this email directly or view it on GitHub:
#66 (comment)