Overloaded task processors

dovi5988 · March 15, 2024, 1:00pm

My asterisk boxes stopped responding to SIP options from OpenSipS. A core debug shows

[2024-03-15 08:49:42] DEBUG[2080012]: res_pjsip/pjsip_distributor.c:390 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x150a6c0159e8)
[2024-03-15 08:49:42] DEBUG[2080012]: res_pjsip/pjsip_distributor.c:550 distributor: Taskprocessor overload alert: Ignoring 'Request msg OPTIONS/cseq=10 (rdata0x150a6c0159e8)'

The output of core show taskprocessors is

                                     Processed   In Queue  Max Depth  Low water High water
app_voicemail                                                                   0          0          0        450        500
ast_msg_queue                                                                   0          0          0        450        500
CCSS_core                                                                       0          0          0        450        500
dns_system_resolver_tp                                                          0          0          0        450        500
hep_queue_tp                                                                    0          0          0        450        500
pjsip/default-0000000d                                                         38          0          1        450        500
pjsip/default-0000000e                                                          0          0          0        450        500
pjsip/default-0000000f                                                          0          0          0        450        500
pjsip/default-00000010                                                          0          0          0        450        500
pjsip/default-00000011                                                          0          0          0        450        500
pjsip/default-00000012                                                          0          0          0        450        500
pjsip/default-00000013                                                          0          0          0        450        500
pjsip/default-00000014                                                          0          0          0        450        500
pjsip/distributor-00000023                                                  26008          0          2        450        500
pjsip/distributor-00000024                                                  28109          0          2        450        500
pjsip/distributor-00000025                                                  27074          0          3        450        500
pjsip/distributor-00000026                                                  32877          0          2        450        500
pjsip/distributor-00000027                                                  27097          0          3        450        500
pjsip/distributor-00000028                                                  26284          0          2        450        500
pjsip/distributor-00000029                                                  27089          0          3        450        500
pjsip/distributor-0000002a                                                  26781          0          2        450        500
pjsip/distributor-0000002b                                                  28174          0          3        450        500
pjsip/distributor-0000002c                                                  31198          0          2        450        500
pjsip/distributor-0000002d                                                  30019          0          3        450        500
pjsip/distributor-0000002e                                                  28328          0          3        450        500
pjsip/distributor-0000002f                                                  27283          0          3        450        500
pjsip/distributor-00000030                                                  30515          0          3        450        500
pjsip/distributor-00000031                                                  23888          0          2        450        500
pjsip/distributor-00000032                                                  30583          0          2        450        500
pjsip/distributor-00000033                                                  30064          0          2        450        500
pjsip/distributor-00000034                                                  28598          0          3        450        500
pjsip/distributor-00000035                                                  29037          0          3        450        500
pjsip/distributor-00000036                                                  29206          0          3        450        500
pjsip/distributor-00000037                                                  35765          0          2        450        500
pjsip/distributor-00000038                                                  29398          0          2        450        500
pjsip/distributor-00000039                                                  30576          0          2        450        500
pjsip/distributor-0000003a                                                  28335          0          2        450        500
pjsip/distributor-0000003b                                                  28706          0          2        450        500
pjsip/distributor-0000003c                                                  27134          0          3        450        500
pjsip/distributor-0000003d                                                  28719          0          2        450        500
pjsip/distributor-0000003e                                                  26025          0          3        450        500
pjsip/distributor-0000003f                                                  26704          0          2        450        500
pjsip/distributor-00000040                                                  29433          0          2        450        500
pjsip/distributor-00000041                                                  26503          0          3        450        500
pjsip/exten_state                                                               0          0          0        450        500
pjsip/mwi-00000053                                                              1          0          1        450        500
pjsip/mwi-00000054                                                              0          0          0        450        500
pjsip/mwi-00000055                                                              0          0          0        450        500
pjsip/mwi-00000056                                                              0          0          0        450        500
pjsip/mwi-00000057                                                              0          0          0        450        500
pjsip/mwi-00000058                                                              0          0          0        450        500
pjsip/mwi-00000059                                                              0          0          0        450        500
pjsip/mwi-0000005a                                                              0          0          0        450        500
pjsip/options/CharidyOutbound-00000045                                          3          0          1        450        500
pjsip/options/CharityOutbound-00000044                                          3          0          1        450        500
pjsip/options/generic-aor-00000042                                              3          0          1        450        500
pjsip/options/LibraryOutbound-00000046                                          3          0          1        450        500
pjsip/options/manage                                                            2          0          1       4500       5000
pjsip/options/TeleCurve-00000043                                                3          0          1        450        500
pjsip/pool                                                                 858039          0          4        450        500
pjsip/pool-control                                                        1716654          0          5        450        500
pjsip/refer                                                                     0          0          0        450        500
sorcery/acl-0000005c                                                            0          0          0        450        500
sorcery/aor-0000001a                                                            2          0          1        450        500
sorcery/auth-00000015                                                           1          0          1        450        500
sorcery/bucket-00000000                                                         0          0          0        450        500
sorcery/certificate-0000004a                                                    0          0          0        450        500
sorcery/client-00000050                                                         1          0          1        450        500
sorcery/contact-00000019                                                        1          0          1       1350       1500
sorcery/domain_alias-0000001b                                                   0          0          0        450        500
sorcery/endpoint-00000016                                                       2          0          1        450        500
sorcery/file-00000001                                                           0          0          0        450        500
sorcery/general-00000048                                                        0          0          0        450        500
sorcery/global-0000001c                                                         6          0          1        450        500
sorcery/identify-00000047                                                       0          0          0        450        500
sorcery/inbound-publication-0000004e                                            0          0          0        450        500
sorcery/location-00000009                                                       0          0          0        450        500
sorcery/log_mappings-0000000b                                                   0          0          0        450        500
sorcery/nat_hook-00000017                                                       0          0          0        450        500
sorcery/opus-00000008                                                           0          0          0        450        500
sorcery/outbound-publish-00000051                                               0          0          0        450        500
sorcery/pool                                                                   16          0          2        450        500
sorcery/pool-control                                                           36          0          2        450        500
sorcery/profile-0000000a                                                        0          0          0        450        500
sorcery/profile-0000004b                                                        0          0          0        450        500
sorcery/registration-0000005e                                                   3          0          1        450        500
sorcery/resource_list-0000004d                                                  0          0          0        450        500
sorcery/store-00000049                                                          0          0          0        450        500
sorcery/subscription_persistence-0000004c                                       0          0          0        450        500
sorcery/system-0000000c                                                         0          0          0        450        500
sorcery/transport-00000018                                                      0          0          0        450        500
stasis/m:bridge:all-00000061                                                    1          0          1        450        500
stasis/m:cache_pattern:0/endpoint:all-00000007                                 10          0          1        450        500
stasis/m:cdr:aggregator-00000005                                           537139          0         45       4500       5000
stasis/m:channel:all-00000062                                                   1          0          1        450        500
stasis/m:devicestate:all-00000002                                           51713          0          4        450        500
stasis/m:devicestate:all-00000003                                           51713          0          6        450        500
stasis/m:manager:core-00000006                                           20368477          0       3047       2700       3000
stasis/m:mwi:all-00000060                                                      15          0          7        450        500
stasis/m:presence_state:all-00000004                                            1          0          1        450        500
stasis/m:security:all-00000022                                                  1          0          1        450        500
stasis/m:security:all-00000063                                                  1          0          1        450        500
stasis/m:system:all-0000005f                                                    1          0          1        450        500
stasis/p:endpoint:PJSIP/CVBNMZAOutbound-00000020                                1          0          1        450        500
stasis/p:endpoint:PJSIP/ABCDEFGOutbound-0000001f                                1          0          1        450        500
stasis/p:endpoint:PJSIP/endpoint-external-0000001d                         536283        703         20        450        500
stasis/p:endpoint:PJSIP/LibraryOutbound-00000021                               12          0          1        450        500
stasis/p:endpoint:PJSIP/TeleCurve-0000001e                                      1          0          1        450        500
stasis/pool                                                                437225          1          2        450        500
stasis/pool-control                                                        887505          0          4        450        500

