[LBBS-13] pty.c: Attempt to lock previously destroyed mutex
Referencing Issues
[LBBS-57] Occasional 100% CPU usage on SSH session termination
This issue has occurred several times, so it reproduces fairly frequently:
Logs prior to crash:
[2024-05-22 21:27:20.322] DEBUG[2315948]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-05-22 21:27:20.322] DEBUG[2315948]: net_ssh.c:905 handle_session: Channel not EOF yet
...
[2024-05-22 21:27:20.370] DEBUG[2315948]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-05-22 21:27:20.370] DEBUG[2315948]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-05-22 21:27:20.370] DEBUG[2315948]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-05-22 21:27:20.371] DEBUG[2315948]: net_ssh.c:905 handle_session: Channel not EOF yet
....
[2024-05-22 21:27:20.373] DEBUG[2315951]: event.c:139 bbs_event_broadcast: Event NODE_SHORT_SESSION dispatched and consumed
[2024-05-22 21:27:20.374] DEBUG[2315951]: node.c:604 node_shutdown: Shutdown pending finalization for node 5
[2024-05-22 21:27:20.374] DEBUG[2315951]: node.c:622 node_free: Node 5 now freed
[2024-05-22 21:27:20.374] == Node 5 has exited
[2024-05-22 21:27:20.374] DEBUG[2315951]: thread.c:133 __thread_unregister: Thread 2315951 is exiting (detached)
[2024-05-22 21:27:20.374] DEBUG[2315952]: thread.c:106 thread_register: Thread 2315952 spawned from pty_master started by thread 2315951 at pty.c:249 bbs_pty_allocate()
[2024-05-22 21:27:20.374] ERROR[2315952]: node.c:320 bbs_node_lock: Attempt to lock mutex &node->lock previously destroyed at node.c:625
[2024-05-22 21:27:20.374] ERROR[2315952]: lock.c:129 __bbs_mutex_lock: Failed assertion 0
[2024-05-22 21:27:20.376] ERROR[2315952]: backtrace.c:263 bbs_log_backtrace: Got 7 backtrace records
[2024-05-22 21:27:20.590] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 0: lbbs bbs_log_backtrace()
[2024-05-22 21:27:20.590] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 1: lbbs __bbs_assert_fatal()
[2024-05-22 21:27:20.591] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 2: lbbs __bbs_mutex_lock()
[2024-05-22 21:27:20.591] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 3: lbbs pty_master()
[2024-05-22 21:27:20.591] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 4: lbbs <unknown>()
[2024-05-22 21:27:20.591] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 5: [0x7f24e5799134] libc.so.6 pthread_create.c:442 start_thread()
[2024-05-22 21:27:20.591] ERROR[2315952]: backtrace.c:287 bbs_log_backtrace: 6: [0x7f24e58197dc] libc.so.6 clone3.S:83 clone3()
BBS server disconnected
[2024-06-17 22:59:41.495] DEBUG[2725746]: event.c:139 bbs_event_broadcast: Event NODE_SHORT_SESSION dispatched and consumed
[2024-06-17 22:59:41.495] DEBUG[2725746]: node.c:604 node_shutdown: Shutdown pending finalization for node 4
[2024-06-17 22:59:41.495] DEBUG[2725746]: node.c:622 node_free: Node 4 now freed
[2024-06-17 22:59:41.495] == Node 4 has exited
[2024-06-17 22:59:41.495] DEBUG[2725746]: thread.c:133 __thread_unregister: Thread 2725746 is exiting (detached)
[2024-06-17 22:59:41.495] DEBUG[2725747]: thread.c:106 thread_register: Thread 2725747 spawned from pty_master started by thread 2725746 at pty.c:249 bbs_pty_allocate()
[2024-06-17 22:59:41.496] ERROR[2725747]: node.c:320 bbs_node_lock: Attempt to lock mutex &node->lock previously destroyed at node.c:625
[2024-06-17 22:59:41.496] ERROR[2725747]: lock.c:129 __bbs_mutex_lock: Failed assertion 0
[2024-06-17 22:59:41.519] ERROR[2725747]: backtrace.c:263 bbs_log_backtrace: Got 7 backtrace records
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 0: lbbs bbs_log_backtrace()
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 1: lbbs __bbs_assert_fatal()
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 2: lbbs __bbs_mutex_lock()
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 3: lbbs pty_master()
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 4: lbbs <unknown>()
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 5: [0x7fd365a7c134] libc.so.6 pthread_create.c:442 start_thread()
[2024-06-17 22:59:41.720] ERROR[2725747]: backtrace.c:287 bbs_log_backtrace: 6: [0x7fd365afc7dc] libc.so.6 clone3.S:83 clone3()
Aborted (core dumped)
00:56:09.980] DEBUG[2735133]: event.c:139 bbs_event_broadcast: Event NODE_SHORT_SESSION dispatched and consumed
[2024-06-19 00:56:09.980] DEBUG[2735133]: node.c:604 node_shutdown: Shutdown pending finalization for node 2
[2024-06-19 00:56:09.980] DEBUG[2735133]: node.c:622 node_free: Node 2 now freed
[2024-06-19 00:56:09.980] == Node 2 has exited
[2024-06-19 00:56:09.980] DEBUG[2735133]: thread.c:133 __thread_unregister: Thread 2735133 is exiting (detached)
[2024-06-19 00:56:09.981] DEBUG[2735134]: thread.c:106 thread_register: Thread 2735134 spawned from pty_master started by thread 2735133 at pty.c:249 bbs_pty_allocate()
[2024-06-19 00:56:09.981] ERROR[2735134]: node.c:320 bbs_node_lock: Attempt to lock mutex &node->lock previously destroyed at node.c:625
[2024-06-19 00:56:09.981] ERROR[2735134]: lock.c:129 __bbs_mutex_lock: Failed assertion 0
[2024-06-19 00:56:09.982] ERROR[2735134]: backtrace.c:263 bbs_log_backtrace: Got 7 backtrace records
[2024-06-19 00:56:10.151] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 0: lbbs bbs_log_backtrace()
[2024-06-19 00:56:10.152] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 1: lbbs __bbs_assert_fatal()
[2024-06-19 00:56:10.152] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 2: lbbs __bbs_mutex_lock()
[2024-06-19 00:56:10.152] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 3: lbbs pty_master()
[2024-06-19 00:56:10.152] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 4: lbbs <unknown>()
[2024-06-19 00:56:10.152] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 5: [0x7f1eb60a8134] libc.so.6 pthread_create.c:442 start_thread()
[2024-06-19 00:56:10.152] ERROR[2735134]: backtrace.c:287 bbs_log_backtrace: 6: [0x7f1eb61287dc] libc.so.6 clone3.S:83 clone3()
[2024-06-20 08:43:49.082] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.082] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.083] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.083] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.083] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.083] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.083] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.083] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.075] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 0: lbbs bbs_log_backtrace()
[2024-06-20 08:43:49.084] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.084] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 1: lbbs __bbs_assert_fatal()
[2024-06-20 08:43:49.084] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 2: lbbs __bbs_mutex_lock()
[2024-06-20 08:43:49.084] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.084] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 3: lbbs pty_master()
[2024-06-20 08:43:49.084] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.084] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 4: lbbs <unknown>()
[2024-06-20 08:43:49.085] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 5: [0x7f347f8a8134] libc.so.6 pthread_create.c:442 start_thread()
[2024-06-20 08:43:49.084] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.085] ERROR[2751237]: backtrace.c:287 bbs_log_backtrace: 6: [0x7f347f9287dc] libc.so.6 clone3.S:83 clone3()
[2024-06-20 08:43:49.085] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-20 08:43:49.085] DEBUG[2751234]: net_ssh.c:905 handle_session: Channel not EOF yet
[2024-06-21 16:44:31.397] DEBUG[2773202]: event.c:139 bbs_event_broadcast: Event NODE_SHORT_SESSION dispatched and consumed
[2024-06-21 16:44:31.397] DEBUG[2773202]: node.c:604 node_shutdown: Shutdown pending finalization for node 4
[2024-06-21 16:44:31.397] DEBUG[2773202]: node.c:622 node_free: Node 4 now freed
[2024-06-21 16:44:31.398] == Node 4 has exited
[2024-06-21 16:44:31.398] DEBUG[2773202]: thread.c:133 __thread_unregister: Thread 2773202 is exiting (detached)
[2024-06-21 16:44:31.398] DEBUG[2773203]: thread.c:106 thread_register: Thread 2773203 spawned from pty_master started by thread 2773202 at pty.c:249 bbs_pty_allocate()
[2024-06-21 16:44:31.398] ERROR[2773203]: node.c:320 bbs_node_lock: Attempt to lock mutex &node->lock previously destroyed at node.c:625
[2024-06-21 16:44:31.398] ERROR[2773203]: lock.c:129 __bbs_mutex_lock: Failed assertion 0
[2024-06-21 16:44:31.399] ERROR[2773203]: backtrace.c:263 bbs_log_backtrace: Got 7 backtrace records
[2024-06-21 16:44:31.551] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 0: lbbs bbs_log_backtrace()
[2024-06-21 16:44:31.552] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 1: lbbs __bbs_assert_fatal()
[2024-06-21 16:44:31.552] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 2: lbbs __bbs_mutex_lock()
[2024-06-21 16:44:31.552] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 3: lbbs pty_master()
[2024-06-21 16:44:31.552] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 4: lbbs <unknown>()
[2024-06-21 16:44:31.552] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 5: [0x7faabc2a8134] libc.so.6 pthread_create.c:442 start_thread()
[2024-06-21 16:44:31.553] ERROR[2773203]: backtrace.c:287 bbs_log_backtrace: 6: [0x7faabc3287dc] libc.so.6 clone3.S:83 clone3()
BBS server disconnectedThread 1 in coredump:
#6 __bbs_mutex_lock (t=t@entry=0x7f60e4007ff0, filename=filename@entry=0x557715a8942f "node.c", lineno=lineno@entry=320, func=func@entry=0x557715a8afb8 <__func__.36> "bbs_node_lock", name=name@entry=0x557715a89575 "&node->lock") at lock.c:184
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#7 0x0000557715a5b84a in bbs_node_lock (node=node@entry=0x7f60e4007f00) at node.c:320
__func__ = "bbs_node_lock"
#8 0x0000557715a6172c in pty_master (varg=varg@entry=0x7f60e4007f00) at pty.c:503
#4 0x000055e287a59957 in __bbs_assert_fatal (condition_str=<optimized out>, file=<optimized out>, line=<optimized out>, function=<optimized out>>
#5 0x000055e287a67506 in __bbs_assert (function=<optimized out>, line=<optimized out>, file=<optimized out>, condition_str=<optimized out>, cond>
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#6 __bbs_mutex_lock (t=t@entry=0x7f1e98028c30, filename=filename@entry=0x55e287aa742f "node.c", lineno=lineno@entry=320, func=func@entry=0x55e28>
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#7 0x000055e287a7984a in bbs_node_lock (node=node@entry=0x7f1e98028b40) at node.c:320
__func__ = "bbs_node_lock"
#8 0x000055e287a7f72c in pty_master (varg=varg@entry=0x7f1e98028b40) at pty.c:503
node = 0x7f1e98028b40
pres = 0
fds = {{fd = 60, events = 57, revents = 0}, {fd = 77, events = 57, revents = 32}, {fd = 0, events = 0, revents = 0}}
#4 0x0000558ea8ef5957 in __bbs_assert_fatal (condition_str=<optimized out>, file=<optimized out>, line=<optimized out>, function=<optimized out>) at backtrace.c:311
#5 0x0000558ea8f03506 in __bbs_assert (function=<optimized out>, line=<optimized out>, file=<optimized out>, condition_str=<optimized out>, condition=<optimized out>) at ../inc>
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#6 __bbs_mutex_lock (t=t@entry=0x7f8074008300, filename=filename@entry=0x558ea8f4342f "node.c", lineno=lineno@entry=320, func=func@entry=0x558ea8f44fb8 <__func__.36> "bbs_node_>
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#7 0x0000558ea8f1584a in bbs_node_lock (node=node@entry=0x7f8074008210) at node.c:320
__func__ = "bbs_node_lock"
#8 0x0000558ea8f1b72c in pty_master (varg=varg@entry=0x7f8074008210) at pty.c:503
#5 0x000055d0bfc5d506 in __bbs_assert (function=<optimized out>, line=<optimized out>, file=<optimized out>, condition_str=<optimized out>, condition=<optimized out>) at ../include/bbs.h:440
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#6 __bbs_mutex_lock (t=t@entry=0x7f24c830cd30, filename=filename@entry=0x55d0bfc9d42f "node.c", lineno=lineno@entry=320, func=func@entry=0x55d0bfc9efb8 <__func__.36> "bbs_node_lock", name=name@entry=0x55d0bfc9d575 "&node->lock") at lock.c:184
res = <optimized out>
c = <optimized out>
now = <optimized out>
elapsed = <optimized out>
start = <optimized out>
__func__ = "__bbs_mutex_lock"
#7 0x000055d0bfc6f84a in bbs_node_lock (node=node@entry=0x7f24c830cc40) at node.c:320
__func__ = "bbs_node_lock"
#8 0x000055d0bfc7572c in pty_master (varg=varg@entry=0x7f24c830cc40) at pty.c:503Comments
You must be