Hello Joshua,
Yesterday I tried to attach log files on this app-dev list but files were
too big. I have sent them directly to your mail. Now I tried to shrink them
as much as possible and will reattach them.
After additional testing I have following conclusions:
- early bridging has problems when outdialing to SIP trunk and getting back
status BUSY. IN channel hangs up in that moment. When dialing to PJSIP or
IAX2 there are no problems.
- early bridging also has problems when outdialing to any IP (SIP, PJSIP or
IAX2) trunk and getting back status CONGESTION. IN channel hangs up in that
moment. This happens when remote system (asterisk) is shutting down. I hope
there are no other situations to get back CONGESTION status?
My solution for now is not to use early bridging when dialing to SIP trunk
and especially if it is not the last one in failover list.
Marin
> I don't believe the caller should hang up, unless it is taking a long
> time in which case they may hang up themselves. A log would show exactly
> what is happening.
>
> --
> Joshua Colp
> Digium, Inc. | Senior Software Developer
17-02-23 15:12:25.784 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelCreated - Channel: 1487859147.3
17-02-23 15:12:25.785 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: SIPURI | Value: sip:telefon@192.168.0.214:5062
17-02-23 15:12:25.786 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: SIPDOMAIN | Value: 192.168.0.98
17-02-23 15:12:25.786 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: SIPCALLID | Value: 120586386
17-02-23 15:12:25.787 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelStateChange - Channel: 1487859147.3 | State: Ring | Name: SIP/telefon-00000001
17-02-23 15:12:25.788 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelDialplan - Channel: 1487859147.3 | DialplanApp: Stasis
17-02-23 15:12:25.789 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: STASISSTATUS | Value:
17-02-23 15:12:25.789 TRACE | nioEventLoopGroup-6-2 | ARI event: StasisStart - Channel: 1487859147.3 | State: Ring | Name: SIP/telefon-00000001
17-02-23 15:12:25.796 - Sent ARI request:
POST /ari/channels/1487859147.3/ring?api_key=ariuser:aripass HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:25.800 - Sent ARI request:
POST /ari/bridges?api_key=ariuser:aripass&type=mixing&bridgeId=C-1-32&name=CONF-1487859147.3 HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:25.802 TRACE | nioEventLoopGroup-6-2 | ARI event: BridgeCreated - Bridge: C-1-32 | Name: CONF-1487859147.3 | Type: mixing | Class: stasis | Tech: simple_bridge | Creator: Stasis
17-02-23 15:12:25.805 - Sent ARI request:
POST /ari/bridges/C-1-32/addChannel?api_key=ariuser:aripass&channel=1487859147.3 HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:25.989 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelEnteredBridge - Bridge: C-1-32 | Name: CONF-1487859147.3 | Channel: 1487859147.3
17-02-23 15:12:26.004 - Sent ARI request:
GET /ari/channels/1487859147.3?api_key=ariuser:aripass HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:26.014 - Sent ARI request:
POST /ari/channels/create?api_key=ariuser:aripass&endpoint=IAX2%2Fiax2-app-server-1%2F457&app=AriStart&originator=1487859147.3 HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:26.019 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelCreated - Channel: 1487859147.4
17-02-23 15:12:26.022 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelDialplan - Channel: 1487859147.4 | DialplanApp: Stasis
17-02-23 15:12:26.024 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.4 | Variable: STASISSTATUS | Value:
17-02-23 15:12:26.027 TRACE | nioEventLoopGroup-6-2 | ARI event: StasisStart - Channel: 1487859147.4 | State: Down | Name: IAX2/iax2-app-server-1-18216
17-02-23 15:12:26.030 - Sent ARI request:
POST /ari/channels/1487859147.3/variable?api_key=ariuser:aripass&variable=CALLERID%28all%29&value=%3C42999104%3E HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:26.033 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelCallerId - Channel: 1487859147.3 | CallerPresentationTxt: Presentation Allowed, Not Screened | CallerPresentation: 0
17-02-23 15:12:26.037 - Sent ARI request:
POST /ari/bridges/C-1-32/addChannel?api_key=ariuser:aripass&channel=1487859147.4 HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:26.222 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelEnteredBridge - Bridge: C-1-32 | Name: CONF-1487859147.3 | Channel: 1487859147.4
17-02-23 15:12:26.227 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: BRIDGEPEER | Value: IAX2/iax2-app-server-1-18216
17-02-23 15:12:26.231 - Sent ARI request:
POST /ari/channels/1487859147.4/dial?api_key=ariuser:aripass&caller=1487859147.3&timeout=60 HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:26.231 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.4 | Variable: BRIDGEPEER | Value: SIP/telefon-00000001
17-02-23 15:12:26.234 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.4 | Variable: BRIDGEPVTCALLID | Value: 120586386
17-02-23 15:12:26.236 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelConnectedLine - Channel: 1487859147.4 | Caller: () | ConnectedLine: (42999104)
17-02-23 15:12:26.239 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelStateChange - Channel: 1487859147.4 | State: Ringing | Name: IAX2/iax2-app-server-1-18216
17-02-23 15:12:26.241 TRACE | nioEventLoopGroup-6-2 | ARI event: Dial - Caller: null | Peer: IAX2/iax2-app-server-1-18216 (Channel: 1487859147.4) | DialStatus: | DialString: iax2-app-server-1/457
17-02-23 15:12:26.242 TRACE | nioEventLoopGroup-6-2 | ARI event: DeviceStateChanged - Name: IAX2/iax2-app-server-1 | State: RINGING
17-02-23 15:12:28.330 TRACE | nioEventLoopGroup-6-2 | ARI event: PeerStatusChange - Peer: null, port: null (Unreachable) | Endpoint: SIP/sip-app-server-1 (offline)
17-02-23 15:12:28.331 TRACE | nioEventLoopGroup-6-2 | ARI event: DeviceStateChanged - Name: SIP/sip-app-server-1 | State: UNAVAILABLE
17-02-23 15:12:28.695 - Sent ARI request:
GET /ari/applications/AriStart?api_key=ariuser:aripass HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:30.235 TRACE | nioEventLoopGroup-6-2 | ARI event: Dial - Caller: null | Peer: IAX2/iax2-app-server-1-18216 (Channel: 1487859147.4) | DialStatus: CONGESTION | DialString:
17-02-23 15:12:30.238 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: BRIDGEPEER | Value:
17-02-23 15:12:30.242 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelLeftBridge - Bridge: C-1-32 | Name: CONF-1487859147.3 | Channel: 1487859147.3
17-02-23 15:12:30.243 - Sent ARI request:
DELETE /ari/channels/1487859147.4?api_key=ariuser:aripass&reason=busy HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:30.246 TRACE | nioEventLoopGroup-6-2 | ARI event: StasisEnd - Channel: 1487859147.3 | State: Ring
17-02-23 15:12:30.250 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: STASISSTATUS | Value: SUCCESS
17-02-23 15:12:30.252 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelHangupRequest - Channel: 1487859147.3 | State: Ring | Cause: 16
17-02-23 15:12:30.255 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelDialplan - Channel: 1487859147.3 | DialplanApp: Stasis
17-02-23 15:12:30.257 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: STASISSTATUS | Value:
17-02-23 15:12:30.258 TRACE | nioEventLoopGroup-6-2 | ARI event: StasisStart - Channel: 1487859147.3 | State: Ring | Name: SIP/telefon-00000001
17-02-23 15:12:30.260 TRACE | nioEventLoopGroup-6-2 | ARI event: StasisEnd - Channel: 1487859147.3 | State: Ring
17-02-23 15:12:30.261 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.3 | Variable: STASISSTATUS | Value: SUCCESS
17-02-23 15:12:30.262 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelDestroyed - Channel: 1487859147.3
17-02-23 15:12:30.263 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelHangupRequest - Channel: 1487859147.4 | State: Ringing | Cause: 32
17-02-23 15:12:30.265 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.4 | Variable: BRIDGEPEER | Value:
17-02-23 15:12:30.266 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.4 | Variable: BRIDGEPVTCALLID | Value:
17-02-23 15:12:30.267 TRACE | nioEventLoopGroup-6-2 | ARI event: DeviceStateChanged - Name: IAX2/iax2-app-server-1 | State: UNKNOWN
17-02-23 15:12:30.268 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelLeftBridge - Bridge: C-1-32 | Name: CONF-1487859147.3 | Channel: 1487859147.4
17-02-23 15:12:30.269 TRACE | nioEventLoopGroup-6-2 | ARI event: StasisEnd - Channel: 1487859147.4 | State: Ringing
17-02-23 15:12:30.271 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelVarset - Channel: 1487859147.4 | Variable: STASISSTATUS | Value: SUCCESS
17-02-23 15:12:30.272 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelHangupRequest - Channel: 1487859147.4 | State: Ringing | Cause: 0
17-02-23 15:12:30.274 TRACE | nioEventLoopGroup-6-2 | ARI event: ChannelDestroyed - Channel: 1487859147.4
GET /ari/bridges/C-1-32?api_key=ariuser:aripass HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:30.324 - Sent ARI request:
DELETE /ari/bridges/C-1-32?api_key=ariuser:aripass HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:30.338 - Sent ARI request:
GET /ari/bridges/C-1-32?api_key=ariuser:aripass HTTP/1.1
Host: localhost
Connection: close
17-02-23 15:12:31.045 TRACE | nioEventLoopGroup-6-2 | ARI event: DeviceStateChanged - Name: PJSIP/pjsip-app-server-1 | State: UNAVAILABLE
17-02-23 15:12:31.068 TRACE | nioEventLoopGroup-6-2 | ARI event: ContactStatusChange - Endpoint: PJSIP/pjsip-app-server-1 (online) | ContactInfo: pjsip-app-server-1 (Unreachable)
17-02-23 15:12:31.070 TRACE | nioEventLoopGroup-6-2 | ARI event: PeerStatusChange - Peer: null, port: null (Unreachable) | Endpoint: PJSIP/pjsip-app-server-1 (offline)
[Feb 23 15:07:16] Asterisk 14.2.1 built by root @ maxvoip on a x86_64 running Linux on 2017-01-05 09:22:40 UTC
...
[Feb 23 15:12:27] DEBUG[17269] threadpool.c: Increasing threadpool stasis-core's size by 1
[Feb 23 15:12:27] DEBUG[17409][C-00000002] pbx.c: Launching 'Stasis'
[Feb 23 15:12:27] VERBOSE[17409][C-00000002] pbx.c: Executing [127@from-sip:1] Stasis("SIP/telefon-00000001", "AriStart") in new stack
...
[Feb 23 15:12:27] DEBUG[17411] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17411] http.c: HTTP Request URI is /ari/channels/1487859147.3/ring?api_key=ariuser:aripass
[Feb 23 15:12:27] DEBUG[17411] http.c: match request [ari/channels/1487859147.3/ring] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17411] http.c: match request [ari/channels/1487859147.3/ring] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17411] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17411] res_ari.c: Finding handler for channels
...
[Feb 23 15:12:27] DEBUG[17411] res_ari.c: Finding handler for 1487859147.3
...
[Feb 23 15:12:27] DEBUG[17411] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17411] res_ari.c: Examining ARI response:
204 No Content
[Feb 23 15:12:27] DEBUG[17411] http.c: HTTP closing session. status_code:204
[Feb 23 15:12:27] DEBUG[17412] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17412] http.c: HTTP Request URI is /ari/bridges?api_key=ariuser:aripass&type=mixing&bridgeId=C-1-32&name=CONF-1487859147.3
[Feb 23 15:12:27] DEBUG[17412] http.c: match request [ari/bridges] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17412] http.c: match request [ari/bridges] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17412] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17412] res_ari.c: Finding handler for bridges
[Feb 23 15:12:27] DEBUG[17412] res_ari.c: Checking bridges
[Feb 23 15:12:27] DEBUG[17412] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17412] dahdi/bridge_native_dahdi.c: Bridge C-1-32: Cannot use native DAHDI. Must have two channels.
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Feb 23 15:12:27] DEBUG[17412] bridge_native_rtp.c: Bridge 'C-1-32' can not use native RTP bridge as two channels are required
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Chose bridge technology simple_bridge
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Bridge C-1-32: calling simple_bridge technology constructor
[Feb 23 15:12:27] DEBUG[17412] bridge.c: Bridge C-1-32: calling simple_bridge technology start
[Feb 23 15:12:27] DEBUG[17412] res_ari.c: Examining ARI response:
200 OK
Content-type: application/json
{"id":"C-1-32","technology":"simple_bridge","channels":[],"creator":"Stasis","bridge_type":"mixing","video_mode":"talker","bridge_class":"stasis","name":"CONF-1487859147.3"}
[Feb 23 15:12:27] DEBUG[17412] http.c: HTTP closing session. status_code:200
[Feb 23 15:12:27] DEBUG[17413] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17413] http.c: HTTP Request URI is /ari/bridges/C-1-32/addChannel?api_key=ariuser:aripass&channel=1487859147.3
[Feb 23 15:12:27] DEBUG[17413] http.c: match request [ari/bridges/C-1-32/addChannel] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17413] http.c: match request [ari/bridges/C-1-32/addChannel] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17413] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17413] res_ari.c: Finding handler for bridges
...
[Feb 23 15:12:27] DEBUG[17413] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17413] stasis/control.c: 1487859147.3: Sending channel add_to_bridge command
[Feb 23 15:12:27] DEBUG[17409][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.0.214:5062
[Feb 23 15:12:27] DEBUG[17409][C-00000002] bridge_roles.c: Roles did not exist on channel SIP/telefon-00000001
[Feb 23 15:12:27] DEBUG[17409][C-00000002] stasis/control.c: 1487859147.3: Adding to bridge C-1-32
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge_channel.c: Bridge C-1-32: 0x7f99ec0020a8(SIP/telefon-00000001) is joining
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge_channel.c: Bridge C-1-32: pushing 0x7f99ec0020a8(SIP/telefon-00000001)
[Feb 23 15:12:27] VERBOSE[17414][C-00000002] bridge_channel.c: Channel SIP/telefon-00000001 joined 'simple_bridge' stasis-bridge <C-1-32>
[Feb 23 15:12:27] DEBUG[17414][C-00000002] dahdi/bridge_native_dahdi.c: Bridge C-1-32: Cannot use native DAHDI. Must have two channels.
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge_native_rtp.c: Bridge 'C-1-32' can not use native RTP bridge as two channels are required
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Chose bridge technology simple_bridge
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Bridge C-1-32 is already using the new technology.
[Feb 23 15:12:27] DEBUG[17414][C-00000002] bridge.c: Bridge C-1-32: 0x7f99ec0020a8(SIP/telefon-00000001) is joining simple_bridge technology
[Feb 23 15:12:27] DEBUG[17414][C-00000002] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet
[Feb 23 15:12:27] DEBUG[17413] res_ari.c: Examining ARI response:
204 No Content
[Feb 23 15:12:27] DEBUG[17413] http.c: HTTP closing session. status_code:204
[Feb 23 15:12:27] DEBUG[17415] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17415] http.c: HTTP Request URI is /ari/channels/1487859147.3?api_key=ariuser:aripass
[Feb 23 15:12:27] DEBUG[17415] http.c: match request [ari/channels/1487859147.3] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17415] http.c: match request [ari/channels/1487859147.3] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17415] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17415] res_ari.c: Finding handler for channels
...
[Feb 23 15:12:27] DEBUG[17415] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17415] res_ari.c: Finding handler for 1487859147.3
...
[Feb 23 15:12:27] DEBUG[17415] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17415] res_ari.c: Examining ARI response:
200 OK
Content-type: application/json
{"id":"1487859147.3","name":"SIP/telefon-00000001","caller":{"name":"telefon desk","number":"telefon"},"state":"Ring","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"from-sip","exten":"127","priority":1},"creationtime":"2017-02-23T15:12:27.164+0100","language":"en"}
[Feb 23 15:12:27] DEBUG[17415] http.c: HTTP closing session. status_code:200
[Feb 23 15:12:27] DEBUG[17416] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17416] http.c: HTTP Request URI is /ari/channels/create?api_key=ariuser:aripass&endpoint=IAX2%2Fiax2-app-server-1%2F457&app=AriStart&originator=1487859147.3
[Feb 23 15:12:27] DEBUG[17416] http.c: match request [ari/channels/create] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17416] http.c: match request [ari/channels/create] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17416] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17416] res_ari.c: Finding handler for channels
...
[Feb 23 15:12:27] DEBUG[17416] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17416] res_stasis.c: AriStart: Subscribing to 1487859147.3
[Feb 23 15:12:27] DEBUG[17416] chan_iax2.c: ip callno count incremented to 3 for 192.168.0.137
[Feb 23 15:12:27] DEBUG[17416] chan_iax2.c: Made call 15664 into trunk call 18216
[Feb 23 15:12:27] DEBUG[17416] res_stasis.c: AriStart: Subscribing to 1487859147.4
[Feb 23 15:12:27] DEBUG[17416] res_ari.c: Examining ARI response:
200 OK
Content-type: application/json
{"id":"1487859147.4","name":"IAX2/iax2-app-server-1-18216","caller":{"name":"","number":""},"state":"Down","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"","exten":"s","priority":1},"creationtime":"2017-02-23T15:12:27.398+0100","language":"en"}
[Feb 23 15:12:27] DEBUG[17416] http.c: HTTP closing session. status_code:200
...
[Feb 23 15:12:27] DEBUG[17418] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17418] http.c: HTTP Request URI is /ari/channels/1487859147.3/variable?api_key=ariuser:aripass&variable=CALLERID%28all%29&value=%3C42999104%3E
[Feb 23 15:12:27] DEBUG[17418] http.c: match request [ari/channels/1487859147.3/variable] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17418] http.c: match request [ari/channels/1487859147.3/variable] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17418] http.c: Match made with [ari]
...
[Feb 23 15:12:27] DEBUG[17418] res_ari.c: Finding handler for 1487859147.3
...
[Feb 23 15:12:27] DEBUG[17418] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17418] res_ari.c: Examining ARI response:
204 No Content
[Feb 23 15:12:27] DEBUG[17418] http.c: HTTP closing session. status_code:204
[Feb 23 15:12:27] DEBUG[17419] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17419] http.c: HTTP Request URI is /ari/bridges/C-1-32/addChannel?api_key=ariuser:aripass&channel=1487859147.4
[Feb 23 15:12:27] DEBUG[17419] http.c: match request [ari/bridges/C-1-32/addChannel] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17419] http.c: match request [ari/bridges/C-1-32/addChannel] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17419] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17419] res_ari.c: Finding handler for bridges
...
[Feb 23 15:12:27] DEBUG[17419] stasis/control.c: 1487859147.4: Sending channel add_to_bridge command
[Feb 23 15:12:27] DEBUG[17311] chan_iax2.c: ip callno count decremented to 3 for 192.168.5.16
[Feb 23 15:12:27] DEBUG[17417] bridge_roles.c: Roles did not exist on channel IAX2/iax2-app-server-1-18216
[Feb 23 15:12:27] DEBUG[17417] stasis/control.c: 1487859147.4: Adding to bridge C-1-32
[Feb 23 15:12:27] DEBUG[17420] bridge_channel.c: Bridge C-1-32: 0x7f99ec0081a8(IAX2/iax2-app-server-1-18216) is joining
[Feb 23 15:12:27] DEBUG[17420] bridge_channel.c: Bridge C-1-32: pushing 0x7f99ec0081a8(IAX2/iax2-app-server-1-18216)
[Feb 23 15:12:27] VERBOSE[17420] bridge_channel.c: Channel IAX2/iax2-app-server-1-18216 joined 'simple_bridge' stasis-bridge <C-1-32>
[Feb 23 15:12:27] DEBUG[17420] dahdi/bridge_native_dahdi.c: Channel 'SIP/telefon-00000001' is not DAHDI.
[Feb 23 15:12:27] DEBUG[17420] dahdi/bridge_native_dahdi.c: Bridge C-1-32: Cannot use native DAHDI. Channel 'SIP/telefon-00000001' not compatible.
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Feb 23 15:12:27] DEBUG[17420] bridge_native_rtp.c: Bridge 'C-1-32' can not use native RTP bridge as it was forbidden while getting details
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Chose bridge technology simple_bridge
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Bridge C-1-32 is already using the new technology.
[Feb 23 15:12:27] DEBUG[17420] bridge.c: Bridge C-1-32: 0x7f99ec0081a8(IAX2/iax2-app-server-1-18216) is joining simple_bridge technology
[Feb 23 15:12:27] DEBUG[17420] channel.c: Channel IAX2/iax2-app-server-1-18216 setting read format path: gsm -> slin
[Feb 23 15:12:27] DEBUG[17420] channel.c: Channel SIP/telefon-00000001 setting write format path: slin -> ulaw
[Feb 23 15:12:27] DEBUG[17420] channel.c: Channel SIP/telefon-00000001 setting read format path: ulaw -> slin
[Feb 23 15:12:27] DEBUG[17284] cdr.c: Finalized CDR for IAX2/iax2-app-server-1-18216 - start 1487859147.399090 answer 0.000000 end 1487859147.601470 dispo FAILED
[Feb 23 15:12:27] DEBUG[17420] channel.c: Channel IAX2/iax2-app-server-1-18216 setting write format path: slin -> gsm
...
[Feb 23 15:12:27] DEBUG[17419] res_ari.c: Examining ARI response:
204 No Content
[Feb 23 15:12:27] DEBUG[17419] http.c: HTTP closing session. status_code:204
[Feb 23 15:12:27] DEBUG[17421] http.c: HTTP opening session. Top level
[Feb 23 15:12:27] DEBUG[17421] http.c: HTTP Request URI is /ari/channels/1487859147.4/dial?api_key=ariuser:aripass&caller=1487859147.3&timeout=60
[Feb 23 15:12:27] DEBUG[17421] http.c: match request [ari/channels/1487859147.4/dial] with handler [httpstatus] len 10
...
[Feb 23 15:12:27] DEBUG[17421] http.c: match request [ari/channels/1487859147.4/dial] with handler [ari] len 3
[Feb 23 15:12:27] DEBUG[17421] http.c: Match made with [ari]
[Feb 23 15:12:27] DEBUG[17421] res_ari.c: Finding handler for channels
[Feb 23 15:12:27] DEBUG[17421] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17421] res_ari.c: Finding handler for 1487859147.4
[Feb 23 15:12:27] DEBUG[17421] res_ari.c: Got it!
[Feb 23 15:12:27] DEBUG[17421] res_ari.c: Examining ARI response:
204 No Content
[Feb 23 15:12:27] DEBUG[17421] http.c: HTTP closing session. status_code:204
[Feb 23 15:12:27] DEBUG[17417] bridge.c: Putting interval hook 0x7f99ec0038d0 with interval 59999 in the heap on features 0x7f99ec0024e0
[Feb 23 15:12:27] DEBUG[17280] devicestate.c: No provider found, checking channel drivers for IAX2 - iax2-app-server-1
[Feb 23 15:12:27] DEBUG[17280] chan_iax2.c: Checking device state for device iax2-app-server-1
[Feb 23 15:12:27] DEBUG[17280] chan_iax2.c: Found peer. What's device state of iax2-app-server-1? addr=192.168.0.137:4569, defaddr=(null) maxms=2000, lastms=1
[Feb 23 15:12:27] DEBUG[17280] devicestate.c: Changing state for IAX2/iax2-app-server-1 - state 6 (Ringing)
[Feb 23 15:12:27] DEBUG[17347] app_queue.c: Device 'IAX2/iax2-app-server-1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Feb 23 15:12:27] DEBUG[17408] res_http_websocket.c: Writing websocket string of length 198
[Feb 23 15:12:27] DEBUG[17408] res_http_websocket.c: Writing websocket text frame, length 198
[Feb 23 15:12:27] DEBUG[17325] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.137:5060
[Feb 23 15:12:28] DEBUG[17325] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.137:5060
[Feb 23 15:12:29] DEBUG[17294] config.c: extract uint from [3] in [0, 4294967295] gives [3](0)
[Feb 23 15:12:29] DEBUG[17294] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Feb 23 15:12:29] DEBUG[17294] config.c: extract uint from [2] in [0, 4294967295] gives [2](0)
[Feb 23 15:12:29] DEBUG[17294] res_pjsip.c: 0x7f99f4022028: Wrapper created
[Feb 23 15:12:29] DEBUG[17294] res_pjsip.c: 0x7f99f4022028: Set timer to 3000 msec
[Feb 23 15:12:29] DEBUG[17294] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.0.137'
[Feb 23 15:12:29] DEBUG[17294] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.0.137' is 'UDP'
[Feb 23 15:12:29] DEBUG[17294] res_pjsip/pjsip_resolver.c: Target '192.168.0.137' is an IP address, skipping resolution
[Feb 23 15:12:29] DEBUG[17294] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.0.98:5061
[Feb 23 15:12:29] DEBUG[17294] netsock2.c: Splitting '192.168.0.98:5061' into...
[Feb 23 15:12:29] DEBUG[17294] netsock2.c: ...host '192.168.0.98' and port '5061'.
[Feb 23 15:12:29] DEBUG[17294] netsock2.c: Splitting '192.168.0.137:5061' into...
[Feb 23 15:12:29] DEBUG[17294] netsock2.c: ...host '192.168.0.137' and port '5061'.
[Feb 23 15:12:29] DEBUG[17325] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.137:5060
[Feb 23 15:12:29] NOTICE[17325] chan_sip.c: Peer 'sip-app-server-1' is now UNREACHABLE! Last qualify: 1
[Feb 23 15:12:29] DEBUG[17325] chan_sip.c: Destroying SIP dialog 5813e53e321cf882668adf7c416630fc@192.168.0.98:5060
[Feb 23 15:12:29] DEBUG[17280] devicestate.c: No provider found, checking channel drivers for SIP - sip-app-server-1
[Feb 23 15:12:29] DEBUG[17280] chan_sip.c: Checking device state for peer sip-app-server-1
[Feb 23 15:12:29] DEBUG[17280] devicestate.c: Changing state for SIP/sip-app-server-1 - state 5 (Unavailable)
[Feb 23 15:12:29] DEBUG[17347] app_queue.c: Device 'SIP/sip-app-server-1' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Feb 23 15:12:29] DEBUG[17293] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.0.98:5061
[Feb 23 15:12:29] DEBUG[17293] netsock2.c: Splitting '192.168.0.98:5061' into...
...
[Feb 23 15:12:30] DEBUG[17422] http.c: HTTP opening session. Top level
[Feb 23 15:12:30] DEBUG[17422] http.c: HTTP Request URI is /ari/applications/AriStart?api_key=ariuser:aripass
[Feb 23 15:12:30] DEBUG[17422] http.c: match request [ari/applications/AriStart] with handler [httpstatus] len 10
...
[Feb 23 15:12:30] DEBUG[17422] http.c: match request [ari/applications/AriStart] with handler [ari] len 3
[Feb 23 15:12:30] DEBUG[17422] http.c: Match made with [ari]
[Feb 23 15:12:30] DEBUG[17422] res_ari.c: Finding handler for applications
...
[Feb 23 15:12:30] DEBUG[17422] res_ari.c: Examining ARI response:
200 OK
Content-type: application/json
{"name":"AriStart","endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]}
[Feb 23 15:12:30] DEBUG[17422] http.c: HTTP closing session. status_code:200
[Feb 23 15:12:30] DEBUG[17293] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.0.98:5061
[Feb 23 15:12:30] DEBUG[17293] netsock2.c: Splitting '192.168.0.98:5061' into...
[Feb 23 15:12:30] DEBUG[17293] netsock2.c: ...host '192.168.0.98' and port '5061'.
[Feb 23 15:12:30] DEBUG[17293] netsock2.c: Splitting '192.168.0.137:5061' into...
[Feb 23 15:12:30] DEBUG[17293] netsock2.c: ...host '192.168.0.137' and port '5061'.
[Feb 23 15:12:31] NOTICE[17316] chan_iax2.c: Auto-congesting call due to slow response
[Feb 23 15:12:31] DEBUG[17284] cdr.c: Finalized CDR for IAX2/iax2-app-server-1-18216 - start 1487859147.615917 answer 0.000000 end 1487859151.615067 dispo CONGESTION
[Feb 23 15:12:31] DEBUG[17414][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 503' onto UDP socket destined for 192.168.0.214:5062
[Feb 23 15:12:31] DEBUG[17414][C-00000002] chan_sip.c: Setting SIP_ALREADYGONE on dialog 120586386
[Feb 23 15:12:31] DEBUG[17414][C-00000002] channel.c: Soft-Hanging (0x01) up channel 'SIP/telefon-00000001'
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge_channel.c: Setting 0x7f99ec0020a8(SIP/telefon-00000001) state from:0 to:1
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge_channel.c: Bridge C-1-32: pulling 0x7f99ec0020a8(SIP/telefon-00000001)
[Feb 23 15:12:31] VERBOSE[17414][C-00000002] bridge_channel.c: Channel SIP/telefon-00000001 left 'simple_bridge' stasis-bridge <C-1-32>
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge_channel.c: Bridge C-1-32: 0x7f99ec0020a8(SIP/telefon-00000001) is leaving simple_bridge technology
[Feb 23 15:12:31] DEBUG[17414][C-00000002] dahdi/bridge_native_dahdi.c: Bridge C-1-32: Cannot use native DAHDI. Must have two channels.
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge_native_rtp.c: Bridge 'C-1-32' can not use native RTP bridge as two channels are required
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Feb 23 15:12:31] DEBUG[17284] cdr.c: Finalized CDR for SIP/telefon-00000001 - start 1487859147.165126 answer 0.000000 end 1487859151.615825 dispo NO ANSWER
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge.c: Chose bridge technology simple_bridge
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge.c: Bridge C-1-32 is already using the new technology.
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge_channel.c: Bridge is returning 0x7f99ec0020a8(SIP/telefon-00000001) to read format ulaw
[Feb 23 15:12:31] DEBUG[17414][C-00000002] channel.c: Channel SIP/telefon-00000001 setting read format path: ulaw -> ulaw
[Feb 23 15:12:31] DEBUG[17414][C-00000002] bridge_channel.c: Bridge is returning 0x7f99ec0020a8(SIP/telefon-00000001) to write format ulaw
[Feb 23 15:12:31] DEBUG[17414][C-00000002] channel.c: Channel SIP/telefon-00000001 setting write format path: ulaw -> ulaw
[Feb 23 15:12:31] DEBUG[17414][C-00000002] stasis/control.c: 1487859147.3, C-1-32: Channel leaving bridge
[Feb 23 15:12:31] DEBUG[17414][C-00000002] stasis/app.c: App 'AriStart' not subscribed to bridge 'C-1-32'
[Feb 23 15:12:31] DEBUG[17414][C-00000002] stasis/control.c: reason: Channel was departed from bridge
[Feb 23 15:12:31] DEBUG[17409][C-00000002] stasis/control.c: 1487859147.3: Channel departing bridge
[Feb 23 15:12:31] DEBUG[17409][C-00000002] bridge.c: Waiting for 0x7f99ec0020a8(SIP/telefon-00000001) bridge thread to die.
[Feb 23 15:12:31] DEBUG[17409][C-00000002] stasis/app.c: App 'AriStart' not subscribed to channel '1487859147.3'
[Feb 23 15:12:31] DEBUG[17409][C-00000002] pbx.c: Extension 127, priority 1 returned normally even though call was hung up
[Feb 23 15:12:31] DEBUG[17409][C-00000002] channel.c: Soft-Hanging (0x10) up channel 'SIP/telefon-00000001'
[Feb 23 15:12:31] DEBUG[17409][C-00000002] channel.c: Soft-Hanging (0x80) up channel 'SIP/telefon-00000001'
[Feb 23 15:12:31] DEBUG[17409][C-00000002] pbx.c: Launching 'Stasis'
[Feb 23 15:12:31] VERBOSE[17409][C-00000002] pbx.c: Executing [h@from-sip:1] Stasis("SIP/telefon-00000001", "AriStart") in new stack
[Feb 23 15:12:31] DEBUG[17409][C-00000002] stasis/app.c: App 'AriStart' not subscribed to channel '1487859147.3'
[Feb 23 15:12:31] DEBUG[17355] res_http_websocket.c: Writing websocket text frame, length 464
[Feb 23 15:12:31] DEBUG[17409][C-00000002] channel.c: Hanging up channel 'SIP/telefon-00000001'
[Feb 23 15:12:31] DEBUG[17409][C-00000002] chan_sip.c: Hangup call SIP/telefon-00000001, SIP callid 120586386
[Feb 23 15:12:31] DEBUG[17409][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f99f4014bb8'
[Feb 23 15:12:31] DEBUG[17280] devicestate.c: No provider found, checking channel drivers for SIP - telefon
[Feb 23 15:12:31] DEBUG[17280] chan_sip.c: Checking device state for peer telefon
[Feb 23 15:12:31] DEBUG[17280] devicestate.c: Changing state for SIP/telefon - state 1 (Not in use)
..._______________________________________________
asterisk-app-dev mailing list
asterisk-app-dev@xxxxxxxxxxxxxxxx
http://lists.digium.com/cgi-bin/mailman/listinfo/asterisk-app-dev
