Jibri recording failed , Current service had an error Error: QuitUnexpectedly SESSION plug:bsnoop: Input/output error

Hi,
I have correctly configured Jibri but the recording is unable to start due to plug:bsnoop: Input/output error.
Exact error from jibri is below:

stractPageObject.visit#38: Waited 477ms for driver to load page
2022-04-25 18:17:33.830 FINE: [66] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-04-25 18:17:34.337 FINE: [66] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-04-25 18:17:34.901 INFO: [66] CallPage.visit#71: Waited 1.10s to join the conference
2022-04-25 18:17:34.904 INFO: [66] [session_id=evyoxpmpfzvctcct] EmptyCallStatusCheck.<init>#26: Starting empty call check with a timeout of PT45S
2022-04-25 18:17:34.923 INFO: [66] [session_id=evyoxpmpfzvctcct] JibriSelenium.onSeleniumStateChange#215: Transitioning from state Starting up to Running
2022-04-25 18:17:34.924 INFO: [66] [session_id=evyoxpmpfzvctcct] FileRecordingJibriService$start$1.invoke#168: Selenium joined the call, starting the capturer
2022-04-25 18:17:34.953 INFO: [66] [session_id=evyoxpmpfzvctcct] JibriSubprocess.launch#42: Starting ffmpeg with command ffmpeg -y -v info -f x11grab -draw_mouse 0 -r 30 -s 1920x1080 -thread_queue_size 4096 -i :0.0+0,0 -f alsa -thread_queue_size 4096 -i plug:bsnoop -acodec aac -strict -2 -ar 44100 -b:a 128k -af aresample=async=1 -c:v libx264 -preset veryfast -profile:v main -level 3.1 -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f mp4 /mnt/efs/recordings/evyoxpmpfzvctcct/0e7a03458bbb4b85a7099004d904a05bwebxteam_2022-04-25-18-17-32.mp4 ([ffmpeg, -y, -v, info, -f, x11grab, -draw_mouse, 0, -r, 30, -s, 1920x1080, -thread_queue_size, 4096, -i, :0.0+0,0, -f, alsa, -thread_queue_size, 4096, -i, plug:bsnoop, -acodec, aac, -strict, -2, -ar, 44100, -b:a, 128k, -af, aresample=async=1, -c:v, libx264, -preset, veryfast, -profile:v, main, -level, 3.1, -pix_fmt, yuv420p, -r, 30, -crf, 25, -g, 60, -tune, zerolatency, -f, mp4, /mnt/efs/recordings/evyoxpmpfzvctcct/0e7a03458bbb4b85a7099004d904a05bwebxteam_2022-04-25-18-17-32.mp4])
2022-04-25 18:17:35.308 FINE: [71] HttpApi$apiModule$2$1$1.invokeSuspend#84: Got health request
2022-04-25 18:17:35.309 FINE: [71] HttpApi$apiModule$2$1$1.invokeSuspend#86: Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=<DOMAIN_NAME))
2022-04-25 18:17:39.959 FINE: [20] [session_id=evyoxpmpfzvctcct] ProcessStatePublisher$startProcessAliveChecks$1.invoke#86: Process ffmpeg hasn't written in 2 seconds, publishing periodic update
2022-04-25 18:17:39.960 INFO: [69] [session_id=evyoxpmpfzvctcct] FfmpegCapturer.onFfmpegProcessUpdate#121: Ffmpeg quit abruptly.  Last output line: plug:bsnoop: Input/output error
2022-04-25 18:17:39.961 INFO: [69] [session_id=evyoxpmpfzvctcct] FfmpegCapturer.onFfmpegStateMachineStateChange#130: Ffmpeg capturer transitioning from state Starting up to Error: QuitUnexpectedly SESSION plug:bsnoop: Input/output error
2022-04-25 18:17:39.961 INFO: [69] [session_id=evyoxpmpfzvctcct] StatefulJibriService.onServiceStateChange#39: File recording service transitioning from state Starting up to Error: QuitUnexpectedly SESSION plug:bsnoop: Input/output error
2022-04-25 18:17:39.962 INFO: [69] XmppApi$createServiceStatusHandler$1.invoke#311: Current service had an error Error: QuitUnexpectedly SESSION plug:bsnoop: Input/output error, sending error iq <iq xmlns='jabber:client' to='jibribrewery@internal.auth.<DOMAIN>/focus' id='4XNR5-8' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' status='off' failure_reason='error' should_retry='true'/></iq>
2022-04-25 18:17:39.963 FINE: [69] JibriStatsDClient.incrementCounter#38: Incrementing statsd counter: stop:recording
2022-04-25 18:17:39.963 INFO: [69] JibriManager.stopService#260: Stopping the current service
2022-04-25 18:17:39.963 INFO: [69] [session_id=evyoxpmpfzvctcct] FileRecordingJibriService.stop#182: Stopping capturer
2022-04-25 18:17:39.963 INFO: [69] [session_id=evyoxpmpfzvctcct] JibriSubprocess.stop#75: Stopping ffmpeg process
2022-04-25 18:17:39.965 INFO: [69] [session_id=evyoxpmpfzvctcct] JibriSubprocess.stop#89: ffmpeg exited with value 1
2022-04-25 18:17:39.965 INFO: [69] [session_id=evyoxpmpfzvctcct] FileRecordingJibriService.stop#184: Quitting selenium
2022-04-25 18:17:39.968 INFO: [69] [session_id=evyoxpmpfzvctcct] FileRecordingJibriService.stop#191: No media was recorded, deleting directory and skipping metadata file & finalize

