[11/24 11:23:05.217] DEBUG[75925] manager.c: Running action 'Originate' [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: : Formats: (none) [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:05.217] DEBUG[76055] stasis.c: Creating topic. name: channel:1637774585.8, detail: [11/24 11:23:05.217] DEBUG[76055] stasis.c: Topic 'channel:1637774585.8': 0x7f7f7000ac90 created [11/24 11:23:05.217] DEBUG[76055] channel.c: Channel 0x7f7f70013710 'Local/1234@IS-00000004;1' allocated [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Local/1234@IS-00000004;1: MultistreamFormats: (slin) [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Set native formats but not topology [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Local/1234@IS-00000004;1: <0:audio-0:audio:sendrecv (slin)> [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Used provided topology [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: : Formats: (none) [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:05.217] DEBUG[76055] stasis.c: Creating topic. name: channel:1637774585.9, detail: [11/24 11:23:05.217] DEBUG[76055] stasis.c: Topic 'channel:1637774585.9': 0x7f7f700149e0 created [11/24 11:23:05.217] DEBUG[76055] channel.c: Channel 0x7f7f70010310 'Local/1234@IS-00000004;2' allocated [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Local/1234@IS-00000004;2: MultistreamFormats: (slin) [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Set native formats but not topology [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Local/1234@IS-00000004;2: <0:audio-0:audio:sendrecv (slin)> [11/24 11:23:05.217] DEBUG[76055] channel_internal_api.c: Used provided topology [11/24 11:23:05.217] DEBUG[75925] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/1234@IS-00000004;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 [11/24 11:23:05.217] DEBUG[75925] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 [11/24 11:23:05.217] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Extension: 1234 Application: AppDial2 AppData: (Outgoing Line) [11/24 11:23:05.217] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Variable: OriginateCallId Value: 4 [11/24 11:23:05.217] DEBUG[75925] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/1234@IS-00000004;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 CID-CallingPres: 1 (Presentation Allowed, Passed Screen) [11/24 11:23:05.217] DEBUG[75925] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Local/1234@IS-00000004;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx_variables.c: Result of 'EXTEN' is '1234' [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx.c: Launching 'Set' [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: OriginateCallId Value: 4 [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx_variables.c: Expression result is '0' [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx.c: Launching 'GotoIf' [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx_builtins.c: Not taking any branch [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: LocalBridge Privilege: call,all LocalOneChannel: Local/1234@IS-00000004;1 LocalOneChannelState: 0 LocalOneChannelStateDesc: Down LocalOneCallerIDNum: 1 LocalOneCallerIDName: LocalA LocalOneConnectedLineNum: 1 LocalOneConnectedLineName: LocalA LocalOneLanguage: en LocalOneAccountCode: LocalOneContext: IS LocalOneExten: 1234 LocalOnePriority: 1 LocalOneUniqueid: 1637774585.8 LocalOneLinkedid: 1637774585.8 LocalTwoChannel: Local/1234@IS-00000004;2 LocalTwoChannelState: 4 LocalTwoChannelStateDesc: Ring LocalTwoCallerIDNum: 1 LocalTwoCallerIDName: LocalA LocalTwoConnectedLineNum: 1 LocalTwoConnectedLineName: LocalA LocalTwoLanguage: en LocalTwoAccountCode: LocalTwoContext: IS LocalTwoExten: 1234 LocalTwoPriority: 1 LocalTwoUniqueid: 1637774585.9 LocalTwoLinkedid: 1637774585.8 Context: IS Exten: 1234 LocalOptimization: Yes [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: Local/1234@IS-00000004;1 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 1 DestCallerIDName: LocalA DestConnectedLineNum: 1 DestConnectedLineName: LocalA DestLanguage: en DestAccountCode: DestContext: IS DestExten: 1234 DestPriority: 1 DestUniqueid: 1637774585.8 DestLinkedid: 1637774585.8 DialString: 1234@IS [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx_variables.c: Expression result is '0' [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx.c: Launching 'GotoIf' [11/24 11:23:05.218] DEBUG[76057][C-00000005] pbx.c: Launching 'AGI' [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Extension: 1234 Application: Set AppData: AMTELCO_EXTEN=1234 [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: AMTELCO_EXTEN Value: 1234 [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 2 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Extension: 1234 Application: GotoIf AppData: 0?IS_pjsip [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 3 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Extension: 1234 Application: GotoIf AppData: 0?IS_sip:IS_agi [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Extension: 1234 Application: AGI AppData: agi:async [11/24 11:23:05.218] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIStart Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Env: agi_request%3A%20async%0Aagi_channel%3A%20Local%2F1234%40IS-00000004%3B2%0Aagi_language%3A%20en%0Aagi_type%3A%20Local%0Aagi_uniqueid%3A%201637774585.9%0Aagi_version%3A%2018.8.0%0Aagi_callerid%3A%201%0Aagi_calleridname%3A%20LocalA%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20IS%0Aagi_extension%3A%201234%0Aagi_priority%3A%2017%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140185046136576%0A%0A [11/24 11:23:07.212] DEBUG[75925] manager.c: Running action 'AGI' [11/24 11:23:07.221] DEBUG[76057][C-00000005] core_unreal.c: Blocked indication -1 [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx_variables.c: Result of 'EXTEN' is 'createcall' [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx.c: Launching 'Set' [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:07.221] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for Local - 1234@IS [11/24 11:23:07.221] DEBUG[75859] devicestate.c: Changing state for Local/1234@IS - state 2 (In use) [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx_variables.c: Expression result is '0' [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx.c: Launching 'GotoIf' [11/24 11:23:07.221] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for Local - 1234@IS [11/24 11:23:07.221] DEBUG[75859] devicestate.c: Changing state for Local/1234@IS - state 2 (In use) [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx_builtins.c: Not taking any branch [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx_variables.c: Expression result is '0' [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx.c: Launching 'GotoIf' [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 CommandId: 1404151049 Command: Answer [11/24 11:23:07.221] DEBUG[76056][C-00000006] pbx.c: Launching 'AGI' [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: Local/1234@IS-00000004;1 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 1 DestCallerIDName: LocalA DestConnectedLineNum: 1 DestConnectedLineName: LocalA DestLanguage: en DestAccountCode: DestContext: IS DestExten: 1234 DestPriority: 1 DestUniqueid: 1637774585.8 DestLinkedid: 1637774585.8 DialStatus: ANSWER [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Extension: createcall Application: Set AppData: AMTELCO_EXTEN=createcall [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 1 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Variable: AMTELCO_EXTEN Value: createcall [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 2 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Extension: createcall Application: GotoIf AppData: 0?IS_pjsip [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 3 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Extension: createcall Application: GotoIf AppData: 0?IS_sip:IS_agi [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Extension: createcall Application: AGI AppData: agi:async [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIStart Privilege: agi,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Env: agi_request%3A%20async%0Aagi_channel%3A%20Local%2F1234%40IS-00000004%3B1%0Aagi_language%3A%20en%0Aagi_type%3A%20Local%0Aagi_uniqueid%3A%201637774585.8%0Aagi_version%3A%2018.8.0%0Aagi_callerid%3A%201%0Aagi_calleridname%3A%20LocalA%0Aagi_callingpres%3A%201%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20IS%0Aagi_extension%3A%20createcall%0Aagi_priority%3A%207%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140185519802112%0A%0A [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/1234@IS State: INUSE [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/1234@IS State: INUSE [11/24 11:23:07.221] DEBUG[75925] manager.c: Examining AMI event: Event: OriginateResponse Privilege: call,all ActionID: S44 Response: Success Channel: Local/1234@IS-00000004;1 Context: IS Exten: createcall Reason: 4 Uniqueid: 1637774585.8 CallerIDNum: 1 CallerIDName: LocalA [11/24 11:23:07.721] DEBUG[76057][C-00000005] channel.c: Didn't receive a media frame from Local/1234@IS-00000004;2 within 500 ms of answering. Continuing anyway [11/24 11:23:07.721] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 CommandId: 1404151049 Command: Answer ResultCode: 200 Result: Success [11/24 11:23:07.721] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Result: 200%20result%3D0%0A CommandId: C45 [11/24 11:23:14.479] DEBUG[75889] res_pjsip_registrar.c: Woke up at 1637774594 Interval: 30 [11/24 11:23:14.479] DEBUG[75889] res_pjsip_registrar.c: Expiring 0 contacts [11/24 11:23:15.293] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32815 (rdata0x7f7f4c02a558) [11/24 11:23:15.293] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32815 (rdata0x7f7f4c02a558) [11/24 11:23:15.293] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.293] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:15.293] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:15.293] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.293] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.293] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.293] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.294] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774574/cb4abc3f4176a134918434bd7b8a5ea8. Actual nonce is 1637774574/cb4abc3f4176a134918434bd7b8a5ea8 [11/24 11:23:15.294] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:15.294] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.294] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.294] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.294] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.296] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32816 (rdata0x7f7f4c02a558) [11/24 11:23:15.296] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32816 (rdata0x7f7f4c02a558) [11/24 11:23:15.296] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.296] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:15.296] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:15.296] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.296] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.296] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.296] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.296] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774595/e2217c1e55463263fc9f0adbb9113b2d. Actual nonce is 1637774595/e2217c1e55463263fc9f0adbb9113b2d [11/24 11:23:15.296] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:15.296] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.296] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.296] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.296] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.299] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574611 (rdata0x7f7f4c02a558) [11/24 11:23:15.299] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574611 (rdata0x7f7f4c02a558) [11/24 11:23:15.299] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.299] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:15.299] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:15.299] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.299] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.299] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.299] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.299] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774574/cb4abc3f4176a134918434bd7b8a5ea8. Actual nonce is 1637774574/cb4abc3f4176a134918434bd7b8a5ea8 [11/24 11:23:15.299] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:15.299] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.299] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.299] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.299] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.302] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574612 (rdata0x7f7f4c02a558) [11/24 11:23:15.302] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574612 (rdata0x7f7f4c02a558) [11/24 11:23:15.302] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.302] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:15.302] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:15.302] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.302] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.302] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.302] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:15.302] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774595/e2217c1e55463263fc9f0adbb9113b2d. Actual nonce is 1637774595/e2217c1e55463263fc9f0adbb9113b2d [11/24 11:23:15.302] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:15.302] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:15.302] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:15.302] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:15.302] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:20.712] DEBUG[75925] manager.c: Running action 'Originate' [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: : Formats: (none) [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:20.712] DEBUG[76058] stasis.c: Creating topic. name: channel:1637774600.10, detail: [11/24 11:23:20.712] DEBUG[76058] stasis.c: Topic 'channel:1637774600.10': 0x7f7f3c008d20 created [11/24 11:23:20.712] DEBUG[76058] channel.c: Channel 0x7f7f3c007170 'Local/5678@IS-00000005;1' allocated [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Local/5678@IS-00000005;1: MultistreamFormats: (slin) [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Set native formats but not topology [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Local/5678@IS-00000005;1: <0:audio-0:audio:sendrecv (slin)> [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Used provided topology [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: : Formats: (none) [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:20.712] DEBUG[76058] stasis.c: Creating topic. name: channel:1637774600.11, detail: [11/24 11:23:20.712] DEBUG[76058] stasis.c: Topic 'channel:1637774600.11': 0x7f7f3c0084c0 created [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/5678@IS-00000005;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 [11/24 11:23:20.712] DEBUG[76058] channel.c: Channel 0x7f7f3c00b960 'Local/5678@IS-00000005;2' allocated [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Local/5678@IS-00000005;2: MultistreamFormats: (slin) [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Set native formats but not topology [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Local/5678@IS-00000005;2: <0:audio-0:audio:sendrecv (slin)> [11/24 11:23:20.712] DEBUG[76058] channel_internal_api.c: Used provided topology [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Extension: 5678 Application: AppDial2 AppData: (Outgoing Line) [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Variable: OriginateCallId Value: 6 [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/5678@IS-00000005;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 CID-CallingPres: 1 (Presentation Allowed, Passed Screen) [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Local/5678@IS-00000005;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx_variables.c: Result of 'EXTEN' is '5678' [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx.c: Launching 'Set' [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Variable: OriginateCallId Value: 6 [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: LocalBridge Privilege: call,all LocalOneChannel: Local/5678@IS-00000005;1 LocalOneChannelState: 0 LocalOneChannelStateDesc: Down LocalOneCallerIDNum: 2 LocalOneCallerIDName: LocalB LocalOneConnectedLineNum: 2 LocalOneConnectedLineName: LocalB LocalOneLanguage: en LocalOneAccountCode: LocalOneContext: IS LocalOneExten: 5678 LocalOnePriority: 1 LocalOneUniqueid: 1637774600.10 LocalOneLinkedid: 1637774600.10 LocalTwoChannel: Local/5678@IS-00000005;2 LocalTwoChannelState: 4 LocalTwoChannelStateDesc: Ring LocalTwoCallerIDNum: 2 LocalTwoCallerIDName: LocalB LocalTwoConnectedLineNum: 2 LocalTwoConnectedLineName: LocalB LocalTwoLanguage: en LocalTwoAccountCode: LocalTwoContext: IS LocalTwoExten: 5678 LocalTwoPriority: 1 LocalTwoUniqueid: 1637774600.11 LocalTwoLinkedid: 1637774600.10 Context: IS Exten: 5678 LocalOptimization: Yes [11/24 11:23:20.712] DEBUG[75925] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: Local/5678@IS-00000005;1 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 2 DestCallerIDName: LocalB DestConnectedLineNum: 2 DestConnectedLineName: LocalB DestLanguage: en DestAccountCode: DestContext: IS DestExten: 5678 DestPriority: 1 DestUniqueid: 1637774600.10 DestLinkedid: 1637774600.10 DialString: 5678@IS [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx_variables.c: Expression result is '0' [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx.c: Launching 'GotoIf' [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx_builtins.c: Not taking any branch [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx_variables.c: Expression result is '0' [11/24 11:23:20.712] DEBUG[76060][C-00000007] pbx.c: Launching 'GotoIf' [11/24 11:23:20.713] DEBUG[76060][C-00000007] pbx.c: Launching 'AGI' [11/24 11:23:20.713] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Extension: 5678 Application: Set AppData: AMTELCO_EXTEN=5678 [11/24 11:23:20.713] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Variable: AMTELCO_EXTEN Value: 5678 [11/24 11:23:20.713] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 2 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Extension: 5678 Application: GotoIf AppData: 0?IS_pjsip [11/24 11:23:20.713] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 3 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Extension: 5678 Application: GotoIf AppData: 0?IS_sip:IS_agi [11/24 11:23:20.713] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Extension: 5678 Application: AGI AppData: agi:async [11/24 11:23:20.713] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIStart Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Env: agi_request%3A%20async%0Aagi_channel%3A%20Local%2F5678%40IS-00000005%3B2%0Aagi_language%3A%20en%0Aagi_type%3A%20Local%0Aagi_uniqueid%3A%201637774600.11%0Aagi_version%3A%2018.8.0%0Aagi_callerid%3A%202%0Aagi_calleridname%3A%20LocalB%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20IS%0Aagi_extension%3A%205678%0Aagi_priority%3A%2017%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140185046648576%0A%0A [11/24 11:23:23.921] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR 'Infinity' [11/24 11:23:23.921] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying contact 'Infinity@@8e1a5218ecc9a4f261aa2bbb88fd04e1' on AOR 'Infinity' [11/24 11:23:23.921] DEBUG[75878] res_pjsip/pjsip_options.c: Could not find an endpoint to qualify contact 'Infinity@@8e1a5218ecc9a4f261aa2bbb88fd04e1' on AOR 'Infinity' [11/24 11:23:26.156] DEBUG[75925] manager.c: Running action 'AGI' [11/24 11:23:26.221] DEBUG[76060][C-00000007] core_unreal.c: Blocked indication -1 [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx_variables.c: Result of 'EXTEN' is 'createcall' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx.c: Launching 'Set' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx_variables.c: Expression result is '0' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx.c: Launching 'GotoIf' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx_builtins.c: Not taking any branch [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx_variables.c: Function CHANNEL(channeltype) result is 'Local' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx_variables.c: Expression result is '0' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx.c: Launching 'GotoIf' [11/24 11:23:26.221] DEBUG[76059][C-00000008] pbx.c: Launching 'AGI' [11/24 11:23:26.221] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for Local - 5678@IS [11/24 11:23:26.221] DEBUG[75859] devicestate.c: Changing state for Local/5678@IS - state 2 (In use) [11/24 11:23:26.221] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for Local - 5678@IS [11/24 11:23:26.221] DEBUG[75859] devicestate.c: Changing state for Local/5678@IS - state 2 (In use) [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 CommandId: 1638397665 Command: Answer [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: Local/5678@IS-00000005;1 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 2 DestCallerIDName: LocalB DestConnectedLineNum: 2 DestConnectedLineName: LocalB DestLanguage: en DestAccountCode: DestContext: IS DestExten: 5678 DestPriority: 1 DestUniqueid: 1637774600.10 DestLinkedid: 1637774600.10 DialStatus: ANSWER [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Extension: createcall Application: Set AppData: AMTELCO_EXTEN=createcall [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 1 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Variable: AMTELCO_EXTEN Value: createcall [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 2 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Extension: createcall Application: GotoIf AppData: 0?IS_pjsip [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 3 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Extension: createcall Application: GotoIf AppData: 0?IS_sip:IS_agi [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Extension: createcall Application: AGI AppData: agi:async [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIStart Privilege: agi,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Env: agi_request%3A%20async%0Aagi_channel%3A%20Local%2F5678%40IS-00000005%3B1%0Aagi_language%3A%20en%0Aagi_type%3A%20Local%0Aagi_uniqueid%3A%201637774600.10%0Aagi_version%3A%2018.8.0%0Aagi_callerid%3A%202%0Aagi_calleridname%3A%20LocalB%0Aagi_callingpres%3A%201%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20IS%0Aagi_extension%3A%20createcall%0Aagi_priority%3A%207%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140185047672576%0A%0A [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: OriginateResponse Privilege: call,all ActionID: S46 Response: Success Channel: Local/5678@IS-00000005;1 Context: IS Exten: createcall Reason: 4 Uniqueid: 1637774600.10 CallerIDNum: 2 CallerIDName: LocalB [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/5678@IS State: INUSE [11/24 11:23:26.221] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/5678@IS State: INUSE [11/24 11:23:26.721] DEBUG[76060][C-00000007] channel.c: Didn't receive a media frame from Local/5678@IS-00000005;2 within 500 ms of answering. Continuing anyway [11/24 11:23:26.721] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 CommandId: 1638397665 Command: Answer ResultCode: 200 Result: Success [11/24 11:23:26.721] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Result: 200%20result%3D0%0A CommandId: C47 [11/24 11:23:35.966] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:35.966] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:35.967] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:35.967] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:35.967] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:35.967] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:35.968] DEBUG[75925] manager.c: Running action 'AGI' [11/24 11:23:35.973] DEBUG[76056][C-00000006] app_confbridge.c: Trying to find conference bridge 'IS__A' [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis.c: Creating topic. name: bridge:all/bridge:f4cd26b0-713b-40f9-9fe7-eac238edcd6e, detail: [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis.c: Topic 'bridge:all/bridge:f4cd26b0-713b-40f9-9fe7-eac238edcd6e': 0x7f7f7800f4c0 created [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Chose bridge technology softmix [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: calling softmix technology constructor [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: calling softmix technology start [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis_bridges.c: Update: 0x7f7f78004d08 Old: New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: : Formats: (none) [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis.c: Creating topic. name: channel:1637774615.12, detail: [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis.c: Topic 'channel:1637774615.12': 0x7f7f78009310 created [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel.c: Channel 0x7f7f78006de0 'CBAnn/IS__A-00000006;1' allocated [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: CBAnn/IS__A-00000006;1: Formats: (slin) [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: New topology set [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: : Formats: (none) [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:35.973] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f78004d08 Old: New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis.c: Creating topic. name: channel:1637774615.13, detail: [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis.c: Topic 'channel:1637774615.13': 0x7f7f78016b10 created [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel.c: Channel 0x7f7f7800fec0 'CBAnn/IS__A-00000006;2' allocated [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: CBAnn/IS__A-00000006;2: Formats: (slin) [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel_internal_api.c: New topology set [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_roles.c: Set role 'announcer' [11/24 11:23:35.973] DEBUG[76056][C-00000006] app_confbridge.c: Created announcer channel 'CBAnn/IS__A-00000006;1' to conference bridge 'IS__A' [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 CommandId: 2111000852 Command: EXEC ConfBridge IS__A [11/24 11:23:35.973] DEBUG[76061] bridge_softmix.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: starting mixing thread [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_channel.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: 0x7f7f780168a0(CBAnn/IS__A-00000006;2) is joining [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_channel.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: pushing 0x7f7f780168a0(CBAnn/IS__A-00000006;2) [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_roles.c: Set role 'announcer' [11/24 11:23:35.973] DEBUG[76063][C-00000006] stasis_bridges.c: Update: 0x7f7f5800c5c8 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: 0x7f7f780168a0(CBAnn/IS__A-00000006;2) is joining softmix technology [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_softmix.c: CBAnn/IS__A-00000006;2: [11/24 11:23:35.973] DEBUG[76063][C-00000006] channel.c: Channel CBAnn/IS__A-00000006;2 setting write format path: slin -> slin [11/24 11:23:35.973] DEBUG[76063][C-00000006] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [11/24 11:23:35.973] DEBUG[76063][C-00000006] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_softmix.c: [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_softmix.c: CBAnn/IS__A-00000006;2: [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: f4cd26b0-713b-40f9-9fe7-eac238edcd6e BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__A BridgeNumChannels: 0 BridgeVideoSourceMode: none [11/24 11:23:35.973] DEBUG[76063][C-00000006] bridge_softmix.c: CBAnn/IS__A-00000006;2: Not in SFU mode [11/24 11:23:35.973] DEBUG[76063][C-00000006] stasis_bridges.c: Update: 0x7f7f58021e08 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[76056][C-00000006] app_confbridge.c: Created conference 'IS__A' and linked to container. [11/24 11:23:35.973] DEBUG[76056][C-00000006] confbridge/conf_state.c: Changing conference 'IS__A' state from EMPTY to SINGLE [11/24 11:23:35.973] DEBUG[76056][C-00000006] app_confbridge.c: User Local/1234@IS-00000004;1 is unmuted: user:0 system:0. [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_channel.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: 0x7f7f7800b870(Local/1234@IS-00000004;1) is joining [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_channel.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: pushing 0x7f7f7800b870(Local/1234@IS-00000004;1) [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis_bridges.c: Update: 0x7f7f78018138 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge.c: Bridge f4cd26b0-713b-40f9-9fe7-eac238edcd6e: 0x7f7f7800b870(Local/1234@IS-00000004;1) is joining softmix technology [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_softmix.c: Local/1234@IS-00000004;1: [11/24 11:23:35.973] DEBUG[76056][C-00000006] channel.c: Channel Local/1234@IS-00000004;1 setting write format path: slin -> slin [11/24 11:23:35.973] DEBUG[76056][C-00000006] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [11/24 11:23:35.973] DEBUG[76056][C-00000006] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_softmix.c: [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_softmix.c: Local/1234@IS-00000004;1: [11/24 11:23:35.973] DEBUG[76056][C-00000006] bridge_softmix.c: Local/1234@IS-00000004;1: Not in SFU mode [11/24 11:23:35.973] DEBUG[76056][C-00000006] stasis_bridges.c: Update: 0x7f7f78020e28 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f5800c5c8 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f58021e08 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f78018138 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f78020e28 Old: f4cd26b0-713b-40f9-9fe7-eac238edcd6e New: f4cd26b0-713b-40f9-9fe7-eac238edcd6e [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: confbridge:IS__A State: INUSE [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeStart Privilege: call,all Conference: IS__A BridgeUniqueid: f4cd26b0-713b-40f9-9fe7-eac238edcd6e BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__A BridgeNumChannels: 1 BridgeVideoSourceMode: none [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: f4cd26b0-713b-40f9-9fe7-eac238edcd6e BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__A BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeJoin Privilege: call,all Conference: IS__A BridgeUniqueid: f4cd26b0-713b-40f9-9fe7-eac238edcd6e BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__A BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Admin: No Muted: No [11/24 11:23:35.973] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774585.8 Linkedid: 1637774585.8 Variable: BRIDGEPEER Value: CBAnn/IS__A-00000006;2 [11/24 11:23:36.338] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32817 (rdata0x7f7f4c02a558) [11/24 11:23:36.338] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32817 (rdata0x7f7f4c02a558) [11/24 11:23:36.338] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.338] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.338] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:36.338] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:36.338] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:36.338] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:36.338] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:36.338] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:36.338] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.338] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.338] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.338] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.338] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: NOAUTH [11/24 11:23:36.338] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.338] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.338] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.338] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.341] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32818 (rdata0x7f7f4c02a558) [11/24 11:23:36.341] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32818 (rdata0x7f7f4c02a558) [11/24 11:23:36.341] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.341] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:36.341] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:36.341] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.341] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.341] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.341] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.341] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774616/c6c6f792d121a5793b86852f4898bb5b. Actual nonce is 1637774616/c6c6f792d121a5793b86852f4898bb5b [11/24 11:23:36.341] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:36.341] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.341] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.341] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.341] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.347] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574613 (rdata0x7f7f4c02a558) [11/24 11:23:36.347] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574613 (rdata0x7f7f4c02a558) [11/24 11:23:36.347] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.347] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.347] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:36.347] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:36.347] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:36.347] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:36.347] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:36.347] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:36.347] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.347] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.347] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.347] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.347] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: NOAUTH [11/24 11:23:36.347] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.347] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.347] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.347] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.351] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574614 (rdata0x7f7f4c02a558) [11/24 11:23:36.351] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574614 (rdata0x7f7f4c02a558) [11/24 11:23:36.351] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.351] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:36.351] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:36.351] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.351] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.351] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.351] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:36.351] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774616/c6c6f792d121a5793b86852f4898bb5b. Actual nonce is 1637774616/c6c6f792d121a5793b86852f4898bb5b [11/24 11:23:36.351] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:36.351] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:36.351] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:36.351] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:36.351] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.355] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32819 (rdata0x7f7f4c02a558) [11/24 11:23:37.355] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32819 (rdata0x7f7f4c02a558) [11/24 11:23:37.355] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.355] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:37.355] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:37.355] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.355] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.355] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.355] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.355] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774616/c6c6f792d121a5793b86852f4898bb5b. Actual nonce is 1637774616/c6c6f792d121a5793b86852f4898bb5b [11/24 11:23:37.355] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:37.355] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.355] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.355] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.355] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.357] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32820 (rdata0x7f7f4c02a558) [11/24 11:23:37.357] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32820 (rdata0x7f7f4c02a558) [11/24 11:23:37.357] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.357] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:37.357] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:37.357] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.357] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.357] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.357] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.357] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4. Actual nonce is 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4 [11/24 11:23:37.357] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:37.357] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.357] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.357] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.357] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.361] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574615 (rdata0x7f7f4c02a558) [11/24 11:23:37.361] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574615 (rdata0x7f7f4c02a558) [11/24 11:23:37.361] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.361] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:37.361] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:37.361] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.361] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.361] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.361] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.361] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774616/c6c6f792d121a5793b86852f4898bb5b. Actual nonce is 1637774616/c6c6f792d121a5793b86852f4898bb5b [11/24 11:23:37.361] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:37.361] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.361] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.361] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.361] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.363] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574616 (rdata0x7f7f4c02a558) [11/24 11:23:37.363] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574616 (rdata0x7f7f4c02a558) [11/24 11:23:37.363] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.363] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:37.363] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:37.363] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.363] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.363] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.363] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:37.363] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4. Actual nonce is 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4 [11/24 11:23:37.363] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:37.363] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:37.363] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:37.363] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:37.363] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:44.384] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:44.384] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:44.385] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:44.385] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:44.385] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:44.385] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:44.386] DEBUG[75925] manager.c: Running action 'AGI' [11/24 11:23:44.393] DEBUG[76057][C-00000005] app_confbridge.c: Trying to find conference bridge 'IS__B' [11/24 11:23:44.393] DEBUG[76057][C-00000005] stasis.c: Creating topic. name: bridge:all/bridge:a4db2896-a3fa-4984-92a3-2a07f2cf2879, detail: [11/24 11:23:44.393] DEBUG[76057][C-00000005] stasis.c: Topic 'bridge:all/bridge:a4db2896-a3fa-4984-92a3-2a07f2cf2879': 0x562cfdac8e90 created [11/24 11:23:44.393] DEBUG[76057][C-00000005] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [11/24 11:23:44.393] DEBUG[76057][C-00000005] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [11/24 11:23:44.393] DEBUG[76057][C-00000005] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [11/24 11:23:44.393] DEBUG[76057][C-00000005] bridge.c: Chose bridge technology softmix [11/24 11:23:44.393] DEBUG[76057][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: calling softmix technology constructor [11/24 11:23:44.393] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 CommandId: 761104300 Command: EXEC ConfBridge IS__B [11/24 11:23:44.393] DEBUG[76057][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: calling softmix technology start [11/24 11:23:44.393] DEBUG[76057][C-00000005] stasis_bridges.c: Update: 0x562cfd748ec8 Old: New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: : Formats: (none) [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:44.394] DEBUG[76057][C-00000005] stasis.c: Creating topic. name: channel:1637774624.14, detail: [11/24 11:23:44.394] DEBUG[76057][C-00000005] stasis.c: Topic 'channel:1637774624.14': 0x562cfd73a3a0 created [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel.c: Channel 0x562cfdabf290 'CBAnn/IS__B-00000007;1' allocated [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: CBAnn/IS__B-00000007;1: Formats: (slin) [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: New topology set [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: : Formats: (none) [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:23:44.394] DEBUG[76057][C-00000005] stasis.c: Creating topic. name: channel:1637774624.15, detail: [11/24 11:23:44.394] DEBUG[76057][C-00000005] stasis.c: Topic 'channel:1637774624.15': 0x562cfd7a6f60 created [11/24 11:23:44.394] DEBUG[75871] stasis_bridges.c: Update: 0x562cfd748ec8 Old: New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel.c: Channel 0x562cfd753310 'CBAnn/IS__B-00000007;2' allocated [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: CBAnn/IS__B-00000007;2: Formats: (slin) [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel_internal_api.c: New topology set [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_roles.c: Set role 'announcer' [11/24 11:23:44.394] DEBUG[76057][C-00000005] app_confbridge.c: Created announcer channel 'CBAnn/IS__B-00000007;1' to conference bridge 'IS__B' [11/24 11:23:44.394] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 0 BridgeVideoSourceMode: none [11/24 11:23:44.394] DEBUG[76064] bridge_softmix.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: starting mixing thread [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x562cfdab5e00(CBAnn/IS__B-00000007;2) is joining [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: pushing 0x562cfdab5e00(CBAnn/IS__B-00000007;2) [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_roles.c: Set role 'announcer' [11/24 11:23:44.394] DEBUG[76066][C-00000005] stasis_bridges.c: Update: 0x7f7f54017a08 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x562cfdab5e00(CBAnn/IS__B-00000007;2) is joining softmix technology [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_softmix.c: CBAnn/IS__B-00000007;2: [11/24 11:23:44.394] DEBUG[76066][C-00000005] channel.c: Channel CBAnn/IS__B-00000007;2 setting write format path: slin -> slin [11/24 11:23:44.394] DEBUG[76066][C-00000005] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [11/24 11:23:44.394] DEBUG[76066][C-00000005] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_softmix.c: [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_softmix.c: CBAnn/IS__B-00000007;2: [11/24 11:23:44.394] DEBUG[76066][C-00000005] bridge_softmix.c: CBAnn/IS__B-00000007;2: Not in SFU mode [11/24 11:23:44.394] DEBUG[76066][C-00000005] stasis_bridges.c: Update: 0x7f7f54014218 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f54017a08 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f54014218 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[76057][C-00000005] app_confbridge.c: Created conference 'IS__B' and linked to container. [11/24 11:23:44.394] DEBUG[76057][C-00000005] confbridge/conf_state.c: Changing conference 'IS__B' state from EMPTY to SINGLE [11/24 11:23:44.394] DEBUG[76057][C-00000005] app_confbridge.c: User Local/1234@IS-00000004;2 is unmuted: user:0 system:0. [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x562cfdaca0a0(Local/1234@IS-00000004;2) is joining [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: pushing 0x562cfdaca0a0(Local/1234@IS-00000004;2) [11/24 11:23:44.394] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: confbridge:IS__B State: INUSE [11/24 11:23:44.394] DEBUG[76057][C-00000005] stasis_bridges.c: Update: 0x562cfd605568 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x562cfdaca0a0(Local/1234@IS-00000004;2) is joining softmix technology [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_softmix.c: Local/1234@IS-00000004;2: [11/24 11:23:44.394] DEBUG[76057][C-00000005] channel.c: Channel Local/1234@IS-00000004;2 setting write format path: slin -> slin [11/24 11:23:44.394] DEBUG[76057][C-00000005] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [11/24 11:23:44.394] DEBUG[76057][C-00000005] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_softmix.c: [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_softmix.c: Local/1234@IS-00000004;2: [11/24 11:23:44.394] DEBUG[76057][C-00000005] bridge_softmix.c: Local/1234@IS-00000004;2: Not in SFU mode [11/24 11:23:44.394] DEBUG[75871] stasis_bridges.c: Update: 0x562cfd605568 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[76057][C-00000005] stasis_bridges.c: Update: 0x562cfda9f838 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[75871] stasis_bridges.c: Update: 0x562cfda9f838 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:44.394] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 [11/24 11:23:44.394] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: BRIDGEPEER Value: CBAnn/IS__B-00000007;2 [11/24 11:23:44.394] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeStart Privilege: call,all Conference: IS__B BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 1 BridgeVideoSourceMode: none [11/24 11:23:44.394] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeJoin Privilege: call,all Conference: IS__B BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Admin: No Muted: No [11/24 11:23:44.479] DEBUG[75889] res_pjsip_registrar.c: Woke up at 1637774624 Interval: 30 [11/24 11:23:44.479] DEBUG[75889] res_pjsip_registrar.c: Expiring 0 contacts [11/24 11:23:45.925] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=101 (rdata0x7f7f4c02a558) [11/24 11:23:45.925] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000052 to use for Request msg OPTIONS/cseq=101 (rdata0x7f7f4c02a558) [11/24 11:23:45.925] DEBUG[75878] netsock2.c: Splitting '192.168.40.60' into... [11/24 11:23:45.925] DEBUG[75878] netsock2.c: ...host '192.168.40.60' and port ''. [11/24 11:23:45.925] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify21' [11/24 11:23:45.925] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify23' [11/24 11:23:45.925] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify18' [11/24 11:23:45.925] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify22' [11/24 11:23:45.925] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '' domain '192.168.40.60' [11/24 11:23:45.925] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '' domain '192.168.40.60' [11/24 11:23:45.925] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:45.925] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:45.925] DEBUG[75878] netsock2.c: Splitting '192.168.40.60' into... [11/24 11:23:45.925] DEBUG[75878] netsock2.c: ...host '192.168.40.60' and port ''. [11/24 11:23:45.925] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: NOAUTH [11/24 11:23:45.925] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:45.925] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:45.925] DEBUG[75878] netsock2.c: Splitting '192.168.40.60' into... [11/24 11:23:45.925] DEBUG[75878] netsock2.c: ...host '192.168.40.60' and port ''. [11/24 11:23:48.184] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:48.184] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:48.185] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:48.185] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:48.186] DEBUG[75925] manager.c: Running action 'Setvar' [11/24 11:23:48.186] DEBUG[75925] pbx_functions.c: Writing CONFBRIDGE from a dangerous context [11/24 11:23:48.186] DEBUG[75925] manager.c: Running action 'AGI' [11/24 11:23:48.266] DEBUG[76060][C-00000007] app_confbridge.c: Trying to find conference bridge 'IS__B' [11/24 11:23:48.266] DEBUG[76060][C-00000007] app_confbridge.c: User Local/1234@IS-00000004;2 is unmuted: user:0 system:0. [11/24 11:23:48.266] DEBUG[76060][C-00000007] app_confbridge.c: User Local/5678@IS-00000005;2 is unmuted: user:0 system:0. [11/24 11:23:48.266] DEBUG[76060][C-00000007] confbridge/conf_state.c: Changing conference 'IS__B' state from SINGLE to MULTI [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x7f7f4400c0c0(Local/5678@IS-00000005;2) is joining [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: pushing 0x7f7f4400c0c0(Local/5678@IS-00000005;2) [11/24 11:23:48.266] DEBUG[76060][C-00000007] stasis_bridges.c: Update: 0x7f7f4400ec88 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:48.266] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 CommandId: 1834899773 Command: EXEC ConfBridge IS__B [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x7f7f4400c0c0(Local/5678@IS-00000005;2) is joining softmix technology [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge_softmix.c: Local/5678@IS-00000005;2: [11/24 11:23:48.266] DEBUG[76060][C-00000007] channel.c: Channel Local/5678@IS-00000005;2 setting write format path: slin -> slin [11/24 11:23:48.266] DEBUG[76060][C-00000007] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [11/24 11:23:48.266] DEBUG[76060][C-00000007] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge_softmix.c: [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge_softmix.c: Local/5678@IS-00000005;2: [11/24 11:23:48.266] DEBUG[76060][C-00000007] bridge_softmix.c: Local/5678@IS-00000005;2: Not in SFU mode [11/24 11:23:48.266] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f4400ec88 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:48.266] DEBUG[76060][C-00000007] stasis_bridges.c: Update: 0x7f7f4401c168 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:48.266] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f4401c168 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:23:48.266] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 3 BridgeVideoSourceMode: none Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 [11/24 11:23:48.266] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: BRIDGEPEER Value: CBAnn/IS__B-00000007;2,Local/5678@IS-00000005;2 [11/24 11:23:48.266] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Variable: BRIDGEPEER Value: CBAnn/IS__B-00000007;2,Local/1234@IS-00000004;2 [11/24 11:23:48.266] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeJoin Privilege: call,all Conference: IS__B BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 3 BridgeVideoSourceMode: none Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Admin: No Muted: No [11/24 11:23:58.400] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32821 (rdata0x7f7f4c02a558) [11/24 11:23:58.400] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32821 (rdata0x7f7f4c02a558) [11/24 11:23:58.400] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.400] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:58.400] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:58.400] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.400] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.400] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.400] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.400] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4. Actual nonce is 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4 [11/24 11:23:58.400] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:58.400] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.400] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.400] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.400] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.402] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32822 (rdata0x7f7f4c02a558) [11/24 11:23:58.402] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32822 (rdata0x7f7f4c02a558) [11/24 11:23:58.402] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.402] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:23:58.402] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:23:58.402] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.402] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.402] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.402] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.402] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774638/f4b7699e0470b6758aa80a282eacb5eb. Actual nonce is 1637774638/f4b7699e0470b6758aa80a282eacb5eb [11/24 11:23:58.402] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:58.402] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.402] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.402] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.402] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.407] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574617 (rdata0x7f7f4c02a558) [11/24 11:23:58.407] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574617 (rdata0x7f7f4c02a558) [11/24 11:23:58.407] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.407] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:58.407] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:58.407] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.407] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.407] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.407] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.407] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4. Actual nonce is 1637774617/fbc98f76d6238c9cf5b7d9372b3d1ff4 [11/24 11:23:58.407] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:58.407] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.407] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.407] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.407] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.410] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574618 (rdata0x7f7f4c02a558) [11/24 11:23:58.410] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574618 (rdata0x7f7f4c02a558) [11/24 11:23:58.410] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.410] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:23:58.410] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:23:58.410] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.410] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.410] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.410] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:23:58.410] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774638/f4b7699e0470b6758aa80a282eacb5eb. Actual nonce is 1637774638/f4b7699e0470b6758aa80a282eacb5eb [11/24 11:23:58.410] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:23:58.410] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:23:58.410] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:23:58.410] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:23:58.410] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR '192.168.33.33' [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying contact '192.168.33.33@@6609419e0fb101bed05785d07e4292dc' on AOR '192.168.33.33' [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Wrapper created [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Set timer to 3000 msec [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.33.33' [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.33.33' is 'UDP transport' [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_resolver.c: Target '192.168.33.33' is an IP address, skipping resolution [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.33.33:5060 (this may be re-written again later) [11/24 11:24:05.168] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=47382 (rdata0x7f7f4c02a558) [11/24 11:24:05.168] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004b to use for Request msg OPTIONS/cseq=47382 (rdata0x7f7f4c02a558) [11/24 11:24:05.168] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:05.168] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:05.168] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.33.33:5060 does not match identify 'identify21' [11/24 11:24:05.168] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.33.33:5060 matches identify 'identify23' [11/24 11:24:05.168] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Identify 'identify23' SIP message matched to endpoint 192.168.33.33 [11/24 11:24:05.168] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:05.168] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:05.168] DEBUG[75877] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=47382 (rdata0x7f7f4c02a558). Using request transaction as basis. [11/24 11:24:05.168] DEBUG[75877] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7f7f3402b968 for Response msg 200/OPTIONS/cseq=47382 (rdata0x7f7f4c02a558). [11/24 11:24:05.168] DEBUG[75877] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/192.168.33.33-00000067 on transaction tsx0x7f7f3402b968 [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: PJSIP tsx response received [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Cancelling timer [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Timer cancelled [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Callbacks executed [11/24 11:24:05.168] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: wrapper destroyed [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_options.c: Contact 192.168.33.33/sip:192.168.33.33 status didn't change: Reachable, RTT: 0.728 msec [11/24 11:24:05.168] DEBUG[75878] res_pjsip/pjsip_options.c: AOR '192.168.33.33' now has 1 available contacts [11/24 11:24:14.479] DEBUG[75889] res_pjsip_registrar.c: Woke up at 1637774654 Interval: 30 [11/24 11:24:14.479] DEBUG[75889] res_pjsip_registrar.c: Expiring 0 contacts [11/24 11:24:19.442] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32823 (rdata0x7f7f4c02a558) [11/24 11:24:19.442] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32823 (rdata0x7f7f4c02a558) [11/24 11:24:19.442] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.442] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:24:19.442] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:24:19.442] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.442] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.442] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.442] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.442] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774638/f4b7699e0470b6758aa80a282eacb5eb. Actual nonce is 1637774638/f4b7699e0470b6758aa80a282eacb5eb [11/24 11:24:19.442] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:19.442] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.442] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.442] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.442] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.444] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32824 (rdata0x7f7f4c02a558) [11/24 11:24:19.444] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32824 (rdata0x7f7f4c02a558) [11/24 11:24:19.445] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.445] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:24:19.445] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:24:19.445] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.445] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.445] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.445] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.445] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774659/ddf5094763a64fb52e793217b7d449e9. Actual nonce is 1637774659/ddf5094763a64fb52e793217b7d449e9 [11/24 11:24:19.445] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:19.445] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.445] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.445] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.445] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.448] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574619 (rdata0x7f7f4c02a558) [11/24 11:24:19.448] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574619 (rdata0x7f7f4c02a558) [11/24 11:24:19.448] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.448] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:24:19.448] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:24:19.448] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.448] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.448] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.448] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.448] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774638/f4b7699e0470b6758aa80a282eacb5eb. Actual nonce is 1637774638/f4b7699e0470b6758aa80a282eacb5eb [11/24 11:24:19.448] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:19.448] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.448] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.448] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.448] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.451] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574620 (rdata0x7f7f4c02a558) [11/24 11:24:19.451] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574620 (rdata0x7f7f4c02a558) [11/24 11:24:19.451] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.451] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:24:19.451] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:24:19.451] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.451] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.451] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.451] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:19.451] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774659/ddf5094763a64fb52e793217b7d449e9. Actual nonce is 1637774659/ddf5094763a64fb52e793217b7d449e9 [11/24 11:24:19.451] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:19.451] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:19.451] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:19.451] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:19.451] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:21.945] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=65587 (rdata0x7f7f4c02a558) [11/24 11:24:21.945] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000056 to use for Request msg REGISTER/cseq=65587 (rdata0x7f7f4c02a558) [11/24 11:24:21.945] DEBUG[75878] netsock2.c: Splitting '192.168.32.66' into... [11/24 11:24:21.945] DEBUG[75878] netsock2.c: ...host '192.168.32.66' and port ''. [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify21' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify23' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify18' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify22' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '1005' domain '192.168.33.33' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '1005' domain '192.168.33.33' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '1005' realm 'asterisk' [11/24 11:24:21.945] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '1005' realm 'asterisk' [11/24 11:24:21.945] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:21.945] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:21.945] DEBUG[75878] netsock2.c: Splitting '192.168.32.66' into... [11/24 11:24:21.945] DEBUG[75878] netsock2.c: ...host '192.168.32.66' and port ''. [11/24 11:24:21.945] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:21.945] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:21.945] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:21.945] DEBUG[75878] netsock2.c: Splitting '192.168.32.66' into... [11/24 11:24:21.945] DEBUG[75878] netsock2.c: ...host '192.168.32.66' and port ''. [11/24 11:24:21.952] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=65588 (rdata0x7f7f4c02a558) [11/24 11:24:21.952] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000056 to use for Request msg REGISTER/cseq=65588 (rdata0x7f7f4c02a558) [11/24 11:24:21.952] DEBUG[75878] netsock2.c: Splitting '192.168.32.66' into... [11/24 11:24:21.952] DEBUG[75878] netsock2.c: ...host '192.168.32.66' and port ''. [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify21' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify23' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify18' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.66:5062 does not match identify 'identify22' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '1005' domain '192.168.33.33' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '1005' domain '192.168.33.33' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '1005' realm 'asterisk' [11/24 11:24:21.952] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '1005' realm 'asterisk' [11/24 11:24:21.952] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:21.952] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:21.952] DEBUG[75878] netsock2.c: Splitting '192.168.32.66' into... [11/24 11:24:21.952] DEBUG[75878] netsock2.c: ...host '192.168.32.66' and port ''. [11/24 11:24:21.952] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774661/31c991af338b944c34b08f0477e629fb. Actual nonce is 1637774661/31c991af338b944c34b08f0477e629fb [11/24 11:24:21.952] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:21.952] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:21.952] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:21.952] DEBUG[75878] netsock2.c: Splitting '192.168.32.66' into... [11/24 11:24:21.952] DEBUG[75878] netsock2.c: ...host '192.168.32.66' and port ''. [11/24 11:24:23.921] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR 'Infinity' [11/24 11:24:23.921] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying contact 'Infinity@@8e1a5218ecc9a4f261aa2bbb88fd04e1' on AOR 'Infinity' [11/24 11:24:23.921] DEBUG[75878] res_pjsip/pjsip_options.c: Could not find an endpoint to qualify contact 'Infinity@@8e1a5218ecc9a4f261aa2bbb88fd04e1' on AOR 'Infinity' [11/24 11:24:30.425] DEBUG[75925] manager.c: Running action 'AGI' [11/24 11:24:30.434] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 CommandId: 1335085906 Command: EXEC Record /var/lib/asterisk/sounds/vox_rec/IS/62087d78-4d4b-11ec-a69f-00155d8e0186.ulaw,5,60,ktxy [11/24 11:24:30.434] DEBUG[76059][C-00000008] channel.c: Channel Local/5678@IS-00000005;1 setting write format path: ulaw -> slin [11/24 11:24:30.434] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Variable: RECORDED_FILE Value: /var/lib/asterisk/sounds/vox_rec/IS/62087d78-4d4b-11ec-a69f-00155d8e0186 [11/24 11:24:30.434] DEBUG[76059][C-00000008] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [11/24 11:24:30.854] DEBUG[76059][C-00000008] channel.c: Scheduling timer at (182 requested / 182 actual) timer ticks per second [11/24 11:24:30.860] DEBUG[76059][C-00000008] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [11/24 11:24:30.860] DEBUG[76059][C-00000008] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [11/24 11:24:30.860] DEBUG[76059][C-00000008] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [11/24 11:24:30.860] DEBUG[76059][C-00000008] channel.c: Channel Local/5678@IS-00000005;1 setting write format path: slin -> slin [11/24 11:24:30.860] DEBUG[76059][C-00000008] channel.c: Channel Local/5678@IS-00000005;1 setting read format path: slin -> slin [11/24 11:24:30.860] DEBUG[76059][C-00000008] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [11/24 11:24:30.860] DEBUG[76059][C-00000008] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [11/24 11:24:32.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:32.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:34.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:34.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:35.914] DEBUG[76059][C-00000008] channel.c: Channel Local/5678@IS-00000005;1 setting read format path: slin -> slin [11/24 11:24:35.914] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Variable: RECORD_STATUS Value: SILENCE [11/24 11:24:35.914] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 CommandId: 1335085906 Command: EXEC Record /var/lib/asterisk/sounds/vox_rec/IS/62087d78-4d4b-11ec-a69f-00155d8e0186.ulaw,5,60,ktxy ResultCode: 200 Result: Success [11/24 11:24:35.914] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Result: 200%20result%3D0%0A CommandId: C60 [11/24 11:24:36.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:36.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:38.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:38.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:40.489] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32825 (rdata0x7f7f4c02a558) [11/24 11:24:40.489] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32825 (rdata0x7f7f4c02a558) [11/24 11:24:40.490] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.490] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.490] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:24:40.490] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:24:40.490] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:24:40.490] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:24:40.490] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:24:40.490] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:24:40.490] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.490] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.490] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.490] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.490] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: NOAUTH [11/24 11:24:40.490] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.490] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.490] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.490] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.496] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32826 (rdata0x7f7f4c02a558) [11/24 11:24:40.496] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32826 (rdata0x7f7f4c02a558) [11/24 11:24:40.496] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.496] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:24:40.496] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:24:40.496] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.496] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.496] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.496] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.496] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774680/2f8f08912d5542a9b8041536e9a402e9. Actual nonce is 1637774680/2f8f08912d5542a9b8041536e9a402e9 [11/24 11:24:40.496] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:40.496] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.496] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.496] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.496] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.500] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574621 (rdata0x7f7f4c02a558) [11/24 11:24:40.500] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574621 (rdata0x7f7f4c02a558) [11/24 11:24:40.500] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.500] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.500] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:24:40.500] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:24:40.500] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:24:40.500] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:24:40.500] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:24:40.500] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:24:40.500] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.500] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.500] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.500] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.500] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: NOAUTH [11/24 11:24:40.500] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.500] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.500] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.500] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.503] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574622 (rdata0x7f7f4c02a558) [11/24 11:24:40.503] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574622 (rdata0x7f7f4c02a558) [11/24 11:24:40.503] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.503] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:24:40.503] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:24:40.503] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.503] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.503] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.503] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:40.503] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774680/2f8f08912d5542a9b8041536e9a402e9. Actual nonce is 1637774680/2f8f08912d5542a9b8041536e9a402e9 [11/24 11:24:40.503] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:40.503] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:40.503] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:40.503] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:40.503] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.507] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32827 (rdata0x7f7f4c02a558) [11/24 11:24:41.507] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32827 (rdata0x7f7f4c02a558) [11/24 11:24:41.507] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.507] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:24:41.507] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:24:41.508] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:24:41.508] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.508] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.508] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.508] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.508] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774680/2f8f08912d5542a9b8041536e9a402e9. Actual nonce is 1637774680/2f8f08912d5542a9b8041536e9a402e9 [11/24 11:24:41.508] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:41.508] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.508] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.508] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.508] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.510] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32828 (rdata0x7f7f4c02a558) [11/24 11:24:41.510] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32828 (rdata0x7f7f4c02a558) [11/24 11:24:41.510] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.510] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:24:41.510] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:24:41.510] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.510] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.510] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.510] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.510] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774681/a7f6587080f2a8eb7b7ceebe7413439e. Actual nonce is 1637774681/a7f6587080f2a8eb7b7ceebe7413439e [11/24 11:24:41.510] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:41.510] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.510] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.510] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.510] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.513] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574623 (rdata0x7f7f4c02a558) [11/24 11:24:41.513] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574623 (rdata0x7f7f4c02a558) [11/24 11:24:41.514] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.514] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:24:41.514] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:24:41.514] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.514] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.514] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.514] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.514] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774680/2f8f08912d5542a9b8041536e9a402e9. Actual nonce is 1637774680/2f8f08912d5542a9b8041536e9a402e9 [11/24 11:24:41.514] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:41.514] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.514] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.514] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.514] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.517] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574624 (rdata0x7f7f4c02a558) [11/24 11:24:41.517] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574624 (rdata0x7f7f4c02a558) [11/24 11:24:41.517] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.517] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:24:41.517] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:24:41.517] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.517] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.517] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.517] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:41.517] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774681/a7f6587080f2a8eb7b7ceebe7413439e. Actual nonce is 1637774681/a7f6587080f2a8eb7b7ceebe7413439e [11/24 11:24:41.517] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:24:41.517] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:41.517] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:41.517] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:24:41.517] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:24:42.015] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.015] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.083] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.083] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.134] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:24:42.134] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:24:42.174] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.228] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.228] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:42.353] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:42.353] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:42.443] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:42.443] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [11/24 11:24:42.572] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:42.572] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:42.717] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:42.717] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:42.860] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:42.860] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:42.954] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:42.954] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.074] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:43.074] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.174] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:43.174] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.274] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.274] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.395] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:43.395] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:43.498] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.498] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.607] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.607] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.761] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:24:43.761] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:24:43.863] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.863] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.967] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:43.967] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:44.071] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:44.071] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:44.222] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:24:44.222] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:24:44.426] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:44.426] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:44.479] DEBUG[75889] res_pjsip_registrar.c: Woke up at 1637774684 Interval: 30 [11/24 11:24:44.479] DEBUG[75889] res_pjsip_registrar.c: Expiring 0 contacts [11/24 11:24:44.626] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:44.626] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:44.874] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 13 instead [11/24 11:24:44.874] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 13 instead [11/24 11:24:45.074] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:45.074] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 9 instead [11/24 11:24:45.274] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 11 instead [11/24 11:24:45.274] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:45.474] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:45.474] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 9 instead [11/24 11:24:45.722] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 13 instead [11/24 11:24:45.722] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 12 instead [11/24 11:24:45.922] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:45.922] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.122] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.122] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.322] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.322] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.522] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.522] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.770] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 12 instead [11/24 11:24:46.770] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 12 instead [11/24 11:24:46.870] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=101 (rdata0x7f7f4c02a558) [11/24 11:24:46.870] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004f to use for Request msg OPTIONS/cseq=101 (rdata0x7f7f4c02a558) [11/24 11:24:46.970] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:46.970] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:47.171] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:47.172] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:47.270] DEBUG[75878] netsock2.c: Splitting '192.168.40.60' into... [11/24 11:24:47.270] DEBUG[75878] netsock2.c: ...host '192.168.40.60' and port ''. [11/24 11:24:47.270] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify21' [11/24 11:24:47.270] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify23' [11/24 11:24:47.270] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify18' [11/24 11:24:47.270] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.40.60:5060 does not match identify 'identify22' [11/24 11:24:47.270] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '' domain '192.168.40.60' [11/24 11:24:47.270] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '' domain '192.168.40.60' [11/24 11:24:47.270] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:47.270] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:47.270] DEBUG[75878] netsock2.c: Splitting '192.168.40.60' into... [11/24 11:24:47.270] DEBUG[75878] netsock2.c: ...host '192.168.40.60' and port ''. [11/24 11:24:47.270] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: NOAUTH [11/24 11:24:47.270] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:24:47.270] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:24:47.270] DEBUG[75878] netsock2.c: Splitting '192.168.40.60' into... [11/24 11:24:47.270] DEBUG[75878] netsock2.c: ...host '192.168.40.60' and port ''. [11/24 11:24:47.374] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 11 instead [11/24 11:24:47.374] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 11 instead [11/24 11:24:47.576] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:47.576] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:47.712] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:47.825] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 12 instead [11/24 11:24:48.007] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 9 instead [11/24 11:24:48.115] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:48.216] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:48.336] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:48.538] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 10 instead [11/24 11:24:48.712] DEBUG[75925] manager.c: Running action 'Hangup' [11/24 11:24:48.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:48.765] DEBUG[75925] channel.c: Soft-Hanging (0x20) up channel 'Local/5678@IS-00000005;1' [11/24 11:24:48.768] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 11 instead [11/24 11:24:48.871] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:48.976] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:24:49.075] DEBUG[76059][C-00000008] res_agi.c: No frame read on channel Local/5678@IS-00000005;1, going out ... [11/24 11:24:49.075] DEBUG[76059][C-00000008] pbx.c: Spawn extension (IS,createcall,7) exited non-zero on 'Local/5678@IS-00000005;1' [11/24 11:24:49.075] DEBUG[76059][C-00000008] channel.c: Soft-Hanging (0x10) up channel 'Local/5678@IS-00000005;1' [11/24 11:24:49.075] DEBUG[76059][C-00000008] channel.c: Channel 0x7f7f3c007170 'Local/5678@IS-00000005;1' hanging up. Refs: 2 [11/24 11:24:49.075] DEBUG[76059][C-00000008] channel.c: Channel 0x7f7f3c007170 'Local/5678@IS-00000005;1' destroying [11/24 11:24:49.075] DEBUG[76059][C-00000008] stasis.c: Destroying topic. name: channel:1637774600.10, detail: [11/24 11:24:49.075] DEBUG[76059][C-00000008] stasis.c: Topic 'channel:1637774600.10': 0x7f7f3c008d20 destroyed [11/24 11:24:49.075] DEBUG[76059][C-00000008] channel_internal_api.c: : MultistreamFormats: (nothing) [11/24 11:24:49.075] DEBUG[76059][C-00000008] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:24:49.075] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for Local - 5678@IS [11/24 11:24:49.075] DEBUG[75859] devicestate.c: Changing state for Local/5678@IS - state 1 (Not in use) [11/24 11:24:49.075] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIEnd Privilege: agi,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 [11/24 11:24:49.076] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Variable: AGISTATUS Value: HANGUP [11/24 11:24:49.076] DEBUG[75925] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Cause: 16 [11/24 11:24:49.076] DEBUG[75925] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Cause: 0 [11/24 11:24:49.076] DEBUG[75925] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: Local/5678@IS-00000005;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: createcall Priority: 7 Uniqueid: 1637774600.10 Linkedid: 1637774600.10 Cause: 0 Cause-txt: Unknown [11/24 11:24:49.076] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.175] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/5678@IS State: NOT_INUSE [11/24 11:24:49.176] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.277] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.378] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.476] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.575] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:49.723] DEBUG[76060][C-00000007] bridge_channel.c: Setting 0x7f7f4400c0c0(Local/5678@IS-00000005;2) state from:0 to:1 [11/24 11:24:49.723] DEBUG[76060][C-00000007] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: pulling 0x7f7f4400c0c0(Local/5678@IS-00000005;2) [11/24 11:24:49.723] DEBUG[76060][C-00000007] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x7f7f4400c0c0(Local/5678@IS-00000005;2) is leaving softmix technology [11/24 11:24:49.723] DEBUG[76060][C-00000007] stasis_bridges.c: Update: 0x7f7f4401b5f8 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:24:49.723] DEBUG[76060][C-00000007] stasis_bridges.c: Update: 0x7f7f4400d438 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:24:49.723] DEBUG[76060][C-00000007] confbridge/conf_state.c: Changing conference 'IS__B' state from MULTI to SINGLE [11/24 11:24:49.723] DEBUG[76060][C-00000007] app_confbridge.c: User Local/1234@IS-00000004;2 is unmuted: user:0 system:0. [11/24 11:24:49.723] DEBUG[76060][C-00000007] res_agi.c: No frame read on channel Local/5678@IS-00000005;2, going out ... [11/24 11:24:49.723] DEBUG[76060][C-00000007] pbx.c: Spawn extension (IS,5678,17) exited non-zero on 'Local/5678@IS-00000005;2' [11/24 11:24:49.723] DEBUG[76060][C-00000007] channel.c: Soft-Hanging (0x10) up channel 'Local/5678@IS-00000005;2' [11/24 11:24:49.723] DEBUG[76060][C-00000007] channel.c: Channel 0x7f7f3c00b960 'Local/5678@IS-00000005;2' hanging up. Refs: 2 [11/24 11:24:49.723] DEBUG[76060][C-00000007] channel.c: Channel 0x7f7f3c00b960 'Local/5678@IS-00000005;2' destroying [11/24 11:24:49.723] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f4401b5f8 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:24:49.723] DEBUG[76060][C-00000007] stasis.c: Destroying topic. name: channel:1637774600.11, detail: [11/24 11:24:49.723] DEBUG[76060][C-00000007] stasis.c: Topic 'channel:1637774600.11': 0x7f7f3c0084c0 destroyed [11/24 11:24:49.723] DEBUG[76060][C-00000007] channel_internal_api.c: : MultistreamFormats: (nothing) [11/24 11:24:49.723] DEBUG[76060][C-00000007] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:24:49.723] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f4400d438 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Variable: BRIDGEPEER Value: [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: BRIDGEPEER Value: CBAnn/IS__B-00000007;2 [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Variable: CONFBRIDGE_RESULT Value: HANGUP [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 CommandId: 1834899773 Command: EXEC ConfBridge IS__B ResultCode: 200 Result: Success [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Result: 200%20result%3D0%0A CommandId: C59 [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIEnd Privilege: agi,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Variable: AGISTATUS Value: HANGUP [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Cause: 16 [11/24 11:24:49.724] DEBUG[75925] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Cause: 16 Cause-txt: Normal Clearing [11/24 11:24:49.724] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for Local - 5678@IS [11/24 11:24:49.724] DEBUG[75859] core_local.c: Checking if extension 5678@IS exists (devicestate) [11/24 11:24:49.724] DEBUG[75859] devicestate.c: Changing state for Local/5678@IS - state 1 (Not in use) [11/24 11:24:49.725] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:49.823] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeLeave Privilege: call,all Conference: IS__B BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 3 BridgeVideoSourceMode: none Channel: Local/5678@IS-00000005;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2 CallerIDName: LocalB ConnectedLineNum: 2 ConnectedLineName: LocalB Language: en AccountCode: Context: IS Exten: 5678 Priority: 17 Uniqueid: 1637774600.11 Linkedid: 1637774600.10 Admin: No [11/24 11:24:49.823] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/5678@IS State: NOT_INUSE [11/24 11:24:49.823] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:49.924] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.023] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.124] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.223] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.324] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.423] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.523] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.623] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:50.771] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:50.871] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:50.971] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.071] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.171] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.271] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.371] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.471] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.571] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:51.719] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:24:51.819] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:51.919] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.019] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.119] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.219] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.319] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.419] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.519] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.619] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:52.767] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:24:52.867] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:52.967] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:53.067] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:53.167] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:53.267] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:24:53.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:53.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:54.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:54.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:55.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:55.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:56.712] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:56.712] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:57.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:57.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:58.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:24:58.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:59.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:24:59.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:00.119] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:00.119] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:00.219] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:00.219] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.219] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.319] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.319] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.319] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:00.419] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:00.419] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.419] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.519] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.519] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.519] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:00.619] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:00.619] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.619] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.767] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:25:00.767] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:25:00.767] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [11/24 11:25:00.867] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.867] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.867] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:00.967] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.967] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:00.967] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.067] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.067] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.067] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.096] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.096] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.167] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.167] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.167] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.267] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.267] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.267] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.307] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.307] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.367] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.367] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.367] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.467] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.467] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.467] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:01.567] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.567] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.567] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.715] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:25:01.715] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:25:01.715] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.815] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:01.815] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.815] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.915] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.915] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:01.915] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:02.015] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:02.015] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.015] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.115] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.115] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.115] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:02.215] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:02.215] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.215] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.315] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.315] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.315] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:02.415] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:02.415] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.415] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.515] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.515] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.515] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:02.615] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:02.615] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32829 (rdata0x7f7f4c02a558) [11/24 11:25:02.615] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32829 (rdata0x7f7f4c02a558) [11/24 11:25:02.615] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.615] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.616] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.616] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.616] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:25:02.616] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:25:02.616] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:25:02.616] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:25:02.616] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:25:02.617] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:25:02.617] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:25:02.617] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:25:02.617] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.617] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.617] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.617] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.617] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774681/a7f6587080f2a8eb7b7ceebe7413439e. Actual nonce is 1637774681/a7f6587080f2a8eb7b7ceebe7413439e [11/24 11:25:02.617] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:25:02.617] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.617] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.617] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.617] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.763] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=32830 (rdata0x7f7f4c02a558) [11/24 11:25:02.763] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004c to use for Request msg REGISTER/cseq=32830 (rdata0x7f7f4c02a558) [11/24 11:25:02.763] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:25:02.763] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:25:02.763] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:02.765] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.765] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify21' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify23' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify18' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5060 does not match identify 'identify22' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '8001' domain '192.168.33.33' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '8001' domain '192.168.33.33' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '8001' realm 'asterisk' [11/24 11:25:02.765] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '8001' realm 'asterisk' [11/24 11:25:02.765] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.765] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.765] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.765] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.765] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774702/0d7cd3376ea1471261fd72ae49990363. Actual nonce is 1637774702/0d7cd3376ea1471261fd72ae49990363 [11/24 11:25:02.765] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:25:02.765] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.765] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.765] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.765] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.863] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:02.863] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574625 (rdata0x7f7f4c02a558) [11/24 11:25:02.863] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574625 (rdata0x7f7f4c02a558) [11/24 11:25:02.863] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.863] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.864] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.864] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:25:02.864] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:25:02.864] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.864] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.864] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.864] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.865] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774681/a7f6587080f2a8eb7b7ceebe7413439e. Actual nonce is 1637774681/a7f6587080f2a8eb7b7ceebe7413439e [11/24 11:25:02.865] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:25:02.865] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.865] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.865] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.865] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.964] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=574626 (rdata0x7f7f4c02a558) [11/24 11:25:02.964] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=574626 (rdata0x7f7f4c02a558) [11/24 11:25:02.964] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.964] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:02.964] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:02.965] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.965] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify21' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify23' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify18' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.32.77:5068 does not match identify 'identify22' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '7292' domain '192.168.33.33' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username '7292' domain '192.168.33.33' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Attempting identify by Authorization username '7292' realm 'asterisk' [11/24 11:25:02.965] DEBUG[75878] res_pjsip_endpoint_identifier_user.c: Endpoint not found for Authentication username '7292' realm 'asterisk' [11/24 11:25:02.965] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.965] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.965] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.965] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:02.965] DEBUG[75878] res_pjsip_authenticator_digest.c: Calculated nonce 1637774702/0d7cd3376ea1471261fd72ae49990363. Actual nonce is 1637774702/0d7cd3376ea1471261fd72ae49990363 [11/24 11:25:02.965] DEBUG[75878] res_pjsip_authenticator_digest.c: Realm: asterisk Username: Result: FAIL [11/24 11:25:02.965] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:02.965] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:02.965] DEBUG[75878] netsock2.c: Splitting '192.168.32.77' into... [11/24 11:25:02.965] DEBUG[75878] netsock2.c: ...host '192.168.32.77' and port ''. [11/24 11:25:03.062] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.062] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.063] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:03.163] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.163] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.163] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:03.263] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:03.263] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.263] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.363] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.363] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.363] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:03.463] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:03.463] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.463] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.563] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.563] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.563] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:03.713] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [11/24 11:25:03.713] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:25:03.713] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 7 instead [11/24 11:25:03.811] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.811] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.811] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:03.911] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.911] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:03.911] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:04.011] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.011] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.011] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:04.111] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.111] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.111] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:04.211] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.211] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.211] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:04.311] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.311] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.311] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:04.411] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.411] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.411] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:04.511] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.511] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.511] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:04.611] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.611] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.611] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:04.759] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:25:04.759] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 8 instead [11/24 11:25:04.759] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:04.859] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:04.859] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.859] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.959] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.959] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:04.959] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:05.059] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:05.059] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.059] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.159] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.159] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.159] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:05.169] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR '192.168.33.33' [11/24 11:25:05.169] DEBUG[75878] res_pjsip/pjsip_options.c: Qualifying contact '192.168.33.33@@6609419e0fb101bed05785d07e4292dc' on AOR '192.168.33.33' [11/24 11:25:05.169] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Wrapper created [11/24 11:25:05.169] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Set timer to 3000 msec [11/24 11:25:05.169] DEBUG[75878] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.33.33' [11/24 11:25:05.169] DEBUG[75878] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.33.33' is 'UDP transport' [11/24 11:25:05.169] DEBUG[75878] res_pjsip/pjsip_resolver.c: Target '192.168.33.33' is an IP address, skipping resolution [11/24 11:25:05.169] DEBUG[75878] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.33.33:5060 (this may be re-written again later) [11/24 11:25:05.259] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:05.259] DEBUG[75877] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=41380 (rdata0x7f7f4c02a558) [11/24 11:25:05.259] DEBUG[75877] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000004a to use for Request msg OPTIONS/cseq=41380 (rdata0x7f7f4c02a558) [11/24 11:25:05.259] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.259] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.261] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:05.261] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:05.261] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.33.33:5060 does not match identify 'identify21' [11/24 11:25:05.261] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.33.33:5060 matches identify 'identify23' [11/24 11:25:05.261] DEBUG[75878] res_pjsip_endpoint_identifier_ip.c: Identify 'identify23' SIP message matched to endpoint 192.168.33.33 [11/24 11:25:05.261] DEBUG[75878] netsock2.c: Splitting '192.168.33.33' into... [11/24 11:25:05.261] DEBUG[75878] netsock2.c: ...host '192.168.33.33' and port ''. [11/24 11:25:05.359] DEBUG[75877] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=41380 (rdata0x7f7f4c02a558). Using request transaction as basis. [11/24 11:25:05.359] DEBUG[75877] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7f7f34032498 for Response msg 200/OPTIONS/cseq=41380 (rdata0x7f7f4c02a558). [11/24 11:25:05.359] DEBUG[75877] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/192.168.33.33-00000067 on transaction tsx0x7f7f34032498 [11/24 11:25:05.359] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.359] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.359] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:05.361] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: PJSIP tsx response received [11/24 11:25:05.361] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Cancelling timer [11/24 11:25:05.361] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Timer cancelled [11/24 11:25:05.361] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: Callbacks executed [11/24 11:25:05.361] DEBUG[75878] res_pjsip.c: 0x7f7f3401b290: wrapper destroyed [11/24 11:25:05.361] DEBUG[75878] res_pjsip/pjsip_options.c: Contact 192.168.33.33/sip:192.168.33.33 status didn't change: Reachable, RTT: 192.105 msec [11/24 11:25:05.361] DEBUG[75878] res_pjsip/pjsip_options.c: AOR '192.168.33.33' now has 1 available contacts [11/24 11:25:05.459] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:05.459] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.459] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.559] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.559] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.559] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [11/24 11:25:05.659] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:05.659] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.659] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [11/24 11:25:05.781] DEBUG[75925] manager.c: Running action 'ConfbridgeKick' [11/24 11:25:05.781] DEBUG[75925] bridge.c: Removing channel Local/1234@IS-00000004;2 from bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.781] DEBUG[75925] bridge_channel.c: Setting 0x562cfdaca0a0(Local/1234@IS-00000004;2) state from:0 to:2 [11/24 11:25:05.781] DEBUG[76061] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:25:05.781] DEBUG[76064] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [11/24 11:25:05.781] DEBUG[75951] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [11/24 11:25:05.781] DEBUG[76057][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: pulling 0x562cfdaca0a0(Local/1234@IS-00000004;2) [11/24 11:25:05.781] DEBUG[76057][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x562cfdaca0a0(Local/1234@IS-00000004;2) is leaving softmix technology [11/24 11:25:05.781] DEBUG[76057][C-00000005] stasis_bridges.c: Update: 0x562cfd58b998 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.781] DEBUG[76057][C-00000005] stasis_bridges.c: Update: 0x562cfdaa1d78 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.781] DEBUG[76057][C-00000005] confbridge/conf_state.c: Changing conference 'IS__B' state from SINGLE to EMPTY [11/24 11:25:05.781] DEBUG[76057][C-00000005] app_confbridge.c: Destroying conference bridge 'IS__B' [11/24 11:25:05.782] DEBUG[75871] stasis_bridges.c: Update: 0x562cfd58b998 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.782] DEBUG[75871] stasis_bridges.c: Update: 0x562cfdaa1d78 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.782] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeLeave Privilege: call,all Conference: IS__B BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Admin: No [11/24 11:25:05.782] DEBUG[75925] manager.c: Examining AMI event: Event: ConfbridgeEnd Privilege: call,all Conference: IS__B BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 1 BridgeVideoSourceMode: none [11/24 11:25:05.782] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: CONFBRIDGE_RESULT Value: KICKED [11/24 11:25:05.782] DEBUG[75925] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Variable: BRIDGEPEER Value: [11/24 11:25:05.782] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 [11/24 11:25:05.782] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: confbridge:IS__B State: NOT_INUSE [11/24 11:25:05.798] DEBUG[76065] channel.c: Channel 0x562cfdabf290 'CBAnn/IS__B-00000007;1' hanging up. Refs: 2 [11/24 11:25:05.798] DEBUG[76065] channel.c: Channel 0x562cfdabf290 'CBAnn/IS__B-00000007;1' destroying [11/24 11:25:05.801] DEBUG[76065] stasis.c: Destroying topic. name: channel:1637774624.14, detail: [11/24 11:25:05.801] DEBUG[76065] stasis.c: Topic 'channel:1637774624.14': 0x562cfd73a3a0 destroyed [11/24 11:25:05.801] DEBUG[76065] channel_internal_api.c: : Formats: (nothing) [11/24 11:25:05.801] DEBUG[76065] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:25:05.802] DEBUG[76066][C-00000005] bridge_channel.c: Setting 0x562cfdab5e00(CBAnn/IS__B-00000007;2) state from:0 to:1 [11/24 11:25:05.802] DEBUG[76066][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: pulling 0x562cfdab5e00(CBAnn/IS__B-00000007;2) [11/24 11:25:05.802] DEBUG[76066][C-00000005] bridge_channel.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: 0x562cfdab5e00(CBAnn/IS__B-00000007;2) is leaving softmix technology [11/24 11:25:05.802] DEBUG[76066][C-00000005] stasis_bridges.c: Update: 0x7f7f5400db08 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.802] DEBUG[76066][C-00000005] stasis_bridges.c: Update: 0x7f7f54007888 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.802] DEBUG[76066][C-00000005] channel.c: Channel 0x562cfd753310 'CBAnn/IS__B-00000007;2' hanging up. Refs: 2 [11/24 11:25:05.802] DEBUG[76066][C-00000005] channel.c: Channel 0x562cfd753310 'CBAnn/IS__B-00000007;2' destroying [11/24 11:25:05.802] DEBUG[76066][C-00000005] stasis.c: Destroying topic. name: channel:1637774624.15, detail: [11/24 11:25:05.802] DEBUG[76066][C-00000005] stasis.c: Topic 'channel:1637774624.15': 0x562cfd7a6f60 destroyed [11/24 11:25:05.802] DEBUG[76066][C-00000005] channel_internal_api.c: : Formats: (nothing) [11/24 11:25:05.802] DEBUG[76066][C-00000005] channel_internal_api.c: Channel is being initialized or destroyed [11/24 11:25:05.802] DEBUG[76057][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: telling all channels to leave the party [11/24 11:25:05.802] DEBUG[76057][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: dissolving bridge with cause 16(Normal Clearing) [11/24 11:25:05.802] DEBUG[76057][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: queueing action type:13 sub:1001 [11/24 11:25:05.802] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f5400db08 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.802] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f54007888 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: a4db2896-a3fa-4984-92a3-2a07f2cf2879 [11/24 11:25:05.802] DEBUG[75925] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 CommandId: 761104300 Command: EXEC ConfBridge IS__B ResultCode: 200 Result: Success [11/24 11:25:05.802] DEBUG[75925] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all Channel: Local/1234@IS-00000004;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1 CallerIDName: LocalA ConnectedLineNum: 1 ConnectedLineName: LocalA Language: en AccountCode: Context: IS Exten: 1234 Priority: 17 Uniqueid: 1637774585.9 Linkedid: 1637774585.8 Result: 200%20result%3D0%0A CommandId: C55 [11/24 11:25:05.802] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for CBAnn - IS__B [11/24 11:25:05.802] DEBUG[75858][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: actually destroying base bridge, nobody wants it anymore [11/24 11:25:05.802] DEBUG[75858][C-00000005] stasis_bridges.c: Update: 0x7f7f3c005e28 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: [11/24 11:25:05.802] DEBUG[75858][C-00000005] stasis.c: Destroying topic. name: bridge:all/bridge:a4db2896-a3fa-4984-92a3-2a07f2cf2879, detail: [11/24 11:25:05.802] DEBUG[75858][C-00000005] stasis.c: Topic 'bridge:all/bridge:a4db2896-a3fa-4984-92a3-2a07f2cf2879': 0x562cfdac8e90 destroyed [11/24 11:25:05.802] DEBUG[75858][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: calling base bridge destructor [11/24 11:25:05.802] DEBUG[75858][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: calling softmix technology stop [11/24 11:25:05.802] DEBUG[75858][C-00000005] bridge.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: calling softmix technology destructor [11/24 11:25:05.802] DEBUG[75858][C-00000005] bridge_softmix.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: Waiting for mixing thread to die. [11/24 11:25:05.802] DEBUG[75871] stasis_bridges.c: Update: 0x7f7f3c005e28 Old: a4db2896-a3fa-4984-92a3-2a07f2cf2879 New: [11/24 11:25:05.802] DEBUG[76064] bridge_softmix.c: Bridge a4db2896-a3fa-4984-92a3-2a07f2cf2879: stopping mixing thread [11/24 11:25:05.802] DEBUG[75925] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: a4db2896-a3fa-4984-92a3-2a07f2cf2879 BridgeType: base BridgeTechnology: softmix BridgeCreator: ConfBridge BridgeName: IS__B BridgeNumChannels: 0 BridgeVideoSourceMode: none [11/24 11:25:05.839] DEBUG[75859] devicestate.c: Changing state for CBAnn/IS__B - state 0 (Unknown) [11/24 11:25:05.839] DEBUG[75859] devicestate.c: No provider found, checking channel drivers for CBAnn - IS__B [11/24 11:25:05.839] DEBUG[75859] devicestate.c: Changing state for CBAnn/IS__B - state 0 (Unknown) [11/24 11:25:05.839] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: CBAnn/IS__B State: UNKNOWN [11/24 11:25:05.839] DEBUG[75925] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: CBAnn/IS__B State: UNKNOWN [11/24 11:25:14.480] DEBUG[75889] res_pjsip_registrar.c: Woke up at 1637774714 Interval: 30 [11/24 11:25:14.480] DEBUG[75889] res_pjsip_registrar.c: Expiring 0 contacts