Skip to content

Commit

Permalink
Temporary fix for generating clean shutdowns even for mem corruption …
Browse files Browse the repository at this point in the history 
…crashes

FULL fix would be to not worry about mem locks in the shutdown procedure ( ie. what cleanup() is doing )

(cherry picked from commit e7b8084)
  • Loading branch information
@vladpaiu
vladpaiu committed Aug 30, 2022
1 parent bf7c0eb commit afe99b7
Showing 1 changed file with 5 additions and 1 deletion.
6 changes: 5 additions & 1 deletion shutdown.c
View file
Expand Up @@ -190,7 +190,11 @@ void shutdown_opensips( int status )
int i, n, p;
int chld_status;

sr_set_core_status( STATE_TERMINATING, MI_SSTR("shutting down"));
/* TODO - temporarily removing this
* in case a mem corruption crash happens, OpenSIPS will get stuck
* in getting the SHM locks in the below function
* sr_set_core_status( STATE_TERMINATING, MI_SSTR("shutting down"));
*/

/* terminate all processes */

Expand Down

2 comments on commit afe99b7

@liviuchircu
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi, @vladpaiu!

This commit causes the shutdown sequence to remain stuck for 5 seconds (see GRACEFUL_SHUTDOWN_TIMEOUT), after which a SIGKILL is now sent to all processes. See below shutdown sequence output:

Sep  5 11:16:16 [16218] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Sep  5 11:16:16 [16218] Memory status (pkg):
Sep  5 11:16:16 [16218] fm_status (0x7f7f1ede7010):
Sep  5 11:16:16 [16218]  heap size= 33554432
Sep  5 11:16:16 [16218]  used= 635176, used+overhead=691096, free=32919256
Sep  5 11:16:16 [16218]  max used (+overhead)= 691744
Sep  5 11:16:16 [16218] dumping free list:
Sep  5 11:16:16 [16219] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Sep  5 11:16:16 [16215] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Sep  5 11:16:16 [16214] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Sep  5 11:16:16 [16219] Memory status (pkg):
Sep  5 11:16:16 [16218] hash = 2059 fragments no.:     1, unused:     0
		 bucket size:  16777216 -  33554432 (first  32863336)
Sep  5 11:16:16 [16215] Memory status (pkg):
Sep  5 11:16:16 [16214] Memory status (pkg):
Sep  5 11:16:16 [16219] fm_status (0x7f7f1ede7010):
Sep  5 11:16:16 [16218] TOTAL:      1 free fragments = 32863336 free bytes
Sep  5 11:16:16 [16215] fm_status (0x7f7f1ede7010):
Sep  5 11:16:16 [16214] fm_status (0x7f7f1ede7010):
Sep  5 11:16:16 [16219]  heap size= 33554432
Sep  5 11:16:16 [16214]  heap size= 33554432
Sep  5 11:16:16 [16218] TOTAL: 48 overhead
Sep  5 11:16:16 [16215]  heap size= 33554432
Sep  5 11:16:16 [16219]  used= 635176, used+overhead=691096, free=32919256
Sep  5 11:16:16 [16214]  used= 639456, used+overhead=695568, free=32914976
Sep  5 11:16:16 [16218] -----------------------------
Sep  5 11:16:16 [16215]  used= 635224, used+overhead=691240, free=32919208
Sep  5 11:16:16 [16219]  max used (+overhead)= 691096
Sep  5 11:16:16 [16214]  max used (+overhead)= 695568
Sep  5 11:16:16 [16218] DBG:core:rpc_process_terminate: Process 5 exiting with code 0...
Sep  5 11:16:16 [16215]  max used (+overhead)= 691240
Sep  5 11:16:16 [16219] dumping free list:
Sep  5 11:16:16 [16214] dumping free list:
Sep  5 11:16:16 [16215] dumping free list:
Sep  5 11:16:16 [16219] hash = 2059 fragments no.:     1, unused:     0
		 bucket size:  16777216 -  33554432 (first  32863336)
Sep  5 11:16:16 [16214] hash = 2059 fragments no.:     1, unused:     0
		 bucket size:  16777216 -  33554432 (first  32858864)
Sep  5 11:16:16 [16215] hash = 2059 fragments no.:     1, unused:     0
		 bucket size:  16777216 -  33554432 (first  32863192)
