search

OpenSIPS / opensips

OpenSIPS is a GPL implementation of a multi-functionality SIP Server that targets to deliver a high-level technical solution (performance, security and quality) to be used in professional SIP server platforms.
https://opensips.org
Other
1.27k stars 578 forks source link

mi_xmlrpc_ng suppresses \r\n #537

Closed staskobzar closed 9 years ago

staskobzar commented 9 years ago

Hello,

I have a bug with mi_xmlrpc_ng module when using tm module MI function t_uac_dlg. I am using this module to restart phones and manage MWI.

Here is the Python script example to reproduce the problem (I have the same problem with ruby xmlrpc client):

#!/usr/bin/env python

import xmlrpclib
opensips = xmlrpclib.ServerProxy('http://10.130.8.20:8000/RPC2')
headers="From: <sip:7714@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04\r\nTo: <sip:7714@voip.etsmtl.ca>\r\nEvent: check-sync\r\n"
opensips.t_uac_dlg('NOTIFY', 'sip:7714@campus.voip.etsmtl.ca', ".", ".", headers)

When I run the script, opensips generates following NOTIFY packet (ngrep capture):

NOTIFY sip:7714@10.130.8.209 SIP/2.0.
Via: SIP/2.0/UDP 10.130.8.20:5060;branch=z9hG4bK43ec.c13af041.0.
Via: SIP/2.0/UDP 10.130.8.20:5060;branch=z9hG4bK43ec.b13af041.0.
To: sip:7714@voip.etsmtl.ca.
From: <sip:7714@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04.
CSeq: 10 NOTIFY.
Call-ID: 1c1bbe0b4e2c0d26-27166@10.130.8.20.
Max-Forwards: 69.
Content-Length: 0.
Server: ETS voip router01.
Event: check-sync
.

There is a terminating character "." missing in header Event: check-sync. Some phones (Avaya) do not accept the packet because of that.

When I run the same command via FIFO:

opensipsctl fifo t_uac_dlg NOTIFY sip:7714@campus.voip.etsmtl.ca . . '"From: <sip:7714@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04\r\nTo: <sip:7714@voip.etsmtl.ca>\r\nEvent: check-sync\r\n"'

The packet looks fine and phones accept it:

NOTIFY sip:7714@10.130.8.209 SIP/2.0.
Via: SIP/2.0/UDP 10.130.8.20:5060;branch=z9hG4bKb31f.4656abe3.0.
Via: SIP/2.0/UDP 10.130.8.20:5060;branch=z9hG4bKb31f.3656abe3.0.
To: sip:7714@voip.etsmtl.ca.
From: <sip:7714@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04.
CSeq: 10 NOTIFY.
Call-ID: 1c1bbe0b4e2c0d1f-27167@10.130.8.20.
Max-Forwards: 69.
Content-Length: 0.
Server: ETS voip router01.
Event: check-sync.
.

The same problem I have with MWI packets (message-summary).

OpenSIPS version: version: opensips 1.11.5-notls (x86_64/linux) flags: STATS: On, USE_IPV6, USE_TCP, DISABLE_NAGLE, USE_MCAST, 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 poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. git revision: 980b680 main.c compiled on 16:04:51 Jun 1 2015 with gcc 4.4.7

Thank you

bogdan-iancu commented 9 years ago

@staskobzar, I'm not able to reproduce the double VIA problem. I'm using the python script you provided together with the opensips default cfg. Indeed, the NOTIFY is sent out to another SIP server (is not looping).

Using latest 1.11: version: opensips 1.11.5-notls (x86_64/linux) flags: STATS: On, USE_IPV6, USE_TCP, DISABLE_NAGLE, USE_MCAST, 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 poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. git revision: e72d1ef main.c compiled on 16:24:30 Jun 4 2015 with gcc 4.8

Now, about the missing \r, it seems to be the fault of libxml2, of the xml standard actually: http://www.w3.org/TR/REC-xml/#sec-line-ends Any \r\n is converted to \n :( ....

I tried to escape the the \r, but is not decoded ...we need to check with @ovidiusas on this.

Regards, Bogdan

staskobzar commented 9 years ago

@bogdan-iancu This problem here is not about the double Via. This issue is about a missing terminating character in the header Event after value "check-sync"

Please, see the SIP packets in the description I got with ngrep. The first one has a problem and another one does not.

Could you reproduce this one?

bogdan-iancu commented 9 years ago

yes, I can reproduce that issue - and see the end of the prev post :

Now, about the missing \r, it seems to be the fault of libxml2, of the xml standard actually: http://www.w3.org/TR/REC-xml/#sec-line-ends Any \r\n is converted to \n :( .... I tried to escape the the \r, but is not decoded ...we need to check with @ovidiusas on this.
staskobzar commented 9 years ago

@bogdan-iancu Thank you, Bogdan. Also I tried to put many "\n" after Event header and seems like they are all trimmed. The same thing happens to my body of message-summary NOTIFY.

bogdan-iancu commented 9 years ago

yeah, that is libxml2 doing that....I asked @ovidiusas is he knows any workarounds...

ovidiusas commented 9 years ago

@staskobzar please re-test on the latest trunk. Make sure that you are at commit 8450630617b2504ffdc4089f2500a26b4187e078

You will need to escape at least "\r" with "&#13;" You may or may not escape "\n" with "&#10;"

#!/usr/bin/env python

import xmlrpclib
opensips = xmlrpclib.ServerProxy('http://10.130.8.20:8000/RPC2')
headers="From: <sip:7714@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04&#13;\nTo: <sip:7714@voip.etsmtl.ca>&#13;&#10;Event: check-sync&#13;\n"
opensips.t_uac_dlg('NOTIFY', 'sip:7714@campus.voip.etsmtl.ca', ".", ".", headers)
staskobzar commented 9 years ago

@ovidiusas sorry, still have issues.

# opensips -V
version: opensips 1.11.5-notls (x86_64/linux)
flags: STATS: On, USE_IPV6, USE_TCP, DISABLE_NAGLE, USE_MCAST, 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
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
git revision: ca2711a
main.c compiled on 15:06:08 Jun 11 2015 with gcc 4.4.7

When I escape "\r" with "&#13;", like this: 

headers="From: <sip:7010@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04&#13;\nTo: <sip:7010@voip.etsmtl.ca>&#13;\nEvent: check-sync&#13;\n"

