[Asterisk-Dev] Bug report

Tue Dec 13 16:01:15 MST 2005

I have 4 Mediatrix 1102 devices connected to asterisk 1.2
(asterisk at home). In random times, all mgcp protocol hangs and the only
way to get it working again is killing asterisk and starting it again.

Last messages refered to mgcp before hang:

Dec 12 12:13:03 VERBOSE[4812] logger.c:     -- Executing
GotoIf("MGCP/aaln/1 at 192.168.1.104-0", "0?5:4") in new stack
Dec 12 12:13:03 VERBOSE[4812] logger.c:     -- Executing
AGI("MGCP/aaln/1 at 192.168.1.104-0", "dialparties.agi") in new stack
Dec 12 12:13:03 VERBOSE[4812] logger.c:     --  dialparties.agi:
channel = MGCP/aaln/1 at 192.168.1.104-0
Dec 12 12:13:03 VERBOSE[4812] logger.c:     --  dialparties.agi: type = MGCP
Dec 12 12:13:03 VERBOSE[4812] logger.c:     -- Executing
Dial("MGCP/aaln/1 at 192.168.1.104-0",
"MGCP/aaln/2 at 192.168.1.104|30|tTrwW") in new stack
Dec 12 12:13:03 DEBUG[4812] chan_mgcp.c: Coundn't determine
subchannel, assuming current master aaln/2 at 192.168.1.104-1
Dec 12 12:13:03 VERBOSE[4812] logger.c:     -- MGCP
mgcp_request(aaln/2 at 192.168.1.104)
Dec 12 12:13:03 VERBOSE[4812] logger.c:     -- MGCP cw: 0, dnd: 0, so: 0, sno: 0
Dec 12 12:13:03 VERBOSE[4812] logger.c:     -- MGCP
mgcp_new(MGCP/aaln/2 at 192.168.1.104-1) created in state: Down
Dec 12 12:13:03 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:03 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:03 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:03 DEBUG[3148] channel.c: Avoiding initial deadlock for
'MGCP/aaln/2 at 192.168.1.104-1'
Dec 12 12:13:03 VERBOSE[4812] logger.c:     --
MGCP/aaln/2 at 192.168.1.104-1 is ringing
Dec 12 12:13:03 DEBUG[3162] chan_mgcp.c: Got response back on transaction 689
Dec 12 12:13:03 DEBUG[3162] chan_mgcp.c: Got response back on transaction 690
Dec 12 12:13:03 DEBUG[3162] chan_mgcp.c: Got response back on transaction 691
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: Coundn't determine
subchannel, assuming current master aaln/1 at 192.168.1.104-0
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: Endpoint
'aaln/1 at 192.168.1.104-0' observed 'hu'
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: MGCP aaln/1 at 192.168.1.104 Went on hook
Dec 12 12:13:06 DEBUG[3162] channel.c: Planning to masquerade channel
Zap/1-1 into the structure of MGCP/aaln/1 at 192.168.1.104-0
Dec 12 12:13:06 DEBUG[3162] channel.c: Done planning to masquerade
channel Zap/1-1 into the structure of MGCP/aaln/1 at 192.168.1.104-0
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: Released sub 0 of channel
aaln/1 at 192.168.1.104
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:06 WARNING[3162] chan_mgcp.c: Transfer attempt failed
Dec 12 12:13:06 NOTICE[4812] chan_mgcp.c: mgcp_fixup(Zap/1-1, Zap/1-1<MASQ>)
Dec 12 12:13:06 WARNING[4812] chan_mgcp.c: old channel wasn't
0x90b6d00 but was (nil)
Dec 12 12:13:06 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:06 DEBUG[4812] channel.c: Released clone lock on
'MGCP/aaln/1 at 192.168.1.104-0<ZOMBIE>'
Dec 12 12:13:06 DEBUG[4796] channel.c: Didn't get a frame from
channel: MGCP/aaln/1 at 192.168.1.104-0<ZOMBIE>
Dec 12 12:13:06 DEBUG[4796] channel.c: Bridge stops bridging channels
MGCP/aaln/1 at 192.168.1.104-0<ZOMBIE> and MGCP/aaln/1 at 192.168.1.104-1
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: Got response back on transaction 692
Dec 12 12:13:06 DEBUG[3162] chan_mgcp.c: Got response back on transaction 693
Dec 12 12:13:08 DEBUG[3162] chan_mgcp.c: Coundn't determine
subchannel, assuming current master aaln/2 at 192.168.1.104-1
Dec 12 12:13:08 DEBUG[3162] chan_mgcp.c: Endpoint
'aaln/2 at 192.168.1.104-1' observed 'hd'
Dec 12 12:13:08 DEBUG[3162] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:08 DEBUG[3162] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:08 VERBOSE[4812] logger.c:     --
MGCP/aaln/2 at 192.168.1.104-1 answered Zap/1-1
Dec 12 12:13:08 DEBUG[4812] chan_mgcp.c: Oooh, format changed to 256
Dec 12 12:13:08 DEBUG[3162] chan_mgcp.c: Got response back on transaction 694
Dec 12 12:13:08 DEBUG[3162] chan_mgcp.c: Got response back on transaction 695
Dec 12 12:13:32 DEBUG[3162] chan_mgcp.c: Coundn't determine
subchannel, assuming current master aaln/2 at 192.168.1.104-1
Dec 12 12:13:32 DEBUG[3162] chan_mgcp.c: Endpoint
'aaln/2 at 192.168.1.104-1' observed 'hu'
Dec 12 12:13:32 DEBUG[3162] chan_mgcp.c: MGCP aaln/2 at 192.168.1.104 Went on hook
Dec 12 12:13:32 DEBUG[4812] channel.c: Didn't get a frame from
channel: MGCP/aaln/2 at 192.168.1.104-1
Dec 12 12:13:32 DEBUG[4812] channel.c: Bridge stops bridging channels
Zap/1-1 and MGCP/aaln/2 at 192.168.1.104-1
Dec 12 12:13:32 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:32 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:32 DEBUG[4812] chan_mgcp.c: Slow sequence is 0
Dec 12 12:13:32 DEBUG[4812] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2005-12-12 12:13:02','š

                                 ','š

                                         ','5753','from-internal',
