Asterisk crashing when pushing sorcery config via ARI

My otherwise perfectly functioning asterisk instance is bombing out whenever I issue a PUT request to the ARI, to try and create a pjsip endpoint.

A GET request works, so for example, I can issue:

GET http://localhost:8088/ari/asterisk/config/dynamic/res_pjsip/auth/alice

to get back a bunch of configTuples

but when I issue a PUT to the same URI, asterisk consumes the request but then crashes before a response is received (console output):

    localhost*CLI> core set verbose 5
    Console verbose was OFF and is now 5.
    localhost*CLI> core set debug 5
    Core debug is still 5.
    localhost*CLI> ari set debug all on
    Debugging on all applications enabled
    <--- ARI request received from: 127.0.0.1:57214 --->
    Host: 127.0.0.1:8088
    Authorization: Basic dW5pZnk6dW4xZnk=
    traceparent: 00-407e7298e9ac6f4d85fb542ff9931cad-5a5f134d65931442-00
    Content-Type: application/json; charset=utf-8
    Content-Length: 147
    body:
    {"fields":[{"Attribute":"auth_type","Value":"userpass"},{"Attribute":"username","Value":"alice"},{"Attribute":"password","Value":"randompassword"}]}

    localhost*CLI> 
    Disconnected from Asterisk server
    Asterisk cleanly ending (0).
    Executing last minute cleanups

I could really use some help debugging this. If I malform the request body in some way, I get a bad request back as I would expect, so I am pretty sure I am ‘using’ the ARI right. This happens regardless of my configuration in sorcery.conf - if I just leave well alone so that pjsip.conf is used (rather than something writable) I get the same effect, surely it shouldn’t be possible to crash the whole process like this.

If I do amend my sorcery.conf with something like:

[res_pjsip]
auth = memory

On startup I then get

[Apr  7 15:19:53] ERROR[9840]: res_pjsip_config_wizard.c:1080 object_type_loaded_observer: There was no wizard for object type 'auth'

But I still get the crash.

I think I need a core dump but could use a bit of guidance please - am I actually seeing a crash here? Cause it feels like it, but then again the console says “Asterisk cleanly ending (0).” I am surprised I can find no trace anywhere of the failure, in /var/log/asterisk/ or anywhere else besides - I think to get a core dump I am going to have to recompile - have I understood that part of the process right?

Would really appreciate some help, next steps kind of guidance in figuring this out. Thanks y’all.

https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

I think it is the CLI process that is terminating normally. The crashing process ceases to be able to output through it, although it is just possible that there is more in the logs than on the screen.

Thank you for your reply, David - it being the CLI that exits gracefully makes perfect sense.

Okay, I have a core dump (no permissions to upload here) - it doesn’t make a deal of sense to me but I can see that the last thing happening before it died was handling my PUT request.

core-brief.txt: https://pastebin.com/raw/UCqbGT8K
core-full.txt: https://pastebin.com/raw/YLUtqttK

Do you think my problem here is related to the pjsip entry regarding “There was no wizard for object type ‘auth’” I suspect the two are closely linked. As I understand it, setting a sorcery wizard of ‘memory’ should give me the volatile persistence of auth objects I’m looking for, I don’t think I’m trying to do anything particularly esoteric here.

Thank you again!

And because I am only allowed 2 links in a post, here is the rest of the core dump:

core-locks.txt: https://pastebin.com/raw/KnNE22ee
core-thread1.txt: https://pastebin.com/raw/TJZvHmXH

Thread 1 (Thread 0x7f2f5fd11700 (LWP 11298)):
#0  0x00007f2f66c24646 in __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120
#1  0x000055d5b2dc912b in _ast_variable_new (name=0x0, value=value@entry=0x0, filename=filename@entry=0x7f2f1edcce78 "", file=file@entry=0x7f2f1edcce03 "ari/resource_asterisk.c", func=func@entry=0x7f2f1edcd4a0 <__PRETTY_FUNCTION__.16704> "ast_ari_asterisk_update_object", lineno=lineno@entry=200) at config.c:291
        variable = <optimized out>
        name_len = <optimized out>
        val_len = <optimized out>
        fn_len = <optimized out>
