Global timeout not firing on 3.2.1 #517

Closed
nfantone opened this Issue Aug 31, 2016 · 28 comments

Projects

None yet

4 participants

@nfantone
Contributor
nfantone commented Aug 31, 2016 edited

@mcdonnelldean Hi, guys! So, today @vigneshnrfs opened an issue over at seneca-amqp-transport explaining that his actions weren't timeoutting using latest Seneca release 3.0.0, but were doing fine in 2.1.0. It turned out he was (is) absolutely right.

I investigated a little bit and found out that some work has been done on this. Like doubling the default timeout value. Has any of the API changed regarding this? Would you have any ideas on why no TIMEOUT errors are being thrown on Seneca 3.0.0? Maybe I need to update something on the transport logic?

Thanks!

@nfantone nfantone referenced this issue in senecajs/seneca-amqp-transport Aug 31, 2016
Closed

timeout error not happening in node v6 #48

@mcdonnelldean
Member

@nfantone Good spot, I'll have a look over this as soon as I can and see. There should be no api changes around this.

@nfantone
Contributor
nfantone commented Aug 31, 2016 edited

Many thanks, @mcdonnelldean. You can find steps to repro this issue at this comment here.

@mcdonnelldean
Member

@nfantone I think we have it cracked in 3.2.0 releasing shortly.

@nfantone
Contributor

Sweet! I'll wait till then.

@mcdonnelldean
Member

Just pushed it about an hour ago 😁

On 27 Sep 2016 5:33 p.m., Nicolás Fantone notifications@github.com wrote:

Sweet! I'll wait till then.


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://github.com/senecajs/seneca/issues/517#issuecomment-249920540, or mute the threadhttps://github.com/notifications/unsubscribe-auth/ADdT6V7RNxKPd4cC7wikuKEEqV0dvKjKks5quUU-gaJpZM4Jxgl_.

@nfantone
Contributor

@mcdonnelldean Sadly, this is still happening on 3.2.1. Have you had a chance to test this..? Or you were just hoping it'd be solved? 😛

@nfantone nfantone changed the title from Global timeout not firing on 3.0.0 to Global timeout not firing on 3.2.1 Sep 27, 2016
@nfantone
Contributor

@mcdonnelldean Weird thing is I can't reproduce this using plain http as transport:

'use strict'

var Seneca = require('seneca')

function timeoutter () {
  this.add('cmd:run', (msg, done) => {
    // Don't call the callback: force a timeout
    // return done(null, {tag: 'timeoutter'})
  })
}

function handler (err, reply) {
  console.log(err, reply)
}

Seneca()
  .use(timeoutter)
  .listen({type: 'http', port: '8260', pin: 'cmd:*'})
  .act('cmd:run', handler)

This will correctly timeout after 22s.

{"kind":"notice","notice":"seneca started","level":"info","when":1475008945715}
(node:1515) DeprecationWarning: 'root' is deprecated, use 'global'


