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
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@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
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@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
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@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: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@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.*
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@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@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
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@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: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@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: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@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.*-- 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,
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@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@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@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
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@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: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@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: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@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: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@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.*-- 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.*-- 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,
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@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@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@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@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
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@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@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@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@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@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
add -a option to journalctl
On Mon, Feb 10, 2020 at 6:19 PM Nuno Ferreira nferreira@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@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@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@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@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@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@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/
*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@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
-
Bastian Triller -
Daniel-Constantin Mierla -
Nuno Ferreira