client.act seems to fail when the input contains cmd: 'get' #375

Closed
heskew opened this Issue Mar 18, 2016 · 17 comments

Projects

None yet

7 participants

@heskew
heskew commented Mar 18, 2016

This behavior started with 1.4.0.

Repro:

'use strict';

const service = require('seneca')();

const inputs = [
    { cmd: 'create' },
    { cmd: 'get' },
    { role: 'test', cmd: 'get' },
    { ball: 'get' },
    { dog: 'get' },
    { thing: 'get' },
    { cmd: 'update' }
];

inputs.forEach((input) => {

    service.add(input, (args, respond) => {

        respond(null, { input });
    });
});

service.listen();

service.ready(function (err) {

    if (err) return;

    const client = require('seneca')().client();

    inputs.forEach((input) => {

        service.act(input, (err, result) => console.log(err  && `👎  (service.act) ${err}` || `👍  (service.act) ${JSON.stringify(result)}`));
        client.act(input, (err, result) => console.log(err  && `👎  (client.act) ${err}` || `👍  (client.act) ${JSON.stringify(result)}`));
    });

    setTimeout(() => service.close((err) => process.exit()), 1000);
});

Expected output (via 1.3.0):

2016-03-18T12:49:34.165Z nu8mey7bb8az/1458305374148/21387/- INFO    hello   Seneca/1.3.0/nu8mey7bb8az/1458305374148/21387/-
2016-03-18T12:49:34.451Z nu8mey7bb8az/1458305374148/21387/- INFO    listen
2016-03-18T12:49:34.539Z i0qppq7gufyj/1458305374536/21387/- INFO    hello   Seneca/1.3.0/i0qppq7gufyj/1458305374536/21387/-
2016-03-18T12:49:34.543Z i0qppq7gufyj/1458305374536/21387/- INFO    client
👍  (service.act) {"input":{"cmd":"create"}}
👍  (service.act) {"input":{"cmd":"get"}}
👍  (service.act) {"input":{"role":"test","cmd":"get"}}
👍  (service.act) {"input":{"ball":"get"}}
👍  (service.act) {"input":{"dog":"get"}}
👍  (service.act) {"input":{"thing":"get"}}
👍  (service.act) {"input":{"cmd":"update"}}
👍  (client.act) {"input":{"cmd":"create"}}
👍  (client.act) {"input":{"cmd":"get"}}
👍  (client.act) {"input":{"role":"test","cmd":"get"}}
👍  (client.act) {"input":{"ball":"get"}}
👍  (client.act) {"input":{"dog":"get"}}
👍  (client.act) {"input":{"thing":"get"}}
👍  (client.act) {"input":{"cmd":"update"}}

1.4.0 output:

2016-03-18T12:53:09.526Z tfpiuy2nfhrm/1458305589510/21555/- INFO    hello   Seneca/1.4.0/tfpiuy2nfhrm/1458305589510/21555/-
2016-03-18T12:53:09.792Z tfpiuy2nfhrm/1458305589510/21555/- INFO    listen
2016-03-18T12:53:09.877Z x0lerjt7ummy/1458305589875/21555/- INFO    hello   Seneca/1.4.0/x0lerjt7ummy/1458305589875/21555/-
2016-03-18T12:53:09.882Z x0lerjt7ummy/1458305589875/21555/- INFO    client
👍  (service.act) {"input":{"cmd":"create"}}
👍  (service.act) {"input":{"cmd":"get"}}
👍  (service.act) {"input":{"role":"test","cmd":"get"}}
👍  (service.act) {"input":{"ball":"get"}}
👍  (service.act) {"input":{"dog":"get"}}
👍  (service.act) {"input":{"thing":"get"}}
👍  (service.act) {"input":{"cmd":"update"}}
2016-03-18T12:53:09.946Z x0lerjt7ummy/1458305589875/21555/- WARN    act -           -   -   seneca: No matching action pattern found for { cmd: 'get' }, and no default result provided (using a default$ property).    act_not_found   {args:{ cmd: 'get' },plugin:{}} Error: seneca: No matching action pattern found for { cmd: 'get' }, and no default result provided (using a default$ property).
    at Object.errormaker [as error] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/eraro/eraro.js:94:15)
    at Object.execute_action [as fn] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/seneca.js:1090:25)
    at Immediate._onImmediate (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/gate-executor/gate-executor.js:136:14)
    at processImmediate [as _immediateCallback] (timers.js:383:17)
