[Home]

Summary:ASTERISK-28445: res_pjsip_session: ast_json_vpack: Invalid UTF-8 string on hangup when TEST_FRAMEWORK enabled
Reporter:Bernhard Schmidt (bschmidt)Labels:pjsip
Date Opened:2019-06-11 17:20:49Date Closed:2020-08-27 08:16:52
Priority:MinorRegression?
Status:Closed/CompleteComponents:Resources/res_pjsip_session
Versions:16.2.1 Frequency of
Occurrence		Constant
Related
Issues:
is related toASTERISK-29049 Memory Leak caused by fix for ASTERISK-28445
Environment:Debian BusterAttachments:( 0) aor
( 1) endpoint
( 2) endpoints.1000.sql
( 3) endpoints.2000.sql
( 4) invite_recv.xml
( 5) invite.csv
( 6) invite.xml
Description:On every hangup the following error is logged

{code}
[2019-06-12 00:11:07] ERROR[12584]: json.c:607 ast_json_vpack: Error building JSON from '{s: s, s: s, s: s, s: s, s: i, s: s}': Invalid UTF-8 string.
[2019-06-12 00:11:07] ERROR[12584]:   Got 11 backtrace records
# 0: /usr/sbin/asterisk(ast_json_pack+0x99) [0x5557a3eda459]
# 1: /usr/sbin/asterisk(__ast_test_suite_event_notify+0x1be) [0x5557a3f6bbae]
# 2: /usr/sbin/asterisk(__ao2_ref+0xa6) [0x5557a3e503a6]
# 3: /usr/lib/asterisk/modules/res_pjsip_session.so(+0x6564) [0x7f8665c19564]
# 4: /usr/sbin/asterisk(ast_taskprocessor_execute+0xd8) [0x5557a3f62f58]
# 5: /usr/sbin/asterisk(+0x1821c0) [0x5557a3f6d1c0]
# 6: /usr/sbin/asterisk(ast_taskprocessor_execute+0xd8) [0x5557a3f62f58]
# 7: /usr/sbin/asterisk(+0x1819a4) [0x5557a3f6c9a4]
# 8: /usr/sbin/asterisk(+0x18843f) [0x5557a3f7343f]
# 9: /lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3) [0x7f868888efa3]
#10: /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f86885e94cf]
{code}

Other than being a big fat RED ERROR in the console it seems to have no ill consequences.

There is no non-ASCII character in the callerid or in the dialplan

Possibly related judging from the backtrace, the Debian package for Asterisk builds with TEST_FRAMEWORK to run the testsuite in CI tests.
Comments:By: Asterisk Team (asteriskteam) 2019-06-11 17:20:50.251-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].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Joshua C. Colp (jcolp) 2019-06-17 05:04:58.140-0500

I can't reproduce this problem. What is the PJSIP endpoint/AOR/contact involved?
By: Bernhard Schmidt (bschmidt) 2019-06-24 15:53:48.898-0500

You are right, the issue does not happen when I'm calling from a manually configured SIP trunk to a conference room (or echo test), but when my phone is involved I get this error.

Very slightly anonymized AOR/endpoint output attached. The endpoint is coming from realtime ODBC on MariaDB.
By: Bernhard Schmidt (bschmidt) 2019-06-24 16:03:46.691-0500

BTW, the only thing that looks slight out of the ordinary would be

{code}
callerid                           : "Schmidt, Bernhard" <7885>
{code}

but I also tried "<7885>" and "7885", no change.
By: Joshua C. Colp (jcolp) 2019-06-25 05:58:16.565-0500

Hrm, I'm still not able to reproduce the problem. If you place the endpoint and AOR into a .conf file does the problem still occur? I'm wondering if the database is the problem.
By: Petros Moisiadis (Ernest0x) 2019-07-04 10:34:26.112-0500

We can confirm this issue with the asterisk package in Debian Buster. Moving the configuration to a .conf file resolves the issue, so the problem should be related with what __ast_test_suite_event_notify  is doing when realtime is used. However, debug information is not enough to understand exactly what could be wrong. Rebuilding the asterisk package without TEST_FRAMEWORK resolves the issue too.
By: Asterisk Team (asteriskteam) 2019-07-18 12:00:01.611-0500

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Kevin Harwell (kharwell) 2019-09-12 15:51:37.691-0500