#2  0x00007f2f1edcba3d in ast_ari_asterisk_update_object (headers=headers@entry=0x7f2f4800f620, args=args@entry=0x7f2f5fd0eb20, response=0x7f2f5fd0ece0) at ari/resource_asterisk.c:197
        new_var = <optimized out>
        json_value = 0x7f2f4800fc80
        i = 0
        sorcery = 0x55d5b4d4f000
        object_type = 0x55d5b50e5d70
        sorcery_obj = 0x7f2f48010098
        fields = 0x7f2f4800da40
        update_set = 0x0
        created = <optimized out>
        __PRETTY_FUNCTION__ = "ast_ari_asterisk_update_object"
#3  0x00007f2f1edcab27 in ast_ari_asterisk_update_object_cb (ser=<optimized out>, get_params=<optimized out>, path_vars=<optimized out>, headers=0x7f2f4800f620, body=<optimized out>, response=<optimized out>) at res_ari_asterisk.c:157
        args = {config_class = 0x7f2f4800ff4c "res_pjsip", object_type = 0x7f2f4800ffdb "auth", id = 0x7f2f48010063 "alice", fields = 0x7f2f4800fb30}
        i = <optimized out>
#4  0x00007f2f2b735138 in ast_ari_invoke (ser=ser@entry=0x7f2f54003ab0, uri=uri@entry=0x7f2f5fd0ed99 "asterisk/config/dynamic/res_pjsip/auth/alice", method=method@entry=AST_HTTP_PUT, get_params=get_params@entry=0x0, headers=headers@entry=0x7f2f4800f620, body=body@entry=0x7f2f4800fb30, response=0x7f2f5fd0ece0) at res_ari.c:587
        root = <optimized out>
        handler = <optimized out>
        wildcard_handler = 0x0
        path_vars = 0x7f2f4800fff0
        path = 0x0
        path_segment = 0x0
        callback = <optimized out>
        __PRETTY_FUNCTION__ = "ast_ari_invoke"
#5  0x00007f2f2b736772 in ast_ari_callback (ser=<optimized out>, urih=0x7f2f2b93d460 <http_uri>, uri=0x7f2f5fd0ed99 "asterisk/config/dynamic/res_pjsip/auth/alice", method=AST_HTTP_PUT, get_params=0x0, headers=0x7f2f4800f620) at res_ari.c:1058
        conf = 0x55d5b5236608
        response_body = 0x7f2f4800f950
        __PRETTY_FUNCTION__ = "ast_ari_callback"
        user = <optimized out>
        response = {message = 0x0, headers = 0x7f2f4800fa70, response_code = 0, fd = -1, response_text = 0x0, no_response = 0}
        post_vars = 0x0
        var = <optimized out>
        app_name = <optimized out>
        body = 0x7f2f4800fb30
        debug_app = 0
#6  0x000055d5b2de771e in handle_uri (headers=0x7f2f4800f620, method=AST_HTTP_PUT, uri=0x7f2f5fd0ed99 "asterisk/config/dynamic/res_pjsip/auth/alice", ser=0x7f2f54003ab0) at http.c:1487
        res = 0
        params = 0x0
        urih = 0x7f2f2b93d460 <http_uri>
        get_vars = 0x0
        prev = <optimized out>
        redirect = <optimized out>
        c = 0x7f2f5fd0ed99 "asterisk/config/dynamic/res_pjsip/auth/alice"
        l = 3
        v = <optimized out>
        headers = 0x7f2f4800f620
        uri = <optimized out>
        transfer_encoding = <optimized out>
        request = 0x7f2f4800f608
        http_method = AST_HTTP_PUT
        len = <optimized out>
        request_line = "PUT000/ari/asterisk/config/dynamic/res_pjsip/auth/alice000HTTP/1.1rn", '000' <repeats 4031 times>
#7  0x000055d5b2de771e in httpd_process_request (ser=ser@entry=0x7f2f54003ab0) at http.c:1928
        headers = 0x7f2f4800f620
        uri = <optimized out>
        transfer_encoding = <optimized out>
        request = 0x7f2f4800f608
        http_method = AST_HTTP_PUT
        len = <optimized out>
        request_line = "PUT000/ari/asterisk/config/dynamic/res_pjsip/auth/alice000HTTP/1.1rn", '000' <repeats 4031 times>
