27 Jun
2014
27 Jun
'14
9:35 p.m.
I'm using the latest rtpengine master and still getting crashes once
every 1-2 days on a high call volume installation:
(gdb) where
#0 0x000000304e232925 in raise () from /lib64/libc.so.6
#1 0x000000304e234105 in abort () from /lib64/libc.so.6
#2 0x000000304e22ba4e in __assert_fail_base () from /lib64/libc.so.6
#3 0x000000304e22bb10 in __assert_fail () from /lib64/libc.so.6
#4 0x0000000000412d50 in stream_packet (fd=<value optimized out>, p=
0x7f1dcc1b1030, u=<value optimized out>) at call.c:547
#5 stream_fd_readable (fd=<value optimized out>, p=0x7f1dcc1b1030,
u=<value optimized out>) at call.c:819
#6 0x000000000040b4ce in poller_poll (p=0x10d3750,
timeout=<value optimized out>) at poller.c:354
#7 0x000000000040722d in poller_loop (d=0x10d3750) at main.c:542
#8 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#9 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#10 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Unfortunately, this packet capture is not very insightful. What's the
easiest way to build rtpengine with debug symbols so that some of these
values can be filled in?
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
27 Jun
27 Jun
11:41 p.m.
On 06/27/14 14:35, Alex Balashov wrote:
I'm using the latest rtpengine master and still
getting crashes once
every 1-2 days on a high call volume installation:
(gdb) where
#0 0x000000304e232925 in raise () from /lib64/libc.so.6
#1 0x000000304e234105 in abort () from /lib64/libc.so.6
#2 0x000000304e22ba4e in __assert_fail_base () from /lib64/libc.so.6
#3 0x000000304e22bb10 in __assert_fail () from /lib64/libc.so.6
#4 0x0000000000412d50 in stream_packet (fd=<value optimized out>, p=
0x7f1dcc1b1030, u=<value optimized out>) at call.c:547
#5 stream_fd_readable (fd=<value optimized out>, p=0x7f1dcc1b1030,
u=<value optimized out>) at call.c:819
#6 0x000000000040b4ce in poller_poll (p=0x10d3750,
timeout=<value optimized out>) at poller.c:354
#7 0x000000000040722d in poller_loop (d=0x10d3750) at main.c:542
#8 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#9 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#10 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Unfortunately, this packet capture is not very insightful. What's the
easiest way to build rtpengine with debug symbols so that some of these
values can be filled in?
The easiest way would be to build it with "make debug", this should make
everything visible.
But this backtrace is quite helpful already, as it's a deliberate
assertion that triggers. If you're lucky, you can find the call-id
through the "sfd" struct ("print sfd->call->callid.s"), and then
check
the logs to see what was going on. If that doesn't work, you can send me
both the binary and the core, I may be able to get some details out of it.
cheers
28 Jun
28 Jun
12:26 a.m.
Hi Richard,
Yes indeed, I am able to pull sfd->call->callid.s in frame 4.
The assert is, of course, stream != NULL:
547 assert(stream != NULL);
And that's where it blows up:
(gdb) print stream
$6 = (struct packet_stream *) 0x0
I seem to have some "interesting" calls going through this system, such
that I can deliver you a "monologue == NULL" crash bug one week and a
stream-NULL abrt/exit the next. :-)
I looked up that Call-ID in the logs and saw this kind of call flow:
Jun 27 17:52:59 rtphost /usr/local/sbin/kamailio[30745]: INFO:
[R-OUTBOUND-VENDOR-TRY:33DEF60F-53ADAF79000E9F75-1C569700] -> Channel
utilisation for this gateway: 112/200
Jun 27 17:52:59 rtphost /usr/local/sbin/kamailio[30745]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY:33DEF60F-53ADAF79000E9F75-1C569700] Sending
media through rtpproxy
Jun 27 17:52:59 rtphost /usr/local/sbin/kamailio[30745]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY:33DEF60F-53ADAF79000E9F75-1C569700] ->
Final request URI: sip:14045372369@18.54.79.82:5060;user=phone
Jun 27 17:52:59 rtphost /usr/local/sbin/kamailio[30745]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY-BRANCH:33DEF60F-53ADAF79000E9F75-1C569700]
-> Sending P-Asserted-Identity
Jun 27 17:52:59 rtphost /usr/local/sbin/kamailio[30745]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-TRY-BRANCH:33DEF60F-53ADAF79000E9F75-1C569700]
-> Sending NPDI parameters
Jun 27 17:53:01 rtphost /usr/local/sbin/kamailio[30745]: INFO:
[R-MAIN:33DEF60F-53ADAF79000E9F75-1C569700] CANCEL received from
104.251.251.8
(RURI=sip:14045372369;npdi=yes;rn=14047890081@205.97.81.46:5060;user=phone)
Jun 27 17:53:02 rtphost /usr/local/sbin/kamailio[30749]: INFO:
[R-OUTBOUND-VENDOR-ROUTE-ADVANCE:33DEF60F-53ADAF79000E9F75-1C569700]
Transaction cancelled
I have another crash with this exact same assertion failure. I'll try to
look up its Call-ID (if I still have the logs) and see if it follows a
similar pattern.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
12:28 a.m.
On 06/27/14 17:26, Alex Balashov wrote:
Hi Richard,
Yes indeed, I am able to pull sfd->call->callid.s in frame 4.
The assert is, of course, stream != NULL:
547 assert(stream != NULL);
And that's where it blows up:
(gdb) print stream
$6 = (struct packet_stream *) 0x0
I seem to have some "interesting" calls going through this system, such
that I can deliver you a "monologue == NULL" crash bug one week and a
stream-NULL abrt/exit the next. :-)
I looked up that Call-ID in the logs and saw this kind of call flow:
...
Also look up the call-id in the rtpengine logs please. The full log (esp
including the SDP) might allow me to reproduce this.
cheers
12:29 a.m.
On 06/27/2014 05:28 PM, Richard Fuchs wrote:
On 06/27/14 17:26, Alex Balashov wrote:
I will. I'm just afraid they may have been rotated out or that the entry
for this was rate-limited out. We forgot to disable rate-limiting on
rsyslogd, and this is a very high call pace installation.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
Hi Richard,
Yes indeed, I am able to pull sfd->call->callid.s in frame 4.
The assert is, of course, stream != NULL:
547 assert(stream != NULL);
And that's where it blows up:
(gdb) print stream
$6 = (struct packet_stream *) 0x0
I seem to have some "interesting" calls going through this system, such
that I can deliver you a "monologue == NULL" crash bug one week and a
stream-NULL abrt/exit the next. :-)
I looked up that Call-ID in the logs and saw this kind of call flow:
...
Also look up the call-id in the rtpengine logs please. The full log (esp
including the SDP) might allow me to reproduce this.
30 Jun
30 Jun
4:48 p.m.
On 27/06/14 05:29 PM, Alex Balashov wrote:
I will. I'm just afraid they may have been rotated
out or that the entry
for this was rate-limited out. We forgot to disable rate-limiting on
rsyslogd, and this is a very high call pace installation.
After carefully considering the code again, I believe the assertion
trigger may be a rare but valid case after all. I have thus removed the
assertion and the code is now simply ignoring this case. I expect that
fixes your problem.
https://github.com/sipwise/rtpengine/commit/2e9ae75fb0eeddaa877f27c9c4ba98a…
cheers
7:04 p.m.
On 06/30/2014 09:48 AM, Richard Fuchs wrote:
After carefully considering the code again, I believe
the assertion
trigger may be a rare but valid case after all. I have thus removed the
assertion and the code is now simply ignoring this case. I expect that
fixes your problem.
https://github.com/sipwise/rtpengine/commit/2e9ae75fb0eeddaa877f27c9c4ba98a…
Thank you, Richard. Can you elaborate as to what this case might be?
If I get another crash in the next few days (seems quite likely), I will
send you log output.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
1 Jul
1 Jul
2:58 p.m.
On 30/06/14 12:04 PM, Alex Balashov wrote:
On 06/30/2014 09:48 AM, Richard Fuchs wrote:
It's about how many ports are used for a particular media stream,
normally it's two, but it can be different. If there's a disagreement
about this between the two sides, then I believe some of the pointers
could be left NULLed. I haven't actually tested this though.
There's also the issue of a race condition due to incorrect locking.
I've just pushed another commit to make this more robust. Either case
requires reception of a stray UDP packet on a local port which is either
unused or not yet used.
cheers
After carefully considering the code again, I
believe the assertion
trigger may be a rare but valid case after all. I have thus removed the
assertion and the code is now simply ignoring this case. I expect that
fixes your problem.
https://github.com/sipwise/rtpengine/commit/2e9ae75fb0eeddaa877f27c9c4ba98a…
Thank you, Richard. Can you elaborate as to what this case might be? 
7:59 p.m.
Hi Richard, Alex,
On Tue, Jul 1, 2014 at 6:58 AM, Richard Fuchs <rfuchs(a)sipwise.com> wrote:
On 30/06/14 12:04 PM, Alex Balashov wrote:
I'm curious about it. Is there a way of simulating this? Under what
conditions should this happen?
Regards,
Carlos
On 06/30/2014 09:48 AM, Richard Fuchs wrote:
After carefully considering the code again, I believe the assertion
It's about how many ports are used for a particular media stream, normally
it's two, but it can be different. If there's a disagreement about this
between the two sides, then I believe some of the pointers could be left
NULLed. I haven't actually tested this though.
trigger may be a rare but valid case after all. I
have thus removed the
assertion and the code is now simply ignoring this case. I expect that
fixes your problem.
https://github.com/sipwise/rtpengine/commit/
2e9ae75fb0eeddaa877f27c9c4ba98a2c64c2d15
Thank you, Richard. Can you elaborate as to what this case might be?
There's also the issue of a race condition due to incorrect locking. I've
just pushed another commit to make this more robust. Either case requires
reception of a stray UDP packet on a local port which is either unused or
not yet used.
cheers
_______________________________________________
sr-dev mailing list
sr-dev(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
--
Carlos
http://caruizdiaz.com
http://ngvoice.com
+52 55 3048 3303
9:57 p.m.
On 01/07/14 12:59 PM, Carlos Ruiz Díaz wrote:
Hi Richard, Alex,
I'm curious about it. Is there a way of simulating
this? Under what
conditions should this happen?
The first case described (differing number of ports) I'm not 100% sure
about. I'm thinking the little used slash notation in the SDP m= line
might be to blame... one side using it (say, 1234/2 to advertise 4 ports
being used), the other side not using it. You'd end up with 4 ports open
for each side, but some of them unused. And then UDP packets coming in
on those ports.
The race condition is harder to test. You'd have to predict which ports
will be opened when an "offer" is received, and have these ports
hammered with UDP packets ahead of time, while the "offer" is being
processed.
cheers
10:01 p.m.
Thank you Richard.
Maybe Alex can tell us what amount of stress were put on rtpengine to make
it crash.
Regards,
Carlos
On Tue, Jul 1, 2014 at 1:57 PM, Richard Fuchs <rfuchs(a)sipwise.com> wrote:
On 01/07/14 12:59 PM, Carlos Ruiz Díaz wrote:
--
Carlos
http://caruizdiaz.com
http://ngvoice.com
+52 55 3048 3303
Hi Richard, Alex,
I'm curious about it. Is there a way of simulating this? Under what
conditions should this happen?
The first case described (differing number of ports) I'm not 100% sure
about. I'm thinking the little used slash notation in the SDP m= line might
be to blame... one side using it (say, 1234/2 to advertise 4 ports being
used), the other side not using it. You'd end up with 4 ports open for each
side, but some of them unused. And then UDP packets coming in on those
ports.
The race condition is harder to test. You'd have to predict which ports
will be opened when an "offer" is received, and have these ports hammered
with UDP packets ahead of time, while the "offer" is being processed.
cheers
_______________________________________________
sr-dev mailing list
sr-dev(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
2 Jul
2 Jul
8:01 p.m.
Related:
Every once in a while, rtpengine will go unresponsive despite continuing
to run. Here, for instance, ping commands from Kamailio can be observed,
but are going unreplied:
17:00:08.498680 IP 209.75.186.86.55305 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$RBQ.VBQ.N. ...%.u22440_43727 d7:command4:pinge
17:00:08.525165 IP 209.75.186.86.40538 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$SBQ.VBQ.N.Z...%."22439_43262 d7:command4:pinge
17:00:08.534777 IP 209.75.186.86.44189 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$ZBQ.VBQ.N.....%..22435_43463 d7:command4:pinge
17:00:08.568766 IP 209.75.186.86.44141 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$XBQ.VBQ.N.m...%..22434_43510 d7:command4:pinge
17:00:08.577805 IP 209.75.186.86.60187 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$OBQ.VBQ.N.....%.d22437_43626 d7:command4:pinge
17:00:08.599840 IP 209.75.186.86.52326 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$TBQ.VBQ.N.f...%..22438_43914 d7:command4:pinge
17:00:08.614967 IP 209.75.186.86.55637 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$RBQ.VBQ.N.U...%.'22441_43745 d7:command4:pinge
17:00:09.497714 IP 209.75.186.86.49158 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$XBQ.VBQ.N.....%.x22436_43834 d7:command4:pinge
17:00:09.499864 IP 209.75.186.86.55305 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$QBQ.VBQ.N. ...%.u22440_43727 d7:command4:pinge
17:00:09.526350 IP 209.75.186.86.40538 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$RBQ.VBQ.N.Z...%."22439_43262 d7:command4:pinge
17:00:09.535925 IP 209.75.186.86.44189 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$YBQ.VBQ.N.....%..22435_43463 d7:command4:pinge
17:00:09.569949 IP 209.75.186.86.44141 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$WBQ.VBQ.N.m...%..22434_43510 d7:command4:pinge
17:00:09.578973 IP 209.75.186.86.60187 > 209.75.186.78.mmcc: UDP, length 29
E..9u @.@.$NBQ.VBQ.N.....%.d22437_43626 d7:command4:pinge
17:00:09.601007 IP 209.75.186.86.52326 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$SBQ.VBQ.N.f...%..22438_43914 d7:command4:pinge
17:00:09.616110 IP 209.75.186.86.55637 > 209.75.186.78.mmcc: UDP, length 29
E..9u.@.@.$QBQ.VBQ.N.U...%.'22441_43745 d7:command4:pinge
There is no output in syslogs.
Other causes (e.g. firewall) have been ruled out.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
8:04 p.m.
On 07/02/14 13:01, Alex Balashov wrote:
Related:
Every once in a while, rtpengine will go unresponsive despite continuing
to run. Here, for instance, ping commands from Kamailio can be observed,
but are going unreplied:
Probably a deadlock. Either jump into the running process with gdb, or
send a core-dumping signal and then load the core in gdb. Execute
"thread apply all bt" to see where it's hung up on.
cheers
8:07 p.m.
Interestingly enough, the polling loop of rtpengine seems to be intact:
[root@sd-rtp01 log]# strace -p 30323
Process 30323 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, ^C <unfinished ...>
Process 30323 detached
So, I'm not sure why it wouldn't be processing the ping messages. It
must be a programmatic issue. Maybe? When I ran this strace and waited
for one of these:
Jul 2 17:04:14 proxyhost /usr/local/sbin/kamailio[22442]: ERROR:
rtpproxy-ng [rtpproxy.c:1549]: send_rtpp_command(): proxy
<udp:209.75.186.78:5050> does not respond, disable it
I saw nothing but this:
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
...
Re: the current thread state with attached GDB:
(gdb) thread apply all bt
Thread 7 (Thread 0x7f874f280700 (LWP 30324)):
#0 0x000000304e233a1d in sigtimedwait () from /lib64/libc.so.6
#1 0x00000000004072f1 in sighandler (x=<value optimized out>) at main.c:114
#2 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#3 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#4 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Thread 6 (Thread 0x7f874e87f700 (LWP 30325)):
#0 0x000000304e2accdd in nanosleep () from /lib64/libc.so.6
#1 0x000000304e2e1e54 in usleep () from /lib64/libc.so.6
#2 0x000000000040af82 in poller_timers_wait_run (p=0x269a740, max=100000)
at poller.c:500
#3 0x000000000040725d in timer_loop (d=0x269a740) at main.c:535
#4 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#5 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#6 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Thread 5 (Thread 0x7f874de7e700 (LWP 30326)):
#0 0x000000304e60b5bc in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib64/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#1 0x0000000000415240 in cookie_cache_lookup (c=0x269e050,
s=0x7f874de6d650)
at cookie_cache.c:57
#2 0x0000000000415b20 in control_ng_incoming (obj=0x269e030,
buf=<value optimized out>, sin=0x7f874de7d700, addr=
0x7f874de7d6c0 "209.75.186.86:39889") at control_ng.c:86
#3 0x000000000041573e in udp_listener_incoming (fd=6, p=0x269d670,
x=<value optimized out>) at udp_listener.c:52
#4 0x000000000040b4ce in poller_poll (p=0x269a740,
timeout=<value optimized out>) at poller.c:354
#5 0x000000000040722d in poller_loop (d=0x269a740) at main.c:542
#6 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#7 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#8 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Thread 4 (Thread 0x7f874d47d700 (LWP 30327)):
#0 0x000000304e60ac50 in pthread_rwlock_wrlock () from
/lib64/libpthread.so.0
#1 0x000000000040f29f in call_destroy (c=0x7f87400b25c0) at call.c:1981
#2 0x0000000000411c16 in call_delete_branch (m=<value optimized out>,
callid=<value optimized out>, branch=<value optimized out>,
fromtag=<value optimized out>, totag=0x7f874d46c540, output=
0x7f8740062c28) at call.c:2486
#3 0x000000000041f901 in call_delete_ng (input=<value optimized out>, m=
---Type <return> to continue, or q <return> to quit---
0x269b400, output=0x7f8740062c28) at call_interfaces.c:649
#4 0x0000000000415fc8 in control_ng_incoming (obj=0x269e030,
buf=<value optimized out>, sin=0x7f874d47c700, addr=
0x7f874d47c6c0 "209.75.186.86:41930") at control_ng.c:117
#5 0x000000000041573e in udp_listener_incoming (fd=6, p=0x269d670,
x=<value optimized out>) at udp_listener.c:52
#6 0x000000000040b4ce in poller_poll (p=0x269a740,
timeout=<value optimized out>) at poller.c:354
#7 0x000000000040722d in poller_loop (d=0x269a740) at main.c:542
#8 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#9 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#10 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Thread 3 (Thread 0x7f874ca7c700 (LWP 30328)):
#0 0x000000304e60ac50 in pthread_rwlock_wrlock () from
/lib64/libpthread.so.0
#1 0x000000000040f29f in call_destroy (c=0x7f8740a2c120) at call.c:1981
#2 0x0000000000411c16 in call_delete_branch (m=<value optimized out>,
callid=<value optimized out>, branch=<value optimized out>,
fromtag=<value optimized out>, totag=0x7f874ca6b540, output=
0x7f8728222828) at call.c:2486
#3 0x000000000041f901 in call_delete_ng (input=<value optimized out>, m=
0x269b400, output=0x7f8728222828) at call_interfaces.c:649
---Type <return> to continue, or q <return> to quit---
#4 0x0000000000415fc8 in control_ng_incoming (obj=0x269e030,
buf=<value optimized out>, sin=0x7f874ca7b700, addr=
0x7f874ca7b6c0 "209.75.186.86:39889") at control_ng.c:117
#5 0x000000000041573e in udp_listener_incoming (fd=6, p=0x269d670,
x=<value optimized out>) at udp_listener.c:52
#6 0x000000000040b4ce in poller_poll (p=0x269a740,
timeout=<value optimized out>) at poller.c:354
#7 0x000000000040722d in poller_loop (d=0x269a740) at main.c:542
#8 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#9 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#10 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Thread 2 (Thread 0x7f8747fff700 (LWP 30329)):
#0 0x000000304e60ac50 in pthread_rwlock_wrlock () from
/lib64/libpthread.so.0
#1 0x000000000040f29f in call_destroy (c=0x7f872c22a1d0) at call.c:1981
#2 0x0000000000411c16 in call_delete_branch (m=<value optimized out>,
callid=<value optimized out>, branch=<value optimized out>,
fromtag=<value optimized out>, totag=0x7f8747fee540, output=
0x7f872c2d4828) at call.c:2486
#3 0x000000000041f901 in call_delete_ng (input=<value optimized out>, m=
0x269b400, output=0x7f872c2d4828) at call_interfaces.c:649
#4 0x0000000000415fc8 in control_ng_incoming (obj=0x269e030,
---Type <return> to continue, or q <return> to quit---
buf=<value optimized out>, sin=0x7f8747ffe700, addr=
0x7f8747ffe6c0 "209.75.186.86:36511") at control_ng.c:117
#5 0x000000000041573e in udp_listener_incoming (fd=6, p=0x269d670,
x=<value optimized out>) at udp_listener.c:52
#6 0x000000000040b4ce in poller_poll (p=0x269a740,
timeout=<value optimized out>) at poller.c:354
#7 0x000000000040722d in poller_loop (d=0x269a740) at main.c:542
#8 0x000000000040bb5f in thread_detach_func (d=<value optimized out>)
at aux.c:160
#9 0x000000304e6079d1 in start_thread () from /lib64/libpthread.so.0
#10 0x000000304e2e8b6d in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7f874f2817c0 (LWP 30323)):
#0 0x000000304e2accdd in nanosleep () from /lib64/libc.so.6
#1 0x000000304e2e1e54 in usleep () from /lib64/libc.so.6
#2 0x000000000040a98a in main (argc=1, argv=0x7fffc99076d8) at main.c:562
-- Alex
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
8:08 p.m.
I need to restart this process to get it back into production, but I'll
get it to dump the core in case you have any other questions.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
8:15 p.m.
On 07/02/14 13:07, Alex Balashov wrote:
Interestingly enough, the polling loop of rtpengine
seems to be intact:
[root@sd-rtp01 log]# strace -p 30323
Process 30323 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
Strace only hooks into the main thread of a process, others don't show
up. If you use "ps -efL" to show the process list, you get to see all
threads of a process including their LWP IDs. Use those IDs to see
what's going on in them with strace (you can specify multiple at the
same time, strace -p $X -p $Y -p $Z ...)
Re: the current thread state with attached GDB:
Would you happen to know the git commit ID of your build, so I can
correlate the line numbers.
cheers
8:17 p.m.
On 07/02/2014 01:15 PM, Richard Fuchs wrote:
On 07/02/14 13:07, Alex Balashov wrote:
Ah, I was wondering if 'ps' could show LWPs. Thanks!
Interestingly enough, the polling loop of
rtpengine seems to be intact:
[root@sd-rtp01 log]# strace -p 30323
Process 30323 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
Strace only hooks into the main thread of a process, others don't show
up. If you use "ps -efL" to show the process list, you get to see all
threads of a process including their LWP IDs. Use those IDs to see
what's going on in them with strace (you can specify multiple at the
same time, strace -p $X -p $Y -p $Z ...) Would you happen to know the git commit ID of your
build, so I can
correlate the line numbers.
Sure, it's master:b0c0e396d62c4a04d1600fc5eb8a3462a0e6cefe.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
8:36 p.m.
On 07/02/14 13:17, Alex Balashov wrote:
On 07/02/2014 01:15 PM, Richard Fuchs wrote:
Found one instance of a missing unlock. Do you perhaps see the error
message "Invalid dialogue association" in your rtpengine logs?
cheers
On 07/02/14 13:07, Alex Balashov wrote:
Ah, I was wondering if 'ps' could show LWPs. Thanks!
Interestingly enough, the polling loop of
rtpengine seems to be intact:
[root@sd-rtp01 log]# strace -p 30323
Process 30323 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
nanosleep({0, 100000000}, NULL) = 0
Strace only hooks into the main thread of a process, others don't show
up. If you use "ps -efL" to show the process list, you get to see all
threads of a process including their LWP IDs. Use those IDs to see
what's going on in them with strace (you can specify multiple at the
same time, strace -p $X -p $Y -p $Z ...) Would you happen to know the git commit ID of
your build, so I can
correlate the line numbers.
Sure, it's master:b0c0e396d62c4a04d1600fc5eb8a3462a0e6cefe.
8:44 p.m.
On 07/02/2014 01:36 PM, Richard Fuchs wrote:
Found one instance of a missing unlock. Do you perhaps
see the error
message "Invalid dialogue association" in your rtpengine logs?
Yes, indeed, from yesterday, which is when it is thought to have stopped
functioning in actuality:
Jul 1 16:22:38 rtphost rtpengine[30323]:
[03C7B67A-53B2E03D0002BE22-091CD700] Protocol error in packet from
209.75.186.86:36639: Invalid dialogue association
[d3:sdp355:v=0#015#012o=Sonus_UAC 15054 20579 IN IP4
97.41.84.17.148#015#012s=SIP Media Capabilities#015#012c=IN IP4
97.41.84.17.148#015#012t=0 0#015#012m=audio 10594 RTP/AVP
0#015#012a=direction: passive#015#012a=rtpmap:0
PCMU/8000#015#012a=sendrecv#015#012a=ptime:20#015#012m=audio 0 RTP/AVP 0
8 101#015#012a=direction: both#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:101
telephone-event/8000#015#012a=sendrecv#015#012a=maxptime:20#015#0125:flagsl13:trust-addresse7:replacel6:origine7:call-id34:03C7B67A-53B2E03D0002BE22-091CD70013:received-froml3:IP414:97.41.84.17.148e8:from-tag34:76D0517D-53B2E03D0002BED6-091CD7006:to-tag20:SDhivi899-gK0a90b54e7:command6:answere]
Jul 1 16:22:38 rtphost rtpengine[30323]:
[03C7B67A-53B2E03D0002BE22-091CD700] Returning to SIP proxy:
d6:result5:error12:error-reason28:Invalid dialogue associatione
Jul 1 16:53:51 rtphost rtpengine[30323]:
[644986138-0-1622069164(a)110.4.8.1] Protocol error in packet from
209.75.186.86:34626: Invalid dialogue association
[d3:sdp230:v=0#015#012o=Sansay-VSXi 188 1 IN IP4
154.50.206.12#015#012s=Session Controller#015#012c=IN IP4
154.50.206.15#015#012t=0 0#015#012m=audio 25376 RTP/AVP 0
101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101
telephone-event/8000#015#012a=fmtp:101
0-15#015#012a=sendrecv#015#012a=maxptime:20#015#0125:flagsl13:trust-addresse7:replacel6:origine7:call-id36:644986138-0-1622069164@110.4.8.113:received-froml3:IP414:107.23.121.178e8:from-tag24:sansay2472712924rdb840496:to-tag23:sansay1041790983rdb43617:command6:answere]
Jul 1 16:53:51 rtphost rtpengine[30323]:
[644986138-0-1622069164(a)110.4.8.1] Returning to SIP proxy:
d6:result5:error12:error-reason28:Invalid dialogue associatione
Jul 1 17:28:21 rtphost rtpengine[30323]:
[68A5EB10-53B2EFB30005599A-BE083700] Protocol error in packet from
209.75.186.86:36511: Invalid dialogue association
[d3:sdp354:v=0#015#012o=Sonus_UAC 28564 27914 IN IP4
97.41.84.17.148#015#012s=SIP Media Capabilities#015#012c=IN IP4
97.41.84.17.148#015#012t=0 0#015#012m=audio 10034 RTP/AVP
0#015#012a=direction: passive#015#012a=rtpmap:0
PCMU/8000#015#012a=sendrecv#015#012a=ptime:20#015#012m=audio 0 RTP/AVP 0
18 101#015#012a=direction: both#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101
telephone-event/8000#015#012a=sendrecv#015#012a=ptime:20#015#0125:flagsl13:trust-addresse7:replacel6:origine7:call-id34:68A5EB10-53B2EFB30005599A-BE08370013:received-froml3:IP414:97.41.84.17.148e8:from-tag34:3438543C-53B2EFB300055A36-BE0837006:to-tag20:SD2sl6999-gK07ba92697:command6:answere]
Jul 1 17:28:21 rtphost rtpengine[30323]:
[68A5EB10-53B2EFB30005599A-BE083700] Returning to SIP proxy:
d6:result5:error12:error-reason28:Invalid dialogue associatione
Jul 1 19:06:11 rtphost rtpengine[30323]:
[5F059A5C-53B306A00009A3D6-5BFDE700] Protocol error in packet from
209.75.186.86:36511: Invalid dialogue association
[d3:sdp328:v=0#015#012o=Sonus_UAC 30494 32324 IN IP4
97.41.84.17.148#015#012s=SIP Media Capabilities#015#012c=IN IP4
97.41.84.17.148#015#012t=0 0#015#012m=audio 11446 RTP/AVP
0#015#012a=direction: passive#015#012a=rtpmap:0
PCMU/8000#015#012a=sendrecv#015#012a=ptime:20#015#012m=audio 0 RTP/AVP 0
101#015#012a=direction: both#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:101
telephone-event/8000#015#012a=sendrecv#015#012a=ptime:20#015#0125:flagsl13:trust-addresse7:replacel6:origine7:call-id34:5F059A5C-53B306A00009A3D6-5BFDE70013:received-froml3:IP414:97.41.84.17.148e8:from-tag34:6243EDDE-53B306A00009A48C-5BFDE7006:to-tag20:SDe3pca99-gK09abfad37:command6:answere]
Jul 1 19:06:11 rtphost rtpengine[30323]:
[5F059A5C-53B306A00009A3D6-5BFDE700] Returning to SIP proxy:
d6:result5:error12:error-reason28:Invalid dialogue associatione
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
8:45 p.m.
On 07/02/14 13:44, Alex Balashov wrote:
On 07/02/2014 01:36 PM, Richard Fuchs wrote:
In that case, this should be for you:
https://github.com/sipwise/rtpengine/commit/15640991d7fc9d398749f77460b8212…
cheers
Found one instance of a missing unlock. Do you
perhaps see the error
message "Invalid dialogue association" in your rtpengine logs?
Yes, indeed, from yesterday, which is when it is thought to have stopped
functioning in actuality:
8:46 p.m.
On 07/02/2014 01:45 PM, Richard Fuchs wrote:
On 07/02/14 13:44, Alex Balashov wrote:
Am I right to assume that this is a missing unlock introduced by error
handling in the previous patch? :-)
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
On 07/02/2014 01:36 PM, Richard Fuchs wrote:
In that case, this should be for you:
https://github.com/sipwise/rtpengine/commit/15640991d7fc9d398749f77460b8212…
Found one instance of a missing unlock. Do you
perhaps see the error
message "Invalid dialogue association" in your rtpengine logs?
Yes, indeed, from yesterday, which is when it is thought to have stopped
functioning in actuality:
8:49 p.m.
On 07/02/14 13:46, Alex Balashov wrote:
On 07/02/2014 01:45 PM, Richard Fuchs wrote:
No, completely unrelated screw-up, from the beginning of June actually :-P
cheers
On 07/02/14 13:44, Alex Balashov wrote:
Am I right to assume that this is a missing unlock introduced by error
handling in the previous patch? :-) On 07/02/2014 01:36 PM, Richard Fuchs wrote:
In that case, this should be for you:
https://github.com/sipwise/rtpengine/commit/15640991d7fc9d398749f77460b8212…
Found one instance of a missing unlock. Do you
perhaps see the error
message "Invalid dialogue association" in your rtpengine logs?
Yes, indeed, from yesterday, which is when it is thought to have stopped
functioning in actuality:
8:49 p.m.
On 07/02/2014 01:49 PM, Richard Fuchs wrote:
Ah well.
Thanks, your help and prompt responses are deeply appreciated.
--
Alex Balashov - Principal
Evariste Systems LLC
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/
Please be kind to the English language:
http://www.entrepreneur.com/article/232906
Am I right to
assume that this is a missing unlock introduced by error
handling in the previous patch? :-)
No, completely unrelated screw-up, from the beginning of June actually :-P
3796
days inactive
3801
days old
22 comments
3 participants
participants (3)
-
Alex Balashov -
Carlos Ruiz Díaz -
Richard Fuchs