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 > <mico...@gmail.com <mailto:mico...@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 >> <mico...@gmail.com <mailto:mico...@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 >>> <mico...@gmail.com <mailto:mico...@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.* -- Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
_______________________________________________ Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
