Salut Bogdan,
Thank you for your response. I think the reply is correct, because in the log file I can see:
2007-10-15 06:28:48.545|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:28:48.545|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:28:48.546|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:28:52.754|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:28:52.754|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=364, group=0\n 2007-10-15 06:28:52.753|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:28:52.753|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:29:15.378|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:29:15.378|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:29:15.378|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:29:19.871|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:29:19.871|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=391, group=0\n 2007-10-15 06:29:19.871|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:29:19.871|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:29:21.853|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n [22569] 2007-10-15 06:29:21.853|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n [22569] 2007-10-15 06:29:25.894|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:29:25.894|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=397, group=0\n 2007-10-15 06:29:25.894|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:29:25.894|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:29:50.049|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:29:50.049|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:29:50.051|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:29:55.014|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:29:55.014|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=425, group=0\n 2007-10-15 06:29:55.014|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:29:55.014|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:31:45.071|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:31:45.071|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:31:45.071|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:31:49.834|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:31:49.834|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=540, group=0\n 2007-10-15 06:31:49.834|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:31:49.834|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
Maybe I don't understand it correctly? It's about T=0xb5e98bd8. It gets matched, removed, deleted. Many times.
The situation was reproduced using 2 different clients: sipp and a proprietary client (using two opensource libraries: osip and exosip).
What do you think?
Thanks, Sica.
----- Original Message ---- From: Bogdan-Andrei Iancu bogdan@voice-system.ro To: Vasile Zaharia sicavz@yahoo.com Cc: users@openser.org Sent: Tuesday, October 30, 2007 6:35:10 AM Subject: Re: [OpenSER-Users] retransmissions after final response
Salut Sica,
The problem may reside in two places: 1) the reply is not correct and the client is not able to match it to the sent request (and keeps retransmitting) 2) the client is not able to match (due whatever other bugs) the reply.
Salutari, Bogdan
Vasile Zaharia wrote:
Hi all,
I'm developing a Presence AS OpenSER module (derived from the OpenSER
Presence module)
and, from time to time, it happens the next situation:
- AS sends a NOTIFY message
- the client receives the NOTIFY and responds with 200 OK
- AS receives 200 OK response, but it starts to retransmit the
original NOTIFY and it
retransmits it until it gets back a 408 Request timeout.
Please note that I use "tm" module for sending SIP messages, so I
don't
handle retransmissions explicitly in my module. Also, note that it does not happen all the time, but from time to
time.
Does anyone else met a similar situation?
Thanks, Sica.
Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
Users mailing list Users@openser.org http://openser.org/cgi-bin/mailman/listinfo/users
__________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
Salut Sica,
So you say that openser does retransmission even after receiving the 200 OK for the request? are you sure it is about the same transaction?
Could you provide the debug log showing also the retransmission events? (just send me the entire log).
Salutari, Bogdan
Vasile Zaharia wrote:
Salut Bogdan,
Thank you for your response. I think the reply is correct, because in the log file I can see:
2007-10-15 06:28:48.545|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:28:48.545|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:28:48.546|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:28:52.754|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:28:52.754|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=364, group=0\n 2007-10-15 06:28:52.753|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:28:52.753|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:29:15.378|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:29:15.378|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:29:15.378|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:29:19.871|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:29:19.871|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=391, group=0\n 2007-10-15 06:29:19.871|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:29:19.871|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:29:21.853|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n [22569] 2007-10-15 06:29:21.853|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n [22569] 2007-10-15 06:29:25.894|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:29:25.894|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=397, group=0\n 2007-10-15 06:29:25.894|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:29:25.894|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:29:50.049|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:29:50.049|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:29:50.051|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:29:55.014|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:29:55.014|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=425, group=0\n 2007-10-15 06:29:55.014|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:29:55.014|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
2007-10-15 06:31:45.071|t_lookup.c:824|t_reply_matching|DEBUG: t_reply_matching: reply matched (T=0xb5e98bd8)!\n 2007-10-15 06:31:45.071|t_lookup.c:924|t_check|DEBUG: t_check: end=0xb5e98bd8\n 2007-10-15 06:31:45.071|t_hooks.c:203|run_trans_callbacks|DBG: trans=0xb5e98bd8, callback type 256, id 0 entered\n 2007-10-15 06:31:49.834|timer.c:434|wait_handler|DEBUG: wait_handler : removing 0xb5e98bd8 from table \n 2007-10-15 06:31:49.834|timer.c:714|remove_timer_unsafe|DEBUG: unlinking timer: tl=0xb5e98d54, timeout=540, group=0\n 2007-10-15 06:31:49.834|timer.c:239|delete_cell|DEBUG: delete transaction 0xb5e98bd8\n 2007-10-15 06:31:49.834|timer.c:443|wait_handler|DEBUG: wait_handler : done\n
Maybe I don't understand it correctly? It's about T=0xb5e98bd8. It gets matched, removed, deleted. Many times.
The situation was reproduced using 2 different clients: sipp and a proprietary client (using two opensource libraries: osip and exosip).
What do you think?
Thanks, Sica.
----- Original Message ---- From: Bogdan-Andrei Iancu bogdan@voice-system.ro To: Vasile Zaharia sicavz@yahoo.com Cc: users@openser.org Sent: Tuesday, October 30, 2007 6:35:10 AM Subject: Re: [OpenSER-Users] retransmissions after final response
Salut Sica,
The problem may reside in two places: 1) the reply is not correct and the client is not able to match it to the sent request (and keeps retransmitting) 2) the client is not able to match (due whatever other bugs) the reply.
Salutari, Bogdan
Vasile Zaharia wrote:
Hi all,
I'm developing a Presence AS OpenSER module (derived from the OpenSER
Presence module)
and, from time to time, it happens the next situation:
- AS sends a NOTIFY message
- the client receives the NOTIFY and responds with 200 OK
- AS receives 200 OK response, but it starts to retransmit the
original NOTIFY and it
retransmits it until it gets back a 408 Request timeout.
Please note that I use "tm" module for sending SIP messages, so I
don't
handle retransmissions explicitly in my module. Also, note that it does not happen all the time, but from time to
time.
Does anyone else met a similar situation?
Thanks, Sica.
Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
Users mailing list Users@openser.org http://openser.org/cgi-bin/mailman/listinfo/users
Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com
-
Bogdan-Andrei Iancu -
Vasile Zaharia