9 Aug
2011
9 Aug
'11
5:17 p.m.
Hello,
Any further insight any of you can provide is very much appreciated.
Here is the core dump syslog:
Aug 9 13:42:10 kernel: [80782620.026999] kamailio[21378]: segfault at
7f269f026e5c ip 7f1c24f72969 sp 7fff3452bbe0 error 4 in
dialog.so[7f1c24f53000+3a000]
Aug 9 13:42:10 /usr/local/sbin/kamailio[21368]: INFO: <core> [main.c:756]:
INFO: terminating due to SIGCHLD
Aug 9 13:42:10 /usr/local/sbin/kamailio[21369]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21370]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21376]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21371]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21372]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21377]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21379]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21374]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21373]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Aug 9 13:42:10 /usr/local/sbin/kamailio[21375]: INFO: <core> [main.c:807]:
INFO: signal 15 received
Here is the full backtrace from GDB:
Program terminated with signal 11, Segmentation fault.
[New process 21378]
#0 unref_dlg (dlg=0x7f1c15232238, cnt=1) at dlg_hash.c:599
599 dlg_lock( d_table, d_entry);
(gdb) bt full
#0 unref_dlg (dlg=0x7f1c15232238, cnt=1) at dlg_hash.c:599
d_entry = (struct dlg_entry *) 0x7f269f026e48
#1 0x00007f1c29fd4a82 in run_trans_callbacks_internal
(cb_lst=0x7f1c1538b6e0, type=32768, trans=0x7f1c1538b670,
params=0x7fff3452bd40) at t_hooks.c:290
cbp = (struct tm_callback *) 0x7f1c1529a170
backup_from = (avp_list_t *) 0x8b4350
backup_to = (avp_list_t *) 0x8b4358
backup_dom_from = (avp_list_t *) 0x8b4360
backup_dom_to = (avp_list_t *) 0x8b4368
backup_uri_from = (avp_list_t *) 0x8b4340
backup_uri_to = (avp_list_t *) 0x8b4348
#2 0x00007f1c29fd4cd6 in run_trans_callbacks (type=32768, trans=<value
optimized out>, req=0x1, rpl=0x7f269f026e48, code=622390088) at
t_hooks.c:317
params = {req = 0x0, rpl = 0x0, param = 0x7f1c1529a180, code = 0,
flags = 0, branch = 0, t_rbuf = 0x0, dst = 0x0, send_buf = {s = 0x0, len =
0}}
#3 0x00007f1c29fbab46 in free_cell (dead_cell=0x7f1c1538b670) at
h_table.c:152
b = <value optimized out>
i = <value optimized out>
rpl = <value optimized out>
tt = <value optimized out>
foo = <value optimized out>
cbs = <value optimized out>
__FUNCTION__ = "free_cell"
#4 0x00007f1c29fd6a71 in wait_handler (ti=<value optimized out>,
wait_tl=<value optimized out>, data=<value optimized out>) at timer.c:645
p_cell = (struct cell *) 0x7f1c1538b670
#5 0x000000000051463f in timer_main () at timer.c:894
No locals.
#6 0x0000000000465101 in main_loop () at main.c:1630
i = 8
pid = <value optimized out>
si = (struct socket_info *) 0x0
si_desc = "udp receiver child=7
sock=67.XXX.XXX.XXX:5060\000\000\000\000\000HÂ\232\000\000\000\000\000\f\000\000\000\000\000\000\000X\023\220",
'\0' <repeats 13 times>,
"t\000\000\000ÿ\177\000\000\030\205ø\024\001\000\000\000\001\000\000\000\000\000\000\000\002",
'\0' <repeats 22 times>
#7 0x00000000004680f3 in main (argc=<value optimized out>,
argv=0x7fff3452c138) at main.c:2410
cfg_stream = (FILE *) 0x1c86010
c = <value optimized out>
r = <value optimized out>
tmp = 0x7fff3452de5f ""
tmp_len = 32540
port = <value optimized out>
proto = <value optimized out>
ret = <value optimized out>
seed = 3355938686
rfd = 4
debug_save = <value optimized out>
debug_flag = 0
dont_fork_cnt = 0
n_lst = <value optimized out>
p = <value optimized out>
Sincerely,
Brandon Armstead
9 Aug
9 Aug
6:08 p.m.
Hello Brandon,
On 09.08.2011 16:17, Brandon Armstead wrote:
Hello,
Any further insight any of you can provide is very much appreciated.
Here is the core dump syslog:
[snip!]
A few months ago, Anton Roman provided a core dump looking very similar
to yours. I wasn't exactly able to pin down the cause but suspected the
dlg_end_dlg() function.
Is there a chance you used that function around the time the crash happened?
Cheers,
--Timo
6:16 p.m.
Timo,
I have actually been researching that thread - it does look *similar*
however it does not look 100% related. I am checking out that commit now
however - and will see if it resolves the same issue.
As for dlg_end_dlg - I am not calling this via FIFO or anything - I am
simply calling dlg_manage() in the routing config - however I am not sure if
this is being called internally (I assume that it is) upon a dialog cleanup?
Sincerely,
Brandon Armstead
On Tue, Aug 9, 2011 at 8:08 AM, Timo Reimann <timo.reimann(a)1und1.de> wrote:
Hello Brandon,
On 09.08.2011 16:17, Brandon Armstead wrote:
Hello,
Any further insight any of you can provide is very much appreciated.
Here is the core dump syslog:
[snip!]
A few months ago, Anton Roman provided a core dump looking very similar
to yours. I wasn't exactly able to pin down the cause but suspected the
dlg_end_dlg() function.
Is there a chance you used that function around the time the crash
happened?
Cheers,
--Timo
6:37 p.m.
Timo,
Looks like that worked - going to keep watching it and see what happens.
However I am now getting:
Aug 9 15:34:00 /usr/local/sbin/kamailio[3040]: CRITICAL: dialog
[dlg_timer.c:138]: Trying to insert a bogus dlg tl=0x7f8dc8089368
tl->next=0x7f8dc80202e0 tl->prev=0x7f8dc8108b68
Aug 9 15:34:00 /usr/local/sbin/kamailio[3040]: CRITICAL: dialog
[dlg_handlers.c:373]: Unable to insert dlg 0x7f8dc8089318 [603:994585481] on
event 3 [2->3] with clid 'CINMGC0320110809153354004076(a)XXX.XXX.XXX.XXX' and
tags 'VPSF506071629460' 'gK0cc7be82'
Which looks similar to the original thread? Not sure if there is still an
underlying issue that I should be wary of?
Sincerely,
Brandon Armrstead
On Tue, Aug 9, 2011 at 8:16 AM, Brandon Armstead <brandon(a)cryy.com> wrote:
Timo,
I have actually been researching that thread - it does look *similar*
however it does not look 100% related. I am checking out that commit now
however - and will see if it resolves the same issue.
As for dlg_end_dlg - I am not calling this via FIFO or anything - I am
simply calling dlg_manage() in the routing config - however I am not sure if
this is being called internally (I assume that it is) upon a dialog cleanup?
Sincerely,
Brandon Armstead
On Tue, Aug 9, 2011 at 8:08 AM, Timo Reimann <timo.reimann(a)1und1.de>wrote;wrote:
Hello Brandon,
On 09.08.2011 16:17, Brandon Armstead wrote:
Hello,
Any further insight any of you can provide is very much appreciated.
Here is the core dump syslog:
[snip!]
A few months ago, Anton Roman provided a core dump looking very similar
to yours. I wasn't exactly able to pin down the cause but suspected the
dlg_end_dlg() function.
Is there a chance you used that function around the time the crash
happened?
Cheers,
--Timo
6:54 p.m.
Timo,
Looks like I spoke too soon! It is still happening.
Any additional thoughts? All and any help is greatly appreciated.
Sincerely,
Brandon Armstead
On Tue, Aug 9, 2011 at 8:37 AM, Brandon Armstead <brandon(a)cryy.com> wrote:
Timo,
Looks like that worked - going to keep watching it and see what happens.
However I am now getting:
Aug 9 15:34:00 /usr/local/sbin/kamailio[3040]: CRITICAL: dialog
[dlg_timer.c:138]: Trying to insert a bogus dlg tl=0x7f8dc8089368
tl->next=0x7f8dc80202e0 tl->prev=0x7f8dc8108b68
Aug 9 15:34:00 /usr/local/sbin/kamailio[3040]: CRITICAL: dialog
[dlg_handlers.c:373]: Unable to insert dlg 0x7f8dc8089318 [603:994585481] on
event 3 [2->3] with clid 'CINMGC0320110809153354004076(a)XXX.XXX.XXX.XXX'
and tags 'VPSF506071629460' 'gK0cc7be82'
Which looks similar to the original thread? Not sure if there is still an
underlying issue that I should be wary of?
Sincerely,
Brandon Armrstead
On Tue, Aug 9, 2011 at 8:16 AM, Brandon Armstead <brandon(a)cryy.com> wrote:
Timo,
I have actually been researching that thread - it does look *similar*
however it does not look 100% related. I am checking out that commit now
however - and will see if it resolves the same issue.
As for dlg_end_dlg - I am not calling this via FIFO or anything - I am
simply calling dlg_manage() in the routing config - however I am not sure if
this is being called internally (I assume that it is) upon a dialog cleanup?
Sincerely,
Brandon Armstead
On Tue, Aug 9, 2011 at 8:08 AM, Timo Reimann <timo.reimann(a)1und1.de>wrote;wrote:
Hello Brandon,
On 09.08.2011 16:17, Brandon Armstead wrote:
Hello,
Any further insight any of you can provide is very much appreciated.
Here is the core dump syslog:
[snip!]
A few months ago, Anton Roman provided a core dump looking very similar
to yours. I wasn't exactly able to pin down the cause but suspected the
dlg_end_dlg() function.
Is there a chance you used that function around the time the crash
happened?
Cheers,
--Timo
7:25 p.m.
Hey Brandon,
On 09.08.2011 17:54, Brandon Armstead wrote:
Looks like I spoke too soon! It is still
happening.
Any additional thoughts? All and any help is greatly appreciated.
My original theory with Anton's issue was (and still is) that the dialog
module is trying to touch a dialog which has already terminated. When
provoking things like that through modifications in the dialog module,
we encountered crashes at similar locations in the code.
Is there any chance you can provide me with some (anonymized) SIP
traces? Dissecting this problem has proven to be very hard even when
given a lot of details, such as Anton's core dumps. Not being able to
reconstruct the call flow has been a show stopper so far.
On Tue, Aug 9, 2011 at 8:37 AM, Brandon Armstead
<brandon(a)cryy.com
<mailto:brandon@cryy.com>> wrote:
Timo,
Looks like that worked - going to keep watching it and see what happens.
However I am now getting:
Aug 9 15:34:00 /usr/local/sbin/kamailio[3040]: CRITICAL: dialog
[dlg_timer.c:138]: Trying to insert a bogus dlg tl=0x7f8dc8089368
tl->next=0x7f8dc80202e0 tl->prev=0x7f8dc8108b68
Aug 9 15:34:00 /usr/local/sbin/kamailio[3040]: CRITICAL: dialog
[dlg_handlers.c:373]: Unable to insert dlg 0x7f8dc8089318
[603:994585481] on event 3 [2->3] with clid
'CINMGC0320110809153354004076(a)XXX.XXX.XXX.XXX' and tags
'VPSF506071629460' 'gK0cc7be82'
Which looks similar to the original thread? Not sure if there is
still an underlying issue that I should be wary of?
This seems to be related to setting up the dialog timer on reception of
a 200 OK message when the given dialog was about to transition from the
"early" state (18x reply seen) to the "confirmed without ACK" state
(200
OK seen, ACK still outstanding).
Not quite sure what this means but it could possibly be just another
manifestation of the same bug.
Cheers,
--Timo
On Tue, Aug 9, 2011 at 8:16 AM, Brandon Armstead
<brandon(a)cryy.com
<mailto:brandon@cryy.com>> wrote:
Timo,
I have actually been researching that thread - it does look
*similar* however it does not look 100% related. I am checking
out that commit now however - and will see if it resolves the
same issue.
As for dlg_end_dlg - I am not calling this via FIFO or anything
- I am simply calling dlg_manage() in the routing config -
however I am not sure if this is being called internally (I
assume that it is) upon a dialog cleanup?
Sincerely,
Brandon Armstead
On Tue, Aug 9, 2011 at 8:08 AM, Timo Reimann
<timo.reimann(a)1und1.de <mailto:timo.reimann@1und1.de>> wrote:
Hello Brandon,
On 09.08.2011 16:17, Brandon Armstead wrote:
Hello,
Any further insight any of you can provide is very much
appreciated.
Here is the core dump syslog:
[snip!]
A few months ago, Anton Roman provided a core dump looking
very similar
to yours. I wasn't exactly able to pin down the cause but
suspected the
dlg_end_dlg() function.
Is there a chance you used that function around the time the
crash happened?
Cheers,
--Timo
15 Aug
15 Aug
12:31 p.m.
Hey,
On 09.08.2011 18:25, Timo Reimann wrote:
On 09.08.2011 17:54, Brandon Armstead wrote:
Git commit 7afb2cf8e fixes the issue. The cause was a race condition
(most likely only manifesting when storing dialogs in the database in
real-time) in conjunction with some awkward call flow behavior that
would lead to the dialog timer list being messed up in rare situations.
In consequence, this let to incorrect reference counting and, in turn,
premature dialog termination.
Along the way, we found another related bug that would cause the
"dlg_list" fifo command to crash Kamailio in certain situations when
dialogs were restored from database. Commit ab21b2565 fixes this.
Major credits go to Brendon Armstead for giving out constant
information, feedback, and overall assistance!
Cheers,
--Timo
Looks like I spoke too soon! It is still
happening.
Any additional thoughts? All and any help is greatly appreciated.
My original theory with Anton's issue was (and still is) that the dialog
module is trying to touch a dialog which has already terminated. When
provoking things like that through modifications in the dialog module,
we encountered crashes at similar locations in the code.
1:12 p.m.
Timo,
Thanks for solving this one!
On Aug 15, 2011, at 2:31 AM, Timo Reimann <timo.reimann(a)1und1.de> wrote:
Hey,
On 09.08.2011 18:25, Timo Reimann wrote:
On 09.08.2011 17:54, Brandon Armstead wrote:
Git commit 7afb2cf8e fixes the issue. The cause was a race condition
(most likely only manifesting when storing dialogs in the database in
real-time) in conjunction with some awkward call flow behavior that
would lead to the dialog timer list being messed up in rare situations.
In consequence, this let to incorrect reference counting and, in turn,
premature dialog termination.
Along the way, we found another related bug that would cause the
"dlg_list" fifo command to crash Kamailio in certain situations when
dialogs were restored from database. Commit ab21b2565 fixes this.
Major credits go to Brendon Armstead for giving out constant
information, feedback, and overall assistance!
Cheers,
--Timo Looks like I spoke too soon! It is still
happening.
Any additional thoughts? All and any help is greatly appreciated.
My original theory with Anton's issue was (and still is) that the dialog
module is trying to touch a dialog which has already terminated. When
provoking things like that through modifications in the dialog module,
we encountered crashes at similar locations in the code.
4878
days inactive
4884
days old
7 comments
2 participants
participants (2)
-
Brandon Armstead -
Timo Reimann