Re: [Serusers] CPL-C and call forward on busy or no answer

Hi Bogdan, I solved the problem with SER startup. The reason was that I download the CVS head onto my notebook and copy it via ftp to the linux server. After downloading CVS head directly onto the linux server, compiling and installing it SER starts up without any error message. But I have still the problem with call forwarding on busy or no answer. Inserting log information into my CPL script I can reproduce that SER is never processing the <busy> or <noanswer> tag and the following tags. I try out the example script from the current IETF CPL draft for Call Forward Busy/No Answer in the following scenario: 6131 forwards calls to 613 if busy -> 6131 has an active session with 614 -> 612 calls 6131 -> 6131 is busy and SER should invite 613 After uploading the CPL script for 6131 the caller 614 cannot reach 6131 and the syslog represents the attached error message. Can you identify any mistake I've done in my configuration? Many thanks. Best Regards, Oliver Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: cpl: start script processing now Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:get_user_script: fetching script for user &lt;6131(a)10.0.60.2&gt; Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:get_user_script: we got the script len=90 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=16777216 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=4194304 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=33554432 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=2097152 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=8388608 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_newtran: msg id=2 , global msg id=0 , T on entrance=0xffffffff Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=-1 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=60 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: t_lookup_request: start searching: hash=57364, isACK=0 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: proceeding to pre-RFC3261 transaction matching Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_lookup_request: no transaction found Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_check: msg id=2 global id=2 T start=0x402ef820 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_check: T alredy found! Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_c:cpl_proxy_to_loc_set: rewriting Request-URI with <sip:6131@10.0.60.2> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_newtran: msg id=2 , global msg id=2 , T on entrance=0x402ef820 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: ERROR: t_newtran: transaction already in process 0x402ef820 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: parse_headers: flags=-1 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: check_via_address(10.0.61.4, 10.0.61.4, 0) Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: ERROR: sl_reply_error used: I'm terribly sorry, server error occured (1/SL) Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_check: msg id=2 global id=2 T start=0x402ef820 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: t_check: T alredy found! Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG: mk_proxy: doing DNS lookup... Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: check_via_address(10.0.61.4, 10.0.61.4, 0) Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: SIP Request: Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: method: <INVITE> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: uri: <sip:6131@10.0.60.2> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: version: <SIP/2.0> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: parse_headers: flags=1 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: Found param type 232, <branch> = <z9hG4bK410e.de7825a6.0>; state=16 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: end of header reached, state=5 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: parse_headers: Via found, flags=1 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: parse_headers: this is the first via Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: After parse_msg... Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: preparing to run routing scripts... Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG : is_maxfwd_present: max_forward header already found! Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG: is_maxfwd_present: value = 10 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: parse_headers: flags=8 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: end of header reached, state=5 sipproxy1:/var/log # less messages | grep cpl Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: cpl: start script processing now Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_c:cpl_proxy_to_loc_set: rewriting Request-URI with <sip:6131@10.0.60.2> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: cpl: start script processing now Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl_c:cpl_proxy_to_loc_set: rewriting Request-URI with <sip:6131@10.0.60.2> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2094]: DEBUG:cpl-c:negativ_reply: ------------------------------> ---------------------------------> negativ reply receive Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2094]: DEBUG:cpl-c:failed_reply:final_reply: got a final 500 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2094]: DEBUG:cpl-c:final_reply: code=500 --------------> --------------------------> final reply received Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: cpl: start script processing now Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl_c:cpl_proxy_to_loc_set: rewriting Request-URI with <sip:6131@10.0.60.2> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2097]: DEBUG:cpl-c:negativ_reply: ------------------------------> ---------------------------------> negativ reply receive Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2097]: DEBUG:cpl-c:failed_reply:final_reply: got a final 500 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2097]: DEBUG:cpl-c:final_reply: code=500 --------------> --------------------------> final reply received Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: cpl: start script processing now Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2091]: DEBUG:cpl_c:cpl_proxy_to_loc_set: rewriting Request-URI with <sip:6131@10.0.60.2> Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_c:cpl_run_script: done for the moment; waiting after signaling! Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:negativ_reply: ------------------------------> ---------------------------------> negativ reply receive Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:failed_reply:final_reply: got a final 500 Jun 24 11:36:22 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:final_reply: code=500 --------------> --------------------------> final reply received Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2088]: DEBUG:cpl_c:cpl_run_script: done for the moment; waiting after signaling! Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: cpl: start script processing now Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_c:cpl_proxy_to_loc_set: rewriting Request-URI with <sip:6131@10.0.60.2> Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl_c:cpl_run_script: done for the moment; waiting after signaling! Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: cpl: start script processing now Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: DEBUG:cpl-c:get_dest_user: tring to get user from new_uri Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: DEBUG:cpl-c:get_dest_user: tring to get user from R_uri Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: DEBUG:cpl_run_script: processing CPL node Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: DEBUG:cpl_run_script: processing location node Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: DEBUG:cpl_run_script: processing proxy node Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: ERROR:cpl-c:run_proxy: processed INVITE is a retransmission! Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2085]: DEBUG:cpl_c:cpl_run_script: script interpretation done! Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl-c:negativ_reply: ------------------------------> ---------------------------------> negativ reply receive Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl-c:failed_reply:final_reply: got a final 500 Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2100]: DEBUG:cpl-c:final_reply: code=500 --------------> --------------------------> final reply received Jun 24 11:36:23 sipproxy1 /usr/local/sbin/ser[2078]: DEBUG:cpl_c:cpl_run_script: done for the moment; waiting after signaling! Bogdan-Andrei IANCU [mailto:iancu@fokus.fraunhofer.de] wrote Hi Oliver, There is nothing wrong with SER and you should use the CVS head version. The problem is in your configuration file - looks like you have some strange string (missing " ?) on the first line. Bogdan Brinker, Oliver wrote: