Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

edit-config SEGFAULT #720

Closed
michalvasko opened this issue Feb 2, 2017 · 4 comments
Closed

edit-config SEGFAULT #720

michalvasko opened this issue Feb 2, 2017 · 4 comments

Comments

@michalvasko
Copy link
Collaborator

Hi,
I encountered a sysrepo crash, this is the output with valgrind:

[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 27 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 23 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=3, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=130320128 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=4, count=0.
[DBG] (rp_session_refresh_req_process:1619) Processing session_data_refresh request.
[INF] (rp_dt_refresh_session:960) Refresh session request running datastore
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy cross-module: mtime sec=1484565293 nsec=994744283
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module cross-module: mtime sec=1484565293 nsec=994744283
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=492117047
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy example-module: mtime sec=1485353122 nsec=136462440
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module example-module: mtime sec=1485353122 nsec=136462440
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=497975590
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy ietf-interfaces: mtime sec=1483435188 nsec=586117581
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module ietf-interfaces: mtime sec=1483435188 nsec=586117581
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=499234065
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy ietf-keystore: mtime sec=1486028880 nsec=638015560
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module ietf-keystore: mtime sec=1486028880 nsec=638015560
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=500615529
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy ietf-netconf-acm: mtime sec=1486029009 nsec=697591226
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module ietf-netconf-acm: mtime sec=1486029009 nsec=697591226
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=501992454
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy ietf-netconf-server: mtime sec=1486029019 nsec=193560059
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module ietf-netconf-server: mtime sec=1486029019 nsec=193560059
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=503087987
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy ietf-system: mtime sec=1486029019 nsec=329559613
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module ietf-system: mtime sec=1486029019 nsec=329559613
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=504270298
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy model1: mtime sec=1484738685 nsec=841363564
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module model1: mtime sec=1484738685 nsec=841363564
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=505318765
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy model2: mtime sec=1484738675 nsec=989384092
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module model2: mtime sec=1484738675 nsec=989384092
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=506378344
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy module-a: mtime sec=1484565293 nsec=718745492
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module module-a: mtime sec=1484565293 nsec=718745492
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=507436096
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy module-b: mtime sec=1484565293 nsec=786745194
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module module-b: mtime sec=1484565293 nsec=786745194
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=508500477
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy nc-notifications: mtime sec=1484046489 nsec=443052066
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module nc-notifications: mtime sec=1484046489 nsec=443052066
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=509565057
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy notifications: mtime sec=1484046489 nsec=443052066
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module notifications: mtime sec=1484046489 nsec=443052066
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=510626595
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy referenced-data: mtime sec=1484565293 nsec=630745878
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module referenced-data: mtime sec=1484565293 nsec=630745878
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=511714955
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy servers: mtime sec=1484565294 nsec=106743792
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module servers: mtime sec=1484565294 nsec=106743792
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=512573323
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy small-module: mtime sec=1484565293 nsec=658745754
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module small-module: mtime sec=1484565293 nsec=658745754
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=513391097
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy state-module: mtime sec=1484565293 nsec=902744685
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module state-module: mtime sec=1484565293 nsec=902744685
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=514200001
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy test: mtime sec=1484644466 nsec=494465734
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module test: mtime sec=1484644466 nsec=494465734
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=515053177
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy top-level-mandatory: mtime sec=1484565293 nsec=930744563
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module top-level-mandatory: mtime sec=1484565293 nsec=930744563
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=515958089
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy turing-machine: mtime sec=1485868240 nsec=672615372
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module turing-machine: mtime sec=1485868240 nsec=672615372
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=516850642
[INF] (rp_dt_refresh_session:972) No operation has been performed on this session so far
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=7, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=130320128 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=8, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 26 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 26 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 115 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 111 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=4, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=138712832 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=5, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=8, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=138712832 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=9, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 137 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 133 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=5, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=147105536 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=6, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/address
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=9, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=147105536 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=0, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 128 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 124 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=6, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=121927424 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=7, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/port
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=0, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=121927424 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=1, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 172 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 168 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=7, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=130320128 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=8, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/certificates/certificate[name='test_server_cert']
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=1, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=130320128 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=2, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 173 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 169 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=8, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=138712832 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=9, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/client-auth/trusted-ca-certs
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=2, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=138712832 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=3, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 165 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 161 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=9, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=147105536 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=0, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/client-auth/cert-maps/cert-to-name[id='1']
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=3, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=147105536 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=4, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 242 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 238 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=0, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=121927424 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=1, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/client-auth/cert-maps/cert-to-name[id='1']/fingerprint
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=4, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=121927424 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=5, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 208 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 204 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=1, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=130320128 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=2, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/client-auth/cert-maps/cert-to-name[id='1']/map-type
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=5, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=130320128 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=6, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 177 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 173 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=2, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=138712832 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=3, count=0.
[DBG] (rp_set_item_req_process:1197) Processing set_item request.
[INF] (rp_dt_set_item_wrapper:570) Set item request running datastore, xpath: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']/tls/client-auth/cert-maps/cert-to-name[id='1']/name
[DBG] (dm_get_data_info:2281) Module ietf-netconf-server already loaded
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=6, current count=1.
[DBG] (rp_worker_thread_execute:3637) Thread id=138712832 will wait.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=7, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_conn_read_cb:1101) fd 6 readable
[DBG] (cm_conn_read_cb:1114) 28 bytes of data received on fd 6
[DBG] (cm_conn_read_cb:1124) fd 6 would block
[DBG] (cm_conn_in_buff_process:1054) New message of size 24 bytes received.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=3, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=0/4, 1 requests in queue
[DBG] (rp_worker_thread_execute:3649) Thread id=147105536 signaled.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=4, count=0.
[DBG] (rp_commit_req_process:1459) Processing commit request.
[DBG] (rp_dt_commit:783) Commit (1/10): process started
[DBG] (dm_get_data_info:2281) Module ietf-keystore already loaded
[DBG] (dm_load_dependant_data:1926) Data tree ietf-keystore appended because of validation
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_load_data_tree:1234) Data file /home/vasko/Documents/sysrepo/build/repository/data/ietf-x509-cert-to-name.running does not exist, creating empty data tree
[DBG] (dm_load_data_tree_file:1186) Usage count ietf-x509-cert-to-name incremented (value=1)
[INF] (dm_load_data_tree_file:1190) Data file /home/vasko/Documents/sysrepo/build/repository/data/ietf-x509-cert-to-name.running is empty
[DBG] (dm_get_data_info:2309) Module ietf-x509-cert-to-name has been loaded
[DBG] (dm_append_data_tree:1852) Dependant module ietf-x509-cert-to-name is empty
[DBG] (dm_load_dependant_data:1926) Data tree ietf-x509-cert-to-name appended because of validation
[DBG] (dm_validate_session_data_trees:2980) Validation succeeded for 'ietf-netconf-server' module
[DBG] (rp_dt_commit:792) Commit (2/10): validation succeeded
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (sr_locking_set_lock_fd:789) File /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.persist has been locked
[DBG] (pm_load_data_tree:263) Persist data successfully loaded from file '/home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.persist'.
[DBG] (sr_locking_set_unlock_close_fd:858) File /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.persist (fd = 11) has been unlocked
[DBG] (pm_cache_subscriptions:784) Caching 0 subscriptions from 'ietf-netconf-server' persist file.
[DBG] (pm_get_subscriptions:1322) Returning 0 subscriptions found in 'ietf-netconf-server' persist file.
[DBG] (pm_module_data_version_changed:577) Module 'ietf-netconf-server' persist file version matches with cached value (1486029019233560702).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (sr_locking_set_lock_fd:789) File /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.persist has been locked
[DBG] (pm_load_data_tree:263) Persist data successfully loaded from file '/home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.persist'.
[DBG] (sr_locking_set_unlock_close_fd:858) File /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.persist (fd = 11) has been unlocked
[DBG] (pm_cache_subscriptions:784) Caching 1 subscriptions from 'ietf-netconf-server' persist file.
[DBG] (pm_get_subscriptions:1322) Returning 1 subscriptions found in 'ietf-netconf-server' persist file.
[DBG] (dm_commit_prepare_context:3675) Commit: In the session there are 1 / 21 modified models
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (sr_locking_set_lock_file_open:725) File /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.running.lock has been locked
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_lock_module:1366) Usage count ietf-netconf-server incremented (value=3)
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (dm_is_info_copy_uptodate:3134) Session copy ietf-netconf-server: mtime sec=1486029019 nsec=193560059
[DBG] (dm_is_info_copy_uptodate:3137) Loaded module ietf-netconf-server: mtime sec=1486029019 nsec=193560059
[DBG] (dm_is_info_copy_uptodate:3140) Current time: mtime sec=1486029091 nsec=628673544
[DBG] (dm_commit_load_modified_models:3878) Timestamp for the model ietf-netconf-server matches, ops will be skipped
[DBG] (dm_commit_load_modified_models:3893) Usage count ietf-netconf-server incremented (value=4)
[DBG] (dm_load_data_tree_file:1120) Loaded module ietf-netconf-server: mtime sec=1486029019 nsec=193560059
[DBG] (dm_load_data_tree_file:1186) Usage count ietf-netconf-server incremented (value=5)
[INF] (dm_load_data_tree_file:1192) Data file /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.running loaded successfully
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (rp_dt_commit:810) Commit (3/10): all modified models loaded successfully
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_replay_operations:644) Skipping op for model ietf-netconf-server
[DBG] (rp_dt_commit:817) Commit (4/10): replay of operation succeeded
[DBG] (rp_dt_commit:827) Commit (5/10): merged models validation succeeded
[DBG] (rp_dt_commit:840) Commit (6/10): write access granted by NACM
[DBG] (dm_commit_notify:4291) Sending verify notifications about the changes made in running datastore...
[DBG] (dm_commit_notify:4377) Deleted: /ietf-keystore:keystore
[DBG] (dm_commit_notify:4377) Created: /ietf-netconf-server:netconf-server/listen/endpoint[name='test_tls_listen_endpt']
[DBG] (rp_dt_commit:847) Commit (7/10): verify phase done
[DBG] (dm_commit_write_files:4033) Data successfully written for module 'ietf-netconf-server'
[DBG] (rp_dt_commit:857) Commit (8/10): data write succeeded
[DBG] (dm_commit_notify:4291) Sending apply notifications about the changes made in running datastore...
[DBG] (np_subscription_notify:1329) Sending module-change notification to '/tmp/sysrepo-subscriptions/ietf-netconf-server/11642.vMQt22.sock' @ 508792345.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=7, current count=1.
[DBG] (np_commit_notif_cnt_increment:295) Creating a new NP commit context for commit ID 151005587.
[INF] (dm_unlock_datastore:1519) Unlock datastore request
[DBG] (dm_unlock_datastore:1527) Module_name ietf-netconf-server
[DBG] (dm_unlock_datastore:1530) Usage count ietf-netconf-server decremented (value=4)
[DBG] (sr_locking_set_unlock_close_file:832) File /home/vasko/Documents/sysrepo/build/repository/data/ietf-netconf-server.running.lock has been unlocked
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=8, current count=2.
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=9, current count=3.
[DBG] (np_commit_notifications_sent:1459) Set up commit timeout for commit id=151005587.
[DBG] (rp_dt_generate_config_change_notification:740) Config changes for module ietf-netconf-server
[DBG] (rp_generate_config_change_notification:337) 2 instance of /ietf-netconf-notifications/netconf-config-change/edit list will be created
[DBG] (rp_generate_config_change_notification:408) CONFIG CHANGE: delete /ietf-keystore:keystore
[DBG] (rp_generate_config_change_notification:408) CONFIG CHANGE: create /ietf-netconf-server:netconf-server/ietf-netconf-server:listen/ietf-netconf-server:endpoint[ietf-netconf-server:name='test_tls_listen_endpt']
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=4, current count=1.
[DBG] (rp_msg_process:4031) Threads: active=1/4, 1 requests in queue
[DBG] (rp_generate_config_change_notification:428) Config changed notification generated session 1556780869
[DBG] (rp_dt_commit:867) Commit (9/10): apply notifications sent
[DBG] (dm_data_info_free:323) Usage count cross-module decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count example-module decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count ietf-interfaces decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count ietf-keystore decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count ietf-netconf-acm decremented (value=1)
[DBG] (dm_data_info_free:323) Usage count ietf-netconf-server decremented (value=3)
[DBG] (dm_data_info_free:323) Usage count ietf-system decremented (value=1)
[DBG] (dm_data_info_free:323) Usage count ietf-x509-cert-to-name decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count model1 decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count model2 decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count module-a decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count module-b decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count nc-notifications decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count notifications decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count referenced-data decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count servers decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count small-module decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count state-module decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count test decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count top-level-mandatory decremented (value=0)
[DBG] (dm_data_info_free:323) Usage count turing-machine decremented (value=0)
[DBG] (rp_dt_commit:911) Commit (10/10): finished successfully
[DBG] (sr_cbuff_enqueue:516) Circular buffer enqueue to position=0, current count=4.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=5, count=0.
[DBG] (rp_event_notif_req_process:2949) Processing event notification request (/ietf-netconf-notifications:netconf-config-change).
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=8, count=3.
[DBG] (cm_out_notif_process:1371) Sending a notification to '/tmp/sysrepo-subscriptions/ietf-netconf-server/11642.vMQt22.sock'.
[DBG] (cm_out_notif_process:1383) Reusing existing connection on fd=8 for the notification destination '/tmp/sysrepo-subscriptions/ietf-netconf-server/11642.vMQt22.sock'
[DBG] (cm_conn_out_buff_flush:505) Sending 140 bytes of data.
[DBG] (ac_set_identity:155) Switching identity to UID='0' and GID='0' (username: root).
[DBG] (cm_conn_out_buff_flush:511) 140 bytes of data sent.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=9, count=2.
[DBG] (cm_out_notif_process:1371) Sending a notification to '/tmp/sysrepo-subscriptions/ietf-netconf-server/11642.vMQt22.sock'.
[DBG] (cm_out_notif_process:1383) Reusing existing connection on fd=8 for the notification destination '/tmp/sysrepo-subscriptions/ietf-netconf-server/11642.vMQt22.sock'
[DBG] (cm_conn_out_buff_flush:505) Sending 115 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 115 bytes of data sent.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=0, count=1.
[DBG] (cm_delayed_msg_process:326) Scheduling a delayed request for 10.000000 seconds.
[DBG] (sr_cbuff_dequeue:532) Circular buffer dequeue, new buffer head=1, count=0.
[DBG] (cm_conn_out_buff_flush:505) Sending 27 bytes of data.
[DBG] (cm_conn_out_buff_flush:511) 27 bytes of data sent.
[DBG] (cm_msg_enqueue_cb:1713) New message enqueued into CM message queue.
[DBG] (cm_server_watcher_cb:1228) New client connection on fd 13
[DBG] (sm_connection_start:353) New connection started successfully, fd=13, conn ctx=0xa0ba410.
[DBG] (cm_conn_read_cb:1101) fd 13 readable
[DBG] (cm_conn_buffer_expand:477) Input buffer for fd=13 expanded to 1024 bytes.
[DBG] (cm_conn_read_cb:1114) 33 bytes of data received on fd 13
==11636== 
==11636== Process terminating with default action of signal 11 (SIGSEGV)
==11636==  General Protection Fault
==11636==    at 0x542C19B: __lll_unlock_elision (in /lib64/libpthread-2.19.so)
==11636==    by 0x4EA3A20: ac_unset_user_identity (access_control.c:510)
==11636==    by 0x4F0D0B4: dm_load_data_tree (data_manager.c:1228)
==11636==    by 0x4F170CB: dm_get_data_info (data_manager.c:2298)
==11636==    by 0x4F36593: dm_validate_procedure (data_manager.c:5724)
==11636==    by 0x4F373EF: dm_validate_event_notif (data_manager.c:5851)
==11636==    by 0x4ED6D1F: rp_event_notif_req_process (request_processor.c:2972)
==11636==    by 0x4ED9A2B: rp_req_dispatch (request_processor.c:3353)
==11636==    by 0x4EDAC4A: rp_msg_dispatch (request_processor.c:3498)
==11636==    by 0x4EDB59A: rp_worker_thread_execute (request_processor.c:3598)
==11636==    by 0x54230A3: start_thread (in /lib64/libpthread-2.19.so)
==11636== 
==11636== HEAP SUMMARY:
==11636==     in use at exit: 3,430,826 bytes in 23,377 blocks
==11636==   total heap usage: 401,176 allocs, 377,799 frees, 2,677,808,670 bytes allocated
==11636== 
==11636== LEAK SUMMARY:
==11636==    definitely lost: 0 bytes in 0 blocks
==11636==    indirectly lost: 0 bytes in 0 blocks
==11636==      possibly lost: 2,240 bytes in 4 blocks
==11636==    still reachable: 3,428,586 bytes in 23,373 blocks
==11636==         suppressed: 0 bytes in 0 blocks
==11636== Rerun with --leak-check=full to see details of leaked memory
==11636== 
==11636== For counts of detected and suppressed errors, rerun with: -v
==11636== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