Output of commands:
aplay -l

`

aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: Loopback [Loopback], device 0: Loopback PCM [Loopback PCM]
Subdevices: 8/8
Subdevice #0: subdevice #0
Subdevice #1: subdevice #1
Subdevice #2: subdevice #2
Subdevice #3: subdevice #3
Subdevice #4: subdevice #4
Subdevice #5: subdevice #5
Subdevice #6: subdevice #6
Subdevice #7: subdevice #7
card 0: Loopback [Loopback], device 1: Loopback PCM [Loopback PCM]
Subdevices: 8/8
Subdevice #0: subdevice #0
Subdevice #1: subdevice #1
Subdevice #2: subdevice #2
Subdevice #3: subdevice #3
Subdevice #4: subdevice #4
Subdevice #5: subdevice #5
Subdevice #6: subdevice #6
Subdevice #7: subdevice #7

`
cat /home/jibri/.asoundrc

pcm.amix {
  type dmix
  ipc_key 219345
  slave.pcm "hw:Loopback,0,0"
}

pcm.asnoop {
  type dsnoop
  ipc_key 219346
  slave.pcm "hw:Loopback_1,1,0"
}

pcm.aduplex {
  type asym
  playback.pcm "amix"
  capture.pcm "asnoop"
}

pcm.bmix {
  type dmix
  ipc_key 219347
  slave.pcm "hw:Loopback_1,0,0"
}

pcm.bsnoop {
  type dsnoop
  ipc_key 219348
  slave.pcm "hw:Loopback,1,0"
}

pcm.bduplex {
  type asym
  playback.pcm "bmix"
  capture.pcm "bsnoop"
}

pcm.pjsua {
  type plug
  slave.pcm "bduplex"
}

pcm.!default {
  type plug
  slave.pcm "aduplex"
}

jibr.conf regarding audio config:

  ffmpeg {
    resolution = "1920x1080"
    // The audio source that will be used to capture audio on Linux
    audio-source = "alsa"
    // The audio device that will be used to capture audio on Linux
    audio-device = "plug:bsnoop"
  }

FFMPEG logs:

2022-04-25 18:17:35.055 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42: [x11grab @ 0x556de0862e40] Stream #0: not enough frames to estimate rate; consider increasing probesize
2022-04-25 18:17:35.055 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42: Input #0, x11grab, from ':0.0+0,0':
2022-04-25 18:17:35.055 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42:   Duration: N/A, start: 1650910655.034374, bitrate: N/A
2022-04-25 18:17:35.055 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42:     Stream #0:0: Video: rawvideo (BGR[0] / 0x524742), bgr0, 1920x1080, 30 fps, 1000k tbr, 1000k tbn, 1000k tbc
2022-04-25 18:17:35.055 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42: ALSA lib pcm_dsnoop.c:641:(snd_pcm_dsnoop_open) unable to open slave
2022-04-25 18:17:35.056 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42: [alsa @ 0x556de086e4c0] cannot open audio device plug:bsnoop (Device or resource busy)
2022-04-25 18:17:35.056 INFO: [70] LoggingUtils$Companion$OutputLogger$1$1.call#42: plug:bsnoop: Input/output error

