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 List
sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com


*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



*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


*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



--

Nuno Ferreira | Architect, CoreUC | nferreira@fuze.com | +351 308805903
Rua Carlos Silva Melo Guimarães 23, 3800-126 Aveiro, Portugal

        


*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