[asterisk-bugs] [JIRA] (ASTERISK-29846) channels: bad ao2 ref causes crash

Fri Jan 28 06:03:07 CST 2022

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

N A commented on ASTERISK-29846:
--------------------------------

All right, some potential more clues in this debug right before the latest crash at 06:36 this morning UTC.

[2022-01-28 06:35:26] DEBUG[5490][C-000001fd] channel.c: Deadlock avoided for write to channel 'Local/0 at radio-feed-00000637;1'
[2022-01-28 06:35:26] VERBOSE[13222] res_pjsip/pjsip_options.c: Contact Modem1/sip:Modem1 at REDACTED:35579;transport=TLS;x-ast-orig-host=192.168.10.101:6062 is$
[2022-01-28 06:35:26] VERBOSE[26746] res_pjsip/pjsip_options.c: Contact voipfone/sip:sip.voipfone.net is now Unreachable.  RTT: 0.000 msec
[2022-01-28 06:35:28] DEBUG[13235] res_pjsip_outbound_registration.c: Received REGISTER response 200(OK)
[2022-01-28 06:35:29] DEBUG[13235] res_pjsip_outbound_registration.c: Processing REGISTER response 200 from server 'sip:sip.voipfone.net' for client 'sip:REDACTED@$
[2022-01-28 06:35:29] DEBUG[5491][C-000001fd] channel.c: Deadlock avoided for write to channel 'Local/0 at radio-feed-00000637;2'
[2022-01-28 06:35:29] DEBUG[13235] res_pjsip_outbound_registration.c: Outbound registration to 'sip:sip.voipfone.net' with client 'sip:REDACTED at sip.voipfone.net' s$
[2022-01-28 06:35:30] DEBUG[13235] res_pjsip_outbound_registration.c: Scheduling outbound registration to server 'sip:sip.voipfone.net' from client 'sip:REDACTED at s$
[2022-01-28 06:35:30] DEBUG[13221] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:35:31] DEBUG[27311] chan_iax2.c: ip callno count decremented to 1 for REDACTED
[2022-01-28 06:35:33] DEBUG[13223] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:35:40] DEBUG[13202] threadpool.c: Worker thread idle timeout reached. Dying.
[2022-01-28 06:35:45] DEBUG[13220] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:35:46] DEBUG[30398] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:35:49] DEBUG[28180] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:36:02] DEBUG[5490][C-000001fd] channel.c: Deadlock avoided for write to channel 'Local/0 at radio-feed-00000637;1'
[2022-01-28 06:36:05] DEBUG[13236] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:36:07] DEBUG[13246] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:36:07] DEBUG[13220] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:36:07] DEBUG[13238] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:36:07] DEBUG[27315] chan_iax2.c: ip callno count incremented to 2 for REDACTED
[2022-01-28 06:36:12] DEBUG[13245] res_pjsip_sips_contact.c: Upgrading contact URI on outgoing SIP request to SIPS due to SIPS Request URI
[2022-01-28 06:36:14] DEBUG[27321] sched.c: Attempted to delete nonexistent schedule entry 57!
[2022-01-28 06:36:15] DEBUG[27311] chan_iax2.c: ip callno count decremented to 1 for REDACTED
[2022-01-28 06:40:02] Asterisk 18.9.0 built by root @ voip on a x86_64 running Linux on 2021-12-27 21:51:01 UTC
[Jan 28 06:40:02] DEBUG[13784] config.c: Parsing /etc/asterisk/logger.conf

The "sched.c: Attempted to delete nonexistent schedule entry 57!" looks mighty suspicious here, especially given that was what happened immediately before the crash. I don't think I've seen that before.

This time, all my fiangling paid off and it DID dump a core, but I was somewhat of an idiot and ran my automated tool, and for some reason the automated POST request failed and then all the files were wiped out afterwards, so I don't have any backtrace to show for this one. I've modified that now to not delete the backtrace files, in case it fails.

When it crashes again in a few days (probably Feb. 1 or 2 by the pattern at this point), I'll be sure to get that backtrace uploaded here.

> channels: bad ao2 ref causes crash
> ----------------------------------
>
>                 Key: ASTERISK-29846
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-29846
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: General
>    Affects Versions: 18.9.0
>         Environment: Debian 10
>            Reporter: N A
>            Assignee: N A
>
> Currently, Asterisk crashes randomly every few days, not seemingly linked to anything going on at the moment. In fact, prior to this crash, the system was completely idle (no calls) for the previous 34 minutes.
> Here is a backtrace from right before the last crash, useful as it has line numbers:
> 01:35:03 ERROR[13076] : Got 10 backtrace records
> # 0: [0x55ca492928cc] asterisk utils.c:2727 __ast_assert_failed()
> # 1: [0x55ca49109db3] asterisk astobj2.c:212 log_bad_ao2()
> # 2: [0x55ca4910a73a] asterisk astobj2.c:501 __ao2_ref()
> # 3: [0x55ca4917269a] asterisk cli.c:1218 handle_chanlist()
> # 4: [0x55ca4917859f] asterisk cli.c:3020 ast_cli_command_full()
> # 5: [0x55ca49178734] asterisk cli.c:3048 ast_cli_command_multiple_full()
> # 6: [0x55ca49101e0c] asterisk asterisk.c:1424 netconsole()
> # 7: [0x55ca4928fb57] asterisk utils.c:1572 dummy_start()
> # 8: [0x7f257c305fa3] libpthread.so.0 pthread_create.c:487 start_thread()
> # 9: [0x7f257bd994cf] libc.so.6 clone.S:97 clone()

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