Call destroyed/hangup unexcpected

Hello,

i have a call from SIP/745 (192.168.3.101) to SIP/743 (192.168.3.8 Cisco7940) and after a few seconds the call just is dropped.

This was a test-case, but i have the situation in production environment too. If needed, there is a longer versio of the sip/asterisk-debug.

I dont know that much about the sip-protocoll and did not see something in the log-messages except the line
"BYE sip:743@192.168.3.8:5060;user=phone;transport=udp SIP/2.0"

With this logline the drop was called, but i have no idea what causes this.

Any help would be appreciated.

Thanks,
Michael

<------------->
--- (14 headers 10 lines) ---
Found RTP audio format 0
Found RTP audio format 101
Peer audio RTP is at port 192.168.3.8:30752
Found audio description format PCMU for ID 0
Found audio description format telephone-event for ID 101
Got unsupported a:fmtp in SDP offer
Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
Peer audio RTP is at port 192.168.3.8:30752
list_route: hop: <sip:743@192.168.3.8:5060;user=phone;transport=udp>
set_destination: Parsing <sip:743@192.168.3.8:5060;user=phone;transport=udp> for address/port to send to
set_destination: set destination to 192.168.3.8, port 5060
Transmitting (no NAT) to 192.168.3.8:5060:
ACK sip:743@192.168.3.8:5060;user=phone;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.200.20:5060;branch=z9hG4bK170bccc5;rport
From: "Saalfrank, Michael" <sip:745@192.168.200.20>;tag=as783dcb66
To: <sip:743@192.168.3.8:5060;user=phone;transport=udp>;tag=0009b7f9ce893a6b5b46c785-7a971715
Contact: <sip:745@192.168.200.20>
Call-ID: 6616022a3f5d59b86f06cc303b090f4d@192.168.200.20
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


--nny*CLI>
    -- SIP/743-00a54880 answered SIP/745-b41c7280
    -- Executing [745@capicall:1] Macro("mISDN/14-u1961", "jumpintern|745") in new stack
    -- Executing [s@macro-jumpintern:1] Set("mISDN/14-u1961", "troption=t") in new stack
    -- Executing [s@macro-jumpintern:2] Goto("mISDN/14-u1961", "fromsip|745|1") in new stack
    -- Goto (fromsip,745,1)
  == Channel 'mISDN/14-u1961' jumping out of macro 'jumpintern'
    -- Executing [745@fromsip:1] Answer("mISDN/14-u1961", "") in new stack
    -- Executing [745@fromsip:2] Macro("mISDN/14-u1961", "cfexten|745") in new stack
    -- Executing [s@macro-cfexten:1] Set("mISDN/14-u1961", "cfstat=0") in new stack
    -- Executing [s@macro-cfexten:2] GotoIf("mISDN/14-u1961", "0?cfim:nocfim") in new stack
    -- Goto (macro-cfexten,s,4)
    -- Executing [s@macro-cfexten:4] NoOp("mISDN/14-u1961", "") in new stack
    -- Executing [745@fromsip:4] NoOp("mISDN/14-u1961", "DialStatus 01: ") in new stack
    -- Executing [745@fromsip:5] Dial("mISDN/14-u1961", "SIP/745|25|t") in new stack
    -- Called 745
    -- Got SIP response 486 "Busy Here" back from 192.168.3.101
    -- SIP/745-009b9770 is busy
  == Everyone is busy/congested at this time (1:1/0/0)
    -- Executing [745@fromsip:6] NoOp("mISDN/14-u1961", "DialStatus 02: BUSY") in new stack
    -- Executing [745@fromsip:7] Macro("mISDN/14-u1961", "usevm|745") in new stack
    -- Executing [s@macro-usevm:1] Set("mISDN/14-u1961", "vmstatus=0") in new stack
    -- Executing [s@macro-usevm:2] GotoIf("mISDN/14-u1961", "0?vmyes:vmno") in new stack
    -- Goto (macro-usevm,s,4)
    -- Executing [s@macro-usevm:4] Congestion("mISDN/14-u1961", "10") in new stack
  == Spawn extension (macro-usevm, s, 4) exited non-zero on 'mISDN/14-u1961'
    -- Got SIP response 486 "Busy Here" back from 192.168.3.101
    -- SIP/279-00a89db0 is busy
    -- Nobody picked up in 0 ms
    -- Started music on hold, class 'default', on mISDN/3-u1953
