[SR-Users] BUG: tls [tls_server.c:98]: Invalid connection state (bug in TCP code)

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/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:activitiesrpid:busy/rpid:on-the-phone/</rpid:activities>dm:noteOn 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:activitiesrpid:busy/rpid:on-the-phone/</rpid:activities>dm:noteOn 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:noteAvailable</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