110 taskprocessors

If I am reading this right it seems that stasis/p:endpoint:PJSIP/endpoint-external-0000001d has 703 tasks in the queue? Is there any way of seeing what these tasks are? Currently the box has no calls on it and I am trying to figure out what fills up the queue over time to the point of no recover.

jcolp · March 15, 2024, 1:05pm

They are endpoint related messages, beyond that not precisely. Building in dev mode using “–enable-dev-mode” to configure will enable a statistics system for stasis, that can provide insight into things for stasis including what message types are being produced, what subscribers are taking a long time to handle messages, and more. The CLI commands can be tab completed using “stasis statistics” and the useful ones for this would be under “stasis statistics show messages” and “stasis statistics show subscriptions”.

jcolp · March 15, 2024, 1:07pm

There is also a PJSIP configuration option to alter the handling of overloads to scope it to PJSIP only, or disable[1].

[1] asterisk/configs/samples/pjsip.conf.sample at master · asterisk/asterisk · GitHub

dovi5988 · March 15, 2024, 1:12pm

@jcolp TY for the last reply. I am going to start with –enable-dev-mode and see if I find anything useful.

dovi5988 · March 29, 2024, 6:42pm

@jcolp So the system acted up again. I see the same result for core show taskprocessors. In Queue is 0 except for