2016-03-18T12:53:09.947Z x0lerjt7ummy/1458305589875/21555/- ERROR   act -           OUT     -   63  {cmd:get}   ENTRY       -   seneca: No matching action pattern found for { cmd: 'get' }, and no default result provided (using a default$ property).    act_not_found   {args:{ cmd: 'get' },plugin:{}} Error: seneca: No matching action pattern found for { cmd: 'get' }, and no default result provided (using a default$ property).
    at Object.errormaker [as error] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/eraro/eraro.js:94:15)
    at Object.execute_action [as fn] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/seneca.js:1090:25)
    at Immediate._onImmediate (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/gate-executor/gate-executor.js:136:14)
    at processImmediate [as _immediateCallback] (timers.js:383:17)
👎  (client.act) Error: seneca: No matching action pattern found for { cmd: 'get' }, and no default result provided (using a default$ property).
2016-03-18T12:53:09.948Z x0lerjt7ummy/1458305589875/21555/- WARN    act -           -   -   seneca: No matching action pattern found for { role: 'test', cmd: 'get' }, and no default result provided (using a default$ property).  act_not_found   {args:{ role: 'test', cmd: 'get' },plugin:{}}   Error: seneca: No matching action pattern found for { role: 'test', cmd: 'get' }, and no default result provided (using a default$ property).
    at Object.errormaker [as error] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/eraro/eraro.js:94:15)
    at Object.execute_action [as fn] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/seneca.js:1090:25)
    at Immediate._onImmediate (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/gate-executor/gate-executor.js:136:14)
    at processImmediate [as _immediateCallback] (timers.js:383:17)
2016-03-18T12:53:09.948Z x0lerjt7ummy/1458305589875/21555/- ERROR   act -           OUT     -   64  {role:test,cmd:get} ENTRY       -   seneca: No matching action pattern found for { role: 'test', cmd: 'get' }, and no default result provided (using a default$ property).  act_not_found   {args:{ role: 'test', cmd: 'get' },plugin:{}}   Error: seneca: No matching action pattern found for { role: 'test', cmd: 'get' }, and no default result provided (using a default$ property).
    at Object.errormaker [as error] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/eraro/eraro.js:94:15)
    at Object.execute_action [as fn] (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/seneca.js:1090:25)
    at Immediate._onImmediate (/Users/heskew/src/nearform/tmp/seneca-tmp/node_modules/seneca/node_modules/gate-executor/gate-executor.js:136:14)
    at processImmediate [as _immediateCallback] (timers.js:383:17)
👎  (client.act) Error: seneca: No matching action pattern found for { role: 'test', cmd: 'get' }, and no default result provided (using a default$ property).
👍  (client.act) {"input":{"cmd":"create"}}
👍  (client.act) {"input":{"ball":"get"}}
👍  (client.act) {"input":{"dog":"get"}}
👍  (client.act) {"input":{"thing":"get"}}
👍  (client.act) {"input":{"cmd":"update"}}
@AdrianRossouw
Contributor

try putting the code that registers the actions in a seneca plugin.

ie:

seneca.use(function(opts) {
    var seneca = this;
    seneca.add(…);
});

Also, this line create a completely new seneca instance:

    const client = require('seneca')().client();
@heskew
heskew commented Mar 18, 2016

@AdrianRossouw: Thanks. Get the same behavior with a plugin. This repro is a super simplification of a larger application where tests broke after upgrading to 1.4.0. POSTing to the service still works, e.g. curl -d '{"cmd":"get"}' http://localhost:10101/act, so maybe it’s a problem in the client?

@AdrianRossouw
Contributor

so the one change that happened recently was how pinning works
they basically tried to make the options handling async, where it was sync before
and this meant that pinning doesn’t work until the system has already been init'd
why i was thinking a plugin might help, is because the client stuff uses pins
so the .ready() might be firing before the system is completely ready to handle it
you’ll also notice that the first few of the client calls fail, but then it starts working
maybe try to put a setTimeout() before you start calling the client actions

@heskew
heskew commented Mar 18, 2016

Fun. 😄 In this repro the client results are out of order. The first one, {cmd:’create’} succeeds. Just tried a 10s delay on the act calls and it’s all the same.

@geek geek added bug and removed bug labels Mar 23, 2016
@geek
Member
geek commented Mar 24, 2016

@heskew

Ok, I ran through and updated the code a little... I was able to reproduce a single failure with { role: 'test', cmd: 'get' }. However, if you change this to { role: 'test', cmd: 'test' } it works. Here is the working code:

'use strict';

const Seneca = require('seneca');

const service = Seneca();

const inputs = [
    { cmd: 'create' },
    { role: 'test', cmd: 'test' },
    { foo: 'bar' },
    { ball: 'get' },
    { dog: 'get' },
    { thing: 'get' },
    { cmd: 'update' }
];

service.listen();

inputs.forEach((input) => {
  service.add(input, (args, respond) => {

      respond(null, input);
  });
})

service.ready(function (err) {

    if (err) process.exit(1);

    const client = Seneca().client();
    client.ready(() => {

      inputs.forEach((input) => {

        service.act(input, (err, result) => console.log(err  && `👎  (service.act) ${err}` || `👍  (service.act) ${JSON.stringify(result)}`));
        client.act(input, (err, result) => { console.log(err  && `👎  (client.act) ${err}` || `👍  (client.act) ${JSON.stringify(result)}`) });
      });
      setTimeout(() => process.exit(), 2000);
    });
});
@geek geek self-assigned this Mar 24, 2016
@heskew
heskew commented Mar 24, 2016

@geek yeah it's that cmd:'get' that gets it. :) It's all good with 1.3.0 though. Not familiar enough (yet) with Seneca internals to know what could have caused this little glitch.

@geek
Member
geek commented Mar 24, 2016

We do have {role: 'options', cmd: 'get'}

Marking this as a bug: we should either return an error when trying to add a pattern that won't work, or determine why the pattern won't be matched

@geek geek added the bug label Mar 24, 2016
@heskew
heskew commented Mar 24, 2016

This problems seems to be just in the client btw. Not sure if you caught that in #375 (comment). So the pattern works on the service side, just not from a Seneca client. E.g. integration tests (unit tests calling act against the same seneca object patterns were registered with are fine) and my convoluted example fail.

@amitava82

I just bumped into this issue.

@indr
Contributor
indr commented Jul 29, 2016 edited

I took this issue as a little debugging exercise to get deeper understanding about pattern matching. There seems to be a problem with the building or reading of the keymap tree (this is where the destination meta info of an action/pattern is looked up). The lookup function is defined in https://github.com/rjrodger/patrun/blob/master/patrun.js#L134. Let me try to explain the algorithm with the following screenshot, taken from the seneca client instance (I used the example provided by geek, but removed all patterns except { role: 'test', cmd: 'bar'} and { role: 'test', cmd: 'get' }):

screenshot from 2016-07-29 15-01-25

All the seneca.add()'ed patterns are added to this tree in alphabetical order. This is why the top element has the key "cmd". Every element in the tree has these properties:

  • d: the destination meta info (if applicable), this is what we are looking for to return!
  • k: the name of the key (ex "cmd")
  • v: an object whose properties are exact match values of the key k (ex "client", "close")
  • s: the next element in the tree (alphabetically), if no exact v is present (if applicable)

