Not loading PJSIP modules correctly

Hey!
Sometimes when I start my Asterisk 18 it does not load all PJSIP modules. I do not get any errors but no calls works and it never gets to the “Asterisk is ready” message in the log.

Here is the logs sip logs on when it is NOT loading correctly:

[2024-04-30 12:19:04.672] Asterisk 16.28.0~dfsg-0+deb11u3 built by nobody @ buildd.debian.org on a unknown running Linux on 2023-06-22 12:47:22 UTC
[2024-04-30 12:19:04.673] VERBOSE[13417] message.c: Message handler ‘dialplan’ registered.
[2024-04-30 12:19:04.673] VERBOSE[13417] pbx_functions.c: Registered custom function ‘MESSAGE’
[2024-04-30 12:19:04.674] VERBOSE[13417] pbx_functions.c: Registered custom function ‘MESSAGE_DATA’
[2024-04-30 12:19:04.674] VERBOSE[13417] pbx_app.c: Registered application ‘MessageSend’
[2024-04-30 12:19:04.675] VERBOSE[13417] manager.c: Manager registered action MessageSend
[2024-04-30 12:19:04.675] VERBOSE[13417] channel.c: Registered channel type ‘Surrogate’ (Surrogate channel used to pull channel from an application)
[2024-04-30 12:19:04.676] VERBOSE[13417] manager.c: Manager registered action BridgeTechnologyList
[2024-04-30 12:19:04.676] VERBOSE[13417] manager.c: Manager registered action BridgeTechnologySuspend
[2024-04-30 12:19:04.677] VERBOSE[13417] manager.c: Manager registered action BridgeTechnologyUnsuspend
[2024-04-30 12:19:04.677] VERBOSE[13417] dns_core.c: Registered DNS resolver ‘system’ with priority ‘2147483647’
[2024-04-30 12:19:04.677] VERBOSE[13417] pbx.c: Asterisk PBX Core Initializing
[2024-04-30 12:19:04.677] VERBOSE[13417] pbx.c: Registering builtin functions:
[2024-04-30 12:19:04.677] VERBOSE[13417] pbx_functions.c: Registered custom function ‘EXCEPTION’
[2024-04-30 12:19:04.678] VERBOSE[13417] pbx_functions.c: Registered custom function ‘TESTTIME’
[2024-04-30 12:19:04.678] VERBOSE[13417] manager.c: Manager registered action ShowDialPlan
[2024-04-30 12:19:04.679] VERBOSE[13417] manager.c: Manager registered action ExtensionStateList
[2024-04-30 12:19:04.679] VERBOSE[13417] pbx_app.c: Registered application ‘Answer’
[2024-04-30 12:19:04.679] VERBOSE[13417] pbx_app.c: Registered application ‘BackGround’
[2024-04-30 12:19:04.680] VERBOSE[13417] pbx_app.c: Registered application ‘Busy’
[2024-04-30 12:19:04.680] VERBOSE[13417] pbx_app.c: Registered application ‘Congestion’
[2024-04-30 12:19:04.680] VERBOSE[13417] pbx_app.c: Registered application ‘ExecIfTime’
[2024-04-30 12:19:04.681] VERBOSE[13417] pbx_app.c: Registered application ‘Goto’
[2024-04-30 12:19:04.681] VERBOSE[13417] pbx_app.c: Registered application ‘GotoIf’
[2024-04-30 12:19:04.682] VERBOSE[13417] pbx_app.c: Registered application ‘GotoIfTime’
[2024-04-30 12:19:04.682] VERBOSE[13417] pbx_app.c: Registered application ‘ImportVar’
[2024-04-30 12:19:04.682] VERBOSE[13417] pbx_app.c: Registered application ‘Hangup’
[2024-04-30 12:19:04.683] VERBOSE[13417] pbx_app.c: Registered application ‘Incomplete’
[2024-04-30 12:19:04.683] VERBOSE[13417] pbx_app.c: Registered application ‘NoOp’
[2024-04-30 12:19:04.683] VERBOSE[13417] pbx_app.c: Registered application ‘Proceeding’
[2024-04-30 12:19:04.684] VERBOSE[13417] pbx_app.c: Registered application ‘Progress’
[2024-04-30 12:19:04.684] VERBOSE[13417] pbx_app.c: Registered application ‘RaiseException’
[2024-04-30 12:19:04.684] VERBOSE[13417] pbx_app.c: Registered application ‘Ringing’
[2024-04-30 12:19:04.684] VERBOSE[13417] pbx_app.c: Registered application ‘SayAlpha’
[2024-04-30 12:19:04.685] VERBOSE[13417] pbx_app.c: Registered application ‘SayAlphaCase’
[2024-04-30 12:19:04.685] VERBOSE[13417] pbx_app.c: Registered application ‘SayDigits’
[2024-04-30 12:19:04.686] VERBOSE[13417] pbx_app.c: Registered application ‘SayMoney’
[2024-04-30 12:19:04.686] VERBOSE[13417] pbx_app.c: Registered application ‘SayNumber’
[2024-04-30 12:19:04.686] VERBOSE[13417] pbx_app.c: Registered application ‘SayOrdinal’
[2024-04-30 12:19:04.687] VERBOSE[13417] pbx_app.c: Registered application ‘SayPhonetic’
[2024-04-30 12:19:04.687] VERBOSE[13417] pbx_app.c: Registered application ‘SetAMAFlags’
[2024-04-30 12:19:04.687] VERBOSE[13417] pbx_app.c: Registered application ‘Wait’
[2024-04-30 12:19:04.688] VERBOSE[13417] pbx_app.c: Registered application ‘WaitDigit’
[2024-04-30 12:19:04.688] VERBOSE[13417] pbx_app.c: Registered application ‘WaitExten’
[2024-04-30 12:19:04.689] VERBOSE[13417] pbx_app.c: Registered application ‘Set’
[2024-04-30 12:19:04.689] VERBOSE[13417] pbx_app.c: Registered application ‘MSet’
[2024-04-30 12:19:04.689] VERBOSE[13417] channel.c: Registered channel type ‘Local’ (Local Proxy Channel Driver)
[2024-04-30 12:19:04.690] VERBOSE[13417] manager.c: Manager registered action LocalOptimizeAway
[2024-04-30 12:19:04.690] VERBOSE[13417] loader.c: Asterisk Dynamic Loader Starting:
[2024-04-30 12:19:04.690] NOTICE[13417] loader.c: 87 modules will be loaded.
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading extconfig.
[2024-04-30 12:19:04.711] VERBOSE[13417] config.c: [ Initializing Custom Configuration Options ]
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: extconfig => (Configuration)
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading logger.
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: logger => (Logger)
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading res_sorcery_astdb.so.
[2024-04-30 12:19:04.711] VERBOSE[13417] sorcery.c: Sorcery registered wizard ‘astdb’
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: res_sorcery_astdb.so => (Sorcery Astdb Object Wizard)
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading res_sorcery_config.so.
[2024-04-30 12:19:04.711] VERBOSE[13417] sorcery.c: Sorcery registered wizard ‘config’
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: res_sorcery_config.so => (Sorcery Configuration File Object Wizard)
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading res_sorcery_memory.so.
[2024-04-30 12:19:04.711] VERBOSE[13417] sorcery.c: Sorcery registered wizard ‘memory’
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: res_sorcery_memory.so => (Sorcery In-Memory Object Wizard)
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading res_sorcery_realtime.so.
[2024-04-30 12:19:04.711] VERBOSE[13417] sorcery.c: Sorcery registered wizard ‘realtime’
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: res_sorcery_realtime.so => (Sorcery Realtime Object Wizard)
[2024-04-30 12:19:04.711] VERBOSE[13417] loader.c: Loading ccss.
[2024-04-30 12:19:04.712] VERBOSE[13417] pbx_app.c: Registered application ‘CallCompletionRequest’
[2024-04-30 12:19:04.712] VERBOSE[13417] pbx_app.c: Registered application ‘CallCompletionCancel’
[2024-04-30 12:19:04.712] VERBOSE[13417] loader.c: ccss => (Call Completion Supplementary Services)
[2024-04-30 12:19:04.712] VERBOSE[13417] loader.c: Loading cdr.
[2024-04-30 12:19:04.715] NOTICE[13417] cdr.c: CDR logging disabled.
[2024-04-30 12:19:04.715] VERBOSE[13417] loader.c: cdr => (CDR Engine)
[2024-04-30 12:19:04.715] VERBOSE[13417] loader.c: Loading cel.
[2024-04-30 12:19:04.715] NOTICE[13417] cel.c: Failed to process CEL configuration; using defaults
[2024-04-30 12:19:04.715] VERBOSE[13417] loader.c: cel => (CEL Engine)
[2024-04-30 12:19:04.715] VERBOSE[13417] loader.c: Loading dnsmgr.
[2024-04-30 12:19:04.716] VERBOSE[13417] loader.c: dnsmgr => (DNS Manager)
[2024-04-30 12:19:04.716] VERBOSE[13417] loader.c: Loading dsp.
[2024-04-30 12:19:04.716] VERBOSE[13417] loader.c: dsp => (DSP)
[2024-04-30 12:19:04.716] VERBOSE[13417] loader.c: Loading enum.
[2024-04-30 12:19:04.716] VERBOSE[13417] loader.c: enum => (ENUM Support)
[2024-04-30 12:19:04.716] VERBOSE[13417] loader.c: Loading features.
[2024-04-30 12:19:04.721] NOTICE[13417] features_config.c: Could not load features config; using defaults
[2024-04-30 12:19:04.722] VERBOSE[13417] pbx_functions.c: Registered custom function ‘FEATURE’
[2024-04-30 12:19:04.722] VERBOSE[13417] pbx_functions.c: Registered custom function ‘FEATUREMAP’
[2024-04-30 12:19:04.723] VERBOSE[13417] pbx_app.c: Registered application ‘Bridge’
[2024-04-30 12:19:04.723] VERBOSE[13417] manager.c: Manager registered action Bridge
[2024-04-30 12:19:04.723] VERBOSE[13417] loader.c: features => (Call Features)
[2024-04-30 12:19:04.723] VERBOSE[13417] loader.c: Loading http.
[2024-04-30 12:19:04.723] VERBOSE[13417] http.c: Bound HTTP server ‘http server’ to address 0.0.0.0:45255
[2024-04-30 12:19:04.723] VERBOSE[13417] loader.c: http => (Built-in HTTP Server)
[2024-04-30 12:19:04.723] VERBOSE[13417] loader.c: Loading indications.
[2024-04-30 12:19:04.724] VERBOSE[13417] indications.c: Registered indication country ‘us’
[2024-04-30 12:19:04.724] VERBOSE[13417] indications.c: Setting default indication country to ‘us’
[2024-04-30 12:19:04.724] VERBOSE[13417] loader.c: indications => (Indication Tone Handling)
[2024-04-30 12:19:04.724] VERBOSE[13417] loader.c: Loading acl.
[2024-04-30 12:19:04.724] VERBOSE[13417] loader.c: acl => (Named ACL system)
[2024-04-30 12:19:04.724] VERBOSE[13417] loader.c: Loading manager.
[2024-04-30 12:19:04.724] VERBOSE[13417] manager.c: Manager registered action Ping
[2024-04-30 12:19:04.725] VERBOSE[13417] manager.c: Manager registered action Events
[2024-04-30 12:19:04.725] VERBOSE[13417] manager.c: Manager registered action Logoff
[2024-04-30 12:19:04.725] VERBOSE[13417] manager.c: Manager registered action Login
[2024-04-30 12:19:04.726] VERBOSE[13417] manager.c: Manager registered action Challenge
[2024-04-30 12:19:04.726] VERBOSE[13417] manager.c: Manager registered action Hangup
[2024-04-30 12:19:04.726] VERBOSE[13417] manager.c: Manager registered action Status
[2024-04-30 12:19:04.727] VERBOSE[13417] manager.c: Manager registered action Setvar
[2024-04-30 12:19:04.727] VERBOSE[13417] manager.c: Manager registered action Getvar
[2024-04-30 12:19:04.727] VERBOSE[13417] manager.c: Manager registered action GetConfig
[2024-04-30 12:19:04.728] VERBOSE[13417] manager.c: Manager registered action GetConfigJSON
[2024-04-30 12:19:04.728] VERBOSE[13417] manager.c: Manager registered action UpdateConfig
[2024-04-30 12:19:04.729] VERBOSE[13417] manager.c: Manager registered action CreateConfig
[2024-04-30 12:19:04.729] VERBOSE[13417] manager.c: Manager registered action ListCategories
[2024-04-30 12:19:04.729] VERBOSE[13417] manager.c: Manager registered action Redirect
[2024-04-30 12:19:04.729] VERBOSE[13417] manager.c: Manager registered action Atxfer
[2024-04-30 12:19:04.730] VERBOSE[13417] manager.c: Manager registered action CancelAtxfer
[2024-04-30 12:19:04.730] VERBOSE[13417] manager.c: Manager registered action Originate
[2024-04-30 12:19:04.730] VERBOSE[13417] manager.c: Manager registered action Command
[2024-04-30 12:19:04.731] VERBOSE[13417] manager.c: Manager registered action ExtensionState
[2024-04-30 12:19:04.731] VERBOSE[13417] manager.c: Manager registered action PresenceState
[2024-04-30 12:19:04.731] VERBOSE[13417] manager.c: Manager registered action AbsoluteTimeout
[2024-04-30 12:19:04.732] VERBOSE[13417] manager.c: Manager registered action MailboxStatus
[2024-04-30 12:19:04.732] VERBOSE[13417] manager.c: Manager registered action MailboxCount
[2024-04-30 12:19:04.732] VERBOSE[13417] manager.c: Manager registered action ListCommands
[2024-04-30 12:19:04.733] VERBOSE[13417] manager.c: Manager registered action SendText
[2024-04-30 12:19:04.733] VERBOSE[13417] manager.c: Manager registered action UserEvent
[2024-04-30 12:19:04.733] VERBOSE[13417] manager.c: Manager registered action WaitEvent
[2024-04-30 12:19:04.734] VERBOSE[13417] manager.c: Manager registered action CoreSettings
[2024-04-30 12:19:04.734] VERBOSE[13417] manager.c: Manager registered action CoreStatus
[2024-04-30 12:19:04.734] VERBOSE[13417] manager.c: Manager registered action Reload
[2024-04-30 12:19:04.734] VERBOSE[13417] manager.c: Manager registered action LoggerRotate
[2024-04-30 12:19:04.735] VERBOSE[13417] manager.c: Manager registered action CoreShowChannels
[2024-04-30 12:19:04.735] VERBOSE[13417] manager.c: Manager registered action ModuleLoad
[2024-04-30 12:19:04.735] VERBOSE[13417] manager.c: Manager registered action ModuleCheck
[2024-04-30 12:19:04.736] VERBOSE[13417] manager.c: Manager registered action AOCMessage
[2024-04-30 12:19:04.736] VERBOSE[13417] manager.c: Manager registered action Filter
[2024-04-30 12:19:04.737] VERBOSE[13417] manager.c: Manager registered action BlindTransfer
[2024-04-30 12:19:04.737] VERBOSE[13417] pbx_functions.c: Registered custom function ‘AMI_CLIENT’
[2024-04-30 12:19:04.752] VERBOSE[13417] manager.c: Manager registered action BridgeList
[2024-04-30 12:19:04.752] VERBOSE[13417] manager.c: Manager registered action BridgeInfo
[2024-04-30 12:19:04.753] VERBOSE[13417] manager.c: Manager registered action BridgeDestroy
[2024-04-30 12:19:04.753] VERBOSE[13417] manager.c: Manager registered action BridgeKick
[2024-04-30 12:19:04.754] VERBOSE[13417] loader.c: manager => (Asterisk Manager Interface)
[2024-04-30 12:19:04.754] VERBOSE[13417] loader.c: Loading plc.
[2024-04-30 12:19:04.754] VERBOSE[13417] loader.c: plc => (PLC)
[2024-04-30 12:19:04.754] VERBOSE[13417] loader.c: Loading udptl.
[2024-04-30 12:19:04.755] NOTICE[13417] udptl.c: Could not load udptl config; using defaults
[2024-04-30 12:19:04.755] VERBOSE[13417] loader.c: udptl => (UDPTL)
[2024-04-30 12:19:04.755] VERBOSE[13417] loader.c: Loading res_timing_timerfd.so.
[2024-04-30 12:19:04.755] VERBOSE[13417] loader.c: res_timing_timerfd.so => (Timerfd Timing Interface)
[2024-04-30 12:19:04.755] VERBOSE[13417] loader.c: Loading res_pjproject.so.
[2024-04-30 12:19:04.757] VERBOSE[13417] loader.c: res_pjproject.so => (PJPROJECT Log and Utility Support)
[2024-04-30 12:19:04.757] VERBOSE[13417] loader.c: Loading res_pjsip.so.
[2024-04-30 12:19:04.765] VERBOSE[13417] res_pjsip.c: Local IPv4 address determined to be: XXX.XXX.XXX.XXX
[2024-04-30 12:19:04.768] VERBOSE[13417] res_pjsip.c: Local IPv6 address determined to be: XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXX
[2024-04-30 12:19:04.770] VERBOSE[13417] manager.c: Manager registered action PJSIPShowEndpoints
[2024-04-30 12:19:04.772] VERBOSE[13417] manager.c: Manager registered action PJSIPShowEndpoint
[2024-04-30 12:19:04.774] VERBOSE[13417] manager.c: Manager registered action PJSIPShowAuths
[2024-04-30 12:19:04.811] VERBOSE[13417] manager.c: Manager registered action PJSIPShowAors
[2024-04-30 12:19:04.820] VERBOSE[13443] res_pjsip/pjsip_resolver.c: ‘UDP+IPv4’ is an available SIP transport
[2024-04-30 12:19:04.820] VERBOSE[13443] res_pjsip/pjsip_resolver.c: ‘TCP+IPv4’ is an available SIP transport
[2024-04-30 12:19:04.820] VERBOSE[13443] res_pjsip/pjsip_resolver.c: ‘TLS+IPv4’ is an available SIP transport
[2024-04-30 12:19:04.820] VERBOSE[13443] res_pjsip/pjsip_resolver.c: ‘UDP+IPv6’ is not an available SIP transport, disabling resolver support for it
[2024-04-30 12:19:04.820] VERBOSE[13443] res_pjsip/pjsip_resolver.c: ‘TCP+IPv6’ is not an available SIP transport, disabling resolver support for it
[2024-04-30 12:19:04.820] VERBOSE[13443] res_pjsip/pjsip_resolver.c: ‘TLS+IPv6’ is not an available SIP transport, disabling resolver support for it
[2024-04-30 12:19:05.314] VERBOSE[13453] manager.c: HTTP Manager ‘hello’ logged on from 127.0.0.1
[2024-04-30 12:20:09.805] VERBOSE[13440] manager.c: HTTP Manager ‘hello’ timed out from 127.0.0.1

