ASYNC Module

List overview All Threads
Download

newer

older

Websocket Load Balancing

lookup("location") question

Aaron Hamstra

12 Jun 2015 12 Jun '15

7:38 p.m.

We just updated our development environment from 4.2.2 to 4.2.5 and started noticing the server sending a 500 I'm terribly sorry, server error occurred (1/TM) error back as soon as the async_route block gets called. I have removed everything from our async route other than an xlog statement trying to determine if something in that route block was causing the 500 to occur. It still happens even with only the xlog.

If the async_route is not in the config, then the server does not send the 500 response.

We rolled back to 4.2.2 and the problem no longer occurs.

I have attached a sip trace of the messages. I believe the relevant parts of our config are below, please let me know if you need more from the config however.

Any ideas?

async_route("PUSHJOIN", "2");

--------------------------

route[PUSHJOIN] {

xlog("L_INFO", "Does it get here?\n");

exit;

}

Thanks in Advance,

Aaron

Attachments:

attachment.html (text/html — 3.4 KB)
sip_trace.txt (text/plain — 2.2 KB)

Show replies by date

Alex Balashov

12 Jun 12 Jun

8:49 p.m.

Aaron,

Where is the call to async_route() situated in the core request route? That is, what is called before and after the async_route?

-- Alex

On 06/12/2015 03:38 PM, Aaron Hamstra wrote:

...

We just updated our development environment from 4.2.2 to 4.2.5 and started noticing the server sending a 500 I'm terribly sorry, server error occurred (1/TM) error back as soon as the async_route block gets called. I have removed everything from our async route other than an xlog statement trying to determine if something in that route block was causing the 500 to occur. It still happens even with only the xlog.

If the async_route is not in the config, then the server does not send the 500 response.

We rolled back to 4.2.2 and the problem no longer occurs.

I have attached a sip trace of the messages. I believe the relevant parts of our config are below, please let me know if you need more from the config however.

Any ideas?

async_route("PUSHJOIN", "2");

route[PUSHJOIN] {

xlog("L_INFO", "Does it get here?\n");

exit;

}

Thanks in Advance,

Aaron

SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Aaron Hamstra

9:03 p.m.

Alex,

We are using a pretty close to default configuration.

Below is the routing blocks above and below where async_route is located(async_route actually is inside my route[REGISTRAR] block.

# Handle requests within SIP dialogs route[WITHINDLG] { if (has_totag()) { # sequential request withing a dialog should # take the path determined by record-routing if (loose_route()) { route(DLGURI); if (is_method("BYE")) { setflag(FLT_ACC); # do accounting ... setflag(FLT_ACCFAILED); # ... even if the transaction fails } else if ( is_method("ACK") ) { # ACK is forwarded statelessy route(NATMANAGE); } else if ( is_method("NOTIFY") ) { # Add Record-Route for in-dialog NOTIFY as per RFC 6665. record_route(); } route(RELAY); } else { if (is_method("SUBSCRIBE") && uri == myself) { # in-dialog subscribe requests route(PRESENCE); exit; } if ( is_method("ACK") ) { if ( t_check_trans() ) {

# no loose-route, but stateful ACK; # must be an ACK after a 487 # or e.g. 404 from upstream server route(RELAY); exit; } else { # ACK without matching transaction ... ignore and discard exit; } } xlog("SCRIPT: $TF Call to $rU but not currently in usrloc db SIP/404\n"); sl_send_reply("404","Not here"); } exit; } }

# Event Route for Expired Contact event_route[usrloc:contact-expired] { xlog("expired contact for $ulc(exp=>aor)\n"); }

# Handle SIP registrations route[REGISTRAR] { if (is_method("REGISTER")) { if(isflagset(FLT_NATS)) { setbflag(FLB_NATB); # uncomment next line to do SIP NAT pinging ##setbflag(FLB_NATSIPPING); } xlog("SCRIPT: $TF $au registered to usrloc db from $si from useragent type of $ua\n"); if (!save("location", "0x4")) sl_reply_error(); async_route("PUSHJOIN", "2"); exit; } } # USER location service route[LOCATION] { #!ifdef WITH_SPEEDDIAL # search for short dialing - 2-digit extension if($rU=~"^[0-9][0-9]$") if(sd_lookup("speed_dial")) route(SIPOUT); #!endif

#!ifdef WITH_ALIASDB # search in DB-based aliases if(alias_db_lookup("dbaliases")) route(SIPOUT); #!endif

$avp(oexten) = $rU; if (!lookup("location")) { $var(rc) = $rc; route(TOVOICEMAIL); t_newtran(); switch ($var(rc)) { case -1: case -3: xlog("SCRIPT: $TF Call to $rU but not currently in usrloc db SIP/404\n"); send_reply("404", "Not Found"); exit; case -2: send_reply("405", "Method Not Allowed"); exit; } }

# when routing via usrloc, log the missed calls also if (is_method("INVITE")) { setflag(FLT_ACCMISSED); }

route(RELAY); exit; }