The top.d destination info is returned as a default if there is no better match. In a seneca instance configured as a client, this holds the info to send the action to the "server". This is used in case of "role:test,cmd:bar" because there is no better match for this pattern in the tree (remember it's only present in the server, not the client).

But what happens in case of "role:test,cmd:get"? The algorithm traverses to top.v.get. This is an exact match. The saved destination info is overwritten with the currents key d property which is undefined (https://github.com/rjrodger/patrun/blob/master/patrun.js#L169). The key "note" is not in our pattern, so we look at the property s to proceed. This key "role" is present in our pattern, but there is no property in v named "test". The algorithm ends because there is no next s and returns the last saved destintion info d, which is undefined. Seneca has no route for the pattern "role:test,cmd:get".

Looking at the screenshot, this issue doesn't only happen with "get". You can use any pattern with a value for "cmd" that is in the screenshot under the first "v" property (ex "client", "close", "list").

The only workaround I could find so far is to pin the role in the client like this:

const client = Seneca().client({
    pin:'role:test'
});

This causes the tree to look a little different and the proper d property is present, found and returned:

screenshot from 2016-07-29 15-22-09

@indr
Contributor
indr commented Jul 29, 2016 edited

Basically, the order of the pattern keys is what causes the issue here. Too bad "role" comes after "cmd". How about @rjrodger changes his rjrodger/patrun algorithm to work in reverse order? 😏 [0]

The following example illustrates the problem a bit better. pattern1 is present in both the client and the service. As with real patterns containing 'cmd:get'. pattern2 exists only on the service.

'use strict';

const Seneca = require('seneca'); // 2.1.0

const service = Seneca();

//const roleKey = 'a'; // works
const roleKey = 'z'; // doesn't work
const cmdKey = 'c';

const pattern1 = {};
pattern1[roleKey] = 'role1';
pattern1[cmdKey] = 'get';

const pattern2 = {};
pattern2[roleKey] = 'role2';
pattern2[cmdKey] = 'get';

const inputs = [pattern1, pattern2];

service.listen();

inputs.forEach((input) => {
  service.add(input, (args, respond) => {
    respond(null, input);
  });
});

service.ready(function (err) {

  if (err) process.exit(1);

  const client = Seneca().client({
    //pin: `${roleKey}:role2` // works in both cases
  });
  client.add(pattern1, (args, respond) => {
    respond(null, pattern1)
  });
  client.ready(() => {

    if (err) process.exit(2);

    inputs.forEach((input) => {
      service.act(input, (err, result, tx) => {
        console.log(err && `👎  (service.act) ${err}` || `👍  (service.act) ${JSON.stringify(result)} ${tx ? 'remote' : 'local'}`);
      });
      client.act(input, (err, result, tx) => {
        console.log(err && `👎  (client.act) ${err}` || `👍  (client.act) ${JSON.stringify(result)} ${tx ? 'remote' : 'local'}`);
      });
    });
    setTimeout(() => process.exit(), 2000);
  });
});
const roleKey = 'a'; // works
//const roleKey = 'z'; // doesn't work
// ---
👍  (service.act) {"a":"role1","c":"get"} local
👍  (client.act) {"a":"role1","c":"get"} local
👍  (service.act) {"a":"role2","c":"get"} local
👍  (client.act) {"a":"role2","c":"get"} remote
//const roleKey = 'a'; // works
const roleKey = 'z'; // doesn't work
// ---
👍  (service.act) {"z":"role1","c":"get"} local
👍  (client.act) {"z":"role1","c":"get"} local
👍  (service.act) {"z":"role2","c":"get"} local
👎  (client.act) Error: seneca: No matching action pattern found for { z: 'role2', c: 'get' }, and no default result provided (using a default$ property).
  const client = Seneca().client({
    pin: `${roleKey}:role2` // works in both cases
  });
// ---
👍  (service.act) {"z":"role1","c":"get"} local
👍  (client.act) {"z":"role1","c":"get"} local
👍  (service.act) {"z":"role2","c":"get"} local
👍  (client.act) {"z":"role2","c":"get"} remote

[0] Wait. When I think about it. Could it be a performance gain in the seneca usage of patrun? role and cmd is used almost everywhere. And the starting letters after R, STUVWXYZ are pretty much less used than the letters A, B and D to Q... This would mean that in many cases the first decision is baed on role and not cmd... Maybe I'm completely off the track here... 3am...

@mcdonnelldean
Member

@indr This is super interesting stuff. The problem plugin is seneca-basic which is coming out soon. It is what is adding the get pattern.

@rjrodger Might be an idea to have a quick look through this. It's interesting to see a clash like this.

@rjrodger
Collaborator

The problem occurs because the catch-all pattern for the client is not being matched properly when there is a partial match (checked alphabetically - c: is checked before z:, but after a:).
If a: does not match, then it goes remote, but once anything matches, it just looks locally.

The workaround is to use explicit client pins.

The investigation starts here: https://github.com/senecajs/seneca/blob/master/lib/actions.js#L21
It's too late for 3.0, but let's aim to fix for 3.1

@rjrodger rjrodger assigned rjrodger and unassigned geek Aug 25, 2016
@heskew
heskew commented Aug 26, 2016

Thanks for that hint on pinning @rjrodger. We've had pinned clients for real use but I found some tests that didn't explicitly pin (we've only had the issue with some tests).

@rjrodger rjrodger added a commit to rjrodger/seneca that referenced this issue Sep 13, 2016
@rjrodger rjrodger patrun 0.5.1; fixes issue #375 455b208
@rjrodger
Collaborator
@rjrodger
Collaborator

@mcollina I believe you discovered this in another context a very long time ago - you'll probably want ti update any usage of patrun 0.5.1
/cc @pelger

@indr
Contributor
indr commented Sep 13, 2016

Thank you @rjrodger ! 😄

@rjrodger rjrodger closed this Sep 27, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment