FreePBX appears to stop communicating with Asterisk

jon_b · March 23, 2021, 2:52am

Inbound Call Centre environment.
700 DID, 250 Queues (Ring-All configuration), 1 SIP trunk, 70 Devices, 70 users, average 4000 inbound calls/24 hrs, peak calls probably never exceeds 50-60 simultaneous. Average number of “day” shift users logged in would be around 25-35.

Ususally runs on a Sangoma Blue Box (Freepbx Appliance 1000)
Quad core Xeon, 16 GB ram, dual 250 GB SSD’s etc.
FreePBX 13/Asterisk 13

Has been running well since 2017 but recently occasionally stops processing new calls. Usually requires a reboot to resolve and then it’s away again till the next time which could be a day or a week away.
It doesn’t seem to coincide with peak call times but is always during “day” shift which means the most users are logged on.

I’ve had Sangoma look at it and the first thing was to prune the size of the CDR and CEL databases. This has helped, but the problem persists.
They are pretty sure that it isn’t a hardware problem.

As well as the call processing issue, web access the the FreePBX GUI is incredibly slow at times and operators are having difficulty logging in/out. Can take 30+ seconds to do this. Other FreePBX *code functions are affected ie Pauseun-pause call-recording.
Suggestion was possibly related to AGI scripts which have been worked on extensively (apparently).

Sangoma’s last suggestion was to update to FreePBX 15/Asterisk 16.
This has been done using a G6 HP ML350 server with similar spec’s to the Blue Box.

However, the same problems are apparent today after the migration.

It would seem the issue is load related. ie at 4am, web access is fine but gets slower as the day progresses.

I’m open to any suggestions as to where to look and what information would be required to reach conclusion.

Thanks

dicko · March 23, 2021, 2:59am

I suggest sysstat, it wont isolate the problem directly but will show what resources are being stretched and when, memory, cpu, io, net . .

jon_b · March 23, 2021, 5:29am

Thanks Dicko.
First time i’ve used this tool
(sampled at 10 minute intervals for the day)

A quick look with sar -u (CPU) shows nothing less than 45% idle. It looks ok

Same quick look with sar -r (Memory) tells a different tale although i could be reading this incorrectly.
Seems that %memused is about 51% in non-peak periods but rises to over 95-99% for a 50 minute period mid-morning which coincides with max number of incoming calls for the day.
Another 40 minute period of >97%memused a few hours later which required a reboot to allow incoming calls again.
After that, %memused dropped to 12% then gradually rose to over 99% a few hours later then dropping away to around 49% where it seems to be stable. (6pm local time)

Could be our smoking gun ??

Next question is: what is the best process to monitor what is hogging memory to this degree.

dicko · March 23, 2021, 5:33am

I would start off looking for anything java, it has that reputation.
Asterisk itself is quite light-weight, So look at any AGI stuff or backend reporting going on.

jfinstrom · March 23, 2021, 6:09am

Isymfony call panel should be the only java

jon_b · March 23, 2021, 7:20am

Thanks, this is new field of endevour for me but here goes.

Call Centre is winding down for the day. Memory usage is steady at around 36-37%, dropping occasionally to 0.3%

htop is reporting /usr/sbin/asterisk -f -U asterisk -G asterisk -vvvg -c as using 36.9%
I have no idea what this means.
There seems to be a varying number of PID’s (10-20 or more) involved.

top is less verbose, but agrees. asterisk (one PID) is up for 36.9% of the total memory.

no sign of anything else of significance. The odd mysql line occasionally as you would expect.

CPU is ~280% as calls come in and ring to the agents, dropping away to ~12% on answer.

I guess we can take a look at a busy period tomorrow and see if there are similarities or if another process makes an appearance.

jon_b · March 25, 2021, 5:38am

Managed to get a look this morning and can see memory usage is fairly constant at 65-75% in non-peak hours.
Mid-morning and mid-afternoon, memory usage climbs to above 98% then drops away to under 10% before rising again.
This is consistent with other days as well so begs the question is there a scheduled task running every 6 hours ?
I’ll take a look at 21:00 tonight.

Htop reports
/usr/sbin/asterisk -f -U asterisk -G asterisk -vvvg -c running consistently and when memory usage hits the high numbers
/usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=usr/mysql/plugin --log-error (there may be more but its off the screenshot) makes an appearance.
When the used memory settles to a low figure
/usr/sbin/asterisk -f -U asterisk -G asterisk -vvvg -c is the main process shown.

So many questions…
Is the system just under-gunned and running out of memory in the heavy traffic times, or is this indicative of an underlying problem ?

If it’s just a performance issue, are these some of the possible causes ?
Queues are set to ring-all, changing this is (currently) non-negotiable with the customer.
Call recording is “Yes” at Inbound routes and “Don’t care” on the queues.
As this was a v13 install, all the zero duration calls to the agents who don’t pickup a call are recorded along with the one actual call. I think we can switch this off in v15. that’ll be helpful
As well i see call recordings are all gsm format. Whilst appreciating this means less storage space being used, does it introduce an unwanted overhead into system operation ?
Lastly, i was wrong previously, the server it’s on at present actually has 24 GB ram not 16 GB. I can look at increasing this if required, but 24 GB does seem to be a pretty healthy amount.

As before, any suggestion is welcome.

dicko · March 25, 2021, 6:21am

Using only g711 and recording to .wav will minimize both cpu and memory requirements. I’n surprised that your machine is struggling given its specs and load though.

jon_b · March 25, 2021, 6:44am

Your surprise is shared by many here as well. 8 CPU cores & 24GB of memory shouldn’t be raising a sweat with this number of calls.

I’ve just been looking at the system logs around the mid-morning incident today. It clearly shows an Asterisk restart but i can’t see what led up to this.

Disclaimer: my expertise with Asterisk log files is next to zero…

dicko · March 25, 2021, 6:47am

Post some log lines just prior to the restart and Is there any bitching in /var/log/messages when asterisk restarted

jon_b · March 25, 2021, 7:13am

What’s the best way to post log files ?
Just cut & paste seem a little “agricultural”

dicko · March 25, 2021, 7:14am

Pastebin of your flavor

grep -C 200 [time of reboot ] /var/log/asterisk/full | pastebinit

sort of thing

jon_b · March 25, 2021, 8:14am

need to work on my pastebinit skills.
Anyway, here’s what /var/log/messages has to say about the morning’s episode

Mar 25 08:25:01 freepbx auditd[785]: Audit daemon rotating Mar 25 08:32:57 freepbx systemd-logind: Removed session Mar 25 09:35:33 freepbx chronyd[877]: Selected source Mar 25 09:54:49 freepbx kernel: letschat invoked oom-killer: Mar 25 09:54:49 freepbx kernel: letschat cpuset=/ mems_allow Mar 25 09:54:49 freepbx kernel: CPU: 0 PID: 3437 Comm: Mar 25 09:54:49 freepbx kernel: Hardware name: HP ProLiant Mar 25 09:54:49 freepbx kernel: Call Trace:
Mar 25 09:54:49 freepbx kernel: [] dump_stack+0x19/0x1b
Mar 25 09:54:49 freepbx kernel: [] dump_header+0x90/0x229
Mar 25 09:54:49 freepbx kernel: Mem-Info:
Mar 25 09:54:49 freepbx kernel: active_anon:5412686 Mar 25 09:54:49 freepbx kernel: Node 0 DMA free:15820kB Mar 25 09:54:49 freepbx kernel: lowmem_reserve[]: 0 Mar 25 09:54:49 freepbx kernel: Node 0 DMA32 free:91572kB Mar 25 09:54:49 freepbx kernel: lowmem_reserve[]: 0 Mar 25 09:54:50 freepbx kernel: Node 0 Normal free:57792kB Mar 25 09:54:50 freepbx kernel: lowmem_reserve[]: 0 Mar 25 09:54:50 freepbx kernel: Node 0 DMA: 14kB Mar 25 09:54:50 freepbx kernel: Node 0 DMA32: 6444kB Mar 25 09:54:50 freepbx kernel: Node 0 Normal: 18184kB Mar 25 09:54:50 freepbx kernel: Node 0 hugepages_total=0 Mar 25 09:54:50 freepbx kernel: Node 0 hugepages_total=0 Mar 25 09:54:50 freepbx kernel: 18073 total pagecache Mar 25 09:54:50 freepbx kernel: 908 pages in swap cache
Mar 25 09:54:50 freepbx kernel: Swap cache stats: add Mar 25 09:54:50 freepbx kernel: Free swap = 0kB
Mar 25 09:54:50 freepbx kernel: Total swap = 12386300kB
Mar 25 09:54:50 freepbx kernel: 6288829 pages RAM
Mar 25 09:54:50 freepbx kernel: 0 pages HighMem/MovableOnly< Mar 25 09:54:50 freepbx kernel: 161632 pages reserved
Mar 25 09:54:50 freepbx kernel: [ pid ] uid tgid total_vm Mar 25 09:54:50 freepbx kernel: [ 604] 0 604 33630 12091 Mar 25 09:54:50 freepbx kernel: [ 624] 0 624 86509 Mar 25 09:54:50 freepbx kernel: [ 634] 0 634 11317 Mar 25 09:54:50 freepbx kernel: [ 785] 0 785 13883 Mar 25 09:54:50 freepbx kernel: [ 810] 994 810 153062 Mar 25 09:54:50 freepbx kernel: [ 811] 0 811 5418 Mar 25 09:54:50 freepbx kernel: [ 813] 0 813 3760 Mar 25 09:54:50 freepbx kernel: [ 814] 32 814 17320 Mar 25 09:54:50 freepbx kernel: [ 818] 81 818 14565 Mar 25 09:54:50 freepbx kernel: [ 820] 0 820 1767 Mar 25 09:54:50 freepbx kernel: [ 831] 0 831 6654 Mar 25 09:54:50 freepbx kernel: [ 833] 70 833 15052 Mar 25 09:54:50 freepbx kernel: [ 838] 70 838 15020 Mar 25 09:54:50 freepbx kernel: [ 877] 991 877 29452 Mar 25 09:54:50 freepbx kernel: [ 1181] 0 1181 28231 Mar 25 09:54:50 freepbx kernel: [ 1186] 99 1186 13475 Mar 25 09:54:50 freepbx kernel: [ 1187] 0 1187 143575 Mar 25 09:54:50 freepbx kernel: [ 1191] 990 1191 36788 Mar 25 09:54:50 freepbx kernel: [ 1192] 0 1192 92750 Mar 25 09:54:50 freepbx kernel: [ 1199] 0 1199 6792 Mar 25 09:54:50 freepbx kernel: [ 1224] 0 1224 66920 Mar 25 09:54:50 freepbx kernel: [ 1225] 0 1225 156194 Mar 25 09:54:50 freepbx kernel: [ 1247] 0 1247 6477 Mar 25 09:54:50 freepbx kernel: [ 1252] 0 1252 31604 Mar 25 09:54:50 freepbx kernel: [ 1325] 0 1325 27551 Mar 25 09:54:50 freepbx kernel: [ 1358] 27 1358 28353 Mar 25 09:54:50 freepbx kernel: [ 1652] 27 1652 1205876 93154 Mar 25 09:54:50 freepbx kernel: [ 1808] 0 1808 22426 Mar 25 09:54:50 freepbx kernel: [ 1810] 89 1810 22496 Mar 25 09:54:50 freepbx kernel: [ 1828] 184 1828 120485 Mar 25 09:54:50 freepbx kernel: [ 1948] 995 1948 49524 Mar 25 09:54:50 freepbx kernel: [ 2072] 995 2072 253416 Mar 25 09:54:50 freepbx kernel: [ 2097] 0 2097 39327 Mar 25 09:54:50 freepbx kernel: [ 2152] 0 2152 28886 Mar 25 09:54:50 freepbx kernel: [ 2650] 0 2650 28853 Mar 25 09:54:50 freepbx kernel: [ 2881] 995 2881 255143 10672 Mar 25 09:54:50 freepbx kernel: [ 3437] 995 3437 319489 Mar 25 09:54:50 freepbx kernel: [ 8693] 0 8693 39360 Mar 25 09:54:50 freepbx kernel: [ 9048] 0 9048 28886 Mar 25 09:54:50 freepbx kernel: [31546] 995 31546 188741 Mar 25 09:54:50 freepbx kernel: [10267] 995 10267 185978 Mar 25 09:54:50 freepbx kernel: [28328] 0 28328 30799 Mar 25 09:54:50 freepbx kernel: [19627] 995 19627 188664 Mar 25 09:54:50 freepbx kernel: [31214] 995 31214 9343014 5272770 Mar 25 09:54:50 freepbx kernel: [28168] 995 28168 188722 Mar 25 09:54:50 freepbx kernel: [30739] 995 30739 186013 Mar 25 09:54:50 freepbx kernel: [30746] 995 30746 188663 Mar 25 09:54:50 freepbx kernel: [ 4627] 0 4627 40560 Mar 25 09:54:50 freepbx kernel: [28733] 995 28733 183643 Mar 25 09:54:50 freepbx kernel: [ 3040] 995 3040 275025 15286 Mar 25 09:54:50 freepbx kernel: [28643] 995 28643 182623 Mar 25 09:54:50 freepbx kernel: [26600] 995 26600 185437 Mar 25 09:54:50 freepbx kernel: [27313] 995 27313 121271 Mar 25 09:54:50 freepbx kernel: [27314] 995 27314 121271 Mar 25 09:54:50 freepbx kernel: [27315] 995 27315 121271 Mar 25 09:54:50 freepbx kernel: [27317] 995 27317 121271 Mar 25 09:54:50 freepbx kernel: [27318] 995 27318 121271 Mar 25 09:54:50 freepbx kernel: [27321] 995 27321 121271 Mar 25 09:54:50 freepbx kernel: [27322] 995 27322 121271 Mar 25 09:54:50 freepbx kernel: [27327] 995 27327 121271 Mar 25 09:54:50 freepbx kernel: [27461] 995 27461 121271 Mar 25 09:54:50 freepbx kernel: [27462] 995 27462 121271 Mar 25 09:54:50 freepbx kernel: [27464] 995 27464 121271 Mar 25 09:54:50 freepbx kernel: [28491] 89 28491 22452 Mar 25 09:54:50 freepbx kernel: [ 6088] 995 6088 182603 Mar 25 09:54:50 freepbx kernel: [ 6104] 995 6104 182613 Mar 25 09:54:50 freepbx kernel: [ 6109] 995 6109 183221 Mar 25 09:54:50 freepbx kernel: [ 6111] 995 6111 185439 Mar 25 09:54:50 freepbx kernel: [23302] 0 23302 45625 Mar 25 09:54:50 freepbx kernel: [23305] 995 23305 28320 Mar 25 09:54:50 freepbx kernel: [23414] 995 23414 128085 11544 Mar 25 09:54:50 freepbx kernel: [27257] 995 27257 121271 Mar 25 09:54:50 freepbx kernel: [27609] 995 27609 121271 Mar 25 09:54:50 freepbx kernel: [27616] 995 27616 121271 Mar 25 09:54:50 freepbx kernel: [27619] 995 27619 121271 Mar 25 09:54:50 freepbx kernel: [27622] 995 27622 121271 Mar 25 09:54:50 freepbx kernel: [27626] 995 27626 121271 Mar 25 09:54:50 freepbx kernel: [27646] 995 27646 121271 Mar 25 09:54:50 freepbx kernel: [27653] 995 27653 111859 Mar 25 09:54:50 freepbx kernel: [27658] 995 27658 121271 Mar 25 09:54:51 freepbx kernel: [27806] 995 27806 121271 Mar 25 09:54:51 freepbx kernel: [27807] 995 27807 121271 Mar 25 09:54:51 freepbx kernel: [27814] 995 27814 121271 Mar 25 09:54:51 freepbx kernel: [27865] 995 27865 121271 Mar 25 09:54:51 freepbx kernel: [27995] 995 27995 121271 Mar 25 09:54:51 freepbx kernel: [28012] 995 28012 121271 Mar 25 09:54:51 freepbx kernel: [28255] 995 28255 121271 Mar 25 09:54:51 freepbx kernel: [28412] 995 28412 121271 Mar 25 09:54:51 freepbx kernel: [28455] 995 28455 121271 Mar 25 09:54:51 freepbx kernel: [28468] 995 28468 121271 Mar 25 09:54:51 freepbx kernel: [28481] 995 28481 121399 Mar 25 09:54:51 freepbx kernel: [28586] 995 28586 120759 Mar 25 09:54:51 freepbx kernel: [28598] 995 28598 121271 Mar 25 09:54:51 freepbx kernel: [28599] 995 28599 120759 Mar 25 09:54:51 freepbx kernel: [28600] 995 28600 120759 Mar 25 09:54:51 freepbx kernel: [28601] 995 28601 120759 Mar 25 09:54:51 freepbx kernel: [28602] 995 28602 120759 Mar 25 09:54:51 freepbx kernel: [28604] 995 28604 120759 Mar 25 09:54:51 freepbx kernel: [28606] 995 28606 121271 Mar 25 09:54:51 freepbx kernel: [28608] 995 28608 120759 Mar 25 09:54:51 freepbx kernel: [28610] 995 28610 120759 Mar 25 09:54:51 freepbx kernel: [28612] 995 28612 120759 Mar 25 09:54:51 freepbx kernel: [28617] 995 28617 120759 Mar 25 09:54:51 freepbx kernel: [28619] 995 28619 121271 Mar 25 09:54:51 freepbx kernel: [28623] 995 28623 120759 Mar 25 09:54:51 freepbx kernel: [28625] 995 28625 121271 Mar 25 09:54:51 freepbx kernel: [28630] 995 28630 121271 Mar 25 09:54:51 freepbx kernel: [28637] 995 28637 121271 Mar 25 09:54:51 freepbx kernel: [28713] 995 28713 121271 Mar 25 09:54:51 freepbx kernel: [28720] 995 28720 121271 Mar 25 09:54:51 freepbx kernel: [28743] 0 28743 45625 Mar 25 09:54:51 freepbx kernel: [28744] 0 28744 45625 Mar 25 09:54:51 freepbx kernel: [28745] 0 28745 45625 Mar 25 09:54:51 freepbx kernel: [28746] 995 28746 28320 Mar 25 09:54:51 freepbx kernel: [28747] 995 28747 28320 Mar 25 09:54:51 freepbx kernel: [28748] 995 28748 28320 Mar 25 09:54:51 freepbx kernel: [28750] 995 28750 124027 Mar 25 09:54:51 freepbx kernel: [28751] 995 28751 125237 Mar 25 09:54:51 freepbx kernel: [28865] 995 28865 121271 Mar 25 09:54:51 freepbx kernel: [28867] 995 28867 120759 Mar 25 09:54:51 freepbx kernel: [28868] 995 28868 121271 Mar 25 09:54:51 freepbx kernel: [28869] 995 28869 120759 Mar 25 09:54:51 freepbx kernel: [28870] 995 28870 121271 Mar 25 09:54:51 freepbx kernel: [28871] 995 28871 121271 Mar 25 09:54:51 freepbx kernel: [28873] 995 28873 121271 Mar 25 09:54:51 freepbx kernel: [28878] 995 28878 121271 Mar 25 09:54:51 freepbx kernel: [28881] 995 28881 121271 Mar 25 09:54:51 freepbx kernel: [28902] 995 28902 121271 Mar 25 09:54:51 freepbx kernel: [28906] 995 28906 121271 Mar 25 09:54:51 freepbx kernel: [28908] 995 28908 121271 Mar 25 09:54:51 freepbx kernel: [28928] 995 28928 121271 Mar 25 09:54:51 freepbx kernel: [28934] 995 28934 121271 Mar 25 09:54:51 freepbx kernel: [28943] 995 28943 121271 Mar 25 09:54:51 freepbx kernel: [28957] 995 28957 121271 Mar 25 09:54:51 freepbx kernel: [29056] 995 29056 120759 Mar 25 09:54:51 freepbx kernel: [29057] 995 29057 120759 Mar 25 09:54:51 freepbx kernel: [29058] 995 29058 120759 Mar 25 09:54:51 freepbx kernel: [29062] 995 29062 120759 Mar 25 09:54:51 freepbx kernel: [29063] 995 29063 120759 Mar 25 09:54:51 freepbx kernel: [29064] 995 29064 120759 Mar 25 09:54:51 freepbx kernel: [29065] 995 29065 120759 Mar 25 09:54:51 freepbx kernel: [29066] 995 29066 120759 Mar 25 09:54:51 freepbx kernel: [29067] 995 29067 120759 Mar 25 09:54:51 freepbx kernel: [29068] 995 29068 120759 Mar 25 09:54:51 freepbx kernel: [29069] 995 29069 120759 Mar 25 09:54:51 freepbx kernel: [29073] 995 29073 120759 Mar 25 09:54:51 freepbx kernel: [29074] 995 29074 120759 Mar 25 09:54:51 freepbx kernel: [29075] 995 29075 120759 Mar 25 09:54:51 freepbx kernel: [29076] 995 29076 120759 Mar 25 09:54:51 freepbx kernel: [29077] 995 29077 120759 Mar 25 09:54:51 freepbx kernel: [29130] 995 29130 120721 Mar 25 09:54:51 freepbx kernel: [29150] 995 29150 120759 Mar 25 09:54:51 freepbx kernel: [29167] 995 29167 120759 Mar 25 09:54:51 freepbx kernel: [29402] 995 29402 120759 Mar 25 09:54:51 freepbx kernel: [29405] 995 29405 120759 Mar 25 09:54:51 freepbx kernel: [29406] 995 29406 120759 Mar 25 09:54:51 freepbx kernel: [29407] 995 29407 120759 Mar 25 09:54:51 freepbx kernel: [29408] 995 29408 120759 Mar 25 09:54:51 freepbx kernel: [29411] 995 29411 120759 Mar 25 09:54:51 freepbx kernel: [29413] 995 29413 120759 Mar 25 09:54:51 freepbx kernel: [29415] 995 29415 120759 Mar 25 09:54:51 freepbx kernel: [29418] 995 29418 120759 Mar 25 09:54:51 freepbx kernel: [29440] 995 29440 120439 Mar 25 09:54:51 freepbx kernel: [29450] 995 29450 120439 Mar 25 09:54:51 freepbx kernel: [29454] 995 29454 120439 Mar 25 09:54:51 freepbx kernel: [29455] 995 29455 120439 Mar 25 09:54:51 freepbx kernel: [29456] 995 29456 120439 Mar 25 09:54:51 freepbx kernel: [29457] 995 29457 120439 Mar 25 09:54:51 freepbx kernel: [29458] 995 29458 120439 Mar 25 09:54:51 freepbx kernel: [29472] 995 29472 120439 Mar 25 09:54:51 freepbx kernel: [29473] 995 29473 120439 Mar 25 09:54:51 freepbx kernel: [29474] 995 29474 120439 Mar 25 09:54:51 freepbx kernel: [29475] 995 29475 120439 Mar 25 09:54:51 freepbx kernel: [29476] 995 29476 120439 Mar 25 09:54:51 freepbx kernel: [29477] 995 29477 120439 Mar 25 09:54:51 freepbx kernel: [29478] 995 29478 120439 Mar 25 09:54:51 freepbx kernel: [29479] 995 29479 120439 Mar 25 09:54:51 freepbx kernel: [29480] 995 29480 120439 Mar 25 09:54:51 freepbx kernel: [29481] 995 29481 120439 Mar 25 09:54:51 freepbx kernel: [29482] 995 29482 120439 Mar 25 09:54:51 freepbx kernel: [29483] 995 29483 120439 Mar 25 09:54:51 freepbx kernel: [29487] 995 29487 120439 Mar 25 09:54:51 freepbx kernel: [29488] 995 29488 120439 Mar 25 09:54:51 freepbx kernel: [29489] 995 29489 120439 Mar 25 09:54:51 freepbx kernel: [29499] 995 29499 120439 Mar 25 09:54:51 freepbx kernel: [29529] 995 29529 119448 Mar 25 09:54:51 freepbx kernel: [29530] 995 29530 119448 Mar 25 09:54:51 freepbx kernel: [29585] 995 29585 61225 Mar 25 09:54:51 freepbx kernel: [29587] 995 29587 61225 Mar 25 09:54:51 freepbx kernel: [29639] 995 29639 18102 Mar 25 09:54:51 freepbx kernel: [29640] 995 29640 2391 Mar 25 09:54:51 freepbx kernel: [29641] 995 29641 2391 Mar 25 09:54:51 freepbx kernel: [29642] 995 29642 2391 Mar 25 09:54:51 freepbx kernel: Out of memory: Kill Mar 25 09:54:52 freepbx kernel: Killed process 31214 Mar 25 09:56:32 freepbx kernel: TCP: request_sock_TCP: log files
9345.
132.181.2.72
gfp_mask=0x201da, order=0, oom_score_adj=0
ed=0
letschat Kdump: loaded Tainted: G IOE ------------ 3.10.0-1127.19.1.el7.x86_64 #1
ML350 G6, BIOS D22 05/21/2018
> 0
3f0
ersects+0x21/0x30
d/0x120
0xc0

5db/0x729
436/0x450
0x110
xb0

[xfs]
[xfs]
x100
c/0x1b0
b0
00
r> br> inactive_anon:510173 isolated_anon:0#012 active_file:4023 inactive_file:4076 isolated_file:29#012 unevictable:0 dirty:2 writeback:0 unstable:0#012 slab_reclaimable:30007 slab_unreclaimable:23754#012 mapped:9500 shmem:9178 pagetables:40379 bounce:0#012 free:41296 free_pcp:1341 free_cma:0
min:40kB low:48kB high:60kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:16kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
3441 23915 23915
min:9716kB low:12144kB high:14572kB active_anon:2764788kB inactive_anon:588328kB active_file:1668kB inactive_file:1520kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3774592kB managed:3527140kB mlocked:0kB dirty:0kB writeback:0kB mapped:5124kB shmem:5156kB slab_reclaimable:15628kB slab_unreclaimable:12228kB kernel_stack:2480kB pagetables:30152kB unstable:0kB bounce:0kB free_pcp:2264kB local_pcp:120kB free_cma:0kB writeback_tmp:0kB pages_scanned:6422 all_unreclaimable? yes
0 20474 20474
min:57820kB low:72272kB high:86728kB active_anon:18885956kB inactive_anon:1452364kB active_file:14424kB inactive_file:14784kB unevictable:0kB isolated(anon):0kB isolated(file):116kB present:21364732kB managed:20965740kB mlocked:0kB dirty:8kB writeback:0kB mapped:32876kB shmem:31556kB slab_reclaimable:104400kB slab_unreclaimable:82772kB kernel_stack:13280kB pagetables:131364kB unstable:0kB bounce:0kB free_pcp:3100kB local_pcp:464kB free_cma:0kB writeback_tmp:0kB pages_scanned:49970 all_unreclaimable? yes
0 0 0
(U) 18kB (U) 016kB 032kB 164kB (U) 1128kB (U) 1256kB (U) 0512kB 11024kB (U) 12048kB (M) 34096kB (M) = 15820kB
(UEM) 5978kB (UEM) 70016kB (UEM) 31432kB (UEM) 23664kB (UEM) 93128kB (UEM) 52256kB (UEM) 11512kB (UEM) 151024kB (UEM) 12048kB (M) 04096kB = 91960kB
(UE) 59858kB (UEM) 17116kB (U) 032kB 064kB 0128kB 0256kB 0512kB 01024kB 02048kB 0*4096kB = 57888kB
hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
pages
7862179, delete 7861354, find 2480432/2704020
br> rss nr_ptes swapents oom_score_adj name
72 60 0 systemd-journal
0 33 149 0 lvmetad
15 23 205 -1000 systemd-udevd
30 27 82 -1000 auditd
92 63 1798 0 polkitd
57 15 33 0 irqbalance
12 13 68 0 incrond
22 37 119 0 rpcbind
91 32 72 -900 dbus-daemon
30 9 16 0 mdadm
55 20 92 0 systemd-logind
36 32 81 0 avahi-daemon
7 31 91 0 avahi-daemon
54 28 81 0 chronyd
34 59 244 -1000 sshd
20 31 81 0 dnsmasq
117 96 2737 0 tuned
308 19 1182 0 redis-server
6475 87 463 0 rsyslogd
4 18 63 0 xinetd
237 90 6107 0 python3.6
628 223 1764 0 httpd
15 18 47 0 atd
143 20 58 0 crond
11 10 31 0 agetty
14 13 72 0 mysqld_safe
403 28912 0 mysqld
18 42 242 0 master
25 42 247 0 qmgr
1273 90 6411 0 mongod
77 52 1053 0 pnp_server
4157 127 6800 0 PM2 v4.5.0: God
93 83 283 0 sshd
59 15 74 0 bash
49 11 39 0 safe_asterisk
125 896 0 node /var/www/h
6829 234 20323 0 letschat
75 79 286 0 sshd
13 14 107 0 bash
1844 260 5458 0 httpd
1848 251 4935 0 httpd
299 16 40 0 htop
3961 259 3311 0 httpd
16607 2929415 0 asterisk
3934 259 3329 0 httpd
3907 252 3041 0 httpd
3818 258 3412 0 httpd
156 35 74 0 top
1958 237 3064 0 httpd
163 1386 0 node /var/www/h
2654 235 1365 0 httpd
3749 249 3008 0 httpd
545 143 4163 0 php
545 143 4163 0 php
43 140 4603 0 php
549 144 4097 0 php
575 143 4131 0 php
546 144 4162 0 php
549 144 4097 0 php
549 141 4097 0 php
43 145 4603 0 php
545 147 4164 0 php
546 141 4161 0 php
51 43 238 0 pickup
2573 231 1364 0 httpd
2539 232 1427 0 httpd
3139 232 1360 0 httpd
5103 248 1669 0 httpd
232 45 43 0 crond
73 13 0 0 sh
157 0 0 php
4685 142 0 0 php
4647 141 0 0 php
4675 140 0 0 php
4685 146 0 0 php
4684 144 0 0 php
4668 143 0 0 php
4684 141 0 0 php
2816 127 0 0 php
4685 146 0 0 php
4692 141 0 0 php
4692 142 0 0 php
4693 146 0 0 php
4682 143 0 0 php
4646 144 0 0 php
4669 142 0 0 php
4675 145 0 0 php
4675 145 0 0 php
4675 142 0 0 php
4676 143 0 0 php
4849 141 0 0 php
4129 140 0 0 php
4680 143 0 0 php
4129 144 0 0 php
4129 145 0 0 php
4128 142 0 0 php
4128 143 0 0 php
4129 141 0 0 php
4662 143 0 0 php
4129 141 0 0 php
4129 143 0 0 php
4129 139 0 0 php
4129 140 0 0 php
4680 142 0 0 php
4129 141 0 0 php
4678 147 0 0 php
4678 142 0 0 php
4668 143 0 0 php
4678 145 0 0 php
4678 148 0 0 php
232 45 43 0 crond
232 45 43 0 crond
232 45 43 0 crond
44 13 0 0 sh
44 13 0 0 sh
43 13 0 0 sh
7416 151 0 0 php
8708 151 0 0 check_system_se
4643 146 0 0 php
4085 143 0 0 php
4642 146 0 0 php
4084 138 0 0 php
4679 144 0 0 php
4643 143 0 0 php
4676 146 0 0 php
4643 141 0 0 php
4643 144 0 0 php
4642 146 0 0 php
4643 140 0 0 php
4642 146 0 0 php
4643 145 0 0 php
4642 145 0 0 php
4643 143 0 0 php
4642 143 0 0 php
4127 139 0 0 php
4127 144 0 0 php
4126 141 0 0 php
4096 141 0 0 php
4127 145 0 0 php
4127 146 0 0 php
4126 141 0 0 php
4126 144 0 0 php
4117 143 0 0 php
4127 143 0 0 php
4127 143 0 0 php
4127 142 0 0 php
4126 141 0 0 php
4127 144 0 0 php
4127 141 0 0 php
4126 146 0 0 php
4159 141 0 0 php
4124 140 0 0 php
4124 146 0 0 php
4127 146 0 0 php
4127 143 0 0 php
4127 146 0 0 php
4121 144 0 0 php
4127 141 0 0 php
4128 139 0 0 php
4115 141 0 0 php
4116 140 0 0 php
4124 144 0 0 php
3790 141 0 0 php
3790 143 0 0 php
3818 142 0 0 php
3791 140 0 0 php
3791 139 0 0 php
3791 142 0 0 php
3791 139 0 0 php
3790 141 0 0 php
3791 140 0 0 php
3818 142 0 0 php
3796 142 0 0 php
3791 145 0 0 php
3818 146 0 0 php
3818 141 0 0 php
3790 140 0 0 php
3791 138 0 0 php
3791 144 0 0 php
3796 139 0 0 php
3790 145 0 0 php
3791 141 0 0 php
3818 139 0 0 php
3791 138 0 0 php
3818 141 0 0 php
2769 140 0 0 php
2769 138 0 0 php
609 72 0 0 php
609 73 0 0 php
311 39 0 0 sangomacrm.agi
36 9 0 0 sh
36 10 0 0 sh
36 10 0 0 sh
process 31214 (asterisk) score 891 or sacrifice child
(asterisk), UID 995, total-vm:37372056kB, anon-rss:21091080kB, file-rss:0kB, shmem-rss:0kB
Possible SYN flooding on port 5038. Sending cookies. Check SNMP counters.

