Server segfaults when a session with active notification subscription disconnects

[jktjkt]

1. start netopeer2-server
2. start the client, connect, subscribe
3. subscribe from the client to a notification that is triggered by a custom app
4. no notification is emitted
5. quit the client
6. the server segfaults

netopeer2-server[605]: Session 1: sending message:

##

netopeer2-server[605]: Session 1: thread 3 event new RPC.
netopeer2-server[605]: Session 1: received message:
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="24"><create-subscription xmlns="urn:ietf:params:xml:ns:netconf:notification:1.0"><filter type="xpath" xmlns:czechlight-roadm-v2="http://czechlight.cesnet.cz/netconf/roadm/v2" select="/czechlight-roadm-v2:*"/></create-subscription></rpc>
netopeer2-server[605]: Resolving unresolved data nodes and their constraints...
netopeer2-server[605]: All data nodes and constraints resolved.
netopeer2-server[605]: Session 1: sending message:

#92

netopeer2-server[605]: Session 1: sending message:
<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="24"><ok/></rpc-reply>
netopeer2-server[605]: Session 1: sending message:

##

netopeer2-server[605]: Session 1: thread 1 event new RPC.

netopeer2-server[605]: Session 1: received message:
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="25"><close-session xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"/></rpc>
netopeer2-server[605]: Session 1: sending message:

#92

netopeer2-server[605]: Session 1: sending message:
<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="25"><ok/></rpc-reply>
netopeer2-server[605]: Session 1: sending message:

##

netopeer2-server[605]: Session 1: polling an invalid session.
netopeer2-server[605]: Session 1: thread 3 event session terminated.
netopeer2-server[605]: Session 1: invalid session to write to.
netopeer2-server[605]: Session 1: failed to write notification.
netopeer2-server[605]: (cl_request_process:492) Sending event-notification request.
netopeer2-server[605]: (cl_request_process:515) event-notification request sent, waiting for response.
netopeer2-server[605]: Session 1: thread 2 event new RPC.
netopeer2-server[605]: Session 1: thread 2 event session terminated.
netopeer2-server[605]: Internal error (/home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/netconf_monitoring.c:77)

Thread 4 "netopeer2-serve" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xb5cfeb40 (LWP 620)]
__memmove_ia32 () at ../sysdeps/i386/i686/multiarch/../memmove.S:71
71      ../sysdeps/i386/i686/multiarch/../memmove.S: No such file or directory.
(gdb) 
(gdb) bt
#0  __memmove_ia32 () at ../sysdeps/i386/i686/multiarch/../memmove.S:71
#1  0x08054f1e in ncm_session_del (session=0x8676110) at /home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/netconf_monitoring.c:172
#2  0x0804ed43 in np2srv_del_session_clb (session=0x8676110) at /home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/main.c:663
#3  0x0804ff5d in worker_thread (arg=0x8675ef0) at /home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/main.c:1095
#4  0xb76e727a in start_thread (arg=0xb5cfeb40) at pthread_create.c:456
#5  0xb732f846 in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:110

When trying to reproduce, I sometimes get a lisghtly different error:

netopeer2-server[625]: Session 3: thread 4 event new RPC.
netopeer2-server[625]: Session 3: received message:
<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="25"><close-session xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"/></rpc>
netopeer2-server[625]: Session 3: sending message:

#92

netopeer2-server[625]: Session 3: sending message:
<rpc-reply xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="25"><ok/></rpc-reply>
netopeer2-server[625]: Session 3: sending message:

##

