RTP Engine Recording Daemon recording duration coming greater than call duration in some cases

[sahil-patel6]

rtpengine version the issue has been seen with

Version: 13.1.0.0+0~mr13.1.0.0 git-master-f3aa776

Used distribution and its version

Debian 10

Linux kernel version used

5.10.0-0.deb10.16-amd64

CPU architecture issue was seen on (see uname -m)

x86_64

Expected behaviour you didn't see

No response

Unexpected behaviour you saw

Recording duration coming greater than call duration

Steps to reproduce the problem

No response

Additional program output to the terminal or logs illustrating the issue

Following is the call 1 Log which I think is resolved when I open issue before https://github.com/sipwise/rtpengine/issues/1871 :

Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [control] Received command 'offer' from 127.0.0.1:40788
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] replace-session-connection flag encountered, but not supported anymore.
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: NOTICE: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Creating new call
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: WARNING: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Interface 'private' not found, using default
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: WARNING: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Interface 'public' not found, using default
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: NOTICE: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Turning on call recording.
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Writing recording file: /var/spool/rtpengine/pcaps/57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.pcap
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=0
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=1
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=2
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=3
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: WARNING: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Error writing SDP body to metadata file: No such file or directory
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [control] Replying to 'offer' from 127.0.0.1:40788 (elapsed time 0.000879 sec)
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [core] New call for recording: '57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta'
Oct 22 06:37:13 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - - [22/Oct/2024:06:37:13 +0000] "POST /write?consistency=any&db=homer HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 12c0a3de-9040-11ef-b69b-3e08bd409893 3614
Oct 22 06:37:14 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [control] Received command 'answer' from 127.0.0.1:40788
Oct 22 06:37:14 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] replace-session-connection flag encountered, but not supported anymore.
Oct 22 06:37:14 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: WARNING: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Error writing SDP body to metadata file: Success
Oct 22 06:37:14 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [control] Replying to 'answer' from 127.0.0.1:40788 (elapsed time 0.000662 sec)
Oct 22 06:37:14 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta] [S tag-1-media-1-component-1-RTP-id-0] [0x9b390fe2] [core] Opened output media file '/root/apps/sbc-recorder-server/recordings/57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909-mix.wav' for writing
Oct 22 06:37:18 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0/0jy5Z7jty0v3m/1 port 46028]: [core] Confirmed peer address as 10.0.0.1:25576
Oct 22 06:37:18 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0/0jy5Z7jty0v3m/1 port 46029]: [core] Confirmed peer address as 10.0.0.1:25577
Oct 22 06:37:19 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0/95484242_c3356d0b_51c5a43f-1d5f-4086-906e-3936fdf9e87f/1 port 42099]: [core] Confirmed peer address as 10.0.0.2:15309
Oct 22 06:37:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0/95484242_c3356d0b_51c5a43f-1d5f-4086-906e-3936fdf9e87f/1 port 42098]: [core] Confirmed peer address as 10.0.0.2:15308
Oct 22 06:37:22 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 10.0.0.1 - - [22/Oct/2024:06:37:22 +0000] "POST /write?consistency=any&db=telegraf&rp=autogen HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 181c04be-9040-11ef-b69c-3e08bd409893 3527
Oct 22 06:37:23 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [control] Received command 'ping' from 127.0.0.1:60488
Oct 22 06:37:23 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [control] Replying to 'ping' from 127.0.0.1:60488 (elapsed time 0.000000 sec)
Oct 22 06:37:23 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - - [22/Oct/2024:06:37:23 +0000] "POST /write?consistency=any&db=telegraf&rp=autogen HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 185b4c87-9040-11ef-b69d-3e08bd409893 2577
Oct 22 06:37:23 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - root [22/Oct/2024:06:37:23 +0000] "POST /write?db=cdrs&p=%5BREDACTED%5D&precision=n&rp=&u=root HTTP/1.1 " 204 0 "-" "-" 18a08172-9040-11ef-b69e-3e08bd409893 3143
Oct 22 06:37:23 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - - [22/Oct/2024:06:37:23 +0000] "POST /write?consistency=any&db=homer HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 18b68847-9040-11ef-b69f-3e08bd409893 4315
Oct 22 06:37:24 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [control] Received command 'ping' from 127.0.0.1:40788
Oct 22 06:37:24 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [control] Replying to 'ping' from 127.0.0.1:40788 (elapsed time 0.000002 sec)
Oct 22 06:37:32 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 10.0.0.1 - - [22/Oct/2024:06:37:32 +0000] "POST /write?consistency=any&db=telegraf&rp=autogen HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 1e120e14-9040-11ef-b6a0-3e08bd409893 6372
Oct 22 06:37:33 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - - [22/Oct/2024:06:37:33 +0000] "POST /write?consistency=any&db=telegraf&rp=autogen HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 1e5112c9-9040-11ef-b6a1-3e08bd409893 10523
Oct 22 06:37:33 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [control] Received command 'delete' from 127.0.0.1:40788
Oct 22 06:37:33 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] replace-session-connection flag encountered, but not supported anymore.
Oct 22 06:37:33 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Scheduling deletion of entire call in 1 seconds
Oct 22 06:37:33 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [control] Replying to 'delete' from 127.0.0.1:40788 (elapsed time 0.000028 sec)
Oct 22 06:37:33 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - - [22/Oct/2024:06:37:33 +0000] "POST /write?consistency=any&db=homer HTTP/1.1 " 204 0 "-" "Telegraf/1.29.5 Go/1.22.0" 1eac6f4f-9040-11ef-b6a2-3e08bd409893 69920
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Final packet stats:
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --- Tag '95484242_c3356d0b_51c5a43f-1d5f-4086-906e-3936fdf9e87f', created 0:21 ago for branch ''
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] ------ Media #1 (audio over RTP/SAVP) using PCMU/8000
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --------- Port  10.0.0.3:42098 <>   10.0.0.2:15308, SSRC 473e089, in 237 p, 40764 b, 0 e, 1 ts, out 984 p, 179088 b, 0 e
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --------- Port  10.0.0.3:42099 <>   10.0.0.2:15309 (RTCP), SSRC 473e089, in 3 p, 300 b, 0 e, 5 ts, out 7 p, 882 b, 0 e
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --- SSRC 473e089
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] ------ Average MOS 4.3, lowest MOS 4.3 (at 0:10), highest MOS 4.3 (at 0:10) lost:0
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta] [S tag-0-media-1-component-2-RTCP-id-3] [core] EOF on stream tag-0-media-1-component-2-RTCP-id-3
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta] [S tag-0-media-1-component-1-RTP-id-2] [core] EOF on stream tag-0-media-1-component-1-RTP-id-2
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] ------ respective (avg/min/max) jitter 0/0/0 ms, RTT-e2e 101.4/101.6/101.6 ms, RTT-dsct 90.9/90.8/90.8 ms, packet loss 0/0/0%
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta] [S tag-1-media-1-component-2-RTCP-id-1] [core] EOF on stream tag-1-media-1-component-2-RTCP-id-1
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta] [S tag-1-media-1-component-1-RTP-id-0] [core] EOF on stream tag-1-media-1-component-1-RTP-id-0
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [core] Recording for call '57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.meta' finished
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --- Tag '0jy5Z7jty0v3m', created 0:21 ago for branch ''
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] ------ Media #1 (audio over RTP/AVP) using PCMU/8000
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --------- Port  10.0.0.3:46028 <>  10.0.0.1:25576, SSRC 9b390fe2, in 984 p, 169248 b, 0 e, 1 ts, out 237 p, 40764 b, 0 e
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --------- Port  10.0.0.3:46029 <>  10.0.0.1:25577 (RTCP), SSRC 9b390fe2, in 7 p, 784 b, 0 e, 1 ts, out 3 p, 300 b, 0 e
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] --- SSRC 9b390fe2
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] ------ Average MOS 3.9, lowest MOS 3.2 (at 0:18), highest MOS 4.3 (at 0:08) lost:3
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] ------ respective (avg/min/max) jitter 58/158/14 ms, RTT-e2e 101.7/101.8/101.5 ms, RTT-dsct 10.7/10.7/10.7 ms, packet loss 0/0/0%
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine[27967]: INFO: [57906315bd4f58139cdce09dc5d47855@0.0.0.0]: [core] Moved metadata file "/var/spool/rtpengine/tmp/rtpengine-meta-57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.tmp" to "/var/spool/rtpengine/metadata"
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [core] Closing output media file '/root/apps/sbc-recorder-server/recordings/57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909-mix.wav'
Oct 22 06:37:34 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: NOTICE: [core] HTTP notification for '57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909-mix' was successful