jon_b · March 25, 2021, 8:20am

/var/log/asterisk/full around 0954

[2021-03-25 09:54:46] VERBOSE[27921][C-0000113a] app_mixmonitor.c: End MixMonitor Recording Local/352@from-queue-000104bc;2
[2021-03-25 09:54:46] WARNING[31341] chan_sip.c: Autodestruct on dialog ‘[email protected]’ with owner SIP/02825582324-0000cbd2 in place (Method: BYE). Rescheduling destruction for 10000 ms
[2021-03-25 09:54:47] WARNING[31341] chan_sip.c: Autodestruct on dialog ‘[email protected]’ with owner SIP/02825582324-0000cbfb in place (Method: BYE). Rescheduling destruction for 10000 ms
[2021-03-25 09:54:48] WARNING[31341] chan_sip.c: Autodestruct on dialog ‘[email protected]’ with owner SIP/02825582324-0000cb5f in place (Method: BYE). Rescheduling destruction for 10000 ms
[2021-03-25 09:54:48] WARNING[31341] chan_sip.c: Autodestruct on dialog ‘[email protected]’ with owner SIP/02825582324-0000cc21 in place (Method: BYE). Rescheduling destruction for 10000 ms
[2021-03-25 09:54:56] Asterisk 16.15.1 built by mockbuild @ jenkins7 on a x86_64 running Linux on 2020-12-23 15:37:11 UTC
[2021-03-25 09:54:56] VERBOSE[29763] message.c: Message handler ‘dialplan’ registered.
[2021-03-25 09:54:56] VERBOSE[29763] pbx_functions.c: Registered custom function ‘MESSAGE’
[2021-03-25 09:54:56] VERBOSE[29763] pbx_functions.c: Registered custom function ‘MESSAGE_DATA’
[2021-03-25 09:54:56] VERBOSE[29763] pbx_app.c: Registered application ‘MessageSend’
[2021-03-25 09:54:56] VERBOSE[29763] manager.c: Manager registered action MessageSend
[2021-03-25 09:54:56] VERBOSE[29763] channel.c: Registered channel type ‘Surrogate’ (Surrogate channel used to pull channel from an application)
[2021-03-25 09:54:56] VERBOSE[29763] manager.c: Manager registered action BridgeTechnologyList
[2021-03-25 09:54:56] VERBOSE[29763] manager.c: Manager registered action BridgeTechnologySuspend
[2021-03-25 09:54:56] VERBOSE[29763] manager.c: Manager registered action BridgeTechnologyUnsuspend
[2021-03-25 09:54:56] VERBOSE[29763] dns_core.c: Registered DNS resolver ‘system’ with priority ‘2147483647’
[2021-03-25 09:54:56] VERBOSE[29763] pbx.c: Asterisk PBX Core Initializing
[2021-03-25 09:54:56] VERBOSE[29763] pbx.c: Registering builtin functions:
[2021-03-25 09:54:56] VERBOSE[29763] pbx_functions.c: Registered custom function ‘EXCEPTION’
[2021-03-25 09:54:56] VERBOSE[29763] pbx_functions.c: Registered custom function ‘TESTTIME’
[2021-03-25 09:54:56] VERBOSE[29763] manager.c: Manager registered action ShowDialPlan

