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

Thu Jun 24 13:33:18 CEST 2004

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 <6131 at 10.0.60.2>
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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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:

>Hi Bogdan,
>
>I've download everything from CVS head, compile it and try to run the
>SER with the basic config file (no database, authentication and cpl support), but I get the following error message in my syslog
>
>Jun  8 15:46:44 sipproxy1 ser: parse error (1,1-2): parse error Jun  8
>15:46:44 sipproxy1 ser: ERROR: cfg. parser: unexpected EOF in unclosed 
>string
>
>... and on the command line together with the whole ser.cfg content
>
>ERROR: bad config file (1 errors)
>
>I leave the ser.cfg unchanged because I want to try out the new
>installation first. After getting these error message I check other 
>versions from CVS (v_0_8_13-dev-29, v_0_8_13dev-t16 ...) but the 
>problem is the same as before. Compilation ist no problem. Which CVS 
>version is the best for me to download? Many thanks for your help.
>
>Regards,
>Oliver
>  
>