Thanks! -----Original Message----- From: sr-users [mailto:sr-users-bounces@lists.sip-router.org] On Behalf Of Alex Balashov Sent: Friday, June 12, 2015 3:50 PM To: sr-users@lists.sip-router.org Subject: Re: [SR-Users] ASYNC Module

Aaron,

Where is the call to async_route() situated in the core request route? That is, what is called before and after the async_route?

-- Alex

On 06/12/2015 03:38 PM, Aaron Hamstra wrote:

...

We just updated our development environment from 4.2.2 to 4.2.5 and started noticing the server sending a 500 I'm terribly sorry, server error occurred (1/TM) error back as soon as the async_route block gets

...

called. I have removed everything from our async route other than an xlog statement trying to determine if something in that route block was causing the 500 to occur. It still happens even with only the

xlog.

...

If the async_route is not in the config, then the server does not send

...

the 500 response.

We rolled back to 4.2.2 and the problem no longer occurs.

I have attached a sip trace of the messages. I believe the relevant parts of our config are below, please let me know if you need more from the config however.

Any ideas?

async_route("PUSHJOIN", "2");

route[PUSHJOIN] {

xlog("L_INFO", "Does it get here?\n");

exit;

}

Thanks in Advance,

Aaron

SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

_______________________________________________ SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users

Alex Balashov

9:11 p.m.

Aaron,

Thanks. You seem to be getting automatic errors from TM, even though your calling code neither creates a transaction nor calls t_relay(). This is because the wrappers provided by the 'async' module utilise TM internally; async_route() really 1) creates a transaction in TM 2) t_suspends() it 3) t_continues() it, at which point there is TM involvement.

One bit of idle speculation: did you happen to set this core parameter?

http://www.kamailio.org/wiki/cookbooks/4.3.x/core#async_workers

If not, try set it to some value. This is subtly different from the 'workers' modparam to the 'async' module.

-- Alex

Aaron Hamstra

9:22 p.m.

Thanks for the insight as to why the error from TM when I couldn't see why TM was involved.. that makes sense.

async_workers=8 is what I have it set to already unfortunately.

Thanks Again,

Aaron -----Original Message----- From: sr-users [mailto:sr-users-bounces@lists.sip-router.org] On Behalf Of Alex Balashov Sent: Friday, June 12, 2015 4:11 PM To: sr-users@lists.sip-router.org Subject: Re: [SR-Users] ASYNC Module

Aaron,

One bit of idle speculation: did you happen to set this core parameter?

http://www.kamailio.org/wiki/cookbooks/4.3.x/core#async_workers

If not, try set it to some value. This is subtly different from the 'workers' modparam to the 'async' module.

-- Alex

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Alex Balashov

9:25 p.m.

Well, in that case, your best bet is to turn up debug= one level and go from there. You know, the usual. :)

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Sent from my BlackBerry. Original Message From: Aaron Hamstra Sent: Friday, June 12, 2015 17:22 To: Kamailio (SER) - Users Mailing List Reply To: Kamailio (SER) - Users Mailing List Subject: Re: [SR-Users] ASYNC Module

Thanks for the insight as to why the error from TM when I couldn't see why TM was involved.. that makes sense.

async_workers=8 is what I have it set to already unfortunately.

Thanks Again,

Aaron,

One bit of idle speculation: did you happen to set this core parameter?

http://www.kamailio.org/wiki/cookbooks/4.3.x/core#async_workers

If not, try set it to some value. This is subtly different from the 'workers' modparam to the 'async' module.

-- Alex

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Aaron Hamstra

11:07 p.m.

