[SR-Users] Fwd: 200OK Retransmission Error
Jijo
realjijo at gmail.com
Tue Jun 14 01:54:07 CEST 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 at 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 at 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 at 192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103 at 192.168.243.150 To=sip:5616990102 at 192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:180 Reason=Ringing CT=5616990102
<sip:5616990102 at 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 at 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 at 192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103 at 192.168.243.150 To=sip:5616990102 at 192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102
<sip:5616990102 at 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 at 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 at 192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103 at 192.168.243.150 To=sip:5616990102 at 192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102
<sip:5616990102 at 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 at 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 at 192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103 at 192.168.243.150 To=sip:5616990102 at 192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102
<sip:5616990102 at 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 at 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 at 192.168.243.150 -RR11 - Entry M=INVITE RURI=<null> From=
sip:5616990103 at 192.168.243.150 To=sip:5616990102 at 192.168.243.151:5060 RD=
<null> IP=192.168.243.161 Code:200 Reason=OK CT=5616990102
<sip:5616990102 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20110613/c44806a4/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 200-retran-osb2.log
Type: application/octet-stream
Size: 136399 bytes
Desc: not available
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20110613/c44806a4/attachment-0001.obj>
More information about the sr-users
mailing list