Spawn callback can be called multiple times

[Mr0grog]

In #233, we created a new bug for in-process factories where the callback to factory.spawn() could be called multiple times. See the conversation at the end for an minimal test case and a solution by @dryajov.

[vasco-santos]

Thanks for creating this issue @Mr0grog, as well as @dryajov for the solution proposal!

I think you wanted to assign @hugomrdias instead of @fsdiogo 😛

[hugomrdias]

Yeah this is related to this ipfs/js-ipfs#1335 ill try to include a fix for this when this PR and dependencies are release.

[Mr0grog]

Oops, yes, sorry! 😬

[hugomrdias]

After reviewing this, i can't see the issue here this works exactly as its suppose to work. With just minor changes to repro this looks much better :)

'use strict'

const IPFSFactory = require('.')
const factory = IPFSFactory.create({type: 'proc', exec: require('ipfs')})

factory.spawn({disposable: true}, (error, daemon) => {
  // This callback should only ever execute once, but instead, it’s about to happen twice.
  if (error) {
    return console.error(error)
  }
  console.log('Daemon spawned!')

  // Do an operation, just to make sure we're working
  daemon.api.id((error, id) => {
    if (error) {
      console.error('Could not get ID!')
    } else {
      console.log('Daemon ID:', id.id)
    }

    // Do something to make stopping fail (this is arbitrary, but let's say
    // anything *could* happen to put the daemon in a bad state)
    daemon.exec._repo.close(error => {
      console.log('Repo prematurely closed')
      if (error) {
        console.error(error)
      }
      // And finally, stop the daemon
      console.log('Stopping daemon...')
      daemon.stop()
    })
  })
})

you get

Swarm listening on /ip4/127.0.0.1/tcp/50290/ipfs/Qmaxs2uAjvos5ZaQoDEb1WsZHg7k6YRNsNYrtz9V72x6Zj
Daemon spawned!
Daemon ID: Qmaxs2uAjvos5ZaQoDEb1WsZHg7k6YRNsNYrtz9V72x6Zj
Repo prematurely closed
Stopping daemon...
Error: repo is already closed
    at IpfsRepo.close (/Users/hugomrdias/code/js-ipfsd-ctl/node_modules/ipfs-repo/src/index.js:235:23)
    at series (/Users/hugomrdias/code/js-ipfs/src/core/components/stop.js:36:26)
    at /Users/hugomrdias/code/js-ipfs/node_modules/async/internal/parallel.js:31:39
    at replenish (/Users/hugomrdias/code/js-ipfs/node_modules/async/internal/eachOfLimit.js:64:17)
    at iterateeCallback (/Users/hugomrdias/code/js-ipfs/node_modules/async/internal/eachOfLimit.js:49:17)
    at /Users/hugomrdias/code/js-ipfs/node_modules/async/internal/onlyOnce.js:12:16
    at /Users/hugomrdias/code/js-ipfs/node_modules/async/internal/parallel.js:36:13
    at series (/Users/hugomrdias/code/js-ipfs/node_modules/libp2p/src/index.js:224:7)
    at /Users/hugomrdias/code/js-ipfs/node_modules/async/internal/parallel.js:39:9
    at /Users/hugomrdias/code/js-ipfs/node_modules/async/internal/once.js:12:16

At least now we don't have hidden errors, and we can handle and propagate them as we want!

[Mr0grog]

@hugomrdias the log line:

Error: repo is already closed
    [stack trace]

Is coming from the second call of the spawn handler, which should not be happening. That is the bug. (You got rid of the error handler I had for daemon.stop(), so you wouldn’t see the same expected output I posted.) It’d be more obvious if you kept the Spawn error: prefix in the logging call.

[dryajov]

I get a slightly different error, but triggered twice running against master

Error: invalid block
    at setImmediate (/Users/dryajov/personal/projects/ipfs/ipfs/js-ipfsd-ctl/node_modules/ipfs-repo/src/blockstore.js:90:20)
    at Immediate._onImmediate (/Users/dryajov/personal/projects/ipfs/ipfs/js-ipfsd-ctl/node_modules/async/internal/setImmediate.js:27:16)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)
Error: invalid block
    at setImmediate (/Users/dryajov/personal/projects/ipfs/ipfs/js-ipfsd-ctl/node_modules/ipfs-repo/src/blockstore.js:90:20)
    at Immediate._onImmediate (/Users/dryajov/personal/projects/ipfs/ipfs/js-ipfsd-ctl/node_modules/async/internal/setImmediate.js:27:16)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)

[hugomrdias]

Yes it should because the code forces an error inside the execution of the first call.

[Mr0grog]

Yes it should