I think this is the section from log when I increase debug up a notch ... I see it mentions in the trace below that the sip_trace module is the line above the 500 response. I just tried disabling that to see if it changed anything and it did not .. still get the 500 response...

Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_lookup.c:1635]: t_lookup_ident(): DEBUG: t_lookup_ident: transaction found Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: INFO: <script>: Does it get here? Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0) called Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_reply.c:1670]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2299]: tcpconn_send_put(): tcp_send: tcp connection found (0x7f36f410d970), acquiring fd Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2309]: tcpconn_send_put(): tcp_send, c= 0x7f36f410d970, n=16 Jun 12 22:55:41 /usr/local/sbin/kamailio[23303]: DEBUG: <core> [tcp_main.c:3567]: handle_ser_child(): handle_ser_child: read response= 7f36f410d970, 2, fd -1 from 21 (23297) Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2339]: tcpconn_send_put(): tcp_send: after receive_fd: c= 0x7f36f410d970 n=8 fd=12 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2518]: tcpconn_do_send(): tcp_send: sending... Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2552]: tcpconn_do_send(): tcp_send: aft£Y;ùô0#}¤V|#031Y#037$kÍlJ8CÂ}F’å«Õ=661 fd=12 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f36f40f0228, callback type 8388608, id 0 entered x#003Ø|ïYå?*â'£qbÔk*#020Ø#03 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: siptrace [siptrace.c:1847]: pipport2su(): the port string is 5061 VâG–.9AÏ#001#030#033#024yt8H¶#001F˜ÃßáF%eæåom~Í’‰ªr(väÓÊ#010 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: siptrace [siptrace.c:1847]: pipport2su(): the port string is 58965 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [proxy.c:278]: mk_proxy(): DEBUG: mk_proxy: doing DNS lookup... Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: siptrace [siptrace.c:1659]: trace_send_hep_duplicate(): setting up the socket_info Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f36fd7b4688: SIP/2.0 500 I'm terr..., shmem=0x7f36f40eb070: SIP/2.0 500 I'm terr Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished

-----Original Message----- From: sr-users [mailto:sr-users-bounces@lists.sip-router.org] On Behalf Of Alex Balashov Sent: Friday, June 12, 2015 4:25 PM To: Aaron Hamstra Subject: Re: [SR-Users] ASYNC Module

Well, in that case, your best bet is to turn up debug= one level and go from there. You know, the usual. :)

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Thanks for the insight as to why the error from TM when I couldn't see why TM was involved.. that makes sense.

async_workers=8 is what I have it set to already unfortunately.

Thanks Again,

Aaron,

One bit of idle speculation: did you happen to set this core parameter?

http://www.kamailio.org/wiki/cookbooks/4.3.x/core#async_workers

If not, try set it to some value. This is subtly different from the 'workers' modparam to the 'async' module.

-- Alex

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Alex Balashov

13 Jun 13 Jun

12:13 a.m.

On 06/12/2015 07:07 PM, Aaron Hamstra wrote:

...

Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2552]: tcpconn_do_send(): tcp_send: aft£Y;ùô0#}¤V|#031Y#037$kÍlJ8CÂ}F’å«Õ=661 fd=12 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f36f40f0228, callback type 8388608, id 0 entered x#003Ø|ïYå?*â'£qbÔk*#020Ø#03 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: siptrace [siptrace.c:1847]: pipport2su(): the port string is 5061 VâG–.9AÏ#001#030#033#024yt8H¶#001F˜ÃßáF%eæåom~Í’‰ªr(väÓÊ#010

I find the garbage data in these log entries highly suspect, although I'm not necessarily qualified to debug this to the bottom.

If you can spare the time, I'd try to test the following things:

1. Does this also occur if you call async_route() while processing another type of request, i.e. an OPTIONS or an INVITE request, as opposed to REGISTER?

2. Does this happen only with the TCP transport, or also UDP?

If #2 doesn't prove to be the case, it might indicate that the cause of the suspected regression is a change in code unrelated to async or TM per se.

-- Alex

Aaron Hamstra

2:34 a.m.

Alex,

I enabled UDP DNS_SRV records and am still seeing the same thing using UDP as I have using TLS or TCP transport.

I also modified the defs.h in the tm module as you mentioned and added #define ENABLE_ASYNC_MUTEX 1

between the

#ifndef _TM_DEFS_H and #define _TM_DEFS_H

lines

Did a new make and make install and restart of kamailio... issue persists unfortunately.

I so appreciate your assistance in troubleshooting this issue.

-Aaron

-----Original Message----- From: sr-users [mailto:sr-users-bounces@lists.sip-router.org] On Behalf Of Alex Balashov Sent: Friday, June 12, 2015 7:13 PM To: sr-users@lists.sip-router.org Subject: Re: [SR-Users] ASYNC Module

On 06/12/2015 07:07 PM, Aaron Hamstra wrote:

