Hi,
I’m using an Asterisk 15.1.5 installed on CentOS Linux release 7.4.1708. Among others, I included Channels REST API and calls setup is done by an ARI application.
Occasionally I notice a full Recv-Q on 5060 socket used by asterisk and then asterisk stop processing calls because sip packet are no more delivered to the asterisk process.
Asterisk still process RTP because it uses another udp sockets.
The machine has 4 cores with 6 RAM and I generate a maximum of 150 calls without transcoding.
# netstat -tunlp|grep asterisk
tcp 0 0 0.0.0.0:8088 0.0.0.0:* LISTEN 16370/asterisk
udp 0 0 0.0.0.0:10146 0.0.0.0:* 16370/asterisk
udp 0 0 0.0.0.0:10147 0.0.0.0:* 16370/asterisk
udp 0 0 0.0.0.0:39454 0.0.0.0:* 16370/asterisk
udp 0 0 0.0.0.0:39455 0.0.0.0:* 16370/asterisk
udp 1053184 0 0.0.0.0:5060 0.0.0.0:* 16370/asterisk
udp 0 0 0.0.0.0:50389 0.0.0.0:* 16370/asterisk
udp 0 0 0.0.0.0:22096 0.0.0.0:* 16370/asterisk
udp 0 0 0.0.0.0:22097 0.0.0.0:* 16370/asterisk
udp6 0 0 :::13685 :::* 16370/asterisk
But there is a strong behaviour when this happens and I don’t understand the raison; the tasks distribution per cores is broken and all tasks are going to 1 core instead of 4.
After an asterisk service restart the distribution is fixed and what I could not understand is how asterisk change the Task-flow and how this could happen ?
# mpstat -P ALL 2 5
Linux 3.10.0-693.17.1.el7.x86_64 (media-server-v130-us-east1-b-3) 05/14/2019 _x86_64_ (4 CPU)
03:49:25 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
03:49:27 PM all 27.42 0.00 3.18 0.00 0.00 0.13 0.00 0.00 0.00 69.27
03:49:27 PM 0 2.21 0.00 5.52 0.00 0.00 0.00 0.00 0.00 0.00 92.27
03:49:27 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:49:27 PM 2 2.23 0.00 5.59 0.00 0.00 0.00 0.00 0.00 0.00 92.18
03:49:27 PM 3 0.51 0.00 1.53 0.00 0.00 0.00 0.00 0.00 0.00 97.96
03:49:27 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
03:49:29 PM all 27.32 0.00 2.12 0.00 0.00 0.00 0.00 0.00 0.00 70.56
03:49:29 PM 0 1.67 0.00 5.00 0.00 0.00 0.00 0.00 0.00 0.00 93.33
03:49:29 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:49:29 PM 2 1.69 0.00 3.39 0.00 0.00 0.00 0.00 0.00 0.00 94.92
03:49:29 PM 3 0.00 0.00 0.00 0.00 0.00 0.51 0.00 0.00 0.00 99.49
03:49:29 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
03:49:31 PM all 27.34 0.00 2.25 0.00 0.00 0.00 0.00 0.00 0.00 70.41
03:49:31 PM 0 1.67 0.00 5.00 0.00 0.00 0.00 0.00 0.00 0.00 93.33
03:49:31 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:49:31 PM 2 1.12 0.00 3.93 0.00 0.00 0.00 0.00 0.00 0.00 94.94
03:49:31 PM 3 1.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 98.00
03:49:31 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
03:49:33 PM all 27.42 0.00 1.99 0.00 0.00 0.00 0.00 0.00 0.00 70.60
03:49:33 PM 0 1.69 0.00 3.93 0.00 0.00 0.00 0.00 0.00 0.00 94.38
03:49:33 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:49:33 PM 2 1.69 0.00 3.93 0.00 0.00 0.00 0.00 0.00 0.00 94.38
03:49:33 PM 3 0.51 0.00 0.51 0.00 0.00 0.00 0.00 0.00 0.00 98.99
03:49:33 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
03:49:35 PM all 27.18 0.00 2.37 0.00 0.00 0.00 0.00 0.00 0.00 70.45
03:49:35 PM 0 2.21 0.00 4.42 0.00 0.00 0.00 0.00 0.00 0.00 93.37
03:49:35 PM 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:49:35 PM 2 1.11 0.00 5.00 0.00 0.00 0.00 0.00 0.00 0.00 93.89
03:49:35 PM 3 0.50 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 98.50
Average: CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
Average: all 27.34 0.00 2.38 0.00 0.00 0.03 0.00 0.00 0.00 70.26
Average: 0 1.89 0.00 4.78 0.00 0.00 0.00 0.00 0.00 0.00 93.33
Average: 1 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
Average: 2 1.57 0.00 4.37 0.00 0.00 0.00 0.00 0.00 0.00 94.06
Average: 3 0.50 0.00 0.81 0.00 0.00 0.10 0.00 0.00 0.00 98.59
The average is 27.34% but in fact 1 core is 100% and the rest are not used.
Asterisk log:
[2019-05-15 03:33:01] Asterisk 15.1.5 built by root @ build-server-001 on a x86_64 running Linux on 2018-01-11 11:02:55 UTC
[2019-05-15 03:36:53] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:19979, rtcp halted Operation not permitted
[2019-05-15 03:37:46] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:15107, rtcp halted Operation not permitted
[2019-05-15 03:39:25] WARNING[31973][C-00003981] app_dial.c: Unable to forward frametype: 2
[2019-05-15 03:48:25] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:17065, rtcp halted Operation not permitted
[2019-05-15 03:54:28] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:10989, rtcp halted Operation not permitted
[2019-05-15 03:54:56] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:16181, rtcp halted Operation not permitted
[2019-05-15 03:56:02] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.22:13035, rtcp halted Operation not permitted
[2019-05-15 04:00:45] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:11721, rtcp halted Operation not permitted
[2019-05-15 04:05:54] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:16381, rtcp halted Operation not permitted
[2019-05-15 04:12:33] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.22:15025, rtcp halted Operation not permitted
[2019-05-15 04:25:55] WARNING[5214][C-00003ba6] app_dial.c: Unable to write frametype: 2
[2019-05-15 04:38:53] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:10843, rtcp halted Operation not permitted
[2019-05-15 04:56:51] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:15319, rtcp halted Operation not permitted
[2019-05-15 06:13:53] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:18913, rtcp halted Operation not permitted
[2019-05-15 07:02:23] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:12209, rtcp halted Operation not permitted
[2019-05-15 07:06:54] WARNING[23538][C-0000409e] app_dial.c: Unable to write frametype: 2
[2019-05-15 07:09:37] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:15919, rtcp halted Operation not permitted
[2019-05-15 07:15:40] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.22:11795, rtcp halted Operation not permitted
[2019-05-15 07:19:08] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:16379, rtcp halted Operation not permitted
[2019-05-15 07:22:33] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:12975, rtcp halted Operation not permitted
[2019-05-15 07:29:50] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:10893, rtcp halted Operation not permitted
[2019-05-15 07:38:26] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.11:19491, rtcp halted Operation not permitted
[2019-05-15 08:00:18] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:11215, rtcp halted Operation not permitted
[2019-05-15 08:06:12] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.11:13277, rtcp halted Operation not permitted
[2019-05-15 08:44:48] WARNING[1372][C-000041ee] app_dial.c: Unable to write frametype: 2
[2019-05-15 09:10:38] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:15323, rtcp halted Operation not permitted
[2019-05-15 09:22:31] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:15755, rtcp halted Operation not permitted
[2019-05-15 10:05:36] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:18207, rtcp halted Operation not permitted
[2019-05-15 10:08:40] WARNING[10419][C-0000430f] app_dial.c: Unable to write frametype: 2
[2019-05-15 10:23:38] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:17759, rtcp halted Operation not permitted
[2019-05-15 10:27:28] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:13365, rtcp halted Operation not permitted
[2019-05-15 10:36:19] ERROR[1773] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.XX:19455, rtcp halted Operation not permitted
[2019-05-15 10:37:26] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:14267, rtcp halted Operation not permitted
[2019-05-15 10:50:34] ERROR[1773] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.11:12853, rtcp halted Operation not permitted
[2019-05-15 10:58:18] Asterisk 15.1.5 built by root @ build-server-001 on a x86_64 running Linux on 2018-01-11 11:02:55 UTC
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'features.conf'
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'acl.conf'
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'udptl.conf'
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'cel.conf'
[2019-05-15 10:58:18] WARNING[16370] ccss.c: Could not find valid ccss.conf file. Using cc_max_requests default
[2019-05-15 10:58:18] WARNING[16370] ccss.c: Could not find valid ccss.conf file. Using cc_[state]_devstate defaults
[2019-05-15 10:58:18] WARNING[16370] loader.c: Error loading module 'app_directory.so': /usr/lib64/asterisk/modules/app_directory.so: cannot open shared object file: No such file or directory
[2019-05-15 10:58:18] WARNING[16370] loader.c: Error loading module 'func_vmcount.so': /usr/lib64/asterisk/modules/func_vmcount.so: cannot open shared object file: No such file or directory
[2019-05-15 10:58:18] WARNING[16370] loader.c: Error loading module 'res_pjsip_endpoint_identifier_dpma.so': /usr/lib64/asterisk/modules/res_pjsip_endpoint_identifier_dpma.so: cannot open shared object file: No such file or directory
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'statsd.conf'
[2019-05-15 10:58:18] ERROR[16370] res_sorcery_config.c: Unable to load config file 'pjproject.conf'
[2019-05-15 10:58:18] ERROR[16370] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[2019-05-15 10:58:18] ERROR[16370] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[2019-05-15 10:58:18] ERROR[16370] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'res_parking.conf'
[2019-05-15 10:58:18] ERROR[16370] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[2019-05-15 10:58:18] ERROR[16370] config_options.c: Unable to load config file 'pjsip_notify.conf'
[2019-05-15 10:58:18] ERROR[16370] res_pjsip_config_wizard.c: Unable to load config file 'pjsip_wizard.conf'
[2019-05-15 10:58:18] ERROR[16370] cdr_custom.c: Unable to load cdr_custom.conf. Not logging custom CSV CDRs.
[2019-05-15 10:58:18] WARNING[16370] cdr_manager.c: Failed to load configuration file. Module not activated.
[2019-05-15 10:58:18] WARNING[16370] app_followme.c: No follow me config file (followme.conf), so no follow me
[2019-05-15 10:58:18] VERBOSE[16370] asterisk.c: Asterisk Ready.
[2019-05-15 10:59:51] ERROR[16555] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:10531, rtcp halted Operation not permitted
[2019-05-15 11:44:10] ERROR[16555] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:16023, rtcp halted Operation not permitted
[2019-05-15 11:45:16] ERROR[16555] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:19489, rtcp halted Operation not permitted
[2019-05-15 11:50:51] ERROR[16555] res_rtp_asterisk.c: RTCP SR transmission error to XX.XX.XX.22:12217, rtcp halted Operation not permitted
[2019-05-15 11:59:42] ERROR[16555] res_rtp_asterisk.c: RTCP RR transmission error to XX.XX.XX.XX:18233, rtcp halted Operation not permitted
Thanks in advance for any help,
/Ouss