Skip to content

Netopeer2 not initiating second call-home #1787

Closed
Closed
Netopeer2 not initiating second call-home#1787
Labels
is:bugBug description.status:completedFrom the developer perspective, the issue was solved (bug fixed, question answered,...)

Description

@Krisscut
Krisscut
opened on Feb 20, 2026

Hello !

I'm trying to upgrade netopeer2-2.4.5 -> netopeer2-v2.7.0-12-g2809ede.
(NOTE: I use versions from the devel to include some fixes related to the latest official release)

I have an issue where in the case of a configuration with 2 callhome endpoints, I have around 30% unstability rate in a test due to the second callhome not being initiated, and I didn't have it on previous release.
It seems to happen whenever the first callhome on first endpoint is a success, then second callhome is never attempted.
If both initial callhome fails, then later one both callhome can be achieved successfully.

Example log snippet failing case (Connect on first endpoint, never attempts second one):

Image

Example log snippet working case (note the attempts on both endpoints):

Image

Configuration used:
xmlCallHomeTree.xml

Activity

  1. Krisscut commented on Feb 20, 2026

    @Krisscut
    Krisscut
    on Feb 20, 2026
    Author

    This may not be related to the latest release actually. In the past there was an issue where when callhome is configured, the callhome would be initiated before configuration was fully loaded (at least it seemed to be that way !), causing error down the line.

    So a workaround was introduced where the configuration was loaded in 2 ways:
    Initial configuration with "fake ips" which will always fail to connect, for instance 127.0.0.1
    Then after a small delay, the ip would be edited to use the real ones.

    Rebasing to the latest release, I removed that workaround, so I encountered the issue mentioned in the first message.

    If I perform again the same work around, I don't reproduce the error anymore. So issue may have already been there since a few release but hidden by the workaround in my env.

    I hope this helps understand the issue.

  2. michalvasko commented on Feb 27, 2026

    @michalvasko
    michalvasko
    on Feb 27, 2026
    Member

    I have failed to reproduce your issue and am generally getting very different messages with more details such as

    [INF]: LN: Call Home client "default-client" endpoint "default-ssh" connecting...
