Multiple kicker triggers in a commit but only first action run

[mareis]

Hi,

I'm experiencing an issue where if a kicker is triggered multiple times in the same commit, only the action from the first trigger is invoked.

From debug kicker, we can see that it is being triggered twice:

admin@ncs(config)# show conf
services loopback
   device XR-0
   !
   device XR-1
   !
!
admin@ncs(config)# commit | debug kicker
kicker: internal at /kicker:kickers changed, invoking {kicker_server,
kicker_data_changed,[]}
kicker: resource-diff-iter at /loopback:resource-manager/loopback:id-pool[loopback:name='pool-1']/loopback:requests[loopback:allocation-id='XR-0-1'] changed, invoking 'diff-iter'
kicker: resource-diff-iter at /loopback:resource-manager/loopback:id-pool[loopback:name='pool-1']/loopback:requests[loopback:allocation-id='XR-1-1'] changed, invoking 'diff-iter'
Commit complete.
admin@ncs(config)#

But from the action logs, only the first action is executed:

<INFO> 09-Jan-2018::19:22:00.9 loopback ncs-dp-30545-loopback:main-4-th-144: - Service create (/ncs:services/loopback:loopback/device{XR-0})

<INFO> 09-Jan-2018::19:22:00.24 loopback ncs-dp-30545-loopback:main-4-th-144: - ID is None

<INFO> 09-Jan-2018::19:22:00.43 loopback ncs-dp-30545-loopback:main-4-th-144: - Service create (/ncs:services/loopback:loopback/device{XR-1})

<INFO> 09-Jan-2018::19:22:00.57 loopback ncs-dp-30545-loopback:main-4-th-144: - ID is None

<INFO> 09-Jan-2018::19:22:00.107 loopback ncs-dp-30545-loopback:main-4-usid-24-diff-iter-action: - Action input: kicker-id: resource-diff-iter, path: /loopback:resource-manager/id-pool{pool-1}/requests{XR-0-1}, tid: 172

<INFO> 09-Jan-2018::19:22:00.108 loopback ncs-dp-30545-loopback:main-4-usid-24-diff-iter-action: - Diff iterate: kp: /loopback:resource-manager/id-pool{pool-1}, op: MOP_MODIFIED(3)

<INFO> 09-Jan-2018::19:22:00.108 loopback ncs-dp-30545-loopback:main-4-usid-24-diff-iter-action: - Diff iterate: kp: /loopback:resource-manager/id-pool{pool-1}/requests{XR-0-1}, op: MOP_CREATED(1)

<INFO> 09-Jan-2018::19:22:00.117 loopback ncs-dp-30545-loopback:main-4-usid-24-diff-iter-action: - Allocate: pool-1, XR-0-1, value: 1

<INFO> 09-Jan-2018::19:22:00.140 loopback ncs-dp-30545-loopback:main-5-th-178: - Service create (/ncs:services/loopback:loopback/device{XR-0})

<INFO> 09-Jan-2018::19:22:00.155 loopback ncs-dp-30545-loopback:main-5-th-178: - ID is 1

Also note that I'm iterating over the diffs from the fictitious transaction id provided to the action. Those diffs only include the changes associated with the first trigger (i.e. device XR-0).

If I split into separate commits (device XR-0, commit, device XR-1, commit) then everything work as expected.

Is this a known limitation of kickers?

I'm running NSO 4.5.2

Kicker config:

kickers data-kicker resource-diff-iter
   monitor /loopback:resource-manager/loopback:id-pool/loopback:requests
   kick-node /resource-manager
   action-name diff-iter
!

Snippet of the yang model:

container resource-manager {
   tailf:info "Configure resource management pools";
   tailf:cli-add-mode;

   list id-pool {
      key name;

      leaf name {
         tailf:info "Unique name for the pool";
         type string;
      }

      list requests {
         key allocation-id;

         leaf allocation-id {
            type string;
         }
      } // list requests

      list responses {
         config false;
         tailf:cdb-oper {
            tailf:persistent true;
         }
         key allocation-id;

         leaf allocation-id {
            type string;
         }

         leaf assigned-id {
            type uint32;
         }
      } // list responses

   } // list id-pool

   tailf:action diff-iter {
      tailf:actionpoint diff-iter-action;
      input {
         uses kicker:action-input-params;
      }
      output {
      }
   }
}

Thanks

Marcelo

[Dan.Sullivan]

Hi Marcelo,

Have you made any progress with this? If not can you provide the actual package and kickers?

-Dan

[frjansso]

Hi!

I tried to reproduce this, but it works for me, NSO 4.5.2

admin@ncs% show kickers

data-kicker k1 {

    monitor     /test[name='f1'];

    kick-node   /action;

    action-name double;

}

data-kicker k2 {

    monitor     /test[name='f2'];

    kick-node   /action;

    action-name double;

}

now if I create f1 and f2 in the same commit:

admin@ncs% set test f1 dummy 10.1.1.1

[ok][2018-01-24 08:58:43]

[edit]

admin@ncs% set test f2 dummy 10.1.1.1

[ok][2018-01-24 08:58:45]

[edit]

admin@ncs% commit

Commit complete.

[ok][2018-01-24 08:58:50]

in my logs I get:

<INFO> 24-Jan-2018::08:58:50.603 test ncs-dp-23578-test:main-7-th-307: - Service create(service=/test:test{f1})

<INFO> 24-Jan-2018::08:58:50.645 test ncs-dp-23578-test:main-7-th-307: - Service create(service=/test:test{f2})

<INFO> 24-Jan-2018::08:58:50.686 test ncs-dp-23578-test:main-8-usid-28-test-action: - action name: double

<INFO> 24-Jan-2018::08:58:50.695 test ncs-dp-23578-test:main-8-usid-28-test-action: - action name: double

So as Dan suggested, please provide your project and we can test.

[mareis]

Hi Dan and Fredrik,

Thanks for the reply. I haven't made any progress. The package can be found here: https://github.com/reismarcelo/loopback

The kicker setup is part of it.

Thanks

Marcelo

[mareis]

Hi Dan, Fredrik,

I spent some time on it today and could isolate to the m.attach() command inside the action. I started with a simple test package like the one Fredrik used, then kept adding the features I use in my package. It breaks when the kicked action runs m.attach(input.tid).

1) Working

class DoubleAction(Action):

    @Action.action

    def cb_action(self, uinfo, name, kp, input, output):

        def iterate(keypath, op, old_value, new_value):

            self.log.info('Diff iterate: kp: {}, op: {}'.format(keypath, op))

            return ncs.ITER_RECURSE

        self.log.info('Action input: kicker-id: {}, path: {}, tid: {}'.format(input.kicker_id, input.path, input.tid))

        with Maapi() as m:

            self.log.info('Inside with Maapi()')

        #   with m.attach(input.tid) as t:

        #       self.log.info('Inside with m.attach()')

        #       t.diff_iterate(iterate, ncs.ITER_WANT_P_CONTAINER)

admin@ncs(config-a-list-alist1)# allocation alloc1 dummy 1.2.3.4

admin@ncs(config-allocation-alloc1)# allocation alloc2 dummy 1.2.3.4

admin@ncs(config-allocation-alloc2)# commit | debug kicker         

kicker: kickn-test-6 at /kickn:test/kickn:a-list[kickn:name='alist1']/kickn:allocation[kickn:alloc-id='alloc1'] changed, invoking double

kicker: kickn-test-6 at /kickn:test/kickn:a-list[kickn:name='alist1']/kickn:allocation[kickn:alloc-id='alloc2'] changed, invoking double

Commit complete.

<INFO> 24-Jan-2018::18:54:01.645 kickn ncs-dp-79184-kickn:main-1-th-113: - Service create(service=/kickn:test/a-list{alist1}/allocation{alloc1})