Sep  5 11:16:16 [16219] TOTAL:      1 free fragments = 32863336 free bytes
Sep  5 11:16:16 [16214] TOTAL:      1 free fragments = 32858864 free bytes
Sep  5 11:16:16 [16215] TOTAL:      1 free fragments = 32863192 free bytes
Sep  5 11:16:16 [16219] TOTAL: 48 overhead
Sep  5 11:16:16 [16214] TOTAL: 48 overhead
Sep  5 11:16:16 [16215] TOTAL: 48 overhead
Sep  5 11:16:16 [16219] -----------------------------
Sep  5 11:16:16 [16214] -----------------------------
Sep  5 11:16:16 [16215] -----------------------------
Sep  5 11:16:16 [16219] DBG:core:rpc_process_terminate: Process 6 exiting with code 0...
Sep  5 11:16:16 [16214] DBG:core:rpc_process_terminate: Process 1 exiting with code 0...
Sep  5 11:16:16 [16215] DBG:core:rpc_process_terminate: Process 2 exiting with code 0...
Sep  5 11:16:16 [16213] INFO:core:shutdown_opensips: process 5(16218) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 5 more
Sep  5 11:16:16 [16213] INFO:core:shutdown_opensips: process 1(16214) [MI FIFO] terminated, still waiting for 4 more
Sep  5 11:16:16 [16213] INFO:core:shutdown_opensips: process 2(16215) [HTTPD *:8888] terminated, still waiting for 3 more
Sep  5 11:16:16 [16213] INFO:core:shutdown_opensips: process 6(16219) [Timer handler] terminated, still waiting for 2 more
Sep  5 11:16:16 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 100 ms ago (now 6200 ms), delaying execution
Sep  5 11:16:16 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 200 ms ago (now 6300 ms), delaying execution
Sep  5 11:16:16 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 300 ms ago (now 6400 ms), delaying execution
Sep  5 11:16:16 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 400 ms ago (now 6500 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 500 ms ago (now 6600 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 600 ms ago (now 6700 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 700 ms ago (now 6800 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 800 ms ago (now 6900 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 890 ms ago (now 6990 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 990 ms ago (now 7090 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1090 ms ago (now 7190 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1190 ms ago (now 7290 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1290 ms ago (now 7390 ms), delaying execution
Sep  5 11:16:17 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1390 ms ago (now 7490 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1490 ms ago (now 7590 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1590 ms ago (now 7690 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1690 ms ago (now 7790 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:timer_ticker: timer task <dlg-reinvite-pinger> already scheduled 990 ms ago (now 7790 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:timer_ticker: timer task <dlg-options-pinger> already scheduled 990 ms ago (now 7790 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:timer_ticker: timer task <dlg-timer> already scheduled 990 ms ago (now 7790 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 990 ms ago (now 7790 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:timer_ticker: timer task <blcore-expire> already scheduled 990 ms ago (now 7790 ms), skipping execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1780 ms ago (now 7880 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1880 ms ago (now 7980 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1980 ms ago (now 8080 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2080 ms ago (now 8180 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2180 ms ago (now 8280 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2280 ms ago (now 8380 ms), delaying execution
Sep  5 11:16:18 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2380 ms ago (now 8480 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2480 ms ago (now 8580 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2580 ms ago (now 8680 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2680 ms ago (now 8780 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:timer_ticker: timer task <dlg-reinvite-pinger> already scheduled 1980 ms ago (now 8780 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:timer_ticker: timer task <dlg-options-pinger> already scheduled 1980 ms ago (now 8780 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:timer_ticker: timer task <dlg-timer> already scheduled 1980 ms ago (now 8780 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 1980 ms ago (now 8780 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:timer_ticker: timer task <blcore-expire> already scheduled 1980 ms ago (now 8780 ms), skipping execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2770 ms ago (now 8870 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2870 ms ago (now 8970 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 2970 ms ago (now 9070 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3070 ms ago (now 9170 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3170 ms ago (now 9270 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3270 ms ago (now 9370 ms), delaying execution
Sep  5 11:16:19 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3370 ms ago (now 9470 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3470 ms ago (now 9570 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3570 ms ago (now 9670 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3670 ms ago (now 9770 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:timer_ticker: timer task <dlg-reinvite-pinger> already scheduled 2970 ms ago (now 9770 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:timer_ticker: timer task <dlg-options-pinger> already scheduled 2970 ms ago (now 9770 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:timer_ticker: timer task <dlg-timer> already scheduled 2970 ms ago (now 9770 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 2970 ms ago (now 9770 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:timer_ticker: timer task <blcore-expire> already scheduled 2970 ms ago (now 9770 ms), skipping execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3770 ms ago (now 9870 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 3860 ms ago (now 9960 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4030 ms ago (now 10130 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4050 ms ago (now 10150 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4150 ms ago (now 10250 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4250 ms ago (now 10350 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4350 ms ago (now 10450 ms), delaying execution
Sep  5 11:16:20 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4450 ms ago (now 10550 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4550 ms ago (now 10650 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4650 ms ago (now 10750 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:timer_ticker: timer task <dlg-reinvite-pinger> already scheduled 3950 ms ago (now 10750 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:timer_ticker: timer task <dlg-options-pinger> already scheduled 3950 ms ago (now 10750 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:timer_ticker: timer task <dlg-timer> already scheduled 3950 ms ago (now 10750 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 3950 ms ago (now 10750 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:timer_ticker: timer task <blcore-expire> already scheduled 3950 ms ago (now 10750 ms), skipping execution
Sep  5 11:16:21 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4750 ms ago (now 10850 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4850 ms ago (now 10950 ms), delaying execution
Sep  5 11:16:21 [16217] WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4950 ms ago (now 11050 ms), delaying execution
Sep  5 11:16:21 [16213] DBG:core:shutdown_opensips: force termination for all processes
Sep  5 11:16:21 [16213] INFO:core:cleanup: cleanup
Sep  5 11:16:21 [16213] DBG:tm:tm_shutdown: tm_shutdown : start
Sep  5 11:16:21 [16213] DBG:tm:unlink_timer_lists: emptying DELETE list for set 0
Sep  5 11:16:21 [16213] DBG:tm:tm_shutdown: emptying hash table
Sep  5 11:16:21 [16213] DBG:tm:tm_shutdown: releasing timers
Sep  5 11:16:21 [16213] DBG:tm:tm_shutdown: removing semaphores
Sep  5 11:16:21 [16213] DBG:tm:tm_shutdown: destroying callback lists
Sep  5 11:16:21 [16213] DBG:tm:tm_shutdown: tm_shutdown : done
Sep  5 11:16:21 [16213] DBG:httpd:httpd_proc_destroy: destroying module ...
Sep  5 11:16:21 [16213] DBG:core:db_do_init: connection 0x7f7f1ee27248 not found in pool
Sep  5 11:16:21 [16213] DBG:db_mysql:db_mysql_connect: opening connection: mysql://xxxx:xxxx@localhost/opensips
Sep  5 11:16:21 [16213] DBG:db_mysql:db_mysql_connect: connection type is Localhost via UNIX socket
Sep  5 11:16:21 [16213] DBG:db_mysql:db_mysql_connect: protocol version is 10
Sep  5 11:16:21 [16213] DBG:db_mysql:db_mysql_connect: server version is 5.7.38-0ubuntu0.18.04.1
Sep  5 11:16:21 [16213] DBG:core:db_do_init: connection 0x7f7f1ee27248 inserted in pool as 0x7f7f1ee273c0
Sep  5 11:16:21 [16213] DBG:core:pool_remove: removing connection from the pool
Sep  5 11:16:21 [16213] Memory status (pkg):
Sep  5 11:16:21 [16213] fm_status (0x7f7f1ede7010):
Sep  5 11:16:21 [16213]  heap size= 33554432
Sep  5 11:16:21 [16213]  used= 182200, used+overhead=236056, free=33372232
Sep  5 11:16:21 [16213]  max used (+overhead)= 264848
Sep  5 11:16:21 [16213] dumping free list:
Sep  5 11:16:21 [16213] hash =   2 fragments no.:     4, unused:     0
		 bucket size:        16 -        16 (first        16)
Sep  5 11:16:21 [16213] hash =   5 fragments no.:     1, unused:     0
		 bucket size:        40 -        40 (first        40)
...
Sep  5 11:16:21 [16213] TOTAL: 48 overhead
Sep  5 11:16:21 [16213] -----------------------------
Sep  5 11:16:21 [16213] DBG:core:shm_mem_destroy: destroying the shared memory lock
Thank you for running opensips

@bogdan-iancu
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@liviuchircu , see 49d3888 for master branch. If this fixes the issue you reported, I'll prepare the backports.

Please sign in to comment.