Hello,
I have noticed that I am seeing an warning whenever PUA sends a request. This wasn't happening during the testing I did for my recent PUA changes, but it is happening now. I believe the WARNING is caused by a timer being set with a time of 0 in the TM module, but I am not very familiar with that part of the code.
If it is in the TM module I suspect it is a recent change made within the last couple of weeks.
The warning I am seeing is: 14(6323) WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added
Does anyone have any ideas?
Thanks,
Peter
Hello,
On 8/18/11 5:05 PM, Peter Dunkley wrote:
Hello,
I have noticed that I am seeing an warning whenever PUA sends a request. This wasn't happening during the testing I did for my recent PUA changes, but it is happening now. I believe the WARNING is caused by a timer being set with a time of 0 in the TM module, but I am not very familiar with that part of the code.
If it is in the TM module I suspect it is a recent change made within the last couple of weeks.
The warning I am seeing is: 14(6323) WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added
Does anyone have any ideas?
Andrei did recently a commit to tm related to timers, maybe he can comment on this.
http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=a92001d4...
Cheers, Daniel
On Aug 18, 2011 at 16:05, Peter Dunkley peter.dunkley@crocodile-rcs.com wrote:
Hello,
I have noticed that I am seeing an warning whenever PUA sends a request. This wasn't happening during the testing I did for my recent PUA changes, but it is happening now. I believe the WARNING is caused by a timer being set with a time of 0 in the TM module, but I am not very familiar with that part of the code.
You get this warning only when trying to send a new request from the pua module? Do you try to send it using t_request or t_request_within? Did you notice anything else, like immediate retransmissions?
Andrei
If it is in the TM module I suspect it is a recent change made within the last couple of weeks.
The warning I am seeing is: 14(6323) WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added
Does anyone have any ideas?
Thanks,
Peter
Peter Dunkley Technical Director Crocodile RCS Ltd
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
On Mon, 2011-08-22 at 12:31 +0200, Andrei Pelinescu-Onciul wrote:
You get this warning only when trying to send a new request from the pua module? Do you try to send it using t_request or t_request_within? Did you notice anything else, like immediate retransmissions?
I see this warning for both PUBLISH (uses t_request) and SUBSCRIBE (uses t_request_within) requests send by PUA.
In this use-case both the PUBLISH and SUBSCRIBE requests are looped locally so the request goes from PUA to PRESENCE in the same Kamailio instance.
I just re-ran the test with the PUBLISH request and saw no retransmissions of the PUBLISH. As far as I can tell everything is working fine. The request is sent and received, the presentity is created, as response is sent and received, there are no retransmissions.
However, despite things appearing to work, this warning message appears once for each request sent from PUA.
Thanks,
Peter
A correction.
PUBLISH uses t_request. SUBSCRIBE uses t_request_outside for initial SUBSCRIBEs and t_request_within for re-SUBSCRIBEs.
I know that I can see the problem for PUBLISH requests and initial SUBSCRIBEs. I am not sure about re-SUBSCRIBEs.
Regards,
Peter
On Mon, 2011-08-22 at 12:09 +0100, Peter Dunkley wrote:
On Mon, 2011-08-22 at 12:31 +0200, Andrei Pelinescu-Onciul wrote:
You get this warning only when trying to send a new request from the pua module? Do you try to send it using t_request or t_request_within? Did you notice anything else, like immediate retransmissions?
I see this warning for both PUBLISH (uses t_request) and SUBSCRIBE (uses t_request_within) requests send by PUA.
In this use-case both the PUBLISH and SUBSCRIBE requests are looped locally so the request goes from PUA to PRESENCE in the same Kamailio instance.
I just re-ran the test with the PUBLISH request and saw no retransmissions of the PUBLISH. As far as I can tell everything is working fine. The request is sent and received, the presentity is created, as response is sent and received, there are no retransmissions.
However, despite things appearing to work, this warning message appears once for each request sent from PUA.
Thanks,
Peter
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
Thanks, it should be fixed now. It was not related to PUA, but to new transactions for which the retransmissions were disabled from the start (e.g. tcp, sctp).
Andrei
On Aug 22, 2011 at 12:09, Peter Dunkley peter.dunkley@crocodile-rcs.com wrote:
On Mon, 2011-08-22 at 12:31 +0200, Andrei Pelinescu-Onciul wrote:
You get this warning only when trying to send a new request from the pua module? Do you try to send it using t_request or t_request_within? Did you notice anything else, like immediate retransmissions?
I see this warning for both PUBLISH (uses t_request) and SUBSCRIBE (uses t_request_within) requests send by PUA.
In this use-case both the PUBLISH and SUBSCRIBE requests are looped locally so the request goes from PUA to PRESENCE in the same Kamailio instance.
I just re-ran the test with the PUBLISH request and saw no retransmissions of the PUBLISH. As far as I can tell everything is working fine. The request is sent and received, the presentity is created, as response is sent and received, there are no retransmissions.
However, despite things appearing to work, this warning message appears once for each request sent from PUA.
Thanks,
Peter
-- Peter Dunkley Technical Director Crocodile RCS Ltd
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
Thanks Andrei,
The fix works for me.
Peter
On Mon, 2011-08-22 at 20:08 +0200, Andrei Pelinescu-Onciul wrote:
Thanks, it should be fixed now. It was not related to PUA, but to new transactions for which the retransmissions were disabled from the start (e.g. tcp, sctp).
Andrei
On Aug 22, 2011 at 12:09, Peter Dunkley peter.dunkley@crocodile-rcs.com wrote:
On Mon, 2011-08-22 at 12:31 +0200, Andrei Pelinescu-Onciul wrote:
You get this warning only when trying to send a new request from the pua module? Do you try to send it using t_request or t_request_within? Did you notice anything else, like immediate retransmissions?
I see this warning for both PUBLISH (uses t_request) and SUBSCRIBE (uses t_request_within) requests send by PUA.
In this use-case both the PUBLISH and SUBSCRIBE requests are looped locally so the request goes from PUA to PRESENCE in the same Kamailio instance.
I just re-ran the test with the PUBLISH request and saw no retransmissions of the PUBLISH. As far as I can tell everything is working fine. The request is sent and received, the presentity is created, as response is sent and received, there are no retransmissions.
However, despite things appearing to work, this warning message appears once for each request sent from PUA.
Thanks,
Peter
-- Peter Dunkley Technical Director Crocodile RCS Ltd
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
Andrei Pelinescu-Onciul writes:
You get this warning only when trying to send a new request from the pua module? Do you try to send it using t_request or t_request_within? Did you notice anything else, like immediate retransmissions?
andrei,
here is an example on how i get the warnings. i start two sip UAs at the same time and they send during same second a bunch of subscribe and publishes via sip proxy sr to presence server sr. there is no pua involved.
-- juha
Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9820]: INFO: SUBSCRIBE sip:test@vm.test.fi by sip:test@test.fi has no Proxy-Authorization header Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9821]: INFO: SUBSCRIBE sip:jh@test.fi by sip:test@test.fi has no Proxy-Authorization header Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9819]: INFO: PUBLISH sip:test@test.fi by sip:test@test.fi has no Proxy-Authorization header Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: SUBSCRIBE sip:jh@vm.test.fi by sip:jh@test.fi has no Proxy-Authorization header Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: PUBLISH sip:jh@test.fi by sip:jh@test.fi has no Proxy-Authorization header Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9820]: INFO: SUBSCRIBE sip:test@vm.test.fi by test@test.fi as sip:test@test.fi from <192.98.102.10> is authorized Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: SUBSCRIBE sip:test@test.fi by sip:jh@test.fi has no Proxy-Authorization header Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9822]: INFO: SUBSCRIBE sip:jh@test.fi by test@test.fi as sip:test@test.fi from <192.98.102.10> is authorized Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9821]: INFO: PUBLISH sip:test@test.fi by test@test.fi as sip:test@test.fi from <192.98.102.10> is authorized Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: SUBSCRIBE sip:jh@vm.test.fi by jh@test.fi as sip:jh@test.fi from <192.98.102.10> is authorized Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9820]: INFO: Routing SUBSCRIBE sip:test@vm.test.fi to sip:127.0.0.1:5082;transport=udp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: Routing SUBSCRIBE sip:jh@vm.test.fi to sip:127.0.0.1:5082;transport=tcp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: <core> [tcp_main.c:2755]: quick connect for 0xb4a530e8 Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: PUBLISH sip:jh@test.fi by jh@test.fi as sip:jh@test.fi from <192.98.102.10> is authorized Aug 22 20:00:25 sip /usr/sbin/pres-serv[9691]: INFO: INFO: Handling SUBSCRIBE sip:test@vm.test.fi Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: INFO: Handling SUBSCRIBE sip:jh@vm.test.fi Aug 22 20:00:25 sip /usr/sbin/pres-serv[9691]: INFO: Routing locally generated NOTIFY to sip:test@192.98.102.10:5074;transport=udp Aug 22 20:00:25 sip /usr/sbin/pres-serv[9691]: INFO: presence [notify.c:1593]: NOTIFY sip:test@test.fi via sip:192.98.102.10;lr;ftag=gabqc on behalf of sip:test@test.fi for event message-summary Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9819]: INFO: Routing in-dialog NOTIFY sip:test@192.98.102.10:5074;transport=udp from sip:test@test.fi Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: Routing locally generated NOTIFY to sip:jh_test_fi@192.98.102.10:5074;alias=192.98.102.10~58663~2;transport=tcp Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: <core> [tcp_main.c:2755]: quick connect for 0xb4f667b0 Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: presence [notify.c:1593]: NOTIFY sip:jh@test.fi via sip:192.98.102.10;transport=tcp;lr;ftag=sspcj on behalf of sip:jh@test.fi for event message-summary Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9822]: INFO: Routing SUBSCRIBE sip:jh@test.fi to sip:127.0.0.1:5082;transport=udp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9821]: INFO: Routing PUBLISH sip:test@test.fi to sip:127.0.0.1:5082;transport=udp Aug 22 20:00:25 sip /usr/sbin/pres-serv[9692]: INFO: INFO: Handling SUBSCRIBE sip:jh@test.fi Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9857]: INFO: Routing in-dialog NOTIFY sip:jh_test_fi@192.98.102.10:5074;transport=tcp from sip:jh@test.fi to sip:192.98.102.10:58663;transport=tcp Aug 22 20:00:25 sip /usr/sbin/pres-serv[9694]: INFO: INFO: Handling PUBLISH sip:test@test.fi Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: Routing PUBLISH sip:jh@test.fi to sip:127.0.0.1:5082;transport=tcp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: INFO: Handling PUBLISH sip:jh@test.fi Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9857]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: SUBSCRIBE sip:test@test.fi by jh@test.fi as sip:jh@test.fi from <192.98.102.10> is authorized Aug 22 20:00:25 sip /usr/sbin/pres-serv[9692]: INFO: Routing locally generated NOTIFY to sip:test@192.98.102.10:5074;transport=udp Aug 22 20:00:25 sip /usr/sbin/pres-serv[9692]: INFO: presence [notify.c:1593]: NOTIFY sip:test@test.fi via sip:192.98.102.10;lr;ftag=jysro on behalf of sip:jh@test.fi for event presence Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9819]: INFO: Routing in-dialog NOTIFY sip:test@192.98.102.10:5074;transport=udp from sip:jh@test.fi Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: INFO: Routing SUBSCRIBE sip:test@test.fi to sip:127.0.0.1:5082;transport=tcp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9855]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: Routing locally generated NOTIFY to sip:test@192.98.102.10:5074;transport=udp Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: presence [notify.c:1593]: NOTIFY sip:test@test.fi via sip:192.98.102.10;lr;ftag=jysro on behalf of sip:jh@test.fi for event presence Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: INFO: Handling SUBSCRIBE sip:test@test.fi Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9820]: INFO: Routing in-dialog NOTIFY sip:test@192.98.102.10:5074;transport=udp from sip:jh@test.fi Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: Routing locally generated NOTIFY to sip:jh_test_fi@192.98.102.10:5074;alias=192.98.102.10~58663~2;transport=tcp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9857]: INFO: Routing in-dialog NOTIFY sip:jh_test_fi@192.98.102.10:5074;transport=tcp from sip:test@test.fi to sip:192.98.102.10:58663;transport=tcp Aug 22 20:00:25 sip /usr/sbin/sip-proxy[9857]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:00:25 sip /usr/sbin/pres-serv[9699]: INFO: presence [notify.c:1593]: NOTIFY sip:jh@test.fi via sip:192.98.102.10;transport=tcp;lr;ftag=qkzdu on behalf of sip:test@test.fi for event presence Aug 22 20:02:25 sip /usr/sbin/sip-proxy[9857]: INFO: Routing in-dialog SUBSCRIBE sip:127.0.0.1:5082;transport=tcp from sip:jh@test.fi Aug 22 20:02:25 sip /usr/sbin/sip-proxy[9857]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:02:25 sip /usr/sbin/pres-serv[9701]: INFO: INFO: Handling in-dialog SUBSCRIBE to sip:test@test.fi from sip:jh@test.fi Aug 22 20:02:25 sip /usr/sbin/pres-serv[9701]: INFO: Routing locally generated NOTIFY to sip:jh_test_fi@192.98.102.10:5074;alias=192.98.102.10~58663~2;transport=tcp Aug 22 20:02:25 sip /usr/sbin/pres-serv[9701]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:02:25 sip /usr/sbin/pres-serv[9701]: INFO: presence [notify.c:1593]: NOTIFY sip:jh@test.fi via sip:192.98.102.10;transport=tcp;lr;ftag=qkzdu on behalf of sip:test@test.fi for event presence Aug 22 20:02:25 sip /usr/sbin/sip-proxy[9855]: INFO: Routing in-dialog NOTIFY sip:jh_test_fi@192.98.102.10:5074;transport=tcp from sip:test@test.fi to sip:192.98.102.10:58663;transport=tcp Aug 22 20:02:25 sip /usr/sbin/sip-proxy[9855]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added
andrei,
here is one more (simpler) example. ua changes presence status that generates publish request via sip proxy to presence server:
Aug 22 20:11:57 sip /usr/sbin/sip-proxy[9857]: INFO: PUBLISH sip:jh@test.fi by jh@test.fi as sip:jh@test.fi from <192.98.102.10> is authorized Aug 22 20:11:57 sip /usr/sbin/sip-proxy[9857]: INFO: Routing PUBLISH sip:jh@test.fi to sip:127.0.0.1:5082;transport=tcp Aug 22 20:11:57 sip /usr/sbin/sip-proxy[9857]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:11:57 sip /usr/sbin/pres-serv[9702]: INFO: INFO: Handling PUBLISH sip:jh@test.fi Aug 22 20:11:57 sip /usr/sbin/pres-serv[9702]: INFO: Routing locally generated NOTIFY to sip:test@192.98.102.10:5074;transport=udp Aug 22 20:11:57 sip /usr/sbin/pres-serv[9702]: INFO: presence [notify.c:1593]: NOTIFY sip:test@test.fi via sip:192.98.102.10;lr;ftag=jysro on behalf of sip:jh@test.fi for event presence Aug 22 20:11:57 sip /usr/sbin/sip-proxy[9820]: INFO: Routing in-dialog NOTIFY sip:test@192.98.102.10:5074;transport=udp from sip:jh@test.fi
and here is what happens when ua sends re-subscribe:
Aug 22 20:13:20 sip /usr/sbin/sip-proxy[9858]: INFO: Routing in-dialog SUBSCRIBE sip:127.0.0.1:5082;transport=tcp from sip:jh@test.fi Aug 22 20:13:20 sip /usr/sbin/sip-proxy[9858]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:13:20 sip /usr/sbin/pres-serv[9699]: INFO: INFO: Handling in-dialog SUBSCRIBE to sip:test@test.fi from sip:jh@test.fi Aug 22 20:13:20 sip /usr/sbin/pres-serv[9699]: INFO: Routing locally generated NOTIFY to sip:jh_test_fi@192.98.102.10:5074;alias=192.98.102.10~58663~2;transport=tcp Aug 22 20:13:20 sip /usr/sbin/sip-proxy[9856]: INFO: Routing in-dialog NOTIFY sip:jh_test_fi@192.98.102.10:5074;transport=tcp from sip:test@test.fi to sip:192.98.102.10:58663;transport=tcp Aug 22 20:13:20 sip /usr/sbin/sip-proxy[9856]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:13:20 sip /usr/sbin/pres-serv[9699]: WARNING: <core> [timer_funcs.h:119]: WARNING: timer: add_timeout: 0 expire timer added Aug 22 20:13:20 sip /usr/sbin/pres-serv[9699]: INFO: presence [notify.c:1593]: NOTIFY sip:jh@test.fi via sip:192.98.102.10;transport=tcp;lr;ftag=qkzdu on behalf of sip:test@test.fi for event presence
-- juha
-
Andrei Pelinescu-Onciul -
Daniel-Constantin Mierla -
Juha Heinanen -
Peter Dunkley