[SR-Users] question on TM transaction matching

[Kelvin Chua]

i am monitoring an issue with 5.1.2 where a cancel is not being propagated
after a 183 is received the packet dump doesn't show anything anomalous.
some notes:
1. the invite went out through t_relay(), transaction is tracked
2. cancel is handled this way
    if (is_method("CANCEL")) {
        xlog("CANCEL received");
        if (t_check_trans()) {
            route(RELAY);
        }
        exit;
    }
3. if the UAC who is sending the call to kamailio is configured to send
invite with RURI without a port i.e.  14087654321 at w.x.y.z instead of
14087654321 at w.x.y.z:6050, then this does not happen
4. can be argued that this is not an issue, and that the client should just
be configured properly with outbound proxy and ruri without port. but i am
just being difficult here and wanted to understand what is going on with
the matching algo.

TM debug, in case it helps
2018-04-18T07:29:50.984652+00:00 pinkman /usr/sbin/kamailio[17670]: ERROR:
<script>: 100 Trying received
2018-04-18T07:29:50.984746+00:00 pinkman /usr/sbin/kamailio[17670]: DEBUG:
tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=100,
new_code=100
2018-04-18T07:29:50.984752+00:00 pinkman /usr/sbin/kamailio[17670]: DEBUG:
tm [t_reply.c:1786]: relay_reply(): branch=1, save=0, relay=-1 icode=0
2018-04-18T07:29:53.564979+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6b8a60
from timer.c:651
2018-04-18T07:29:53.752387+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6bbcd8
from timer.c:651
2018-04-18T07:29:54.002501+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6bf130
from timer.c:651
2018-04-18T07:29:54.184438+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f8212d77e28) id=3 global id=2
T start=0xffffffffffffffff
2018-04-18T07:29:54.184454+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 6057 label
0 branch 1
2018-04-18T07:29:54.184468+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f8212d77e28) matched an
active transaction (T=0x7f820b6cc988)!
2018-04-18T07:29:54.184474+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f8212d77e28) id=3 global id=3
T end=0x7f820b6cc988
2018-04-18T07:29:54.184485+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_reply.c:2207]: reply_received(): org. status uas=100, uac[1]=100
local=0 is_invite=1)
2018-04-18T07:29:54.184544+00:00 pinkman /usr/sbin/kamailio[17671]: ERROR:
<script>: 183 Session Progress received
2018-04-18T07:29:54.184825+00:00 pinkman rtpengine[1660]: INFO:
[EqRkPDiOFOOhFg_3018V8A..]: Received command 'answer' from 127.0.0.1:41084
2018-04-18T07:29:54.184918+00:00 pinkman rtpengine[1660]: INFO:
[EqRkPDiOFOOhFg_3018V8A..]: answer time = 0.000074 sec
2018-04-18T07:29:54.184931+00:00 pinkman rtpengine[1660]: INFO:
[EqRkPDiOFOOhFg_3018V8A..]: Replying to 'answer' from 127.0.0.1:41084
2018-04-18T07:29:54.185049+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=100,
new_code=183
2018-04-18T07:29:54.185066+00:00 pinkman /usr/sbin/kamailio[17671]: DEBUG:
tm [t_reply.c:1786]: relay_reply(): branch=1, save=0, relay=1 icode=0
2018-04-18T07:29:54.252450+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6c2540
from timer.c:651
2018-04-18T07:29:54.377492+00:00 pinkman rtpengine[1660]: WARNING:
[EqRkPDiOFOOhFg_3018V8A.. port 18598]: RTP packet with unknown payload type
95 received
2018-04-18T07:29:54.564924+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6c57a8
from timer.c:651
2018-04-18T07:29:55.627429+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6c8bf8
from timer.c:651
2018-04-18T07:29:55.939949+00:00 pinkman /usr/sbin/kamailio[17678]: DEBUG:
tm [h_table.c:129]: free_cell_helper(): freeing transaction 0x7f820b6cc988
from timer.c:651
2018-04-18T07:29:56.404385+00:00 pinkman /usr/sbin/kamailio[17673]: ERROR:
<script>: CANCEL received
2018-04-18T07:29:56.404411+00:00 pinkman /usr/sbin/kamailio[17673]: DEBUG:
tm [t_lookup.c:711]: t_lookupOriginalT(): searching on hash entry 6057
2018-04-18T07:29:56.404424+00:00 pinkman /usr/sbin/kamailio[17673]: DEBUG:
tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed
2018-04-18T07:29:56.404429+00:00 pinkman /usr/sbin/kamailio[17673]: DEBUG:
tm [t_lookup.c:801]: t_lookupOriginalT():  no CANCEL matching found!
2018-04-18T07:29:56.404434+00:00 pinkman /usr/sbin/kamailio[17673]: DEBUG:
tm [t_lookup.c:803]: t_lookupOriginalT(): lookup completed
2018-04-18T07:29:56.404441+00:00 pinkman /usr/sbin/kamailio[17673]: DEBUG:
tm [tm.c:1096]: ki_t_lookup_cancel_flags(): lookup_original:
t_lookupOriginalT returned: (nil)



Kelvin Chua
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20180418/91f8b21f/attachment.html>