That’s Asterisk 16, not Asterisk 18, which no longer receives changes or fixes. Common reasons for such a thing at startup is DNS blocking.

Ah pardon me and nice catch! I will try and update to the latest version and hope that it solves the issue.

sip-logs.txt (256.9 KB)

I have now updated to Asterisk 20 and the issue seems to still persist. The logs are from the latest hang where around 30 registration events and calls were tried but no communication came back from the server. Any clue on what could be wrong? It works again after a restart but around every 8th-10th restart this happens and I cannot figure out why.

You would need to do further troubleshooting and confirm assumptions. Do a packet capture and ensure traffic is being received, see if it shows up in “pjsip set logger on”, get a backtrace to see if Asterisk itself is hung.

I have done some further troubleshooting and now the modules are loading but a new issue has occurred. When I make a call the callee never receives the INVITE message. With wireshark I can see that the caller INVITE is being authorized but after that nothing happens and the caller receives a 503 error message from the asterisk. Do you have any knowledge in this? I have attached different types of logs.

Wireshark:
sip-error

Asterisk logs:
New Text Document.txt (16.4 KB)

PJSIP settings:

[transport-udp-ipv4]
type = transport
protocol = udp
bind = {udp_address}

basic_settings_endpoint ; A template used for endpoints
type = endpoint
context = Internal-Main
disallow = all
allow = ulaw,alaw,speex
direct_media = no
dtmf_mode = auto_info
media_encryption = sdes
media_encryption_optimistic = yes
identify_by = username
trust_id_outbound = yes