{"notice":"seneca: Action cmd:run failed: [TIMEOUT].","code":"act_execute","err":{"eraro":true,"orig":{},"code":"act_execute","seneca":true,"package":"seneca","msg":"seneca: Action cmd:run failed: [TIMEOUT].","details":{"message":"[TIMEOUT]","pattern":"cmd:run","instance":"Seneca/1p2k1p1aa6xg/1475008945649/1515/3.2.1/-","orig$":{},"message$":"[TIMEOUT]","plugin":{}},"callpoint":"at Object.act_tm [
# ...
@nfantone
Contributor
nfantone commented Sep 27, 2016 edited

All right, now I ended up getting a timeout, even on AMQP, by just adding:

  .use('amqp-transport')
  .listen({type: 'amqp', url: process.env.AMQP_URL, pin: 'cmd:*'})

Original reported issue still occurs, though. But this is promising. I'm diggin further.

@nfantone
Contributor

@mcdonnelldean Ok, spotted the difference. The original issue declares a client with no listener, whereas the example I've provided in my previous comment, listener is configured but it doesn't reply.

AFAIK, this is not reproducible using http as transport, since connection will fail almost immediately with an ECONNREFUSED error. But it is with AMQP, given its async nature.

So long story short: this is still a bug in 3.2.1 and it didn't happen on 2.1.0. Thoughts?

@paolochiodi paolochiodi referenced this issue in senecajs/gate-executor Oct 12, 2016
Open

timeout bug #16

@paolochiodi
Contributor

I think this is a problem with the updated gate-executor not respecting timeouts, causing most of the actions in seneca to never timeout, see senecajs/gate-executor#16

@nfantone
Contributor
nfantone commented Oct 12, 2016 edited

@paolochiodi Good catch. If you need any help, let me know.

And if it tells you anything, I've found out that it doesn't seem to be consistent. Sometimes, actions just hang, other they do timeout. Couldn't figure out a clear pattern, though.

@paolochiodi
Contributor

@nfantone I've submitted a PR with a possible solution to the problem, @rjrodger should review it.

About the inconsistent behaviour, I think it depends on how and when the action execution is inserted into the gate-executor.
If this happen before start is called on the gate, or this is the first action the timeout will work correctly.
Following actions won't.

I've tested your use case on amqp with the updated gate-executor and it seems to work correctly.
Let's try it again when it is officially released.

@nfantone
Contributor

@paolochiodi Very nice. Let's wait on @rjrodger for the review. Glad to see someone actively working on this.

@rjrodger rjrodger closed this in d56deb0 Oct 25, 2016
@nfantone
Contributor
nfantone commented Oct 25, 2016 edited

@paolochiodi and @rjrodger Tried this again with 3.2.2 and it's still not working. Timeout just doesn't happen.

Could we review this, please? Try and run the examples on seneca-amqp-transport and see if it's working for you.

cd seneca-amqp-transport
AMQP_URL=amqp://guest:guest@localhost:5672 node examples/client.js
{"kind":"notice","notice":"hello seneca ri8ryoqrb8l8/1477424664741/2857/3.2.2/-","level":"info","when":1477424664806}

It just hangs there.

@nfantone
Contributor
@paolochiodi
Contributor

@nfantone sure, I'll double check this

@paolochiodi
Contributor

Just checked, and it works for me (default timeout is ~ 22 seconds).
Can you try to set the timeout explicitly to a lower value, i.e. 100, and see what happen?
It should timeout almost immediately.

@nfantone
Contributor

Um... already did: was the first thing I tried. Nothing. examples/client.js just runs forever with no output.

#!/usr/bin/env node
'use strict';

var client = require('seneca')({ timeout: 100 })
  .use('..')
  .client({
    type: 'amqp',
    pin: 'cmd:log',
    url: process.env.AMQP_URL
  });

setInterval(function() {
  client.act('cmd:log', {
    message: 'Hello from seneca client over AMQP'
  });
}, 2000);

@paolochiodi Did you rm -rf node_modules && npm i before trying? Are you on node@6.9.1?

@paolochiodi
Contributor

Uhm, weird.
Yes, I deleted node_modules - I'm currently on node@6.2.0

The other difference that may be present is that I tried without an actual amqp instance running.
There may be a chance that with a server in place for some reason the timeout is reset - but this seems unlikely.

I'll try with amqp in place and updating node

@nfantone
Contributor
nfantone commented Oct 25, 2016 edited

@paolochiodi All right. And how exactly were you running the microservices, then? If you don't have a running broker, script will fail immediately with a connect ECONNREFUSED 127.0.0.1:5672 error - which is not a timeout failure.

@paolochiodi
Contributor

@nfantone Sorry, you're right: I actually have an instance of rabbitmq running.

Seem even more strange.
Just to check the obvious:

  • you're on branch develop for seneca-amqp-transport (but have updated package.json to use seneca 3.2.2)
  • in node_modules you have seneca 3.2.2 and gate-executor 1.1.1
  • using node 6.9.1
  • not configuration to hide logs
  • whatever time you wait for, you don't get the timeout

If you have time now, we can have a chat on the seneca gitter around this (I've 10-15 minutes free) or we can keep this async

@nfantone
Contributor

My bad. This is now working as expected. Issue was due to a missing callback on .act. If you don't declare one, all errors are swallowed.

@paolochiodi
Contributor

@rjrodger is that ☝️ the intended behaviour?

@nfantone
Contributor
nfantone commented Oct 25, 2016 edited

To be clear, this will timeout and log the exception:

  client.act('cmd:salute', { name: 'World' }, (err, res) => {
    if (err) {
      throw err;
    }
    console.log(res);
  });

This won't do anything (or, at least, appears like so):

  client.act('cmd:salute', { name: 'World' });
@paolochiodi
Contributor

@nfantone just for clarity: I was checking seneca today and noticed that even if there's no callback the timeout is still fired and that will trigger the generic "error" handler

client.error(function (err) {
     console.log(err)
})
 client.act('cmd:salute', { name: 'World' });
@nfantone
Contributor
nfantone commented Nov 3, 2016

But if you have none of that, errors will get swallowed, right? That's to be expected.

@josephbisaillon

was this ever resolved for amqp?

@nfantone
Contributor

@josephbisaillon It was never AMQP specific, but rather a general Seneca issue. And yes, it was resolved by the time the issue was closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment