Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:628]: SIP Request: 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:630]:  method:  <INVITE> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:632]:  uri:     <sip:+47734yyyyy@test-server.test:5060> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:634]:  version: <SIP/2.0> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK14d3.0b80dd42.0>; state=16 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=2 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: this is the first via 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [receive.c:145]: After parse_msg... 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts... 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK14d3.7e79b114.0>; state=16 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:526]: parse_headers: this is the second via 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK16ed24c9>; state=6 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 235, <rport> = <7476>; state=16 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=as7348360d 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: MAIN ROUTE - INVITE: sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: REQINIT: Entered 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [37]; uri=[sip:+47734yyyyy@158.xxx.xxx.xxx:777]  
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: to body [<sip:+47734yyyyy@158.xxx.xxx.xxx:777>^M ] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: maxfwd [mf_funcs.c:85]: value = 68  
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:199]: DEBUG: get_hdr_body : content_length=266 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [parser/msg_parser.c:101]: found end of header 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: siputils [checks.c:73]: no totag 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=15681, isACK=0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=1 global id=1 T end=(nil) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: AUTHANDSOURCE: Entered -  sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 24==13 &&  [origin.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [forward.c:434]: check_self: host != me 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: FROMEXTERNAL: Entered Route - sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: EXPAND: Entered +47734yyyyy 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: EXPAND: After expanding: +47734yyyyy and type of call is 4 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: CHKLOCALUSER: Entered (+47734yyyyy) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:118]: allocate 48 bytes for result set at 0xa90b80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:68]: 2 columns returned from the query 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:155]: allocate 16 bytes for result names at 0xa90c10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:165]: allocate 8 bytes for result types at 0xa2be08 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[0] at 0xa90c80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c80)[0]=[username] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90cf0)[1]=[domain] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:184]: allocate 16 bytes for rows at 0xa90d60 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_row.c:119]: allocate 64 bytes for row values at 0xa90dd0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_val.c:117]: converting STRING [miguel] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_val.c:117]: converting STRING [test-server.test] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: alias_db [alookup.c:198]: new URI [0] is [sip:miguel@test-server.test] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:81]: freeing 2 columns 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xa90c80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xa90c10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xa2be08 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:54]: freeing 1 rows 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_row.c:97]: freeing row values at 0xa90dd0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:62]: freeing rows at 0xa90d60 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xa90b80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: CHKFORWARD:(INVITE) Entered - sip:+47945xxxxx@origin.test to sip:miguel@test-server.test (miguel) (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:118]: allocate 48 bytes for result set at 0xa90b80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:155]: allocate 24 bytes for result names at 0xa90dd0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:165]: allocate 12 bytes for result types at 0xa90d60 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[0] at 0xa90c10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c10)[0]=[value] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90cf0)[1]=[attribute] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[2] at 0xa90c80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c80)[2]=[type] 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:100]: use DB1_INT result type 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: db_mysql [km_res.c:169]: no rows returned from the query 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: avpops [avpops_db.c:271]: close avp query 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:81]: freeing 3 columns 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xa90c10 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[2] at 0xa90c80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xa90dd0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xa90d60 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xa90b80 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: avpops [avpops_impl.c:419]: loaded avps = 0 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: CHK_FORWARD:(INVITE) No forward setting - sip:+47945xxxxx@origin.test to sip:miguel@test-server.test (miguel) (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: TESTEXEC: Entered (miguel) 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [md5utils.c:94]: DEBUG: MD5 calculated: f55ad989e64de778bb776aff99262435 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:628]: SIP Request: 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=266 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:630]:  method:  <INVITE> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:632]:  uri:     <sip:+47734yyyyy@test-server.test:5060> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:634]:  version: <SIP/2.0> 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK14d3.0b80dd42.0>; state=16 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Mon, 13 Feb 2012 11:44:08 GMT 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=67 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=2 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=UNINETT SBC 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: this is the first via 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [receive.c:145]: After parse_msg... 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=72071bf95c7b3d27651034730f125520@origin.test 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts... 
Feb 13 12:44:08 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=<sip:%2b47945xxxxx@158.36.141.13:777> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK14d3.7e79b114.0>; state=16 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=<sip:+47734yyyyy@158.xxx.xxx.xxx:777> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="+47945xxxxx" <sip:+47945xxxxx@origin.test>;tag=as7348360d 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP yyy.yyy.yyy.149:5062;branch=z9hG4bK14d3.0b80dd42.0,SIP/2.0/UDP 158.36.141.13:777;branch=z9hG4bK16ed24c9;rport=7476,SIP/2.0/UDP 158.xxx.xxx.xxx:777;branch=z9hG4bK14d3.7e79b114.0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:526]: parse_headers: this is the second via 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_hf.c:267]: SIP_HF_RECORD_ROUTE=<sip:yyy.yyy.yyy.149:5062;lr=on>,<sip:158.xxx.xxx.xxx:777;lr=on> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK16ed24c9>; state=6 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: exec [exec_mod.c:208]: executing [/root/miguel_test.pl] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 235, <rport> = <7476>; state=16 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=as7348360d 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: MAIN ROUTE - INVITE: sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: REQINIT: Entered 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [37]; uri=[sip:+47734yyyyy@158.xxx.xxx.xxx:777]  
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: to body [<sip:+47734yyyyy@158.xxx.xxx.xxx:777>^M ] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: maxfwd [mf_funcs.c:85]: value = 68  
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:199]: DEBUG: get_hdr_body : content_length=266 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [parser/msg_parser.c:101]: found end of header 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: siputils [checks.c:73]: no totag 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=15681, isACK=0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=1 global id=1 T end=(nil) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: AUTHANDSOURCE: Entered -  sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 24==13 &&  [origin.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [forward.c:434]: check_self: host != me 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: FROMEXTERNAL: Entered Route - sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: EXPAND: Entered +47734yyyyy 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: EXPAND: After expanding: +47734yyyyy and type of call is 4 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: CHKLOCALUSER: Entered (+47734yyyyy) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:118]: allocate 48 bytes for result set at 0xa90b80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:68]: 2 columns returned from the query 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:155]: allocate 16 bytes for result names at 0xa90c10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:165]: allocate 8 bytes for result types at 0xa2be08 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[0] at 0xa90c80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c80)[0]=[username] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90cf0)[1]=[domain] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:184]: allocate 16 bytes for rows at 0xa90d60 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_row.c:119]: allocate 64 bytes for row values at 0xa90dd0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_val.c:117]: converting STRING [miguel] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_val.c:117]: converting STRING [test-server.test] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: alias_db [alookup.c:198]: new URI [0] is [sip:miguel@test-server.test] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:81]: freeing 2 columns 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xa90c80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xa90c10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xa2be08 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:54]: freeing 1 rows 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_row.c:97]: freeing row values at 0xa90dd0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:62]: freeing rows at 0xa90d60 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xa90b80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: CHKFORWARD:(INVITE) Entered - sip:+47945xxxxx@origin.test to sip:miguel@test-server.test (miguel) (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:118]: allocate 48 bytes for result set at 0xa90b80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:155]: allocate 24 bytes for result names at 0xa90dd0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:165]: allocate 12 bytes for result types at 0xa90d60 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[0] at 0xa90c10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c10)[0]=[value] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90cf0)[1]=[attribute] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[2] at 0xa90c80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c80)[2]=[type] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:100]: use DB1_INT result type 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: db_mysql [km_res.c:169]: no rows returned from the query 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: avpops [avpops_db.c:271]: close avp query 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:81]: freeing 3 columns 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xa90c10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[2] at 0xa90c80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xa90dd0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xa90d60 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xa90b80 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: avpops [avpops_impl.c:419]: loaded avps = 0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: CHK_FORWARD:(INVITE) No forward setting - sip:+47945xxxxx@origin.test to sip:miguel@test-server.test (miguel) (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: INFO: <script>: TESTEXEC: Entered (miguel) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: <core> [md5utils.c:94]: DEBUG: MD5 calculated: f55ad989e64de778bb776aff99262435 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=266 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Mon, 13 Feb 2012 11:44:08 GMT 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=67 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=UNINETT SBC 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=72071bf95c7b3d27651034730f125520@origin.test 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=<sip:%2b47945xxxxx@158.36.141.13:777> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=<sip:+47734yyyyy@158.xxx.xxx.xxx:777> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="+47945xxxxx" <sip:+47945xxxxx@origin.test>;tag=as7348360d 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP yyy.yyy.yyy.149:5062;branch=z9hG4bK14d3.0b80dd42.0,SIP/2.0/UDP 158.36.141.13:777;branch=z9hG4bK16ed24c9;rport=7476,SIP/2.0/UDP 158.xxx.xxx.xxx:777;branch=z9hG4bK14d3.7e79b114.0 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_hf.c:267]: SIP_HF_RECORD_ROUTE=<sip:yyy.yyy.yyy.149:5062;lr=on>,<sip:158.xxx.xxx.xxx:777;lr=on> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31621]: DEBUG: exec [exec_mod.c:208]: executing [/root/miguel_test.pl] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:628]: SIP Request: 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:630]:  method:  <INVITE> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:632]:  uri:     <sip:+47734yyyyy@test-server.test:5060> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:634]:  version: <SIP/2.0> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK14d3.0b80dd42.0>; state=16 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=2 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: this is the first via 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [receive.c:145]: After parse_msg... 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [receive.c:186]: preparing to run routing scripts... 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK14d3.7e79b114.0>; state=16 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:526]: parse_headers: this is the second via 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232, <branch> = <z9hG4bK16ed24c9>; state=6 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:1287]: Found param type 235, <rport> = <7476>; state=16 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param: tag=as7348360d 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=29 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: MAIN ROUTE - INVITE: sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: REQINIT: Entered 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/parse_to.c:803]: end of header reached, state=10 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To> [37]; uri=[sip:+47734yyyyy@158.xxx.xxx.xxx:777]  
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: to body [<sip:+47734yyyyy@158.xxx.xxx.xxx:777>^M ] 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: maxfwd [mf_funcs.c:85]: value = 68  
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:199]: DEBUG: get_hdr_body : content_length=266 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [parser/msg_parser.c:101]: found end of header 
Feb 13 12:44:09 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: siputils [checks.c:73]: no totag 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=15681, isACK=0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=1 global id=1 T end=(nil) 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: AUTHANDSOURCE: Entered -  sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 24==13 &&  [origin.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [forward.c:434]: check_self: host != me 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: FROMEXTERNAL: Entered Route - sip:+47945xxxxx@origin.test to sip:+47734yyyyy@test-server.test:5060 (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: EXPAND: Entered +47734yyyyy 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: EXPAND: After expanding: +47734yyyyy and type of call is 4 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: CHKLOCALUSER: Entered (+47734yyyyy) 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking if host==us: 6==13 &&  [test-server.test] == [yyy.yyy.yyy.150] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking if port 5060 matches port 5060 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:118]: allocate 48 bytes for result set at 0xa90b80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:68]: 2 columns returned from the query 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:155]: allocate 16 bytes for result names at 0xa90c10 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:165]: allocate 8 bytes for result types at 0xa2be08 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[0] at 0xa90c80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c80)[0]=[username] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90cf0)[1]=[domain] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:184]: allocate 16 bytes for rows at 0xa90d60 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_row.c:119]: allocate 64 bytes for row values at 0xa90dd0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_val.c:117]: converting STRING [miguel] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_val.c:117]: converting STRING [test-server.test] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: alias_db [alookup.c:198]: new URI [0] is [sip:miguel@test-server.test] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:81]: freeing 2 columns 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xa90c80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xa90c10 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xa2be08 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:54]: freeing 1 rows 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_row.c:97]: freeing row values at 0xa90dd0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:62]: freeing rows at 0xa90d60 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xa90b80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: CHKFORWARD:(INVITE) Entered - sip:+47945xxxxx@origin.test to sip:miguel@test-server.test (miguel) (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:118]: allocate 48 bytes for result set at 0xa90b80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:68]: 3 columns returned from the query 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:155]: allocate 24 bytes for result names at 0xa90dd0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:165]: allocate 12 bytes for result types at 0xa90d60 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[0] at 0xa90c10 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c10)[0]=[value] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90cf0)[1]=[attribute] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:136]: use DB1_STRING result type 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:85]: allocate 16 bytes for RES_NAMES[2] at 0xa90c80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:92]: RES_NAMES(0xa90c80)[2]=[type] 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:100]: use DB1_INT result type 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: db_mysql [km_res.c:169]: no rows returned from the query 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: avpops [avpops_db.c:271]: close avp query 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:81]: freeing 3 columns 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xa90c10 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xa90cf0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[2] at 0xa90c80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xa90dd0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xa90d60 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xa90b80 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: avpops [avpops_impl.c:419]: loaded avps = 0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: CHK_FORWARD:(INVITE) No forward setting - sip:+47945xxxxx@origin.test to sip:miguel@test-server.test (miguel) (IP:yyy.yyy.yyy.149:5062) 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: INFO: <script>: TESTEXEC: Entered (miguel) 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: <core> [md5utils.c:94]: DEBUG: MD5 calculated: f55ad989e64de778bb776aff99262435 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=266 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Mon, 13 Feb 2012 11:44:08 GMT 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=67 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=UNINETT SBC 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=72071bf95c7b3d27651034730f125520@origin.test 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=<sip:%2b47945xxxxx@158.36.141.13:777> 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=<sip:+47734yyyyy@158.xxx.xxx.xxx:777> 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="+47945xxxxx" <sip:+47945xxxxx@origin.test>;tag=as7348360d 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP yyy.yyy.yyy.149:5062;branch=z9hG4bK14d3.0b80dd42.0,SIP/2.0/UDP 158.36.141.13:777;branch=z9hG4bK16ed24c9;rport=7476,SIP/2.0/UDP 158.xxx.xxx.xxx:777;branch=z9hG4bK14d3.7e79b114.0 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_hf.c:267]: SIP_HF_RECORD_ROUTE=<sip:yyy.yyy.yyy.149:5062;lr=on>,<sip:158.xxx.xxx.xxx:777;lr=on> 
Feb 13 12:44:10 test-server /usr/ipbx/kamailio/sbin/kamailio[31622]: DEBUG: exec [exec_mod.c:208]: executing [/root/miguel_test.pl] 
Feb 13 12:44:16 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: DEBUG: <core> [main.c:842]: SIGCHLD received: we do not worry about grand-children 
Feb 13 12:44:16 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: TESTEXEC: Returned value is nobusy 
Feb 13 12:44:16 test-server /usr/ipbx/kamailio/sbin/kamailio[31620]: INFO: <script>: TESTEXEC: Exiting (miguel)