steps.zip

Steps to reproduce are included in the attachment, there are relatively complex. Also, when I tried running sysrepo with valgrind and connected to it with (started) netopeer2-server, every few tries sysrepo got stuck and could have only been terminated by sending SIGKILL (which may hint a lock problem). The server then failed with:

netopeer2-server[11090]: (cl_message_recv:204) While waiting for a response, timeout has expired.
netopeer2-server[11090]: (cl_request_process:449) Unable to receive the message with response (session id=1362276331, operation=subscribe).
netopeer2-server[11090]: (sr_module_change_subscribe:2540) Error by processing of the request.
netopeer2-server[11090]: (cl_message_recv:204) While waiting for a response, timeout has expired.
netopeer2-server[11090]: (cl_request_process:449) Unable to receive the message with response (session id=1362276331, operation=unsubscribe).
netopeer2-server[11090]: (cl_subscription_close:243) Error by processing of the request.
netopeer2-server[11090]: Failed to subscribe to "ietf-netconf-server" module changes (Timeout has expired).
netopeer2-server[11090]: Server init failed.

I have not investigated this further, but I can start a separate issue if you prefer.

Regards,
Michal
@lukasmacko
Copy link
Contributor

Hi Michal,

I am trying to reproduce the issue. I had to make following modifications to successfully walk through all steps:

  • I've changed the permissions on ietf-keystore, ietf-netconf-server, ietf-system to 666 to be able to test it with my local user
  • I've initialized the ret variable to pass the first rpc
