15 Jun
2011
15 Jun
'11
7:16 a.m.
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