...

Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: <core> [tcp_main.c:2552]: tcpconn_do_send(): tcp_send: aft£Y;ùô0#}¤V|#031Y#037$kÍlJ8CÂ}F’å«Õ=661 fd=12 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f36f40f0228, callback type 8388608, id 0 entered x#003Ø|ïYå?*â'£qbÔk*#020Ø#03 Jun 12 22:55:41 /usr/local/sbin/kamailio[23297]: DEBUG: siptrace [siptrace.c:1847]: pipport2su(): the port string is 5061 VâG–.9AÏ#001#030#033#024yt8H¶#001F˜ÃßáF%eæåom~Í’‰ªr(väÓÊ#010

I find the garbage data in these log entries highly suspect, although I'm not necessarily qualified to debug this to the bottom.

If you can spare the time, I'd try to test the following things:

1. Does this also occur if you call async_route() while processing another type of request, i.e. an OPTIONS or an INVITE request, as opposed to REGISTER?

2. Does this happen only with the TCP transport, or also UDP?

If #2 doesn't prove to be the case, it might indicate that the cause of the suspected regression is a change in code unrelated to async or TM per se.

-- Alex

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Alex Balashov

12 Jun 12 Jun

9:27 p.m.

It is strange that you should see this change between minor point releases. That does suggest a possible regression.

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Sent from my BlackBerry.

Aaron Hamstra

11:10 p.m.

I see that there was some work done to the ASYNC module between 4.2.2 and 4.2.5 via Changelog...

commit bf8be8c52039fc50dafd0c9c140c01ab84384977 Author: Daniel-Constantin Mierla miconda@gmail.com Date: Sun May 10 18:18:00 2015 +0200

tm: disabled use of dedicated mutex for async continue

- it can be enabled by defining ENABLE_ASYNC_MUTEX - reply mutex is re-entrant and protects better the transaction strucutre - a dedicated lock for async continue exposes a race on removing from timer when suspended transaction is resument at the same time when the timer fires expiration event

I tried to just add a #!define ENABLE_ASYNC_MUTEX and the issue remains....

-----Original Message----- From: sr-users [mailto:sr-users-bounces@lists.sip-router.org] On Behalf Of Alex Balashov Sent: Friday, June 12, 2015 4:27 PM To: Aaron Hamstra Subject: Re: [SR-Users] ASYNC Module

It is strange that you should see this change between minor point releases. That does suggest a possible regression.

-- Alex Balashov | Principal | Evariste Systems LLC 303 Perimeter Center North, Suite 300 Atlanta, GA 30346 United States

Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct) Web: http://www.evaristesys.com/, http://www.csrpswitch.com/

Sent from my BlackBerry.

Alex Balashov

13 Jun 13 Jun

12:10 a.m.

Aaron,

On 06/12/2015 07:10 PM, Aaron Hamstra wrote:

...

I tried to just add a #!define ENABLE_ASYNC_MUTEX and the issue remains....

In this case, the committer's comment that "it can be enabled by defining ENABLE_ASYNC_MUTEX" does not refer to preprocessor #!defines within the Kamailio route script, but rather preprocessor defines within the C source code, from which the former take their inspiration. :-)

sasha@saurus:~/kamailio$ fgrep -HR ENABLE_ASYNC_MUTEX . ./modules/tm/h_table.h:#ifdef ENABLE_ASYNC_MUTEX ./modules/tm/lock.c:#ifdef ENABLE_ASYNC_MUTEX ./modules/tm/lock.c:#ifdef ENABLE_ASYNC_MUTEX ./modules/tm/lock.c:#ifdef ENABLE_ASYNC_MUTEX ./modules/tm/lock.c:#ifdef ENABLE_ASYNC_MUTEX ./modules/tm/lock.c:#ifdef ENABLE_ASYNC_MUTEX ./modules/tm/lock.c:#endif /* ENABLE_ASYNC_MUTEX */ ./modules/tm/t_suspend.c:#ifdef ENABLE_ASYNC_MUTEX ./ChangeLog: - it can be enabled by defining ENABLE_ASYNC_MUTEX

So, if that's a bit you want to toggle, so to speak, you'll want to go into modules/tm/defs.h and add:

#define ENABLE_ASYNC_MUTEX

Be sure to do so between these lines:

#ifndef _TM_DEFS_H #define _TM_DEFS_H

...

#define ENABLE_ASYNC_MUTEX 1 /* you add this */

#endif

And don't confuse the Kamailio-style #!define with the C-style #define -- in this case, you want the latter.

Then, rebuild the 'tm' module by executing a 'make install' in that directory, and restart Kamailio.

3548

Age (days ago)

3549

Last active (days ago)

sr-users@lists.kamailio.org

11 comments

2 participants

tags (0)

participants (2)

Aaron Hamstra
Alex Balashov