<INFO> 24-Jan-2018::18:54:01.651 kickn ncs-dp-79184-kickn:main-1-th-113: - Service create(service=/kickn:test/a-list{alist1}/allocation{alloc2})

<INFO> 24-Jan-2018::18:54:01.668 kickn ncs-dp-79184-kickn:main-2-usid-25-kickn-action: - Action input: kicker-id: kickn-test-6, path: /kickn:test/a-list{alist1}/allocation{alloc1}, tid: 133

<INFO> 24-Jan-2018::18:54:01.669 kickn ncs-dp-79184-kickn:main-2-usid-25-kickn-action: - Inside with Maapi()

<INFO> 24-Jan-2018::18:54:01.672 kickn ncs-dp-79184-kickn:main-2-usid-25-kickn-action: - Action input: kicker-id: kickn-test-6, path: /kickn:test/a-list{alist1}/allocation{alloc2}, tid: 136

<INFO> 24-Jan-2018::18:54:01.673 kickn ncs-dp-79184-kickn:main-2-usid-25-kickn-action: - Inside with Maapi()

2) Not working (second action is not executed)

class DoubleAction(Action):

    @Action.action

    def cb_action(self, uinfo, name, kp, input, output):

        def iterate(keypath, op, old_value, new_value):

            self.log.info('Diff iterate: kp: {}, op: {}'.format(keypath, op))

            return ncs.ITER_RECURSE

        self.log.info('Action input: kicker-id: {}, path: {}, tid: {}'.format(input.kicker_id, input.path, input.tid))

        with Maapi() as m:

            self.log.info('Inside with Maapi()')

            with m.attach(input.tid) as t:

                self.log.info('Inside with m.attach()')

        #       t.diff_iterate(iterate, ncs.ITER_WANT_P_CONTAINER)

admin@ncs(config-a-list-alist1)# allocation alloc1 dummy 1.2.3.4

admin@ncs(config-allocation-alloc1)# allocation alloc2 dummy 1.2.3.4

admin@ncs(config-allocation-alloc2)# commit | debug kicker         

kicker: kickn-test-6 at /kickn:test/kickn:a-list[kickn:name='alist1']/kickn:allocation[kickn:alloc-id='alloc1'] changed, invoking double

kicker: kickn-test-6 at /kickn:test/kickn:a-list[kickn:name='alist1']/kickn:allocation[kickn:alloc-id='alloc2'] changed, invoking double

Commit complete.

<INFO> 24-Jan-2018::19:00:21.852 kickn ncs-dp-80255-kickn:main-1-th-158: - Service create(service=/kickn:test/a-list{alist1}/allocation{alloc1})

<INFO> 24-Jan-2018::19:00:21.859 kickn ncs-dp-80255-kickn:main-1-th-158: - Service create(service=/kickn:test/a-list{alist1}/allocation{alloc2})

<INFO> 24-Jan-2018::19:00:21.876 kickn ncs-dp-80255-kickn:main-2-usid-27-kickn-action: - Action input: kicker-id: kickn-test-6, path: /kickn:test/a-list{alist1}/allocation{alloc1}, tid: 174

<INFO> 24-Jan-2018::19:00:21.877 kickn ncs-dp-80255-kickn:main-2-usid-27-kickn-action: - Inside with Maapi()

<INFO> 24-Jan-2018::19:00:21.877 kickn ncs-dp-80255-kickn:main-2-usid-27-kickn-action: - Inside with m.attach()

[frjansso]

Marcelo,

input doesn't have a attribute called tid, don't you get an exception in the logs?

uinfo has a actx_thandle, you probably want to check that one.

[mareis]

Hi Fredrik,

