Do you see anything wrong in the following trace ? Although I muted my microphone, AMI catches Confbridge Talking On event …
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: Newchannel
Event: Newchannel
Privilege: call,all
Channel: Bridge/0x7f4c34011d98-input
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context:
Uniqueid: 1528445670.2
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: Newchannel
Privilege: call,all
Channel: Bridge/0x7f4c34011d98-input
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context:
Uniqueid: 1528445670.2
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: CEL
Privilege: call,all
EventName: CHAN_START
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-input
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.2
LinkedID: 1528445670.2
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: Newchannel
Event: Newchannel
Privilege: call,all
Channel: Bridge/0x7f4c34011d98-output
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context:
Uniqueid: 1528445670.3
[Jun 8 11:14:30] DEBUG[2100]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: CEL
Event: CEL
Privilege: call,all
EventName: CHAN_START
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-input
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.2
LinkedID: 1528445670.2
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[2100]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: CEL
Event: CEL
Privilege: call,all
EventName: CHAN_START
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-output
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.3
LinkedID: 1528445670.3
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[2100]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: CEL
Event: CEL
Privilege: call,all
EventName: ANSWER
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-output
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.3
LinkedID: 1528445670.3
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[2100]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: CEL
Event: CEL
Privilege: call,all
EventName: ANSWER
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-input
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.2
LinkedID: 1528445670.2
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: app_confbridge.c:1355 alloc_playback_chan: Created a playback channel to conference bridge '4444'
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: Newchannel
Privilege: call,all
Channel: Bridge/0x7f4c34011d98-output
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context:
Uniqueid: 1528445670.3
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: CEL
Privilege: call,all
EventName: CHAN_START
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-output
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.3
LinkedID: 1528445670.3
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: CEL
Privilege: call,all
EventName: ANSWER
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-output
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.3
LinkedID: 1528445670.3
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: CEL
Privilege: call,all
EventName: ANSWER
AccountCode:
CallerIDnum:
CallerIDname:
CallerIDani:
CallerIDrdnis:
CallerIDdnid:
Exten: s
Context: default
Channel: Bridge/0x7f4c34011d98-input
Application:
AppData:
EventTime: 2018-06-08 11:14:30
AMAFlags: DOCUMENTATION
UniqueID: 1528445670.2
LinkedID: 1528445670.2
Userfield:
Peer:
PeerAccount:
Extra:
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:3604 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
-- <Bridge/0x7f4c34011d98-input> Playing 'confbridge-join.slin' (language 'en')
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:940 bridge_channel_join: Joining bridge channel 0x7f4c34001ac8 to bridge 0x7f4c340045f8
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:162 bridge_array_add: Added channel Bridge/0x7f4c34011d98-output(0x7f4c3402d7a8) to bridge array on 0x7f4c340045f8, new count is 2
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:592 bridge_make_compatible: Bridge 0x7f4c340045f8 is happy that channel Bridge/0x7f4c34011d98-output already has read format slin
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:613 bridge_make_compatible: Bridge 0x7f4c340045f8 is happy that channel Bridge/0x7f4c34011d98-output already has write format slin
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:979 bridge_channel_join: Giving bridge technology softmix notification that 0x7f4c34001ac8 is joining bridge 0x7f4c340045f8
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridge_softmix.c:388 softmix_bridge_join: softmix_bridge_join
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridge_softmix.c:342 set_softmix_bridge_data: set_softmix_bridge_data
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: dsp.c:482 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: dsp.c:482 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridge_softmix.c:378 set_softmix_bridge_data: set_softmix_bridge_data, dsp talking thresholSSSs is set to 160
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=0
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:586 softmix_bridge_write: softmix_bridge_write:: ast_bridge_notify_talking CALLED, update_talking=1 !!!
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] DEBUG[2137]: chan_sip.c:3874 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.1.90.52:5060
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=0,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=20,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=40,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=60,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=80,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] DEBUG[2137]: chan_sip.c:3874 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.1.10.59:5060
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=100,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:3604 ast_settimeout: Scheduling timer at (174 requested / 174 actual) timer ticks per second
[Jun 8 11:14:30] WARNING[4423][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=105,silence_threshold=2500, sc->talking=-1
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:3604 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:3604 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:3604 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: app_confbridge.c:1391 play_sound_helper: Departing underlying channel 'Bridge/0x7f4c34011d98-output' from bridge '0x7f4c340045f8'
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:1036 bridge_channel_join: Giving bridge technology softmix notification that 0x7f4c34001ac8 is leaving bridge 0x7f4c340045f8
[Jun 8 11:14:30] DEBUG[4423][C-00000000]: bridging.c:198 bridge_array_remove: Removed channel 0x7f4c3402d7a8 from bridge array on 0x7f4c340045f8, new count is 1
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: ConfbridgeJoin
Event: ConfbridgeJoin
Privilege: call,all
Channel: SIP/4502-00000000
Uniqueid: 1528445666.0
Conference: 4444
CallerIDnum: 4502
CallerIDname: didem
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:940 bridge_channel_join: Joining bridge channel 0x7f4c34029d68 to bridge 0x7f4c340045f8
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:162 bridge_array_add: Added channel SIP/4502-00000000(0x7f4c4402a838) to bridge array on 0x7f4c340045f8, new count is 2
[Jun 8 11:14:30] DEBUG[2111]: manager.c:4787 match_filter: Examining event:
Event: ConfbridgeJoin
Privilege: call,all
Channel: SIP/4502-00000000
Uniqueid: 1528445666.0
Conference: 4444
CallerIDnum: 4502
CallerIDname: didem
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:583 bridge_make_compatible: Bridge technology softmix wants to read any of formats (slin) but channel has ulaw
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:5388 set_format: Set channel SIP/4502-00000000 to read format slin
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:590 bridge_make_compatible: Bridge 0x7f4c340045f8 put channel SIP/4502-00000000 into read format slin
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:604 bridge_make_compatible: Bridge technology softmix wants to write any of formats (slin) but channel has ulaw
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: channel.c:5388 set_format: Set channel SIP/4502-00000000 to write format slin
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:611 bridge_make_compatible: Bridge 0x7f4c340045f8 put channel SIP/4502-00000000 into write format slin
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridging.c:979 bridge_channel_join: Giving bridge technology softmix notification that 0x7f4c34029d68 is joining bridge 0x7f4c340045f8
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridge_softmix.c:388 softmix_bridge_join: softmix_bridge_join
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridge_softmix.c:342 set_softmix_bridge_data: set_softmix_bridge_data
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: dsp.c:482 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: dsp.c:482 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: bridge_softmix.c:375 set_softmix_bridge_data: set_softmix_bridge_data, dsp talking threshold is set to 5000
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: res_rtp_asterisk.c:2465 ast_rtp_raw_write: Difference is 2880, ms is 380
[Jun 8 11:14:30] DEBUG[2111]: manager.c:5206 process_message: Running action 'Monitor'
[Jun 8 11:14:30] DEBUG[2111]: res_monitor.c:402 ast_monitor_start: Cannot start monitoring SIP/4502-00000000, already monitored
[Jun 8 11:14:30] DEBUG[2111]: res_monitor.c:603 ast_monitor_change_fname: comparing tmpstring /var/spool/asterisk/monitor/20180608111/20180608111426.0 to filename_base /var/spool/asterisk/monitor/20180608111/20180608111426.0
[Jun 8 11:14:30] DEBUG[2111]: res_monitor.c:610 ast_monitor_change_fname: No need to rename monitor filename to itself
[Jun 8 11:14:30] WARNING[4369][C-00000000]: bridge_softmix.c:549 softmix_bridge_write: totalsilence=20,silence_threshold=5000, sc->talking=0
[Jun 8 11:14:30] WARNING[4369][C-00000000]: bridge_softmix.c:586 softmix_bridge_write: softmix_bridge_write:: ast_bridge_notify_talking CALLED, update_talking=1 !!!
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: app_confbridge.c:1426 conf_handle_talker_cb: app_confbridge::conf_handle_talker_cb
[Jun 8 11:14:30] WARNING[4369][C-00000000]:app_confbridge.c:1457 conf_handle_talker_cb: app_confbridge::conf_handle_talker_cb, ConfbridgeTalking EVENT WAS TRIGGERED! Talking = on
[Jun 8 11:14:30] DEBUG[4369][C-00000000]: res_recording.c:2782 amihook_helper: AMI Event:
Category: 2 Event: ConfbridgeTalking
Event: ConfbridgeTalking
Privilege: call,all
Channel: SIP/4502-00000000
Uniqueid: 1528445666.0
Conference: 4444
TalkingStatus: on