For the things to be even more strange, we are using same AMI on AWS for other environments and it works! It doesn’t work only on this one particular environment.

We have tried to change instance_type, re-deploy instance, update kernel, update jibri , ffmpeg is already the latest version, but nothing helps.
The only thing that resolved this was to change audio config in jitsi.conf as below:

  ffmpeg {
    resolution = "1920x1080"
    // The audio source that will be used to capture audio on Linux
    audio-source = "alsa"
    // The audio device that will be used to capture audio on Linux
    audio-device = "plug:dsnoop"
  }

So basically to change from bsnoop => dsnoop

Current jibri version:
dpkg -l | grep jibri
ii jibri 8.0-121-g27323fe-1 all Jibri

Does anyone have idea what could be wrong ?

Regards,
Srdjan I.

What’s the output of:

lsmod | grep snd_aloop

lsmod | grep snd_aloop
snd_aloop 24576 0
snd_pcm 106496 1 snd_aloop
snd 90112 3 snd_timer,snd_aloop,snd_pcm

What java version are you running?
What does arecord -l show? Run that as jibri user.

java -version
openjdk version "11.0.14" 2022-01-18
OpenJDK Runtime Environment (build 11.0.14+9-Ubuntu-0ubuntu2.20.04)
OpenJDK 64-Bit Server VM (build 11.0.14+9-Ubuntu-0ubuntu2.20.04, mixed mode, sharing)
root@dev2:/home/ubuntu# su - jibri
$ arecord -l
**** List of CAPTURE Hardware Devices ****
card 0: Loopback [Loopback], device 0: Loopback PCM [Loopback PCM]
  Subdevices: 8/8
  Subdevice #0: subdevice #0
  Subdevice #1: subdevice #1
  Subdevice #2: subdevice #2
  Subdevice #3: subdevice #3
  Subdevice #4: subdevice #4
  Subdevice #5: subdevice #5
  Subdevice #6: subdevice #6
  Subdevice #7: subdevice #7
card 0: Loopback [Loopback], device 1: Loopback PCM [Loopback PCM]
  Subdevices: 8/8
  Subdevice #0: subdevice #0
  Subdevice #1: subdevice #1
  Subdevice #2: subdevice #2
  Subdevice #3: subdevice #3
  Subdevice #4: subdevice #4
  Subdevice #5: subdevice #5
  Subdevice #6: subdevice #6
  Subdevice #7: subdevice #7

The only thing i can see as the difference between the instance that works is Java version. On instance that work properly :

java -version
openjdk version "11.0.14.1" 2022-02-08
OpenJDK Runtime Environment (build 11.0.14.1+1-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.14.1+1-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)

Perhaps it’s worth trying with the same java version to see if that makes a difference.

Java updated but still exact same error.
Server rebooted after updating.

root@dev2:/home/ubuntu# java -version
openjdk version "11.0.14.1" 2022-02-08
OpenJDK Runtime Environment (build 11.0.14.1+1-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.14.1+1-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)

root@dev2:/home/ubuntu# update-alternatives --config java
There is only one alternative in link group java (providing /usr/bin/java): /usr/lib/jvm/java-11-openjdk-amd64/bin/java
Nothing to configure.

This is not on Docker, is it?

Correct, this is not on docker.
OS: Ubuntu 20.04.4 LTS (Focal Fossa)

And you don’t have a desktop environment on that instance, right? Anything else running on the server?

Desktop environment is not installed

ps -e | grep -E -i "xfce|kde|gnome"
     57 ?        00:00:00 kdevtmpfs

Nothing else, only thing i can think is of is that in initial-script we have google-chrome “warm up” section where we actually run google-chrome and google-chrome headless but those process are killed after some time and aren’t present in current process tree. Also there is service for asg protection of the instance but that is not related.

ps-aux.txt (16.7 KB)

It’s baffling.
What chrome flags do you have set in jibri.conf?