Here is another call 2 which has the same issue of having recording duration greater than call duration without that SDP issue like previous call had:
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [control] Received command 'offer' from 127.0.0.1:40788
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] replace-session-connection flag encountered, but not supported anymore.
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: NOTICE: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Creating new call
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: WARNING: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Interface 'private' not found, using default
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: WARNING: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Interface 'public' not found, using default
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: NOTICE: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Turning on call recording.
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=0
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [core] New call for recording: '798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta'
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=1
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=2
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] media_rec_slot=0, media_rec_slots=0, stream=3
Oct 18 08:51:39 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [control] Replying to 'offer' from 127.0.0.1:40788 (elapsed time 0.000828 sec)
Oct 18 08:51:40 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [control] Received command 'answer' from 127.0.0.1:40788
Oct 18 08:51:40 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] replace-session-connection flag encountered, but not supported anymore.
Oct 18 08:51:40 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [control] Replying to 'answer' from 127.0.0.1:40788 (elapsed time 0.000506 sec)
Oct 18 08:51:40 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta] [S tag-1-media-1-component-1-RTP-id-0] [0x9b33e964] [core] Opened output media file '/root/apps/sbc-recorder-server/recordings/798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678-mix.wav' for writing
Oct 18 08:51:44 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/FUNXaXK0UNSyK/1 port 52056]: [core] Confirmed peer address as 10.0.0.1:38720
Oct 18 08:51:44 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/FUNXaXK0UNSyK/1 port 52056]: [core] Kernelizing media stream: 10.0.0.1:38720 -> 10.0.0.3:52056 | 10.0.0.3:50402 -> 10.0.0.2:13782
Oct 18 08:51:44 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/FUNXaXK0UNSyK/1 port 52057]: [core] Confirmed peer address as 10.0.0.1:38721
Oct 18 08:51:44 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/FUNXaXK0UNSyK/1 port 52057]: [core] Kernelizing media stream: 10.0.0.1:38721 -> 10.0.0.3:52057 | 10.0.0.3:50403 -> 10.0.0.2:13783
Oct 18 08:51:44 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/30136940_c3356d0b_1bd9d9e8-55a0-4fab-954f-c88741dd25a6/1 port 50402]: [core] Confirmed peer address as 10.0.0.2:13782
Oct 18 08:51:44 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/30136940_c3356d0b_1bd9d9e8-55a0-4fab-954f-c88741dd25a6/1 port 50402]: [core] Kernelizing media stream: 10.0.0.2:13782 -> 10.0.0.3:50402 | 10.0.0.3:52056 -> 10.0.0.1:38720
Oct 18 08:51:45 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/30136940_c3356d0b_1bd9d9e8-55a0-4fab-954f-c88741dd25a6/1 port 50403]: [core] Confirmed peer address as 10.0.0.2:13783
Oct 18 08:51:45 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0/30136940_c3356d0b_1bd9d9e8-55a0-4fab-954f-c88741dd25a6/1 port 50403]: [core] Kernelizing media stream: 10.0.0.2:13783 -> 10.0.0.3:50403 | 10.0.0.3:52057 -> 10.0.0.1:38721
Oct 18 08:51:56 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Received command 'ping' from 127.0.0.1:60488
Oct 18 08:51:56 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Replying to 'ping' from 127.0.0.1:60488 (elapsed time 0.000001 sec)
Oct 18 08:51:57 debian-s-2vcpu-4gb-nyc3-01 influxd-systemd-start.sh[1618]: [httpd] 127.0.0.1 - root [18/Oct/2024:08:51:57 +0000] "POST /write?db=cdrs&p=%5BREDACTED%5D&precision=n&rp=&u=root HTTP/1.1 " 204 0 "-" "-" 3b3531d7-8d2e-11ef-b490-3e08bd409893 3062
Oct 18 08:51:58 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Received command 'ping' from 127.0.0.1:40788
Oct 18 08:51:58 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Replying to 'ping' from 127.0.0.1:40788 (elapsed time 0.000001 sec)
Oct 18 08:52:16 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Received command 'ping' from 127.0.0.1:60488
Oct 18 08:52:16 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Replying to 'ping' from 127.0.0.1:60488 (elapsed time 0.000001 sec)
Oct 18 08:52:18 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Received command 'ping' from 127.0.0.1:40788
Oct 18 08:52:18 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [control] Replying to 'ping' from 127.0.0.1:40788 (elapsed time 0.000001 sec)
Oct 18 08:52:20 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [control] Received command 'delete' from 127.0.0.1:40788
Oct 18 08:52:20 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] replace-session-connection flag encountered, but not supported anymore.
Oct 18 08:52:20 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Scheduling deletion of entire call in 1 seconds
Oct 18 08:52:20 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [control] Replying to 'delete' from 127.0.0.1:40788 (elapsed time 0.000024 sec)
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Final packet stats:
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --- Tag '30136940_c3356d0b_1bd9d9e8-55a0-4fab-954f-c88741dd25a6', created 0:42 ago for branch ''
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] ------ Media #1 (audio over RTP/SAVP) using PCMU/8000
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --------- Port  10.0.0.3:50402 <>   10.0.0.2:13782, SSRC 57bd1473, in 157 p, 28354 b, 0 e, 2 ts, out 1992 p, 344314 b, 0 e
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --------- Port  10.0.0.3:50403 <>   10.0.0.2:13783 (RTCP), SSRC 57bd1473, in 13 p, 1344 b, 0 e, 6 ts, out 27 p, 3038 b, 0 e
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta] [S tag-0-media-1-component-2-RTCP-id-3] [core] EOF on stream tag-0-media-1-component-2-RTCP-id-3
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta] [S tag-0-media-1-component-1-RTP-id-2] [core] EOF on stream tag-0-media-1-component-1-RTP-id-2
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta] [S tag-1-media-1-component-2-RTCP-id-1] [core] EOF on stream tag-1-media-1-component-2-RTCP-id-1
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --- SSRC 57bd1473
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [C 798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta] [S tag-1-media-1-component-1-RTP-id-0] [core] EOF on stream tag-1-media-1-component-1-RTP-id-0
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] ------ Average MOS 4.3, lowest MOS 4.3 (at 0:10), highest MOS 4.3 (at 0:10) lost:0
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] ------ respective (avg/min/max) jitter 0/0/0 ms, RTT-e2e 96.8/96.0/96.0 ms, RTT-dsct 90.9/90.8/90.8 ms, packet loss 0/0/0%
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: INFO: [core] Recording for call '798fb4ab9362d2bce6d667e268b59941%400.0.0.0-ca6936fc90323678.meta' finished
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --- Tag 'FUNXaXK0UNSyK', created 0:42 ago for branch ''
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] ------ Media #1 (audio over RTP/AVP) using PCMU/8000
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --------- Port  10.0.0.3:52056 <>  10.0.0.1:38720, SSRC 9b33e964, in 1992 p, 342624 b, 0 e, 1 ts, out 157 p, 27004 b, 0 e
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --------- Port  10.0.0.3:52057 <>  10.0.0.1:38721 (RTCP), SSRC 9b33e964, in 53 p, 5936 b, 0 e, 1 ts, out 7 p, 680 b, 0 e
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] --- SSRC 9b33e964
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] ------ Average MOS 3.1, lowest MOS 1.1 (at 0:29), highest MOS 4.1 (at 0:20) lost:1
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] ------ respective (avg/min/max) jitter 166/385/58 ms, RTT-e2e 96.8/97.1/97.2 ms, RTT-dsct 5.7/5.8/6.3 ms, packet loss 0/0/0%
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Removing media stream from kernel: local 10.0.0.3:52056 (final call cleanup)
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Removing media stream from kernel: local 10.0.0.3:52057 (final call cleanup)
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Removing media stream from kernel: local 10.0.0.3:50402 (final call cleanup)
Oct 18 08:52:21 debian-s-2vcpu-4gb-nyc3-01 rtpengine[2922]: INFO: [798fb4ab9362d2bce6d667e268b59941@0.0.0.0]: [core] Removing media stream from kernel: local 10.0.0.3:50403 (final call cleanup)

Anything else?

As I have shared 2 call logs above from syslog. For both I am facing issue of having recording duration greater than call duration.

Note: This is not happening for all calls and also we are using kernel module to kernelize stream so that recording daemon can record calls. And also I have replaced IP addresses to dummy ones for security reasons. I cannot reproduce this, it happened suddenly and if it happens again then will share logs for the same too. Also it is to be noted that #1871 was created for SDP issue and I that is why it was causing recording and call duration difference and it has huge difference like 8 sec recording duration and call was like 133 secs something. But the Call 1 had same SDP issue but this time recording duration was greater than call duration. Can you please tell me what is the issue and how can be fixed. And If I talk about Call 2 everything seems normal based on the logs but it had recording duration had 47 secs whereas call duration was 39 secs. I do not have pcap and metadata file for Call 2.

Here is the PCAP file generated by rtpengine for Call 1:
call_1_issue.zip

Here is the configuration for rtpengine-recording:

[rtpengine-recording]

table = 0

### number of worker threads (default 8)
 num-threads = 16

### where to forward to (unix socket)
# forward-to = /run/rtpengine/sock

### where to store recordings: file (default), db, both
 output-storage = file

### format of stored recordings: wav (default), mp3
 output-format = wav

### directory containing rtpengine metadata files
 spool-dir = /var/spool/rtpengine

### where to store media files to
 output-dir = /root/apps/recorder-server/recordings

### file name pattern for output files
#output-pattern = %c-%t

### resample all output audio
resample-to = 8000

### bits per second for MP3 encoding
# mp3-bitrate = 24000
log-level=6
### mix participating sources into a single output
output-mixed=true
flush-packets=true
### maximum number of inputs for mixed output
# mix-num-inputs = 4

### create one output file for each source
# output-single = true

### TCP/TLS output of PCM audio
# tcp-send-to = 10.4.1.7:15413
# tcp-resample = 16000
### OR
# tls-send-to = 10.4.1.7:15413
# tls-resample = 16000

### mysql configuration for db storage
 mysql-host = localhost
 mysql-port = 3306
 mysql-user = admin
 mysql-pass = password
 mysql-db = rtpengine

### ownership/permission control for output files
#output-chmod = 0640
#output-chmod-dir = 0750
#output-chown = rtpengineoutput-chgrp = rtpengine

### HTTP notifications for finished recordings
notify-uri = https://somedomain.com/recordings/recording-completed
 notify-post = true
# notify-no-verify = false
# notify-purge = false
# notify-concurrency = 5
# notify-retries = 10

Here is the configuration for rtpengine service:

[Unit]
Description=rtpengine
After=syslog.target network.target local-fs.target

[Service]
; service
Type=forking
ExecStart=/usr/local/bin/rtpengine --interface 10.0.0.3!10.0.0.3 \
--listen-ng=22222 \
--listen-udp=12222 \
--listen-cli=127.0.0.1:9900 \
--pidfile /var/run/rtpengine.pid \
--port-min 40000 \
--port-max 60000 \
--recording-dir=/var/spool/rtpengine \
--recording-method=all \
--log-level 6 \
--table=0\
--delete-delay=1\
--homer=127.0.0.1:9060 \
--homer-id=13 \
--homer-protocol=udp
PIDFile=/var/run/rtpengine.pid
TimeoutSec=15s
Restart=always
; exec
User=root
Group=daemon
LimitCORE=infinity
LimitNOFILE=100000
LimitNPROC=60000
;LimitSTACK=240
LimitRTPRIO=infinity
LimitRTTIME=7000000
IOSchedulingClass=realtime
IOSchedulingPriority=2
CPUSchedulingPolicy=rr
CPUSchedulingPriority=89
UMask=0007

[Install]
WantedBy=multi-user.target

Here is rtpengine metadata for Call 1:

/var/spool/rtpengine/pcaps/57906315bd4f58139cdce09dc5d47855%400.0.0.0-274e4525d9b2e909.pcap

Timestamp started ms: 1729579033397.754
SDP mode: offer
SDP before RTP packet: 1


Timestamp started ms: 1729579033397.765
SDP mode: answer
SDP before RTP packet: 1


Timestamp terminated ms(first monologue): 1729579053775.602

call start time: 2024-10-22T06:37:13
call end time: 2024-10-22T06:37:34

[rfuchs]

It's probably due to timestamp skews of one of RTP sources. SSRC 0473e089 in your pcap seems to have problems keeping its clock in sync. For example between packets 546 and 620: 1.4 seconds have passed, but the RTP timestamp increased only by 160, which corresponds to 0.02 seconds. This gap has to be made up somehow when writing the audio to file. Then between packets 684 and 726, the timestamp increased by 17680, corresponding to 2.21 seconds, but only 0.8 seconds real time have elapsed, now bringing the clock skew back again. Again this discrepancy has to be accounted for somehow when writing audio to file.

So ultimately the RTP source is to blame for this. You can see this when analysing the RTP stream in Wireshark. Of course the recording daemon could detect this and try to do a better job at compensating for it, but at the moment it doesn't.

[sahil-patel6]

Hi rfuchs,

Thanks for the reply. Can you please confirm the following:

1. will it affect the actual recording content?
2. RTP Engine Recording Daemon not recording properly for some cases #1871 - this issue you have closed, can you please confirm that it will not cause the recording duration being way less than call duration like 8 sec rec and 133 sec call duration?

Thanks in advance for helping out.

[rfuchs]

1. will it affect the actual recording content?

The synchronisation between the two audio sources in the mixed output file will likely be wrong.

2. RTP Engine Recording Daemon not recording properly for some cases #1871 - this issue you have closed, can you please confirm that it will not cause the recording duration being way less than call duration like 8 sec rec and 133 sec call duration?

No that has nothing to do with the duration of recordings.

[sahil-patel6]

@rfuchs , Thanks for the reply. by actual recording content, I meant that the actual audio data, I mean I can understand due to packets coming delay causing this issue.

Also regarding 2nd point, what can I do to solve that? can you please tell me? shall I use –output-mixed-per-media? I asked because in the logs I can see that it was related to SDP and that's why maybe rtpengine recording daemon was facing issue to record the call?

Thanks in advance for helping me out.

[sahil-patel6]

@rfuchs , I was able to restore the recording with pcap file as it had the recording which had call and recording duration difference

[sahil-patel6]

@rfuchs, can you please check out the logs #1871. As I also saw this in the logs of rtpengine-recording:

Oct 19 11:41:27 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: ERR: [C 2125114003-3938326873-2083106341%40IRISMSC7.iristel.net-f27ce55656064be9.meta] [S tag-1-media-1-component-1-RTP-id-0] [0x9b1e9232] [core] Failed to add frame to mixer: received samples for old re-used input channel
Oct 19 11:41:27 debian-s-2vcpu-4gb-nyc3-01 rtpengine-recording[2178]: ERR: [C 2125114003-3938326873-2083106341%40IRISMSC7.iristel.net-f27ce55656064be9.meta] [S tag-1-media-1-component-1-RTP-id-0] [0x9b1e9232] [core] Failed to add decoded packet to mixed output

[rfuchs]

This is unrelated to this issue. Use the mailing list for general support questions.

[sahil-patel6]

Okay thanks. Will post there