[SR-Users] pipelimit: inexistent pipe error logs
Nuno Ferreira
nferreira at fuze.com
Wed Jan 22 12:34:08 CET 2020
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 at 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 at 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 at 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 at 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.*
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20200122/c8f8ad6d/attachment.html>
More information about the sr-users
mailing list