sysrepo icon indicating copy to clipboard operation
sysrepo copied to clipboard

Published 20 hours ago • verified publisher icon sysrepo

AddressSanitizer: heap-use-after-free via Netopeer2's test suite

Open jktjkt opened this issue 2 years ago • 3 comments

I'm on the latest devel of everything, plus #2851:

  • CESNET/libyang@ba8cae2e
  • CESNET/libnetconf2@4d9d799
  • sysrepo 5ec23c35d801740ce991e167104628e89f5d992c (devel plus #2851)
  • CESNET/Netopeer2@d6dc2f4
 8/20 Test  #8: test_subscribe_param .............Subprocess aborted***Exception:  19.20 sec
[==========] Running 11 test(s).
[ RUN      ] test_stop_time_invalid
[       OK ] test_stop_time_invalid
[ RUN      ] test_start_time_invalid
[       OK ] test_start_time_invalid
[ RUN      ] test_stop_time_no_start_time
[       OK ] test_stop_time_no_start_time
[ RUN      ] test_basic_replay
[       OK ] test_basic_replay
[ RUN      ] test_replay_real_time
[       OK ] test_replay_real_time
[ RUN      ] test_stop_time
[       OK ] test_stop_time
[ RUN      ] test_stop_time_sub_end
Session 9 [ERR]: Communication file descriptor (9) unexpectedly closed.
0x6 != 0
[   LINE   ] --- /home/jkt/work/cesnet/gerrit/github/CESNET/Netopeer2/tests/test_subscribe_param.c:54: error: Failure!

And here's the end of the log from Netopeer2/tests/repositories/test_subscribe_param/np2.log:

[INF]: LN: Accepted a connection on ./tests/repositories/test_subscribe_param/np2.sock.
[WRN]: NP: Session 9 uses a transport protocol not supported by ietf-netconf-monitoring, will not be monitored.
[INF]: SR: Session 93 (user "jkt", CID 28) created.
[INF]: SR: There are no subscribers for "ietf-netconf-notifications" notifications.
[INF]: NP: Generated new event (netconf-session-start).
[INF]: LN: Session 9: Schema "ietf-datastores@<any>" was requested.
[INF]: NP: Session 9: thread 4 event new RPC.
[INF]: LN: Session 9: Schema "ietf-origin@<any>" was requested.
[INF]: NP: Session 9: thread 1 event new RPC.
[INF]: LN: Session 9: Schema "ietf-netconf-with-defaults@2011-06-01" was requested.
[INF]: NP: Session 9: thread 1 event new RPC.
[INF]: SR: Published event "rpc" "/ietf-netconf-nmda:get-data" with ID 9 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf-nmda:get-data" "rpc" event with ID 9 priority 0 (remaining 1 subscribers).
[INF]: SR: Successful processing of "rpc" event with ID 9 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 9 priority 0 succeeded.
[INF]: NP: Session 9: thread 1 event new RPC.
[INF]: LN: Session 9: Schema "sysrepo@2021-10-08" was requested.
[INF]: NP: Session 9: thread 4 event new RPC.
[INF]: LN: Session 9: Schema "sysrepo-monitoring@2022-04-08" was requested.
[INF]: NP: Session 9: thread 4 event new RPC.
[INF]: LN: Session 9: Schema "sysrepo-plugind@2022-03-10" was requested.
[INF]: NP: Session 9: thread 4 event new RPC.
[INF]: LN: Session 9: Schema "ietf-netconf-notifications@2012-02-06" was requested.
[INF]: NP: Session 9: thread 4 event new RPC.
[INF]: LN: Session 9: Schema "notif1@<any>" was requested.
[INF]: NP: Session 9: thread 3 event new RPC.
[INF]: LN: Session 9: Schema "notif2@<any>" was requested.
[INF]: NP: Session 9: thread 3 event new RPC.
[INF]: SR: Published event "rpc" "/notifications:create-subscription" with ID 7 priority 0 for 1 subscribers.
[INF]: SR: Processing "/notifications:create-subscription" "rpc" event with ID 7 priority 0 (remaining 1 subscribers).
[WRN]: SR: Module "ietf-yang-library" does not support notification replay.
[WRN]: SR: Module "ietf-netconf-notifications" does not support notification replay.
[WRN]: SR: Module "nc-notifications" does not support notification replay.
[WRN]: SR: Module "ietf-keystore" does not support notification replay.
[WRN]: SR: Module "ietf-truststore" does not support notification replay.
[WRN]: SR: Module "ietf-network-instance" does not support notification replay.
=================================================================
==1737344==ERROR: AddressSanitizer: heap-use-after-free on address 0x60400012f320 at pc 0x7fb70ca6ba22 bp 0x7fb706bf77b0 sp 0x7fb706bf77a8
READ of size 4 at 0x60400012f320 thread T8
    #0 0x7fb70ca6ba21 in sr_shmsub_notif_listen_module_stop_time /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3672:28
    #1 0x7fb70c9383b5 in sr_subscription_process_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:4004:25
    #2 0x7fb70ca6cbc8 in sr_shmsub_listen_thread /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3783:15
    #3 0x7fb70c5aeff1 in start_thread (/nix/store/f6kvkdzp6qfjm6h94d0jgfvm4r06xcaq-glibc-2.34-210/lib/libc.so.6+0x85ff1)
    #4 0x7fb70c631bfb in __GI___clone3 (/nix/store/f6kvkdzp6qfjm6h94d0jgfvm4r06xcaq-glibc-2.34-210/lib/libc.so.6+0x108bfb)

0x60400012f320 is located 16 bytes inside of 48-byte region [0x60400012f310,0x60400012f340)
freed by thread T1 here:
    #0 0x4cf8b7 in __interceptor_realloc (/home/jkt/work/prog/_build/czechlight-clang-asan-ubsan-ly2/Netopeer2/netopeer2-server+0x4cf8b7)
    #1 0x7fb70c959c40 in sr_subscr_notif_sub_add /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/common.c:409:18
    #2 0x7fb70c94bd5b in _sr_notif_subscribe /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5690:21
    #3 0x7fb70c94c50b in sr_notif_subscribe_tree /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5742:12
    #4 0x7fb70ca663ce in sr_shmsub_rpc_listen_call_callback /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3062:21
    #5 0x7fb70ca63076 in sr_shmsub_rpc_listen_process_rpc_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3347:25
    #6 0x7fb70c9381a1 in sr_subscription_process_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:3989:25
    #7 0x7fb70ca6cbc8 in sr_shmsub_listen_thread /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3783:15
    #8 0x7fb70c5aeff1 in start_thread (/nix/store/f6kvkdzp6qfjm6h94d0jgfvm4r06xcaq-glibc-2.34-210/lib/libc.so.6+0x85ff1)

previously allocated by thread T1 here:
    #0 0x4cf8b7 in __interceptor_realloc (/home/jkt/work/prog/_build/czechlight-clang-asan-ubsan-ly2/Netopeer2/netopeer2-server+0x4cf8b7)
    #1 0x7fb70c959c40 in sr_subscr_notif_sub_add /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/common.c:409:18
    #2 0x7fb70c94bd5b in _sr_notif_subscribe /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5690:21
    #3 0x7fb70c94c50b in sr_notif_subscribe_tree /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5742:12
    #4 0x7fb70ca663ce in sr_shmsub_rpc_listen_call_callback /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3062:21
    #5 0x7fb70ca63076 in sr_shmsub_rpc_listen_process_rpc_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3347:25
    #6 0x7fb70c9381a1 in sr_subscription_process_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:3989:25
    #7 0x7fb70ca6cbc8 in sr_shmsub_listen_thread /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3783:15
    #8 0x7fb70c5aeff1 in start_thread (/nix/store/f6kvkdzp6qfjm6h94d0jgfvm4r06xcaq-glibc-2.34-210/lib/libc.so.6+0x85ff1)

Thread T8 created by T1 here:
    #0 0x440542 in __interceptor_pthread_create (/home/jkt/work/prog/_build/czechlight-clang-asan-ubsan-ly2/Netopeer2/netopeer2-server+0x440542)
    #1 0x7fb70c93ca00 in sr_subscr_new /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:4542:15
    #2 0x7fb70c94b9e0 in _sr_notif_subscribe /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5656:25
    #3 0x7fb70c94c50b in sr_notif_subscribe_tree /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5742:12
    #4 0x7fb70ca663ce in sr_shmsub_rpc_listen_call_callback /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3062:21
    #5 0x7fb70ca63076 in sr_shmsub_rpc_listen_process_rpc_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3347:25
    #6 0x7fb70c9381a1 in sr_subscription_process_events /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:3989:25
    #7 0x7fb70ca6cbc8 in sr_shmsub_listen_thread /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3783:15
    #8 0x7fb70c5aeff1 in start_thread (/nix/store/f6kvkdzp6qfjm6h94d0jgfvm4r06xcaq-glibc-2.34-210/lib/libc.so.6+0x85ff1)

Thread T1 created by T0 here:
LLVMSymbolizer: error reading file: No such file or directory
    #0 0x440542 in __interceptor_pthread_create (/home/jkt/work/prog/_build/czechlight-clang-asan-ubsan-ly2/Netopeer2/netopeer2-server+0x440542)
    #1 0x7fb70c93ca00 in sr_subscr_new /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:4542:15
    #2 0x7fb70c9469e5 in _sr_rpc_subscribe /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5247:25
    #3 0x7fb70c947358 in sr_rpc_subscribe_tree /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/sysrepo.c:5314:12
    #4 0x7fb70c552236 in __libc_start_call_main (/nix/store/f6kvkdzp6qfjm6h94d0jgfvm4r06xcaq-glibc-2.34-210/lib/libc.so.6+0x29236)
    #5 0x7ffe90fe00ac  ([stack]+0x200ac)

SUMMARY: AddressSanitizer: heap-use-after-free /home/jkt/work/cesnet/gerrit/github/sysrepo/sysrepo/src/shm_sub.c:3672:28 in sr_shmsub_notif_listen_module_stop_time
Shadow bytes around the buggy address:
  0x0c088001de10: fa fa fd fd fd fd fd fa fa fa fd fd fd fd fd fd
  0x0c088001de20: fa fa fd fd fd fd fd fd fa fa fd fd fd fd fd fd
  0x0c088001de30: fa fa fd fd fd fd fd fd fa fa fd fd fd fd fd fa
  0x0c088001de40: fa fa fd fd fd fd fd fd fa fa fd fd fd fd fd fd
  0x0c088001de50: fa fa fd fd fd fd fd fd fa fa fd fd fd fd fd fd
=>0x0c088001de60: fa fa fd fd[fd]fd fd fd fa fa fd fd fd fd fd fd
  0x0c088001de70: fa fa fd fd fd fd fd fd fa fa fd fd fd fd fd fa
  0x0c088001de80: fa fa fd fd fd fd fd fa fa fa fd fd fd fd fd fd
  0x0c088001de90: fa fa fd fd fd fd fd fd fa fa fd fd fd fd fd fd
  0x0c088001dea0: fa fa fd fd fd fd fd fa fa fa fd fd fd fd fd fd
  0x0c088001deb0: fa fa fd fd fd fd fd fa fa fa fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==1737344==ABORTING

jktjkt avatar Jun 26 '22 21:06 jktjkt

I managed to reproduce it but completely fail to understand how it can occur, there is SUBS READ lock when checking the stop time and SUBS WRITE lock when reallocating the subscriptions. When I added some messages I can no longer reproduce it and it was difficult even before. Do you see the error often enough?

michalvasko avatar Jul 13 '22 15:07 michalvasko

I'm afraid I cannot quantify that; we're getting occasional failures in the CI, but the sources vary.

jktjkt avatar Jul 16 '22 11:07 jktjkt

There have been quite a lot of fixes implemented in netopeer2-server recently and I cannot reproduce this at all now. Please, use the latest devel branches and let me know if you still encounter this problem.

michalvasko avatar Jul 21 '22 12:07 michalvasko