Processed   In Queue  Max Depth  Low water High water
stasis/p:endpoint:PJSIP/endpoint-external-0000001d                         470902        596         10        450        500

Showing the topic gives me

a15-c3-njr2*CLI> stasis show topic cache:4/endpoint:PJSIP/endpoint-external
Name: cache:4/endpoint:PJSIP/endpoint-external
Detail: 
Subscribers count: 1
Forwarding topic count: 0
Duration time: 341:22:11

Subscribers:
  UniqueID: manager_endpoints.c:cache_pattern:0/endpoint:all-0, Topic: cache_pattern:0/endpoint:all, Detail: 

Forwarded topics:
a15-c3-njr2*CLI>

I don’t see thing of use above. stasis statistics show messages doesn’t seem to say much either

a15-c3-njr2*CLI> stasis statistics show messages 

Message Type                                                      Published     Unused
stasis_cache_clear_type                                                   7          0
stasis_cache_update_type                                              45248      45248
stasis_subscription_change_type                                          31          0
ast_endpoint_snapshot_type                                            45248          0
ast_endpoint_state_type                                                   8          0
ast_endpoint_contact_state_type                                          90          0
ast_rtp_rtcp_sent_type                                              2809178          0
ast_rtp_rtcp_received_type                                          2633691          0
ast_mwi_state_type                                                       14          0
ast_device_state_message_type                                         45416          0
ast_channel_snapshot_type                                            471646          0
ast_channel_dial_type                                                    14          0
ast_channel_varset_type                                             1212308          0
ast_channel_hangup_request_type                                       45258          0
ast_channel_dtmf_begin_type                                           48040          0
ast_channel_dtmf_end_type                                             48044          0
ast_channel_hold_type                                                    46          0
ast_channel_unhold_type                                                  39          0
ast_channel_hangup_handler_type                                       96924          0
ast_channel_moh_start_type                                            23018          0
ast_channel_moh_stop_type                                             23018          0
ast_bridge_snapshot_type                                                 65          0
ast_channel_entered_bridge_type                                          14          0
ast_channel_left_bridge_type                                             14          0
ast_format_register_type                                                 36         36
ast_local_bridge_type                                                     7          0
ast_manager_get_generic_type                                              2          0
agi_exec_start_type                                                 5045574          0
agi_exec_end_type                                                   5045574          0
Total                                                              17638572      45284

29 seen message types

stasis statistics show subscriptions shows


Subscription                                                        Dropped     Passed    Lowest Invoke   Highest Invoke
cdr.c:cdr:aggregator-0                                             11587915     471691                0               25
confbridge/confbridge_manager.c:bridge:all-0                             93          1                0                0
confbridge/confbridge_manager.c:channel:all-0                      12059510          1                0                0
devicestate.c:devicestate:all-1                                           1      45417                0                0
endpoints.c:endpoint:PJSIP/CdOutbound-1                                   4          1                0                0
endpoints.c:endpoint:PJSIP/CtOutbound-1                                   4          1                0                0
endpoints.c:endpoint:PJSIP/LibraryOutbound-1                              4          1                0                0
endpoints.c:endpoint:PJSIP/TeleCurve-1                                   49          1                0                0
endpoints.c:endpoint:PJSIP/endpoint-external-1                     11631692     471498                0               23
manager.c:manager:core-0                                                 43   17547935                0               58
manager_endpoints.c:cache_pattern:0/endpoint:all-0                 12148449         55                0                0
pbx.c:devicestate:all-2                                                   0      45417                0                0
pbx.c:presence_state:all-1                                                0          1                0                0
res_mwi_devstate.c:mwi:all-1                                              7         15                0                0
res_pjsip/pjsip_configuration.c:security:all-0                            2          1                0                0
res_pjsip_acl.c:security:all-1                                            1          1                0                0
res_pjsip_outbound_registration.c:system:all-0                            1          1                0                0
res_security_log.c:security:all-2                                         0          1                0                0
stasis_cache.c:devicestate:all-0                                          0      45419                0                1
stasis_cache.c:endpoint:PJSIP-0                                    12058002      45249                0                0
stasis_cache.c:endpoint:PJSIP/CdOutbound-0                                1          5                0                0
stasis_cache.c:endpoint:PJSIP/CtOutbound-0                           1          5                0                0
stasis_cache.c:endpoint:PJSIP/LibraryOutbound-0                           1          5                0                0
stasis_cache.c:endpoint:PJSIP/TeleCurve-0                                46          5                0                0
stasis_cache.c:endpoint:PJSIP/endpoint-external-0                  12057953      45238                0               22
stasis_cache.c:mwi:all-0                                                  0         23                0                0
stasis_cache.c:presence_state:all-0                                       0          2                0                0
Total                                                              71543779   18717990

27 subscriptions

