[OpenSIPS-Users] DRouting Madness

Christopher Dye chris.dye at paragon.net
Wed Jan 18 08:45:29 CET 2012 

Hello All,
                I've been posing this question in IRC, but haven't had any luck with a lead...

                I'm trying to setup DRouting and I think I'm really close, but for some reason when I get into my drouting subroute (in this case route[4]) it matches from a row in the database on the first try, but continues to loop through that subroute up to 32 additional times before starting to throw errors. I'll attach a snippet here to illustrate:

Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:core:parse_headers: flags=10
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:core:parse_to_param: tag=as3cde8572
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:core:parse_to: end of header reached, state=29
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:core:parse_to: display={"username_of_caller"}, ruri={sip:username_of_caller at address_of_caller}
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: using dr group 0
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:internal_check_rt: found rgid 0 (rule list 0xa741465c)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[4] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: CRITICAL:core:eval_expr: too many expressions (101)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: WARNING:core:do_action: error in expression (l=387)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: CRITICAL:core:eval_expr: too many expressions (101)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: WARNING:core:do_action: error in expression (l=391)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DEBUG: >>>BEGIN: route[1] Block -->
Jan 18 01:39:06 core01 /sbin/opensips[8489]: CRITICAL:core:eval_expr: too many expressions (101)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: WARNING:core:do_action: error in expression (l=369)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: CRITICAL:core:eval_expr: too many expressions (101)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: WARNING:core:do_action: error in expression (l=372)
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: setting GW attr [] as for ruri
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: setting GW id [1] as avp
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: setting RULE id [3] as avp
Jan 18 01:39:06 core01 /sbin/opensips[8489]: DBG:drouting:do_routing: setting the gw [0] as ruri "sip:NXXNXXNXXX at address_of_gateway_from_mysql"

It continues, then, to loop through my first subroute (the same number of times as route[4] hits) and then dies... One important thing to note is that if I throw an xlog() the line after the do_routing() call, it doesn't fire between the loops... the looping seems to happen within the function...

An ngrep packet capture reveals that there is a copy of the INVITE sent to the gateway for every one of the attempts. The gateway responds after the flood with a "500: Server Error", which is ironically correctly forwarded back to the caller address (so the record_route() seems to be working).

My subroute is as follows:

route[4] {
        #log that we're trying dynamically at least
        xlog("DEBUG: >>>BEGIN: route[4] Block -->\n");
        if (!do_routing("0")) {
                xlog("!do_routing: No Rules matching the URI\n");
                send_reply("503", "No Rules matching the URI");
                exit;
        }

        if (is_method("INVITE")) {
                t_on_failure("4");
        }

        route(1);
}

There seems to be precedence for this problem as I found a pastebin containing the exact same issue from Feb 17, 2011 - but no resolution was discernible...

I apologize in advance if this isn't the proper forum for this question, but I'm getting desperate to get this working and didn't know where else to go.

Thanks in Advance,
Chris
chris.dye at paragon.net

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20120118/cd2cfa3a/attachment-0001.htm>

More information about the Users mailing list