[asterisk-dev] AMI events in Asterisk 16.1 happening 26+ seconds after parking a call.

[Steve Sether]

I'm testing Asterisk 16, and I'm seeing a very serious delay in 
bridging, and other events being displayed in the AMI, either that, or 
I'm misunderstanding how things are supposed to work.

My test setup is very simple, I'm using netcat to connect to port 5038, 
and outputting to a file.  I've isolated to a test instance of Asterisk 
with no other calls on it.


The logs are voluminous, so I'll try to pair this down to just what's 
relevant.  But the short description is I see events generated from call 
parking 30 seconds after the call has been parked.  I've seen examples 
where the delay is even longer (a minute or two at times).  I don't 
really know how to interpret this, but it's causing trouble in how we're 
displaying real time call information.


Here's the entry where I Park the call:

Event: ParkedCall
Privilege: call,all
Timestamp: 1545251863.452334
ParkeeChannel: SIP/usitest-XXXXXXXXXXXX-00000035
ParkeeChannelState: 6
ParkeeChannelStateDesc: Up
ParkeeCallerIDNum: 253
ParkeeCallerIDName: Venus Flytrap
ParkeeConnectedLineNum: 254
ParkeeConnectedLineName: Johnny Fever
ParkeeLanguage: en
ParkeeAccountCode: usitest-stevesether
ParkeeContext: parkCall
ParkeeExten: blind
ParkeePriority: 3
ParkeeUniqueid: 1545251698.668
ParkeeLinkedid: 1545251698.668
ParkerDialString: SIP/usitest-YYYYYYYYYYYY
Parkinglot: usitest-main
ParkingSpace: 801
ParkingTimeout: 600
ParkingDuration: 0


A holding bridge gets created right after I get back the parking space.

Event: BridgeEnter
Privilege: call,all
Timestamp: 1545251867.524454
BridgeUniqueid: 989137d7-07eb-422f-8371-ff2d8f92fcde
BridgeType: parking
BridgeTechnology: holding_bridge
BridgeCreator: Parking
BridgeName: usitest-main
BridgeNumChannels: 1
BridgeVideoSourceMode: none
Channel: SIP/usitest-XXXXXXXXXXXX-00000035
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 253
CallerIDName: Venus Flytrap
ConnectedLineNum: 254
ConnectedLineName: Johnny Fever
Language: en
AccountCode: usitest-stevesether
Context: parkCall
Exten: blind
Priority: 3
Uniqueid: 1545251698.668
Linkedid: 1545251698.668

Hold music gets played:


Event: MusicOnHoldStart
Privilege: call,all
Timestamp: 1545251867.525020
Channel: SIP/usitest-XXXXXXXXXXXX-00000035
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 253
CallerIDName: Venus Flytrap
ConnectedLineNum: 254
ConnectedLineName: Johnny Fever
Language: en
AccountCode: usitest-stevesether
Context: parkCall
Exten: blind
Priority: 3
Uniqueid: 1545251698.668
Linkedid: 1545251698.668
Class: default

But then there's another bridging event that shows up 26 seconds after 
the first.  This happens after the call is parked, and hold music starts 
playing.

Event: BridgeEnter
Privilege: call,all
Timestamp: 1545251893.569056
BridgeUniqueid: 07b50cd4-1047-4bc7-add2-645f91b0fe70
BridgeType: basic
BridgeTechnology: simple_bridge
BridgeCreator: <unknown>
BridgeName: <unknown>
BridgeNumChannels: 1
BridgeVideoSourceMode: none
Channel: SIP/usitest-YYYYYYYYYYYY-00000037
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: usitest-YYYYYYYYYYYY
CallerIDName: Venus Flytrap
ConnectedLineNum: 801
ConnectedLineName: Parking Lot: main
Language: en
AccountCode: usitest
Context: from-internal-phone
Exten:
Priority: 1
Uniqueid: 1545251863.687
Linkedid: 1545251863.682


Event: BridgeEnter
Privilege: call,all
Timestamp: 1545251893.569584
BridgeUniqueid: 07b50cd4-1047-4bc7-add2-645f91b0fe70
BridgeType: basic
BridgeTechnology: simple_bridge
BridgeCreator: <unknown>
BridgeName: <unknown>
BridgeNumChannels: 2
BridgeVideoSourceMode: none
Channel: Local/usitest-64167f3a547e at parkCall_do_park-0000000f;2
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 801
CallerIDName: Parking Lot: main
ConnectedLineNum: 253
ConnectedLineName: Venus Flytrap
Language: en
AccountCode: usitest
Context: parkCall_do_park
Exten: usitest-64167f3a547e
Priority: 8
Uniqueid: 1545251863.683
Linkedid: 1545251863.682


But then the bridge gets torn down quickly after:


Event: BridgeLeave
Privilege: call,all
Timestamp: 1545251893.575106
BridgeUniqueid: 07b50cd4-1047-4bc7-add2-645f91b0fe70
BridgeType: basic
BridgeTechnology: simple_bridge
BridgeCreator: <unknown>
BridgeName: <unknown>
BridgeNumChannels: 1
BridgeVideoSourceMode: none
Channel: Local/usitest-YYYYYYYYYYYY at parkCall_do_park-0000000f;2
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 801
CallerIDName: Parking Lot: main
ConnectedLineNum: 253
ConnectedLineName: Venus Flytrap
Language: en
AccountCode: usitest
Context: parkCall_do_park
Exten: usitest-YYYYYYYYYYYY
Priority: 8
Uniqueid: 1545251863.683
Linkedid: 1545251863.682


Event: BridgeLeave
Privilege: call,all
Timestamp: 1545251893.577566
BridgeUniqueid: 07b50cd4-1047-4bc7-add2-645f91b0fe70
BridgeType: basic
BridgeTechnology: simple_bridge
BridgeCreator: <unknown>
BridgeName: <unknown>
BridgeNumChannels: 0
BridgeVideoSourceMode: none
Channel: SIP/usitest-YYYYYYYYYYYY-00000037
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: usitest-YYYYYYYYYYYY
CallerIDName: Venus Flytrap
ConnectedLineNum: 801
ConnectedLineName: Parking Lot: main
Language: en
AccountCode: usitest
Context: from-internal-phone
Exten:
Priority: 1
Uniqueid: 1545251863.687
Linkedid: 1545251863.682



This doesn't make much sense to me.  Why are there parking events 
happening so longer after the call is parked?  While there's description 
of these events in the documentation, I don't know of any documentation 
on how these events relate to call setup, parking, etc.

Thanks for any help anyone can provide.


Is this a bug in Asterisk, or do I need to better understand these 
events?  If the latter, how can I go about that?