[Serusers] cpl-c and transactions? call to t_newtran() causes a crash

Hi All, I'm setting up the cpl-c module. On invite I'm calling cpl_run_script("incoming", "force_stateful"), and I'm getting no transaction found. If I add a t_newtran() before the call ser crashes. I have played with is_stateless and is_statefull all with similar results. Below you will find version, ser log with and without the t_newtran(), the CPL I'm testing with, and my config. Is my t_newtran() badly placed? I'm surprised I managed to actually crash ser with this. Version: host:/usr/local/etc/ser# ser -V version: ser 0.8.14-2 (i386/linux) flags: STATS:Off, USE_IPV6, USE_TCP, DISABLE_NAGLE, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535 @(#) $Id: main.c,v 1.168.4.3 2004/06/28 15:41:21 andrei Exp $ main.c compiled on 13:40:08 Oct 7 2004 with gcc 2.95 ser log: Oct 12 12:25:02 host ser[30289]: SIP Request: Oct 12 12:25:02 host ser[30289]: method: <INVITE> Oct 12 12:25:02 host ser[30289]: uri: <sip:8661@example.com> Oct 12 12:25:02 host ser[30289]: version: <SIP/2.0> Oct 12 12:25:02 host ser[30289]: parse_headers: flags=1 Oct 12 12:25:02 host ser[30289]: Found param type 235, <rport> = <n/a>; state=6 Oct 12 12:25:02 host ser[30289]: Found param type 232, <branch> = <z9hG4bK99405135488C4EAEAEFDC9CEA70D60C3>; state=16 Oct 12 12:25:02 host ser[30289]: end of header reached, state=5 Oct 12 12:25:02 host ser[30289]: parse_headers: Via found, flags=1 Oct 12 12:25:02 host ser[30289]: parse_headers: this is the first via Oct 12 12:25:02 host ser[30289]: After parse_msg... Oct 12 12:25:02 host ser[30289]: preparing to run routing scripts... Oct 12 12:25:02 host ser[30289]: XLOG: xl_print_log: final buffer length 50 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=8 Oct 12 12:25:02 host ser[30289]: DEBUG: add_param: tag=535325945 Oct 12 12:25:02 host ser[30289]: end of header reached, state=29 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=4 Oct 12 12:25:02 host ser[30289]: end of header reached, state=9 Oct 12 12:25:02 host ser[30289]: DEBUG: get_hdr_field: <To> [34]; uri=[sip:8661@example.com] Oct 12 12:25:02 host ser[30289]: DEBUG: to body [<sip:8661@example.com>^M ] Oct 12 12:25:02 host ser[30289]: XLOG: xl_print_log: final buffer length 76 Oct 12 12:25:02 host ser[30289]: DEBUG : is_maxfwd_present: searching for max_forwards header Oct 12 12:25:02 host ser[30289]: parse_headers: flags=128 Oct 12 12:25:02 host ser[30289]: get_hdr_field: cseq <CSeq>: <30982> <INVITE> Oct 12 12:25:02 host ser[30289]: DEBUG: is_maxfwd_present: value = 70 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=256 Oct 12 12:25:02 host ser[30289]: DEBUG: get_hdr_body : content_length=294 Oct 12 12:25:02 host ser[30289]: found end of header Oct 12 12:25:02 host ser[30289]: find_first_route(): No Route headers found Oct 12 12:25:02 host ser[30289]: loose_route(): There is no Route HF Oct 12 12:25:02 host ser[30289]: check_via_address(xxx.xxx.xxx.aaa, xxx.xxx.xxx.aaa, 0) Oct 12 12:25:02 host ser[30289]: XLOG: xl_print_log: final buffer length 47 Oct 12 12:25:02 host ser[30289]: check_self - checking if host==us: 21==9 && [example.com] == [127.0.0.1] Oct 12 12:25:02 host ser[30289]: check_self - checking if port 5060 matches port 5060 Oct 12 12:25:02 host ser[30289]: check_self - checking if host==us: 21==13 && [example.com] == [xxx.xxx.xxx.bbb] Oct 12 12:25:02 host ser[30289]: check_self - checking if port 5060 matches port 5060 Oct 12 12:25:02 host ser[30289]: lookup(): '8661' Not found in usrloc Oct 12 12:25:02 host ser[30289]: rwrite(): Rewriting Request-URI with 'sip:8661@xxx.xxx.xxx.aaa:60125' Oct 12 12:25:02 host ser[30289]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Oct 12 12:25:02 host ser[30289]: DEBUG:get_user_script: fetching script for user &lt;8661(a)xxx.xxx.xxx.aaa&gt; Oct 12 12:25:02 host ser[30289]: query="select cpl_bin from cpl where user=&#39;8661(a)xxx.xxx.xxx.aaa&#39;&quot; Oct 12 12:25:02 host ser[30289]: DEBUG:get_user_script: we got the script len=148 Oct 12 12:25:02 host ser[30289]: DEBUG:cpl_run_script: processing CPL node Oct 12 12:25:02 host ser[30289]: DEBUG:cpl_run_script: processing location node Oct 12 12:25:02 host ser[30289]: DEBUG:cpl_run_script: processing proxy node Oct 12 12:25:02 host ser[30289]: parse_headers: flags=16777216 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=4194304 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=2097152 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=8388608 Oct 12 12:25:02 host ser[30289]: DEBUG: t_check: msg id=20 global id=7 T start=(nil) Oct 12 12:25:02 host ser[30289]: parse_headers: flags=-1 Oct 12 12:25:02 host ser[30289]: parse_headers: flags=60 Oct 12 12:25:02 host ser[30289]: t_lookup_request: start searching: hash=31907, isACK=0 Oct 12 12:25:02 host ser[30289]: DEBUG: RFC3261 transaction matching failed Oct 12 12:25:02 host ser[30289]: DEBUG: t_lookup_request: no transaction found Oct 12 12:25:02 host ser[30289]: DEBUG: t_check: msg id=20 global id=20 T end=(nil) Oct 12 12:25:02 host ser[30289]: DEBUG: t_check: msg id=20 global id=20 T start=(nil) Oct 12 12:25:02 host ser[30289]: DEBUG: t_check: T previously sought and not found Oct 12 12:25:02 host ser[30289]: DEBUG:destroy_avp_list: destroing list (nil) Oct 12 12:25:02 host ser[30289]: receive_msg: cleaning up ser.log WITH t_newtran() in INVITE Oct 12 12:30:20 host ser[30605]: DEBUG:get_user_script: we got the script len=148 Oct 12 12:30:20 host ser[30605]: DEBUG:cpl_run_script: processing CPL node Oct 12 12:30:20 host ser[30605]: DEBUG:cpl_run_script: processing location node Oct 12 12:30:20 host ser[30605]: DEBUG:cpl_run_script: processing proxy node Oct 12 12:30:20 host ser[30605]: parse_headers: flags=16777216 Oct 12 12:30:20 host ser[30605]: parse_headers: flags=4194304 Oct 12 12:30:20 host ser[30605]: parse_headers: flags=2097152 Oct 12 12:30:20 host ser[30605]: parse_headers: flags=8388608 Oct 12 12:30:20 host ser[30605]: DEBUG: t_check: msg id=1 global id=1 T start=0x402d36c0 Oct 12 12:30:20 host ser[30605]: DEBUG: t_check: T alredy found! Oct 12 12:30:20 host ser[30663]: DBG: tcp_main_loop: dead child 15 (shutting down?) Oct 12 12:30:20 host ser[30594]: Memory status (pkg): Oct 12 12:30:20 host ser[30594]: fm_status (0x80d9840): Oct 12 12:30:20 host ser[30642]: Memory status (pkg): Oct 12 12:30:20 host ser[30595]: Memory status (pkg): Oct 12 12:30:20 host ser[30575]: Memory status (pkg): Oct 12 12:30:20 host ser[30594]: heap size= 1047440 Oct 12 12:30:20 host ser[30572]: Memory status (pkg): cpl.xml <cpl> <subaction id="voicemail"> <location url="sip:8667@example.com"> <proxy/> </location> </subaction> <incoming> <location url="sip:8661@example.com"> <proxy timeout="8"> <busy> <sub ref="voicemail"/> </busy> <noanswer> <sub ref="voicemail"/> </noanswer> </proxy> </location> </incoming> </cpl> ser.cfg: debug=9 log_stderror=no check_via=no # (cmd. line: -v) dns=no # (cmd. line: -r) rev_dns=no # (cmd. line: -R) #port=5060 #children=4 fifo="/tmp/ser_fifo" alias="example.com" # ------------------ module loading ---------------------------------- # Uncomment this if you want to use SQL database loadmodule "/usr/local/lib/ser/modules/mysql.so" loadmodule "/usr/local/lib/ser/modules/sl.so" loadmodule "/usr/local/lib/ser/modules/tm.so" loadmodule "/usr/local/lib/ser/modules/rr.so" loadmodule "/usr/local/lib/ser/modules/maxfwd.so" loadmodule "/usr/local/lib/ser/modules/usrloc.so" loadmodule "/usr/local/lib/ser/modules/registrar.so" loadmodule "/usr/local/lib/ser/modules/xlog.so" loadmodule "/usr/local/lib/ser/modules/nathelper.so" loadmodule "/usr/local/lib/ser/modules/textops.so" loadmodule "/usr/local/lib/ser/modules/acc.so" loadmodule "/usr/local/lib/ser/modules/enum.so" loadmodule "/usr/local/lib/ser/modules/cpl-c.so" #loadmodule "/usr/local/lib/ser/modules/group.so" # Uncomment this if you want digest authentication # mysql.so must be loaded ! loadmodule "/usr/local/lib/ser/modules/auth.so" loadmodule "/usr/local/lib/ser/modules/auth_db.so" # ----------------- setting module-specific parameters --------------- # -- usrloc params -- modparam("usrloc", "db_mode", 2) # Uncomment this if you want to use SQL database # for persistent storage and comment the previous line #modparam("usrloc", "db_mode", 2) # -- auth params -- # Uncomment if you are using auth module # modparam("auth_db", "calculate_ha1", yes) # # If you set "calculate_ha1" parameter to yes (which true in this config), # uncomment also the following parameter) # modparam("auth_db", "password_column", "password") # -- rr params -- # add value to ;lr param to make some broken UAs happy modparam("rr", "enable_full_lr", 1) # nathelper parameters modparam("registrar", "nat_flag", 10) modparam("nathelper", "natping_interval", 10) #send udp ping every 30 seconds modparam("nathelper", "ping_nated_only", 1) # -- acc parameters -- # Sip messages that have flag 1 will be pumped to the accounting module. modparam("acc","radius_flag", 9) modparam("acc", "log_level", 1) modparam("acc", "log_flag", 1) modparam("acc", "radius_missed_flag", 2) modparam("acc", "log_fmt", "miocfst") modparam("acc", "failed_transactions" ,1) # -- tm parameters -- # Timer to give up on ringing, applies to all transactions modparam("tm","fr_inv_timer", 50) # -- group parameters -- #modparam("group","db_url", "mysql://ser:heslo@localhost/ser") # -- cpl parameters -- modparam("cpl-c","cpl_db","mysql://ser:heslo@localhost/ser") modparam("cpl-c","cpl_table","cpl") modparam("cpl-c","cpl_dtd_file","/usr/local/etc/ser/cpl-06.dtd") modparam("cpl-c","log_dir","/var/log/ser/cpl") modparam("cpl-c","proxy_recurse",3) modparam("cpl-c","nat_flag",10) # ------------------------- request routing logic ------------------- # main routing logic route{ xlog("L_ERR","---------------DEFAULT ROUTE start----------------"); xlog("L_ERR","%rm from %fu to %tu"); # initial sanity checks -- messages with # max_forwards==0, or excessively long requests if (!mf_process_maxfwd_header("10")) { sl_send_reply("483","Too Many Hops"); break; }; if ( msg:len > max_len ) { sl_send_reply("513", "Message too big"); break; }; # we record-route all messages -- to make sure that # subsequent messages will go through our proxy; that's # particularly good if upstream and downstream entities # use different transport protocol record_route(); # loose-route processing if (loose_route()) { t_relay(); break; }; # Flag all transactions for accounting. setflag(9); # Detect if our client is behind a NAT firewall, if so set flag 10. if (nat_uac_test("2")) { xlog("L_ERR","Nated client %fu"); setflag(10); #Natted FLAG force_rport(); fix_nated_contact(); #fix_nated_sdp(); append_hf("P-hint: natted UAC fixed\r\n"); } else { xlog("L_ERR","NON-Nated client %fu"); }; # If the request is not directed at us (ACKS,BYES) then relay if (!uri==myself) { xlog("L_ERR","uri not eq myself from %fu to %tu"); if(!t_relay()){ xlog("L_ERR","ERROR calling t_relay from %fu to %tu"); sl_reply_error(); } else { xlog("L_ERR","--- %rm t_relayd from %fu to %tu at end of default route"); } } if (method=="REGISTER") { xlog("L_ERR","AUTH? %fu"); # Uncomment this if you want to use digest authentication if (!www_authorize("", "subscriber")) { xlog("L_ERR","NOT AUTHed, challanging... %fu"); www_challenge("", "0"); break; }; xlog("L_ERR","AUTHed, saving location... %fu"); save("location"); cpl_process_register(); break; }; #End of REGISTER lookup("aliases"); # native SIP destinations are handled using our USRLOC DB if (!lookup("location")) { xlog("L_ERR","%rm from %fu to %tu not found in location"); prefix("+"); if (!enum_query("e164.example.com.")){ strip(1); xlog("L_ERR","%rm from %fu to %tu not found in enum"); # We pass through our routemanagment block, if the requested # uri matches a route, then it should not return to the default # route, if it does not match we will proceed to our location and # alias tables. t_on_reply("1"); route(2); break; sl_send_reply("404","User not found"); break; }; }; if (method == "INVITE") { # if ( !t_newtran()) { # sl_reply_error(); # break; # }; if ( !cpl_run_script("incoming", "force_stateful") ){ # script execution failed t_reply("500","CPL script execution failed"); break; }; t_on_reply("1"); t_on_failure("1"); force_rtp_proxy(); }; t_relay(); } # all incoming replies for t_onrepli-ed transactions enter here onreply_route[1] { xlog("L_ERR","%rm onreply_route 1 from %fu to %tu"); if(isflagset(10)){ fix_nated_contact(); #fix_nated_sdp(); force_rport(); xlog("L_ERR","%rm nated UAC fix_nated_contact and force_rport called. from %fu to %tu"); } if (!(status=~"183" || status=~"200")) break; if ( (status=~"200" || status=~"183") ) { xlog("L_ERR","%rm onreply_route(1) Forcing rtpproxy. from %fu to %tu"); force_rtp_proxy(); append_hf("P-hint: response forced to rtp proxy\r\n"); } } route[2]{ # Welcome to route[2], your friendly route managment route. This is where we look # at your requested URI and decide where to put it. URI manipulation also happens # here occasionally. Have a great route! if (uri=~"^sip:999@.*" || uri=~"^sip:911@.*") { route(3); #put emergency services route here. break; } if (uri=~"^sip:300[0-9]@.*") { route(4); break; } } #local PSTN route[3]{ xlog("L_INFO", "%rm from %fu to %tu forwarding to PSTN gateway\n"); rewritehostport("xxx.xxx.xxx.xxx:5060"); force_rtp_proxy(); if(!t_relay()){ xlog("L_ERR", "Relay to Cisco failed"); break; }; } # SEMS route[4]{ xlog("L_ERR","%rm route 4 from %fu to %tu"); revert_uri(); #Start from scratch, incase there has been changes done already rewritehostport("example.com:5061"); force_rtp_proxy(); # append_branch(); t_relay(); } failure_route[1]{ xlog("L_ERR","%rm failure_route 1 from %fu to %tu"); revert_uri(); #Start from scratch, incase there has been changes done already rewritehostport("example.com:5061"); append_branch(); t_relay(); }