I'm using kicker:action-input-params:

    tailf:action double {

      tailf:actionpoint kickn-action;

      input {

        uses kicker:action-input-params;

      }

      output {

      }

    }

  grouping action-input-params {

    description

      "A kicker action can choose to implement this grouping as it input

       parameters. If so the action will be invoked with:

         * kicker-id - The id of the triggering kicker

         * path      - The path to the subtree containing the change

         * tid       - The transaction id to a synthetic transaction

                       containing the change.

       The transaction is synthetic in the sense that it contains the

       same change-set as the triggering transaction (which has been committed).

       However the synthetic transaction is started over an empty datastore

       and is therefore only suitable for diff-iteration over the changes.

       Kicker actions that does not implement this grouping as its input

       parameters will be invoked with an empty parameter list.";

    uses notification-params;

    leaf tid {

      type uint32;

      description

        "Synthetic read transaction containing the triggering changes";

    }

  }

[mareis · Accepted solution]

Hi Frederik,

I tried your suggestion from the other thread:

"

I'm not sure m.attach supports the with statement ("with m.attach.."), is there any difference if you do

m.attach(input.tid)

m.detach(input.tid)

"

You were right, it worked when not using the context manager:

class DoubleAction(Action):

    @Action.action

    def cb_action(self, uinfo, name, kp, input, output):

        self.log.info('Action input: kicker-id: {}, path: {}, tid: {}'.format(input.kicker_id, input.path, input.tid))

        with Maapi() as m:

            self.log.info('Inside with Maapi()')

            try:

                t = m.attach(input.tid)

                self.log.info('Attached')

            finally:

                m.detach(input.tid)

                self.log.info('Detached')

admin@ncs(config-allocation-alloc1)# allocation alloc2 dummy 1.2.3.4

admin@ncs(config-allocation-alloc2)# allocation alloc3 dummy 1.2.3.4

admin@ncs(config-allocation-alloc3)# commit | debug kicker         

kicker: kickn-test-6 at /kickn:test/kickn:a-list[kickn:name='alist1']/kickn:allocation[kickn:alloc-id='alloc2'] changed, invoking double

kicker: kickn-test-6 at /kickn:test/kickn:a-list[kickn:name='alist1']/kickn:allocation[kickn:alloc-id='alloc3'] changed, invoking double

<INFO> 25-Jan-2018::09:07:19.379 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Action input: kicker-id: kickn-test-6, path: /kickn:test/a-list{alist1}/allocation{alloc2}, tid: 232

<INFO> 25-Jan-2018::09:07:19.379 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Inside with Maapi()

<INFO> 25-Jan-2018::09:07:19.379 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Attached

<INFO> 25-Jan-2018::09:07:19.380 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Detached

<INFO> 25-Jan-2018::09:07:19.383 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Action input: kicker-id: kickn-test-6, path: /kickn:test/a-list{alist1}/allocation{alloc3}, tid: 235

<INFO> 25-Jan-2018::09:07:19.384 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Inside with Maapi()

<INFO> 25-Jan-2018::09:07:19.384 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Attached

<INFO> 25-Jan-2018::09:07:19.384 kickn ncs-dp-20739-kickn:main-1-usid-30-kickn-action: - Detached

However, I believe there is still an issue with ncs.maapi.Transaction. So m.attach() returns an ncs.maapi.Transaction object. Looking at it in maapi.py, we can see that Transaction does implement the context manager magic methods (__enter__, __exit__). There is even an example of using Transaction inside a context manager in the docstring. Shouldn't __exit__ be calling detach?

Thanks

Marcelo

[frjansso]

This is the correct behavior according to the docs:

An instance of this class is also a context manager:

with Transaction(mymaapi, th=myth) as trans:

1. do something here...

When exiting the with statement, finish() will be called.

As attach/detach is not very widely used, I believe the behavior today is the correct one. That means, in the attach/detach scenario you have to handle it yourself with try/finally.

[mareis]

That's quite an "unpythonic" behavior, but your explanation makes sense. It's probably not worthwhile making it automatically look for attached sessions if attach/detach is not something commonly used.

Thank you Fredrik, much appreciated.

[frjansso]

I agree, it would be nice if the Transaction object could capture if it's a new transactions (call finish) or an attached transaction (call detach).

I can report it as a suggested feature.

[mareis]

Yes, that would be a very good improvement. Thank you Fredrik