xrobau · March 25, 2021, 8:20am

I think this explains your problem. Your machine doesn’t have enough memory. WHY it doesn’t have enough memory is a different question.

dicko · March 25, 2021, 8:22am

My guess, yes oom, but why ?

Mar 25 09:54:51 freepbx kernel: [29529] 995 29529 119448 2769 140 0 0 php
Mar 25 09:54:51 freepbx kernel: [29530] 995 29530 119448 2769 138 0 0 php
Mar 25 09:54:51 freepbx kernel: [29585] 995 29585 61225 609 72 0 0 php
Mar 25 09:54:51 freepbx kernel: [29587] 995 29587 61225 609 73 0 0 php
Mar 25 09:54:51 freepbx kernel: [29639] 995 29639 18102 311 39 0 0 sangomacrm.agi
Mar 25 09:54:51 freepbx kernel: [29640] 995 29640 2391 36 9 0 0 sh
Mar 25 09:54:51 freepbx kernel: [29641] 995 29641 2391 36 10 0 0 sh
Mar 25 09:54:51 freepbx kernel: [29642] 995 29642 2391 36 10 0 0 sh
Mar 25 09:54:51 freepbx kernel: Out of memory: Kill process 31214 (asterisk) score 891 or sacrifice child
Mar 25 09:54:52 freepbx kernel: Killed process 31214 (asterisk), UID 995, total-vm:37372056kB, anon-rss:21091080kB, file-rss:0kB, shmem-rss:0kB
Mar 25 09:56:32 freepbx kernel: TCP: request_sock_TCP: Possible SYN flooding on port 5038. Sending cookies. Check SNMP counters.

Would lead me to suspect that xmpp had a brainfart and sent lots of php processes to AMI all at the same time

PitzKey · March 25, 2021, 8:29am

If you don’t have it yet enabled, enable FastAGI under advanced settings and restart the PBX.

Then, uninstall any module you don’t use. If you don’t need SangomaCRM, Zulu, iSymphony, SIP Station etc uninstall it

dicko · March 25, 2021, 8:30am

Particularly xmpp (letschat)

jon_b · March 25, 2021, 8:31am

No doubt it’s an oom issue, but yes why ?
When is 24 GB not enough ?

Remember this (well i think it’s the same issue, definitely the same symptoms) has happened on a Sangoma Blue Box running v13 and now on an HP server running v15.

dicko · March 25, 2021, 8:32am

Well xmpp caused the oom handler to begin, is that avalanche of php processes letschat ? I don’t know. Do you use it?