22 Jan
2020
22 Jan
'20
5:45 p.m.
Hello,
do you have http_reply_parse=yes ?
The error is from topos catching the http reply being sent out and
trying to handle it.
Cheers,
Daniel
On 22.01.20 12:34, Nuno Ferreira wrote:
Hi,
I'm using kamailio 5.2.4 (topos enabled) and HTTP 1.1
Here's ngrep output:
####
T 127.0.0.1:32322 <http://127.0.0.1:32322> -> 127.0.0.1:8000
<http://127.0.0.1:8000> [AP]
POST /RPC HTTP/1.1.
User-Agent: curl/7.29.0. <http://7.29.0.>
Host: 127.0.0.1:8000 <http://127.0.0.1:8000>.
Accept: */*.
Content-Type: application/json.
Content-Length: 75.
.
{"id": 1, "jsonrpc": "2.0", "method":
"pl.list", "params":
["pipe_INVITE"]}
##
T 127.0.0.1:8000 <http://127.0.0.1:8000> -> 127.0.0.1:32322
<http://127.0.0.1:32322> [AP]
HTTP/1.1 400 Unknown pipe id pipe_INVITE.
Sia: SIP/2.0/TCP 127.0.0.1:32322 <http://127.0.0.1:32322>.
Content-Type: application/json.
Server: SIP Proxy (v1.1.0-360).
Content-Length: 105.
.
{
."jsonrpc":."2.0",
."error":.{
.."code":.400,
.."message":."Unknown pipe id pipe_INVITE"
.},
."id":.1
}
####
Debug logs from kamailio:
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection:
127.0.0.1
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/tcp_main.c:999]: tcpconn_new(): on port 32304, type 2
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/tcp_main.c:1309]: tcpconn_add(): hashes: 3634:3788:434, 41
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa85ba0, 39,
2, 0x7f87c726b9e0), fd_no=29
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa85ba0, 39,
-1, 0x0) fd_no=30 called
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/tcp_main.c:3878]: send2child(): selected tcp worker idx:0
proc:19 pid:18996 for activity on [tcp:127.0.0.1:8000
<http://127.0.0.1:8000>], 0x7f87c726b9e0
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:1759]: handle_io(): received n=8 con=0x7f87c726b9e0,
fd=11
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:1560]: tcp_read_req(): content-length=75
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:612]: parse_msg(): method: <POST>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:614]: parse_msg(): uri: </RPC>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:616]: parse_msg(): version: <HTTP/1.1>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:185]: get_hdr_field(): content_length=75
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: topos
[topos_mod.c:269]: tps_prepare_msg(): non sip request message
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:612]: parse_msg(): method: <POST>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:614]: parse_msg(): uri: </RPC>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:616]: parse_msg(): version: <HTTP/1.1>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:185]: get_hdr_field(): content_length=75
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/receive.c:246]: receive_msg(): --- received sip message -
request - call-id: [] - cseq: []
Jan 22 11:20:50 proxy1 kamailio[18996]: [328B blob data]
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:612]: parse_msg(): method: <POST>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:614]: parse_msg(): uri: </RPC>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:616]: parse_msg(): version: <HTTP/1.1>
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/parse_via.c:2639]: parse_via(): end of header reached,
state=5
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:500]: parse_headers(): this is the first via
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:185]: get_hdr_field(): content_length=75
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
Jan 22 11:20:50 proxy1 kamailio[18996]: ERROR: pipelimit
[pl_ht.c:519]: rpc_pl_list(): no pipe: pipe_INVITE
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: jsonrpcs
[jsonrpcs_mod.c:423]: jsonrpc_send(): sending response with body:
0x7ffce2bc6810 - 400 Unknown pipe id pipe_INVITE
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: xhttp
[xhttp_mod.c:429]: xhttp_send_reply(): response with content-type:
application/json
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: xhttp
[xhttp_mod.c:439]: xhttp_send_reply(): response with body: {
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: xhttp
[xhttp_mod.c:441]: xhttp_send_reply(): sending out response: 400
Unknown pipe id pipe_INVITE
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/msg_translator.c:162]: check_via_address(): (127.0.0.1,
127.0.0.1, 0)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: sl [sl_funcs.c:500]:
sl_run_callbacks(): execute callback for event type 1
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: siptrace
[siptrace.c:1369]: trace_sl_onreply_out(): trace off...
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line:
bad request first line
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 20:
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
HTTP/1.1 400 Unknown
Jan 22 11:20:50 proxy1 kamailio[18996]: ERROR: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line:
bad message (offset: 20)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/parser/msg_parser.c:606]: parse_msg(): invalid message
Jan 22 11:20:50 proxy1 kamailio[18996]: [456B blob data]
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: topos
[topos_mod.c:263]: tps_prepare_msg(): outbuf buffer parsing failed!
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_main.c:2226]: tcpconn_send_put(): send from reader (18996
(19)), reusing fd
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_main.c:2460]: tcpconn_do_send(): sending...
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_main.c:2494]: tcpconn_do_send(): after real write: c=
0x7f87c726b9e0 n=278 fd=11
Jan 22 11:20:50 proxy1 kamailio[18996]: [431B blob data]
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/xavp.c:495]: xavp_destroy_list(): destroying xavp list (nil)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/receive.c:458]: receive_msg(): cleaning up
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xaf1560, 11,
2, 0x7f87c726b9e0), fd_no=1
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:198]: tcp_emit_closed_event(): TCP closed event
creation triggered (reason: 0)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:206]: tcp_emit_closed_event(): no callback
registering for handling TCP closed event
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:318]: tcp_read_data(): EOF on 0x7f87c726b9e0, FD 11
([127.0.0.1]:32304 ->
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:319]: tcp_read_data(): -> [127.0.0.1]:8000)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:1527]: tcp_read_req(): EOF
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xaf1560, 11,
-1, 0x10) fd_no=2 called
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:1683]: release_tcpconn(): releasing con
0x7f87c726b9e0, state -1, fd=11, id=4137 ([127.0.0.1]:32304 ->
[127.0.0.1]:8000)
Jan 22 11:20:50 proxy1 kamailio[18996]: DEBUG: <core>
[core/tcp_read.c:1684]: release_tcpconn(): extra_data (nil)
Jan 22 11:20:50 proxy1 kamailio[19000]: DEBUG: <core>
[core/tcp_main.c:3308]: handle_tcp_child(): reader response=
7f87c726b9e0, -1 from 0
Regards,
Nuno
On Wed, Jan 22, 2020 at 7:19 AM Daniel-Constantin Mierla
<miconda(a)gmail.com <mailto:miconda@gmail.com>> wrote:
Hello,
what version of kamailio are you using and what http version is
curl using? Can you paste here the http request taken with ngrep
from the network?
Cheers,
Daniel
On 21.01.20 19:00, Nuno Ferreira wrote:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
Hi Daniel,
There's no other traffic than the HTTP requests.
This comment in src/core/parser/parse_fline.c 99 - 113, caugh my
attention:
} else if (http_reply_parse != 0 &&
(*tmp=='H' || *tmp=='h') &&
/* 'HTTP/1.' */
strncasecmp( tmp+1, HTTP_VERSION+1, HTTP_VERSION_LEN-1)==0 &&
/* [0|1] */
((*(tmp+HTTP_VERSION_LEN)=='0') || (*(tmp+HTTP_VERSION_LEN)=='1'))
&&
(*(tmp+HTTP_VERSION_LEN+1)==' ') ){
*/* ugly hack to be able to route http replies
* Note: - the http reply must have a via
* - the message is marked as SIP_REPLY (ugly)*
*/
fl->type=SIP_REPLY;
fl->flags|=FLINE_FLAG_PROTO_HTTP;
fl->u.reply.version.len=HTTP_VERSION_LEN+1 /*include last digit*/;
tmp=buffer+HTTP_VERSION_LEN+1 /* last digit */;
and later in error1:
error1:
fl->type=SIP_INVALID;
LOG((core, core_cfg, corelog), "parse_first_line: bad message
(offset: %d)\n", offset);
/* skip line */
nl=eat_line(buffer,len);
return nl;
So that log line can be conditional if FLINE_FLAG_PROTO_HTTP is
not part of fl->flags.
I just don't know where the "[466B blob data]" is getting printed
On Tue, Jan 21, 2020 at 4:30 PM Daniel-Constantin Mierla
<miconda(a)gmail.com <mailto:miconda@gmail.com>> wrote:
Hello,
as I said, watch the traffic on port 8000 with ngrep or some
other network sniffer to see what data comes there. You can
also start kamailio with debug=3 in config, more debug logs
should be printed to syslog to get the context of what is
processed at that time.
Cheers,
Daniel
On 21.01.20 16:31, Nuno Ferreira wrote:
--
Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
<http://www.asipto.com>
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
<http://www.kamailioworld.com>
*Confidentiality Notice: The information contained in this e-mail and any
attachments may be confidential. If you are not an intended recipient, you
are hereby notified that any dissemination, distribution or copying of
this
e-mail is strictly prohibited. If you have received this e-mail in error,
please notify the sender and permanently delete the e-mail and any
attachments immediately. You should not retain, copy or use this e-mail or
any attachment for any purpose, nor disclose all or any part of the
contents to any other person. Thank you.* Hi Daniel,
Thanks for your feedback.
I have a dedicated listen directive for JSONRPC
listen = 127.0.0.1:8000 <http://127.0.0.1:8000>
and then an event_route for it:
event_route[xhttp:request] {
if ($Rp != 8000) {
xhttp_reply("403", "Forbidden",
"text/html",
"<html><body>Forbidden</body></html>");
exit;
}
if ($hu =~ "^/RPC") {
jsonrpc_dispatch();
} else {
xhttp_reply("200", "OK", "text/html",
"<html><body>Wrong URL $hu</body></html>");
}
return;
}
So, I'm already doing HTTP traffic only in port 8000.
The interesting part is that if I use kamcmd pl.list
pipe_INVITE, only the first log line is printed. Using curl,
I see the other 2 logs all the time.
Thank you
On Tue, Jan 21, 2020 at 2:45 PM Daniel-Constantin Mierla
<miconda(a)gmail.com <mailto:miconda@gmail.com>> wrote:
Hello,
can you want the traffic on port 8000 and see if there
is no "unexpected" traffic there? There should be no
error message for parsing the first line of an HTTP request.
The error message related the missing pipe can be made
debug.
Cheers,
Daniel
On 21.01.20 15:34, Nuno Ferreira wrote:
--
Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
<http://www.asipto.com>
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
<http://www.kamailioworld.com>
*Confidentiality Notice: The information contained in this e-mail
and any
attachments may be confidential. If you are not an intended
recipient, you
are hereby notified that any dissemination, distribution or
copying of this
e-mail is strictly prohibited. If you have received this e-mail
in error,
please notify the sender and permanently delete the e-mail and any
attachments immediately. You should not retain, copy or use this
e-mail or
any attachment for any purpose, nor disclose all or any part of the
contents to any other person. Thank you.* Hi all,
I'm using pipelimit with the "clean_unused" option to
get rid of pipes that are not used for quite some time.
At the same time we are monitoring pipelimit with a
jsonrpc call similar to:
# curl --header 'Content-Type: application/json'
--data-binary '{"id": 1, "jsonrpc": "2.0",
"method":
"pl.list", "params": ["pipe_INVITE"]'
http://127.0.0.1:8000/RPC
Reply:
{
"jsonrpc": "2.0",
"error": {
"code": 400,
"message": "Unknown pipe id pipe_INVITE"
},
"id": 1
}
The above reply is valid because the pipe_INVITE was
not loaded yet, but the request makes kamailio to log
the following log messages:
Jan 20 11:21:48 proxy1 kamailio[24474]: ERROR:
pipelimit [pl_ht.c:519]: rpc_pl_list(): no pipe:
pipe_INVITE
Jan 20 11:21:48 proxy1 kamailio[24474]: ERROR: <core>
[core/parser/parse_fline.c:262]: parse_first_line():
parse_first_line: bad message (offset: 20)
Jan 20 11:21:48 proxy1 kamailio[24474]: [466B blob data]
Since the monitoring system does periodic requests,
those log lines get a bit annoying and fill the log
with ERROR messages that aren't really errors.
IMHO the first log line should be converted to DEBUG
instead of ERROR, but I have some doubts about the one
from parse_fline.c:262. parse_first_line() is used to
process both SIP and HTTP. It makes sense to log ERROR
if SIP but not in the case of HTTP...
Regarding the "[466B blob data]" I really don't know
from where it's coming from.
I can submit a PR, but I would like to have first some
feedback from you.
Thank you,
Nuno
*Confidentiality Notice: The information contained in
this e-mail and any
attachments may be confidential. If you are not an
intended recipient, you
are hereby notified that any dissemination,
distribution or copying of this
e-mail is strictly prohibited. If you have received
this e-mail in error,
please notify the sender and permanently delete the
e-mail and any
attachments immediately. You should not retain, copy or
use this e-mail or
any attachment for any purpose, nor disclose all or any
part of the
contents to any other person. Thank you.*
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org <mailto:sr-users@lists.kamailio.org>
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
<http://www.asipto.com>
Kamailio World Conference - April 27-29, 2020, in Berlin --
www.kamailioworld.com <http://www.kamailioworld.com>
*Confidentiality Notice: The information contained in this
e-mail and any
attachments may be confidential. If you are not an intended
recipient, you
are hereby notified that any dissemination, distribution or
copying of this
e-mail is strictly prohibited. If you have received this
e-mail in error,
please notify the sender and permanently delete the e-mail
and any
attachments immediately. You should not retain, copy or use
this e-mail or
any attachment for any purpose, nor disclose all or any part
of the
contents to any other person. Thank you.*