I have error:

Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x19c0180, url=/RPC2, method=POST, versio=HTTP/1.0, upload_data[0]=(nil), *con_cls=(nil)
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: running MHD_create_post_processor
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x19c0180, url=/RPC2, method=POST, versio=HTTP/1.0, upload_data[546]=0x19c7054, *con_cls=0x7fa1ea364d18
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: NOT a regular POST :o)
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:getConnectionHeader: Content-Type=text/xml
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:getConnectionHeader: Content-Length=546
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: got ContentType [1] with len [546]: <?xml version='1.0'?>#012<methodCall>#012<methodName>t_uac_dlg</methodName>#012<params>#012<param>#012<value><string>NOTIFY</string></value>#012</param>#012<param>#012<value><string>sip:7010@campus.voip.etsmtl.ca</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>From: &lt;sip:7010@voip.etsmtl.ca&gt;;tag=8755a8d01aa27e903a6f4ccaf393f04&amp;#13;#012To: &lt;sip:7010@voip.etsmtl.ca&gt;&amp;#13;#012Event: check-sync&amp;#13;#012</string></value>#012</param>#012</params>#012</methodCall>#012\n
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x19c0180, url=/RPC2, method=POST, versio=HTTP/1.0, upload_data[0]=(nil), *con_cls=0x7fa1ea364d18
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: normalised_url=[]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_answer_to_connection: START *** cls=(nil), connection=0x19c0180, url=, method=POST, versio=HTTP/1.0, upload_data[0]=(nil), *con_cls=0x7fa1ea364d50
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:httpd_get_val: DATA=[0x7fa1ea364d98] [0x7fa1ea364db8][0x7fa1ea364db9] [1]->[<?xml version='1.0'?>#012<methodCall>#012<methodName>t_uac_dlg</methodName>#012<params>#012<param>#012<value><string>NOTIFY</string></value>#012</param>#012<param>#012<value><string>sip:7010@campus.voip.etsmtl.ca</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>From: &lt;sip:7010@voip.etsmtl.ca&gt;;tag=8755a8d01aa27e903a6f4ccaf393f04&amp;#13;#012To: &lt;sip:7010@voip.etsmtl.ca&gt;&amp;#13;#012Event: check-sync&amp;#13;#012</string></value>#012</param>#012</params>#012</methodCall>#012]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got methodName=t_uac_dlg
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_build_async_handler: hdl [0x7fa1c2b40210], hdl->param [0x7fa1c2b40228], *hdl->param [(nil)] mi_xmlrpc_http_lock=[0x7fa1c29b1880]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [NOTIFY]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [sip:7010@campus.voip.etsmtl.ca]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [.]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [.]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [From: <sip:7010@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04&#13;#012To: <sip:7010@voip.etsmtl.ca>&#13;#012Event: check-sync&#13;#012]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:parse_headers: flags=ffffffffffffffff
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:parse_to: spitting out [&] in status 10
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: ERROR:core:get_hdr_field: bad to header
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:set_err_info: ec: 1, el: 3, ei: 'error parsing To header'
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:get_hdr_field: error exit
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: INFO:core:parse_headers: bad header field
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got mi_rpl=[0x7fa1ea364ff8]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_answer_to_connection: building on page [0x7fa1ea2e4d00:0]
Jun 11 15:35:36 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_build_header: return code: 400

When I escape both \r and \n with "&#13;&#10;" , like this:

headers="From: <sip:7010@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04&#13;&#10;To: <sip:7010@voip.etsmtl.ca>&#13;&#10;Event: check-sync&#13;&#10;"

I have this in the logs:

Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: got ContentType [1] with len [570]: <?xml version='1.0'?>#012<methodCall>#012<methodName>t_uac_dlg</methodName>#012<params>#012<param>#012<value><string>NOTIFY</string></value>#012</param>#012<param>#012<value><string>sip:7010@campus.voip.etsmtl.ca</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>From: &lt;sip:7010@voip.etsmtl.ca&gt;;tag=8755a8d01aa27e903a6f4ccaf393f04&amp;#13;&amp;#10;To: &lt;sip:7010@voip.etsmtl.ca&gt;&amp;#13;&amp;#10;Event: check-sync&amp;#13;&amp;#10;</string></value>#012</param>#012</params>#012</methodCall>#012\n
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x19c0180, url=/RPC2, method=POST, versio=HTTP/1.0, upload_data[0]=(nil), *con_cls=0x7fa1ea364d18
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: normalised_url=[]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_answer_to_connection: START *** cls=(nil), connection=0x19c0180, url=, method=POST, versio=HTTP/1.0, upload_data[0]=(nil), *con_cls=0x7fa1ea364d50
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:httpd_get_val: DATA=[0x7fa1ea365648] [0x7fa1ea365668][0x7fa1ea365669] [1]->[<?xml version='1.0'?>#012<methodCall>#012<methodName>t_uac_dlg</methodName>#012<params>#012<param>#012<value><string>NOTIFY</string></value>#012</param>#012<param>#012<value><string>sip:7010@campus.voip.etsmtl.ca</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>.</string></value>#012</param>#012<param>#012<value><string>From: &lt;sip:7010@voip.etsmtl.ca&gt;;tag=8755a8d01aa27e903a6f4ccaf393f04&amp;#13;&amp;#10;To: &lt;sip:7010@voip.etsmtl.ca&gt;&amp;#13;&amp;#10;Event: check-sync&amp;#13;&amp;#10;</string></value>#012</param>#012</params>#012</methodCall>#012]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got methodName=t_uac_dlg
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_build_async_handler: hdl [0x7fa1c2bf7998], hdl->param [0x7fa1c2bf79b0], *hdl->param [(nil)] mi_xmlrpc_http_lock=[0x7fa1c29b1880]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [NOTIFY]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [sip:7010@campus.voip.etsmtl.ca]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [.]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [.]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got string param [From: <sip:7010@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04&#13;&#10;To: <sip:7010@voip.etsmtl.ca>&#13;&#10;Event: check-sync&#13;&#10;]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:parse_headers: flags=ffffffffffffffff
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: ERROR:core:get_hdr_field: bad body for <From: <sip:7010@voip.etsmtl.ca>;tag=8755a8d01aa27e903a6f4ccaf393f04&#13;&#10;To: <sip:7010@voip.etsmtl.ca>&#13;&#10;Event: check-sync&#13;&#10;>(4)
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:set_err_info: ec: 1, el: 3, ei: 'error parsing headers'
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:core:get_hdr_field: error exit
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: INFO:core:parse_headers: bad header field
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_run_mi_cmd: got mi_rpl=[0x7fa1ea365318]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_answer_to_connection: building on page [0x7fa1ea2e4d00:0]
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:mi_xmlrpc_ng:mi_xmlrpc_http_build_header: return code: 400
Jun 11 15:44:02 grannos01 /opt/opensips/sbin/opensips[19851]: DBG:httpd:answer_to_connection: MHD_create_response_from_data [0x7fa1ea2e4d00:147]
ovidiusas commented 9 years ago

Of course you have issues. I asked you to test on trunk, not on 1.11. Please test on trunk, report back and then I will backport.

staskobzar commented 9 years ago

@ovidiusas it works. thank you.

ovidiusas commented 9 years ago

@staskobzar Thanks for testing it!