[Dec 20 17:11:41] WARNING[9668]: interface.c:215 decodeMP3: Junk at the beginning of frame 49443303
    -- Stopped music on hold on mISDN/13-u1955
  == Spawn extension (capicall, 598, 5) exited non-zero on 'mISDN/13-u1955'
    -- Executing [h@capicall:1] Hangup("mISDN/13-u1955", "") in new stack
  == Spawn extension (capicall, h, 1) exited non-zero on 'mISDN/13-u1955'
    -- Executing [88@fromsip:1] Dial("SIP/279-b41dd8f0", "mISDN/g:TEPorts/88|30|rtT") in new stack
    -- Called g:TEPorts/88
    -- mISDN/5-u1965 is ringing
P[ 3]  --> Didn't find BC so temporarly creating dummy BC (l3id:ffff0001) on this port.
[Dec 20 17:11:47] WARNING[6601]: chan_misdn.c:5650 chan_misdn_log: Got EVENT_FACILITY but we don't have a ch!
    -- mISDN/5-u1965 answered SIP/279-b41dd8f0
    -- Executing [745@capicall:1] Macro("mISDN/14-u1966", "jumpintern|745") in new stack
    -- Executing [s@macro-jumpintern:1] Set("mISDN/14-u1966", "troption=t") in new stack
    -- Executing [s@macro-jumpintern:2] Goto("mISDN/14-u1966", "fromsip|745|1") in new stack
    -- Goto (fromsip,745,1)
  == Channel 'mISDN/14-u1966' jumping out of macro 'jumpintern'
    -- Executing [745@fromsip:1] Answer("mISDN/14-u1966", "") in new stack
    -- Executing [745@fromsip:2] Macro("mISDN/14-u1966", "cfexten|745") in new stack
    -- Executing [s@macro-cfexten:1] Set("mISDN/14-u1966", "cfstat=0") in new stack
    -- Executing [s@macro-cfexten:2] GotoIf("mISDN/14-u1966", "0?cfim:nocfim") in new stack
    -- Goto (macro-cfexten,s,4)
    -- Executing [s@macro-cfexten:4] NoOp("mISDN/14-u1966", "") in new stack
    -- Executing [745@fromsip:4] NoOp("mISDN/14-u1966", "DialStatus 01: ") in new stack
    -- Executing [745@fromsip:5] Dial("mISDN/14-u1966", "SIP/745|25|t") in new stack
    -- Called 745
    -- Got SIP response 486 "Busy Here" back from 192.168.3.101
    -- SIP/745-00a3d150 is busy
  == Everyone is busy/congested at this time (1:1/0/0)
    -- Executing [745@fromsip:6] NoOp("mISDN/14-u1966", "DialStatus 02: BUSY") in new stack
    -- Executing [745@fromsip:7] Macro("mISDN/14-u1966", "usevm|745") in new stack
    -- Executing [s@macro-usevm:1] Set("mISDN/14-u1966", "vmstatus=0") in new stack
    -- Executing [s@macro-usevm:2] GotoIf("mISDN/14-u1966", "0?vmyes:vmno") in new stack
    -- Goto (macro-usevm,s,4)
    -- Executing [s@macro-usevm:4] Congestion("mISDN/14-u1966", "10") in new stack
  == Spawn extension (macro-usevm, s, 4) exited non-zero on 'mISDN/14-u1966'
    -- Executing [s@macro-jumpintern:1] Set("mISDN/14-u1967", "troption=t") in new stack
    -- Executing [s@macro-jumpintern:2] Goto("mISDN/14-u1967", "fromsip|615|1") in new stack
    -- Goto (fromsip,615,1)
  == Channel 'mISDN/14-u1967' jumping out of macro 'jumpintern'
    -- Executing [615@fromsip:1] Answer("mISDN/14-u1967", "") in new stack
    -- Executing [615@fromsip:2] Macro("mISDN/14-u1967", "cfexten|615") in new stack
    -- Executing [s@macro-cfexten:1] Set("mISDN/14-u1967", "cfstat=0") in new stack
    -- Executing [s@macro-cfexten:2] GotoIf("mISDN/14-u1967", "0?cfim:nocfim") in new stack
    -- Goto (macro-cfexten,s,4)
    -- Executing [s@macro-cfexten:4] NoOp("mISDN/14-u1967", "") in new stack
    -- Executing [745@capicall:1] Macro("mISDN/13-u1968", "jumpintern|745") in new stack
    -- Executing [s@macro-jumpintern:1] Set("mISDN/13-u1968", "troption=t") in new stack
    -- Executing [s@macro-jumpintern:2] Goto("mISDN/13-u1968", "fromsip|745|1") in new stack
    -- Goto (fromsip,745,1)
  == Channel 'mISDN/13-u1968' jumping out of macro 'jumpintern'
    -- Executing [745@fromsip:1] Answer("mISDN/13-u1968", "") in new stack
    -- Executing [745@fromsip:2] Macro("mISDN/13-u1968", "cfexten|745") in new stack
    -- Executing [s@macro-cfexten:1] Set("mISDN/13-u1968", "cfstat=0") in new stack
    -- Executing [s@macro-cfexten:2] GotoIf("mISDN/13-u1968", "0?cfim:nocfim") in new stack
    -- Goto (macro-cfexten,s,4)
    -- Executing [s@macro-cfexten:4] NoOp("mISDN/13-u1968", "") in new stack
    -- Executing [745@fromsip:4] NoOp("mISDN/13-u1968", "DialStatus 01: ") in new stack
    -- Executing [745@fromsip:5] Dial("mISDN/13-u1968", "SIP/745|25|t") in new stack
    -- Called 745
    -- Got SIP response 486 "Busy Here" back from 192.168.3.101
    -- SIP/745-00a7baf0 is busy
  == Everyone is busy/congested at this time (1:1/0/0)
    -- Executing [745@fromsip:6] NoOp("mISDN/13-u1968", "DialStatus 02: BUSY") in new stack
    -- Executing [745@fromsip:7] Macro("mISDN/13-u1968", "usevm|745") in new stack
    -- Executing [s@macro-usevm:1] Set("mISDN/13-u1968", "vmstatus=0") in new stack
    -- Executing [s@macro-usevm:2] GotoIf("mISDN/13-u1968", "0?vmyes:vmno") in new stack
    -- Goto (macro-usevm,s,4)
    -- Executing [s@macro-usevm:4] Congestion("mISDN/13-u1968", "10") in new stack
  == Spawn extension (macro-usevm, s, 4) exited non-zero on 'mISDN/13-u1968'