[INF]: LN: Call Home client "default-client2" endpoint "default-ssh" connecting...
[INF]: LN: Trying to connect via IPv6 to ::1:4334.
[INF]: LN: Trying to connect via IPv6 to ::1:4335.
[INF]: SR: Triggering "libnetconf2-netconf-server" "done" event on enabled data.
[INF]: LN: Connection error (Connection refused).
[INF]: LN: Successfully connected to [localhost]:4334 over IPv6.
[INF]: LN: Trying to connect via IPv4 to 127.0.0.1:4335.
[INF]: LN: Connection error (Connection refused).
[INF]: LN: Received an SSH message "request-service" of subtype "ssh-userauth".
[INF]: LN: Received an SSH message "request-auth" of subtype "none".
[INF]: LN: Received an SSH message "request-auth" of subtype "publickey".
[INF]: LN: Received an SSH message "request-auth" of subtype "publickey".
[INF]: LN: User "vasko" authenticated.
[INF]: LN: Received an SSH message "request-channel-open" of subtype "session".
[INF]: LN: Received an SSH message "request-channel" of subtype "subsystem".
[INF]: LN: Call Home client "default-client2" timeout of 5 seconds expired, reconnecting.
[INF]: LN: Trying to connect via IPv6 to ::1:4335.
[INF]: LN: Connection error (Connection refused).
[INF]: LN: Trying to connect via IPv4 to 127.0.0.1:4335.
[INF]: LN: Session 1: Call Home client "default-client" session 1 established.
[INF]: LN: Connection error (Connection refused).

    which leads me to think you are using an old version of libnetconf2.

  3. michalvasko
    added
    is:bugBug description.
    on Feb 27, 2026

  4. Krisscut commented on Feb 27, 2026

    @Krisscut
    Krisscut
    on Feb 27, 2026
    Author

    I'm using version libnetconf2-v4.1.2-34-g50defb3 which is the devel one but not yet the latest one. (I didn't want to include some major changes & refactoring from latest devel/libyang)

    Are you already listening for the callhome on your first endpoint before it tries to connect initially ?

    I think here you are having the same kind of traces as my "working case" because we can see both "Trying to connect" before the "Successfully connected" is reached on the first link.
    I only had around 30% unstability rate on this.

  5. michalvasko commented on Mar 2, 2026

    @michalvasko
    michalvasko
    on Mar 2, 2026
    Member

    Are you already listening for the callhome on your first endpoint before it tries to connect initially ?

    In that case there is a dead-lock that results in a timeout that will be fixed later, I am not able to currently. But I have never observed the behavior you are describing.

  6. Krisscut commented on Mar 4, 2026

    @Krisscut
    Krisscut
    on Mar 4, 2026
    Author

    Do you think of some potentials issue that I could confirm by maybe adding some debug traces on my env to help with investigation ?
    When I have more time I might try to deep dive on this by adding traces by myself to try to understand where it is stuck, but not sure when I can do this.

  7. michalvasko commented on Mar 4, 2026

    @michalvasko
    michalvasko
    on Mar 4, 2026
    Member

    Best to check with gdb where the threads are stuck, which should actually be enough if you post the stack trace of each thread. But I am still wondering why you don't see any messages such as

    [INF]: LN: Call Home client "default-client" endpoint "default-ssh" connecting...
  8. Roytak
    added a commit that references this issue on Mar 11, 2026

    session server BUGFIX call home deadlock

    7793771
  9. michalvasko
    added a commit that references this issue on Mar 11, 2026

    session server BUGFIX call home deadlock

    e386501

  10. Roytak commented on Mar 11, 2026

    @Roytak
    Roytak
    on Mar 11, 2026
    Contributor

    Hello, should be fixed by CESNET/libnetconf2#581, could you please try it and let us know? Thank you.

  11. Krisscut commented on Mar 24, 2026

    @Krisscut
    Krisscut
    on Mar 24, 2026
    Author

    Hi !

    Unfortunately I didn't have time yet to test these modifications, but I will let you know if it's better !
    Thanks for taking a look at this !

  12. Krisscut commented on Mar 27, 2026

    @Krisscut
    Krisscut
    on Mar 27, 2026
    Author

    Hello,

    I applied the fix as a patch on my version, and I can confirm it solves the issue.
    I executed the test where I encountered the issue 500 times and nearly got a flawless run:

    Image

    So to me it looks like a great improvement !

    Both failure I got are related to a session where I connect on netopeer2 to establish a session. (Initially one session is established by callhome, then a second one is done with connect)

    First one

    �[42C2026-03-27T10:34:05.743923+00:00 
�[0K> connect --host=172.1.1.10 --login netconf
�[43C
2026-03-27T10:34:15.743936+00:00 nc ERROR: SSH connect timeout.
 cmd_connect: Connecting to the 172.1.1.10:830 as user "netconf" failed.

    [ Exchanges of schemas ]

2026-03-27 10:34:05.314 [INF]: SR: There are no subscribers for "netopeer-notifications" notifications.
2026-03-27 10:34:05.315 [INF]: NP: Generated new event (post get-schema).
2026-03-27 10:34:05.316 [INF]: NP: Session 1: thread 1 event new RPC.
2026-03-27 10:34:18.358 [INF]: LN: Accepted a connection on 172.1.1.10:830 from 172.1.1.5:48530.
2026-03-27 10:34:18.365 [INF]: LN: Call Home client "NC-Client-2" timeout of 5 seconds expired, reconnecting.
2026-03-27 10:34:18.365 [INF]: LN: Trying to connect via IPv4 to 172.1.1.8:443.
2026-03-27 10:34:18.365 [INF]: LN: Connection error (Connection refused).
2026-03-27 10:34:18.365 [INF]: LN: Call Home client "NC-Client-2" timeout of 5 seconds expired, reconnecting.
2026-03-27 10:34:18.366 [INF]: LN: Trying to connect via IPv4 to 172.1.1.8:443.
2026-03-27 10:34:18.367 [INF]: LN: Connection error (Connection refused).
2026-03-27 10:34:18.367 [INF]: SR: There are no subscribers for "netopeer-notifications" notifications.
2026-03-27 10:34:18.367 [WRN]: LN: SSH: ssh_packet_disconnect_callback: Received SSH_MSG_DISCONNECT: 11:Bye Bye
2026-03-27 10:34:18.368 [WRN]: LN: SSH: ssh_socket_exception_callback: Socket exception callback: 2 (2)
2026-03-27 10:34:18.368 [WRN]: LN: SSH: ssh_socket_exception_callback: Socket error: No such file or directory
2026-03-27 10:34:18.368 [ERR]: LN: SSH key exchange error (Socket error: No such file or directory).
2026-03-27 10:34:19.030 [WRN]: LN: SSH: ssh_socket_exception_callback: Socket exception callback: 1 (0)
2026-03-27 10:34:19.031 [WRN]: LN: SSH: ssh_socket_exception_callback: Socket error: disconnected
2026-03-27 10:34:19.031 [ERR]: LN: Session 1: SSH channel poll error (Socket error: disconnected).
2026-03-27 10:34:19.031 [INF]: NP: Session 1: thread 1 event session terminated.
2026-03-27 10:34:19.751 [INF]: LN: Call Home client "NC-Client-2" timeout of 5 seconds expired, reconnecting.
2026-03-27 10:34:19.751 [INF]: LN: Call Home client "NC-Client-2" endpoint "default-ssh" failed connection attempt limit 3 reached.
2026-03-27 10:34:19.751 [INF]: LN: Call Home client "NC-Client-2" endpoint "default-ssh" connecting...
2026-03-27 10:34:19.751 [INF]: LN: Trying to connect via IPv4 to 172.1.1.8:443.
2026-03-27 10:34:19.752 [INF]: LN: Connection error (Connection refused).
2026-03-27 10:34:19.890 [INF]: LN: Call Home client "NC-Client-1" session terminated.
2026-03-27 10:34:19.890 [INF]: LN: Call Home client "NC-Client-1" endpoint "default-ssh" connecting...
2026-03-27 10:34:19.890 [INF]: LN: Trying to connect via IPv4 to 172.1.1.5:4334.
2026-03-27 10:34:19.890 [INF]: LN: Connection error (Connection refused).

    Second one

    �[42C2026-03-27T11:26:05.860379+00:00 
�[0K> connect --host=172.1.1.10 --login netconf
�[43C
2026-03-27T11:26:31.277431+00:00 nc ERROR: SSH connect timeout.
2026-03-27T11:26:31.414713+00:00 cmd_connect: Connecting to the 172.1.1.10:830 as user "netconf" failed.

    [Schema exchange]
2026-03-27 11:26:05.505 SR: There are no subscribers for "netopeer-notifications" notifications.
2026-03-27 11:26:05.505 NP: Generated new event (post get-schema).
2026-03-27 11:26:05.507 NP: Session 1: thread 1 event new RPC.
2026-03-27 11:26:31.419 LN: nc_ps_poll: failed to wait for a pollsession condition (Connection timed out).
2026-03-27 11:26:31.420 LN: nc_ps_poll: failed to wait for a pollsession condition (Connection timed out).
2026-03-27 11:26:31.421 LN: Accepted a connection on 172.1.1.10:830 from 172.1.1.5:35632.
2026-03-27 11:26:31.421 LN: nc_ps_poll: failed to wait for a pollsession condition (Connection timed out).
2026-03-27 11:26:31.421 LN: nc_ps_poll: failed to wait for a pollsession condition (Connection timed out).
2026-03-27 11:26:31.421 LN: nc_ps_poll: failed to wait for a pollsession condition (Connection timed out).
2026-03-27 11:26:31.421 LN: nc_ps_poll: failed to wait for a pollsession condition (Connection timed out).
2026-03-27 11:26:31.421 LN: SSH: ssh_packet_disconnect_callback: Received SSH_MSG_DISCONNECT: 11:Bye Bye
2026-03-27 11:26:31.421 LN: SSH key exchange error (Received SSH_MSG_DISCONNECT: 11:Bye Bye).
2026-03-27 11:26:39.983 SR: EV ORIGIN: "/sysrepo-monitoring:sysrepo-state/connection[cid='58']/nacm-stats" "oper get" index 0 ID 1524 published.
2026-03-27 11:26:39.984 SR: EV ORIGIN: "/sysrepo-monitoring:sysrepo-state/connection[cid='58']/nacm-stats" "oper get" index 0 ID 1524 succeeded.
2026-03-27 11:26:39.984 SR: EV ORIGIN: "/sysrepo-monitoring:sysrepo-state/connection[cid='58']/nacm-stats" "oper get" index 0 ID 1525 published.
2026-03-27 11:26:39.985 SR: EV ORIGIN: "/sysrepo-monitoring:sysrepo-state/connection[cid='58']/nacm-stats" "oper get" index 0 ID 1525 succeeded.

    It might be a local environment issue (slowness of the host), it's not the same problem as treated in this issue I think.

    Thanks for the support !

  13. michalvasko commented on Mar 27, 2026

    @michalvasko
    michalvasko
    on Mar 27, 2026
    Member

    Seems good now. The first log problems start with Received SSH_MSG_DISCONNECT meaning it was the client that initiated the termination. Not sure what the following error No such file or directory is supposed to mean, never seen it before.

    The second issue is a synchronization problem when there are too many threads competing for access to the pollsession structure. Probably just an unfortunate scheduler run but in my experience this never resulted in any actual problem other than the error being printed.

  14. michalvasko
    added
    status:completedFrom the developer perspective, the issue was solved (bug fixed, question answered,...)
    on Mar 27, 2026
  15. michalvasko
    closed this as completedin e386501on Mar 31, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    is:bugBug description.status:completedFrom the developer perspective, the issue was solved (bug fixed, question answered,...)

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions