21 Jan
2020
21 Jan
'20
5:34 p.m.
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.*
21 Jan
21 Jan
5:45 p.m.
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:
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
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
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
6:31 p.m.
Hi Daniel,
Thanks for your feedback.
I have a dedicated listen directive for JSONRPC
listen = 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>
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:
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
Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
--
*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.*
7:30 p.m.
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:
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
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 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.*
9 p.m.
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>
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:
Hi Daniel,
Thanks for your feedback.
I have a dedicated listen directive for JSONRPC
listen = 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> wrote:
--
*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.*
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:
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
Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
*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.*
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
22 Jan
22 Jan
10:18 a.m.
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:
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
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,
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.*
2:34 p.m.
Hi,
I'm using kamailio 5.2.4 (topos enabled) and HTTP 1.1
Here's ngrep output:
####
T 127.0.0.1:32322 -> 127.0.0.1:8000 [AP]
POST /RPC HTTP/1.1.
User-Agent: curl/7.29.0.
Host: 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 -> 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.
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], 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>
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:
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> wrote:
--
*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.*
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:
Hi Daniel,
Thanks for your feedback.
I have a dedicated listen directive for JSONRPC
listen = 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> wrote:
*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.*
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
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:
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
Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
*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.*
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
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.*
6:03 p.m.
Hi,
http_reply_parse is not present in the configs. I've explicitly set it as
"no" and the result is the same. If I set it as "yes", topos complains
like
this:
Jan 22 15:00:10 proxy1 kamailio[29316]: ERROR: topos [topos_mod.c:282]:
tps_prepare_msg(): cannot parse cseq header
Thank you,
Nuno
On Wed, Jan 22, 2020 at 2:45 PM Daniel-Constantin Mierla <miconda(a)gmail.com>
wrote:
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 -> 127.0.0.1:8000 [AP]
POST /RPC HTTP/1.1.
User-Agent: curl/7.29.0.
Host: 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 -> 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.
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], 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> wrote:
--
*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.*
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:
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> wrote:
*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.*
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
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:
Hi Daniel,
Thanks for your feedback.
I have a dedicated listen directive for JSONRPC
listen = 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> wrote:
*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.*
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
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:
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
Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
*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.*
--
Daniel-Constantin Mierla -- www.asipto.comwww.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
10 Feb
10 Feb
8:16 p.m.
Hi Daniel,
I noticed that you already moved the ERR log to DBG in the pipe limit
module. Did you have the opportunity to look at the other 2 errors?
Glad if I can help, but I will need some directions especially about
the place where the "[466B blob data]" is getting printed.
Thanks,
Nuno
On Wed, Jan 22, 2020 at 3:03 PM Nuno Ferreira <nferreira(a)fuze.com> wrote:
Hi,
http_reply_parse is not present in the configs. I've explicitly set it as
"no" and the result is the same. If I set it as "yes", topos
complains like
this:
Jan 22 15:00:10 proxy1 kamailio[29316]: ERROR: topos [topos_mod.c:282]:
tps_prepare_msg(): cannot parse cseq header
Thank you,
Nuno
On Wed, Jan 22, 2020 at 2:45 PM Daniel-Constantin Mierla <
miconda(a)gmail.com> wrote:
> 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 -> 127.0.0.1:8000 [AP]
> POST /RPC HTTP/1.1.
> User-Agent: curl/7.29.0.
> Host: 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 -> 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.
> 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], 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> 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:
>>
>> 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> 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:
>>>
>>> Hi Daniel,
>>>
>>> Thanks for your feedback.
>>> I have a dedicated listen directive for JSONRPC
>>> listen = 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> 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:
>>>>
>>>> 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
Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>
>>>> --
>>>> Daniel-Constantin Mierla -- www.asipto.comwww.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
>>>>
>>>>
>>>
>>> *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.*
>>>
>>> --
>>> Daniel-Constantin Mierla -- www.asipto.comwww.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
>>>
>>>
>>
>> *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.*
>>
>> --
>> Daniel-Constantin Mierla -- www.asipto.comwww.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
>>
>>
>
> *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.*
>
> --
> Daniel-Constantin Mierla -- www.asipto.comwww.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
>
>
--
*Nuno Ferreira* | Architect, CoreUC | nferreira(a)fuze.com | +351 308805903
Rua Carlos Silva Melo Guimarães 23, 3800-126 Aveiro, Portugal
<http://www.facebook.com/fuze> <http://www.twitter.com/fuze>
<https://www.linkedin.com/company/fuze-inc>
<https://plus.google.com/110150232345018024360>
<https://www.instagram.com/fuze_hq/>
<http://www.fuze.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.*
20 Mar
20 Mar
10:16 p.m.
add -a option to journalctl
On Mon, Feb 10, 2020 at 6:19 PM Nuno Ferreira <nferreira(a)fuze.com> wrote:
Hi Daniel,
I noticed that you already moved the ERR log to DBG in the pipe limit
module. Did you have the opportunity to look at the other 2 errors?
Glad if I can help, but I will need some directions especially about
the place where the "[466B blob data]" is getting printed.
Thanks,
Nuno
On Wed, Jan 22, 2020 at 3:03 PM Nuno Ferreira <nferreira(a)fuze.com> wrote:
Hi,
http_reply_parse is not present in the configs. I've explicitly set it as
"no" and the result is the same. If I set it as "yes", topos
complains like
this:
Jan 22 15:00:10 proxy1 kamailio[29316]: ERROR: topos [topos_mod.c:282]:
tps_prepare_msg(): cannot parse cseq header
Thank you,
Nuno
On Wed, Jan 22, 2020 at 2:45 PM Daniel-Constantin Mierla <
miconda(a)gmail.com> wrote:
> 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 -> 127.0.0.1:8000 [AP]
> POST /RPC HTTP/1.1.
> User-Agent: curl/7.29.0.
> Host: 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 -> 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.
> 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], 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> 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:
>>
>> 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> 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:
>>>
>>> Hi Daniel,
>>>
>>> Thanks for your feedback.
>>> I have a dedicated listen directive for JSONRPC
>>> listen = 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> 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:
>>>>
>>>> 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
Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>
>>>> --
>>>> Daniel-Constantin Mierla -- www.asipto.comwww.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
>>>>
>>>>
>>>
>>> *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.*
>>>
>>> --
>>> Daniel-Constantin Mierla -- www.asipto.comwww.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
>>>
>>>
>>
>> *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.*
>>
>> --
>> Daniel-Constantin Mierla -- www.asipto.comwww.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
>>
>>
>
> *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.*
>
> --
> Daniel-Constantin Mierla -- www.asipto.comwww.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
>
>
--
*Nuno Ferreira* | Architect, CoreUC | nferreira(a)fuze.com | +351 308805903
Rua Carlos Silva Melo Guimarães 23, 3800-126 Aveiro, Portugal
<http://www.facebook.com/fuze> <http://www.twitter.com/fuze>
<https://www.linkedin.com/company/fuze-inc>
<https://plus.google.com/110150232345018024360>
<https://www.instagram.com/fuze_hq/>
<http://www.fuze.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.*
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
1708
days inactive
1767
days old
10 comments
3 participants
participants (3)
-
Bastian Triller -
Daniel-Constantin Mierla -
Nuno Ferreira