ASTERISK-26186: res_pjsip_multihomed: Deadlock when finding message header

[Home]

Summary: ASTERISK-26186: res_pjsip_multihomed: Deadlock when finding message header

Reporter: Mateusz Kowalski (mkowalski) Labels:

Date Opened: 2016-07-11 07:59:15 Date Closed:

Priority: Major Regression?

Status: Open/New Components: Resources/res_pjsip_multihomed

Versions: 13.9.1 Frequency of
Occurrence One Time

Related
Issues:

Environment: CentOS 7.2 (3.10.0-327.22.2.el7.x86_64) Asterisk 13.9.1 PJSIP 2.5.1 MariaDB-server 10.1.14 mysql-connector-odbc 5.3.6 Attachments: ( 0) trace1.txt
( 1) trace2.txt

Description: Hello,

I encountered a deadlock in PJSIP module. Two backtraces available as
* http://pastebin.com/raw/kZtc5df3 (Thread 43)
* http://pastebin.com/raw/93H9qe4x (Thread 42)

Output from {{core show locks}} is empty:
{code}
tone-0058-re-1*CLI> core show locks

=======================================================================
=== 13.9.1
=== Currently Held Locks
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=======================================================================
{code}

Any packets arriving to the machine on port 5060 are left without any response. They are not visible in Asterisk console even with {{pjsip set logger on}}

Output from {{netstat}} shows big RX queue for the process:
{code}
udp 214912 0 0.0.0.0:5060 0.0.0.0:* 46787/asterisk
{code}