'MGCP/aaln/1 at 192.168.1.104-0','MGCP/aaln/2 at 192.168.1.104-1','ResetCDR','w',30,24,'ANSWERED',3,'','asterisk-3094-1134385976.297')
Dec 12 12:13:32 WARNING[4812] cdr.c: CDR on channel
'MGCP/aaln/1 at 192.168.1.104-0' not posted
Dec 12 12:13:32 WARNING[4812] cdr.c: CDR on channel
'MGCP/aaln/1 at 192.168.1.104-0' lacks end
Dec 12 12:13:32 DEBUG[3162] chan_mgcp.c: Got response back on transaction 696
Dec 12 12:13:33 DEBUG[3162] chan_mgcp.c: Got response back on transaction 697
Dec 12 12:13:33 DEBUG[3162] chan_mgcp.c: Got response back on transaction 698
Dec 12 12:14:19 DEBUG[4760] channel.c: Bridge stops bridging channels
MGCP/aaln/1 at 192.168.1.100-0 and Zap/2-1
Dec 12 12:14:19 VERBOSE[4760] logger.c:   == Spawn extension
(macro-dialout-trunk, s, 14) exited non-zero on
'MGCP/aaln/1 at 192.168.1.100-0' in macro 'dialout-trunk'
Dec 12 12:14:19 VERBOSE[4760] logger.c:   == Spawn extension
(from-internal, 915164873, 1) exited non-zero on
'MGCP/aaln/1 at 192.168.1.100-0'
Dec 12 12:14:19 VERBOSE[4760] logger.c:     -- Executing
Macro("MGCP/aaln/1 at 192.168.1.100-0", "hangupcall") in new stack
Dec 12 12:14:19 VERBOSE[4760] logger.c:     -- Executing
ResetCDR("MGCP/aaln/1 at 192.168.1.100-0", "w") in new stack
Dec 12 12:14:19 DEBUG[4760] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2005-12-12
12:11:09','1169','1169','915164873','from-internal',
'MGCP/aaln/1 at 192.168.1.100-0','Zap/2-1','ResetCDR','w',190,184,'ANSWERED',3,'','asterisk-3094-1134385866.279')
Dec 12 12:14:19 VERBOSE[4760] logger.c:     -- Executing
NoCDR("MGCP/aaln/1 at 192.168.1.100-0", "") in new stack
Dec 12 12:14:19 WARNING[4760] cdr.c: CDR on channel
'MGCP/aaln/1 at 192.168.1.100-0' not posted
Dec 12 12:14:19 WARNING[4760] cdr.c: CDR on channel
'MGCP/aaln/1 at 192.168.1.100-0' lacks end
Dec 12 12:14:19 VERBOSE[4760] logger.c:     -- Executing
Wait("MGCP/aaln/1 at 192.168.1.100-0", "5") in new stack
Dec 12 12:14:19 DEBUG[3162] chan_mgcp.c: Coundn't determine
subchannel, assuming current master aaln/1 at 192.168.1.100-0
Dec 12 12:14:19 DEBUG[3162] chan_mgcp.c: Endpoint
'aaln/1 at 192.168.1.100-0' observed 'hu'
Dec 12 12:14:19 DEBUG[3162] chan_mgcp.c: MGCP aaln/1 at 192.168.1.100 Went on hook
Dec 12 12:14:19 VERBOSE[4760] logger.c:   == Spawn extension
(macro-hangupcall, s, 3) exited non-zero on
'MGCP/aaln/1 at 192.168.1.100-0' in macro 'hangupcall'
Dec 12 12:14:19 VERBOSE[4760] logger.c:   == Spawn extension
(from-internal, h, 1) exited non-zero on 'MGCP/aaln/1 at 192.168.1.100-0'
Dec 12 12:14:19 DEBUG[4760] chan_mgcp.c: Slow sequence is 0
Dec 12 12:14:19 DEBUG[4760] chan_mgcp.c: Slow sequence is 0
Dec 12 12:14:19 DEBUG[4760] chan_mgcp.c: Slow sequence is 0
Dec 12 12:14:19 DEBUG[3162] chan_mgcp.c: Got response back on transaction 699
Dec 12 12:14:19 DEBUG[3162] chan_mgcp.c: Got response back on transaction 700
Dec 12 12:14:19 DEBUG[3162] chan_mgcp.c: Got response back on transaction 701
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 DEBUG[4845] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:14:59 VERBOSE[4839] logger.c:     -- Executing
Dial("Zap/1-1",
"MGCP/aaln/1 at 192.168.1.104&MGCP/aaln/2 at 192.168.1.103|10|tTrwW") in new
stack
Dec 12 12:14:59 DEBUG[4839] chan_mgcp.c: Coundn't determine
subchannel, assuming current master aaln/1 at 192.168.1.104-1
Dec 12 12:36:45 VERBOSE[5039] logger.c:     -- Reloading module
'chan_mgcp.so' (Media Gateway Control Protocol (MGCP))
Dec 12 12:36:45 VERBOSE[5039] logger.c: Previous mgcp reload not yet done
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'
Dec 12 12:36:45 DEBUG[5039] channel.c: Avoiding initial deadlock for
'MGCP/aaln/1 at 192.168.1.104-1'

--
Alejandro Vargas