chrome {
// The flags which will be passed to chromium when launching
flags = [
“–use-fake-ui-for-media-stream”,
“–start-maximized”,
“–kiosk”,
“–enabled”,
“–autoplay-policy=no-user-gesture-required”,
“–disable-web-security”,
“–disable-infobars”,
“–log-file=/var/log/jitsi/jibri/chromedriver.log”
]
}
It is very baffling because it is working on some environments and not only on one. Is there any way that this could be related to config of jitsi-meet instance to which jibri instance is connected ?I don’t see how it could be but no other ideas.

Just reminder, when i change

audio-device = “plug:dsnoop”

it works

Is this instance connected to a different JMS from the ones that work?

Yes because every environment have different jitsi-meet instance. All Jibri instances are made from same AMI, its just that they have different jibri.conf made dinamically. So looking at wider picture only difference is jitsi-meet instance they are connected to.

Well, that can definitely be an issue. To confirm, try connecting this Jibri instance to the JMS that works with the others. Ideally, you want to use a Jibri instance that’s closest to the JMS it’ll be connecting to as far as release date. There was some issue with aloop that was fixed a while back, for instance.

Ok after removing peace by peace we found that app.bundle.js is causing this issue, specifically usage of
JitsiMeetJS.createLocalTracks
which we used to implement volume-meter.

            return dispatch(getAvailableDevices())
                .then(devices => {
                    const newAudioInputDevices = devices.filter(nDevice => nDevice.kind === "audioinput");
                    const onlyNewDevices = newAudioInputDevices.filter(
                        (nDevice) =>
                            !_cachedAudioInputDevices.find(
                                (device) => device.deviceId === nDevice.deviceId
                            )
                    );
                    createLocalAudioTracks(onlyNewDevices).then(audioTracks => {
                        return audioTracks.map(({jitsiTrack}) => {
                            if (jitsiTrack) {
                                jitsiTrack.on(
                                    JitsiTrackEvents.TRACK_AUDIO_LEVEL_CHANGED,
                                    audioLevel => dispatch(trackAudioLevelChanged(jitsiTrack, audioLevel))
                                );
                            }
                        });
                    }).catch();
                    _cachedAudioInputDevices = [...newAudioInputDevices];

But i am still unable to see how is this affecting jibri recording and why at the end jibri recording works when i change plug:bsnoop to plug:dsnoop.
Another thing i notices when changing plug:bsnoop to plug:dsnoop is that audio is not actually captured, i suppose because it didn’t use correct loopback device.

Tried changing .asoundrc config as below :

pcm.amix {
  type dmix
  ipc_key 219345
  slave.pcm "hw:Loopback_1,0,0"
}

pcm.asnoop {
  type dsnoop
  ipc_key 219346
  slave.pcm "hw:Loopback_1,0,1"
}

pcm.aduplex {
  type asym
  playback.pcm "amix"
  capture.pcm "asnoop"
}

pcm.bmix {
  type dmix
  ipc_key 219347
  slave.pcm "hw:Loopback_1,1,1"
}

pcm.bsnoop {
  type dsnoop
  ipc_key 219348
  slave.pcm "hw:Loopback_1,1,0"
}

pcm.bduplex {
  type asym
  playback.pcm "bmix"
  capture.pcm "bsnoop"
}

pcm.pjsua {
  type plug
  slave.pcm "bduplex"
}

pcm.!default {
  type plug
  slave.pcm "aduplex"
}

and it again doesn’t work with this JS implementation but works without.

Any clues , could this be related to jitsi version ?

Updated jitsi to latest version and i still have the same issue…

Probably a stupid suggestion but sometimes ugly workarounds can save the day, how about bypassing alsa and its mysteries and switching to pulseaudio ?

Thanks, tried that and recording now works, file is properly saved but i am not having audio in saved mp4 file, undependable on JMS server i connect on, only video.
FFMPEG logs , jicofo logs and jibri logs show that everything is fine.

When i add

echo $ARGS >>/tmp/ffmpeg.log
ps auxww | grep pulse | grep -v grep >>/tmp/ffmpeg.log
cat /tmp/ffmpeg.log 
-y -v info -f x11grab -draw_mouse 0 -r 30 -s 1920x1080 -thread_queue_size 4096 -i :0.0+0,0 -f pulse -thread_queue_size 4096 -i default -acodec aac -strict -2 -ar 44100 -b:a 128k -af aresample=async=1 -c:v libx264 -preset veryfast -profile:v main -level 3.1 -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f mp4 /mnt/efs/recordings/inoakgbhprhkphsr/prvasoba_2022-04-28-11-45-12.mp4
jibri    2168138  0.0  0.2 1669536 17580 ?       Sl   10:57   0:02 /usr/bin/pulseaudio --start --log-target=syslog
ubuntu   2187232  0.0  0.2 356624 18036 ?        Ssl  11:33   0:00 /usr/bin/pulseaudio --daemonize=no --log-target=journal
jibri    2193286  0.0  0.0   8616  3256 ?        S    11:45   0:00 /bin/bash /usr/local/bin/ffmpeg -y -v info -f x11grab -draw_mouse 0 -r 30 -s 1920x1080 -thread_queue_size 4096 -i :0.0+0,0 -f pulse -thread_queue_size 4096 -i default -acodec aac -strict -2 -ar 44100 -b:a 128k -af aresample=async=1 -c:v libx264 -preset veryfast -profile:v main -level 3.1 -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f mp4 /mnt/efs/recordings/inoakgbhprhkphsr/prvasoba_2022-04-28-11-45-12.mp4
jibri    2193299  0.0  0.0   8616   264 ?        R    11:45   0:00 /bin/bash /usr/local/bin/ffmpeg -y -v info -f x11grab -draw_mouse 0 -r 30 -s 1920x1080 -thread_queue_size 4096 -i :0.0+0,0 -f pulse -thread_queue_size 4096 -i default -acodec aac -strict -2 -ar 44100 -b:a 128k -af aresample=async=1 -c:v libx264 -preset veryfast -profile:v main -level 3.1 -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f mp4 /mnt/efs/recordings/inoakgbhprhkphsr/prvasoba_2022-04-28-11-45-12.mp4


And here are the logs from syslog from pulseaudio.

Apr 28 13:34:13 jibri-10-41-1-99 pulseaudio[734]: [pulseaudio] alsa-util.c: Disabling timer-based scheduling because running inside a VM.
Apr 28 13:34:13 jibri-10-41-1-99 dbus-daemon[647]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.12' (uid=997 pid=734 comm="/usr/bin/pulseaudio --start --log-target=syslog " label="unconfined")
Apr 28 13:34:13 jibri-10-41-1-99 pulseaudio[734]: [pulseaudio] alsa-util.c: Disabling timer-based scheduling because running inside a VM.
Apr 28 13:35:05 jibri-10-41-1-99 pulseaudio[1933]: Disabling timer-based scheduling because running inside a VM.
Apr 28 13:35:05 jibri-10-41-1-99 pulseaudio[1933]: Disabling timer-based scheduling because running inside a VM.
Apr 28 13:38:45 jibri-10-41-1-99 pulseaudio[734]: [alsa-sink-Loopback PCM] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write.
Apr 28 13:38:45 jibri-10-41-1-99 pulseaudio[734]: [alsa-sink-Loopback PCM] alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_aloop'. Please report this issue to the ALSA developers.
Apr 28 13:38:45 jibri-10-41-1-99 pulseaudio[734]: [alsa-sink-Loopback PCM] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Apr 28 13:39:17 jibri-10-41-1-99 pulseaudio[734]: [alsa-source-Loopback PCM] alsa-source.c: ALSA woke us up to read new data from the device, but there was actually nothing to read.
Apr 28 13:39:17 jibri-10-41-1-99 pulseaudio[734]: [alsa-source-Loopback PCM] alsa-source.c: Most likely this is a bug in the ALSA driver 'snd_aloop'. Please report this issue to the ALSA developers.
Apr 28 13:39:17 jibri-10-41-1-99 pulseaudio[734]: [alsa-source-Loopback PCM] alsa-source.c: We were woken up with POLLIN set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

Besides the changes explained here Tip: Pulseaudio support for Jibri is there anything else to be done on jitsi/jibri side ?

I tried moving to generic kernel-109 but with no luck.

Out of ideas