Scheduling destruction of SIP dialog '6616022a3f5d59b86f06cc303b090f4d@192.168.200.20' in 6976 ms (Method: INVITE)
set_destination: Parsing <sip:743@192.168.3.8:5060;user=phone;transport=udp> for address/port to send to
set_destination: set destination to 192.168.3.8, port 5060
Reliably Transmitting (no NAT) to 192.168.3.8:5060:
BYE sip:743@192.168.3.8:5060;user=phone;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.200.20:5060;branch=z9hG4bK25c45ed5;rport
From: "Saalfrank, Michael" <sip:745@192.168.200.20>;tag=as783dcb66
To: <sip:743@192.168.3.8:5060;user=phone;transport=udp>;tag=0009b7f9ce893a6b5b46c785-7a971715
Call-ID: 6616022a3f5d59b86f06cc303b090f4d@192.168.200.20
CSeq: 103 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
  == Spawn extension (fromsip, 743, 5) exited non-zero on 'SIP/745-b41c7280'
    -- Executing [h@fromsip:1] Hangup("SIP/745-b41c7280", "") in new stack
  == Spawn extension (fromsip, h, 1) exited non-zero on 'SIP/745-b41c7280'
lenny*CLI>
<--- SIP read from 192.168.3.8:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.200.20:5060;branch=z9hG4bK25c45ed5;rport
From: "Saalfrank, Michael" <sip:745@192.168.200.20>;tag=as783dcb66
To: <sip:743@192.168.3.8:5060;user=phone;transport=udp>;tag=0009b7f9ce893a6b5b46c785-7a971715
Call-ID: 6616022a3f5d59b86f06cc303b090f4d@192.168.200.20
Date: Thu, 20 Dec 2007 16:11:58 GMT
CSeq: 103 BYE
Server: Cisco-CP7960G/8.0
Content-Length: 0

Perhaps here is problem ?

Cheers.

Marco Bruni

I know, that while the call from 745 to 743 was established, there was another try, to call 745. So, i think the busy-signal was ok. But i dont get or know, why the active call just was hangup.

regards,
Michael