If you check {{netstat}} per port, it happens also on RTP port (I'm using 10000-20000):
{code}
udp 0 0 0.0.0.0:2727 0.0.0.0:* 46787/asterisk
udp 896 0 0.0.0.0:35859 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:37171 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:4520 0.0.0.0:* 46787/asterisk
udp 214912 0 0.0.0.0:5060 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:10520 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:10521 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:11356 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:11357 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:12048 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:12049 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:12062 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:12063 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:13890 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:13891 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:14608 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:14609 0.0.0.0:* 46787/asterisk
udp 213248 0 0.0.0.0:14678 0.0.0.0:* 46787/asterisk
udp 34048 0 0.0.0.0:14679 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:14752 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:14753 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:15106 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:15107 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:18100 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:18101 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:18392 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:18393 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:18918 0.0.0.0:* 46787/asterisk
udp 0 0 0.0.0.0:18919 0.0.0.0:* 46787/asterisk
{code}

Initially I reported issue on #asterisk but later on got redirected to open a ticket in here.

Snaps of my configuration in here:

{{asterisk.conf}}
{code}
[directories](!)
astetcdir => /etc/asterisk
astmoddir => /usr/lib/asterisk/modules
astvarlibdir => /var/lib/asterisk
astdbdir => /var/lib/asterisk
astkeydir => /var/lib/asterisk
astdatadir => /var/lib/asterisk
astagidir => /var/lib/asterisk/agi-bin
astspooldir => /var/spool/asterisk
astrundir => /var/run/asterisk
astlogdir => /var/log/asterisk
astsbindir => /usr/sbin

[options]
;verbose = 5
;debug = 5
;alwaysfork = yes ; Same as -F at startup.
;nofork = yes ; Same as -f at startup.
;quiet = yes ; Same as -q at startup.
;timestamp = yes ; Same as -T at startup.
;execincludes = yes ; Support #exec in config files.
;console = yes ; Run as console (same as -c at startup).
;highpriority = yes ; Run realtime priority (same as -p at
; startup).
;initcrypto = yes ; Initialize crypto keys (same as -i at
; startup).
;nocolor = yes ; Disable console colors.
;dontwarn = yes ; Disable some warnings.
;dumpcore = yes ; Dump core on crash (same as -g at startup).
;languageprefix = yes ; Use the new sound prefix path syntax.
;systemname = my_system_name ; Prefix uniqueid with a system name for
; Global uniqueness issues.
;autosystemname = yes ; Automatically set systemname to hostname,
; uses 'localhost' on failure, or systemname if
; set.
;mindtmfduration = 80 ; Set minimum DTMF duration in ms (default 80 ms)
; If we get shorter DTMF messages, these will be
; changed to the minimum duration
;maxcalls = 10 ; Maximum amount of calls allowed.
;maxload = 0.9 ; Asterisk stops accepting new calls if the
; load average exceed this limit.
;maxfiles = 1000 ; Maximum amount of openfiles.
;minmemfree = 1 ; In MBs, Asterisk stops accepting new calls if
; the amount of free memory falls below this
; watermark.
;cache_record_files = yes ; Cache recorded sound files to another
; directory during recording.
;record_cache_dir = /tmp ; Specify cache directory (used in conjunction
; with cache_record_files).
;transmit_silence = yes ; Transmit silence while a channel is in a
; waiting state, a recording only state, or
; when DTMF is being generated. Note that the
; silence internally is generated in raw signed
; linear format. This means that it must be
; transcoded into the native format of the
; channel before it can be sent to the device.
; It is for this reason that this is optional,
; as it may result in requiring a temporary
; codec translation path for a channel that may
; not otherwise require one.
;transcode_via_sln = yes ; Build transcode paths via SLINEAR, instead of
; directly.
;runuser = asterisk ; The user to run as.
;rungroup = asterisk ; The group to run as.
;lightbackground = yes ; If your terminal is set for a light-colored
; background.
;forceblackbackground = yes ; Force the background of the terminal to be
; black, in order for terminal colors to show
; up properly.
;defaultlanguage = en ; Default language
documentation_language = en_US ; Set the language you want documentation
; displayed in. Value is in the same format as
; locale names.
;hideconnect = yes ; Hide messages displayed when a remote console
; connects and disconnects.
;lockconfdir = no ; Protect the directory containing the
; configuration files (/etc/asterisk) with a
; lock.
;stdexten = gosub ; How to invoke the extensions.conf stdexten.
; macro - Invoke the stdexten using a macro as
; done by legacy Asterisk versions.
; gosub - Invoke the stdexten using a gosub as
; documented in extensions.conf.sample.
; Default gosub.
;live_dangerously = no ; Enable the execution of 'dangerous' dialplan
; functions from external sources (AMI,
; etc.) These functions (such as SHELL) are
; considered dangerous because they can allow
; privilege escalation.
; Default no

; Changing the following lines may compromise your security.
;[files]
;astctlpermissions = 0660
;astctlowner = root
;astctlgroup = apache
;astctl = asterisk.ctl
{code}

{{extensions.conf}}
{code}
[professional]
switch => Realtime/professional@extensions

[private]
switch => Realtime/private@extensions

[sigos]
switch => Realtime/sigos@extensions
{code}

{{hep.conf}}
{code}
[general]
enabled = yes
capture_address = XXX:9060
;capture_password = foo
capture_id = 1234
{code}

{{modules.conf}}
{code}
[modules]
autoload=yes

preload => res_odbc.so
preload => res_config_odbc.so
{code}

{{pjsip.conf}}
{code}
[transport-udp]
type=transport
protocol=udp
bind=0.0.0.0
{code}

{{sorcery.conf}}
{code}
[res_pjsip]
endpoint=realtime,ps_endpoints
;endpoint=config,pjsip.conf,criteria=type=endpoint
;auth=realtime,ps_auths
aor=realtime,ps_aors
;aor=config,pjsip.conf,criteria=type=aor
;domain_alias=realtime,ps_domain_aliases
;contact=realtime,ps_contacts

[res_pjsip_endpoint_identifier_ip]
identify=realtime,ps_endpoint_id_ips
;identify=config,pjsip.conf,criteria=type=identify
{code}

{{/etc/odbc.ini}}
{code}
[asterisk]
Driver = MySQL ODBC 5.3 Unicode Driver
Description = MySQL connection to ‘asterisk’ database
Server = localhost
Port = 3306
Database = XXX
UserName = XXX
Password = XXX
Socket = /mnt/mysqld/mysql.sock
{code}

{{/etc/odbcinst.ini}}
{code}
[MySQL ODBC 5.3 Unicode Driver]
Driver=/usr/lib64/libmyodbc5w.so
FileUsage = 1
Pooling = Yes
CPTimeout = 120
{code}

Thanks for any help,
Mateusz

Comments: By: Asterisk Team (asteriskteam) 2016-07-11 07:59:15.692-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Joshua C. Colp (jcolp) 2016-07-11 08:49:06.642-0500

Please attach backtraces as attachments so they are not lost. As well please provide the console output and configuration.
By: Mateusz Kowalski (mkowalski) 2016-07-11 09:44:36.219-0500

Updated with config files and uploaded backtraces. I'm not attaching console output as during deadlock there is nothing in the output.
By: Joshua C. Colp (jcolp) 2016-07-11 09:56:59.205-0500

While there's nothing going on when it deadlocks there is logging before it occurs, which may provide further insight into how it got there. It's best to give all the information you can when filing an issue so that the person who works on it does not have to ask for more if they need it, and it also makes it easier to find things.
By: Mateusz Kowalski (mkowalski) 2016-07-11 10:02:45.347-0500

Asterisk logfile around the moment deadlock occured
{code}
[Jul 8 14:54:34] WARNING[95561][C-0000117a] res_rtp_asterisk.c: RTP Transmission error of packet to 137.138.34.223:32228: Operation not permitted
[Jul 11 12:03:00] NOTICE[85699] sorcery.c: Type 'system' is not reloadable, maintaining previous values
[Jul 11 12:06:09] Asterisk 13.9.1 built by root @ tone-0058-re-1.cern.ch on a x86_64 running Linux on 2016-07-01 13:00:59 UTC
[Jul 11 12:06:09] NOTICE[147869] res_odbc.c: Registered ODBC class 'asterisk' dsn->[asterisk]
[Jul 11 12:06:09] NOTICE[26978] sorcery.c: Type 'system' is not reloadable, maintaining previous values
[Jul 11 12:06:09] ERROR[147869] ari/config.c: No configured users for ARI
[Jul 11 12:06:09] NOTICE[147869] cel_custom.c: No mappings found in cel_custom.conf. Not logging CEL to custom CSVs.
[Jul 11 12:06:09] NOTICE[147869] app_queue.c: queuerules.conf has not changed since it was last loaded. Not taking any action.
{code}