Is there any way to keep my log from being filled with PUBLISH requests?

FreePBX Security
1

So I now have a fleet of Cisco CP-8941s on FreePBX17. These run Enterprise firmware only Cisco never released multiprotocol 3rd party call control firmware for them.

There’s an annoying feature/misfeature with these phones. Every once in a while, for some unknown reason, a random phone in the network will start sending out constant PUBLISH requests and filling up the log, here’s an example:

[2025-10-29 12:39:14] NOTICE[1511995]: res_pjsip/pjsip_distributor.c:688 log_failed_request: Request 'PUBLISH' from '<sip:[email protected]>' failed for '172.16.160.22:46554' (callid: [email protected]) - Failed to authenticate
[2025-10-29 12:39:19] NOTICE[2958916]: res_pjsip/pjsip_distributor.c:688 log_failed_request: Request 'PUBLISH' from '<sip:[email protected]>' failed for '172.16.160.22:46554' (callid: [email protected]) - Failed to authenticate
[2025-10-29 12:39:24] NOTICE[383801]: res_pjsip/pjsip_distributor.c:688 log_failed_request: Request 'PUBLISH' from '<sip:[email protected]>' failed for '172.16.160.22:46554' (callid: [email protected]) - Failed to authenticate
[2025-10-29 12:39:29] NOTICE[1080276]: res_pjsip/pjsip_distributor.c:688 log_failed_request: Request 'PUBLISH' from '<sip:[email protected]>' failed for '172.16.160.22:46554' (callid: [email protected]) - Failed to authenticate

In this case the phone at IP 172.16.160.22 is on extension 5358, and it is registered in:

phony*CLI> pjsip list endpoints

.
.
 Endpoint:  5358/5358                                            Not in use    0 of inf
.
.

you can make and get calls with it no problem.

If I ssh into the phone and reboot it - then it stops doing it. I don’t know WHAT it’s doing - it’s trying to use it’s hostname as the username for the @sip - but it’s probably something trivial and/or weird like trying to get message light status or something like that with the Cisco enterprise firmware supports in a weird way.

Anyway, there’s nothing I can do to the phone to get it to stop doing whatever it’s doing - Cisco never released 3rd party call control firmware for this phone - and I was wondering if there’s anyway to set a flag on the extension entry in FreePBX that will make it ignore these and stop filling up the log?

2

This is more precisely a failed authentication. As such it is likely that it was faulted before it was identified as publish, in which case, it would take quite detailed source code changes to retain logging of other authentication failures.

3

Asterisk doesn’t handle PUBLISH requests so even if it does authenticate it will be rejected.

4

Drat. Oh well.

Now, I’d just like to figure out how to get the thousands of

[2025-10-29 13:28:12] DEBUG[1613]: threadpool.c:536 grow: Increasing threadpool stasis/pool's size by 0
[2025-10-29 13:28:12] DEBUG[1613]: threadpool.c:536 grow: Increasing threadpool stasis/pool's size by 0

to go away when debugging is at the highest level.

5

There is no ability, aside from editing the code or lowering the level. That message itself is at level 3.

6

Is there any way to pre-increase the threadpool so that it’s big enough so the system doesn’t have to constantly do it?

7

Are you are sure these are only intermittent short term overloads? If the average traffic is too high, queuing theory would tend to suggest that the queue length will go up very rapidly with offered traffic, if the queues are already very long.

Note there have been several threads, in the past, about how you could attack the symptom, but you really need to address the cause.

8

The PBX is currently in a building with no employees in it yet, that hasn’t gone online yet, and there are only 80 extensions on it. The only thing I can do is boost the memory, or CPU, or disk space of the virtual machine that FreePBX is running in. What do you recommend for something like this? I’d estimate in operation at peak maybe 10 concurrent calls on average…

9

Is there an actual problem, or are you thinking there is a problem based on a debug level message?

10

I am wondering if it indicates a problem. Standard Operating Practice in all UNIX programs I have used is no output indicates success, output indicates failure. So if it’s spitting out a human readable log message the usual idea I’ve encountered is the programmer who wrote the code wants a human to look at the message for some reason.

Interestingly, just searching the forum for “increasing threadpool” brings up 11 messages from the forum - all of which have that string in them as a side effect of people posting log snippits about some other problem and having a few “increasing threadpool” messages leak into the log. Which of course indicates that this log spamming is likely endemic to all FreePBX installs.

It does seem counterproductive to have a debug message that is just a meaningless “notice” type of message which increases the time needed to read through a full capture of the log.

11

If debug messages are enabled people think there are problems because it gives insight into logic and what is going on - not outright errors. Sometimes these log messages show normal operation, sometimes they don’t. It requires context to know what is actually going on.

In this case something was queued to a threadpool. No thread was available to handle it. It tried to grow the threadpool. Configuration didn’t allow it to grow. The thing wanting a thread will wait for one to become available. This is normal, and what the threadpool is designed to do.

