[asterisk-bugs] [JIRA] (ASTERISK-28999) Sorcery FRACKs PJSIP on reload of large pjsip.conf configuration

Tue Jul 21 11:06:26 CDT 2020

    [ https://issues.asterisk.org/jira/browse/ASTERISK-28999?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=251482#comment-251482 ] 

Asterisk Team commented on ASTERISK-28999:
------------------------------------------

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. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

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.

> Sorcery FRACKs PJSIP on reload of large pjsip.conf configuration
> ----------------------------------------------------------------
>
>                 Key: ASTERISK-28999
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-28999
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Core/Sorcery
>    Affects Versions: 16.11.1
>         Environment: Ubuntu 18.04.4 LTS, Asterisk 16.11.1
>            Reporter: Gregory Massel
>            Severity: Minor
>
> I have an extremely large pjsip.conf (~24,000 endpoints) all being loaded directly from configuration files (no realtime).
> Every single time I start Astersik up or do a "module reload res_pjsip.so", aside from it being extremely slow (over five minutes) to process, it always results in FRACKs.
> e.g. On startup:
> [Jul 21 03:44:23] ERROR[11916] stasis.c: Excessive refcount 100000 reached on ao2 object 0x563b78882c30
> [Jul 21 03:44:23] ERROR[11916] stasis.c: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x563b78882c30 (0)
> [Jul 21 03:44:23] ERROR[11916] : Got 23 backtrace records
> # 0: [0x563b77a0d1fe] asterisk utils.c:2404 __ast_assert_failed()
> # 1: [0x563b77880221] asterisk astobj2.c:588 __ao2_ref()
> # 2: [0x563b779ceb22] asterisk stasis.c:541 link_topic_proxy()
> # 3: [0x563b779ceffc] asterisk stasis.c:594 stasis_topic_create_with_detail()
> # 4: [0x563b779cf0f7] asterisk stasis.c:614 stasis_topic_create()
> # 5: [0x563b779d1f6c] asterisk stasis.c:1901 stasis_topic_pool_get_topic()
> # 6: [0x563b77953961] asterisk mwi.c:103 ast_mwi_topic()
> # 7: [0x563b77953ea6] asterisk mwi.c:215 ast_publish_mwi_state_full()
> # 8: [0x7fe6f20208cc] app_voicemail.so app_voicemail.c:8219 queue_mwi_event()
> # 9: [0x7fe6f2030173] app_voicemail.so app_voicemail.c:12568 append_mailbox()
> #10: [0x7fe6f2034083] app_voicemail.so app_voicemail.c:13934 load_users()
> #11: [0x7fe6f20377f8] app_voicemail.so app_voicemail.c:14603 actual_load_config()
> #12: [0x7fe6f2033b1d] app_voicemail.so app_voicemail.c:13830 load_config()
> #13: [0x7fe6f2038658] app_voicemail.so app_voicemail.c:15437 load_module()
> #14: [0x563b7793fa92] asterisk loader.c:1711 start_resource()
> #15: [0x563b7794053d] asterisk loader.c:1887 start_resource_attempt()
> #16: [0x563b77940f22] asterisk loader.c:1984 start_resource_list()
> #17: [0x563b77941ccf] asterisk loader.c:2166 load_resource_list()
> #18: [0x563b77942724] asterisk loader.c:2379 load_modules()
> #19: [0x563b7787e711] asterisk asterisk.c:4152 asterisk_daemon()
> #20: [0x563b7787dbda] asterisk asterisk.c:3924 main()
> #21: [0x7fe7545d2b97] libc.so.6 libc-start.c:344 __libc_start_main()
> #22: asterisk <unknown>()
> e.g. On reload:
> [Jul 21 08:33:12] VERBOSE[3902] loader.c: Reloading module 'res_pjsip.so' (Basic SIP resource)
> [..time passes and lots of unrelated logs..]
> [Jul 21 08:35:39] ERROR[5408][C-0000281f] format_cap.c: Excessive refcount 100000 reached on ao2 object 0x563b7888d528
> [Jul 21 08:35:39] ERROR[5408][C-0000281f] format_cap.c: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x563b7888d528 (0)
> [Jul 21 08:35:39] ERROR[872][C-00002262] frame.c: Excessive refcount 100000 reached on ao2 object 0x563b7888d528
> [Jul 21 08:35:39] ERROR[872][C-00002262] frame.c: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x563b7888d528 (0)
> [Jul 21 08:35:39] ERROR[3949][C-0000263d] frame.c: Excessive refcount 100000 reached on ao2 object 0x563b7888d528
> [Jul 21 08:35:39] ERROR[3949][C-0000263d] frame.c: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x563b7888d528 (0)
> [Jul 21 08:35:39] ERROR[22121] : Got 26 backtrace records
> # 0: [0x563b77a0d1fe] asterisk utils.c:2404 __ast_assert_failed()
> # 1: [0x563b77880221] asterisk astobj2.c:588 __ao2_ref()
> # 2: [0x563b7792b5e0] asterisk format_cap.c:211 __ast_format_cap_append()
> # 3: [0x563b7792bed0] asterisk format_cap.c:379 ast_format_cap_update_by_allow_disallow()
> # 4: [0x563b778fad86] asterisk config_options.c:1515 codec_handler_fn()
> # 5: [0x563b778f834d] asterisk config_options.c:797 aco_process_var()
> # 6: [0x563b779ca316] asterisk sorcery.c:1648 ast_sorcery_objectset_apply()
> # 7: [0x7fe6ddcb8b3f] res_sorcery_config.so res_sorcery_config.c:408 sorcery_config_internal_load()
> # 8: [0x7fe6ddcb8e4c] res_sorcery_config.so res_sorcery_config.c:448 sorcery_config_reload()
> # 9: [0x563b779c8528] asterisk sorcery.c:1272 sorcery_wizard_load()
> #10: [0x563b779c8ae4] asterisk sorcery.c:1354 sorcery_object_load()
> #11: [0x563b77882050] asterisk astobj2_container.c:328 internal_ao2_traverse()
> #12: [0x563b77882340] asterisk astobj2_container.c:414 __ao2_callback()
> #13: [0x563b779c9278] asterisk sorcery.c:1415 ast_sorcery_reload()
> #14: [0x7fe6da9de970] res_pjsip.so pjsip_configuration.c:2058 ast_res_pjsip_reload_configuration()
> #15: [0x7fe6da9b6e60] res_pjsip.so res_pjsip.c:5095 reload_configuration_task()
> #16: [0x7fe6da9b5bfb] res_pjsip.so res_pjsip.c:4611 sync_task()
> #17: [0x563b779f6836] asterisk taskprocessor.c:1239 ast_taskprocessor_execute()
> #18: [0x563b77a00b4c] asterisk threadpool.c:1354 execute_tasks()
> #19: [0x563b779f6836] asterisk taskprocessor.c:1239 ast_taskprocessor_execute()
> #20: [0x563b779fe515] asterisk threadpool.c:367 threadpool_execute()
> #21: [0x563b77a00315] asterisk threadpool.c:1137 worker_active()
> #22: [0x563b77a00085] asterisk threadpool.c:1057 worker_start()
> #23: [0x563b77a0a05e] asterisk utils.c:1249 dummy_start()
> #24: [0x7fe7554e16db] libpthread.so.0 pthread_create.c:463 start_thread()
> #25: [0x7fe7546d2a3f] libc.so.6 clone.S:97 clone()
> [Jul 21 08:35:39] ERROR[4141][C-00002698] frame.c: Excessive refcount 100000 reached on ao2 object 0x563b7888d528
> [Jul 21 08:35:39] ERROR[4141][C-00002698] frame.c: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x563b7888d528 (0)
> [..more unrelated logs..]
> [Jul 21 08:35:40] ERROR[872][C-00002262] : Got 14 backtrace records
> # 0: [0x563b77a0d1fe] asterisk utils.c:2404 __ast_assert_failed()
> # 1: [0x563b77880221] asterisk astobj2.c:588 __ao2_ref()
> # 2: [0x563b7792e7ae] asterisk frame.c:349 ast_frdup()
> # 3: [0x563b778ac53a] asterisk bridge_channel.c:1046 ast_bridge_channel_queue_frame()
> # 4: [0x563b778ac8cb] asterisk bridge_channel.c:1104 ast_bridge_queue_everyone_else()
> # 5: [0x7fe6e7ed123d] bridge_simple.so bridge_simple.c:174 simple_bridge_write()
> # 6: [0x563b778ab8ee] asterisk bridge_channel.c:696 bridge_channel_write_frame()
> # 7: [0x563b778b0fdf] asterisk bridge_channel.c:2633 bridge_handle_trip()
> # 8: [0x563b778b141f] asterisk bridge_channel.c:2768 bridge_channel_wait()
> # 9: [0x563b778b1c8b] asterisk bridge_channel.c:2917 bridge_channel_internal_join()
> #10: [0x563b778935cb] asterisk bridge.c:1819 bridge_channel_ind_thread()
> #11: [0x563b77a0a05e] asterisk utils.c:1249 dummy_start()
> #12: [0x7fe7554e16db] libpthread.so.0 pthread_create.c:463 start_thread()
> #13: [0x7fe7546d2a3f] libc.so.6 clone.S:97 clone()
> [Jul 21 08:35:40] VERBOSE[24864] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '196.216.192.8'
> [Jul 21 08:35:40] VERBOSE[4064] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'vpbx0.switchtel.co.za'
> [Jul 21 08:35:40] ERROR[5408][C-0000281f] : Got 20 backtrace records
> # 0: [0x563b77a0d1fe] asterisk utils.c:2404 __ast_assert_failed()
> # 1: [0x563b77880221] asterisk astobj2.c:588 __ao2_ref()
> # 2: [0x563b7792b5e0] asterisk format_cap.c:211 __ast_format_cap_append()
> # 3: [0x563b7792b901] asterisk format_cap.c:279 ast_format_cap_append_from_cap()
> # 4: [0x563b779ee74a] asterisk stream.c:628 ast_format_cap_from_stream_topology()
> # 5: [0x7fe6d525672f] chan_pjsip.so chan_pjsip.c:524 compatible_formats_exist()
> # 6: [0x7fe6d5256ae7] chan_pjsip.so chan_pjsip.c:573 chan_pjsip_new()
> # 7: [0x7fe6d525d4c4] chan_pjsip.so chan_pjsip.c:2712 chan_pjsip_request_with_stream_topology()
> # 8: [0x563b778d1834] asterisk channel.c:6253 request_channel()
> # 9: [0x563b778d1f39] asterisk channel.c:6346 ast_request_with_stream_topology()
> #10: [0x7fe6e0758d81] app_dial.so app_dial.c:2570 dial_exec_full()
> #11: [0x7fe6e075cb41] app_dial.so app_dial.c:3324 dial_exec()
> #12: [0x563b7797811f] asterisk pbx_app.c:492 pbx_exec()
> #13: [0x563b77961a1f] asterisk pbx.c:2947 pbx_extension_helper()
> #14: [0x563b77965eb7] asterisk pbx.c:4197 ast_spawn_extension()
> #15: [0x563b77966c6b] asterisk pbx.c:4371 __ast_pbx_run()
> #16: [0x563b779685e8] asterisk pbx.c:4696 pbx_thread()
> #17: [0x563b77a0a05e] asterisk utils.c:1249 dummy_start()
> #18: [0x7fe7554e16db] libpthread.so.0 pthread_create.c:463 start_thread()
> #19: [0x7fe7546d2a3f] libc.so.6 clone.S:97 clone()
> [Jul 21 08:35:40] ERROR[3949][C-0000263d] : Got 23 backtrace records
> # 0: [0x563b77a0d1fe] asterisk utils.c:2404 __ast_assert_failed()
> # 1: [0x563b77880221] asterisk astobj2.c:588 __ao2_ref()
> # 2: [0x563b7792e7ae] asterisk frame.c:349 ast_frdup()
> # 3: [0x563b778ac53a] asterisk bridge_channel.c:1046 ast_bridge_channel_queue_frame()
> # 4: [0x563b778ac8cb] asterisk bridge_channel.c:1104 ast_bridge_queue_everyone_else()
> # 5: [0x7fe6e7ed123d] bridge_simple.so bridge_simple.c:174 simple_bridge_write()
> # 6: [0x563b778ab8ee] asterisk bridge_channel.c:696 bridge_channel_write_frame()
> # 7: [0x563b778b0fdf] asterisk bridge_channel.c:2633 bridge_handle_trip()
> # 8: [0x563b778b141f] asterisk bridge_channel.c:2768 bridge_channel_wait()
> # 9: [0x563b778b1c8b] asterisk bridge_channel.c:2917 bridge_channel_internal_join()
> #10: [0x563b7789330f] asterisk bridge.c:1749 ast_bridge_join()
> #11: [0x563b77a50313] asterisk features.c:680 ast_bridge_call_with_flags()
> #12: [0x563b77a50403] asterisk features.c:711 ast_bridge_call()
> #13: [0x7fe6e075c726] app_dial.so app_dial.c:3267 dial_exec_full()
> #14: [0x7fe6e075cb41] app_dial.so app_dial.c:3324 dial_exec()
> #15: [0x563b7797811f] asterisk pbx_app.c:492 pbx_exec()
> #16: [0x563b77961a1f] asterisk pbx.c:2947 pbx_extension_helper()
> #17: [0x563b77965eb7] asterisk pbx.c:4197 ast_spawn_extension()
> #18: [0x563b77966c6b] asterisk pbx.c:4371 __ast_pbx_run()
> #19: [0x563b779685e8] asterisk pbx.c:4696 pbx_thread()
> #20: [0x563b77a0a05e] asterisk utils.c:1249 dummy_start()
> #21: [0x7fe7554e16db] libpthread.so.0 pthread_create.c:463 start_thread()
> #22: [0x7fe7546d2a3f] libc.so.6 clone.S:97 clone()
> [..more unrelated logs..]
> [Jul 21 08:35:40] ERROR[4141][C-00002698] : Got 23 backtrace records
> # 0: [0x563b77a0d1fe] asterisk utils.c:2404 __ast_assert_failed()
> # 1: [0x563b77880221] asterisk astobj2.c:588 __ao2_ref()
> # 2: [0x563b7792e7ae] asterisk frame.c:349 ast_frdup()
> # 3: [0x563b778ac53a] asterisk bridge_channel.c:1046 ast_bridge_channel_queue_frame()
> # 4: [0x563b778ac8cb] asterisk bridge_channel.c:1104 ast_bridge_queue_everyone_else()
> # 5: [0x7fe6e7ed123d] bridge_simple.so bridge_simple.c:174 simple_bridge_write()
> # 6: [0x563b778ab8ee] asterisk bridge_channel.c:696 bridge_channel_write_frame()
> # 7: [0x563b778b0fdf] asterisk bridge_channel.c:2633 bridge_handle_trip()
> # 8: [0x563b778b141f] asterisk bridge_channel.c:2768 bridge_channel_wait()
> # 9: [0x563b778b1c8b] asterisk bridge_channel.c:2917 bridge_channel_internal_join()
> #10: [0x563b7789330f] asterisk bridge.c:1749 ast_bridge_join()
> #11: [0x563b77a50313] asterisk features.c:680 ast_bridge_call_with_flags()
> #12: [0x563b77a50403] asterisk features.c:711 ast_bridge_call()
> #13: [0x7fe6e075c726] app_dial.so app_dial.c:3267 dial_exec_full()
> #14: [0x7fe6e075cb41] app_dial.so app_dial.c:3324 dial_exec()
> #15: [0x563b7797811f] asterisk pbx_app.c:492 pbx_exec()
> #16: [0x563b77961a1f] asterisk pbx.c:2947 pbx_extension_helper()
> #17: [0x563b77965eb7] asterisk pbx.c:4197 ast_spawn_extension()
> #18: [0x563b77966c6b] asterisk pbx.c:4371 __ast_pbx_run()
> #19: [0x563b779685e8] asterisk pbx.c:4696 pbx_thread()
> #20: [0x563b77a0a05e] asterisk utils.c:1249 dummy_start()
> #21: [0x7fe7554e16db] libpthread.so.0 pthread_create.c:463 start_thread()
> #22: [0x7fe7546d2a3f] libc.so.6 clone.S:97 clone()
> [..more unrelated logs..]
> [Jul 21 08:38:43] NOTICE[22121] sorcery.c: Type 'system' is not reloadable, maintaining previous values
> These do NOT crash Asterisk, however, if Asterisk is doing a full start-up, it is unresponsive for at least five minutes. During just a pjsip reload, it remains responsive.

--
This message was sent by Atlassian JIRA
(v6.2#6252)