Fwd: 200OK Retransmission Error - sr-dev

14 Jun 2011

Hi All,

In an INVITE transaction, no ACK from A party and B party continue
retransmission of 200 OK. I have observed that kamailio is not passing the
retransmitted 200 OK message from B party to the Application(script) after 3
seconds. Instead kamailio directly sending to A party without passing to the
script.

I see in the logs that kamailio is cleaning up the transaction after 3
seconds..look for the string "DEBUG: t_lookup_request: no transaction
found"  before this log it is cleaning up the timer in the log "DEBUG:
cleanup_uac_timers: RETR/FR timers reset"

What does it mean by that??
How can we make the kamailio to pass the response to the application?

Please let me know your comments.. Here is the flow. I cannot send the
complete logs which is quite big. so i grep'd using the stirng
"tcp_read_req:
content-length|get_hdr_field|t_reply_matching|cleanup_uac_timers|RR11" from
the complete log..

A             kamailo                 B

----INVITE-->- --------------------INVITE

180 Ringing--<---------------180 Ringing
200 OK-----------<---------------200 OK 0
200 OK-----------<---------------200 OK 500ms
200 OK-----------<---------------200 OK 1s
200 OK-----------<---------------200 OK 2s

< From here it is not passing to the application- script>

200 OK-----------<---------------200 OK 4s
200 OK-----------<---------------200 OK 4s

  28 102:2011-06-13T19:47:37+01:00 [debug] sipserver: [26177] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [50]; uri=[
sip:5616990102@192.168.243.151:5060]
  36 95:2011-06-13T19:47:37+01:00 [debug] sipserver: [26177] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  267 86:2011-06-13T19:47:37+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 0
  282 102:2011-06-13T19:47:37+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  284 95:2011-06-13T19:47:37+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  285 89:2011-06-13T19:47:37+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  286 90:2011-06-13T19:47:38+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb0f62e50)!
  292 96:2011-06-13T19:47:38+01:00 [info] sipserver: [26269] INFO: <script>:
CI=1-8028(a)192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103@192.168.243.150 To=sip:5616990102@192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:180 Reason=Ringing CT=5616990102 <sip:
5616990102@192.168.243.161:5060;transport=tcp>
  331 86:2011-06-13T19:47:39+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  346 102:2011-06-13T19:47:39+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  348 95:2011-06-13T19:47:39+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  349 89:2011-06-13T19:47:39+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  350 90:2011-06-13T19:47:39+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb0f62e50)!
  356 96:2011-06-13T19:47:39+01:00 [info] sipserver: [26269] INFO: <script>:
CI=1-8028(a)192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103@192.168.243.150 To=sip:5616990102@192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102 <sip:5616990102
@192.168.243.161:5060;transport=tcp>
  398 89:2011-06-13T19:47:39+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_reply.c:1467]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
  406 86:2011-06-13T19:47:40+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  421 102:2011-06-13T19:47:40+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  423 95:2011-06-13T19:47:40+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  424 89:2011-06-13T19:47:40+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  425 90:2011-06-13T19:47:40+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb0f62e50)!
  431 96:2011-06-13T19:47:40+01:00 [info] sipserver: [26269] INFO: <script>:
CI=1-8028(a)192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103@192.168.243.150 To=sip:5616990102@192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102 <sip:5616990102
@192.168.243.161:5060;transport=tcp>
  481 86:2011-06-13T19:47:41+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  496 102:2011-06-13T19:47:41+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  498 95:2011-06-13T19:47:41+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  499 89:2011-06-13T19:47:41+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  500 90:2011-06-13T19:47:41+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb0f62e50)!
  506 96:2011-06-13T19:47:41+01:00 [info] sipserver: [26269] INFO: <script>:
CI=1-8028(a)192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103@192.168.243.150 To=sip:5616990102@192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102 <sip:5616990102
@192.168.243.161:5060;transport=tcp>
  556 86:2011-06-13T19:47:43+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  571 102:2011-06-13T19:47:43+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  573 95:2011-06-13T19:47:43+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  574 89:2011-06-13T19:47:43+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  575 90:2011-06-13T19:47:43+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb0f62e50)!
  581 96:2011-06-13T19:47:43+01:00 [info] sipserver: [26269] INFO: <script>:
CI=1-8028(a)192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103@192.168.243.150 To=sip:5616990102@192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102 <sip:5616990102
@192.168.243.161:5060;transport=tcp>
  631 86:2011-06-13T19:47:47+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  646 102:2011-06-13T19:47:47+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  648 95:2011-06-13T19:47:47+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  649 89:2011-06-13T19:47:47+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  650 90:2011-06-13T19:47:47+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  651 90:2011-06-13T19:47:47+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction
  693 86:2011-06-13T19:47:51+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  708 102:2011-06-13T19:47:51+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  710 95:2011-06-13T19:47:51+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  711 89:2011-06-13T19:47:51+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  712 90:2011-06-13T19:47:51+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  713 90:2011-06-13T19:47:51+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction
  755 86:2011-06-13T19:47:55+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  770 102:2011-06-13T19:47:55+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  772 95:2011-06-13T19:47:55+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  773 89:2011-06-13T19:47:55+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  774 90:2011-06-13T19:47:55+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  775 90:2011-06-13T19:47:55+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction
  817 86:2011-06-13T19:47:59+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  832 102:2011-06-13T19:47:59+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  834 95:2011-06-13T19:47:59+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  835 89:2011-06-13T19:47:59+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  836 90:2011-06-13T19:47:59+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  837 90:2011-06-13T19:47:59+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction
  879 86:2011-06-13T19:48:03+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  894 102:2011-06-13T19:48:03+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  896 95:2011-06-13T19:48:03+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  897 89:2011-06-13T19:48:03+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  898 90:2011-06-13T19:48:03+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  899 90:2011-06-13T19:48:03+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction
  941 86:2011-06-13T19:48:07+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  956 102:2011-06-13T19:48:07+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  958 95:2011-06-13T19:48:07+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  959 89:2011-06-13T19:48:07+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  960 90:2011-06-13T19:48:07+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  961 90:2011-06-13T19:48:07+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction
  1003 86:2011-06-13T19:48:11+01:00 [debug] sipserver: [26269] DEBUG: <core>
[tcp_read.c:933]: tcp_read_req: content-length= 191
  1018 102:2011-06-13T19:48:11+01:00 [debug] sipserver: [26269] DEBUG:
<core> [parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [65]; uri=[
sip:5616990102@192.168.243.151:5060]
  1020 95:2011-06-13T19:48:11+01:00 [debug] sipserver: [26269] DEBUG: <core>
[parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
  1021 89:2011-06-13T19:48:11+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:967]: DEBUG: t_reply_matching: hash 5084 label 418362480 branch
0
  1022 90:2011-06-13T19:48:11+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1052]: DEBUG: t_reply_matching: no matching transaction exists
  1023 90:2011-06-13T19:48:11+01:00 [debug] sipserver: [26269] DEBUG: tm
[t_lookup.c:1055]: DEBUG: t_reply_matching: failure to match a transaction