Where this falls apart is if the rate of threadpool users queueing things exceeds the rate at which the number of threads can handle things. If the queue grows unbound and alerts (which is what the /pool taskprocessor is) then that indicates either the threadpool is undersized, or some other fundamental problem. Unless that’s happening there’s nothing going on to look at.

I don’t know what FreePBX sets for default logging settings, for Asterisk we don’t enable it by default. A user has to explicitly do so which is why we provide instructions for collecting such information.

13

I can understand that explanation but what should then follow is if I please, I can change the configuration so the threadpool is bigger which will then reduce the incidence of these messages.

I took a look at:

Performance Tuning - Asterisk Documentation

which has much to say about this and shows where to change that config. But that’s Asterisk only.

In FreePBX in the various config interfaces I can find nothing about threadpool - which indicates that in order to raise it, pjsip.conf must be modified - however the autogenerated pjsip.conf file has no mention of threadpool - which means asterisk is operating on whatever defaults were when asterisk was compiled. So, to get the spamming of the log to stop, I could, presumably, add the threadpool directives and other tuning directives into /etc/asterisk/pjsip_custom.conf

There is also an interesting discussion of this resource issue here:

Taskprocessor Always High Water / Locking Up - General Help - FreePBX Community Forums

Unfortunately, the OP never posted a followup saying whether or not he fixed the problem.

Anyway, since this is a new PBX installation I want to get ahead of any possible potential problems. Defaults are quite often low in UNIX software because most of that software was developed by people who were raised in the “UNIX Way” which dates back oh about 60 years ago where people liked to use single letter variables because it saved a few bytes, and commands were abbreviated from list to ls because it saved 2 bytes.

Today we have modo huge amounts of resources in even basic servers so I am used to the defaults for most programs being too low. For example many programs today that use mariaDB make recommendations on setting my.conf variables to more suit their software, like IBM is doing here:

MariaDB configuration file example - IBM Documentation

I have been so far unable to find much discussion in FreePBX of tuning optimizations for different systems. There is no discussion at all comparable in the FreePBX groups equivalent to the Asterisk tuning discussion I linked to above.

14

That’s assuming this is coming from PJSIP. PJSIP by default has an unbound growable threadpool based on usage. It isn’t limited. It would grow if it needed another thread. Of course, FreePBX could have changed those defaults but I haven’t seen that.

The threadpool is also used by stasis, the internal message bus so if you really wanted to you COULD touch that I guess potentially in the stasis configuration file. The next version of Asterisk, however, will change stasis from using threadpool to a new API called taskpool and the logging will just go away anyway and everyone will get a CPU load decrease without touching configuration.

I have seen very few installations (maybe 1 or 2) where changing the defaults for threadpool have been needed - across small or large installations. What I’ve seen is people thinking it’s their problem and that it’ll solve issues, and then it doesn’t, and in some cases causes more problems because of the overhead of managing so many threads. In these cases their problem was actually elsewhere - specifically the user of the threadpool in some capacity.

15

(The log message is specifically stasis/pool so it is the stasis threadpool)

16

I didn’t read the log carefully, and assumed the more common question about the queues to use the pool threads. However…

That’s not generally true of Unix programs when you enable debug options. They do turn on a lot of noisy output.

The intent of the debug category is to be more noisy than the notice category (and the verbose category)! If the coder thought something was wrong, they would use the error category, and if they though something might be of concern, they would use the warning category.

17

I did not find a solution, I fought forever and tuned everything I could tune, and I just ended up substantially over-sizing the VM and then it STILL persisted, til I just accept it and ignored it.

My assumption was it was coming from our extensive use of complex queues/ringgroups/timegroups, we flattened our queues to the best of our ability, and shrunk them down (against our operational requirements) and it complains much less now, but it’s still not perfectly happy :frowning:

18

The default install of FreepBX 17 puts an /etc/stasis.conf file with all variables commented out. This is identical to:

asterisk/configs/samples/stasis.conf.sample at master · asterisk/asterisk

This file lacks the warning message:

 ;--------------------------------------------------------------------------------;
; Do NOT edit this file as it is auto-generated by FreePBX. All modifications to ;
; this file must be done via the web gui. There are alternative files to make    ;
; custom modifications.                                                          ;
;--------------------------------------------------------------------------------;

It also is not a softlink to

/var/www/html/admin/modules/core/etc/stasis.conf

like the other FreePBX confg files are, therefore, it is available for editing.

Unfortunately, however, there does NOT appear to be any commands that show what the defaults the system used on boot. Since these are all commented out it would have gone to the default settings in the source code. I don’t have the source in front of me to look.

The commented out section says:

[threadpool]
;initial_size = 5          ; Initial size of the threadpool.
;                          ; 0 means the threadpool has no threads initially
;                          ; until a task needs a thread.
;idle_timeout_sec = 20     ; Number of seconds a thread should be idle before
;                          ; dying. 0 means threads never time out.
;max_size = 50             ; Maximum number of threads in the Stasis threadpool.
;                          ; 0 means no limit to the number of threads in the
;

by convention, the example commented out variables would normally be the same as the defaults in the source. But I do not know at this point if source was updated. So I am going to have to test this out on faith despite the warning:

