Hello there,
We have multiple servers running asterisk 16.10.0 without any major issues, but this morning two servers experienced issues, those are servers for different customers on different instances, and issues started within a 30 minute timeframe.
I reviewed the logs and here is what I found:
First, we got multiple errors like this:
[Jan 25 08:45:22] ERROR[30233] pjproject: icess0x7f4e85605fc8 ......Error sending STUN request: Invalid argument
[Jan 25 08:46:15] ERROR[360] pjproject: icess0x7f4e7c03eaa8 ......Error sending STUN request: Invalid argument
[Jan 25 08:49:07] ERROR[360] pjproject: icess0x7f4e78d61cb8 ......Error sending STUN request: Invalid argument
Then the FRACK:
[Jan 25 09:01:51] ERROR[8601] res_pjsip_session.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x7f4e9f11c440 (0)
[Jan 25 09:01:51] ERROR[8601] : Got 13 backtrace records
# 0: /usr/sbin/asterisk() [0x45c977]
# 1: /usr/sbin/asterisk() [0x45ff1b]
# 2: /usr/sbin/asterisk(__ao2_find+0x28) [0x460108]
# 3: /usr/lib/asterisk/modules/res_pjsip_session.so(ast_sip_session_get_datastore+0x31) [0x7f50accaf491]
# 4: /usr/lib/asterisk/modules/res_pjsip_header_funcs.so(+0x1f56) [0x7f50ab65ff56]
# 5: /usr/lib/asterisk/modules/res_pjsip.so(+0x11730) [0x7f50af12c730]
# 6: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 7: /usr/sbin/asterisk() [0x5a2d10]
# 8: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 9: /usr/sbin/asterisk() [0x5a34b0]
#10: /usr/sbin/asterisk() [0x5ab34c]
#11: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f512530c6ba]
#12: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f51248e641d]
Then Asterisk became slow to respond, and any webRTC connection was failing.
We didn’t see any CPU or RAM spikes, so our monitoring tools were pretty useless, that was just asterisk failing silently.
[Jan 25 09:02:01] WARNING[31257][C-0002f838] taskprocessor.c: The 'stasis/m:rtp:all-000004be' task processor queue reached 500 scheduled tasks again.
[Jan 25 09:02:11] NOTICE[2192] res_pjsip/pjsip_transport_management.c: Shutting down transport 'WS to redacted' since no request was received in 32 seconds
[Jan 25 09:02:12] NOTICE[2202] res_pjsip_sdp_rtp.c: Disconnecting channel 'PJSIP/redacted' for lack of audio RTP activity in 69 seconds
[Jan 25 09:02:35] WARNING[30615][C-0002f804] taskprocessor.c: The 'stasis/m:rtp:all-000004be' task processor queue reached 500 scheduled tasks again.
[...]
On our other impacted server, the FRACK errors were showing at regular intervals, here is what happened:
[Jan 25 07:30:54] WARNING[5807] pjproject: tsx0x7f6588a25e48 ..Error sending Response msg 200/REGISTER/cseq=6 (tdta0x7f6588e67f98): Unknown Error (PJ_EUNKNOWN)
[Jan 25 08:09:37] ERROR[8776] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[Jan 25 08:18:38] ERROR[10721] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[Jan 25 08:26:57] ERROR[29558] res_pjsip_session.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x7f658bd72540 (0)
[Jan 25 08:26:57] ERROR[29558] : Got 13 backtrace records
# 0: /usr/sbin/asterisk() [0x45c977]
# 1: /usr/sbin/asterisk() [0x45ff1b]
# 2: /usr/sbin/asterisk(__ao2_find+0x28) [0x460108]
# 3: /usr/lib/asterisk/modules/res_pjsip_session.so(ast_sip_session_get_datastore+0x31) [0x7f655b260491]
# 4: /usr/lib/asterisk/modules/res_pjsip_header_funcs.so(+0x1f56) [0x7f6559c10f56]
# 5: /usr/lib/asterisk/modules/res_pjsip.so(+0x11730) [0x7f655d6dd730]
# 6: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 7: /usr/sbin/asterisk() [0x5a2d10]
# 8: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 9: /usr/sbin/asterisk() [0x5a34b0]
#10: /usr/sbin/asterisk() [0x5ab34c]
#11: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f65c7a216ba]
#12: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f65c6ffb41d]
[Jan 25 08:27:26] WARNING[12749][C-0000d6ed] res_stasis_playback.c: 9b3f5cc550ee0b3020d2-1611559637.228703: Playback failed for tone:ring
[Jan 25 08:29:38] WARNING[13179][C-0000d6f8] res_stasis_playback.c: 9b3f5cc550ee0b3020d2-1611559771.228726: Playback failed for tone:ring
[Jan 25 08:31:25] ERROR[14845] res_pjsip_session.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x7f658c31af70 (0)
[Jan 25 08:31:25] ERROR[14845] : Got 13 backtrace records
# 0: /usr/sbin/asterisk() [0x45c977]
# 1: /usr/sbin/asterisk() [0x45ff1b]
# 2: /usr/sbin/asterisk(__ao2_find+0x28) [0x460108]
# 3: /usr/lib/asterisk/modules/res_pjsip_session.so(ast_sip_session_get_datastore+0x31) [0x7f655b260491]
# 4: /usr/lib/asterisk/modules/res_pjsip_header_funcs.so(+0x1f56) [0x7f6559c10f56]
# 5: /usr/lib/asterisk/modules/res_pjsip.so(+0x11730) [0x7f655d6dd730]
# 6: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 7: /usr/sbin/asterisk() [0x5a2d10]
# 8: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 9: /usr/sbin/asterisk() [0x5a34b0]
#10: /usr/sbin/asterisk() [0x5ab34c]
#11: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f65c7a216ba]
#12: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f65c6ffb41d]
[Jan 25 08:35:24] ERROR[14671] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[Jan 25 08:35:33] ERROR[14713] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[Jan 25 08:35:55] WARNING[4218] res_http_websocket.c: Web socket closed abruptly
[Jan 25 08:36:15] WARNING[15292] res_pjsip_registrar.c: Registration attempt from endpoint '0d04b186-4f34-448f-bc26-3d5ee745dfd1' to AOR '0d04b186-4f34-448f-bc26-3d5ee745dfd1' will exceed max contacts of 1
[Jan 25 08:36:51] ERROR[15104] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[Jan 25 08:39:32] ERROR[15292] res_pjsip_session.c: FRACK!, Failed assertion bad magic number 0x0 for object 0x7f65953d40a0 (0)
[Jan 25 08:39:32] ERROR[15292] : Got 13 backtrace records
# 0: /usr/sbin/asterisk() [0x45c977]
# 1: /usr/sbin/asterisk() [0x45ff1b]
# 2: /usr/sbin/asterisk(__ao2_find+0x28) [0x460108]
# 3: /usr/lib/asterisk/modules/res_pjsip_session.so(ast_sip_session_get_datastore+0x31) [0x7f655b260491]
# 4: /usr/lib/asterisk/modules/res_pjsip_header_funcs.so(+0x1f56) [0x7f6559c10f56]
# 5: /usr/lib/asterisk/modules/res_pjsip.so(+0x11730) [0x7f655d6dd730]
# 6: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 7: /usr/sbin/asterisk() [0x5a2d10]
# 8: /usr/sbin/asterisk(ast_taskprocessor_execute+0xce) [0x59b61e]
# 9: /usr/sbin/asterisk() [0x5a34b0]
#10: /usr/sbin/asterisk() [0x5ab34c]
#11: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f65c7a216ba]
#12: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f65c6ffb41d]
And so on (bad magic repeating with task processors alerts on m:rtp:all)
We are using stasis and realtime, no changes were made, load was pretty low in terms of cps, there was < 50 channels on the second server that had repeating bad magic number issues.
I know this is maybe too little information to pin down the issue, but I don’t know what went wrong and I am not able to reproduce the issue.
Regards