Reading data from proc file

[sumit kumar]

Hi Team,

I have a use case where I read audio data from proc files. I am reading both the stream interfaces in a separate thread. 

I have observed that when the thread reads in the background, rtpengine cannot delete the .meta file. It waits for the program to terminate and then the .meta file gets deleted immediately.

I need to know how reading data from proc files blocks the deletion of .meta file. 
I want to use the delete event of .meta file to terminate the thread.

Please help!!

[Richard Fuchs]

I'm not sure why that would happen. The .meta file should be deleted
immediately, regardless of whether anything reads from the /proc files
or not (assuming an underlying file system with POSIX semantics). The
.meta file isn't even directly linked to the /proc files, so there's no
mechanism how one would block the other.

In fact this is how the recording-daemon detects termination of a call
(inotify for the unlink event of the .meta file).

What happens when you try to delete the .meta file manually from the shell?

Cheers

[sumit kumar]

Hi Richard,

I tried deleting .meta file manually and it worked fine, my program was able to detect the file delete event. I am also using inotify to figure out .meta file creation and deletion.

I have written my code in rust on debian. I am using epoll for the streams to figure out if they are available to read. The proc streams are opened in non-blocking mode and I am creating epoll instance inside thread which reads data from these streams in infinite loop.

If I just watch the inotify events on /var/spool/rtpengine then everything works, but the moment I introduce thread to read from proc files, the .meta file doesn't get deleted or my main thread doesn't get the .meta file delete event.

[Richard Fuchs]

On 24/06/2023 11.05, [EXT] sumit kumar wrote:
> Hi Richard,
> I tried deleting .meta file manually and it worked fine, my program
> was able to detect the file delete event. I am also using inotify to
> figure out .meta file creation and deletion.
> I have written my code in rust on debian. I am using epoll for the
> streams to figure out if they are available to read. The proc streams
> are opened in non-blocking mode and I am creating epoll instance
> inside thread which reads data from these streams in infinite loop.
> If I just watch the inotify events on /var/spool/rtpengine then
> everything works, but the moment I introduce thread to read from proc
> files, the .meta file doesn't get deleted or my main thread doesn't
> get the .meta file delete event.

Not sure what to tell you since obviously I'm not able to reproduce
this. Perhaps try using strace to attach to rtpengine and watch for the
unlink() done on the .meta file. Maybe that gives you a clue as to why
the deletion doesn't happen.

Cheers

[Sumit]

Hi Richard,