a15-c3-njr2*CLI>

Here are some other outputs all which don’t seem to say much

a15-c3-njr2*CLI> stasis statistics show subscription endpoints.c:endpoint:PJSIP/endpoint-external-1
Subscription: endpoints.c:endpoint:PJSIP/endpoint-external-1
Pointer Address: 0x55fc58489570
Source filename: endpoints.c
Source line number: 275
Source function: endpoint_internal_create
Number of messages dropped due to filtering: 11631692
Number of messages passed to subscriber callback: 471498
Using mailbox to queue messages: Yes
Using stasis threadpool for handling messages: Yes
Lowest amount of time (in milliseconds) spent invoking message: 0
Highest amount of time (in milliseconds) spent invoking message: 23
Offender message type for highest invoking time: ast_channel_snapshot_type
Number of topics: 1
Subscribed topics:
        endpoint:PJSIP/endpoint-external
a15-c3-njr2*CLI> 

a15-c3-njr2*CLI> stasis statistics show topic endpoint:PJSIP/endpoint-external
Topic: endpoint:PJSIP/endpoint-external
Pointer Address: 0x55fc57bbb280
Number of messages published that went to no subscriber: 0
Number of messages that went to at least one subscriber: 45238
Lowest amount of time (in milliseconds) spent dispatching message: 0
Highest amount of time (in milliseconds) spent dispatching messages: 22
Number of subscribers: 4
Subscribers:
        endpoints.c:endpoint:PJSIP/endpoint-external-1
        manager_endpoints.c:cache_pattern:0/endpoint:all-0
        stasis_cache.c:endpoint:PJSIP-0
        stasis_cache.c:endpoint:PJSIP/endpoint-external-0
a15-c3-njr2*CLI> 
a15-c3-njr2*CLI> 
a15-c3-njr2*CLI> stasis statistics show topic devicestate:all/PJSIP/endpoint-external 
Topic: devicestate:all/PJSIP/endpoint-external
Pointer Address: 0x146524006d10
Number of messages published that went to no subscriber: 0
Number of messages that went to at least one subscriber: 45323
Lowest amount of time (in milliseconds) spent dispatching message: 0
Highest amount of time (in milliseconds) spent dispatching messages: 4
Number of subscribers: 4
Subscribers:
        devicestate.c:devicestate:all-1
        manager.c:manager:core-0
        pbx.c:devicestate:all-2
        stasis_cache.c:devicestate:all-0
a15-c3-njr2*CLI> stasis statistics show topic cache:4/endpoint:PJSIP/endpoint-external
Topic: cache:4/endpoint:PJSIP/endpoint-external
Pointer Address: 0x55fc581d3f80
Number of messages published that went to no subscriber: 45236
Number of messages that went to at least one subscriber: 0
Lowest amount of time (in milliseconds) spent dispatching message: 0
Highest amount of time (in milliseconds) spent dispatching messages: 0
Number of subscribers: 1
Subscribers:
        manager_endpoints.c:cache_pattern:0/endpoint:all-0
a15-c3-njr2*CLI>

Any idea what it may be? The box works for months and then randomly has this issue. It’s almost as if there is some sort of issue were the queue builds up and ends in a “hung” state and can’t recover.

jcolp · March 29, 2024, 7:26pm

Are you actively using manager? A 58ms invoke time for manager sticks out.

dovi5988 · April 11, 2024, 6:26pm

@jcolp ,

I don’t believe I am using the manager at all. I have some scripts that will connect to the asterisk CLI to delete files every so often but those scripts I don’t see here. At this site I have two boxes and they both seem to “die” around the same time leading me to believe it may be some sort of connectivity issue. Since where the Inqueue is going up, is related to PJSIP.

I dumped all of the SIP traffic in hoping I would see something strange for the time the asterisk stopped responding to SIP OPTIONS but I don’t see anything in the logs for that that. Also any calls that were ongoing work OK so I suspect that something “went wonky” earlier that increased that tasks in queue.

What’s also strange is this time the system worked for weeks before this issue happened again. I wrote a bash script to log anytime In queue has a value that is not 0. The next time Asterisk stops responding I will try to see when that number went up and if we see anything in the SIP traffic OR the logs.

jcolp · April 11, 2024, 6:28pm

Is manager enabled in manager.conf?

dovi5988 · April 11, 2024, 6:34pm

@jcolp Yes, my stock config allows connections from the localhost. Doing a dump on the port it was bound to showed no traffic. I have completely disabled it manager.conf and I will take a look at the stats the next time the issue arrises.

dovi5988 · April 11, 2024, 6:42pm

FYI: Manager is completely disabled. The system currently has about 20 calls on hold and is playing a sound file. The task process stasis/m:manager:core-00000006 keeps going at a rate of 10-15 per second.