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:activities><rpid:busy/><rpid:on-the-phone/></rpid:activities><dm:note>On the phone</dm:note></dm:person></presence>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [33]; uri=[sip:alice@atlanta.test] 
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body ["alice"<sip:alice@atlanta.test>#015#012]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=3 global id=2 T start=0xffffffff
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <16> <PUBLISH>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: beginning of SIP-If-Match: yet=0x2d706973
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: middle of SIP-If-Match: yet=0x6d2d6669
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: end of SIP-If-Match
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=517
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=3518, isACK=0
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=3 global id=3 T end=(nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=6470be16
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [nonce.c:186]: comparing [4a81babd0000000bdc0c130f92356ce11fc7ea51a926c644] and [4a81babd0000000bdc0c130f92356ce11fc7ea51a926c644]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82bd628
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 12 bytes for result names at 0x82f55d8
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 12 bytes for result types at 0x82f52fc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82f4e4c
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4e4c)[0]=[password]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82dbf88
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82dbf88)[1]=[email_address]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[2] at 0x82f5768
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f5768)[2]=[rpid]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f4ebc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 60 bytes for row values at 0x82f5390
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [bakker]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING []
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:003631001001@atlanta.test]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:123]: HA1 string calculated: 67bb4b4b59a70b7f246682dfdd188df2
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:239]: our result = '527ee7c53e6f621ef9ee161426da4afd'
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:246]: authorization is OK
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:194]: nonce index= 11
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [index.c:187]: nonce already used
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:198]: nonce index not valid
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 3 columns
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82f4e4c
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82dbf88
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82f5768
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f55d8
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f52fc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5390
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f4ebc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82bd628
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [index.c:128]: second= 16, sec_monit= 8,  index= 12
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:107]: nonce index= 12
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:151]: 'Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2", qop="auth"#015#012'
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 742 bytes written
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=742 fd=8
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 407 Proxy Authentication Required#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-260c1648321add52-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: "alice"<sip:alice@atlanta.test>;tag=f8f2ab2c1295e90ed7dbb499b30f44b2.a62c#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 16 PUBLISH#015#012Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2", qop="auth"#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells:  pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:alice@atlanta.test out_uri=sip:alice@atlanta.test via_cnt==1"#015#012#015#012
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 517
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request:
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]:  method:  <PUBLISH>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]:  uri:     <sip:alice@atlanta.test>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]:  version: <SIP/2.0>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-8b6841568301eb55-1---d8754z->; state=6
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg...
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts...
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: PUBLISH sip:alice@atlanta.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-8b6841568301eb55-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: "alice"<sip:alice@atlanta.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 17 PUBLISH#015#012Expires: 1200#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/pidf+xml#015#012Proxy-Authorization: Digest username="alice",realm="atlanta.test",nonce="4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2",uri="sip:alice@atlanta.test",response="cc8d63baac587662386d887e507bf60b",cnonce="1eeeeb8bf845982d90f185276c67bc78",nc=00000001,qop=auth,algorithm=MD5#015#012SIP-If-Match: a.1250015022.397.2.8#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Event: presence#015#012Content-Length: 517#015#012#015#012<?xml version='1.0' encoding='UTF-8'?><presence xmlns='urn:ietf:params:xml:ns:pidf' xmlns:dm='urn:ietf:params:xml:ns:pidf:data-model' xmlns:rpid='urn:ietf:params:xml:ns:pidf:rpid' xmlns:c='urn:ietf:params:xml:ns:pidf:cipid' xmlns:lt='urn:ietf:params:xml:ns:location-type' entity='sip:alice@atlanta.test'><tuple id='tae2c271a'><status><basic>open</basic></status></tuple><dm:person id='p7a66b539'><rpid:activities><rpid:busy/><rpid:on-the-phone/></rpid:activities><dm:note>On the phone</dm:note></dm:person></presence>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [33]; uri=[sip:alice@atlanta.test] 
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body ["alice"<sip:alice@atlanta.test>#015#012]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=4 global id=3 T start=(nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <17> <PUBLISH>
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: beginning of SIP-If-Match: yet=0x2d706973
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: middle of SIP-If-Match: yet=0x6d2d6669
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_hname2.c:182]: end of SIP-If-Match
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=517
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=3519, isACK=0
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=4 global id=4 T end=(nil)
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=6470be16
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [nonce.c:186]: comparing [4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2] and [4a81bacc0000000cc8f1349a189042236344c2b25f33aeb2]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82bd628
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 12 bytes for result names at 0x82f55d8
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 12 bytes for result types at 0x82f52fc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82f4ebc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4ebc)[0]=[password]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82f5768
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f5768)[1]=[email_address]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[2] at 0x82dbf88
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82dbf88)[2]=[rpid]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f4e4c
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 60 bytes for row values at 0x82f5390
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [bakker]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING []
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:003631001001@atlanta.test]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:123]: HA1 string calculated: 67bb4b4b59a70b7f246682dfdd188df2
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:239]: our result = 'cc8d63baac587662386d887e507bf60b'
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:246]: authorization is OK
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:194]: nonce index= 12
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:176]: set string AVP ""/13 = "sip:003631001001@atlanta.test"
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 3 columns
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82f4ebc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82f5768
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82dbf88
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f55d8
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f52fc
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5390
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f4e4c
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82bd628
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: uri_db [checks.c:137]: Digest username and URI username match
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:108]: No Route headers found
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:907]: There is no Route HF
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:38 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1383]: DEBUG: t_newtran: msg id=4 , global msg id=4 , T on entrance=(nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=3519, isACK=0
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_hooks.c:335]: DBG: trans=0xb585090c, callback type 1, id 0 entered
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [event_list.c:349]: start event= [presence/1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [publish.c:369]: SIP-If-Match header found
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [publish.c:378]: existing etag  = a.1250015022.397.2.8 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [publish.c:390]: Expires header found, value= 1200
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82f56e4
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 2 columns returned from the query
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 8 bytes for result names at 0x82f5768
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 8 bytes for result types at 0x82f4ebc
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82f4e84
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4e84)[0]=[body]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:121]: use DB1_BLOB result type
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82f5730
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f5730)[1]=[sender]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f4e10
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 40 bytes for row values at 0x82f5960
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:168]: converting BLOB [<?xml version='1.0' encoding='UTF-8'?><presence xmlns='urn:ietf:params:xml:ns:pidf' xmlns:dm='urn:ietf:params:xml:ns:pidf:data-model' xmlns:rpid='urn:ietf:params:xml:ns:pidf:rpid' xmlns:c='urn:ietf:params:xml:ns:pidf:cipid' xmlns:lt='urn:ietf:params:xml:ns:location-type' entity='sip:alice@atlanta.test'><tuple id='tae2c271a'><status><basic>open</basic></status></tuple><dm:person id='p7a66b539'><dm:note>Available</dm:note></dm:person></presence>]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING []
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 2 columns
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82f4e84
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82f5730
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f5768
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f4ebc
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5960
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f4e10
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82f56e4
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [presentity.c:88]: etag= a.1250015022.390.2.9 / 20#012 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [presentity.c:102]: send 200OK reply
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [presentity.c:103]: etag= a.1250015022.390.2.9 - len= 20
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=4 global id=4 T start=0xb585090c
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1152]: DEBUG: t_check_msg: T already found!
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [mem/shm_mem.c:117]: WARNING:vqm_resize: resize(0) called
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:1355]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 643 bytes written
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=643 fd=8
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-8b6841568301eb55-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: "alice"<sip:alice@atlanta.test>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-2965#015#012From: "alice"<sip:alice@atlanta.test>;tag=6470be16#015#012Call-ID: MTM5NDE0YjRjMmU2ZWNlOThjNDI1MGM2ZjAzMDBjZjA.#015#012CSeq: 17 PUBLISH#015#012Expires: 1200#015#012SIP-ETag: a.1250015022.390.2.9#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells:  pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:alice@atlanta.test out_uri=sip:alice@atlanta.test via_cnt==1"#015#012#015#012
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:610]: DEBUG: reply sent out. buf=0x82f5c80: SIP/2.0 2..., shmem=0xb584f674: SIP/2.0 2
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:620]: DEBUG: _reply_light: finished
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: sl [sl.c:309]: reply in stateful mode (tm)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [notify.c:1302]: found 0 dialogs( 0 in database and 0 in hash_table)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: presence [notify.c:1321]: Could not find subs_dialog
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 544
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request:
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]:  method:  <INVITE>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]:  uri:     <sip:bob@biloxi.test>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]:  version: <SIP/2.0>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z->; state=6
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: INVITE sip:bob@biloxi.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 1 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [23]; uri=[sip:bob@biloxi.test] 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>#015#012]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffff
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=544
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=5d194242
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=47015, isACK=0
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=5 global id=5 T end=(nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:126]: credentials with given realm not found
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [index.c:128]: second= 18, sec_monit= 8,  index= 13
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:107]: nonce index= 13
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [challenge.c:151]: 'Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0", qop="auth"#015#012'
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: sl [sl.c:314]: reply in stateless mode (sl)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 724 bytes written
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=724 fd=8
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 407 Proxy Authentication Required#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>;tag=f8f2ab2c1295e90ed7dbb499b30f44b2.d643#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 1 INVITE#015#012Proxy-Authenticate: Digest realm="atlanta.test", nonce="4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0", qop="auth"#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells:  pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 0
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request:
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]:  method:  <ACK>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]:  uri:     <sip:bob@biloxi.test>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]:  version: <SIP/2.0>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-0b3389781d1b817e-1---d8754z->; state=6
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=f8f2ab2c1295e90ed7dbb499b30f44b2.d643
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [65]; uri=[sip:bob@biloxi.test] 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: sl [sl_funcs.c:327]: local ACK found -> dropping it!
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 544
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request:
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]:  method:  <INVITE>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]:  uri:     <sip:bob@biloxi.test>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]:  version: <SIP/2.0>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-2a767f38e361686d-1---d8754z->; state=6
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts...
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: ERROR: <script>: Misi: INVITE sip:bob@biloxi.test SIP/2.0#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport#015#012Max-Forwards: 70#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Proxy-Authorization: Digest username="alice",realm="atlanta.test",nonce="4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0",uri="sip:bob@biloxi.test",response="60ca1ab3ccd52ae04fded05e2056a49a",cnonce="41e9f5aabf671596242bb02343062a1b",nc=00000001,qop=auth,algorithm=MD5#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: maxfwd [mf_funcs.c:85]: value = 70 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=9
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [23]; uri=[sip:bob@biloxi.test] 
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>#015#012]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: siputils [checks.c:65]: no totag
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1080]: DEBUG: t_check_msg: msg id=7 global id=5 T start=(nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field: cseq <CSeq>: <2> <INVITE>
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_body : content_length=544
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:89]: found end of header
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=5d194242
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=47012, isACK=0
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1149]: DEBUG: t_check_msg: msg id=7 global id=7 T end=(nil)
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==9 &&  [atlanta.test] == [127.0.0.1]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 12==14 &&  [atlanta.test] == [195.111.158.41]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [nonce.c:186]: comparing [4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0] and [4a81bacd0000000dda4c36dd574a1b80048af63c44e36fd0]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:116]: allocate 28 bytes for result set at 0x82bd628
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:153]: allocate 12 bytes for result names at 0x82f55d8
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:163]: allocate 12 bytes for result types at 0x82f52b8
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[0] at 0x82dbf88
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82dbf88)[0]=[password]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[1] at 0x82f4e4c
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4e4c)[1]=[email_address]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:85]: allocate 8 bytes for RES_NAMES[2] at 0x82f4ebc
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0x82f4ebc)[2]=[rpid]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:182]: allocate 8 bytes for rows at 0x82f5768
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:119]: allocate 60 bytes for row values at 0x82f5960
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [bakker]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING []
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:003631001001@atlanta.test]
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:123]: HA1 string calculated: 67bb4b4b59a70b7f246682dfdd188df2
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:239]: our result = '60ca1ab3ccd52ae04fded05e2056a49a'
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:246]: authorization is OK
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth [api.c:194]: nonce index= 13
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: auth_db [authorize.c:176]: set string AVP ""/13 = "sip:003631001001@atlanta.test"
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:79]: freeing 3 columns
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[0] at 0x82dbf88
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[1] at 0x82f4e4c
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:83]: freeing RES_NAMES[2] at 0x82f4ebc
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:92]: freeing result names at 0x82f55d8
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:97]: freeing result types at 0x82f52b8
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:52]: freeing 1 rows
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_row.c:97]: freeing row values at 0x82f5960
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:60]: freeing rows at 0x82f5768
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: <core> [db_res.c:134]: freeing result set at 0x82bd628
Aug 11 20:38:39 a1 /usr/sbin/ser[390]: DEBUG: uri_db [checks.c:137]: Digest username and URI username match
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:108]: No Route headers found
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: rr [loose.c:907]: There is no Route HF
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 &&  [biloxi.test] == [127.0.0.1]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 &&  [biloxi.test] == [195.111.158.41]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 &&  [biloxi.test] == [127.0.0.1]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 &&  [biloxi.test] == [195.111.158.41]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 &&  [biloxi.test] == [127.0.0.1]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 &&  [biloxi.test] == [195.111.158.41]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5061 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==9 &&  [biloxi.test] == [127.0.0.1]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:484]: grep_sock_info - checking if host==us: 11==14 &&  [biloxi.test] == [195.111.158.41]
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [socket_info.c:487]: grep_sock_info - checking if port 5060 matches port 5060
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [forward.c:318]: check_self: host != me
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1383]: DEBUG: t_newtran: msg id=7 , global msg id=7 , T on entrance=(nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=47012, isACK=0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_hooks.c:335]: DBG: trans=0xb584cf18, callback type 1, id 0 entered
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_funcs.c:348]: SER: new INVITE
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [mem/shm_mem.c:117]: WARNING:vqm_resize: resize(0) called
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 572 bytes written
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=572 fd=8
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 100 trying -- your call is important to us#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells:  pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:610]: DEBUG: reply sent out. buf=0x82f5c80: SIP/2.0 1..., shmem=0xb58505ec: SIP/2.0 1
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:620]: DEBUG: _reply_light: finished
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(biloxi.test(11), 35), h=599
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2674]: naptr_iterate: found a valid sip NAPTR rr _sip._tcp.biloxi.test, proto 2
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1091]: naptr_choose(o: -1 w: -1 p:0 , o: 20 w:50 p:2)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1107]: naptr_choose: changed
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2674]: naptr_iterate: found a valid sip NAPTR rr _sip._udp.biloxi.test, proto 1
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1091]: naptr_choose(o: 20 w: 50 p:2 , o: 30 w:50 p:1)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1102]: naptr_choose: no change
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2674]: naptr_iterate: found a valid sip NAPTR rr _sips._tcp.biloxi.test, proto 3
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1091]: naptr_choose(o: 20 w: 50 p:2 , o: 10 w:50 p:3)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [resolve.c:1107]: naptr_choose: changed
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2688]: naptr_iterate: choosed NAPTR rr _sips._tcp.biloxi.test, proto 3 tried: 0x0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(_sips._tcp.biloxi.test(22), 33), h=208
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2246]: dns_srv_get_nxt_rr(0xb5864a2c, 0, 0, 559080590): selected 0/1 in grp. 0 (rand_w=0, rr=0xb5864a70 p=10 w=0 rsum=0)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(b1.biloxi.test(14), 1), h=386
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b1.biloxi.test, 0) returning 0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3115]: dns_srv_resolve_ip("_sips._tcp.biloxi.test", 0, 0), ret=0, ip=195.111.158.43
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3350]: dns_naptr_sip_resolve(biloxi.test, 0, 0), srv0, ret=0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: <script>: new branch at sip:bob@biloxi.test
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:2379]: create_via_hf: id added: <;i=2>, rcv proto=3
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1778]: tcp_send: no open tcp connection found, opening new one
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [ip_addr.c:116]: tcpconn_new: new tcp connection: 195.111.158.43
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1050]: tcpconn_new: on port 5061, type 3
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, 2, fd 68 from 36 (390)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: BUG: tls [tls_server.c:98]: Invalid connection state (bug in TCP code)
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:1349]: tcpconn_add: hashes: 1306:736:1196, 9
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tls [tls_server.c:145]: Delayed init failed
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:361]: DBG: io_watch_add(0x8228560, 68, 2, 0xb5865b20), fd_no=55
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb5865b20 n=-1 fd=13
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012INVITE sip:bob@biloxi.test SIP/2.0#015#012Record-Route: <sip:195.111.158.41:5061;transport=tls;lr=on;ftag=5d194242>#015#012Via: SIP/2.0/TLS 195.111.158.41:5061;branch=z9hG4bK4a7b.1036c875.0;i=2#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;received=92.249.143.13;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783#015#012Max-Forwards: 69#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012P-hint: outbound#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: <core> [tcp_main.c:2166]: ERROR: tcp_send: failed to send on 0xb5865b20 (195.111.158.41:59267->195.111.158.43:5061): Operation now in progress (115)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tm [../../forward.h:163]: msg_send: ERROR: tcp_send failed
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, -2, fd -1 from 36 (390)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_fwd.c:961]: t_send_branch: send to 195.111.158.43:5061 (3) failed
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: ERROR: <core> [tcp_main.c:3027]: handle_ser_child: ERROR: received CON_ERROR for 0xb5865b20 (id 9), refcnt 2
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b1.biloxi.test, 1) returning -1
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:588]: DBG: io_watch_del (0x8228560, 68, -1, 0x10) fd_no=56 called
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2246]: dns_srv_get_nxt_rr(0xb5864a2c, 0, 0, 559080593): selected 0/1 in grp. 1 (rand_w=0, rr=0xb5864a98 p=20 w=0 rsum=0)
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: tls [tls_server.c:689]: Closing SSL connection
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:560]: dns_hash_find(b2.biloxi.test(14), 1), h=281
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b2.biloxi.test, 0) returning 0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3115]: dns_srv_resolve_ip("_sips._tcp.biloxi.test", 1, 0), ret=0, ip=195.111.158.44
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3256]: dns_sip_resolve(biloxi.test, 1, 0), srv, ret=0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:2379]: create_via_hf: id added: <;i=2>, rcv proto=3
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_fwd.c:974]: t_send_branch: send on branch 0 failed, adding another branch with another ip
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1778]: tcp_send: no open tcp connection found, opening new one
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [ip_addr.c:116]: tcpconn_new: new tcp connection: 195.111.158.44
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1050]: tcpconn_new: on port 5061, type 3
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: BUG: tls [tls_server.c:98]: Invalid connection state (bug in TCP code)
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, 2, fd 68 from 36 (390)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tls [tls_server.c:145]: Delayed init failed
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:1349]: tcpconn_add: hashes: 1693:359:2697, 10
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb5865b20 n=-1 fd=13
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:361]: DBG: io_watch_add(0x8228560, 68, 2, 0xb5865b20), fd_no=55
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012INVITE sip:bob@biloxi.test SIP/2.0#015#012Record-Route: <sip:195.111.158.41:5061;transport=tls;lr=on;ftag=5d194242>#015#012Via: SIP/2.0/TLS 195.111.158.41:5061;branch=z9hG4bK4a7b.1036c875.1;i=2#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;received=92.249.143.13;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783#015#012Max-Forwards: 69#015#012Contact: <sip:alice@92.249.143.13:2783;transport=TLS>#015#012To: <sip:bob@biloxi.test>#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces#015#012User-Agent: Bria Professional release 2.4 stamp 49381#015#012Content-Length: 544#015#012P-hint: outbound#015#012#015#012v=0#015#012o=- 6 2 IN IP4 92.249.143.13#015#012s=CounterPath Bria Professional#015#012c=IN IP4 92.249.143.13#015#012t=0 0#015#012m=audio 4242 RTP/AVP 107 119 100 106 0 98 8 18 101#015#012a=alt:1 2 : bg/abBbq 9nirlFAG 192.168.1.7 4242#015#012a=alt:2 1 : wCTfkbfT 6n6JS41z 92.249.143.13 4242#015#012a=fmtp:18 annexb=yes#015#012a=fmtp:101 0-15#015#012a=rtpmap:107 BV32/16000#015#012a=rtpmap:119 BV32-FEC/16000#015#012a=rtpmap:100 SPEEX/16000#015#012a=rtpmap:106 SPEEX-FEC/16000#015#012a=rtpmap:98 iLBC/8000#015#012a=rtpmap:18 G729/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=sendrecv#015#012a=x-rtp-session-id:C5EF9F1EE4C64633A625BEC3FF808160#015#012
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: <core> [tcp_main.c:2166]: ERROR: tcp_send: failed to send on 0xb5865b20 (195.111.158.41:55898->195.111.158.44:5061): Operation now in progress (115)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tm [../../forward.h:163]: msg_send: ERROR: tcp_send failed
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [tcp_main.c:3014]: handle_ser_child: read response= b5865b20, -2, fd -1 from 36 (390)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_fwd.c:961]: t_send_branch: send to 195.111.158.44:5061 (3) failed
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: ERROR: <core> [tcp_main.c:3027]: handle_ser_child: ERROR: received CON_ERROR for 0xb5865b20 (id 10), refcnt 2
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:2861]: dns_a_resovle(b2.biloxi.test, 1) returning -1
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: <core> [io_wait.h:588]: DBG: io_watch_del (0x8228560, 68, -1, 0x10) fd_no=56 called
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3115]: dns_srv_resolve_ip("_sips._tcp.biloxi.test", 2, 1), ret=-1, ip=
Aug 11 20:38:40 a1 /usr/sbin/ser[398]: DEBUG: tls [tls_server.c:689]: Closing SSL connection
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [dns_cache.c:3256]: dns_sip_resolve(biloxi.test, 2, 1), srv, ret=-1
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: ERROR: tm [t_fwd.c:980]: ERROR: t_send_branch: sending request on branch 1 failed
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_funcs.c:358]: ERROR:tm:t_relay_to:  t_forward_nonack returned error 
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_funcs.c:366]: -477 error reply generation delayed 
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: sl [sl_funcs.c:283]: error text is Unfortunately error on sending to next hop occurred (477/SL)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 636 bytes written
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=636 fd=8
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 477 Unfortunately error on sending to next hop occurred (477/SL)#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>;tag=f8f2ab2c1295e90ed7dbb499b30f44b2.573f#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells:  pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_lookup.c:1536]: t_unref: delayed error reply generation(-477)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [msg_translator.c:200]: check_via_address(92.249.143.13, 192.168.1.7, 0)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:1355]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:1998]: tcp_send: send from reader (390 (36)), reusing fd
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2049]: tcp_send: sending...
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tls [tls_server.c:738]: write finished, 636 bytes written
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2085]: tcp_send: after real write: c= 0xb584b448 n=636 fd=8
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_main.c:2086]: tcp_send: buf=#012SIP/2.0 477 Unfortunately error on sending to next hop occurred (477/TM)#015#012Via: SIP/2.0/TLS 192.168.1.7:4241;branch=z9hG4bK-d8754z-2a767f38e361686d-1---d8754z-;rport=2783;received=92.249.143.13#015#012To: <sip:bob@biloxi.test>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-573f#015#012From: "alice"<sip:alice@atlanta.test>;tag=5d194242#015#012Call-ID: ZTczYjE5ZThhZjhkNmYyMDY0NGYxM2ExOTdkYjg5ZDM.#015#012CSeq: 2 INVITE#015#012Server: SIP Router (2.99.0-dev01-serk (i386/linux))#015#012Content-Length: 0#015#012Warning: 392 195.111.158.41:5061 "Noisy feedback tells:  pid=390 req_src_ip=92.249.143.13 req_src_port=2783 in_uri=sip:bob@biloxi.test out_uri=sip:bob@biloxi.test via_cnt==1"#015#012#015#012
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_hooks.c:252]: DBG: trans=0xb584cf18, callback type 128, id 0 entered
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:610]: DEBUG: reply sent out. buf=0x82f6088: SIP/2.0 4..., shmem=0xb58505ec: SIP/2.0 4
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: tm [t_reply.c:620]: DEBUG: _reply_light: finished
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 0
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request:
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]:  method:  <ACK>
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]:  uri:     <sip:bob@biloxi.test>
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]:  version: <SIP/2.0>
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-2a767f38e361686d-1---d8754z->; state=6
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17
Aug 11 20:38:40 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:127]: After parse_msg...
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:166]: preparing to run routing scripts...
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=f8f2ab2c1295e90ed7dbb499b30f44b2.573f
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_to.c:753]: end of header reached, state=29
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:173]: DEBUG: get_hdr_field: <To> [65]; uri=[sip:bob@biloxi.test] 
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:175]: DEBUG: to body [<sip:bob@biloxi.test>]
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: sl [sl_funcs.c:327]: local ACK found -> dropping it!
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [usr_avp.c:629]: DEBUG:destroy_avp_list: destroying list (nil)
Aug 11 20:38:41 a1 /usr/sbin/ser[390]: DEBUG: <core> [receive.c:254]: receive_msg: cleaning up

Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [tcp_read.c:713]: tcp_read_req: content-length= 447
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:599]: SIP Request:
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:601]:  method:  <PUBLISH>
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:603]:  uri:     <sip:alice@atlanta.test>
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:605]:  version: <SIP/2.0>
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 232, <branch> = <z9hG4bK-d8754z-0d1d4d59c544e42e-1---d8754z->; state=6
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:1283]: Found param type 235, <rport> = <n/a>; state=17
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/parse_via.c:2296]: end of header reached, state=5
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:495]: parse_headers: Via found, flags=2
Aug 11 20:38:44 a1 /usr/sbin/ser[390]: DEBUG: <core> [parser/msg_parser.c:497]: parse_headers: this is the first via