[OpenSIPS-Users] My OpenSIPS apparently ignoring 100s

[Jock McKechnie]

On Wed, Feb 2, 2011 at 6:20 AM, Bogdan-Andrei Iancu <bogdan at opensips.org>wrote:

> Hi Jock,
>
>
> Jock McKechnie wrote:
>
>> Greetings;
>>
>> I apologise in advance for this one. I _know_ I screwed it up, but I just
>> cannot see how. I'm sure it's something blazingly obvious, but I just cannot
>> find it and it's driving me nuts.
>>
>> I've written an OpenSIPS config that uses an external perl 'helper' to do
>> an LCR lookup (it incorporates a bunch more things that the built-in
>> OpenSIPS LCR can't do, elsewise I'd use it),
>>
> Have you looked at Dynamic Routing module (a more powerful LCR) -
> http://www.opensips.org/html/docs/modules/1.6.x/drouting.html
>
>
>  I've rewritten the configuration several times over, and somewhere along
>> the way I've borked it, I guess. When the system receives a call it'll do
>> the LCR lookup, find a route, and sends the call out to that route.
>> The gateway it sends the call to responds with a '100 Trying'.... and then
>> a second later OpenSIPS sends the INVITE again, and gets another '100
>> Trying'. And then a second later, OpenSIPS sends the INVITE again, etc. Even
>> when the call comes up, sometimes OpenSIPS isn't "seeing" the '200 OK' and
>> continues sending INVITES until it times out the call.
>>
>
> Set debug=6, make a call, and post the output somewhere - most probably the
> replies from GW are not matching the INVITE transaction....but let's see
> what the logs say. (attaching a SIP capture of the call will help)
>

Thanks, Bogdan.

I'm staring at this and I'm not seeing where it's getting the '100 Tryings'
at all, but perhaps it's forest/trees for me. I've stripped off all the
syslog date/time headers, but during this time space it sent out the initial
INVITE, received a 100, send a second INVITE, a second 100 back, received a
183 Session Progress (presumably from the first INVITE)... after the time
frame included it sent another three INVITEs and received two 183s back
before everything BYE'd out.

[Wed Feb  2 09:05:38 2011] Attempting to relay call to
sip:+16414560000 at 192.168.1.99 <sip%3A%2B16414560000 at 192.168.1.99>
DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
DBG:core:parse_headers: flags=ffffffffffffffff
DBG:core:parse_headers: flags=78
DBG:tm:t_lookup_request: start searching: hash=22751, isACK=0
DBG:tm:matching_3261: RFC3261 transaction matching failed
DBG:tm:t_lookup_request: no transaction found
DBG:tm:run_reqin_callbacks: trans=0x7f5d8c2a14e8, callback type 1, id 1
entered
DBG:core:parse_headers: flags=78
DBG:dialog:new_dlg_val: inserting <accX_created>=<
DBG:tm:run_reqin_callbacks: trans=0x7f5d8c2a14e8, callback type 1, id 0
entered
DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout
DBG:core:parse_headers: flags=ffffffffffffffff
DBG:core:check_ip_address: params 10.10.101.101, 10.10.101.101, 0
DBG:core:_shm_resize: resize(0) called
DBG:tm:_reply_light: reply sent out. buf=0x7b21d8: SIP/2.0 1...,
shmem=0x7f5d8c2942b8: SIP/2.0 1
DBG:tm:_reply_light: finished
DBG:core:mk_proxy: doing DNS lookup...
DBG:tm:set_timer: relative timeout is 500000
DBG:tm:insert_timer_unsafe: [4]: 0x7f5d8c2a1708 (446000000)
DBG:tm:set_timer: relative timeout is 30
DBG:tm:insert_timer_unsafe: [0]: 0x7f5d8c2a1738 (475)
DBG:tm:t_relay_to: new transaction fwd'ed
DBG:tm:t_unref: UNREF_UNSAFE: [0x7f5d8c2a14e8] after is 0
DBG:dialog:unref_dlg: unref dlg 0x7f5d8c294d68 with 1 -> 2
DBG:core:destroy_avp_list: destroying list (nil)
DBG:core:receive_msg: cleaning up
DBG:tm:utimer_routine: timer routine:4,tl=0x7f5d8c2a1708 next=(nil),
timeout=446000000
DBG:tm:retransmission_handler: retransmission_handler : request resending
(t=0x7f5d8c2a14e8, INVITE si ... )
DBG:tm:set_timer: relative timeout is 1000000
DBG:tm:insert_timer_unsafe: [5]: 0x7f5d8c2a1708 (447000000)
DBG:tm:retransmission_handler: retransmission_handler : done
DBG:tm:utimer_routine: timer routine:5,tl=0x7f5d8c2a1708 next=(nil),
timeout=447000000
DBG:tm:retransmission_handler: retransmission_handler : request resending
(t=0x7f5d8c2a14e8, INVITE si ... )
DBG:tm:utimer_routine: timer routine:7,tl=0x7f5d8c292a20 next=(nil),
timeout=448000000
DBG:tm:retransmission_handler: retransmission_handler : request resending
(t=0x7f5d8c292800, INVITE si ... )
DBG:tm:set_timer: relative timeout is 4000000
DBG:tm:insert_timer_unsafe: [7]: 0x7f5d8c292a20 (452000000)
DBG:tm:retransmission_handler: retransmission_handler : done
DBG:tm:utimer_routine: timer routine:6,tl=0x7f5d8c2a1708 next=(nil),
timeout=449000000
DBG:tm:retransmission_handler: retransmission_handler : request resending
(t=0x7f5d8c2a14e8, INVITE si ... )
DBG:tm:set_timer: relative timeout is 4000000
DBG:tm:insert_timer_unsafe: [7]: 0x7f5d8c2a1708 (453000000)
DBG:tm:retransmission_handler: retransmission_handler : done
DBG:tm:utimer_routine: timer routine:7,tl=0x7f5d8c2a4408 next=(nil),
timeout=449000000
DBG:tm:retransmission_handler: retransmission_handler : request resending
(t=0x7f5d8c2a41e8, INVITE si ... )
DBG:tm:set_timer: relative timeout is 4000000
DBG:tm:insert_timer_unsafe: [7]: 0x7f5d8c2a4408 (453000000)
DBG:tm:retransmission_handler: retransmission_handler : done

The only way I have of replicating this is when I stick live system traffic
to it - so providing logs is a bit troublesome as it will have several calls
going through at once. But if more is required, I should be able to scrub
out identifying information and provider better details.

Thanks;

 - JP
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20110202/d1dfd48c/attachment.htm>