Disconnected from Server

zodell · May 15, 2007, 5:26pm

I have a new installation of * installed at a customer site and I keep the console running on my PC so that I monitor the calls and the system. Twice in the last two days, I have been disconnected from the console and * has stopped running.

This didn’t happen at the same time during the day, nor did it occur when a common application (DIAL/VOICEMAIL) was used. I have enabled debugging and verbose to /var/log/asterisk/message and have caught the last disconnect.

/var/log/asterisk/message

[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '6205555555'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '95555555'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'default'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'SIP/1018-b6a22460'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'Zap/2-1'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'Dial'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'Zap/g1/555555'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '2007-05-15 10:53:32'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '2007-05-15 10:53:37'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '2007-05-15 10:55:41'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '129'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '124'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'ANSWERED'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is 'DOCUMENTATION'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is ''
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is '1179244412.457'
[May 15 10:55:41] DEBUG[30466] pbx.c: Function result is ''
[May 15 10:55:42] DEBUG[30476] channel.c: Didn't get a frame from channel: SIP/1015-b6a288d0
[May 15 10:55:42] DEBUG[30476] channel.c: Bridge stops bridging channels SIP/1015-b6a288d0 and Zap/1-1
[May 15 10:55:42] DEBUG[30476] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[May 15 10:55:42] DEBUG[30476] chan_zap.c: Hangup: channel: 1 index = 0, normal = 10, callwait = -1, thirdcall = -1
[May 15 10:55:42] DEBUG[30476] chan_zap.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[May 15 10:55:42] DEBUG[30476] chan_zap.c: disabled echo cancellation on channel 1
[May 15 10:55:42] DEBUG[30476] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
[May 15 10:55:42] DEBUG[30476] chan_zap.c: Updated conferencing on 1, with 0 conference users
[May 15 10:55:42] DEBUG[30476] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
[May 15 10:55:42] DEBUG[30476] chan_zap.c: disabled echo cancellation on channel 1
[May 15 10:55:42] VERBOSE[30476] logger.c:     -- Hungup 'Zap/1-1'
[May 15 10:55:42] VERBOSE[30476] logger.c:   == Spawn extension (default, 5555555, 1) exited non-zero on 'SIP/1015-b6a288d0'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '"" <620555555>'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '620555555'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '95555555'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'default'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'SIP/1015-b6a288d0'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'Zap/1-1'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'Dial'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'Zap/g1/5555555'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '2007-05-15 10:54:07'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '2007-05-15 10:54:12'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '2007-05-15 10:55:42'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '95'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '90'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'ANSWERED'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is 'DOCUMENTATION'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is ''
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is '1179244447.459'
[May 15 10:55:42] DEBUG[30476] pbx.c: Function result is ''
[May 15 10:55:47] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:47] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:47] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:55:47] VERBOSE[30568] logger.c:     -- Playing 'vm-helpexit' (language 'en')
[May 15 10:55:50] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:50] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:54] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:55:54] VERBOSE[30568] logger.c:     -- Playing 'vm-deleted' (language 'en')
[May 15 10:55:56] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:56] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:56] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:55:56] VERBOSE[30568] logger.c:     -- Playing 'vm-onefor' (language 'en')
[May 15 10:55:57] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:57] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:57] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:55:57] VERBOSE[30568] logger.c:     -- Playing 'vm-Old' (language 'en')
[May 15 10:55:58] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:58] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:58] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:55:58] VERBOSE[30568] logger.c:     -- Playing 'vm-messages' (language 'en')
[May 15 10:55:59] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:59] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:55:59] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:55:59] VERBOSE[30568] logger.c:     -- Playing 'vm-opts' (language 'en')
[May 15 10:56:00] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:00] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:00] VERBOSE[30568] logger.c:     -- Playing 'vm-first' (language 'en')
[May 15 10:56:01] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:01] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:01] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:01] VERBOSE[30568] logger.c:     -- Playing 'vm-message' (language 'en')
[May 15 10:56:02] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:02] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:02] VERBOSE[30568] logger.c:   == Parsing '/var/spool/asterisk/voicemail/default/1002/Old/msg0000.txt': [May 15 10:56:02] VERBOSE[30568] logger.c: Found
[May 15 10:56:02] DEBUG[30568] say.c: Parsing ' (offset 0) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:02] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:02] VERBOSE[30568] logger.c:     -- Playing 'vm-received' (language 'en')
[May 15 10:56:03] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:03] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:03] DEBUG[30568] say.c: Parsing   (offset 13) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:03] DEBUG[30568] say.c: Parsing q (offset 14) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:03] DEBUG[30568] say.c: Parsing A (offset 0) in A
[May 15 10:56:03] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:03] VERBOSE[30568] logger.c:     -- Playing 'digits/day-5' (language 'en')
[May 15 10:56:04] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:04] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:04] DEBUG[30568] say.c: Parsing   (offset 15) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:04] DEBUG[30568] say.c: Parsing ' (offset 16) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:04] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:04] VERBOSE[30568] logger.c:     -- Playing 'digits/at' (language 'en')
[May 15 10:56:05] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:05] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:05] DEBUG[30568] say.c: Parsing   (offset 27) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:05] DEBUG[30568] say.c: Parsing I (offset 28) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:05] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:05] VERBOSE[30568] logger.c:     -- Playing 'digits/1' (language 'en')
[May 15 10:56:06] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:06] DEBUG[30568] channel.c: Scheduling timer at 0 sample intervals
[May 15 10:56:06] DEBUG[30568] say.c: Parsing M (offset 29) in 'vm-received' q 'digits/at' IMp
[May 15 10:56:06] DEBUG[30568] channel.c: Scheduling timer at 160 sample intervals
[May 15 10:56:06] VERBOSE[30568] logger.c:     -- Playing 'digits/10' (language 'en')

*Disconnect happens here*


*Restart Asterisk here w/ astersik -cvvvvvv*

[May 15 10:56:12] VERBOSE[30604] logger.c: Asterisk Event Logger Started /var/log/asterisk/event_log
[May 15 10:56:12] VERBOSE[30604] logger.c: Asterisk Dynamic Loader Starting:
[May 15 10:56:12] VERBOSE[30604] logger.c:   == Parsing '/etc/asterisk/modules.conf': [May 15 10:56:12] VERBOSE[30604] logger.c: Found
[May 15 10:56:12] VERBOSE[30604] logger.c:   == Parsing '/etc/asterisk/dnsmgr.conf': [May 15 10:56:12] VERBOSE[30604] logger.c: Found
[May 15 10:56:12] VERBOSE[30604] logger.c:   == Parsing '/etc/asterisk/http.conf': [May 15 10:56:12] VERBOSE[30604] logger.c: Found
[May 15 10:56:12] VERBOSE[30604] logger.c:   == Manager registered action Ping
[May 15 10:56:12] VERBOSE[30604] logger.c:   == Manager registered action Events

I have been using asterisk for several years and have never seen this problem before. It is almost like “stop now” was issued. It has never hung after restarting the process.

Any help would be appreciated.

Dell Poweredge 2860
TE405P
Asterisk 1.4.0

zodell · May 23, 2007, 4:12pm

^bump^

zodell · May 29, 2007, 2:53pm

So I started asterisk with /usr/sbin/safe_asterisk and asterisk died.

Last Three Lines of /tmp/core.xxxxx

Core was generated by `/usr/sbin/asterisk -vvvg -c'.
Program terminated with signal 11, Segmentation fault.
#0  0xb7f6cfcd in pthread_mutex_lock () from /lib/libpthread.so.0

Any suggestions?

dswartz · June 2, 2007, 1:38am

have you run memtest86?

zodell · June 2, 2007, 5:38pm

No I haven’t.

From what I read, it can take some time to test the RAM on the server. The problem is this. This server is in a production environment that is open 24/7. I don’t have any way to down this server for even 30 min.

Is there any other method, other than BIOS to test the mem?

zodell · June 6, 2007, 5:20pm

So here is some more info. Asterisk has died twice today.

Here is the core dump w/ bt full

1st Crash

Core was generated by `/usr/sbin/asterisk -vvvvvvvvvvvvvvvg -c'.
Program terminated with signal 11, Segmentation fault.
#0  0xb741dab0 in __sip_destroy (p=0xb6b0a9d0, lockowner=1) at chan_sip.c:2950
2950            ast_string_field_free_pools(p);



(gdb) bt full
#0  0xb741dab0 in __sip_destroy (p=0xb6b0a9d0, lockowner=1) at chan_sip.c:2950
        this = (struct ast_string_field_pool *) 0x302074
        prev = <value optimized out>
        cur = <value optimized out>
        cp = (struct sip_pkt *) 0x0
        __PRETTY_FUNCTION__ = "__sip_destroy"
#1  0xb742f2cc in __sip_autodestruct (data=0xb6b0a9d0) at chan_sip.c:3081
        p = (struct sip_pvt *) 0x302074
        __PRETTY_FUNCTION__ = "__sip_autodestruct"
#2  0x080e27fc in ast_sched_runq (con=0x81b56d0) at sched.c:358
        numevents = 0
        res = <value optimized out>
#3  0xb7436e04 in do_monitor (data=0x0) at chan_sip.c:14863
        prev = <value optimized out>
        res = 5
        sip = (struct sip_pvt *) 0x0
        t = 1181130703
        fastrestart = 0
        lastpeernum = -1
        curpeernum = 45
        reloading = <value optimized out>
        __PRETTY_FUNCTION__ = "do_monitor"
#4  0x080ed780 in dummy_start (data=0x81b9ae8) at utils.c:545
---Type <return> to continue, or q <return> to quit---
        _buffer = {__routine = 0x8069ad0 <ast_unregister_thread>,
  __arg = 0x20008, __canceltype = -1210627232, __prev = 0x0}
        ret = <value optimized out>
#5  0xb7f01b51 in pthread_start_thread () from /lib/libpthread.so.0
No symbol table info available.
#6  0xb7d3874a in clone () from /lib/libc.so.6
No symbol table info available.

2nd Crash

[code]
Core was generated by `/usr/sbin/asterisk -vvvvvvvvvvvvvvvg -c’.
Program terminated with signal 11, Segmentation fault.
#0 0xb744a407 in reqprep (req=0xb6ab602c, p=0xb68065f0, sipmethod=8,
seqno=102, newbranch=1)
at /root/archive/asterisk-1.4.0/include/asterisk/strings.h:35
35 return (!s || (*s == ‘\0’));

#0 0xb744a407 in reqprep (req=0xb6ab602c, p=0xb68065f0, sipmethod=8, seqno=102, newbranch=1) at /root/archive/asterisk-1.4.0/include/asterisk/strings.h:35
orig = (struct sip_request *) 0xb68068f4
stripped = “\000\000\000\000\000\000\000\000Â¬Ã½\026\b”, ‘\0’ <repeats 28 times>, “Ã¿Ã¿Ã¿Ã¿+\000\000\000GÂ£\022\bÂ¤dÂ«Â¶”, ‘\0’ <repeats 12 times>, "\001\000\000\000\000\000\000\000\000\000\000"
tmp = "Ã€Â£Ã