sr-users August 2009

sr-users@lists.kamailio.org

55 participants
77 discussions

Re: [Kamailio-Users] presence_dialoginfo context
by David 14 Aug '09

14 Aug '09

Hey, Here is an expert from the /var/log/messsages : Aug 14 10:16:42 kamailio-dev /usr/sbin/kamailio[28924]: New request - M=PUBLISH RURI=sip:group1.105@mydomain.tld F=sip:group1.105@mydomain.tld T=sip:group1.105@mydomain.tld IP=72.55.182.125 ID=7bddec01-28924(a)72.55.182.125 Aug 14 10:16:42 kamailio-dev /usr/sbin/kamailio[28924]: Publish rewritten forwarded for ext=group1.105 ruri=sip:group1.105@mydomain.tld duri=<null> body=<?xml version="1.0"?> <dialog-info xmlns="urn:… [View More]ietf:params:xml:ns:dialog-info" version="0" state="full" entity="sip:group1.105@mydomain.tld"> <dialog id="5a9207de129fc16f49cafaa425e312f1(a)mydomain.tld" call-id="5a9207de129fc16f49cafaa425e312f1(a)mydomain.tld" local-tag="4fbrxu9548" remote-tag="as4fb63283" direction="recipient"> <state>early</state> <remote> <identity>sip:103@mydomain.tld</identity> <target uri="sip:103@mydomain.tld"/> </remote> <local> <identity>sip:group1.105@mydomain.tld</identity> <target uri="sip:group1.105@mydomain.tld"/> </local> </dialog> </dialog-info> Aug 14 10:16:42 kamailio-dev /usr/sbin/kamailio[28932]: New request - M=PUBLISH RURI=sip:group1.105@mydomain.tld F=sip:group1.105@mydomain.tld T=sip:group1.105@mydomain.tld IP=72.55.182.125 ID=7bddec01-28924(a)72.55.182.125 Aug 14 10:16:42 kamailio-dev /usr/sbin/kamailio[28932]: Publish accepted for ext=group1.105 ruri=sip:group1.105@mydomain.tld duri=<null> body=<?xml version="1.0"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="0" state="full" entity="sip:105@mydomain.tld"> <dialog id="5a9207de129fc16f49cafaa425e312f1(a)mydomain.tld" call-id="5a9207de129fc16f49cafaa425e312f1(a)mydomain.tld" local-tag="4fbrxu9548" remote-tag="as4fb63283" direction="recipient"> <state>early</state> <remote> <identity>sip:103@mydomain.tld</identity> <target uri="sip:103@mydomain.tld"/> </remote> <local> <identity>sip:105@mydomain.tld</identity> <target uri="sip:105@mydomain.tld"/> </local> </dialog> </dialog-info> Aug 14 10:16:42 kamailio-dev /usr/sbin/kamailio[28932]: INFO:presence:send_notify_request: NOTIFY sip:group1.101@mydomain.tld via sip:group1.101@phone.ip:57234 on behalf of sip:105@mydomain.tld for event dialog But the phone's syslog shows this : Aug 14 10:16:21 linksys [0:57234]<<server.ip:5060 Aug 14 10:16:21 linksys [0:57234]<<server.ip:5060 Aug 14 10:16:21 linksys NOTIFY sip:group1.101@phone.ip:57234 SIP/2.0^M Via: SIP/2.0/UDP 72.55.182.125;branch=z9hG4bK0b0a.9725e23.0^M To: sip:group1.101@mydomain.tld;tag=1c32db3af4d889ac^M From: sip:105@mydomain.tld;tag=6d6077e15fecee48b2721a5e94bf8883-91a8^M CSeq: 12 NOTIFY^M Call-ID: 984d4cd2-37b04f4(a)192.168.1.104^M Content-Length: 655^M User-Agent: Kamailio (1.5.2-tls (i386/linux))^M Max-Forwards: 70^M Event: dialog^M Contact: <sip:mydomain.tld:5060>^M Subscription-State: active;expires=1470^M Content-Type: application/dialog-info+xml^M ^M <?xml version="1.0"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="11" state="full" entity="group1.105(a)mydomain.tld"> <dialog id="0b5776fb2ea599c429038414054eb383(a)mydomain.tld" call-id="0b5776fb2ea599c429038414054eb383(a)mydomain.tld" local-tag="loto7h3i9a" remote-tag="as4f284f05" direction="recipient"> <state>early</state> <remote> <identity>sip:103@mydomain.tld</identity> <target uri=" Everything is good, but notice the entity is somehow back to group1.105. Where do you want me to run the traceroute? On the server? David Klaus Darilion wrote: > > > David schrieb: >> Hey, >> >> I tried that, but it did not seem to change anything. I saw the >> message change on the second loop, but it seems that the presence >> module figure out my tactic and fixed the message. > > That's not possible. The presence module does not alter the received > body. I think the problem is somewhere else. > > Can you send me a trace? > > ngrep -t -P "" -W byline -d any port 5060 > > regards > klaus > > >> >> David >> >> Klaus Darilion wrote: >>> That does not work: presence_server always uses the original >>> received body, the modifications applied by you are not seen by the >>> presence server. >>> >>> The workaround would be to "loop" the modified PUBLISH to Kamailio >>> again, e.g.: >>> >>> listen=.......:5060 >>> listen=.......:5050 >>> >>> route{ >>> ... >>> if (is_method("PUBLISH")) { >>> if (dst_port==5060) { >>> subst_body('/group1[.]//'); >>> t_relay("udp:127.0.0.1:5050); >>> } else if (dst_port==5050) { >>> handle_publish(); >>> t_release(); >>> } >>> } >>> ... >>> } >>> >>> >>> klaus >>> David schrieb: >>>> Hey, >>>> >>>> I tried doing a subst or replace_body_all to change the entity="" >>>> value, >>>> >>>> if (is_method("PUBLISH") ) >>>> { >>>> subst_body('/group1[.]//'); >>>> handle_publish(); >>>> t_release(); >>>> } >>>> >>>> It did not work, the $rb variable still shows the old body and the >>>> NOTIFY received on the phone is the old body as well. >>>> >>>> I thought about doing a string replace on the outbound NOTIFY but >>>> it never hits my routing script, so I can't. >>>> >>>> I read textops and it does not list any limitations relating to me. >>>> >>>> Any ideas? >>>> >>>> David >>>> >>>> Klaus Darilion wrote: >>>>> I think the problem lies within the dialog module. Dialog module >>>>> stores from/to URI. Both, from and to URI are derived from the >>>>> headers. We could extend the dialog module to store request-URI in >>>>> the dialog-info structure too, and add an option to pua_dialoginfo >>>>> to use RURI instead of To-URI. >>>>> >>>>> regards >>>>> klaus >>>>> >>>>> David schrieb: >>>>>> Hey, >>>>>> >>>>>> I think I am doing something wrong, because here is the NOTIFY >>>>>> that comes to the phone : >>>>>> >>>>>> NOTIFY sip:group1.101@my.home.ip:57234 SIP/2.0 >>>>>> Via: SIP/2.0/UDP my.kamailio.ip;branch=z9hG4bK3cab.78e494a4.0 >>>>>> To: sip:group1.101@my.kamailio.domain.name;tag=b2514519391e8b4d >>>>>> From: >>>>>> sip:102@my.kamailio.domain.name;tag=6d6077e15fecee48b2721a5e94bf8883-f712 >>>>>> >>>>>> CSeq: 12 NOTIFY^M Call-ID: 24db3209-611c031d(a)192.168.1.104 >>>>>> Content-Length: 298 >>>>>> User-Agent: MyServer 1.0 >>>>>> Max-Forwards: 70 >>>>>> Event: dialog >>>>>> Contact: <sip:my.kamailio.domain.name:5060> >>>>>> Subscription-State: active;expires=1570 >>>>>> Content-Type: application/dialog-info+xml >>>>>> >>>>>> <?xml version="1.0"?> <dialog-info >>>>>> xmlns="urn:ietf:params:xml:ns:dialog-info" version="11" >>>>>> state="full" entity="group1.102(a)my.kamailio.domain.name"> >>>>>> <dialog id="7aaa32e84362a246716009175ad670be(a)domain.tld" >>>>>> direction="recipient"> <state>early</state> </dialog> >>>>>> </dialog-info> >>>>>> >>>>>> The phone ( I tested with a GXP2000, GXP2020 and SPA962 + SPA932) >>>>>> does not flash lights or anything. Since you suggested that a >>>>>> solid kamailio would work out of the box, I suspect that either I >>>>>> miscommunicated my setup or did something really wrong. The >>>>>> notify definitely gets to the phone and the phone replies 200/OK >>>>>> when it receives the NOTIFY. But I think that the telephone is >>>>>> not understanding the request because it subscribed to '102' but >>>>>> received a notification for 'group1.102'. The funny thing is, the >>>>>> From header matches the subscribe To header, it's just the XML >>>>>> has the full name instead of the shortened name. >>>>>> >>>>>> To: >>>>>> <sip:102@my.kamailio.domain.name>;tag=6d6077e15fecee48b2721a5e94bf8883-f712 >>>>>> >>>>>> >>>>>> I see this in my ( on kamailio ) /var/log/messages : >>>>>> >>>>>> Aug 13 09:55:24 kamailio-dev /usr/sbin/kamailio[25449]: >>>>>> INFO:presence:send_notify_request: NOTIFY >>>>>> sip:group1.101@my.kamailio.domain.name via >>>>>> sip:group1.101@my.home.ip.where.phone.is:57234 on behalf of >>>>>> sip:102@my.kamailio.domain.name for event dialog >>>>>> >>>>>> I should also mention that the NOTIFY sent out by presence >>>>>> bypasses my routing scripts. So I have the PUBLISH come through ( >>>>>> which I leave alone ) and the NOTIFY is sent according to the >>>>>> location table without ever consulting my routing script. >>>>>> >>>>>> So everything amazingly worked out well, except that the lights >>>>>> are not changing status which I think is related to the XML >>>>>> document dialog-info entity attribute containing the group name, >>>>>> sent from my server. >>>>>> >>>>>> Any ideas or suggestions ? >>>>>> >>>>>> Thanks, >>>>>> >>>>>> David >>>>>> >>>>>> Other information : >>>>>> >>>>>> if ( is_method("SUBSCRIBE") ) >>>>>> { >>>>>> avp_db_query("select groupname from sometable ", >>>>>> "$avp(s:groupname)"); >>>>>> avp_printf("$ru", >>>>>> "sip:$avp(s:zone).$tU@my.kamailio.domain.name"); >>>>>> xlog("L_INFO", "Subscribe rewritten from $tU to $ru >>>>>> - M=$rm \n"); >>>>>> xlog("L_INFO", "Handling SUBSCRIBE - $fU - >>>>>> $avp(s:zone) - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n"); >>>>>> handle_subscribe(); >>>>>> t_release(); >>>>>> exit; >>>>>> } >>>>>> >>>>>> Kamailio compiled from sources : >>>>>> >>>>>> Path: /usr/src/kamailio >>>>>> URL: >>>>>> https://openser.svn.sourceforge.net/svnroot/openser/branches/1.5 >>>>>> Repository Root: https://openser.svn.sourceforge.net/svnroot/openser >>>>>> Repository UUID: 689a6050-402a-0410-94f2-e92a70836424 >>>>>> Revision: 5910 >>>>>> Node Kind: directory >>>>>> Schedule: normal >>>>>> Last Changed Author: henningw >>>>>> Last Changed Rev: 5910 >>>>>> Last Changed Date: 2009-08-06 13:08:30 -0400 (Thu, 06 Aug 2009) >>>>>> >>>>>> >>>>>> Klaus Darilion wrote: >>>>>>> notifies are generated by the presence module, based on the >>>>>>> subscription. So, there is nothing you have to do with NOTIFY. >>>>>>> Also PUBLISHs are created internally. Depending on your concrete >>>>>>> setup (e.g. format of the SIP user names) it should work out of >>>>>>> the box. >>>>>>> >>>>>>> klaus >>>>>>> >>>>>>> dlublink schrieb: >>>>>>>> What about the notifies? >>>>>>>> >>>>>>>> Klaus Darilion wrote: >>>>>>>>> dlublink wrote: >>>>>>>>>> Hello, >>>>>>>>>> >>>>>>>>>> I have three different groups of extensions on my kamailio I >>>>>>>>>> want to be able to separate them, so I prefixed a name to the >>>>>>>>>> extensions, so I have : >>>>>>>>>> >>>>>>>>>> 1. group1.101 >>>>>>>>>> 2. group1.102 >>>>>>>>>> 3. group2.101 >>>>>>>>>> 4. group2.102 >>>>>>>>>> 5. group3.102 >>>>>>>>>> 6. group3.103. >>>>>>>>>> >>>>>>>>>> The phones from different groups can not call each other, I >>>>>>>>>> found a pseudo variable that I use to rewrite the destination >>>>>>>>>> url, so if user group1.101 dials 102 I rewrite it to group1.102. >>>>>>>>>> >>>>>>>>>> I want to do the same thing for presence_dialog info, how can >>>>>>>>>> I rewrite the subscribe, presence and and notify messages to >>>>>>>>>> append the appropriate prefix ? >>>>>>>>> >>>>>>>>> Just apply the same rewrite you have already done for the >>>>>>>>> INVITE also for the SUBSCRIBE >>>>>>>>> >>>>>>>>> regards >>>>>>>>> klaus >>>>>>>>> >>>>>>>>>> >>>>>>>>>> Thanks, >>>>>>>>>> >>>>>>>>>> David >>>>>>>>>> >>>>>>>>>> _______________________________________________ >>>>>>>>>> Kamailio (OpenSER) - Users mailing list >>>>>>>>>> Users(a)lists.kamailio.org >>>>>>>>>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>>>>>>>>> http://lists.openser-project.org/cgi-bin/mailman/listinfo/users >>>>>>>> >>>>>> >>>> >> [View Less]

1 0

[Kamailio-Users] Generate INVITE from Openser
by ALAEDDINE abbech 14 Aug '09

14 Aug '09

Hello all How can i generate an INVITE from OpenSER. That means that Openser make the role of UAC. Who have an idea for this pb. Thanks Regards Aladin

6 9

[Kamailio-Users] presence_dialoginfo context
by dlublink 14 Aug '09

14 Aug '09

Hello, I have three different groups of extensions on my kamailio I want to be able to separate them, so I prefixed a name to the extensions, so I have : 1. group1.101 2. group1.102 3. group2.101 4. group2.102 5. group3.102 6. group3.103. The phones from different groups can not call each other, I found a pseudo variable that I use to rewrite the destination url, so if user group1.101 dials 102 I rewrite it to group1.102. I want to do the same thing for presence_dialog info, how can I … [View More]

4 10

[Kamailio-Users] Load Balancing Asterisk using Kamailio
by Kurt Weasel 14 Aug '09

14 Aug '09

Hi, I searched around the web to load balance asterisk servers and found Kamailio for possible solution. Let's say I have two identical asterisk servers with same dialplan and configuration and I want both servers look like they have same IP address from clients. Based on my understanding, we need 1 Kamailio as load balancer and 2 Asterisk servers as the real servers. Let's say the setup is : Kamailio load balancer 192.168.2.1 Asterisk Server #1 192.168.2.2 Asterisk Server #2 192.168.2.3 My … [View More]

5 8

[Kamailio-Users] OpenSER without MYSQL
by Ratheendran R 13 Aug '09

13 Aug '09

Hello everyone, I want to port openSER on an embedded board,I need configure the openser without MySQL due to space constraint. So can you let me know whether this is possible also can you give any reference document on how to port on ARM 9 based boad. Regards, Rathndran <users(a)lists.kamailio.org>

7 9

[Kamailio-Users] Fwd: dialog info + Grandstreams = freezing
by Daniel-Constantin Mierla 13 Aug '09

13 Aug '09

.. fwd to list ... reply all button mismatch ... ---------- Forwarded message ---------- From: Daniel-Constantin Mierla <miconda(a)gmail.com> Date: Wed, Aug 12, 2009 at 9:20 AM Subject: Re: [Kamailio-Users] dialog info + Grandstreams = freezing To: David <kamailio.org(a)spam.lublink.net> Hello, On Tue, Aug 11, 2009 at 2:18 PM, David <kamailio.org(a)spam.lublink.net>wrote: > Hey, > > I am not good at diagrams, but here goes : > > > [ Asterisk] [ Asterisk ]… [View More] ================> [ MySQL ] > / \ / \ > [ Kamailio ] ============/\ > / \ / \ / \ > [ Extension ] [ Extension ] [ Extension ] > > Here is a simple flow : > > 1. Extension 1 is plugged in > 2. It registers to Kamailio and Kamailio stores to Location > 3. Extension 1 subscribes to all the other extensions > 4. Kamailio calls handle_publish() and t_release() > 5. Extension 1 dials '102' > 6. Kamailio receives the INVITE chooses an asterisk server and relays the > INVITE ( t_relay ) > 7. Asterisk does some checking, starts monitor ( if needed ) and some other > stuff > 8. Asterisk sends INVITE to Kamailio for testspace.102 > 9. Kamailio finds testspace.102 in database and forwards INVITE to the > appropriate extension > 10. Extension replies 'OK' > 11. Kamailio, using reply-route, sends it back to asterisk > 12. Asterisk bridges the call with 101 > 13. Asterisk sends an OK back through Kamailio to Extension 1. > 14. Asterisk tries to reinvite the audio ( if not monitoring ) > 15. Audio bypasses Asterisk, but the SIP still is making the full trip. > > Does this answer your question? Do you do call tracking with dialog for both legs (inbond: phone to asterisk; outbound: asterisk to phone)? You should do it for one, outbound is the best, in case asterisk auto-answers the inbound leg. Cheers, Daniel > > David > > > > Daniel-Constantin Mierla wrote: > >> Hello, >> >> I am using the module with snom 370 and works ok. The BLF is on for >> Polycoms but they do not implement the call pickup properly (they have >> direct call pickup as far as I could get). >> >> Please take latest kamailio 1.5 from svn branch 1.5 as there were >> committed some updates (maybe they don't affect you, being mainly to rls, >> but is better to have the latest stable so we refer to same source code). >> >> What would be good is to have a diagram of the signaling, since you say >> there are lot of messages sent around. >> http://callflow.sourceforge.net/ >> >> Cheers, >> Daniel >> >> >> On 11.08.2009 5:03 Uhr, David wrote: >> >>> Hello, >>> >>> I am having this problem on kamailio 1.5.2-tls compiled on Ubuntu 8.04, >>> 1.5.1-tls ( compiled with no tls ) on Ubuntu 8.04 and with OpenSIPS >>> 1.5.2-tls compilde on Ubuntu 8.04 >>> >>> I am trying to setup presence_dialoginfo with my Grandstreams, Snom and >>> Linksys. I have a 4 phones on the server. >>> >>> 101 - Linksys SPA962 ( 6.1.5a ) >>> 102 - Grandstream GXP2020 ( 1.2.1.4 ) >>> 103 - Grandstream GXP2000 ( 1.2.1.4 ) >>> 104 - Grandstream GXP2000 ( 1.1.6.46 ) >>> 105 - Snom 360 ( 7.3.23 ) >>> >>> My Kamailio deals with registrations, NAT and BLF everything else is sent >>> to one of two asterisk boxes. I use the dispatcher module for this. This >>> means that when I call one extension to the other, both call legs from >>> asterisk are going through Kamailio as separate calls. But to divide my >>> customers, the usernames are different from the URL that the user types. For >>> example the customer dials '101' but it is changed to testspace.101 when it >>> comes back from asterisk. So Kamailio would have two calls in the event that >>> 101 dials 102. >>> >>> sip:testspace.101@myserver to 102 ( this is sent to asterisk ) >>> sip:testspace.101@myserver to testspace.102 ( this is coming back from >>> asterisk ) >>> >>> Something is horribly wrong. I have the following problems : >>> >>> 1. If 102 calls 103, when 103 answers both phones hang for about 2 >>> minutes >>> 2. If 105 calls 101, 101 BLF comes back to the inactive state ( green on >>> the Linksys and dark on the Snom), but the orange light stays on on the Snom >>> and it thinks the call is still active ( the light is on, but the call is >>> over ) >>> 3. If any extension calls any extension and I try a call pickup, it >>> fails. It looks like the Linksys is sending a NOTIFY to pickup the call ( I >>> thought it was supposed to send an invite... ? ) >>> >>> Looking at the logs it looks like Kamailio is sending out so many NOTIFYs >>> that it is crashing the Grandstreams, and causing the Snom to act funny. >>> >>> Here are some experts from my config file : >>> >>> root@kamailio-dev:/etc/kamailio# grep dialog * >>> kamailio.cfg:# * avp value for dialogs is still not correct >>> kamailio.cfg:loadmodule "dialog.so" >>> kamailio.cfg:loadmodule "presence_dialoginfo.so" >>> kamailio.cfg:loadmodule "pua_dialoginfo.so" >>> kamailio.cfg:#modparam("pua_dialoginfo", "include_localremote", 0) >>> kamailio.cfg:#modparam("pua_dialoginfo", "include_tags", 0) >>> kamailio.cfg:#modparam("pua_dialoginfo", "include_callid", 0) >>> kamailio.cfg:modparam("dialog", "dlg_flag", 4) >>> kamailio.cfg:modparam("dialog", "db_mode", 1) >>> kamailio.cfg:modparam("dialog", "timeout_avp", "$avp(i:10)") # I still >>> haven't figured out how to set $avp(i:10) >>> kamailio.cfg:modparam("pua_dialoginfo", "override_lifetime", 300) >>> kamailio.cfg:modparam("presence_dialoginfo", "force_single_dialog", 1) >>> kamailio.cfg:modparam("pua_dialoginfo", "caller_confirmed", 1) >>> kamailio.cfg:modparam("auth_db|usrloc|acc|domain|avpops|presence|presence_xml|pua|dialog", >>> "db_url", >>> kamailio.cfg:# Flag 4 = Mark the current request for a dialog >>> kamailio.cfg: # sequential request withing a dialog should >>> >>> the set flag looks like this : >>> if ( ds_is_from_list() ) >>> { >>> xlog("L_INFO", "Coming from asterisk"); >>> if ( is_method("INVITE")) >>> { >>> setflag(4); >>> } >>> } >>> >>> So the dialog flag is only set for the leg coming back from asterisk. >>> >>> When a notify comes in : >>> >>> if(is_method("NOTIFY") ) >>> { >>> if (! t_newtran()) >>> { >>> sl_reply_error(); >>> exit; >>> }; >>> >>> t_reply("200", "OK"); >>> t_release(); >>> exit ; >>> } >>> >>> Publish and subscribe are like this : >>> >>> >>> if( is_method("PUBLISH") || is_method("SUBSCRIBE") ) >>> { >>> route(5); >>> exit; >>> } >>> >>> route[5] >>> { >>> # absorb retransmissions >>> if (! t_newtran()) >>> { >>> xlog("L_INFO", "Ignoring PUBLISH/SUBSCRIBE on retransmition - >>> M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n"); >>> sl_reply_error(); >>> exit; >>> }; >>> >>> append_to_reply("Contact: <sip:myserver.tld:5060>\r\n"); >>> >>> if(is_method("PUBLISH")) >>> { >>> handle_publish(); >>> t_release(); >>> >>> } else if( is_method("SUBSCRIBE")) { >>> handle_subscribe(); >>> t_release(); >>> } >>> else >>> { >>> } >>> >>> exit; >>> } >>> >>> I also have NAT checking for those telephones where stun isn't enough. >>> Before I reach publish/subscribe/invite/notify, I also call setbflag() and >>> sometimes call fix_nated_contact(). Additionnally, I have a block if code >>> before my presence stuff if ( has_totag() && loose_route()) { t_relay(); }. >>> >>> If sip.conf:canreinvite=yes, the grandstreams freeze so long that the >>> server times out, and the BLFs get really messed up. if sip:canreinvite=no >>> the grandstreams only freeze for about 30 seconds. >>> >>> Obviously I am doing something wrong, but despite having searched google >>> for endless hours, and poured over documentation, I can not seem to find >>> what I did wrong. >>> >>> I would really appreciate if someone could shed light on my problem. >>> >>> I am having this problem on kamailio 1.5.2-tls compiled on Ubuntu 8.04, >>> 1.5.1-tls ( compiled with no tls ) on Ubuntu 8.04 and with OpenSIPS >>> 1.5.2-tls compilde on Ubuntu 8.04 >>> >>> Thanks, >>> >>> David >>> >>> _______________________________________________ >>> Kamailio (OpenSER) - Users mailing list >>> Users(a)lists.kamailio.org >>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users >>> http://lists.openser-project.org/cgi-bin/mailman/listinfo/users >>> >>> >> > > _______________________________________________ > Kamailio (OpenSER) - Users mailing list > Users(a)lists.kamailio.org > http://lists.kamailio.org/cgi-bin/mailman/listinfo/users > http://lists.openser-project.org/cgi-bin/mailman/listinfo/users > -- Daniel-Constantin Mierla http://www.asipto.com -- Daniel-Constantin Mierla http://www.asipto.com [View Less]

2 2

[Kamailio-Users] acc doesn't write to database and to a log file
by Koffedor 13 Aug '09

13 Aug '09

Hello to all I enabled the acc module but it isn't writing to "acc" or "missed_calls" table in mysql, and to a log file too. my config: (...) loadmodule "db_mysql.so" loadmodule "tm.so" loadmodule "rr.so" (...) # ----- acc params ----- /* what sepcial events should be accounted ? */ modparam("acc", "early_media", 1) modparam("acc", "report_ack", 1) modparam("acc", "report_cancels", 1) /* by default ww do not adjust the direct of the sequential requests. if you enable this parameter, be … [View More]sure the enable "append_fromtag" in "rr" module */ modparam("acc", "detect_direction", 0) /* account triggers (flags) */ modparam("acc", "failed_transaction_flag", 3) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 2) modparam("acc", "log_extra","src_user=$fU;src_domain=$fd;dst_ouser=$tU;dst_user=$rU;dst_domain=$rd") /* uncomment the following lines to enable DB accounting also */ modparam("acc", "db_flag", 1) modparam("acc", "db_missed_flag", 2) modparam("acc", "db_url", "mysql://xxx:xxxx@localhost/kamailio") modparam("acc", "db_extra", "src_user=$fU;src_domain=$fd;dst_ouser=$tU;dst_user=$rU;dst_domain=$rd") Flags 1 and 2 set just like in a sample configuration file. (...) if (loose_route()) { if (is_method("BYE")) { setflag(1); # do accounting ... setflag(3); # ... even if the transaction fails } route(1); (...) # account only INVITEs if (is_method("INVITE")) { setflag(1); # do accounting } Mysql tables are created: | acc | CREATE TABLE `acc` ( `id` int(10) unsigned NOT NULL auto_increment, `method` varchar(16) NOT NULL default '', `from_tag` varchar(64) NOT NULL default '', `to_tag` varchar(64) NOT NULL default '', `callid` varchar(128) NOT NULL default '', `sip_code` char(3) NOT NULL default '', `sip_reason` varchar(32) NOT NULL default '', `time` datetime NOT NULL default '0000-00-00 00:00:00', `src_ip` varchar(64) NOT NULL default '', `dst_user` varchar(64) NOT NULL default '', `dst_domain` varchar(128) NOT NULL default '', `src_user` varchar(64) NOT NULL default '', `src_domain` varchar(128) NOT NULL default '', `cdr_id` int(11) NOT NULL default '0', `dst_ouser` varchar(64) NOT NULL default '', PRIMARY KEY (`id`), KEY `acc_callid` (`callid`) ) ENGINE=MyISAM DEFAULT CHARSET=latin1 | | missed_calls | CREATE TABLE `missed_calls` ( `id` int(10) unsigned NOT NULL auto_increment, `method` varchar(16) NOT NULL default '', `from_tag` varchar(64) NOT NULL default '', `to_tag` varchar(64) NOT NULL default '', `callid` varchar(128) NOT NULL default '', `sip_code` char(3) NOT NULL default '', `sip_reason` varchar(32) NOT NULL default '', `time` datetime NOT NULL default '0000-00-00 00:00:00', `src_ip` varchar(64) NOT NULL default '', `dst_user` varchar(64) NOT NULL default '', `dst_domain` varchar(128) NOT NULL default '', `src_user` varchar(64) NOT NULL default '', `src_domain` varchar(128) NOT NULL default '', `cdr_id` int(11) NOT NULL default '0', `dst_ouser` varchar(64) NOT NULL default '', PRIMARY KEY (`id`), KEY `mc_callid` (`callid`) ) ENGINE=MyISAM DEFAULT CHARSET=latin1 There are no errors in log, and nothing about acc module in debug mode. Cant get where is my mistake. [View Less]

2 3

BUG: tls [tls_server.c:98]: Invalid connection state (bug in TCP code)
by MÉSZÁROS Mihály 12 Aug '09

12 Aug '09

Hello! Another problem I am using sip-router git version with the attached configuration files. I am getting the error mentioned in subject. Please see the debug log and my configuration files. Can anyone help me figure out what i a configured wrong? Misi Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 517 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:38 a1 /usr/sbin/… [View More]ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <PUBLISH> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:alice@atlanta.test> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-260c1648321add52-1---d8754z->; state=6 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg... Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts... Aug 11 20:38:38 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: PUBLISH sip:alice@atlanta.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-260c1648321add52-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: "alice"<sip:alice@atlanta.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 16 PUBLISH#015#012Expires: 1200#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/pidf+xml#015#012Proxy-Authorization: Digest username="alice",realm="atlanta.test",nonce="4a81babd0000000bdc0c130f92356ce11fc7ea51a926c644",uri="sip:alice@atlanta.test",response="527ee7c53e6f621ef9ee161426da4afd",cnonce="9f418c76f9b91cd9c3d71fbb4d36f415",nc=00000002,qop=auth,algorithm=MD5#015#012SIP-If-Match: a.1250015022.397.2.8#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Event: presence#015#012Content-Length: 517#015#012#015#012<?xml version='1.0' encoding='UTF-8'?><presence xmlns='urn:ietf:params:xml:ns:pidf' xmlns:dm='urn:ietf:params:xml:ns:pidf:data-model' xmlns:rpid='urn:ietf:params:xml:ns:pidf:rpid' xmlns:c='urn:ietf:params:xml:ns:pidf:cipid' xmlns:lt='urn:ietf:params:xml:ns:location-type' entity='sip:alice@atlanta.test'><tuple id='tae2c271a'><status><basic>open</basic></status></tuple><dm:person id='p7a66b539'><rpid:activities><rpid:busy/><rpid:on-the-phone/></rpid:activities><dm:note>On the phone</dm:note></dm:person></presence> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [33]; uri=[sip:alice@atlanta.test] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body ["alice"<sip:alice@atlanta.test>#015#012] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=3 global id=2 T start=0xffffffff Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <16> <PUBLISH> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: beginning of SIP-If-Match: yet=0x2d706973 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: middle of SIP-If-Match: yet=0x6d2d6669 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: end of SIP-If-Match Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=517 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=3518, isACK=0 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=3 global id=3 T end=(nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=6470be16 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [nonce.c:186]: comparing [4a81babd0000000bdc0c130f92356ce11fc7ea51a926c644] and [4a81babd0000000bdc0c130f92356ce11fc7ea51a926c644] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82bd628 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 12 bytes for result names at 0x82f55d8 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 12 bytes for result types at 0x82f52fc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82f4e4c Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4e4c)[0]=[password] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82dbf88 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82dbf88)[1]=[email_address] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[2] at 0x82f5768 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f5768)[2]=[rpid] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f4ebc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 60 bytes for row values at 0x82f5390 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [bakker] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:003631001001@atlanta.test] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:123]: HA1 string calculated: 67bb4b4b59a70b7f246682dfdd188df2 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:239]: our result = '527ee7c53e6f621ef9ee161426da4afd' Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:246]: authorization is OK Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:194]: nonce index= 11 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [index.c:187]: nonce already used Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:198]: nonce index not valid Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 3 columns Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82f4e4c Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82dbf88 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82f5768 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f55d8 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f52fc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5390 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f4ebc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82bd628 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [index.c:128]: second= 16, sec_monit= 8, index= 12 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:107]: nonce index= 12 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:151]: 'Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2", qop="auth"#015#012' Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 742 bytes written Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=742 fd=8 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 407 Proxy Authentication Required#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-260c1648321add52-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: "alice"<sip:alice@atlanta.test>;tag=f8f2ab2c1295e90ed7dbb499b30f44b2.a62c#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 16 PUBLISH#015#012Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2", qop="auth"#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells: pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:alice@atlanta.test out_uri=sip:alice@atlanta.test via_cnt==1"#015#012#015#012 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 517 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <PUBLISH> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:alice@atlanta.test> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-8b6841568301eb55-1---d8754z->; state=6 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg... Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts... Aug 11 20:38:38 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: PUBLISH sip:alice@atlanta.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-8b6841568301eb55-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: "alice"<sip:alice@atlanta.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 17 PUBLISH#015#012Expires: 1200#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/pidf+xml#015#012Proxy-Authorization: Digest username="alice",realm="atlanta.test",nonce="4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2",uri="sip:alice@atlanta.test",response="cc8d63baac587662386d887e507bf60b",cnonce="1eeeeb8bf845982d90f185276c67bc78",nc=00000001,qop=auth,algorithm=MD5#015#012SIP-If-Match: a.1250015022.397.2.8#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Event: presence#015#012Content-Length: 517#015#012#015#012<?xml version='1.0' encoding='UTF-8'?><presence xmlns='urn:ietf:params:xml:ns:pidf' xmlns:dm='urn:ietf:params:xml:ns:pidf:data-model' xmlns:rpid='urn:ietf:params:xml:ns:pidf:rpid' xmlns:c='urn:ietf:params:xml:ns:pidf:cipid' xmlns:lt='urn:ietf:params:xml:ns:location-type' entity='sip:alice@atlanta.test'><tuple id='tae2c271a'><status><basic>open</basic></status></tuple><dm:person id='p7a66b539'><rpid:activities><rpid:busy/><rpid:on-the-phone/></rpid:activities><dm:note>On the phone</dm:note></dm:person></presence> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [33]; uri=[sip:alice@atlanta.test] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body ["alice"<sip:alice@atlanta.test>#015#012] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=4 global id=3 T start=(nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <17> <PUBLISH> Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: beginning of SIP-If-Match: yet=0x2d706973 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: middle of SIP-If-Match: yet=0x6d2d6669 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: end of SIP-If-Match Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=517 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=3519, isACK=0 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=4 global id=4 T end=(nil) Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=6470be16 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [nonce.c:186]: comparing [4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2] and [4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82bd628 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 12 bytes for result names at 0x82f55d8 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 12 bytes for result types at 0x82f52fc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82f4ebc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4ebc)[0]=[password] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82f5768 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f5768)[1]=[email_address] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[2] at 0x82dbf88 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82dbf88)[2]=[rpid] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f4e4c Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 60 bytes for row values at 0x82f5390 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [bakker] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:003631001001@atlanta.test] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:123]: HA1 string calculated: 67bb4b4b59a70b7f246682dfdd188df2 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:239]: our result = 'cc8d63baac587662386d887e507bf60b' Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:246]: authorization is OK Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:194]: nonce index= 12 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:176]: set string AVP ""/13 = "sip:003631001001@atlanta.test" Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 3 columns Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82f4ebc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82f5768 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82dbf88 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f55d8 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f52fc Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5390 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f4e4c Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82bd628 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: uri_db [checks.c:137]: Digest username and URI username match Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:108]: No Route headers found Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:907]: There is no Route HF Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1383]: DEBUG: t_newtran: msg id=4 , global msg id=4 , T on entrance=(nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=3519, isACK=0 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_hooks.c:335]: DBG: trans=0xb585090c, callback type 1, id 0 entered Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [event_list.c:349]: start event= [presence/1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [publish.c:369]: SIP-If-Match header found Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [publish.c:378]: existing etag = a.1250015022.397.2.8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [publish.c:390]: Expires header found, value= 1200 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82f56e4 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 2 columns returned from the query Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 8 bytes for result names at 0x82f5768 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 8 bytes for result types at 0x82f4ebc Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82f4e84 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4e84)[0]=[body] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:121]: use DB1_BLOB result type Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82f5730 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f5730)[1]=[sender] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f4e10 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 40 bytes for row values at 0x82f5960 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:168]: converting BLOB [<?xml version='1.0' encoding='UTF-8'?><presence xmlns='urn:ietf:params:xml:ns:pidf' xmlns:dm='urn:ietf:params:xml:ns:pidf:data-model' xmlns:rpid='urn:ietf:params:xml:ns:pidf:rpid' xmlns:c='urn:ietf:params:xml:ns:pidf:cipid' xmlns:lt='urn:ietf:params:xml:ns:location-type' entity='sip:alice@atlanta.test'><tuple id='tae2c271a'><status><basic>open</basic></status></tuple><dm:person id='p7a66b539'><dm:note>Available</dm:note></dm:person></presence>] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 2 columns Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82f4e84 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82f5730 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f5768 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f4ebc Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5960 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f4e10 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82f56e4 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [presentity.c:88]: etag= a.1250015022.390.2.9 / 20#012 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [presentity.c:102]: send 200OK reply Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [presentity.c:103]: etag= a.1250015022.390.2.9 - len= 20 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=4 global id=4 T start=0xb585090c Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1152]: DEBUG: t_check_msg: T already found! Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [mem/shm_mem.c:117]: WARNING:vqm_resize: resize(0) called Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:1355]: DEBUG: cleanup_uac_timers: RETR/FR timers reset Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 643 bytes written Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=643 fd=8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-8b6841568301eb55-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: "alice"<sip:alice@atlanta.test>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-2965#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 17 PUBLISH#015#012Expires: 1200#015#012SIP-ETag: a.1250015022.390.2.9#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells: pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:alice@atlanta.test out_uri=sip:alice@atlanta.test via_cnt==1"#015#012#015#012 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:610]: DEBUG: reply sent out. buf=0x82f5c80: SIP/2.0 2..., shmem=0xb584f674: SIP/2.0 2 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:620]: DEBUG: _reply_light: finished Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: sl [sl.c:309]: reply in stateful mode (tm) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [notify.c:1302]: found 0 dialogs( 0 in database and 0 in hash_table) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [notify.c:1321]: Could not find subs_dialog Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 544 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <INVITE> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:bob@biloxi.test> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z->; state=6 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: INVITE sip:bob@biloxi.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 1 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [23]; uri=[sip:bob@biloxi.test] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>#015#012] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffff Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=544 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=5d194242 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=47015, isACK=0 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=5 global id=5 T end=(nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:126]: credentials with given realm not found Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [index.c:128]: second= 18, sec_monit= 8, index= 13 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:107]: nonce index= 13 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:151]: 'Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0", qop="auth"#015#012' Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 724 bytes written Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=724 fd=8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 407 Proxy Authentication Required#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>;tag=f8f2ab2c1295e90ed7dbb499b30f44b2.d643#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 1 INVITE#015#012Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0", qop="auth"#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells: pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 0 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <ACK> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:bob@biloxi.test> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z->; state=6 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=f8f2ab2c1295e90ed7dbb499b30f44b2.d643 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [65]; uri=[sip:bob@biloxi.test] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: sl [sl_funcs.c:327]: local ACK found -> dropping it! Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 544 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <INVITE> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:bob@biloxi.test> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-2a767f38e361686d-1---d8754z->; state=6 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts... Aug 11 20:38:39 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: INVITE sip:bob@biloxi.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Proxy-Authorization: Digest username="alice",realm="atlanta.test",nonce="4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0",uri="sip:bob@biloxi.test",response="60ca1ab3ccd52ae04fded05e2056a49a",cnonce="41e9f5aabf671596242bb02343062a1b",nc=00000001,qop=auth,algorithm=MD5#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [23]; uri=[sip:bob@biloxi.test] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>#015#012] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=7 global id=5 T start=(nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <2> <INVITE> Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=544 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=5d194242 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=47012, isACK=0 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=7 global id=7 T end=(nil) Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 && [atlanta.test] == [127.0.0.1] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 && [atlanta.test] == [195.111.158.41] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [nonce.c:186]: comparing [4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0] and [4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82bd628 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 12 bytes for result names at 0x82f55d8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 12 bytes for result types at 0x82f52b8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82dbf88 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82dbf88)[0]=[password] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82f4e4c Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4e4c)[1]=[email_address] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[2] at 0x82f4ebc Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4ebc)[2]=[rpid] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f5768 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 60 bytes for row values at 0x82f5960 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [bakker] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:003631001001@atlanta.test] Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:123]: HA1 string calculated: 67bb4b4b59a70b7f246682dfdd188df2 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:239]: our result = '60ca1ab3ccd52ae04fded05e2056a49a' Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:246]: authorization is OK Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:194]: nonce index= 13 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:176]: set string AVP ""/13 = "sip:003631001001@atlanta.test" Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 3 columns Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82dbf88 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82f4e4c Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82f4ebc Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f55d8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f52b8 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5960 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f5768 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82bd628 Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: uri_db [checks.c:137]: Digest username and URI username match Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:108]: No Route headers found Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:907]: There is no Route HF Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 && [biloxi.test] == [127.0.0.1] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 && [biloxi.test] == [195.111.158.41] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 && [biloxi.test] == [127.0.0.1] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 && [biloxi.test] == [195.111.158.41] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 && [biloxi.test] == [127.0.0.1] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 && [biloxi.test] == [195.111.158.41] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 && [biloxi.test] == [127.0.0.1] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 && [biloxi.test] == [195.111.158.41] Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [forward.c:318]: check_self: host != me Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1383]: DEBUG: t_newtran: msg id=7 , global msg id=7 , T on entrance=(nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=47012, isACK=0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_hooks.c:335]: DBG: trans=0xb584cf18, callback type 1, id 0 entered Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_funcs.c:348]: SER: new INVITE Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [mem/shm_mem.c:117]: WARNING:vqm_resize: resize(0) called Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 572 bytes written Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=572 fd=8 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 100 trying -- your call is important to us#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells: pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:610]: DEBUG: reply sent out. buf=0x82f5c80: SIP/2.0 1..., shmem=0xb58505ec: SIP/2.0 1 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:620]: DEBUG: _reply_light: finished Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(biloxi.test(11), 35), h=599 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2674]: naptr_iterate: found a valid sip NAPTR rr _sip._tcp.biloxi.test, proto 2 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1091]: naptr_choose(o: -1 w: -1 p:0 , o: 20 w:50 p:2) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1107]: naptr_choose: changed Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2674]: naptr_iterate: found a valid sip NAPTR rr _sip._udp.biloxi.test, proto 1 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1091]: naptr_choose(o: 20 w: 50 p:2 , o: 30 w:50 p:1) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1102]: naptr_choose: no change Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2674]: naptr_iterate: found a valid sip NAPTR rr _sips._tcp.biloxi.test, proto 3 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1091]: naptr_choose(o: 20 w: 50 p:2 , o: 10 w:50 p:3) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1107]: naptr_choose: changed Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2688]: naptr_iterate: choosed NAPTR rr _sips._tcp.biloxi.test, proto 3 tried: 0x0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(_sips._tcp.biloxi.test(22), 33), h=208 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2246]: dns_srv_get_nxt_rr(0xb5864a2c, 0, 0, 559080590): selected 0/1 in grp. 0 (rand_w=0, rr=0xb5864a70 p=10 w=0 rsum=0) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(b1.biloxi.test(14), 1), h=386 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b1.biloxi.test, 0) returning 0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3115]: dns_srv_resolve_ip("_sips._tcp.biloxi.test", 0, 0), ret=0, ip=195.111.158.43 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3350]: dns_naptr_sip_resolve(biloxi.test, 0, 0), srv0, ret=0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: <script>: new branch at sip:bob@biloxi.test Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:2379]: create_via_hf: id added: <;i=2>, rcv proto=3 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1778]: tcp_send: no open tcp connection found, opening new one Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [ip_addr.c:116]: tcpconn_new: new tcp connection: 195.111.158.43 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1050]: tcpconn_new: on port 5061, type 3 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, 2, fd 68 from 36 (390) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: BUG: tls [tls_server.c:98]: Invalid connection state (bug in TCP code) Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:1349]: tcpconn_add: hashes: 1306:736:1196, 9 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tls [tls_server.c:145]: Delayed init failed Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:361]: DBG: io_watch_add(0x8228560, 68, 2, 0xb5865b20), fd_no=55 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb5865b20 n=-1 fd=13 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012INVITE sip:bob@biloxi.test SIP/2.0#015#012Record-Route: <sip:195.111.158.41:5061;transport=tls;lr=on;ftag=5d194242>#015#012Via: SIP/2.0/TLS 195.111.158.41:5061;branch=z9hG4bK4a7b.1036c875.0;i=2#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;received=92.249.143.13;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783#015#012Max-Forwards: 69#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012P-hint: outbound#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: <core> [tcp_main.c:2166]: ERROR: tcp_send: failed to send on 0xb5865b20 (195.111.158.41:59267->195.111.158.43:5061): Operation now in progress (115) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tm [../../forward.h:163]: msg_send: ERROR: tcp_send failed Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, -2, fd -1 from 36 (390) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_fwd.c:961]: t_send_branch: send to 195.111.158.43:5061 (3) failed Aug 11 20:38:40 a1 /usr/sbin/ser[398]: ERROR: <core> [tcp_main.c:3027]: handle_ser_child: ERROR: received CON_ERROR for 0xb5865b20 (id 9), refcnt 2 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b1.biloxi.test, 1) returning -1 Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:588]: DBG: io_watch_del (0x8228560, 68, -1, 0x10) fd_no=56 called Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2246]: dns_srv_get_nxt_rr(0xb5864a2c, 0, 0, 559080593): selected 0/1 in grp. 1 (rand_w=0, rr=0xb5864a98 p=20 w=0 rsum=0) Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: tls [tls_server.c:689]: Closing SSL connection Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(b2.biloxi.test(14), 1), h=281 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b2.biloxi.test, 0) returning 0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3115]: dns_srv_resolve_ip("_sips._tcp.biloxi.test", 1, 0), ret=0, ip=195.111.158.44 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3256]: dns_sip_resolve(biloxi.test, 1, 0), srv, ret=0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:2379]: create_via_hf: id added: <;i=2>, rcv proto=3 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_fwd.c:974]: t_send_branch: send on branch 0 failed, adding another branch with another ip Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1778]: tcp_send: no open tcp connection found, opening new one Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [ip_addr.c:116]: tcpconn_new: new tcp connection: 195.111.158.44 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1050]: tcpconn_new: on port 5061, type 3 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:40 a1 /usr/sbin/ser[390]: BUG: tls [tls_server.c:98]: Invalid connection state (bug in TCP code) Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, 2, fd 68 from 36 (390) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tls [tls_server.c:145]: Delayed init failed Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:1349]: tcpconn_add: hashes: 1693:359:2697, 10 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb5865b20 n=-1 fd=13 Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:361]: DBG: io_watch_add(0x8228560, 68, 2, 0xb5865b20), fd_no=55 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012INVITE sip:bob@biloxi.test SIP/2.0#015#012Record-Route: <sip:195.111.158.41:5061;transport=tls;lr=on;ftag=5d194242>#015#012Via: SIP/2.0/TLS 195.111.158.41:5061;branch=z9hG4bK4a7b.1036c875.1;i=2#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;received=92.249.143.13;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783#015#012Max-Forwards: 69#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012P-hint: outbound#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: <core> [tcp_main.c:2166]: ERROR: tcp_send: failed to send on 0xb5865b20 (195.111.158.41:55898->195.111.158.44:5061): Operation now in progress (115) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tm [../../forward.h:163]: msg_send: ERROR: tcp_send failed Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, -2, fd -1 from 36 (390) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_fwd.c:961]: t_send_branch: send to 195.111.158.44:5061 (3) failed Aug 11 20:38:40 a1 /usr/sbin/ser[398]: ERROR: <core> [tcp_main.c:3027]: handle_ser_child: ERROR: received CON_ERROR for 0xb5865b20 (id 10), refcnt 2 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b2.biloxi.test, 1) returning -1 Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:588]: DBG: io_watch_del (0x8228560, 68, -1, 0x10) fd_no=56 called Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3115]: dns_srv_resolve_ip("_sips._tcp.biloxi.test", 2, 1), ret=-1, ip= Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: tls [tls_server.c:689]: Closing SSL connection Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3256]: dns_sip_resolve(biloxi.test, 2, 1), srv, ret=-1 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tm [t_fwd.c:980]: ERROR: t_send_branch: sending request on branch 1 failed Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_funcs.c:358]: ERROR:tm:t_relay_to: t_forward_nonack returned error Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_funcs.c:366]: -477 error reply generation delayed Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: sl [sl_funcs.c:283]: error text is Unfortunately error on sending to next hop occurred (477/SL) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 636 bytes written Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=636 fd=8 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 477 Unfortunately error on sending to next hop occurred (477/SL)#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>;tag=f8f2ab2c1295e90ed7dbb499b30f44b2.573f#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells: pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1536]: t_unref: delayed error reply generation(-477) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:1355]: DEBUG: cleanup_uac_timers: RETR/FR timers reset Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending... Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 636 bytes written Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=636 fd=8 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 477 Unfortunately error on sending to next hop occurred (477/TM)#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-573f#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells: pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_hooks.c:252]: DBG: trans=0xb584cf18, callback type 128, id 0 entered Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:610]: DEBUG: reply sent out. buf=0x82f6088: SIP/2.0 4..., shmem=0xb58505ec: SIP/2.0 4 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:620]: DEBUG: _reply_light: finished Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 0 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <ACK> Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:bob@biloxi.test> Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-2a767f38e361686d-1---d8754z->; state=6 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg... Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts... Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=f8f2ab2c1295e90ed7dbb499b30f44b2.573f Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29 Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [65]; uri=[sip:bob@biloxi.test] Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>] Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: sl [sl_funcs.c:327]: local ACK found -> dropping it! Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil) Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 447 Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request: Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]: method: <PUBLISH> Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]: uri: <sip:alice@atlanta.test> Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]: version: <SIP/2.0> Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-0d1d4d59c544e42e-1---d8754z->; state=6 Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17 Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5 Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2 Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via # # $Id$ # # This a very basic config file w aliases and anamed route but # w/o authentication, accounting, database, multi-domain support etc. # Please refer to sip-router.cfg for a more complete example # # ----------- global configuration parameters ------------------------ debug=5 # debug level (cmd line: -dddddddddd) memdbg=6 # memory debug message level memlog=6 # memory statistics log level #log_facility=LOG_LOCAL0 # sets the facility used for logging (see syslog(3)) /* Uncomment these lines to enter debugging mode fork=no log_stderror=yes */ check_via=no # (cmd. line: -v) dns=no # (cmd. line: -r) rev_dns=no # (cmd. line: -R) #port=5060 #children=4 user=ser group=ser #disable_core=yes #disables core dumping #open_fd_limit=1024 # sets the open file descriptors limit #mhomed=yes # usefull for multihomed hosts, small performance penalty #TLS enable_tls=yes #TCP settings disable_tcp=no tcp_async=no tcp_send_timeout=2 #tcp_accept_aliases=yes # accepts the tcp alias via option (see NEWS) tcp_delayed_ack=no tcp_fd_cache=no # Alias alias=atlanta.test:5061 alias=atlanta.test:5060 #Tells how long to keep negative DNS responses in cache. If set to 0, disables caching of negative responses. #Default is 60 (seconds). dns_cache_negative_ttl=5 #Number of dns retransmissions before giving up. dns_retr_no=3 #Time in seconds before retrying a dns request. dns_retr_time=3 #dns_srv_loadbalancing Enable dns srv weight based load balancing dns_srv_lb = yes #If it is set to 'yes' and a DNS lookup fails, it will retry it for ipv6 (AAAA record) dns_try_ipv6=yes #Enable NAPTR support according to RFC 3263 dns_try_naptr = yes #Set preference for each protocol when doing naptr lookups. #By default dns_udp_pref=30, dns_tcp_pref=20, dns_tls_pref=10 and dns_sctp_pref=20. #To completely ignore NAPTR records for a specific protocol, set the corresponding protocol preference to -1 (or any other negative number). dns_udp_pref = 1 dns_tcp_pref = 1 dns_tls_pref = 1 dns_sctp_pref = 1 #If set to 'no', the search list in '/etc/resolv.conf' will be ignored. #(-> fewer lookups -> gives up faster). Default value is 'yes'. dns_use_search_list=no #default off use_dns_failover=yes # ------------------ module loading ---------------------------------- #loadpath "modules:modules_s" #loadpath "/usr/lib/ser/modules:/usr/lib/ser/modules_s" # common modules loadpath "/usr/lib/ser/modules" loadmodule "tm" loadmodule "utils" loadmodule "db_mysql" loadmodule "avpops.so" loadmodule "tls" # Kamailio modules loadpath "/usr/lib/ser/modules_k" loadmodule "sl" loadmodule "rr" loadmodule "usrloc" loadmodule "registrar" loadmodule "maxfwd" loadmodule "textops" loadmodule "uri_db.so" loadmodule "acc.so" loadmodule "auth.so" loadmodule "auth_db.so" loadmodule "alias_db.so" loadmodule "pv.so" loadmodule "siputils.so" loadmodule "presence.so" loadmodule "presence_xml.so" loadmodule "presence_mwi.so" loadmodule "presence_dialoginfo.so" loadmodule "xlog.so" # ser modules loadpath "/usr/lib/ser/modules_s" loadmodule "ctl" loadmodule "cfg_rpc" loadmodule "auth_identity" #loadmodule "sl" #loadmodule "sanity" #loadmodule "registrar" # ----------------- setting module-specific parameters --------------- # -- tls params -- modparam("tls","config","/etc/ser/tls.cfg") # -- usrloc params -- modparam("usrloc", "db_mode", 0) # -- rr params -- # add value to ;lr param to make some broken UAs happy modparam("rr", "enable_full_lr", 1) # ctl params # by default ctl listens on unixs:/tmp/sip-router_ctl if no other address is # specified in modparams; this is also the default for sercmd modparam("ctl", "binrpc", "unixs:/tmp/sip-router_ctl") # listen on the "standard" fifo for backward compatibility modparam("ctl", "fifo", "fifo:/tmp/sip-router_fifo") # listen on tcp, localhost #modparam("ctl", "binrpc", "tcp:localhost:2046") # ----- registrar params ----- #modparam("registrar", "method_filtering", 1) /* uncomment the next line to disable parallel forking via location */ # modparam("registrar", "append_branches", 0) /* uncomment the next line not to allow more than 10 contacts per AOR */ #modparam("registrar", "max_contacts", 10) # ----- usrloc params ----- #modparam("usrloc", "db_mode", 0) /* uncomment the following lines if you want to enable DB persistency for location entries */ modparam("usrloc", "db_mode", 1) modparam("usrloc", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # ----- uri_db params ----- /* by default we disable the DB support in the module as we do not need it in this configuration */ modparam("uri_db", "use_uri_table", 0) modparam("uri_db", "db_url", "") # ----- acc params ----- /* what sepcial events should be accounted ? */ modparam("acc", "early_media", 1) modparam("acc", "report_ack", 1) modparam("acc", "report_cancels", 1) /* by default ww do not adjust the direct of the sequential requests. if you enable this parameter, be sure the enable "append_fromtag" in "rr" module */ modparam("acc", "detect_direction", 0) /* account triggers (flags) */ modparam("acc", "failed_transaction_flag", 3) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 2) /* uncomment the following lines to enable DB accounting also */ modparam("acc", "db_flag", 1) modparam("acc", "db_missed_flag", 2) # ----- auth params ----- modparam("auth", "rpid_avp", "$avp(i:13)") # ----- auth_db params ----- /* uncomment the following lines if you want to enable the DB based authentication */ modparam("auth_db", "calculate_ha1", yes) modparam("auth_db", "password_column", "password") modparam("auth_db", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") modparam("auth_db", "load_credentials", "$avp(i:13)=rpid;email_address") # ----- alias_db params ----- /* uncomment the following lines if you want to enable the DB based aliases */ modparam("alias_db", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # ----- presence params ----- /* uncomment the following lines if you want to enable presence */ modparam("presence", "db_url","mysql://opensips:opensipsrw@localhost/opensips") modparam("presence", "server_address", "sip:atlanta.test") modparam("presence_xml", "db_url","mysql://opensips:opensipsrw@localhost/opensips") modparam("presence_xml", "force_active", 1) # ----- auth identity params ----- modparam("auth_identity","cainfo_path","/etc/ssl/certs/ca-certificates.crt") #TODO web server publicating CERTIFICATE. modparam("auth_identity","certificate_url","https://www.atlanata.test/mycert.der") modparam("auth_identity","certificate_path","/etc/ser/tls/cert.pem") modparam("auth_identity","privatekey_path","/etc/ser/tls/privkey.pem") ####### Routing Logic ######## # main request routing logic route{ xlog("L_ERR", "Misi: $mb\n"); # initial sanity checks -- messages with # max_forwards==0, or excessively long requests if (!mf_process_maxfwd_header("10")) { sl_send_reply("483","Too Many Hops"); exit; } if (msg:len >= 4096 ) { sl_send_reply("513", "Message too big"); exit; } if (has_totag()) { # sequential request withing a dialog should # take the path determined by record-routing if (loose_route()) { if (is_method("BYE")) { setflag(1); # do accounting ... setflag(3); # ... even if the transaction fails } else if (is_method("INVITE")) { # even if in most of the cases is useless, do RR for # re-INVITEs alos, as some buggy clients do change route set # during the dialog. record_route(); } # route it out to whatever destination was set by loose_route() # in $du (destination URI). route(1); } else { /* uncomment the following lines if you want to enable presence */ if (is_method("SUBSCRIBE") && $rd == "atlanta.test") { # in-dialog subscribe requests route(2); exit; } if ( is_method("ACK") ) { if ( t_check_trans() ) { # non loose-route, but stateful ACK; must be an ACK after # a 487 or e.g. 404 from upstream server t_relay(); exit; } else { # ACK without matching transaction -> # ignore and discard exit; } } sl_send_reply("404","Not here"); } exit; } #initial requests # CANCEL processing if (is_method("CANCEL")) { if (t_check_trans()) t_relay(); exit; } t_check_trans(); # authenticate if from local subscriber (uncomment to enable auth) # authenticate all initial non-REGISTER request that pretend to be # generated by local subscriber (domain from FROM URI is local) if (!(method=="REGISTER") && from_uri==myself) /*no multidomain version*/ ##if (!(method=="REGISTER") && is_from_local()) /*multidomain version*/ { if (!proxy_authorize("", "subscriber")) { proxy_challenge("", "0"); exit; } if (!check_from()) { sl_send_reply("403","Forbidden auth ID"); exit; } consume_credentials(); # caller authenticated } # preloaded route checking if (loose_route()) { xlog("L_ERR", "Attempt to route with preloaded Route's [$fu/$tu/$ru/$ci]"); if (!is_method("ACK")) sl_send_reply("403","Preload Route denied"); exit; } # record routing if (!is_method("REGISTER|MESSAGE")) record_route(); # account only INVITEs if (is_method("INVITE")) { setflag(1); # do accounting } if (!uri==myself) ## replace with following line if multi-domain support is used ##if (!is_uri_host_local()) { append_hf("P-hint: outbound\r\n"); # if you have some interdomain connections via TLS ##if($rd=="tls_domain1.net") { ## t_relay("tls:domain1.net"); ## exit; ##} else if($rd=="tls_domain2.net") { ## t_relay("tls:domain2.net"); ## exit; ##} route(1); } # requests for my domain ## uncomment this if you want to enable presence server ## and comment the next 'if' block ## NOTE: uncomment also the definition of route[2] from below if( is_method("PUBLISH|SUBSCRIBE")) route(2); #if (is_method("PUBLISH")) #{ # sl_send_reply("503", "Service Unavailable"); # exit; #} if (is_method("REGISTER")) { # authenticate the REGISTER requests (uncomment to enable auth) if (!www_authorize("", "subscriber")) { www_challenge("", "0"); exit; } if (!check_to()) { sl_send_reply("403","Forbidden auth ID"); exit; } if (!save("location")) sl_reply_error(); exit; } if ($rU=="") { # request with no Username in RURI sl_send_reply("484","Address Incomplete"); exit; } # apply DB based aliases (uncomment to enable) alias_db_lookup("dbaliases"); if(uri=~"sip:0.*@.*"){ sethost("195.111.158.3"); strip(1); # Append Remote-Party-ID header field append_rpid_hf("<", ">;party=calling;id-type=subscriber;screen=yes;privacy=off"); /* Remote-Party-ID: <sip:003646565111@195.111.104.13>;party=calling;screen=no;privacy=off */ route(1); exit; } if (!lookup("location")) { switch ($rc) { case -1: case -3: t_newtran(); t_reply("404", "Not Found"); exit; case -2: sl_send_reply("405", "Method Not Allowed"); exit; } } # when routing via usrloc, log the missed calls also setflag(2); route(1); } route[1] { # for INVITEs enable some additional helper routes if (is_method("INVITE")) { t_on_branch("2"); t_on_reply("2"); t_on_failure("1"); } if (!t_relay()) { sl_reply_error(); }; exit; } # Presence route /* uncomment the whole following route for enabling presence NOTE: do not forget to enable the call of this route from the main route */ route[2] { if (!t_newtran()) { sl_reply_error(); exit; }; if(is_method("PUBLISH")) { handle_publish(); # Removed command. Not Supported anymore. # At the end of script the transaction is automaticaly relased by TM. #t_release(); } else if( is_method("SUBSCRIBE")) { handle_subscribe(); # Removed command. Not Supported anymore. # At the end of script the transaction is automaticaly relased by TM. #t_release(); } exit; } branch_route[2] { xlog("new branch at $ru\n"); } onreply_route[2] { xlog("L_ERR", "Reply Misi: $mb\n"); xlog("incoming reply\n"); } failure_route[1] { if (t_is_canceled()) { exit; } # uncomment the following lines if you want to block client # redirect based on 3xx replies. ##if (t_check_status("3[0-9][0-9]")) { ##t_reply("404","Not found"); ## exit; ##} # uncomment the following lines if you want to redirect the failed # calls to a different new destination ##if (t_check_status("486|408")) { ## sethostport("192.168.2.100:5060"); ## # do not set the missed call flag again ## t_relay(); ##} } ####################################Ser########################################## # ## ------------------------- request routing logic ------------------- # ## main routing logic # #route{ # # # initial sanity checks -- messages with # # max_forwards==0, or excessively long requests # if (!mf_process_maxfwd_header("10")) { # sl_send_reply("483","Too Many Hops"); # break; # } # if (msg:len >= 4096 ) { # sl_send_reply("513", "Message too big"); # break; # } # # # we record-route all messages -- to make sure that # # subsequent messages will go through our proxy; that's # # particularly good if upstream and downstream entities # # use different transport protocol # if (!method=="REGISTER") record_route(); # # # subsequent messages withing a dialog should take the # # path determined by record-routing # if (loose_route()) { # # mark routing logic in request # append_hf("P-hint: rr-enforced\r\n"); # route(FORWARD); # break; # } # # if (!uri==myself) { # # mark routing logic in request # append_hf("P-hint: outbound\r\n"); # route(FORWARD); # break; # } # # # if the request is for other domain use UsrLoc # # (in case, it does not work, use the following command # # with proper names and addresses in it) # if (uri==myself) { # # if (method=="REGISTER") { # save_contacts("location"); ## break; # } # # # native SIP destinations are handled using our USRLOC DB # if (!lookup_contacts("location")) { # sl_send_reply("404", "Not Found"); # break; # } ## append_hf("P-hint: usrloc applied\r\n"); # } # route(FORWARD); #} # #route[FORWARD] #{ # # send it out now; use stateful forwarding as it works reliably # # even for UDP2TCP # if (!t_relay()) { # sl_reply_error(); ## } #} # # $Id$ # # Example SER TLS Configuration File # # This is the default server domain, settings # in this domain will be used for all incoming # connections that do not match any other server # domain in this configuration file. # # We do not enable anything else than TLSv1 # over the public internet. Clients do not have # to present client certificates by default. # [server:default] method = TLSv1 verify_certificate = yes require_certificate = no private_key = /etc/ser/tls/privkey.pem certificate = /etc/ser/tls/cert.pem ca_list = /etc/ser/tls/calist.pem # This is the default client domain, settings # in this domain will be used for all outgoing # TLS connections that do not match any other # client domain in this configuration file. # We require that servers present valid certificate. # [client:default] verify_certificate = yes require_certificate = yes # This is example server domain for TLS connections # received from the loopback interface. We allow # the use of SSLv2 and SSLv3 protocols here, we do # not require that clients present client certificates # but if they present it it must be valid. We also use # a special certificate and CA list for loopback # interface. # #[server:127.0.0.1:5061] #method = SSLv23 #verify_certificate = yes #require_certificate = no #private_key = local_key.pem #certificate = local_cert.pem #verify_depth = 3 #ca_list = local_ca.pem # Special settings for the iptel.org public SIP # server. We do not verify the certificate of the # server because it can be expired. The server # implements authentication using SSL client # certificates so configure the client certificate # that was given to use by iptel.org staff here. # #[client:195.37.77.101:5061] #verify_certificate = no #certificate = iptel_client.pem #private_key = iptel_key.pem #ca_list = iptel_ca.pem [View Less]

2 3

sip-router select
by MÉSZÁROS Mihály 12 Aug '09

12 Aug '09

Hi! Can any of you explain how select framework is working? Where can i find any documentation about it. I am experiencing problem when i am try using it. Any help highly appreciated! Regards, Misi

2 4

[Kamailio-Users] HOWTO rewrite to: header
by alexander merkulov 12 Aug '09

12 Aug '09

here is correct reqwest and reqwest via kamailio is there any way to rewrite To: field in kamailio because now it nto work correct reqwest(asterisk) RECEIVING FROM: 69.70.173.195:5060 CANCEL sip:34249@193.110.78.12:8484 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.180:5060;branch=z9hG4bK4c97bd4a From: "Unknown" <sip:Unknown@voip1.bravotelecom.com<sip%3AUnknown(a)voip1.bravotelecom.com> >;tag=as366a0ba0 To: <sip:34249@193.110.78.12:8484> Call-ID: 322db75c71be4ba45a61c7666b93e6be(a)… [View More]

6 21

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

2005

2004

2003

2002

sr-users August 2009