#8  0x000055d5b2de797b in httpd_helper_thread (data=0x7f2f54003ab0) at http.c:1991
        ser = 0x7f2f54003ab0
        timeout = 15000
        arg = 1
        __PRETTY_FUNCTION__ = "httpd_helper_thread"
#9  0x000055d5b2d9c24f in dummy_start (data=<optimized out>) at utils.c:1249
        __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {139841249494128, 6701288466647955088, 139841447726976, 0, 139841249487168, 139840095276096, -6727957860386785648, -624689827054537072}, __mask_was_saved = 0}}, __pad = {0x7f2f5fd10ed0, 0x0, 0x7f2f66f5a758 <__elf_set___libc_thread_subfreeres_element___rpc_thread_destroy__>, 0x7f2f66f5a760 <_IO_helper_jumps>}}
        __cancel_arg = 0x7f2f5fd11700
        __not_first_call = <optimized out>
        ret = <optimized out>
        a = {start_routine = 0x55d5b2d8d750 <handle_tcptls_connection>, data = 0x7f2f54003ab0, name = <optimized out>}
        __PRETTY_FUNCTION__ = "dummy_start"
#10 0x00007f2f6775b6db in start_thread (arg=0x7f2f5fd11700) at pthread_create.c:463
        pd = 0x7f2f5fd11700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139841447728896, 6701288466647955088, 139841447726976, 0, 139841249487168, 139840095276096, -6727957860409854320, -6728082411504191856}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#11 0x00007f2f66c9488f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Ir has definitely crashed whilst updating the configuration. Unfortunately it wasn’t built with NOOPTIMISE, so a lot of key information is missing.

It’s trying to take the length of a string, but seems to have an invalid pointer.

I don’t know if there is enough information for someone who knows that part of the code to get an idea what is going wrong, or whether you will need to rebuild with optimisation disabled, to get useful output.

The JSON “name” fields are case-sensitive. Trying changing “Attribute” to “attribute” and “Value” to “value” for all instances.

However this should not cause Asterisk to crash. Please file an issue on the issue tracker.

Note - the Asterisk Community Services infrastructure is undergoing a physical move today, so some services like *.asterisk.org will be down for a bit today (April 07, 2021), so might have to create the issue later.

Thanks!

Thats it! Quite reproducibly, capitalise Attribute and Value and get a crash, drop them to lower case and you get expected behaviour! Just reproduced on 17.3.0 and 18.2.0.

I will file an issue on the tracker!

A more general question then - now that I am successfully pushing objects, if you both please. My ideal use case is to push objects from my ARI application which are lost upon asterisk restart. I am getting this behaviour - exactly as wanted, with no entries at all in the stock sorcery.conf file. If I add a [res-pjsip] section to sorcery.conf with auth = memory, all that achieves is a startup error (per the 1st post) of “res_pjsip_config_wizard.c:1080 object_type_loaded_observer: There was no wizard for object type ‘auth’”

First, where have I misunderstood how sorcery is supposed to work? I would not expect to be able to push any kind of config (create/update/delete) without first signalling that intent to sorcery.conf. And second, what on earth does that error mean? (which I can find no reference to from google bar where the source code has been indexed) So by having my sorcery.conf ‘wrong’ I get what I want, and by having it ‘right’ I break that behaviour.

Thank you both so much! I have lost a day to this crash and in the end it was so simple!

I’m not exactly sure what’s going on here, but it appears the pjsip config wizard interface is “listening” for sorcery object changes on particular types like “auth”. It’s trying to find a matching pjsip config wizard for the type, but is unable to. I don’t really have any experience with the config wizard so not sure why it outputs that error. It might be a bug, but for your purposes you might be able to ignore it for now

You are correct. In order to get the pushed configuration to save between restarts you’ll need to configure something in the sorcery.conf file. I take it you’ve seen pushing-pjsip-configuration-with-ari? If not that should walk you through an example of how to save your configuration between restarts using the astdb.