netopeer2-server[625]: Session 3: thread 4 event new RPC.
netopeer2-server[625]: Session 3: polling an invalid session.
netopeer2-server[625]: Session 3: thread 3 event session terminated.
netopeer2-server[625]: Session 3: invalid session to write to.
netopeer2-server[625]: Session 3: failed to write notification.
netopeer2-server[625]: Session 3: polling an invalid session.
netopeer2-server[625]: Session 3: thread 2 event session terminated.
netopeer2-server[625]: Session 3: polling an invalid session.
netopeer2-server[625]: Session 3: thread 0 event session terminated.
netopeer2-server[625]: Session 3: polling an invalid session.
netopeer2-server[625]: Session 3: thread 1 event session terminated.
netopeer2-server[625]: (cl_request_process:492) Sending event-notification request.
netopeer2-server[625]: (cl_request_process:515) event-notification request sent, waiting for response.
netopeer2-server[625]: Internal error (/home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/netconf_monitoring.c:77)
netopeer2-server[625]: Session 3: thread 4 event session terminated.
netopeer2-server[625]: (cl_sm_fd_read_data:1161) fd 8 readable
netopeer2-server[625]: (cl_sm_fd_read_data:1175) 402 bytes of data received on fd 8
netopeer2-server[625]: (cl_sm_fd_read_data:1185) fd 8 would block
netopeer2-server[625]: (cl_sm_conn_in_buff_process:1112) New message of size 398 bytes received.
netopeer2-server[625]: (cl_sm_event_notif_process:966) Received an event notification type=0 for subscription id=441287285.
netopeer2-server[625]: (cl_sm_event_notif_process:1005) Calling event notification callback for subscription id=441287285.
netopeer2-server[625]: Received a realtime notification "/ietf-netconf-notifications:netconf-session-end" (1495551603).
*** Error in `/usr/bin/netopeer2-server': malloc(): memory corruption: 0xb5303dd0 ***

Thread 4 "netopeer2-serve" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xb5cfeb40 (LWP 628)]
__memmove_ia32 () at ../sysdeps/i386/i686/multiarch/../memmove.S:71
71      ../sysdeps/i386/i686/multiarch/../memmove.S: No such file or directory.
(gdb) 
(gdb) 
(gdb) 
(gdb) 
(gdb) bt
#0  __memmove_ia32 () at ../sysdeps/i386/i686/multiarch/../memmove.S:71
#1  0x08054f1e in ncm_session_del (session=0xb65061a0) at /home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/netconf_monitoring.c:172
#2  0x0804ed43 in np2srv_del_session_clb (session=0xb65061a0) at /home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/main.c:663
#3  0x0804ff5d in worker_thread (arg=0x9b42e40) at /home/jkt/work/prog/buildroot/out-epia-geode/build/netopeer2-server-custom/server/main.c:1095
#4  0xb776d27a in start_thread (arg=0xb5cfeb40) at pthread_create.c:456
#5  0xb73b5846 in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:110

• netopeer2 278ebfd
• CESNET/libnetconf2@cbf256a
• sysrepo/sysrepo@4b4a52a
• CESNET/libyang@27b91d0

[jktjkt]

I've traced this a bit more, and it looks that the the ncm_session_del is being called from several worker threads. I see that proper lock are in place, so it isn't a race per se, but the code fails when the (second and other subsequent) thread calls find_session_idx which returns an uninitialized integer as a result because that session cannot be found anymore. I have no clue whether it's OK to call that handler from all threads sequentially, nor why that happens.

[michalvasko]

Hi,
this likely had nothing to do with notifications but was a polling problem of libnetconf2, hopefully fixed now.

Regards,
Michal

[gurugod]

hi @michalvasko
Facing similar issue in Netopeer2-0.5-r1
Code is failing in op_ntf_unsubscribe()
assert(i < subscribers.num);
What can you suggest to avoid Netopper-2 crash ?
And occurance of crash is very random .

Using below versions:
sysrepo-0.7.4 , libyang-1.0-r4 , libnetconf2-0.11-r1

Thanks,
Gaurav J.

[michalvasko]

Hi,
I suggest you update the whole stack because you are using ancient versions. Not sure what answer did you expect when using now almost 2 years old software, which is being updated.

Regards,
Michal