I have tried strace but I only get below message.
strace: Process 549819 attached
futex(0x5653643f4acc, FUTEX_WAIT_PRIVATE, 0, NULL

Another interesting observation is I checked RTPEngine logs and I am adding the last few log statements here

Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscribed to 'aa0ad5ff-9462-436c-8252-f9c23dd02524'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscription for 'aa0ad5ff-9462-436c-8252-f9c23dd02524'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ------ Media #1 (audio over RTP/AVP) using PCMU/8000
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30098 <>    172.31.31.51:39524, SSRC ca110004, 6427 p, 1105444 b, 0 e, 2 ts
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30099 <>     3.21.154.44:37699 (RTCP), SSRC 0, 0 p, 0 b, 0 e, 133 ts
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --- Tag 'aa0ad5ff-9462-436c-8252-f9c23dd02524' (label '{"callId":"205AB196-6499902000070A49-20552700","startTime":1687785504955,"callDetails":{},"agentParticipantId":1}'), created 2:13 ago for branch ''
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscribed to '1D5A11A0-6499902000070A37-20552700'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscription for '1D5A11A0-6499902000070A37-20552700'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ------ Media #1 (audio over RTP/AVP) using PCMU/8000
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30078 <>    172.31.31.51:37698, SSRC ca110000, 6427 p, 1105444 b, 0 e, 3 ts
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30079 <>     3.21.154.44:39525 (RTCP), SSRC 0, 0 p, 0 b, 0 e, 133 ts
Jun 26 13:21:31 ip-172-31-25-82 rtpengine[549819]: DEBUG: [core] timer run time = 54.652115 sec
Jun 26 13:21:31 ip-172-31-25-82 rtpengine[549819]: INFO: [core] Increasing timer run interval to 1 seconds
Jun 26 13:21:31 ip-172-31-25-82 rtpengine[549819]: DEBUG: [core] timer run time = 0.000006 sec

The highlighted log statement came only after I terminated my program. Usually, these timer run time statements keep printing but in this case, once the call terminates, it seems these timer statements also stop.

--
You received this message because you are subscribed to a topic in the Google Groups "rtpengine" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rtpengine/nAi6ChXHfM0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rtpengine+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/rtpengine/e716dfcd-9e4e-6b9b-67eb-96416f990066%40sipwise.com.

--

With Regards,
Sumit Kumar

[Richard Fuchs]

On 26/06/2023 09.37, [EXT] Sumit wrote:

Hi Richard,

I have tried strace but I only get below message.
strace: Process 549819 attached
futex(0x5653643f4acc, FUTEX_WAIT_PRIVATE, 0, NULL

You need to use the `-f` option to also attach to other threads, or pick one of individual thread PIDs to attach to (seen for example in `ps -efL`)

Another interesting observation is I checked RTPEngine logs and I am adding the last few log statements here

Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscribed to 'aa0ad5ff-9462-436c-8252-f9c23dd02524'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscription for 'aa0ad5ff-9462-436c-8252-f9c23dd02524'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ------ Media #1 (audio over RTP/AVP) using PCMU/8000
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30098 <>    172.31.31.51:39524, SSRC ca110004, 6427 p, 1105444 b, 0 e, 2 ts
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30099 <>     3.21.154.44:37699 (RTCP), SSRC 0, 0 p, 0 b, 0 e, 133 ts
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --- Tag 'aa0ad5ff-9462-436c-8252-f9c23dd02524' (label '{"callId":"205AB196-6499902000070A49-20552700","startTime":1687785504955,"callDetails":{},"agentParticipantId":1}'), created 2:13 ago for branch ''
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscribed to '1D5A11A0-6499902000070A37-20552700'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ---     subscription for '1D5A11A0-6499902000070A37-20552700'
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] ------ Media #1 (audio over RTP/AVP) using PCMU/8000
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30078 <>    172.31.31.51:37698, SSRC ca110000, 6427 p, 1105444 b, 0 e, 3 ts
Jun 26 13:20:37 ip-172-31-25-82 rtpengine[549819]: INFO: [205AB196-6499902000070A49-20552700]: [core] --------- Port    172.31.25.82:30079 <>     3.21.154.44:39525 (RTCP), SSRC 0, 0 p, 0 b, 0 e, 133 ts
Jun 26 13:21:31 ip-172-31-25-82 rtpengine[549819]: DEBUG: [core] timer run time = 54.652115 sec
Jun 26 13:21:31 ip-172-31-25-82 rtpengine[549819]: INFO: [core] Increasing timer run interval to 1 seconds
Jun 26 13:21:31 ip-172-31-25-82 rtpengine[549819]: DEBUG: [core] timer run time = 0.000006 sec

The highlighted log statement came only after I terminated my program. Usually, these timer run time statements keep printing but in this case, once the call terminates, it seems these timer statements also stop.

This would be the main timer thread blocking on something. With a non-master version of rtpengine, this thread would show up as "poller timer" (or something like it) in `ps -ecL`. You can try attach strace to just that thread and maybe see what it blocks on. (Or attach to all with `-f` and then identify which thread it is based on what it does.)

Cheers

[Sumit]

Hi Richard,
I tried running strace with -f option and I saw another interesting observation, when my program runs and read proc files in a thread, at the end of the call if I try to terminate the strace, it gets stuck in the terminating process.
I am sharing the strace output in the attached file.

--
You received this message because you are subscribed to the Google Groups "rtpengine" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rtpengine+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/rtpengine/d5862823-e82c-b0e7-9384-819f86d9148d%40sipwise.com.

[Richard Fuchs]

On 27/06/2023 03.14, [EXT] Sumit wrote:
> Hi Richard,

> I tried running strace with -f option and I saw another
> interesting observation, when my program runs and read proc files in a
> thread, at the end of the call if I try to terminate the strace, it
> gets stuck in the terminating process.
> I am sharing the strace output in the attached file.

PID 549822 would be the timer thread.

At which point did it get stuck? Was it at the last line? (`write(3,
"\6\0...`)

That would be the `REMG_DEL_CALL` call, to remove the call from the
kernel intercept list (handled by `table_del_call()`).

That one acquires a few locks in its code path, but you would see a busy
lock as a CPU spinning 100%.

The other option is that it goes to sleep here:


    /* At this point, there should only be 2 references left: ours, and
the entry in
     * the "streams" array. Any other references are open files and we
must wait until
     * they're closed. There can be no new open file references as the
stream is set
     * to eof. */
    DBG("del_stream() waiting for other refs\n");
    while (1) {
        if (wait_event_interruptible(stream->close_wq,
atomic_read(&stream->refcnt) == 2) == 0)
            break;
    }

Does your reader code perhaps not react to EOF correctly? It should see
EOF on the /proc files and then close them, which releases the
references and allows the intercept call to be removed.

Cheers

[Sumit]

You are right, I have to close the file descriptor explicitly and it started deleting the meta file. I was under the assumption that Rust will take care of closing the files but with file descriptors it is not the case.

Thanks for pointing that out.

--
You received this message because you are subscribed to the Google Groups "rtpengine" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rtpengine+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/rtpengine/ccfb07a6-39c1-ad4c-244e-2c939bd2e6fb%40sipwise.com.