diff --git a/keystored/keystored.c b/keystored/keystored.c
index 45872df..87d7ef9 100644
--- a/keystored/keystored.c
+++ b/keystored/keystored.c
@@ -420,7 +420,7 @@ ks_privkey_load_cb(const char *UNUSED(xpath), const sr_node_t *input, const size
 {
     struct keystored_ctx *ctx = (struct keystored_ctx *)private_ctx;
     pid_t pid;
-    int ret, status, len, fd;
+    int ret = 0, status, len, fd;
     char *priv_path = NULL, *pub_path = NULL;
     FILE *privkey = NULL;
  • I've noticed that netopeer doesn't subscribe to ietf-netconf-server and the second edit config fails due to it. Could you check if the netopeer is subscribed when you are hitting the issue? There should be record in REPOSITORY/data/ietf-netconf-server.persist Meanwhile, I've tried a workaround, where I've just enabled running using application_example (no verification, no action, it just enables running)

with these changes all steps passes and sysrepod survives

> user-rpc --content load_server_key.xml
OK
> edit-config --target running --config=load_server_certs.xml
OK
> edit-config --target running --config=tls_listen.xml
OK

do you have any suggestions that might help to reproduce the issue?

thanks,
Lukas

@michalvasko
Copy link
Collaborator Author

Hi Lukas,

  • I have used username root for all the operations, I could have mentioned it,
  • I have fixed this, thanks, not sure why did the compiler not complain,
  • netopeer2-server should subscribe to ietf-netconf-server if configured properly (function ietf_netconf_server_init does so).

I have now committed first version of instructions for server configuration, so please look at the beginning to learn how to enable it, because it is required here. Also, the XMLs are committed too now. If you have any problems, it would probably be best if we communicate directly, it has not been checked or tried by anyone but me.

I will also mentioned that the first crash I experienced was after some additional edit-config operations, it crashes sooner with valgrind. I deduced that it was likely due to the first problem, it just manifested later. There is no way to know, anyway.

Regards,
Michal

@lukasmacko
Copy link
Contributor

Hi,

I am still not able to reproduce the issue locally, however I've noticed one more thing: according to the logs sysrepo was sending /ietf-netconf-notifications:netconf-config-change just before the crash. Do you have a subscriber for this notification in your setup? (...it might be just a misleading track. I just wanted to check.)

Lukas

@michalvasko
Copy link
Collaborator Author

Hi,

no, in the branch I used there are no notifications yet. If you can't reproduce it, you can hardly debug it, so nevermind for now. If we learn more, I'll let you know.

Regards,
Michal

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@michalvasko @lukasmacko