I ran into this issue while testing for another one, and can consistently replicate it. Here is what I did:

1. Compiled Asterisk using '--enable-dev-mode' and make sure the TEST_FRAMEWORK flag is enabled.
2. Setup 2000 endpoints with associated auths and aors in realtime using a postgresql database.
3. At 30-50 cps had endpoints 1000-1999 call 2000-2999.
4. After a few seconds (probably less than a minute) observed the following:
{noformat}

[2019-09-12 15:33:39] ERROR[3747]: json.c:607 ast_json_vpack: Error building JSON from '{s: s, s: s, s: s, s: s, s: i, s: s}': Invalid UTF-8 string.
[2019-09-12 15:33:39] ERROR[10357]:   Got 16 backtrace records
# 0: asterisk ast_json_vpack()
# 1: asterisk ast_json_pack()
# 2: asterisk __ast_test_suite_event_notify()
# 3: [0x7f82104eacb5] res_pjsip_session.so res_pjsip_session.c:2201 session_destructor()
# 4: asterisk __ao2_ref()
# 5: asterisk __ao2_cleanup_debug()
# 6: [0x7f82104ef0ab] res_pjsip_session.so res_pjsip_session.c:3520 session_end_completion()
# 7: asterisk ast_taskprocessor_execute()
# 8: asterisk <unknown>()
# 9: asterisk ast_taskprocessor_execute()
#10: asterisk <unknown>()
#11: asterisk <unknown>()
#12: asterisk <unknown>()
#13: asterisk <unknown>()
#14: [0x7f827c8516db] libpthread.so.0 pthread_create.c:463 start_thread()
#15: [0x7f827ba3a88f] libc.so.6 clone.S:97 clone()
{noformat}
I also added some logging and printed out the data just before packing and saw something like the following:
{noformat}
state=SESSION_DESTROYED, appfile=res_pjsip_session.c, func=session_destructor, line=2200, data=Endpoint: ���<�
{noformat}
So maybe something is getting corrupted when setting the variable parameters string:
{noformat}
va_start(ap, fmt);
ast_str_set_va(&buf, 0, fmt, ap);
va_end(ap);
{noformat}
Because logging the data before seemingly looked okay.
By: Kevin Harwell (kharwell) 2019-09-12 16:01:38.591-0500

_pjsip.conf_:
{noformat}
[transport_t](!)
type=transport
bind=0.0.0.0

[transport_udp](transport_t)
protocol=udp
{noformat}
Not sure if it matters, but had caching enabled in _sorcery.conf_ at the time:
{noformat}
[res_pjsip]
endpoint/cache = memory_cache,maximum_objects=2000,expire_on_reload=yes,object_lifetime_maximum=3600,object_lifetime_stale=60
endpoint=config,pjsip.conf,criteria=type=endpoint
endpoint=realtime,ps_endpoints

auth/cache = memory_cache,maximum_objects=2000,expire_on_reload=yes,object_lifetime_maximum=3600,object_lifetime_stale=60
auth=config,pjsip.conf,criteria=type=auth
auth=realtime,ps_auths

aor/cache = memory_cache,maximum_objects=2000,expire_on_reload=yes,object_lifetime_maximum=3600,object_lifetime_stale=60
aor=config,pjsip.conf,criteria=type=aor
aor=realtime,ps_aors
{noformat}
_extensions.conf_:
{noformat}
[globals]
TECH=PJSIP

[default]
exten => _.,hint,${TECH}/{$EXTEN}

exten => _2XXX,1,NoOp()
same => n,Dial(${TECH}/${EXTEN},10)
same => n,Hangup()
{noformat}
_extconfig.conf_:
{noformat}
[settings]
ps_endpoints => odbc,asterisk
ps_auths => odbc,asterisk
ps_aors => odbc,asterisk
{noformat}
And don't forget to configure _res_odbc.conf_:
{noformat}
[asterisk]
enabled => yes
dsn => postgres
username => <your username>
password => <your password>
max_connections => 10
pre-connect => yes
{noformat}
Use alembic to create the tables in the db, insert the records, start Asterisk, then start the receiving SIPp scenario:
{noformat}
sipp 127.0.0.1 -p 5062 -aa -sf invite_recv.xml
{noformat}
Lastly, start the caller scenario:
{noformat}
sipp 127.0.0.1 -p 5061 -sf invite.xml -inf invite.csv -aa -r 50
{noformat}
By: Stefan Schmidt (Netwalker) 2019-12-03 08:31:48.502-0600

I have the exactly the same issue, endpoints configured in Realtime MariaDB throws after Hangup
{noformat}
[Dec  3 14:58:09] ERROR[916]: json.c:607 ast_json_vpack: Error building JSON from '{s: s, s: s, s: s, s: s, s: i, s: s}': Invalid UTF-8 string.
[Dec  3 14:58:09] ERROR[916]:   Got 11 backtrace records
# 0: /usr/sbin/asterisk(ast_json_pack+0x99) [0x55c2ee739449]
# 1: /usr/sbin/asterisk(__ast_test_suite_event_notify+0x1be) [0x55c2ee7cac0e]
# 2: /usr/sbin/asterisk(__ao2_ref+0xa6) [0x55c2ee6af396]
# 3: /usr/lib/asterisk/modules/res_pjsip_session.so(+0x6564) [0x7f493601e564]
# 4: /usr/sbin/asterisk(ast_taskprocessor_execute+0xd8) [0x55c2ee7c1f58]
# 5: /usr/sbin/asterisk(+0x182220) [0x55c2ee7cc220]
# 6: /usr/sbin/asterisk(ast_taskprocessor_execute+0xd8) [0x55c2ee7c1f58]
# 7: /usr/sbin/asterisk(+0x181a04) [0x55c2ee7cba04]
# 8: /usr/sbin/asterisk(+0x18849f) [0x55c2ee7d249f]
# 9: /lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3) [0x7f494aae1fa3]
#10: /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f494a83c4cf]
{noformat}

if the endpoints are configured in pjsip.conf, this errow disapears. Asterisk 16.2.1 Debian Buster pt package.

is there any solution?
Best Regards
Stefan
By: Joshua C. Colp (jcolp) 2019-12-03 08:35:14.191-0600

This issue is open and unresolved, any updates including fixes would be posted here. I wouldn't expect the package to be built with TEST_FRAMEWORK enabled, but we don't manage them.
By: Friendly Automation (friendly-automation) 2019-12-04 17:21:36.303-0600

Change 13344 merged by Friendly Automation:
res_pjsip_session.c: Prevent use-after-free with TEST_FRAMEWORK enabled

[https://gerrit.asterisk.org/c/asterisk/+/13344|https://gerrit.asterisk.org/c/asterisk/+/13344]
By: Friendly Automation (friendly-automation) 2019-12-04 17:48:21.810-0600

Change 13345 merged by Friendly Automation:
res_pjsip_session.c: Prevent use-after-free with TEST_FRAMEWORK enabled

[https://gerrit.asterisk.org/c/asterisk/+/13345|https://gerrit.asterisk.org/c/asterisk/+/13345]
By: Friendly Automation (friendly-automation) 2019-12-04 18:06:06.055-0600

Change 13364 merged by Kevin Harwell:
res_pjsip_session.c: Prevent use-after-free with TEST_FRAMEWORK enabled

[https://gerrit.asterisk.org/c/asterisk/+/13364|https://gerrit.asterisk.org/c/asterisk/+/13364]
By: Friendly Automation (friendly-automation) 2019-12-04 18:06:32.566-0600

Change 13346 merged by Kevin Harwell:
res_pjsip_session.c: Prevent use-after-free with TEST_FRAMEWORK enabled

[https://gerrit.asterisk.org/c/asterisk/+/13346|https://gerrit.asterisk.org/c/asterisk/+/13346]
By: Bernhard Schmidt (bschmidt) 2020-08-27 08:14:26.050-0500

I think this patch is causing a memory leak, see ASTERISK-29049
By: Asterisk Team (asteriskteam) 2020-08-27 08:14:26.437-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Joshua C. Colp (jcolp) 2020-08-27 08:16:53.067-0500

Please see my response on the other issue, and continue discussion there.