[Nov 28 09:41:29] -- Executing [1@crash:2] Dial("Local/1@crash-000002f5;2", "IAX2/REDACTED@REDACTED/REDACTED") in new stack [Nov 28 09:41:29] DEBUG[76860][C-00000353]: app_dial.c:2305 dial_exec_full: Local/1@crash-000002f5;2: Data: IAX2/REDACTED@REDACTED/REDACTED [Nov 28 09:41:29] DEBUG[76860][C-00000353]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'REDACTED' into... [Nov 28 09:41:29] DEBUG[76860][C-00000353]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'REDACTED' and port ''. [Nov 28 09:41:29] == Begin MixMonitor Recording Local/1@crash-000002f5;2 [Nov 28 09:41:29] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:29] DEBUG[76860][C-00000353]: chan_iax2.c:2665 peercnt_add: ip callno count incremented to 1 for ASTERISK-SIDE-B-IP [Nov 28 09:41:29] DEBUG[76860][C-00000353]: chan_iax2.c:3202 __find_callno: Creating new call structure 8616 [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:682 ast_channel_nativeformats_set: : Formats: (none) [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:692 ast_channel_nativeformats_set: Channel is being initialized or destroyed [Nov 28 09:41:29] DEBUG[76860][C-00000353]: stasis.c:579 stasis_topic_create_with_detail: Creating topic. name: channel:SFCU01-1638110489.3793, detail: [Nov 28 09:41:29] DEBUG[76860][C-00000353]: stasis.c:613 stasis_topic_create_with_detail: Topic 'channel:SFCU01-1638110489.3793': 0x7fa8c8030920 created [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel.c:951 __ast_channel_alloc_ap: Channel 0x7fa8c802e7f0 'IAX2/ASTERISK-SIDE-B-IP:4569-8616' allocated [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:682 ast_channel_nativeformats_set: IAX2/ASTERISK-SIDE-B-IP:4569-8616: Formats: (ulaw|alaw|g722) [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:700 ast_channel_nativeformats_set: New topology set [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:805 ast_channel_callid_set: Channel Call ID changing from [C-00000353] to [C-00000353] [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:682 ast_channel_nativeformats_set: IAX2/ASTERISK-SIDE-B-IP:4569-8616: Formats: (ulaw) [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:700 ast_channel_nativeformats_set: New topology set [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel_internal_api.c:805 ast_channel_callid_set: Channel Call ID changing from [C-00000353] to [C-00000353] [Nov 28 09:41:29] DEBUG[76860][C-00000353]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'REDACTED' into... [Nov 28 09:41:29] DEBUG[76860][C-00000353]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'REDACTED' and port ''. [Nov 28 09:41:29] DEBUG[76860][C-00000353]: chan_iax2.c:5269 iax2_call: OSP token is undefined [Nov 28 09:41:29] -- Called IAX2/REDACTED@REDACTED/REDACTED [Nov 28 09:41:29] DEBUG[76860][C-00000353]: app_dial.c:1233 wait_for_answer: Local/1@crash-000002f5;2 [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel.c:5752 set_format: Channel IAX2/ASTERISK-SIDE-B-IP:4569-8616 setting read format path: ulaw -> slin [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel.c:5752 set_format: Channel Local/1@crash-000002f5;2 setting write format path: slin -> slin [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel.c:5752 set_format: Channel Local/1@crash-000002f5;2 setting read format path: slin -> slin [Nov 28 09:41:29] DEBUG[76860][C-00000353]: channel.c:5752 set_format: Channel IAX2/ASTERISK-SIDE-B-IP:4569-8616 setting write format path: slin -> ulaw [Nov 28 09:41:29] DEBUG[18879]: chan_iax2.c:3414 send_packet: Sending 18 on 8616/0 to ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Nov 28 09:41:29] Timestamp: 00018ms SCall: 08616 DCall: 00000 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] VERSION : 2 [Nov 28 09:41:29] CALLED NUMBER : REDACTED [Nov 28 09:41:29] CODEC_PREFS : (ulaw|alaw|g722) [Nov 28 09:41:29] CALLING PRESNTN : 67 [Nov 28 09:41:29] CALLING TYPEOFN : 0 [Nov 28 09:41:29] CALLING TRANSIT : 0 [Nov 28 09:41:29] CALLING ANI2 : 0 [Nov 28 09:41:29] LANGUAGE : en [Nov 28 09:41:29] USERNAME : REDACTED [Nov 28 09:41:29] ENCRYPTION : 32769 [Nov 28 09:41:29] FORMAT : 4 [Nov 28 09:41:29] FORMAT2 : ulaw [Nov 28 09:41:29] CAPABILITY : 4108 [Nov 28 09:41:29] CAPABILITY2 : Unknown [Nov 28 09:41:29] ADSICPE : 0 [Nov 28 09:41:29] DATE TIME : 2021-11-28 09:41:28 [Nov 28 09:41:29] [Nov 28 09:41:29] DEBUG[18862]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] DEBUG[18862]: chan_iax2.c:14556 iax2_devicestate: Checking device state for device ASTERISK-SIDE-B-IP [Nov 28 09:41:29] DEBUG[18862]: devicestate.c:466 do_state_change: Changing state for IAX2/ASTERISK-SIDE-B-IP:4569 - state 4 (Invalid) [Nov 28 09:41:29] DEBUG[18901]: app_queue.c:2589 device_state_cb: Device 'IAX2/ASTERISK-SIDE-B-IP:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Nov 28 09:41:29] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Nov 28 09:41:29] Timestamp: 00018ms SCall: 00001 DCall: 08616 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] CALLTOKEN : 51 bytes [Nov 28 09:41:29] [Nov 28 09:41:29] DEBUG[18887][C-00000353]: chan_iax2.c:10404 socket_process_helper: Received packet 0, (6, 40) [Nov 28 09:41:29] DEBUG[18887][C-00000353]: chan_iax2.c:10501 socket_process_helper: Cancelling transmission of packet 0 [Nov 28 09:41:29] DEBUG[18887][C-00000353]: chan_iax2.c:10675 socket_process_helper: IAX subclass 40 received [Nov 28 09:41:29] DEBUG[18887][C-00000353]: chan_iax2.c:10684 socket_process_helper: For call=8616, set last=18 [Nov 28 09:41:29] DEBUG[18879]: chan_iax2.c:3414 send_packet: Sending 27 on 8616/0 to ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Nov 28 09:41:29] Timestamp: 00027ms SCall: 08616 DCall: 00000 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] VERSION : 2 [Nov 28 09:41:29] CALLED NUMBER : REDACTED [Nov 28 09:41:29] CODEC_PREFS : (ulaw|alaw|g722) [Nov 28 09:41:29] CALLING PRESNTN : 67 [Nov 28 09:41:29] CALLING TYPEOFN : 0 [Nov 28 09:41:29] CALLING TRANSIT : 0 [Nov 28 09:41:29] CALLING ANI2 : 0 [Nov 28 09:41:29] LANGUAGE : en [Nov 28 09:41:29] USERNAME : REDACTED [Nov 28 09:41:29] ENCRYPTION : 32769 [Nov 28 09:41:29] FORMAT : 4 [Nov 28 09:41:29] FORMAT2 : ulaw [Nov 28 09:41:29] CAPABILITY : 4108 [Nov 28 09:41:29] CAPABILITY2 : Unknown [Nov 28 09:41:29] ADSICPE : 0 [Nov 28 09:41:29] DATE TIME : 2021-11-28 09:41:28 [Nov 28 09:41:29] CALLTOKEN : 51 bytes [Nov 28 09:41:29] [Nov 28 09:41:29] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACCEPT [Nov 28 09:41:29] Timestamp: 00018ms SCall: 01987 DCall: 08616 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] FORMAT : 4 [Nov 28 09:41:29] FORMAT2 : ulaw [Nov 28 09:41:29] [Nov 28 09:41:29] DEBUG[18891][C-00000353]: chan_iax2.c:10404 socket_process_helper: Received packet 0, (6, 7) [Nov 28 09:41:29] DEBUG[18891][C-00000353]: chan_iax2.c:10501 socket_process_helper: Cancelling transmission of packet 0 [Nov 28 09:41:29] DEBUG[18891][C-00000353]: chan_iax2.c:10675 socket_process_helper: IAX subclass 7 received [Nov 28 09:41:29] -- Call accepted by ASTERISK-SIDE-B-IP:4569 (format ulaw) [Nov 28 09:41:29] DEBUG[18891][C-00000353]: channel_internal_api.c:682 ast_channel_nativeformats_set: IAX2/ASTERISK-SIDE-B-IP:4569-8616: Formats: (ulaw) [Nov 28 09:41:29] DEBUG[18891][C-00000353]: channel_internal_api.c:700 ast_channel_nativeformats_set: New topology set [Nov 28 09:41:29] -- Format for call is (ulaw) [Nov 28 09:41:29] DEBUG[18891][C-00000353]: chan_iax2.c:3414 send_packet: Sending 18 on 8616/1987 to ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:29] Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK [Nov 28 09:41:29] Timestamp: 00018ms SCall: 08616 DCall: 01987 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:9195 __sip_alloc: Allocating new SIP dialog for 315e1fcc18cc50c17ae5cf075f8dbb96@127.0.1.1:16262 - OPTIONS (No RTP) [Nov 28 09:41:31] DEBUG[18878]: acl.c:1047 ast_ouraddrfor: For destination '10.55.1.196', our source address is '10.55.1.247'. [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:4036 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 10.55.1.247:16262 [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:8984 change_callid_pvt: SIP call-id changed from '315e1fcc18cc50c17ae5cf075f8dbb96@127.0.1.1:16262' to '578d04d36d3890b841a95726072ca24b@10.55.1.247:16262' [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:3503 initialize_initreq: Initializing initreq for method OPTIONS - callid 578d04d36d3890b841a95726072ca24b@10.55.1.247:16262 [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:3860 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.55.1.196:5062 [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:9602 __find_call: = Looking for Call ID: 578d04d36d3890b841a95726072ca24b@10.55.1.247:16262 (Checking To) --From tag as567b52e9 --To-tag 535521953 [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:4663 __sip_ack: Stopping retransmission on '578d04d36d3890b841a95726072ca24b@10.55.1.247:16262' of Request 102: Match Found [Nov 28 09:41:31] DEBUG[18878]: chan_sip.c:6735 sip_pvt_dtor: Destroying SIP dialog 578d04d36d3890b841a95726072ca24b@10.55.1.247:16262 [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:9195 __sip_alloc: Allocating new SIP dialog for 598d09f4789671c00e88e6aa06484432@127.0.1.1:16262 - OPTIONS (No RTP) [Nov 28 09:41:34] DEBUG[18878]: acl.c:1047 ast_ouraddrfor: For destination '10.55.1.197', our source address is '10.55.1.247'. [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:4036 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 10.55.1.247:16262 [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:8984 change_callid_pvt: SIP call-id changed from '598d09f4789671c00e88e6aa06484432@127.0.1.1:16262' to '1147203765d6265f424d9cec079229a3@10.55.1.247:16262' [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:3503 initialize_initreq: Initializing initreq for method OPTIONS - callid 1147203765d6265f424d9cec079229a3@10.55.1.247:16262 [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:3860 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.55.1.197:5060 [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:9602 __find_call: = Looking for Call ID: 1147203765d6265f424d9cec079229a3@10.55.1.247:16262 (Checking To) --From tag as5f75ef58 --To-tag 1807620032 [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:4663 __sip_ack: Stopping retransmission on '1147203765d6265f424d9cec079229a3@10.55.1.247:16262' of Request 102: Match Found [Nov 28 09:41:34] DEBUG[18878]: chan_sip.c:6735 sip_pvt_dtor: Destroying SIP dialog 1147203765d6265f424d9cec079229a3@10.55.1.247:16262 [Nov 28 09:41:35] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: VOICE Subclass: 4 [Nov 28 09:41:35] Timestamp: 05640ms SCall: 01987 DCall: 08616 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:35] DEBUG[18882][C-00000353]: chan_iax2.c:10404 socket_process_helper: Received packet 1, (2, 0) [Nov 28 09:41:35] DEBUG[18882][C-00000353]: chan_iax2.c:10635 socket_process_helper: Ooh, voice format changed to 'ulaw' [Nov 28 09:41:35] DEBUG[18882][C-00000353]: channel_internal_api.c:682 ast_channel_nativeformats_set: IAX2/ASTERISK-SIDE-B-IP:4569-8616: Formats: (ulaw) [Nov 28 09:41:35] DEBUG[18882][C-00000353]: channel_internal_api.c:700 ast_channel_nativeformats_set: New topology set [Nov 28 09:41:35] DEBUG[18882][C-00000353]: chan_iax2.c:3414 send_packet: Sending 5640 on 8616/1987 to ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:35] Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK [Nov 28 09:41:35] Timestamp: 05640ms SCall: 08616 DCall: 01987 ASTERISK-SIDE-B-IP:4569 [Nov 28 09:41:35] DEBUG[18882][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5640 [Nov 28 09:41:35] DEBUG[76860][C-00000353]: audiohook.c:189 ast_audiohook_write_frame: Flushing audiohook 0x7fa8c8045f50 so it remains in sync [Nov 28 09:41:35] DEBUG[76860][C-00000353]: audiohook.c:199 ast_audiohook_write_frame: Audiohook 0x7fa8c8045f50 has stale audio in its factories. Flushing them both [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:312 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x7fa8c8045fd8 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:35] DEBUG[18885][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5660 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:312 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x7fa8c8045fd8 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:35] DEBUG[18884][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5680 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:312 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x7fa8c8045fd8 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:35] DEBUG[18888][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5700 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:312 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x7fa8c8045fd8 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:35] DEBUG[18886][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5720 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:312 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x7fa8c8045fd8 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:35] DEBUG[18890][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5740 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:312 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x7fa8c8045fd8 [Nov 28 09:41:35] DEBUG[76861][C-00000353]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x7fa8c8045fd8 and write factory 0x7fa8c8046a18 both fail to provide 160 samples [Nov 28 09:41:35] DEBUG[18889][C-00000353]: chan_iax2.c:11996 socket_process_helper: For call=8616, set last=5760