search

CESNET / netopeer2

NETCONF toolset
BSD 3-Clause "New" or "Revised" License
300 stars 188 forks source link

crash in netopeer2-server/sysrepo #538

Closed igortern closed 4 years ago

igortern commented 4 years ago

Hi,

valgrind run didn't yield any additional info, just reported that address accessed in shm_main.c:995 is invalid and "is not stack'd, malloc'd or (recently) free'd" I can reproduce is easily in my setup, but not sure how to reduce it to simple steps. If crash log below is insufficient, please let me know and I'll try to find simpler steps.

Crash log:

[INF]: LN: Accepted a connection on 0.0.0.0:10830.
[INF]: SR: Session 3 (user "root") created.
[2020/01/23 13:46:57.537100, 2] ssh_pki_import_privkey_base64:  Trying to decode privkey passphrase=false
[2020/01/23 13:46:57.542749, 2] ssh_server_connection_callback:  SSH client banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/23 13:46:57.542796, 2] ssh_analyze_banner:  Analyzing banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/23 13:46:57.542862, 2] ssh_kex_select_methods:  Negotiated ecdh-sha2-nistp521,ssh-rsa,aes128-ctr,aes128-ctr,hmac-sha1,hmac-sha1,none,none,,
[2020/01/23 13:46:57.637610, 2] ssh_packet_server_ecdh_init:  SSH_MSG_KEXDH_REPLY sent
[2020/01/23 13:46:57.645817, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/23 13:46:57.645850, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/23 13:46:57.645895, 2] ssh_packet_server_ecdh_init:  SSH_MSG_NEWKEYS sent
[2020/01/23 13:46:57.662895, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[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 "interactive".
[2020/01/23 13:46:57.681936, 2] ssh_message_auth_interactive_request:  Warning: Got a keyboard-interactive response but it seems we didn't send the request.
[INF]: LN: Received an SSH message "request-auth" of subtype "interactive".
[INF]: LN: User "igort" authenticated.
[INF]: LN: Received an SSH message "request-channel-open" of subtype "session".
[INF]: LN: Received an SSH message "request-channel" of subtype "subsystem".
[2020/01/23 13:46:57.699372, 2] grow_window:  growing window (channel 43:0) to 1280000 bytes
[INF]: SR: Session 4 (user "root") created.
[INF]: SR: There are no subscribers for "ietf-netconf-notifications" notifications.
[INF]: NP: Generated new event (netconf-session-start).
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 5 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "ietf-yang-library" event with ID 1.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 1 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 2 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 6 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 2 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 2 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "nc-notifications" event with ID 1.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 2 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 2 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 0 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 7 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 3 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 3 priority 0 (remaining 1 subscribers).
[INF]: SR: Finished processing "rpc" event with ID 3 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 3 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[WRN]: LY: Unable to print anydata content (type 32) as XML.
[INF]: NP: Session 1: thread 4 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 8 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/notifications:create-subscription" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[New Thread 0x7ffff1982700 (LWP 17162)]
[ERR]: SR: Internal error (/home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605).
[WRN]: SR: Cleaning up after a non-existent sysrepo client with PID 1953459759.

Thread 2 "netopeer2-serve" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff4988700 (LWP 17109)]
0x00007ffff73f792f in sr_shmmain_state_recover (conn=0x61fba0) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:995
995                     if ((mod_locks[j][k].mode == SR_LOCK_READ) || (mod_locks[j][k].mode == SR_LOCK_WRITE)) {
(gdb) 
(gdb) 
(gdb) 
(gdb) 
(gdb) bt
#0  0x00007ffff73f792f in sr_shmmain_state_recover (conn=0x61fba0) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:995
#1  0x00007ffff73fad20 in sr_shmmain_lock_remap (conn=0x61fba0, mode=SR_LOCK_WRITE, remap=0x1, lydmods=0x0, func=0x7ffff740a950 <__func__.9085> "_sr_event_notif_subscribe")
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:1964
#2  0x00007ffff73d0f2a in _sr_event_notif_subscribe (session=0x90ce10, mod_name=0x638460 "ietf-netconf-notifications", xpath=0x0, start_time=0x0, stop_time=0x0, callback=0x0, 
    tree_callback=0x40a792 <np2srv_ntf_new_cb>, private_data=0x653e30, opts=0x1, subscription=0x61e7e0 <np2srv+32>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4340
#3  0x00007ffff73d12b1 in sr_event_notif_subscribe_tree (session=0x90ce10, module_name=0x638460 "ietf-netconf-notifications", xpath=0x0, start_time=0x0, stop_time=0x0, 
    callback=0x40a792 <np2srv_ntf_new_cb>, private_data=0x653e30, opts=0x1, subscription=0x61e7e0 <np2srv+32>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4420
#4  0x000000000040d925 in np2srv_rpc_subscribe_cb (session=0x7ffff4987c40, UNUSED_op_path=0x62b7e0 "/notifications:create-subscription", input=0x7fffe00012f0, 
    UNUSED_event=SR_EV_RPC, UNUSED_request_id=0x1, UNUSED_output=0x7fffe00017e0, UNUSED_private_data=0x0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/netconf.c:718
#5  0x00007ffff7404cab in sr_shmsub_rpc_listen_call_callback (rpc_sub=0x629530, tmp_sess=0x7ffff4987c40, input_op=0x7fffe00012f0, event=SR_SUB_EV_RPC, request_id=0x1, 
    output_op=0x7ffff4987c18, err_code=0x7ffff4987be4) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2327
#6  0x00007ffff74056f8 in sr_shmsub_rpc_listen_process_rpc_events (rpc_subs=0x651e00, conn=0x61fba0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2531
#7  0x00007ffff73cceee in sr_process_events (subscription=0x642c20, session=0x0, stop_time_in=0x7ffff4987e20)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:3012
#8  0x00007ffff740663f in sr_shmsub_listen_thread (arg=0x642c20) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2925
#9  0x00007ffff7bbd6db in start_thread (arg=0x7ffff4988700) at pthread_create.c:463
#10 0x00007ffff6e4d88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb) p mod_locks[j][k].mode
Cannot access memory at address 0x7573ad656c5d8572
(gdb) p mod_locks[j][k]
Cannot access memory at address 0x7573ad656c5d8572
(gdb) p j
$1 = 0x0
(gdb) p k
$2 = 0x0
(gdb) p mod_locks
$3 = (sr_conn_state_lock_t (*)[3]) 0x7573ad656c5d8572
(gdb) p *mod_locks
Cannot access memory at address 0x7573ad656c5d8572
(gdb)

Regards, Igor

michalvasko commented 4 years ago

Hi, the error is a nasty one that takes a long time to debug but I would say it is not the actual problem. Are you using the latest devel sysrepo? It seems to me it is a SHM remapping issue that should have been already fixed.

Regards, Michal

igortern commented 4 years ago

Hi Michal,

I took sysrepo from devel today about 8h ago. Please let me know if potential fix was submitted since.

Thanks, Igor

Sent from mobile, sorry for typos.

On Thu, 23 Jan. 2020, 21:51 Michal Vasko, notifications@github.com wrote:

Hi, the error is a nasty one that takes a long time to debug but I would say it is not the actual problem. Are you using the latest devel sysrepo? It seems to me it is a SHM remapping issue that should have been already fixed.

Regards, Michal

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/CESNET/Netopeer2/issues/538?email_source=notifications&email_token=AEX4KW62HPQQO2UF2MMSAJTQ7FZDZA5CNFSM4KKP6AFKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJW6X5I#issuecomment-577629173, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEX4KW5XSLB3SWA2AFM5FJTQ7FZDZANCNFSM4KKP6AFA .

michalvasko commented 4 years ago

Hi Igor, that should be recent enough. As for the issue, it would be great if I could reproduce it but it may not be easy to find a use-case. Maybe it will not be needed, could you please provide the backtrace from the internal error (using gdb)?

Regards, Michal

igortern commented 4 years ago

Hi Michal, I tried to reproduce it today and it looked a little different. I've 2 sysrepo clients: netopeer2-server and my application which is a backend of TR-385. 1) first my application triggered internal error in sysrepo when subscribing to ietf-interfaces. See ====Application traceback 2) On the next RPC netopeer2-server crashed. There were no error messages preceding the crash ====Netopeer2 log

I don't know if it is the same problem or different.

Regards, Igor

====Application traceback

Thread 9 "bcmolt_netconf_" hit Breakpoint 1, sr_shmmain_ext_defrag (shm_main=0x1cb7aa0, shm_ext=0x1cb7ab8, defrag_ext_buf=0x7ffff557cd08)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605
605         SR_ERRINFO_INT(&err_info);
(gdb) bt
#0  sr_shmmain_ext_defrag (shm_main=0x1cb7aa0, shm_ext=0x1cb7ab8, defrag_ext_buf=0x7ffff557cd08)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605
#1  0x00007ffff743ad34 in sr_shmmain_unlock (conn=0x1cb79f0, mode=SR_LOCK_WRITE, remap=0x1, lydmods=0x0, func=0x7ffff744a5d0 <__func__.8843> "sr_module_change_subscribe")
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:2023
#2  0x00007ffff740dcad in sr_module_change_subscribe (session=0x1cf3150, module_name=0x828999 "ietf-interfaces", xpath=0x828ad8 "/ietf-interfaces:interfaces/interface", 
    callback=0x6d3e8b <bbf_xpon_change_cb>, private_data=0x0, priority=0x0, opts=0x10, subscription=0xbcdd30 <sr_ctx>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:3360
#3  0x00000000006d442f in bbf_xpon_subscribe (srs=0x1cf3150) at /home/igort/Perforce/OLT/aspen/main/host/netconf_server/modules/bbf-xpon/bbf-xpon.c:291
#4  0x00000000006d4892 in _device_indication_cb (olt=0x0, msg=0x7fffdc000ec0) at /home/igort/Perforce/OLT/aspen/main/host/netconf_server/modules/bbf-xpon/bbf-xpon.c:387
#5  0x00000000006be9b7 in _bcmtr_unpack_and_deliver (tmsg=0x7fffe8004c50, handler=0x22105c0) at /home/igort/Perforce/OLT/aspen/main/common/transport/bcmtr_transport.c:223
#6  0x00000000006beaf1 in _bcmtr_ipc_msg_handler (module_id=BCMOS_MODULE_ID_NETCONF_SERVER, m=0x7fffe8004cb8)
    at /home/igort/Perforce/OLT/aspen/main/common/transport/bcmtr_transport.c:255
#7  0x0000000000813da6 in bcmos_dft_task_handler (data=0xb93d80) at /home/igort/Perforce/OLT/aspen/main/common/os_abstraction/bcmos_common.c:1779
#8  0x00007ffff78746db in start_thread (arg=0x7ffff557d700) at pthread_create.c:463
#9  0x00007ffff713088f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb) c
Continuing.
[1727833: E SYSREPO             ] Internal error (/home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605).

====Netopeer2 log

[INF]: LN: Accepted a connection on 0.0.0.0:10830.
[INF]: SR: Session 3 (user "root") created.
[2020/01/24 09:15:12.531521, 2] ssh_pki_import_privkey_base64:  Trying to decode privkey passphrase=false
[2020/01/24 09:15:12.541067, 2] ssh_server_connection_callback:  SSH client banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/24 09:15:12.541122, 2] ssh_analyze_banner:  Analyzing banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/24 09:15:12.541219, 2] ssh_kex_select_methods:  Negotiated ecdh-sha2-nistp521,ssh-rsa,aes128-ctr,aes128-ctr,hmac-sha1,hmac-sha1,none,none,,
[2020/01/24 09:15:12.576626, 2] ssh_packet_server_ecdh_init:  SSH_MSG_KEXDH_REPLY sent
[2020/01/24 09:15:12.576891, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/24 09:15:12.576962, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/24 09:15:12.576991, 2] ssh_packet_server_ecdh_init:  SSH_MSG_NEWKEYS sent
[2020/01/24 09:15:12.593233, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[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 "interactive".
[2020/01/24 09:15:12.640158, 2] ssh_message_auth_interactive_request:  Warning: Got a keyboard-interactive response but it seems we didn't send the request.
[INF]: LN: Received an SSH message "request-auth" of subtype "interactive".
[INF]: LN: User "igort" authenticated.
[INF]: LN: Received an SSH message "request-channel-open" of subtype "session".
[INF]: LN: Received an SSH message "request-channel" of subtype "subsystem".
[2020/01/24 09:15:12.651538, 2] grow_window:  growing window (channel 43:0) to 1280000 bytes
[INF]: SR: Session 4 (user "root") created.
[INF]: SR: There are no subscribers for "ietf-netconf-notifications" notifications.
[INF]: NP: Generated new event (netconf-session-start).
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 5 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "ietf-yang-library" event with ID 1.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 1 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 4 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 6 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 2 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 2 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "nc-notifications" event with ID 1.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 2 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 2 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 0 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 7 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 3 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 3 priority 0 (remaining 1 subscribers).
[INF]: SR: Finished processing "rpc" event with ID 3 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 3 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[WRN]: LY: Unable to print anydata content (type 32) as XML.
[INF]: NP: Session 1: thread 1 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 8 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/notifications:create-subscription" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[New Thread 0x7ffff2183700 (LWP 19087)]
[INF]: SR: Finished processing "rpc" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 1 priority 0 succeeded.
[INF]: NP: Session 1: thread 4 event new RPC.

[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 9 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:copy-config" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[INF]: SR: There are no subscribers for changes of the module "ietf-keystore" in running DS.
[INF]: SR: There are no subscribers for changes of the module "ietf-interfaces" in running DS.
[INF]: SR: Published event "done" with ID 1 priority 0 for 22 subscribers.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Processing "ietf-netconf-server" "done" event with ID 1 priority 0 (remaining 22 subscribers).
[ERR]: LN: Endpoint "default-ssh" was not found.
[ERR]: LN: Endpoint "default-ssh" was not found.
[ERR]: LN: Endpoint "default-ssh" was not found.
[ERR]: LN: Endpoint "default-ssh" was not found.
[INF]: SR: Finished processing "done" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Published event "notif" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Finished processing "rpc" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 1 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Processing "notif" "ietf-netconf-notifications" event with ID 1.
[INF]: SR: Finished processing "notif" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: NP: Session 1: thread 3 event new RPC.

[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 10 (user "root") created.
[WRN]: SR: Cleaning up after a non-existent sysrepo client with PID 1852793716.
netopeer2-server: /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:1009: sr_shmmain_state_recover: Assertion `shm_lock->write_locked' failed.

Thread 5 "netopeer2-serve" received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff3185700 (LWP 19040)]
__GI_raise (sig=sig@entry=0x6) at ../sysdeps/unix/sysv/linux/raise.c:51
51  ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) 
(gdb) bt
#0  __GI_raise (sig=sig@entry=0x6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff6d6c801 in __GI_abort () at abort.c:79
#2  0x00007ffff6d5c39a in __assert_fail_base (fmt=0x7ffff6ee37d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7ffff740f6d1 "shm_lock->write_locked", 
    file=file@entry=0x7ffff740f110 "/home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c", line=line@entry=0x3f1, 
    function=function@entry=0x7ffff740fdb0 <__PRETTY_FUNCTION__.8440> "sr_shmmain_state_recover") at assert.c:92
#3  0x00007ffff6d5c412 in __GI___assert_fail (assertion=0x7ffff740f6d1 "shm_lock->write_locked", 
    file=0x7ffff740f110 "/home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c", line=0x3f1, 
    function=0x7ffff740fdb0 <__PRETTY_FUNCTION__.8440> "sr_shmmain_state_recover") at assert.c:101
#4  0x00007ffff73f788b in sr_shmmain_state_recover (conn=0x61fba0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:1009
#5  0x00007ffff73faad6 in sr_shmmain_lock_remap (conn=0x61fba0, mode=SR_LOCK_READ, remap=0x0, lydmods=0x0, func=0x7ffff740a6f0 <__func__.9058> "sr_rpc_send_tree")
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:1964
#6  0x00007ffff73d0424 in sr_rpc_send_tree (session=0x7fffe40255c0, input=0x7fffe4003a50, timeout_ms=0x7d0, output=0x7ffff3184c78)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4107
#7  0x000000000040766c in np2srv_rpc_cb (rpc=0x7fffe4003a50, ncs=0x7fffe4000e30)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/main.c:409
#8  0x00007ffff7648b25 in nc_server_send_reply_io (session=0x7fffe4000e30, io_timeout=0x0, rpc=0x7fffe4003a00)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/session_server.c:1300
#9  0x00007ffff76498a2 in nc_ps_poll (ps=0x65bef0, timeout=0x0, session=0x7ffff3184ed8)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/session_server.c:1655
#10 0x0000000000409647 in worker_thread (arg=0x650fb0) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/main.c:892
#11 0x00007ffff7bbd6db in start_thread (arg=0x7ffff3185700) at pthread_create.c:463
#12 0x00007ffff6e4d88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb)
michalvasko commented 4 years ago

Hi Igor, okay, I think only the application error is relevant, netopeer2-server then crashes because of it. Can you please enable debug output for the application and post the output prior to the crash? Then, if there was a simple way of reproducing it, it would be great and I would need no more information from you. Note that any preceding writes into SHM (new/deleted connections, subscriptions, ...) may be relevant.

Regards, Michal

igortern commented 4 years ago

Hi Michal, I reproduced the original problem: no "internal errors" in my application, netopeer2-server reports internal error and crashes. Below is netopeer2 traceback from the breakpoint @ internal error Regards, Igor

[INF]: LN: Accepted a connection on 0.0.0.0:10830.
[INF]: SR: Session 3 (user "root") created.
[2020/01/25 08:44:46.821487, 2] ssh_pki_import_privkey_base64:  Trying to decode privkey passphrase=false
[2020/01/25 08:44:46.825884, 2] ssh_server_connection_callback:  SSH client banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/25 08:44:46.825917, 2] ssh_analyze_banner:  Analyzing banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/25 08:44:46.825965, 2] ssh_kex_select_methods:  Negotiated ecdh-sha2-nistp521,ssh-rsa,aes128-ctr,aes128-ctr,hmac-sha1,hmac-sha1,none,none,,
[2020/01/25 08:44:46.875595, 2] ssh_packet_server_ecdh_init:  SSH_MSG_KEXDH_REPLY sent
[2020/01/25 08:44:46.876093, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/25 08:44:46.876323, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/25 08:44:46.876570, 2] ssh_packet_server_ecdh_init:  SSH_MSG_NEWKEYS sent
[2020/01/25 08:44:46.900807, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[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 "interactive".
[2020/01/25 08:44:46.946196, 2] ssh_message_auth_interactive_request:  Warning: Got a keyboard-interactive response but it seems we didn't send the request.
[INF]: LN: Received an SSH message "request-auth" of subtype "interactive".
[INF]: LN: User "igort" authenticated.
[INF]: LN: Received an SSH message "request-channel-open" of subtype "session".
[INF]: LN: Received an SSH message "request-channel" of subtype "subsystem".
[2020/01/25 08:44:46.962029, 2] grow_window:  growing window (channel 43:0) to 1280000 bytes
[INF]: SR: Session 4 (user "root") created.
[INF]: SR: There are no subscribers for "ietf-netconf-notifications" notifications.
[INF]: NP: Generated new event (netconf-session-start).
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 5 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "ietf-yang-library" event with ID 1.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 1 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 3 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 6 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 2 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 2 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "nc-notifications" event with ID 1.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 2 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 2 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 1 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 7 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 3 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 3 priority 0 (remaining 1 subscribers).
[INF]: SR: Finished processing "rpc" event with ID 3 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 3 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[WRN]: LY: Unable to print anydata content (type 32) as XML.
[INF]: NP: Session 1: thread 0 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 8 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/notifications:create-subscription" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[New Thread 0x7ffff1982700 (LWP 5559)]
[Switching to Thread 0x7ffff4988700 (LWP 5483)]

Thread 2 "netopeer2-serve" hit Breakpoint 2, sr_shmmain_ext_defrag (shm_main=0x61fc50, shm_ext=0x61fc68, defrag_ext_buf=0x7ffff49878a8)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605
605         SR_ERRINFO_INT(&err_info);
(gdb) bt
#0  sr_shmmain_ext_defrag (shm_main=0x61fc50, shm_ext=0x61fc68, defrag_ext_buf=0x7ffff49878a8)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605
#1  0x00007ffff73fad86 in sr_shmmain_unlock (conn=0x61fba0, mode=SR_LOCK_WRITE, remap=0x1, lydmods=0x0, func=0x7ffff740a770 <__func__.9090> "_sr_event_notif_subscribe")
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:2023
#2  0x00007ffff73d0eba in _sr_event_notif_subscribe (session=0x7fffec021670, mod_name=0x62b660 "ietf-yang-library", xpath=0x0, start_time=0x0, stop_time=0x0, callback=0x0, 
    tree_callback=0x40a792 <np2srv_ntf_new_cb>, private_data=0x7fffec000e30, opts=0x0, subscription=0x61e7e0 <np2srv+32>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4349
#3  0x00007ffff73d1067 in sr_event_notif_subscribe_tree (session=0x7fffec021670, module_name=0x62b660 "ietf-yang-library", xpath=0x0, start_time=0x0, stop_time=0x0, 
    callback=0x40a792 <np2srv_ntf_new_cb>, private_data=0x7fffec000e30, opts=0x0, subscription=0x61e7e0 <np2srv+32>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4387
#4  0x000000000040d925 in np2srv_rpc_subscribe_cb (session=0x7ffff4987c40, UNUSED_op_path=0x62b7e0 "/notifications:create-subscription", input=0x7fffe001d060, 
    UNUSED_event=SR_EV_RPC, UNUSED_request_id=0x1, UNUSED_output=0x7fffe0000ef0, UNUSED_private_data=0x0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/netconf.c:718
#5  0x00007ffff7404ab3 in sr_shmsub_rpc_listen_call_callback (rpc_sub=0x629530, tmp_sess=0x7ffff4987c40, input_op=0x7fffe001d060, event=SR_SUB_EV_RPC, request_id=0x1, 
    output_op=0x7ffff4987c18, err_code=0x7ffff4987be4) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2327
#6  0x00007ffff7405500 in sr_shmsub_rpc_listen_process_rpc_events (rpc_subs=0x651e00, conn=0x61fba0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2531
#7  0x00007ffff73ccca4 in sr_process_events (subscription=0x642c20, session=0x0, stop_time_in=0x7ffff4987e20)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:2979
#8  0x00007ffff7406447 in sr_shmsub_listen_thread (arg=0x642c20) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2925
#9  0x00007ffff7bbd6db in start_thread (arg=0x7ffff4988700) at pthread_create.c:463
#10 0x00007ffff6e4d88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb)
michalvasko commented 4 years ago

Hi, okay, but I have asked for the debug output (netopeer2-server -c SYSREPO), so please provide that. Also, the warning

[WRN]: LY: Unable to print anydata content (type 32) as XML.

should most likely not appear. So it would be great if you could just post the steps to reproduce this instead. Meaning what RPCs have you sent to the server. Thanks.

Regards, Michal

igortern commented 4 years ago

Hi Michal, I reproduces the original problem. The scenario is: 1) local sysrepo client subscribes to notifications 2) remote client connects to netopeer2-server and subscribes to notifications 3) netopeer2-server crashes All packages have been updated from devel today. Traceback is below, from breakpoint at shm_main.c:605

Regards, Igor

[INF]: LN: Accepted a connection on 0.0.0.0:10830.
[INF]: SR: Session 3 (user "root") created.
[2020/01/28 11:55:38.252109, 2] ssh_pki_import_privkey_base64:  Trying to decode privkey passphrase=false
[2020/01/28 11:55:38.257153, 2] ssh_server_connection_callback:  SSH client banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/28 11:55:38.257220, 2] ssh_analyze_banner:  Analyzing banner: SSH-2.0-SSHD-UNKNOWN
[2020/01/28 11:55:38.257290, 2] ssh_kex_select_methods:  Negotiated ecdh-sha2-nistp521,ssh-rsa,aes128-ctr,aes128-ctr,hmac-sha1,hmac-sha1,none,none,,
[2020/01/28 11:55:38.289141, 2] ssh_packet_server_ecdh_init:  SSH_MSG_KEXDH_REPLY sent
[2020/01/28 11:55:38.289434, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/28 11:55:38.289559, 2] ssh_init_rekey_state:  Set rekey after 4294967296 blocks
[2020/01/28 11:55:38.289703, 2] ssh_packet_server_ecdh_init:  SSH_MSG_NEWKEYS sent
[2020/01/28 11:55:38.299762, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[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 "interactive".
[2020/01/28 11:55:38.347378, 2] ssh_message_auth_interactive_request:  Warning: Got a keyboard-interactive response but it seems we didn't send the request.
[INF]: LN: Received an SSH message "request-auth" of subtype "interactive".
[INF]: LN: User "igort" authenticated.
[INF]: LN: Received an SSH message "request-channel-open" of subtype "session".
[INF]: LN: Received an SSH message "request-channel" of subtype "subsystem".
[2020/01/28 11:55:38.354456, 2] grow_window:  growing window (channel 43:0) to 1280000 bytes
[INF]: SR: Session 4 (user "root") created.
[INF]: SR: There are no subscribers for "ietf-netconf-notifications" notifications.
[INF]: NP: Generated new event (netconf-session-start).
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 5 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "ietf-yang-library" event with ID 1.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 1 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 1 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 0 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 6 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 2 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 2 priority 0 (remaining 1 subscribers).
[INF]: SR: Published event "operational" with ID 1.
[INF]: SR: Processing "operational" "nc-notifications" event with ID 1.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Finished processing "operational" event with ID 1.
[INF]: SR: Event "operational" with ID 1 succeeded.
[INF]: SR: Finished processing "rpc" event with ID 2 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 2 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: NP: Session 1: thread 3 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 7 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 3 priority 0 for 1 subscribers.
[INF]: SR: Processing "/ietf-netconf:get" "rpc" event with ID 3 priority 0 (remaining 1 subscribers).
[INF]: SR: Finished processing "rpc" event with ID 3 priority 0 (remaining 0 subscribers).
[INF]: SR: Event "rpc" with ID 3 priority 0 succeeded.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[WRN]: LY: Unable to print anydata content (type 32) as XML.
[INF]: NP: Session 1: thread 0 event new RPC.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Session 8 (user "root") created.
[INF]: LY: Resolving unresolved data nodes and their constraints...
[INF]: LY: All data nodes and constraints resolved.
[INF]: SR: Published event "rpc" with ID 1 priority 0 for 1 subscribers.
[INF]: SR: Processing "/notifications:create-subscription" "rpc" event with ID 1 priority 0 (remaining 1 subscribers).
[New Thread 0x7ffff1981700 (LWP 32734)]
[DBG]: SR: #SHM before defrag
[Switching to Thread 0x7ffff4987700 (LWP 32674)]

Thread 2 "netopeer2-serve" hit Breakpoint 1, sr_shmmain_ext_defrag (shm_main=0x61fc50, shm_ext=0x61fc68, defrag_ext_buf=0x7ffff49868a8)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605
605         SR_ERRINFO_INT(&err_info);
(gdb) 
(gdb) 
(gdb) 
(gdb) bt
#0  sr_shmmain_ext_defrag (shm_main=0x61fc50, shm_ext=0x61fc68, defrag_ext_buf=0x7ffff49868a8)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:605
#1  0x00007ffff73fa260 in sr_shmmain_unlock (conn=0x61fba0, mode=SR_LOCK_WRITE, remap=0x1, lydmods=0x0, 
    func=0x7ffff7409cb0 <__func__.9109> "_sr_event_notif_subscribe")
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_main.c:2023
#2  0x00007ffff73d00e0 in _sr_event_notif_subscribe (session=0x7fffe8021670, mod_name=0x62b510 "ietf-yang-library", xpath=0x0, start_time=0x0, stop_time=0x0, 
    callback=0x0, tree_callback=0x40a792 <np2srv_ntf_new_cb>, private_data=0x7fffe8000e30, opts=0x0, subscription=0x61e7e0 <np2srv+32>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4367
#3  0x00007ffff73d028d in sr_event_notif_subscribe_tree (session=0x7fffe8021670, module_name=0x62b510 "ietf-yang-library", xpath=0x0, start_time=0x0, stop_time=0x0, 
    callback=0x40a792 <np2srv_ntf_new_cb>, private_data=0x7fffe8000e30, opts=0x0, subscription=0x61e7e0 <np2srv+32>)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:4405
#4  0x000000000040d925 in np2srv_rpc_subscribe_cb (session=0x7ffff4986c40, UNUSED_op_path=0x62bf20 "/notifications:create-subscription", input=0x7fffe0002d10, 
    UNUSED_event=SR_EV_RPC, UNUSED_request_id=0x1, UNUSED_output=0x7fffe00274a0, UNUSED_private_data=0x0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/netconf.c:718
#5  0x00007ffff7403fb4 in sr_shmsub_rpc_listen_call_callback (rpc_sub=0x62af00, tmp_sess=0x7ffff4986c40, input_op=0x7fffe0002d10, event=SR_SUB_EV_RPC, 
    request_id=0x1, output_op=0x7ffff4986c18, err_code=0x7ffff4986be4)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2330
#6  0x00007ffff7404a01 in sr_shmsub_rpc_listen_process_rpc_events (rpc_subs=0x651f40, conn=0x61fba0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2534
#7  0x00007ffff73cbdc0 in sr_process_events (subscription=0x6433b0, session=0x0, stop_time_in=0x7ffff4986e20)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/sysrepo.c:2983
#8  0x00007ffff7405948 in sr_shmsub_listen_thread (arg=0x6433b0)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/sysrepo/sysrepo-devel/src/shm_sub.c:2928
#9  0x00007ffff7bbd6db in start_thread (arg=0x7ffff4987700) at pthread_create.c:463
#10 0x00007ffff6e4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb)
michalvasko commented 4 years ago

Hi, I reproduced it even though I thought I won't based on your brief description. There were actually a few things wrong, all of which were critical bugs, so I am surprised it was not discovered earlier. Anyway, please clear your SHM (I suppose you know how), pull latest devel and try again. It should work now.

Also, while not being a critical bug, I would still like you to help me reproduce this warning

[WRN]: LY: Unable to print anydata content (type 32) as XML.

I think it causes the reply to your 3rd <get> to be incorrect.

Regards, Michal

igortern commented 4 years ago

Hi Michal,

The crash is fixed now. Below is the backtrace of [WRN]: LY: Unable to print anydata content (type 32) as XML.

I progressed to th next problem :). Now sysrepo is unable to parse valid config-set request (at least the old sysrepo was able to parse it with no trouble). I'll file another issue.

Thanks, Igor

Thread 4 "netopeer2-serve" hit Breakpoint 1, xml_print_anydata (out=0x7ffff39836f0, level=0, node=0x7fffec002fa0, toplevel=1, options=257) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:621 621 LOGWRN(node->schema->module->ctx, "Unable to print anydata content (type %d) as XML.", any->value_type); (gdb) (gdb) bt

0 xml_print_anydata (out=0x7ffff39836f0, level=0, node=0x7fffec002fa0, toplevel=1, options=257)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:621

1 0x00007ffff7968adc in xml_print_node (out=0x7ffff39836f0, level=0, node=0x7fffec002fa0, toplevel=1, options=257)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:667

2 0x00007ffff7968dc1 in xml_print_data (out=0x7ffff39836f0, root=0x7fffec002fa0, options=257)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:732

3 0x00007ffff7931076 in lydprint (out=0x7ffff39836f0, root=0x7fffec001310, format=LYD_XML, options=257)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer.c:720

4 0x00007ffff7931483 in lyd_print_clb (writeclb=0x7ffff7631bff , arg=0x7ffff39837e0, root=0x7fffec001310, format=LYD_XML, options=257)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer.c:838

5 0x00007ffff76330a9 in nc_write_msg_io (session=0x7fffdc000e30, io_timeout=0, type=6)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/io.c:1250

6 0x00007ffff7647ba4 in nc_server_send_reply_io (session=0x7fffdc000e30, io_timeout=0, rpc=0x7fffec001430)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/session_server.c:1310

7 0x00007ffff76488a2 in nc_ps_poll (ps=0x65bf50, timeout=0, session=0x7ffff3983ed8)

at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/session_server.c:1655

8 0x0000000000409647 in worker_thread (arg=0x652660) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/main.c:892

9 0x00007ffff7bbd6db in start_thread (arg=0x7ffff3984700) at pthread_create.c:463

10 0x00007ffff6e4b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

michalvasko commented 4 years ago

Hi, thanks, but this is not very helpful. I can learn from this only that a reply was being sent from the server that included an anydata that could not be printed into XML because it failed to be parsed into a datatree before. Do you think you could provide the module and its data so I could reproduce this?

Regards, Michal

igortern commented 4 years ago

Hi Michal, The client issued rpc below. I tried to collect all info I could think of from gdb breakpoint. See below. Models are in https://github.com/CESNET/Netopeer2/issues/url

Regards, Igor

[INF]: LY: All data nodes and constraints resolved.
[Switching to Thread 0x7ffff2181700 (LWP 1912)]

Thread 7 "netopeer2-serve" hit Breakpoint 1, xml_print_anydata (out=0x7ffff21806f0, level=0, node=0x7fffdc027230, toplevel=1, options=257)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:621
621             LOGWRN(node->schema->module->ctx, "Unable to print anydata content (type %d) as XML.", any->value_type);
(gdb) 
(gdb) p *node
$1 = {schema = 0x623910, validity = 0 '\000', dflt = 0 '\000', when_status = 0 '\000', attr = 0x0, next = 0x0, prev = 0x7fffdc027230, parent = 0x7fffdc002c10, hash = 1400815510, 
  ht = 0x7fffdc002090, child = 0x0}
(gdb) p *node->schema
$2 = {name = 0x641240 "data", 
  dsc = 0x6532a0 "Copy of the running datastore subset and/or state\ndata that matched the filter criteria (if any).\nAn empty data container indicates that the request did not\nproduce any results.", ref = 0x0, flags = 0, ext_size = 0 '\000', iffeature_size = 0 '\000', padding = "\000\000\000", ext = 0x0, iffeature = 0x0, module = 0x6790d0, nodetype = LYS_ANYXML, 
  parent = 0x623890, child = 0x0, next = 0x0, prev = 0x623910, priv = 0x0, hash = "\226\000\000"}
(gdb) p *node->prev
$3 = {schema = 0x623910, validity = 0 '\000', dflt = 0 '\000', when_status = 0 '\000', attr = 0x0, next = 0x0, prev = 0x7fffdc027230, parent = 0x7fffdc002c10, hash = 1400815510, 
  ht = 0x7fffdc002090, child = 0x0}
(gdb) p *node->parent
$4 = {schema = 0x623570, validity = 0 '\000', dflt = 0 '\000', when_status = 0 '\000', attr = 0x0, next = 0x0, prev = 0x7fffdc002c10, parent = 0x0, hash = 1772939101, ht = 0x0, 
  child = 0x7fffdc027230}
(gdb) p *node->parent->schema
$5 = {name = 0x623650 "get", dsc = 0x664420 "Retrieve running configuration and device state information.", ref = 0x6235f0 "RFC 6241, Section 7.7", flags = 0, ext_size = 0 '\000', 
  iffeature_size = 0 '\000', padding = "\000\000\000", ext = 0x0, iffeature = 0x0, module = 0x6790d0, nodetype = LYS_RPC, parent = 0x0, child = 0x623690, next = 0x6239a0, prev = 0x622e50, 
  priv = 0x0, hash = "\335\000\000"}
(gdb) p *node->schema->module
$6 = {ctx = 0x61fd90, name = 0x63df20 "ietf-netconf", prefix = 0x66cf10 "nc", 
  dsc = 0x678370 "NETCONF Protocol Data Types and Protocol Operations.\n\nCopyright (c) 2011 IETF Trust and the persons identified as\nthe document authors.  All rights reserved.\n\nRedistribution and use in source and bina"..., ref = 0x0, org = 0x6288f0 "IETF NETCONF (Network Configuration) Working Group", 
  contact = 0x66b4a0 "WG Web:   <http://tools.ietf.org/wg/netconf/>\nWG List:  <netconf@ietf.org>\n\nWG Chair: Bert Wijnen\n          <bertietf@bwijnen.net>\n\nWG Chair: Mehmet Ersue\n          <mehmet.ersue@nsn.com>\n\nEditor:   M"..., filepath = 0x687c80 "/home/igort/Perforce/OLT/aspen/main/build/host-sim/fs/sysrepo/yang/ietf-netconf@2013-09-29.yang", type = 0 '\000', 
  version = 0 '\000', deviated = 0 '\000', disabled = 0 '\000', implemented = 1 '\001', latest_revision = 1 '\001', padding1 = 0 '\000', padding2 = "\000", rev_size = 2 '\002', 
  imp_size = 2 '\002', inc_size = 0 '\000', ident_size = 0, tpdf_size = 5, features_size = 8 '\b', augment_size = 0 '\000', deviation_size = 0 '\000', extensions_size = 1 '\001', 
  ext_size = 3 '\003', rev = 0x665df0, imp = 0x666e10, inc = 0x0, tpdf = 0x66ae70, ident = 0x0, features = 0x67acf0, augment = 0x0, deviation = 0x0, extensions = 0x64f220, ext = 0x665f30, 
  data = 0x67b5a0, ns = 0x661b30 "urn:ietf:params:xml:ns:netconf:base:1.0"}
(gdb) p *node->parent->schema->module
$7 = {ctx = 0x61fd90, name = 0x63df20 "ietf-netconf", prefix = 0x66cf10 "nc", 
  dsc = 0x678370 "NETCONF Protocol Data Types and Protocol Operations.\n\nCopyright (c) 2011 IETF Trust and the persons identified as\nthe document authors.  All rights reserved.\n\nRedistribution and use in source and bina"..., ref = 0x0, org = 0x6288f0 "IETF NETCONF (Network Configuration) Working Group", 
  contact = 0x66b4a0 "WG Web:   <http://tools.ietf.org/wg/netconf/>\nWG List:  <netconf@ietf.org>\n\nWG Chair: Bert Wijnen\n          <bertietf@bwijnen.net>\n\nWG Chair: Mehmet Ersue\n          <mehmet.ersue@nsn.com>\n\nEditor:   M"..., filepath = 0x687c80 "/home/igort/Perforce/OLT/aspen/main/build/host-sim/fs/sysrepo/yang/ietf-netconf@2013-09-29.yang", type = 0 '\000', 
  version = 0 '\000', deviated = 0 '\000', disabled = 0 '\000', implemented = 1 '\001', latest_revision = 1 '\001', padding1 = 0 '\000', padding2 = "\000", rev_size = 2 '\002', 
  imp_size = 2 '\002', inc_size = 0 '\000', ident_size = 0, tpdf_size = 5, features_size = 8 '\b', augment_size = 0 '\000', deviation_size = 0 '\000', extensions_size = 1 '\001', 
  ext_size = 3 '\003', rev = 0x665df0, imp = 0x666e10, inc = 0x0, tpdf = 0x66ae70, ident = 0x0, features = 0x67acf0, augment = 0x0, deviation = 0x0, extensions = 0x64f220, ext = 0x665f30, 
  data = 0x67b5a0, ns = 0x661b30 "urn:ietf:params:xml:ns:netconf:base:1.0"}
(gdb) bt
#0  xml_print_anydata (out=0x7ffff21806f0, level=0, node=0x7fffdc027230, toplevel=1, options=257)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:621
#1  0x00007ffff7968adc in xml_print_node (out=0x7ffff21806f0, level=0, node=0x7fffdc027230, toplevel=1, options=257)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:667
#2  0x00007ffff7968dc1 in xml_print_data (out=0x7ffff21806f0, root=0x7fffdc027230, options=257)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer_xml.c:732
#3  0x00007ffff7931076 in lyd_print_ (out=0x7ffff21806f0, root=0x7fffdc002c10, format=LYD_XML, options=257)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer.c:720
#4  0x00007ffff7931483 in lyd_print_clb (writeclb=0x7ffff7631bff <nc_write_xmlclb>, arg=0x7ffff21807e0, root=0x7fffdc002c10, format=LYD_XML, options=257)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libyang/libyang-devel/src/printer.c:838
#5  0x00007ffff76330a9 in nc_write_msg_io (session=0x7fffe8000e30, io_timeout=0, type=6)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/io.c:1250
#6  0x00007ffff7647ba4 in nc_server_send_reply_io (session=0x7fffe8000e30, io_timeout=0, rpc=0x7fffdc000b20)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/session_server.c:1310
#7  0x00007ffff76488a2 in nc_ps_poll (ps=0x65bf30, timeout=0, session=0x7ffff2180ed8)
    at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/libnetconf2/libnetconf2-devel/src/session_server.c:1655
#8  0x0000000000409647 in worker_thread (arg=0x65c0b0) at /home/igort/Perforce/OLT/aspen/external/build/host-sim/third_party/netopeer2/Netopeer2-devel-server/server/main.c:892
#9  0x00007ffff7bbd6db in start_thread (arg=0x7ffff2181700) at pthread_create.c:463
#10 0x00007ffff6e4b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb) Quit

=====RPC=====

<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
  <copy-config>
    <target>
      <running/>
    </target>
    <source>
      <config>
        <bbf-qos-filt:filters xmlns:bbf-qos-filt="urn:bbf:yang:bbf-qos-filters"/>
        <bbf-lt:link-table xmlns:bbf-lt="urn:bbf:yang:bbf-link-table"/>
        <ipfix:ipfix xmlns:ipfix="urn:ietf:params:xml:ns:yang:ietf-ipfix-psamp"/>
        <hw:hardware xmlns:hw="urn:ietf:params:xml:ns:yang:ietf-hardware"/>
        <bbf-qos-cls:classifiers xmlns:bbf-qos-cls="urn:bbf:yang:bbf-qos-classifiers"/>
        <pw:pseudowires xmlns:pw="urn:ietf:params:xml:ns:yang:ietf-pseudowires"/>
        <bbf-xpon:xpon xmlns:bbf-xpon="urn:bbf:yang:bbf-xpon"/>
        <bbf-ghn:ghn xmlns:bbf-ghn="urn:bbf:yang:bbf-ghn"/>
        <bbf-qos-pol:qos-policy-profiles xmlns:bbf-qos-pol="urn:bbf:yang:bbf-qos-policies"/>
        <al:alarms xmlns:al="urn:ietf:params:xml:ns:yang:ietf-alarms"/>
        <bbf-vdsl:vdsl xmlns:bbf-vdsl="urn:bbf:yang:bbf-vdsl"/>
        <bbf-xpongemtcont:xpongemtcont xmlns:bbf-xpongemtcont="urn:bbf:yang:bbf-xpongemtcont"/>
        <sys:system xmlns:sys="urn:ietf:params:xml:ns:yang:ietf-system"/>
        <bbf-qos-plc-ep:envelope-profiles xmlns:bbf-qos-plc-ep="urn:bbf:yang:bbf-qos-policer-envelope-profiles"/>
        <bbf-ghs:ghs xmlns:bbf-ghs="urn:bbf:yang:bbf-ghs"/>
        <if:interfaces xmlns:if="urn:ietf:params:xml:ns:yang:ietf-interfaces"/>
        <bbf-qos-pol:policies xmlns:bbf-qos-pol="urn:bbf:yang:bbf-qos-policies"/>
        <bbf-qos-tm:tm-profiles xmlns:bbf-qos-tm="urn:bbf:yang:bbf-qos-traffic-mngt"/>
        <bbf-qos-plc:policing-profiles xmlns:bbf-qos-plc="urn:bbf:yang:bbf-qos-policing"/>
        <bbf-selt:selt xmlns:bbf-selt="urn:bbf:yang:bbf-selt"/>
        <bbf-l2-d4r:l2-dhcpv4-relay-profiles xmlns:bbf-l2-d4r="urn:bbf:yang:bbf-l2-dhcpv4-relay"/>
        <dot1x:nid-group xmlns:dot1x="urn:ieee:std:802.1X:yang:ieee802-dot1x"/>
        <nacm:nacm xmlns:nacm="urn:ietf:params:xml:ns:yang:ietf-netconf-acm"/>
        <bbf-hw-rpf-dpu:rpf xmlns:bbf-hw-rpf-dpu="urn:bbf:yang:bbf-hardware-rpf-dpu"/>
        <bbf-pppoe-ia:pppoe-profiles xmlns:bbf-pppoe-ia="urn:bbf:yang:bbf-pppoe-intermediate-agent"/>
        <bbf-fast:fast xmlns:bbf-fast="urn:bbf:yang:bbf-fast"/>
        <bbf-mgmd:multicast xmlns:bbf-mgmd="urn:bbf:yang:bbf-mgmd"/>
        <bbf-melt:melt xmlns:bbf-melt="urn:bbf:yang:bbf-melt"/>
        <bbf-subprof:subscriber-profiles xmlns:bbf-subprof="urn:bbf:yang:bbf-subscriber-profiles"/>
        <bbf-ldra:dhcpv6-ldra-profiles xmlns:bbf-ldra="urn:bbf:yang:bbf-ldra"/>
        <bbf-l2-fwd:forwarding xmlns:bbf-l2-fwd="urn:bbf:yang:bbf-l2-forwarding"/>
      </config>
    </source>
  </copy-config>
</rpc>
michalvasko commented 4 years ago

Hi, unfortunately, I did not reproduces this even though I really tried. But it may be fairly simple for you to provide all the information I need. Just put a breakpoint to parser_xml.c:575 instead. There, iter should be NULL and I need to see the error. It should be printed by

print *ly_err_first(node->schema->module->ctx)

Thanks.

Regards, Michal

igortern commented 4 years ago

parser_xml.c:575 looks like an odd place. Is it what you meant? image

michalvasko commented 4 years ago

Oh, sorry, I meant printer_xml.c:575.

Regards, Michal

igortern commented 4 years ago

log is attached Regards, Igor netopeer2-server.log

michalvasko commented 4 years ago

Hi Igor, okay, thanks. Obviously there was no error even though I expected one. Could you please try it with the latest libyang? It may be fixed.

Regards, Michal

igortern commented 4 years ago

I can confirm that after updating libyang the warning is no longer printed.

Regards, Igor

RamonSalem commented 4 years ago

Hi @igortern, can you tell me which libyang's version did you update to? Did you update with the devel version at the time?

igortern commented 4 years ago

Hi Ramon,

I'm currently working with devel branch, waiting for the next release.

Regards, Igor

Sent from mobile, sorry for typos.

On Tue, 7 Apr 2020, 04:00 Ramon Salém, notifications@github.com wrote:

Hi @igortern https://github.com/igortern, can you tell me which libyang's version did you update to?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/CESNET/Netopeer2/issues/538#issuecomment-609947798, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEX4KW7UUU3OTTASLJNDTFLRLIKELANCNFSM4KKP6AFA .