Bug#498399: asterisk: random segfaults
On Tue, Sep 16, 2008 at 02:27:00PM +0200, Lionel Elie Mamane wrote: >> Asterisk seemingly randomly dies (...) (...) provide a backtrace with gdb >> I've enabled SIP history (dumping) and debug, and restarted >> asterisk. Next segfault will have more information in log. > Here it is. Note that I register to phonesystems.net *twice*, with > two different usernames; that is probably ultimately the source of > the problem, the two registrations get confused or something like > that. Indeed, I disabled one of the two registrations, and now Asterisk has been running for nearly a month without crash. -- Lionel -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
Bug#498399: asterisk: random segfaults
On Wed, Sep 10, 2008 at 02:01:52PM +0200, Lionel Elie Mamane wrote: > On Wed, Sep 10, 2008 at 03:51:22AM +0300, Faidon Liambotis wrote: >> Lionel Elie Mamane wrote: >>> On Tue, Sep 09, 2008 at 09:04:43PM +0200, Lionel Elie Mamane wrote: Asterisk seemingly randomly dies (...) >> (...) provide a backtrace with gdb > #0 handle_response_register (p=0x748910, resp=408, rest=0x401a1e84 > "Request Timeout", req=0x401a1a50, ignore=0, seqno=298) at > chan_sip.c:12552 I've enabled SIP history (dumping) and debug, and restarted asterisk. Next segfault will have more information in log. -- Lionel -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
Bug#498399: asterisk: random segfaults
On Wed, Sep 10, 2008 at 03:51:22AM +0300, Faidon Liambotis wrote:
> Lionel Elie Mamane wrote:
>> On Tue, Sep 09, 2008 at 09:04:43PM +0200, Lionel Elie Mamane wrote:
>>> Asterisk seemingly randomly dies (...)
> (...) provide a backtrace with gdb
#0 handle_response_register (p=0x748910, resp=408, rest=0x401a1e84 "Request
Timeout", req=0x401a1a50, ignore=0, seqno=298) at chan_sip.c:12552
expires =
expires_ms =
r = (struct sip_registry *) 0x0
__PRETTY_FUNCTION__ = "handle_response_register"
#1 0x2aaab5d46aaa in handle_response (p=0x748910, resp=408,
rest=0x401a1e84 "Request Timeout", req=0x401a1a50, ignore=0, seqno=298) at
chan_sip.c:12867
owner = (struct ast_channel *) 0x0
sipmethod = 2
c =
msg = 0x401a1fbb "REGISTER"
__PRETTY_FUNCTION__ = "handle_response"
#2 0x2aaab5d485aa in handle_request (p=0x748910, req=0x401a1a50,
sin=0x401a2f80, recount=0x401a2f94, nounlock=0x401a2f98) at chan_sip.c:15329
cmd = 0x401a1e78 "SIP/2.0"
cseq =
useragent =
seqno = 298
len =
ignore =
respid = 408
res = 0
debug = 0
e = 0x401a1e80 "408 Request Timeout"
__PRETTY_FUNCTION__ = "handle_request"
#3 0x2aaab5d49fd7 in sipsock_read (id=, fd=, events=, ignore=)
at chan_sip.c:15562
req = {rlPart1 = 0x401a1e78 "SIP/2.0", rlPart2 = 0x401a1e80 "408
Request Timeout", len = 649, headers = 10, method = 1, lines = 0, flags = 0,
header = {
0x401a1e78 "SIP/2.0", 0x401a1e95 "Via: SIP/2.0/UDP
193.202.115.224:5060;branch=z9hG4bK3c8bc4db;rport=5060",
0x401a1ede "From: ;tag=as152f9fdc",
0x401a1f1b "To: ;tag=c16928e0b64c75110ac550bd62be7243-8035",
0x401a1f71 "Call-ID: [EMAIL PROTECTED]", 0x401a1fb1 "CSeq: 298 REGISTER",
0x401a1fc5 "Contact: ;expires=600", 0x401a2002
"Server: PSN Sip Proxy (1.1.3 (PRX3-EXTERNAL))",
0x401a2031 "Content-Length: 0",
0x401a2044 "Warning: 392 213.11.62.39:5060 \"Noisy feedback tells:
pid=2468 req_src_ip=193.202.115.224 req_src_port=5060
in_uri=sip:sip.phonesystems.net out_uri=sip:sip.phonesystems.net via_cnt==0\"",
0x401a20ff "", 0x0 }, line = {0x401a2101 "", 0x0 },
data = "SIP/2.0\000408 Request Timeout\000\000Via: SIP/2.0/UDP
193.202.115.224:5060;branch=z9hG4bK3c8bc4db;rport=5060\000\000From: ;tag=as152f9fdc\000\000To:
len = 16
nounlock = 0
recount = 0
lockretry = 100
__PRETTY_FUNCTION__ = "sipsock_read"
#4 0x0045ace2 in ast_io_wait (ioc=0x2c041460, howlong=) at io.c:279
res =
#5 0x2aaab5d4e369 in do_monitor (data=) at
chan_sip.c:15775
res =
sip = (struct sip_pvt *) 0x0
t = 1221047345
fastrestart = 0
lastpeernum = -1
curpeernum =
reloading = 0
__PRETTY_FUNCTION__ = "do_monitor"
#6 0x0049b76c in dummy_start (data=) at
utils.c:895
__cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf =
{46912518791008, -5074825979469889938, 140735903873008, 47755899604736, 0,
4096,
-5074966769022140818, -5074826448064086418}, __mask_was_saved = 0}},
__pad = {0x401a31e0, 0x0, 0x0, 0x0}}
not_first_call =
ret =
#7 0x2b6f096e8fc7 in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#8 0x2b6f0a0a47cd in clone () from /lib/libc.so.6
No symbol table info available.
#9 0x in ?? ()
No symbol table info available.
The end of the log:
[Sep 10 13:48:48] DEBUG[585] chan_sip.c: ** SIP timers: Rescheduling
retransmission 2 to 1000 ms (t1 500 ms (Retrans id #2249))
[Sep 10 13:48:48] DEBUG[589] chan_iax2.c: Allocate call number
[Sep 10 13:48:48] DEBUG[589] chan_iax2.c: Registration created on call 1769
[Sep 10 13:48:49] DEBUG[585] chan_sip.c: ** SIP timers: Rescheduling
retransmission 3 to 2000 ms (t1 500 ms (Retrans id #2249))
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: ** SIP timers: Rescheduling
retransmission 4 to 4000 ms (t1 500 ms (Retrans id #2249))
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: = Found Their Call ID: [EMAIL
PROTECTED] Their Tag Our tag: as7128f565
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: Stopping retransmission on '[EMAIL
PROTECTED]' of Request 297: Match Found
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: Initializing already initialized SIP
dialog [EMAIL PROTECTED] (presumably reinvite)
[Sep 10 13:48:51] VERBOSE[585] logger.c: REGISTER attempt 181 to [EMAIL
PROTECTED]
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: = Found Their Call ID: [EMAIL
PROTECTED] Their Tag Our tag: as152f9fdc
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: Stopping retransmission on '[EMAIL
PROTECTED]' of Request 298: Match Found
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: Registration successful
[Sep 10 13:48:51] DEBUG[585] chan_sip.c: Cancelling timeout 2248
[Sep 10 13:48:57] DEBUG[599] pbx_dundi.c: Got canonical message 13 (0), 160
bytes data
[Sep 10 13:48:57] DEBUG[599] pbx_dundi.c: Expected
Bug#498399: asterisk: random segfaults
On Wed, Sep 10, 2008 at 11:19:59AM +0200, Lionel Elie Mamane wrote: (...) > but no corefile. OK, I have understood why I was not getting a corefile. (See my commit of revision 6188.) Just have to wait now. -- Lionel -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
Bug#498399: asterisk: random segfaults
On Wed, Sep 10, 2008 at 03:51:22AM +0300, Faidon Liambotis wrote: > Have a look at /etc/default/asterisk and try to get a corefile. I set: AST_DUMPCORE=yes CORE_PATTERN='core.%p.%e.%t' and /etc/init.d/asterisk set by default: AST_DUMPCORE_DIR="/var/spool/asterisk" and restarted Asterisk, naturally. I checked in "ps -Af f" that Asterisk had indeed been started with -g. Asterisk segfaulted: I have this in my syslog Sep 10 09:23:31 agate kernel: asterisk[17687]: segfault at 00e0 rip 2aaab5d44649 rsp 401a11e0 error 6 but no corefile. Please explain to me how I can beat my system into giving me corefile. -- Lionel -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
Bug#498399: asterisk: random segfaults
Lionel Elie Mamane wrote: > On Tue, Sep 09, 2008 at 09:04:43PM +0200, Lionel Elie Mamane wrote: > >> Asterisk seemingly randomly dies (...) > >> Today, I caught it dying while stracing it. > > Another crash and this time I had a console open: I'm afraid straces and console won't help much. Have a look at /etc/default/asterisk and try to get a corefile. After that, it should be easy to provide a backtrace with gdb (ping me if you're wondering how). _That_ would really help :-) Thanks, Faidon -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
Bug#498399: asterisk: random segfaults
On Tue, Sep 09, 2008 at 09:04:43PM +0200, Lionel Elie Mamane wrote: > Asterisk seemingly randomly dies (...) > Today, I caught it dying while stracing it. Another crash and this time I had a console open: Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER Really destroying SIP dialog '[EMAIL PROTECTED]' Method: OPTIONS [Sep 9 22:57:55] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #72) REGISTER attempt 73 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:58:15] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #70) REGISTER attempt 71 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:58:15] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #73) REGISTER attempt 74 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER REGISTER attempt 1 to [EMAIL PROTECTED] [Sep 9 22:58:35] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #71) REGISTER attempt 72 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:58:35] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #74) REGISTER attempt 75 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:58:55] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #72) REGISTER attempt 73 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER Really destroying SIP dialog '[EMAIL PROTECTED]' Method: OPTIONS [Sep 9 22:58:55] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #75) REGISTER attempt 76 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:59:15] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #73) REGISTER attempt 74 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:59:15] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #76) REGISTER attempt 77 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:59:35] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #74) REGISTER attempt 75 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER [Sep 9 22:59:35] NOTICE[8712]: chan_sip.c:7517 sip_reg_timeout:-- Registration for '[EMAIL PROTECTED]' timed out, trying again (Attempt #77) REGISTER attempt 78 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: REGISTER REGISTER attempt 76 to [EMAIL PROTECTED] REGISTER attempt 79 to [EMAIL PROTECTED] Really destroying SIP dialog '[EMAIL PROTECTED]' Method: OPTIONS -- Lionel -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
Bug#498399: asterisk: random segfaults
Package: asterisk
Version: 1:1.4.21.2~dfsg-1+b1
Severity: important
Asterisk seemingly randomly dies and has to be restarted by
hand. Sometimes it holds weeks before dying, but some days it dies 5
times the same day.
Today, I caught it dying while stracing it. The exact strace command was:
strace -s10240 -e
'trace=!poll,ioctl,gettimeofday,time,nanosleep,rt_sigprocmask,rt_sigaction,stat,futex,clock_gettime'
-t -f -o asterisk.strace -p7261
Here is the end of the strace:
8266 19:32:28 brk(0x79)= 0x79
8266 19:32:28 brk(0x78)= 0x78
8266 19:32:28 sendto(11, "\25\3766\203\1\0\r\0\20
\336\363\344\25\346\355\301'!\340\205\20\231=ac/P[\342v\6\2377u\342o^\356\7\362k"...,
42, 0, {sa_family=AF_INET, sin_port=htons(4520),
sin_addr=inet_addr("82.95.233.223")}, 16) = 42
8266 19:32:28 _exit(0) = ?
7283 19:32:28 recvfrom(11, "6\203\25\376\1\1\300\0"..., 8191, 0,
{sa_family=AF_INET, sin_port=htons(4520), sin_addr=inet_addr("82.95.233.223")},
[16]) = 8
7269 19:32:29 recvfrom(8, "\0\0\0\0"..., 4095, 0, {sa_family=AF_INET,
sin_port=htons(5060), sin_addr=inet_addr("67.55.159.160")}, [16]) = 4
7283 19:32:35 recvfrom(11,
"^\v\0\0\0\0\r\0\1\6\0\340\201u\333\253\23\4\36_\206\340\0200\347\221h~\203i\277e\371\226\223Y\242p\335a)7\334I\316\21\354\246E\376h\242s\213\3\24/\253\1\202R\r\3621.\232P\2211\342\10\224"...,
8191, 0, {sa_family=AF_INET, sin_port=htons(4520),
sin_addr=inet_addr("88.207.234.220")}, [16]) = 72
7283 19:32:35 lseek(7, 12288, SEEK_SET) = 12288
7283 19:32:35 write(7,
"\3\0\0\0\2\0\0\0\0\0\0\0\2\0\0\0002\0\204\10$\17\200\0160\r\214\f\354\vH\v\250\n\4\nd\t\300\10\304\17D\16\204\10\370\r\320\rM\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\327\261t\0\0\0\0\0\305^u\0\0\0\0\0k]u\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\350\\u\0\0\0\0\0r^u\0\0\0\0\0{^u\0\0\0\0\0\271]u\0\0\0\0\0\0\237M\0\0\0\0\0c]u\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\370\261t\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\204^u\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0004^u\0\0\0\0\0x]u\0\0\0\0\0\270\261t\0\0\0\0\0\0\237M\0\0\0\0\0\0\237M\0\0\0\0\0\260\261t\0\0\0\0\0\0\4\0\0\0\0\0\0\267\3\0\0\0\0\0\0I\0\0\0\0\0\0\0f\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0f\0\0\0\0\0\0\0\2
\17\n\0\200\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0~\n\23\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\32\204\212'\0\0\0\0as446e958a\0\0\0\0\0\0\0\0\0\0\2\0v\314WFx\273\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\2\0v\314WFx\273\0\0\0\0\0\0\0\0\301\312s\340\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0Init:
[EMAIL PROTECTED]:[EMAIL
PROTECTED]:30412;rinstance=b5a7d515f8014b51\0SIP/2.0\0\0Via: SIP/2.0/UDP
193.202.115.224:5060;branch=z9hG4bK278a841a;rport\0\0From:
\33\0\0\0\27\0\0\0\0/dundi/dpeers/00E08175DBAB\00088.207.234.220:4520:60\4\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1017/lemfat/r\0001220981706|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0\0\0\\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1017/lemfat/e\0001220981706|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0AB|4\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1014/lemfat/r\0001220981701|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0\0\0\\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1014/lemfat/e\0001220981701|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0AB|4\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1013/lemfat/r\0001220981696|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0\0\0\\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1013/lemfat/e\0001220981696|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0AB|4\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1012/lemfat/r\0001220981691|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0\0\0\\0\0\0d\0\0\0\0/dundi/cache/00E08175DBAB/1012/lemfat/e\0001220981691|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/00E08175DBAB|\0wzn\24\0\0\0\v\0\0\0\0/dundi/secretexpiry\0001220983077\0\16\0\0\0002\0\0\0\0/dundi/secret\0MzU2beXhpke2srxA7v84VA==;Bo0KadzIEVtIAUxlgInqJQ==\0di/\33\0\0\0\27\0\0\0\0/dundi/dpeers/003018B026C9\00062.235.221.196:4520:60\4\0\0\0d\0\0\0\0/dundi/cache/003018B026C9/1002/lemfat/r\0001220976290|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/003018B026C9|\0\0\0\\0\0\0d\0\0\0\0/dundi/cache/003018B026C9/1002/lemfat/e\0001220976290|389/0/1/dundi:[EMAIL
PROTECTED]/[EMAIL
PROTECTED]/003018B026C9|\0AB|\33\0\0\0\27\0\0\0\0/dund
