[SR-Users] start_recording and stop_recording inside event_route[xhttp:request]

Thu Apr 29 15:39:38 CEST 2021

I run Kamailio with debug=3 and Rtpengine with LOG_LEVEL=6.

Rtpengine logs offers, answers and deletes but there is nothing when I
trigger *start_recording* with HTTP request. Below is the full Kamailio log
for the request. It looks to be failing right on the *start_recording*
function and I don't see any other issues except empty Call-Id here:
"receive_msg(): --- received sip message - request - call-id: [] - cseq:
[]".

I tried to add Call-Id header to my HTTP request and found out that now
rtpengine module will complain about missing To header. With tries and
errors, I specified all required headers and Rtpengine started call
recording:

*/usr/bin/curl -H "Content-Type: text"
"http://localhost:8088/CALL_RECORD_START/38687ab466a031d20d852706710d2b4f@127.0.0.1:5080.1
<http://localhost:8088/CALL_RECORD_START/38687ab466a031d20d852706710d2b4f@127.0.0.1:5080.1>"
-H "Call-Id: 38687ab466a031d20d852706710d2b4f at 127.0.0.1:5080.1" -H "To:
sip:200-test at 127.0.0.1:5060 <http://sip:200-test@127.0.0.1:5060>" -H "From:
<sip:2564286000 at 127.0.0.1:5080
<http://sip:2564286000@127.0.0.1:5080>>;tag=as7a92114c"*

It also looks like rtpengine module does not care about actual header
values. Function *start_recording* called with Call-Id value is enough to
start call recording even if all headers contain random invalid values:

* /usr/bin/curl -H "Content-Type: text"
"http://localhost:8088/CALL_RECORD_START/6559572e21e08e0a41503ba5779c6604@127.0.0.1:5080.0
<http://localhost:8088/CALL_RECORD_START/6559572e21e08e0a41503ba5779c6604@127.0.0.1:5080.0>"
-H "Call-Id: does_mot_matter" -H "To: sip:456 at 127.0.0.1:5060
<http://sip:456@127.0.0.1:5060>" -H "From: <sip:123 at 127.0.0.1:5080
<http://sip:123@127.0.0.1:5080>>;tag=1"*

*Thank you very much for your help!*

*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection:
127.0.0.1*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/tcp_main.c:1175]: tcpconn_new(): on port 42782, type 2, socket 64*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/tcp_main.c:1498]: tcpconn_add(): hashes: 1710:1616:2551, 1*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/io_wait.h:375]: io_watch_add(): DBG: io_watch_add(0xae63a0, 64, 2,
0x7f943ba04ac0), fd_no=50*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0xae63a0, 64, -1,
0x0) fd_no=51 called*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/tcp_main.c:4457]: handle_tcpconn_ev(): sending to child, events 1*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/tcp_main.c:4130]: send2child(): selected tcp worker idx:0 proc:35
pid:24116 for activity on [tcp:127.0.0.1:8088 <http://127.0.0.1:8088>],
0x7f943ba04ac0*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_read.c:1749]: handle_io(): received n=8 con=0x7f943ba04ac0, fd=13*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:610]: parse_msg(): SIP Request:*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:612]: parse_msg():  method:  <GET>*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:614]: parse_msg():  uri:
</CALL_RECORD_START/7a444c165953cf0a196e10e50d0b611e at 127.0.0.1:5080.0>*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:616]: parse_msg():  version: <HTTP/1.1>*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:89]: get_hdr_field(): found end of header*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/receive.c:324]: receive_msg(): --- received sip message - request -
call-id: [] - cseq: []*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: xhttp
[xhttp_mod.c:382]: xhttp_handler(): new fake msg created (286 bytes):*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:610]: parse_msg(): SIP Request:*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:612]: parse_msg():  method:  <GET>*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:614]: parse_msg():  uri:
</CALL_RECORD_START/7a444c165953cf0a196e10e50d0b611e at 127.0.0.1:5080.0>*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:616]: parse_msg():  version: <HTTP/1.1>*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:500]: parse_headers(): this is the first via*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <script>: == TRACE.
xhttp:request*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <script>: == TRACE.
xhttp:request. HTTP Request Received*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <script>: == TRACE.
xhttp:request. hu is:
/CALL_RECORD_START/7a444c165953cf0a196e10e50d0b611e at 127.0.0.1:5080.0*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <script>:
call-id=7a444c165953cf0a196e10e50d0b611e at 127.0.0.1:5080.0*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/parser/msg_parser.c:89]: get_hdr_field(): found end of header*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: ERROR: rtpengine
[rtpengine_funcs.c:294]: get_callid(): call-id not found*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: ERROR: rtpengine
[rtpengine.c:2383]: rtpp_function_call(): can't get Call-Id field*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: xhttp
[xhttp_mod.c:441]: xhttp_send_reply(): sending out response: 200 OK*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/msg_translator.c:161]: check_via_address(): (127.0.0.1, 127.0.0.1, 0)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_main.c:1590]: _tcpconn_find(): found connection by id: 1*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_main.c:2472]: tcpconn_send_put(): send from reader (24116 (35)),
reusing fd*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_main.c:2706]: tcpconn_do_send(): sending...*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_main.c:2739]: tcpconn_do_send(): after real write: c=
0x7f943ba04ac0 n=113 fd=13*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_main.c:2740]: tcpconn_do_send(): buf=*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/xavp.c:539]: xavp_destroy_list(): destroying xavp list (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/receive.c:528]: receive_msg(): cleaning up*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/io_wait.h:375]: io_watch_add(): DBG: io_watch_add(0xb2a640, 13, 2,
0x7f943ba04ac0), fd_no=1*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/tcp_main.c:3793]: handle_ser_child(): read response= 7f943ba04ac0,
-1, fd -1 from 35 (24116)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0xb2a640, 13, -1,
0x10) fd_no=2 called*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_read.c:1890]: handle_io(): removing from list 0x7f943ba04ac0 id 1
fd 13, state -1, flags 4028, main fd -1, refcnt 1 ([127.0.0.1]:42782 ->
[127.0.0.1]:8088)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_read.c:1671]: release_tcpconn(): releasing con 0x7f943ba04ac0,
state -2, fd=13, id=1 ([127.0.0.1]:42782 -> [127.0.0.1]:8088)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24116]: DEBUG: <core>
[core/tcp_read.c:1672]: release_tcpconn(): extra_data (nil)*
*Apr 29 16:01:47 test /usr/sbin/kamailio[24120]: DEBUG: <core>
[core/tcp_main.c:3560]: handle_tcp_child(): reader response= 7f943ba04ac0,
-2 from 0*

чт, 29 квіт. 2021 о 13:17 Daniel-Constantin Mierla <miconda at gmail.com> пише:

> Ohhh, blindly missed the assignment before. You should run both kamailio
> and rtpengine with higher debug level and see if you get any hints from the
> log messages.
>
> Cheers,
> Daniel
> On 29.04.21 11:51, Володимир Іванець wrote:
>
> Hello Daniel,
>
> That is correct. My *$var(call_id)* variable contains concatenation of
> the "call-id=" string and a Call-Id value.
>
> *Apr 27 18:25:00 test /usr/sbin/kamailio[5347]: DEBUG: <script>:
> call-id=3de74068278ede4417086eb82bdf5a06 at 127.0.0.1:5080.0
> <call-id=3de74068278ede4417086eb82bdf5a06 at 127.0.0.1:5080.0>*
>
>
> Thank you!
>
> чт, 29 квіт. 2021 о 09:58 Daniel-Constantin Mierla <miconda at gmail.com>
> пише:
>
>> Hello,
>>
>> related to the initial config snippet example, the call-id is expected to
>> be provide as a named flag, like:
>>
>> start_recording("call-id=$var(call_id)");
>>
>> See the readme of the rtpengine module for more details.
>>
>> Cheers,
>> Daniel
>> On 29.04.21 08:23, Володимир Іванець wrote:
>>
>> Hello Richard,
>>
>> Thank you very much for the suggestion! I will give it a try.
>>
>> ср, 28 квіт. 2021, 20:00 користувач Richard Fuchs <rfuchs at sipwise.com>
>> пише:
>>
>>> On 28/04/2021 10.53, [ EXT ] Володимир Іванець wrote:
>>>
>>> Hello!
>>>
>>> I'm testing call recording with Rtpengine. It works fine when the
>>> "record-call=on" flag is added to the *rtpengine_offer* or
>>> *start_recording* is used in the *request_route*.
>>>
>>> But I was wondering if the call recording can be managed by a separate
>>> application. So I add the following lines to the
>>> *event_route[xhttp:request]* and triggered it with an HTTP request
>>> after the call was established. The call-id value was taken from the
>>> Rtpengine log and sent with the request.
>>>
>>> *  if ($hu =~ "^/CALL_RECORD_START/") {*
>>> *    $var(call_id) = *"call-id=" + *$(hu{s.select,2,/});*
>>>     xlog("L_DBG", "$var(call_id)");
>>> *    start_recording($var(call_id));*
>>>     exit;
>>> *  }*
>>>
>>> If you have to reason to go through Kamailio for this, you can simply
>>> trigger the command from any other external application. There's a sample
>>> script included in the repo that can be used for this purpose directly
>>> (making use of the Perl module that is also included):
>>> https://github.com/sipwise/rtpengine/blob/master/utils/rtpengine-ng-client
>>>
>>> There's also a nodejs client that I'm aware of:
>>> https://github.com/davehorton/rtpengine-client
>>>
>>> Or you can hand-roll the request and talk to rtpengine via HTTP or
>>> Websocket for example.
>>>
>>> Cheers
>>> __________________________________________________________
>>> Kamailio - Users Mailing List - Non Commercial Discussions
>>>   * sr-users at lists.kamailio.org
>>> Important: keep the mailing list in the recipients, do not reply only to
>>> the sender!
>>> Edit mailing list options or unsubscribe:
>>>   * https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>
>>
>> __________________________________________________________
>> Kamailio - Users Mailing List - Non Commercial Discussions
>>   * sr-users at lists.kamailio.org
>> Important: keep the mailing list in the recipients, do not reply only to the sender!
>> Edit mailing list options or unsubscribe:
>>   * https://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 - Online
>> May 17-20, 2021 (Europe Timezone) - June 7-10, 2021 (America Timezone)
>>   * https://www.asipto.com/sw/kamailio-advanced-training-online/
>>
>> --
> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda
> Kamailio Advanced Training - Online
> May 17-20, 2021 (Europe Timezone) - June 7-10, 2021 (America Timezone)
>   * https://www.asipto.com/sw/kamailio-advanced-training-online/
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20210429/e7316a7a/attachment.htm>