CESNET / netopeer2

NETCONF toolset
BSD 3-Clause "New" or "Revised" License
301 stars 189 forks source link

Internal error while sending notifications to multiple subscribers #1399

Closed ankit7gup closed 1 year ago

ankit7gup commented 1 year ago

Hi @michalvasko,

We are using latest sysrepo-netopeer2.

While sending notifications to multiple subscribers with/without subscription filter, we are observing below error.. One client is based on old version of libnconf2 and another client uses NcClient.

netopeer2-server[1410]: Internal error (/usr/src/debug/sysrepo/git-r0/git/src/shm_sub.c:4385).

5 subscriptions are being done. Attached image

image

Please suggest.

Thanks!

regards, Ankit

michalvasko commented 1 year ago

It would be best if I could reproduce it but that may not be that simple, so I would at least need to see the error. Please apply the patch and post the printed error.

diff --git a/src/shm_sub.c b/src/shm_sub.c
index eccefe9f..6d2b670b 100644
--- a/src/shm_sub.c
+++ b/src/shm_sub.c
@@ -4382,6 +4382,7 @@ sr_shmsub_notif_listen_filter_is_valid(const struct lyd_node *notif, const char
     }

     if (lyd_eval_xpath(notif, xpath, &result)) {
+        sr_errinfo_new_ly(&err_info, LYD_CTX(notif), notif);
         SR_ERRINFO_INT(&err_info);
         sr_errinfo_free(&err_info);
         return 0;
ankit7gup commented 1 year ago

Hi @michalvasko,

Please find the logs as below.

2023-05-15 13:34:40.044220 host info netopeer2-server[1372]: EV LISTEN: "o-ran-sync" "notif" ID 1 processing. 2023-05-15 13:34:40.044361 host err netopeer2-server[1372]: Cannot apply XPath operation union on node set and boolean. (Data location "/o-ran-sync:synchronization-state-change".) 2023-05-15 13:34:40.044384 host err netopeer2-server[1372]: Internal error (/usr/src/debug/sysrepo/git-r0/git/src/shm_sub.c:4386). 2023-05-15 13:34:40.044407 host info netopeer2-server[1372]: EV LISTEN: "o-ran-sync" "notif" ID 1 priority 0 success (remaining 0 subscribers).

2023-05-15 13:34:40.044887 host info netopeer2-server[1372]: EV LISTEN: "o-ran-fm" "notif" ID 1 processing. 2023-05-15 13:34:40.045039 host info netopeer2-server[1372]: EV LISTEN: "o-ran-fm" "notif" ID 1 priority 0 success (remaining 0 subscribers).

 2023-05-15 13:34:40.374781 host info netopeer2-server[1372]: EV LISTEN: "ietf-hardware" "notif" ID 1 processing. 2023-05-15 13:34:40.374929 host err netopeer2-server[1372]: Cannot apply XPath operation union on node set and boolean. (Data location "/ietf-hardware:hardware-state-oper-enabled".) 2023-05-15 13:34:40.374955 host err netopeer2-server[1372]: Internal error (/usr/src/debug/sysrepo/git-r0/git/src/shm_sub.c:4386). 2023-05-15 13:34:40.374980 host info netopeer2-server[1372]: EV LISTEN: "ietf-hardware" "notif" ID 1 priority 0 success (remaining 0 subscribers). 2023-05-15 13:34:40.756247 host info netopeer2-server[1372]: Trying to connect via IPv6 to 2001:db9:130::11:4334.

2023-05-15 13:35:32.950174 host info netopeer2-server[1372]: EV LISTEN: "o-ran-troubleshooting" "notif" ID 1 processing. 2023-05-15 13:35:32.950318 host err netopeer2-server[1372]: Cannot apply XPath operation union on node set and boolean. (Data location "/o-ran-troubleshooting:troubleshooting-log-generated".) 2023-05-15 13:35:32.950342 host err netopeer2-server[1372]: Internal error (/usr/src/debug/sysrepo/git-r0/git/src/shm_sub.c:4386). 2023-05-15 13:35:32.950367 host info netopeer2-server[1372]: EV LISTEN: "o-ran-troubleshooting" "notif" ID 1 priority 0 success (remaining 0 subscribers).

We've used only one subscription from one client this time.

michalvasko commented 1 year ago

Please try to use the latest libyang from the devel branch, I believe this has already been fixed.

ankit7gup commented 1 year ago

Please try to use the latest libyang from the devel branch, I believe this has already been fixed.

Can you please share the commit, if this can be done as a patch on last official release. Thanks!

michalvasko commented 1 year ago

Fine, https://github.com/CESNET/libyang/commit/3ff82dd469432b0d55c348b31ca8575e59b4d5a2.

ankit7gup commented 1 year ago

We tested with the code patch, seems like error is not there anymore, but if using create subscriptions, notifications are being received, but not printed with or without filters. Please suggest.

michalvasko commented 1 year ago

If you are certain the filter you use is supposed to match a notification but it is not received, perhaps you have not subscribed to the stream that the notification is a part of? NETCONF includes all the notifications. Another problem that may occur is with NACM, if the subscriber does not have read access to the notification, it is silently dropped as per the specs.

If none of these issues occurred then I assume there really is a bug and you can either try to collect more information and even debug yourself to some extent or help me reproduce the problem.

ankit7gup commented 1 year ago

Using User-rpc with xml for create-subscription without any filter (NETCONF stream by default) notifications are not being printed, can only be seen with verbose level enabled. But same is visible and printed if using subscribe option from the cli.

michalvasko commented 1 year ago

Yes, that makes sense. It is one thing to subscribe for the notifications to be sent to the client but it is another to actually receive them. The simple netopeer2-cli does that only if subscribe is run, it does not inspect every RPC sent whether it is not create-subscription or establish-subscription since there are dedicated commands for that.

ankit7gup commented 1 year ago

Hi @michalvasko

We are facing an intermittent issue, We subscribe for create-subscription RPC in our application at priority 5. Also, in reception of the RPC callback, we send notification from another thread. Somehow, we don't receive RPC ok message or any further notifications on Netconf client application (using libnetconf2).

The version being used at client is quite old, and not in our control to upgrade. Can you please suggest.

Client logs:

May:22: 5:41:29:347741|error|976|ncClient.cpp|799|lnc2_print_clb():nc VERBOSE: Session[3], received message:

<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0"><eventTime>2023-05-22T05:41:29.008110297+00:00</eventTime><hardware-state-oper-enabled xmlns="urn:ietf:params:xml:ns:yang:ietf-hardware"><name>ORU</name><admin-state>unlocked</admin-state></hardware-state-oper-enabled></notification>

May:22: 5:41:29:347741|error|976|ncClient.cpp|799|lnc2_print_clb():nc VERBOSE: Session[3], received message:
<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0"><eventTime>2023-05-22T05:41:29.008110297+00:00</eventTime><hardware-state-oper-enabled xmlns="urn:ietf:params:xml:ns:yang:ietf-hardware"><name>ORU</name><admin-state>unlocked</admin-state></hardware-state-oper-enabled></notification>

May:22: 5:41:29:347833|error|976|ncClient.cpp|793|lnc2_print_clb():nc ERROR: Session 3: received a <notification> but session is not subscribed.
May:22: 5:41:29:347849|error|976|ncClient.cpp|428|rpc_send_recv_reply():RU[2], session[3], msg: failed to receive a reply for rpc[ 15].

Netconf server Logs:

2023-05-22 05:41:28.863958 info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 2 priority 5 for 1 subscribers published.
2023-05-22 05:41:28.867333 info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 2 priority 5 succeeded.

2023-05-22 05:41:28.867832  info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 2 priority 0 for 1 subscribers published.
2023-05-22 05:41:28.868804  info netopeer2-server[1735]: EV LISTEN: "/notifications:create-subscription" "rpc" ID 2 priority 0 processing (remaining 1 subscribers).
2023-05-22 05:41:28.889121  info netopeer2-server[1735]: EV LISTEN: "/notifications:create-subscription" "rpc" ID 2 priority 0 success (remaining 0 subscribers).
2023-05-22 05:41:28.889470 info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 2 priority 0 succeeded.
2023-05-22 05:41:28.890589  info netopeer2-server[1735]: Session 2: thread 2 event new RPC.
2023-05-22 05:41:28.939776  info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 3 priority 5 for 1 subscribers published.
2023-05-22 05:41:28.943272  info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 3 priority 5 succeeded.

2023-05-22 05:41:28.943831 info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 3 priority 0 for 1 subscribers published.
2023-05-22 05:41:28.944348 info netopeer2-server[1735]: EV LISTEN: "/notifications:create-subscription" "rpc" ID 3 priority 0 processing (remaining 1 subscribers).

2023-05-22 05:41:29.346553  info netopeer2-server[1735]: EV LISTEN: "ietf-hardware" "notif" ID 1 processing.
2023-05-22 05:41:29.347754  info netopeer2-server[1735]: EV LISTEN: "ietf-hardware" "notif" ID 1 priority 0 success (remaining 0 subscribers).

2023-05-22 05:41:29.406616  info netopeer2-server[1735]: EV LISTEN: "/notifications:create-subscription" "rpc" ID 3 priority 0 success (remaining 0 subscribers).
2023-05-22 05:41:29.406746  info netopeer2-server[1735]: EV ORIGIN: "/notifications:create-subscription" "rpc" ID 3 priority 0 succeeded.

Thanks!

michalvasko commented 1 year ago

I am still confused, you wrote your own NC client using libnetconf2 and are getting the error you posted? Just follow what netopeer2-cli is doing and it must work. I think there had been a function you needed to call on the client if you expect to receive notifications, which has most likely been removed later since I cannot even find the error in the current libnetconf2.

ankit7gup commented 1 year ago

I am still confused; you wrote your own NC client using libnetconf2 and are getting the error you posted? Just follow what netopeer2-cli is doing and it must work. I think there had been a function you needed to call on the client if you expect to receive notifications, which has most likely been removed later since I cannot even find the error in the current libnetconf2.

Yes, there is own Nc client written using libnetconf2 which uses Libnetconf2 V0.11. Below is the API being used. nc_recv_notif_dispatch(session, &ncClient::lnc2_notifClb);

  / we read notif, want a rpc-reply /     if (msgid && (msgtype == NC_MSG_NOTIF)) {         if (!session->opts.client.ntf_tid) {             ERR("Session %u: received a but session is not subscribed.", session->id);             lyxml_free(session->ctx, xml);             return NC_MSG_ERROR;         }

michalvasko commented 1 year ago

Like I said, look into the code of netopeer2-cli in that version for functions to call. I cannot help you with such an outdated library,