" Don’t. Touch. This."

in this thread:

Task processor queue reached 500 - FreePBX / Integration - FreePBX Community Forums

My default install doing this:

/sbin/asterisk -rvvv
core set verbose 4
core set debug 4

pumps out many of the threadpool notices from time to time even if the system is doing nothing other than sitting there with a bunch of phones registered into it. Possibly those phones are sending garbage to Asterisk that is prodding it to emit these lines

AI seems to claim that commands:

threadpool show
threadpool show pjsip/default
threadpool show stasis-core

exist. However, when attempting to execute these commands I get an error. Possibly they might have existed in some past version of Asterisk or maybe they are a Copilot hallucination.

Issuing the commands

phony*CLI> core show ?
application     applications    calls           channel         channels        channeltype     channeltypes    codec           codecs
config          file            function        functions       hanguphandlers  help            hint            hints           image
license         profile         settings        sound           sounds          switches        sysinfo         taskprocessor   taskprocessors
threads         translation     uptime          version         warranty
phony*CLI> core show taskprocessor
No such command 'core show taskprocessor' (type 'core show help core show taskprocessor' for other possible commands)
phony*CLI>

is also disappointing since one of the commands “taskprocessor” that the help system claims exists - doesn’t exist, either.

Anyway, I took a baseline as best I could:

root@phony:/etc/asterisk# /sbin/asterisk -rx "core show taskprocessors" | grep stasis | wc
    497    2982   62622
root@phony:/etc/asterisk#

And, based on that, based on pure guesstimates, based on recommendations here:

Performance Tuning - Asterisk Documentation

I added:

initial_size = 20
max_size = 150

in stasis.conf and did a

/sbin/service asterisk stop
/sbin/service asterisk start

Now, a

core set verbose 4
core set debug

gives me the nice debugging output I wanted, without the spamming of the increasing threadpool size

Also, taskprocessors seem to have dropped as well.

root@phony:/etc/asterisk# /sbin/asterisk -rx "core show taskprocessors" | grep stasis | wc
    182    1092   22932
root@phony:/etc/asterisk#

I can only conclude the following:

due to code changes between older Asterisk versions, some of the compiled-in defaults are now too small. It also seems that some of the show commands have been possibly accidentally deleted.

I have to wonder if this is a bug?

Hopefully this will help others. Never assume defaults are the best in any software.

19

It exists but you’re using it wrong and because you’re using the command wrong the command you gave was not found. When asterisk suggest you do something like type 'core show help core show taskprocessor' for other possible commands you should do it to make sure you’re using things right. You would have found:

fpbx17-dev*CLI> core show help core show taskprocessor
core show taskprocessor alerted subsystems -- List task processor subsystems in alert
core show taskprocessors [like] -- List instantiated task processors and statistics

threadpool has never existed in Asterisk.

It helps to understand the settings and how the defaults apply to them. Just changing defaults without a real understanding of how the settings and their config options should be used can break things even more.

20

Task processors and their queues dates from after the time when I was deep into the internals of Asterisk, so I only have a hazy understanding of their purpose, but could someone possibly indicate to me the circumstances in which a task processor could legitimately block, other than when waiting for more work, from its input queue?

My assumption was that they were an attempt to avoid the complex locking that was subject to unforeseen deadlocks, and race conditions, in which case I would have expected them not to block on internal conditions, although they may still block on database accesses, or blocking shelled out commands My assumption would be, in the absence of heavy use of database, or shelling to blocking processes, that there would be no advantage in going much beyond the number of processor cores.

If you are doing external accesses that block, you may need to look into those

21

They’re not notices, they’re debug messages. The phones are also not “sending garbage”. Things are going on which is causing messages to be created in the stasis message bus through normal operation. The purpose of the pool is NOT to have a huge number of threads. It’s to have a pool that threads are reused from, and that means some things wait to get a thread - which occurs when that debug message is print. This is normal and expected. It’s not a bad thing. Originally we didn’t have a threadpool in stasis and everything got its own thread. It was a disaster.

Having spent considerable time in threadpool and written a replacement, no. The defaults are NOT too small. Things are working as expected, and the debug message is expected.

The queueing of tasks to a taskprocessor can’t really block. What can block is the callback invoked on tasks, which results in the queue of tasks growing. This can block indefinitely (deadlock generally) or for periods of time, which then result in the queue growing. Problems with taskprocessors are always not with taskprocessors themselves but with the USER of taskprocessors - they are either using it inefficiently, shouldn’t be used it at all, or the task callback has an issue.

You’re pretty much right. Threadpool can benefit from more to a degree due to the management and cost of growing/shrinking if that’s enabled. The new taskpool API doesn’t need anywhere near as many. At 400 calls per second each answered, with a wait for 1 second, and then hung up on my system with taskpool stasis benefitted from 3 total, on an 8 core system. Any more were never touched/used. Taskpool and the move of stasis to it will be in the next releases, there will be a blog post and I’ll be doing a talk at AstriCon (which will be recorded) about performance including this.