No notification after re-establishing connection and sending same subscription again
Closed this issue · 3 comments
mpet commented
Hi,
We have the following scenario using toxic-proxy to simulate a lost connection.
- Start SSH connection to Netopeer2. ok
- Send create subscription. ok reply received.
- Change value for
<probe-interval>to 3. ok reply received. - Wait for event from Netopeer2. Event received.
- Simulate connection lost using toxic proxy.
- Create a new SSH connection to Netopeer2. ok
- Send create subscription again. ok reply received.
- Change value for
<probe-interval>to 4. ok reply received. - Wait for event from Netopeer2. No event received!!
This is an snippet of log for step 6 -->
2024-10-01 07:13:34,044 (Log.java:220) INFO : The 2 time connecting to node.
2024-10-01 07:13:34,044 (Ssh.java:57) INFO : Creating a SSH connection to localhost:32858
2024-10-01 07:13:34,045 (AbstractCli.java:80) DEBUG : Connecting cli
2024-10-01 07:13:34,045 (ImplSsh.java:468) DEBUG : Creating a ssh connection: localhost:32858_ID9604808
2024-10-01 07:13:34,101 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Accepted a connection on 0.0.0.0:830 from 172.19.0.3:60010.
2024-10-01 07:13:34,211 (ImplSsh.java:493) DEBUG : Done creating a ssh connection: localhost:32858_ID9604808
2024-10-01 07:13:34,256 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Received an SSH message "request-service" of subtype "ssh-userauth".
2024-10-01 07:13:34,257 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Received an SSH message "request-auth" of subtype "none".
2024-10-01 07:13:34,257 (ImplSsh.java:386) DEBUG : Available authentication methods: [keyboard-interactive]
2024-10-01 07:13:34,258 (ImplSsh.java:388) DEBUG : Ignoring authentication methods: [gssapi-with-mic]
2024-10-01 07:13:34,258 (ImplSsh.java:398) DEBUG : Trying to authenticate with method: keyboard-interactive
2024-10-01 07:13:34,259 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Received an SSH message "request-auth" of subtype "interactive".
2024-10-01 07:13:34,286 (ImplSsh.java:412) DEBUG : keyboard-interactive authentication successful? true
2024-10-01 07:13:34,287 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: User "netconf" authenticated.
2024-10-01 07:13:34,287 (ImplSsh.java:424) DEBUG : Authentication Complete: localhost:32858_ID9604808
2024-10-01 07:13:34,287 (ImplSsh.java:243) DEBUG : Opening a ssh session: localhost:32858_ID9604808
2024-10-01 07:13:34,288 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Received an SSH message "request-channel-open" of subtype "session".
2024-10-01 07:13:34,288 (ImplSsh.java:250) DEBUG : Done opening a ssh session: localhost:32858_ID9604808
2024-10-01 07:13:34,289 (ImplSsh.java:279) DEBUG : Starting subsystem: netconf
2024-10-01 07:13:34,290 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Received an SSH message "request-channel" of subtype "subsystem".
2024-10-01 07:13:34,290 (ImplSsh.java:286) DEBUG : Done starting netconf session
2024-10-01 07:13:34,290 (AbstractCli.java:84) DEBUG : Done connecting cli
2024-10-01 07:13:34,290 (Ssh.java:88) INFO : Established a SSH connection to localhost:32858
2024-10-01 07:13:34,291 (AbstractTransport.java:790) INFO : Notfication subscribers '[com.ericsson.commonlibrary.netconf.util.CombinedTestModelAndConnectionEventsImpl@64f981e2, com.ericsson.commonlibrary.netconf.transport.NotificationSubscriptionImpl@480b57e2]'
2024-10-01 07:13:34,291 (NetconfMessageReaderImpl.java:45) INFO : Submitted a NetconfMessageReaderTask to executor
2024-10-01 07:13:34,292 (AbstractTransport.java:795) INFO : Started netconfMessgeReader
2024-10-01 07:13:34,292 (AbstractTransport.java:560) DEBUG : Starting to exchange the <hello> messages
2024-10-01 07:13:34,292 (NetconfMessageReaderTask.java:149) INFO : Message received: <hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><capabilities><capability>urn:ietf:params:netconf:base:1.0</capability><capability>urn:ietf:params:netconf:base:1.1</capability><capability>urn:ietf:params:netconf:capability:writable-running:1.0</capability><capability>urn:ietf:params:netconf:capability:candidate:1.0</capability><capability>urn:ietf:params:netconf:capability:confirmed-commit:1.1</capability><capability>urn:ietf:params:netconf:capability:rollback-on-error:1.0</capability><capability>urn:ietf:params:netconf:capability:validate:1.1</capability><capability>urn:ietf:params:netconf:capability:startup:1.0</capability><capability>urn:ietf:params:netconf:capability:xpath:1.0</capability><capability>urn:ietf:params:netconf:capability:with-defaults:1.0?basic-mode=explicit&also-supported=report-all,report-all-tagged,trim,explicit</capability><capability>urn:ietf:params:netconf:capability:notification:1.0</capability><capability>urn:ietf:params:netconf:capability:interleave:1.0</capability><capability>urn:ietf:params:netconf:capability:url:1.0?scheme=ftp,ftps,http,https,scp,sftp</capability><capability>urn:ietf:params:xml:ns:yang:ietf-yang-metadata?module=ietf-yang-metadata&revision=2016-08-05</capability><capability>urn:ietf:params:xml:ns:yang:ietf-inet-types?module=ietf-inet-types&revision=2013-07-15</capability><capability>urn:ietf:params:xml:ns:yang:ietf-yang-types?module=ietf-yang-types&revision=2013-07-15</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-acm?module=ietf-netconf-acm&revision=2018-02-14</capability><capability>urn:ietf:params:netconf:capability:yang-library:1.1?revision=2019-01-04&content-id=2008448144</capability><capability>urn:sysrepo:plugind?module=sysrepo-plugind&revision=2022-08-26</capability><capability>urn:ietf:params:xml:ns:netconf:base:1.0?module=ietf-netconf&revision=2013-09-29&features=writable-running,candidate,confirmed-commit,rollback-on-error,validate,startup,url,xpath</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-with-defaults?module=ietf-netconf-with-defaults&revision=2011-06-01</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-notifications?module=ietf-netconf-notifications&revision=2012-02-06</capability><capability>urn:ietf:params:xml:ns:netconf:notification:1.0?module=notifications&revision=2008-07-14</capability><capability>urn:ietf:params:xml:ns:netmod:notification?module=nc-notifications&revision=2008-07-14</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-monitoring?module=ietf-netconf-monitoring&revision=2010-10-04</capability><capability>urn:ietf:params:xml:ns:yang:ietf-x509-cert-to-name?module=ietf-x509-cert-to-name&revision=2014-12-10</capability><capability>urn:ietf:params:xml:ns:yang:iana-crypt-hash?module=iana-crypt-hash&revision=2014-04-04&features=crypt-hash-md5,crypt-hash-sha-256,crypt-hash-sha-512</capability></capabilities><session-id>2</session-id></hello>
2024-10-01 07:13:34,293 (PowerLogger.java:428) INFO : Hello message '<hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><capabilities><capability>urn:ietf:params:netconf:base:1.0</capability><capability>urn:ietf:params:netconf:base:1.1</capability><capability>urn:ietf:params:netconf:capability:writable-running:1.0</capability><capability>urn:ietf:params:netconf:capability:candidate:1.0</capability><capability>urn:ietf:params:netconf:capability:confirmed-commit:1.1</capability><capability>urn:ietf:params:netconf:capability:rollback-on-error:1.0</capability><capability>urn:ietf:params:netconf:capability:validate:1.1</capability><capability>urn:ietf:params:netconf:capability:startup:1.0</capability><capability>urn:ietf:params:netconf:capability:xpath:1.0</capability><capability>urn:ietf:params:netconf:capability:with-defaults:1.0?basic-mode=explicit&also-supported=report-all,report-all-tagged,trim,explicit</capability><capability>urn:ietf:params:netconf:capability:notification:1.0</capability><capability>urn:ietf:params:netconf:capability:interleave:1.0</capability><capability>urn:ietf:params:netconf:capability:url:1.0?scheme=ftp,ftps,http,https,scp,sftp</capability><capability>urn:ietf:params:xml:ns:yang:ietf-yang-metadata?module=ietf-yang-metadata&revision=2016-08-05</capability><capability>urn:ietf:params:xml:ns:yang:ietf-inet-types?module=ietf-inet-types&revision=2013-07-15</capability><capability>urn:ietf:params:xml:ns:yang:ietf-yang-types?module=ietf-yang-types&revision=2013-07-15</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-acm?module=ietf-netconf-acm&revision=2018-02-14</capability><capability>urn:ietf:params:netconf:capability:yang-library:1.1?revision=2019-01-04&content-id=2008448144</capability><capability>urn:sysrepo:plugind?module=sysrepo-plugind&revision=2022-08-26</capability><capability>urn:ietf:params:xml:ns:netconf:base:1.0?module=ietf-netconf&revision=2013-09-29&features=writable-running,candidate,confirmed-commit,rollback-on-error,validate,startup,url,xpath</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-with-defaults?module=ietf-netconf-with-defaults&revision=2011-06-01</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-notifications?module=ietf-netconf-notifications&revision=2012-02-06</capability><capability>urn:ietf:params:xml:ns:netconf:notification:1.0?module=notifications&revision=2008-07-14</capability><capability>urn:ietf:params:xml:ns:netmod:notification?module=nc-notifications&revision=2008-07-14</capability><capability>urn:ietf:params:xml:ns:yang:ietf-netconf-monitoring?module=ietf-netconf-monitoring&revision=2010-10-04</capability><capability>urn:ietf:params:xml:ns:yang:ietf-x509-cert-to-name?module=ietf-x509-cert-to-name&revision=2014-12-10</capability><capability>urn:ietf:params:xml:ns:yang:iana-crypt-hash?module=iana-crypt-hash&revision=2014-04-04&features=crypt-hash-md5,crypt-hash-sha-256,crypt-hash-sha-512</capability></capabilities><session-id>2</session-id></hello>'
2024-10-01 07:13:34,300 (AbstractTransport.java:600) DEBUG : The exchange of 'hello' messages phase is completed, the session ID is 2
2024-10-01 07:13:34,300 (AbstractTransport.java:255) INFO : Established NETCONF session to node 'localhost' in '30279' milliseconds.
2024-10-01 07:13:34,300 (PowerLogger.java:338) DEBUG : startKeepAliveThread() on session 2
2024-10-01 07:13:34,300 (KeepAlive.java:64) DEBUG : Initiated the keepAlive pool-6-thread-1 for this session 2
2024-10-01 07:13:34,301 (AutomaticConnectImpl.java:45) INFO : [AUTOMATIC CONNECT] NETCONF session re-established
2024-10-01 07:13:34,301 (AutomaticConnectImpl.java:93) INFO : [AUTOMATIC CONNECTION] Sending subscription again ' <rpc message-id="2" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<urn:create-subscription xmlns:urn="urn:ietf:params:xml:ns:netconf:notification:1.0"/>
</rpc>
]]>]]>'
2024-10-01 07:13:34,301 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Generated new event (netconf-session-start).
2024-10-01 07:13:34,302 (PowerLogger.java:328) DEBUG : <rpc message-id="2" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<urn:create-subscription xmlns:urn="urn:ietf:params:xml:ns:netconf:notification:1.0"/>
</rpc>
]]>]]>
2024-10-01 07:13:34,302 (PowerLogger.java:328) DEBUG : <rpc message-id="11" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<get>
<filter type="subtree"/>
</get>
</rpc>
]]>]]>
2024-10-01 07:13:34,307 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Session 2: thread 0 event new RPC.
2024-10-01 07:13:34,310 (NetconfMessageReaderTask.java:149) INFO : Message received: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="2"><ok/></rpc-reply>
2024-10-01 07:13:34,310 (PowerLogger.java:348) DEBUG : The reply for session '2' is '<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="2"><ok/></rpc-reply>'
2024-10-01 07:13:34,312 (Slf4jLogConsumer.java:73) INFO : STDERR: [ERR]: SR: Invalid arguments for function "srsn_filter_subtree2xpath".
2024-10-01 07:13:34,312 (Slf4jLogConsumer.java:73) INFO : STDERR: [WRN]: SR: EV ORIGIN: "/ietf-netconf:get" "rpc" ID 2 priority 0 failed (Invalid argument).
2024-10-01 07:13:34,312 (Slf4jLogConsumer.java:73) INFO : STDERR: [ERR]: SR: User callback failed.
2024-10-01 07:13:34,312 (Slf4jLogConsumer.java:73) INFO : STDERR: [ERR]: NP: Failed to send an RPC (User callback failed).
2024-10-01 07:13:34,313 (AutomaticConnectImpl.java:49) INFO : [AUTOMATIC CONNECT] successfully re-subscribed
2024-10-01 07:13:34,313 (AutomaticConnectImpl.java:52) INFO : [AUTOMATIC CONNECT] re-sending message
2024-10-01 07:13:34,313 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Session 2: thread 0 event new RPC.
2024-10-01 07:13:34,313 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Session 2: thread 0 event reply error.
2024-10-01 07:13:34,313 (PowerLogger.java:328) DEBUG : <rpc message-id="4" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<edit-config>
<target>
<running/>
</target>
<config>
<netconf-server xmlns="urn:ietf:params:xml:ns:yang:ietf-netconf-server">
<listen>
<idle-timeout>180</idle-timeout>
<endpoints>
<endpoint>
<name>default-ssh</name>
<ssh>
<tcp-server-parameters>
<local-address>0.0.0.0</local-address>
<local-port>830</local-port>
<keepalives>
<idle-time>7200</idle-time>
<max-probes>9</max-probes>
<probe-interval>4</probe-interval>
</keepalives>
</tcp-server-parameters>
<ssh-server-parameters>
<server-identity>
<host-key>
<name>default-key</name>
<public-key>
<central-keystore-reference>genkey</central-keystore-reference>
</public-key>
</host-key>
</server-identity>
<client-authentication>
<users>
<user>
<name>netconf</name>
<keyboard-interactive xmlns="urn:cesnet:libnetconf2-netconf-server">
<use-system-auth/>
</keyboard-interactive>
</user>
</users>
</client-authentication>
</ssh-server-parameters>
</ssh>
</endpoint>
</endpoints>
</listen>
</netconf-server>
</config>
</edit-config>
</rpc>
]]>]]>
2024-10-01 07:13:34,322 (NetconfMessageReaderTask.java:149) INFO : Message received: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="11"><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">Invalid arguments for function "srsn_filter_subtree2xpath".</error-message></rpc-error><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">User callback failed.</error-message></rpc-error></rpc-reply>
2024-10-01 07:13:34,322 (PowerLogger.java:328) DEBUG : <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="11"><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">Invalid arguments for function "srsn_filter_subtree2xpath".</error-message></rpc-error><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">User callback failed.</error-message></rpc-error></rpc-reply>
2024-10-01 07:13:34,324 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: edit-config error-option "stop-on-error" not supported, rollback-on-error will be performed.
2024-10-01 07:13:34,327 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Session 2: thread 2 event new RPC.
2024-10-01 07:13:34,333 (NetconfMessageReaderTask.java:149) INFO : Message received: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="4"><ok/></rpc-reply>
2024-10-01 07:13:34,333 (PowerLogger.java:348) DEBUG : The reply for session '2' is '<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="4"><ok/></rpc-reply>'
2024-10-01 07:13:34,335 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Session 2: Received an SSH message "request-channel" of subtype "unknown".
2024-10-01 07:13:37,695 (PowerLogger.java:328) DEBUG : <rpc message-id="12" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<get>
<filter type="subtree"/>
</get>
</rpc>
]]>]]>
2024-10-01 07:13:37,743 (Slf4jLogConsumer.java:73) INFO : STDERR: [ERR]: SR: Invalid arguments for function "srsn_filter_subtree2xpath".
2024-10-01 07:13:37,743 (Slf4jLogConsumer.java:73) INFO : STDERR: [WRN]: SR: EV ORIGIN: "/ietf-netconf:get" "rpc" ID 3 priority 0 failed (Invalid argument).
2024-10-01 07:13:37,743 (Slf4jLogConsumer.java:73) INFO : STDERR: [ERR]: SR: User callback failed.
2024-10-01 07:13:37,743 (Slf4jLogConsumer.java:73) INFO : STDERR: [ERR]: NP: Failed to send an RPC (User callback failed).
2024-10-01 07:13:37,744 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Session 2: thread 1 event new RPC.
2024-10-01 07:13:37,744 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: NP: Session 2: thread 1 event reply error.
2024-10-01 07:13:37,758 (NetconfMessageReaderTask.java:149) INFO : Message received: <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="12"><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">Invalid arguments for function "srsn_filter_subtree2xpath".</error-message></rpc-error><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">User callback failed.</error-message></rpc-error></rpc-reply>
2024-10-01 07:13:37,758 (PowerLogger.java:328) DEBUG : <rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="12"><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">Invalid arguments for function "srsn_filter_subtree2xpath".</error-message></rpc-error><rpc-error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-severity>error</error-severity><error-message xml:lang="en">User callback failed.</error-message></rpc-error></rpc-reply>
2024-10-01 07:13:37,872 (Slf4jLogConsumer.java:73) INFO : STDERR: [INF]: LN: Session 2: Received an SSH message "request-channel" of subtype "unknown".
2024-10-01 07:13:39,307 (PowerLogger.java:328) DEBUG : <rpc message-id="13" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<get>
<filter type="subtree"/>
</get>
</rpc>
Any ideas why I do not see the event again. I am expecting same as previously this ( see below) or am I missing something?
br
//mike
<notification xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0">
<eventTime>2024-10-01T05:13:02.909470041+00:00</eventTime>
<netconf-config-change xmlns="urn:ietf:params:xml:ns:yang:ietf-netconf-notifications">
<changed-by>
<username>root</username>
<session-id>0</session-id>
</changed-by>
<datastore>running</datastore>
<edit>
<target xmlns:ncs="urn:ietf:params:xml:ns:yang:ietf-netconf-server">/ncs:netconf-server/ncs:listen/ncs:endpoints/ncs:endpoint[ncs:name='default-ssh']/ncs:ssh/ncs:tcp-server-parameters/ncs:keepalives/ncs:probe-interval</target>
<operation>replace</operation>
</edit>
</netconf-config-change>
michalvasko commented
What netopeer2 version are you using? Please update to the latest release if not already.
mpet commented
I am using v2.2.31.
It there a fix for notifications recently?
mpet commented
Never mind this was an issue on our side. Netopeer2 works as expected.