basic_settings_auth ; A template used for auth
type = auth
auth_type = userpass

basic_settings_aor ; A template used for aor
type = aor
max_contacts = 1
remove_existing = yes
minimum_expiration = 1 ; Minimum keep alive time for an AoR (default: “60”)

1000
auth = 1000
aors = 1000
callerid = Lindsey Freddie <1000>

1000
password = 1000
username = 1000

1000
mailboxes = 1000@example

1001
auth = 1001
aors = 1001
callerid = Temple Morgan <1001>

1001
password = 1001
username = 1001

1001
mailboxes = 1001@example

Error message on the caller:
10:34:41.905 Call ID: 0, Current state: Calling Reason Initiated New state: DISCONNECTED, PJSUA code: 503, PJSUA reason End of file (PJ_EEOF)
10:34:41.943 SIP session disconnected (calling), last status code: 503

Is chan_pjsip loaded?

Yes, it is being loaded correctly

from logs - “loader.c: START: chan_pjsip.so”

What is the complete output of “module show like pjsip”? What is the actual SIP traffic from “pjsip set logger on”? How was Asterisk built?

What is the complete console log at startup?

The Asterisk is built within a docker container that is then started and stopped with a python program. Therefore I am not sure on how the get the logs required as I do not have access to the asterisk CLI. Do you know if there is away to activate pjsip set logger on in any other way?

You can configure it to be enabled by default in pjsip.conf

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.