What should do what? I’m not quite sure I’m following you here.

From my perspective, If I call:

factory.spawn({disposable: true}, (error, daemon) => {
  console.log('This line should run once and only once, ever.');

That spawn() callback should only ever happen once, no matter what. That’s pretty standard for any callback, and that’s the expectation we’re breaking. It’s not an event handler.

[hugomrdias]

(You got rid of the error handler I had for daemon.stop(), so you wouldn’t see the same expected output I posted.) It’d be more obvious if you kept the Spawn error: prefix in the logging call.

Its the same error, so we only handle at the top level.

That spawn() callback should only ever happen once, no matter what. That’s pretty standard for any callback, and that’s the expectation we’re breaking. It’s not an event handler.

I respectfully disagree if you force an error inside the first execution, i expect the callback to run again so i can handle the error or else propagation dies.

[Mr0grog]

I respectfully disagree if you force an error inside the first execution, i expect the callback to run again so i can handle the error or else propagation dies.

Ok, I think this might need some more input from others, then. To be perfectly honest, that expectation seems really surprising to me. I’m not sure I’m aware of any other system with completion callbacks like spawn’s that works this way (e.g. Node.js’s server.listen()).

I’m also not sure, for example, how a user should differentiate in that callback between a failed startup and a failed shutdown (as we are seeing in the example).

[dryajov]

@hugomrdias .spawn the callback to .spawn was written to be called only once, that was my original intent when I wrote it. It should not be called more than once even if there was an error. If the error needs to be captured, it has to be attached to the daemon passed to spawn once the callback returns. @Mr0grog assessment of this bug is correct.

[hugomrdias]

.spawn only runs once the callback runs twice.

[dryajov]

@hugomrdias I added a clarification to - #239 (comment)

For context, I was driving the original rewrite of this module - #176

[dryajov]

Here is a PR addressing this issue - #243

[vasco-santos]

Hey @Mr0grog @dryajov @hugomrdias

Error handling is a complex task and it is good that we are trying to get the best approach.

Personally, I don't see any problem in having callbacks executed more than once, since it is a common pattern in JS. The error is caught and the following code is not executed.

Taking into account the current flow, if the node does not start correctly, the callback is called with the error, which is ok. Moreover, if the node starts correctly and later it fails, the callback is called with the error, which should be propagated upwards the stack, in order to be handled.

In your PR @dryajov, more specifically here, I see a strange behavior that seems more like an hack. In my point of view, we should try to avoid this type of modifications, since they may be a potential source of confusion for other contributor, as well as future refactors. On the other side, in the callback approach, the code flow is more perceptible, and consequently less prone to future problems.

[dryajov]

@vasco-santos can you explain what's hacky about it? Also, can you provide examples when it's ok to use callbacks more than once and why?

[vasco-santos]

Removing a listener, because you know that it will be executed next is not a sound solution. But, we can receive more opinions here.

For instance, on the server side each time a http-server receives a request, the same callback is executed.

[dryajov]

Removing a listener, because you know that it will be executed next is not a sound solution. But, we can receive more opinions here.

Hmm. Not sure what you mean here. If you're talking about not catching errors, then once we execute the callback from spawn, it's the responsibility of the user to register an error handler on the returned ipfsd object.

For instance, on the server side each time a http-server receives a request, the same callback is executed.

Yeah, but you don't expect your callback to be called more than once for the same request?

[vasco-santos]

After discussing with @dryajov , we agreed that in spite of not being a good looking solution, we have to proceed with this change, in order to maintain consistency among all daemon types!
Thanks @dryajov

[Mr0grog]

I don't see any problem in having callbacks executed more than once, since it is a common pattern in JS… on the server side each time a http-server receives a request, the same callback is executed.

I think at least part of the problem here is vague language. Callback is a really broad term, and there are different kinds of callbacks. One classical distinction is by categorizing them into event handlers and completions/continuations. The way these two things are treated is different: completions or continuations only get called once — they represent the completion of a single operation (e.g. spawning a node, creating a server, creating a digest hash) and the continuation of a single line of logic. Can you complete a single operation more than once? No. Can you continue a single line of logic from the same place multiple times? Only if you’re talking about loops (e.g. map, reduce, forEach).

As for Node.js’s HTTP sever, you’ll note that the docs take pains to refer to the callback in question as a listener (called multiple times), not a callback. (http.get(), on the other hand, takes a callback, which is only called once.) They’re trying very hard to avoid this imprecise language and only use callback for things that are completions or continuations.

[daviddias]

Has this been fixed? Is there a test that reproduces the case?

[vasco-santos]

It has been fixed in PR 234. And a test is also added. I will close this issue.