I am getting Recording failed to start after preparing the recording

Question

I am getting Recording failed to start after preparing the recording

dhanasekaranw2s opened this issue 3 years ago · 3 comments

Hi,

I am attached below my logs, please help me to get resolve this.

Jicofo log

Jicofo 2022-02-17 10:13:56.471 INFO: [33] JibriSession.processJibriIqFromJibri#435: Updating status from JIBRI: for newchat@conference.jitsi.mydomain.com
Jicofo 2022-02-17 10:13:56.471 INFO: [33] JibriSession.handleJibriStatusUpdate#623: Got Jibri status update: Jibri jibribrewery@internal.auth.jitsi.mydomain.com/jibri has status pending and failure reason null, current Jibri jid is jibribrewery@internal.auth.jitsi.mydomain.com/jibri
Jicofo 2022-02-17 10:13:56.471 INFO: [33] [room=newchat@conference.jitsi.mydomain.com meeting_id=bc816cba-badc-43cf-92c8-17c81093e74d] JibriRecorder.handleStartRequest#113: Started Jibri session
Jicofo 2022-02-17 10:14:28.442 INFO: [33] JibriSession.processJibriIqFromJibri#435: Updating status from JIBRI: for newchat@conference.jitsi.mydomain.com
Jicofo 2022-02-17 10:14:28.442 INFO: [33] JibriSession.handleJibriStatusUpdate#623: Got Jibri status update: Jibri jibribrewery@internal.auth.jitsi.mydomain.com/jibri has status off and failure reason error, current Jibri jid is jibribrewery@internal.auth.jitsi.mydomain.com/jibri
Jicofo 2022-02-17 10:14:28.442 INFO: [33] JibriSession.clearPendingTimeout#575: Jibri is no longer pending, cancelling pending timeout task
Jicofo 2022-02-17 10:14:28.442 INFO: [33] JibriSession.handleJibriStatusUpdate#662: Jibri failed, trying to fall back to another Jibri
Jicofo 2022-02-17 10:14:28.442 SEVERE: [33] JibriSession.startInternal#308: Unable to find an available Jibri, can't start
Jicofo 2022-02-17 10:14:28.443 WARNING: [33] JibriSession.handleJibriStatusUpdate#673: Failed to fall back to another Jibri, this session has now failed: org.jitsi.jicofo.jibri.JibriSession$StartException$AllBusy: All jibri instances are busy
org.jitsi.jicofo.jibri.JibriSession$StartException$AllBusy: All jibri instances are busy
at org.jitsi.jicofo.jibri.JibriSession.startInternal(JibriSession.java:312)
at org.jitsi.jicofo.jibri.JibriSession.start(JibriSession.java:286)
at org.jitsi.jicofo.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:599)
at org.jitsi.jicofo.jibri.JibriSession.handleJibriStatusUpdate(JibriSession.java:666)
at org.jitsi.jicofo.jibri.JibriSession.processJibriIqFromJibri(JibriSession.java:437)
at org.jitsi.jicofo.jibri.JibriSession.processJibriIqRequestFromJibri(JibriSession.java:421)
at org.jitsi.jicofo.jibri.BaseJibri.doHandleIQRequest(BaseJibri.kt:158)
at org.jitsi.jicofo.jibri.BaseJibri.incomingIqQueue$lambda-0(BaseJibri.kt:56)
at org.jitsi.utils.queue.PacketQueue$HandlerAdapter.handleItem(PacketQueue.java:416)
at org.jitsi.utils.queue.AsyncQueueHandler$1.run(AsyncQueueHandler.java:136)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Jicofo 2022-02-17 10:14:28.444 INFO: [33] [room=newchat@conference.jitsi.mydomain.com meeting_id=bc816cba-badc-43cf-92c8-17c81093e74d] JibriRecorder.publishJibriRecordingStatus#158: Got jibri status off and failure error
Jicofo 2022-02-17 10:14:28.444 INFO: [33] [room=newchat@conference.jitsi.mydomain.com meeting_id=bc816cba-badc-43cf-92c8-17c81093e74d] JibriRecorder.publishJibriRecordingStatus#183: Publishing new jibri-recording-status: in: newchat@conference.jitsi.mydomain.com
Jicofo 2022-02-17 10:14:28.445 INFO: [33] JibriSession.cleanupSession#390: Cleaning up current JibriSession
Jicofo 2022-02-17 10:14:31.657 INFO: [22] [room=newchat@conference.jitsi.mydomain.com meeting_id=bc816cba-badc-43cf-92c8-17c81093e74d] JitsiMeetConferenceImpl.onMemberLeft#795: Member left:4507ef8f
Jicofo 2022-02-17 10:14:31.657 WARNING: [22] [room=newchat@conference.jitsi.mydomain.com meeting_id=bc816cba-badc-43cf-92c8-17c81093e74d] JitsiMeetConferenceImpl.onMemberLeft#810: Participant not found for 4507ef8f. Terminated already or never started?
Jicofo 2022-02-17 10:14:31.658 INFO: [22] [room=newchat@conference.jitsi.mydomain.com meeting_id=bc816cba-badc-43cf-92c8-17c81093e74d] JitsiMeetConferenceImpl.stop#436: Stopped

Jibri log

2022-02-17 10:14:24.376 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:24.883 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:25.390 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:25.896 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:26.403 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:26.910 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:27.417 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:27.924 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:28.430 FINE: [54] CallPage$visit$$inlined$measureTimedValue$lambda$1.apply#58: Not joined yet: Cannot read properties of undefined (reading 'isJoined')
2022-02-17 10:14:28.435 SEVERE: [54] CallPage.visit#65: Timed out waiting for call page to load
2022-02-17 10:14:28.437 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.onSeleniumStateChange#215: Transitioning from state Starting up to Error: FailedToJoinCall SESSION Failed to join the call
2022-02-17 10:14:28.438 INFO: [54] [session_id=mledrcfqjzvsqchc] StatefulJibriService.onServiceStateChange#39: File recording service transitioning from state Starting up to Error: FailedToJoinCall SESSION Failed to join the call
2022-02-17 10:14:28.439 INFO: [54] XmppApi$createServiceStatusHandler$1.invoke#243: Current service had an error Error: FailedToJoinCall SESSION Failed to join the call, sending error iq
2022-02-17 10:14:28.439 FINE: [54] JibriStatsDClient.incrementCounter#38: Incrementing statsd counter: stop:recording
2022-02-17 10:14:28.440 INFO: [54] JibriManager.stopService#260: Stopping the current service
2022-02-17 10:14:28.440 INFO: [54] [session_id=mledrcfqjzvsqchc] FileRecordingJibriService.stop#181: Stopping capturer
2022-02-17 10:14:28.440 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSubprocess.stop#75: Stopping ffmpeg process
2022-02-17 10:14:28.440 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSubprocess.stop#89: ffmpeg exited with value null
2022-02-17 10:14:28.440 INFO: [54] [session_id=mledrcfqjzvsqchc] FileRecordingJibriService.stop#183: Quitting selenium
2022-02-17 10:14:28.441 INFO: [54] [session_id=mledrcfqjzvsqchc] FileRecordingJibriService.stop#190: No media was recorded, deleting directory and skipping metadata file & finalize
2022-02-17 10:14:28.441 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#336: Leaving call and quitting browser
2022-02-17 10:14:28.441 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#339: Recurring call status checks cancelled
2022-02-17 10:14:28.456 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#345: Got 21 log entries for type browser
2022-02-17 10:14:28.503 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#345: Got 1047 log entries for type driver
2022-02-17 10:14:28.630 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#345: Got 0 log entries for type client
2022-02-17 10:14:28.630 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#354: Leaving web call
2022-02-17 10:14:28.660 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#361: Quitting chrome driver
2022-02-17 10:14:28.730 INFO: [54] [session_id=mledrcfqjzvsqchc] JibriSelenium.leaveCallAndQuitBrowser#363: Chrome driver quit
2022-02-17 10:14:28.731 INFO: [54] JibriStatusManager$$special$$inlined$observable$1.afterChange#72: Busy status has changed: BUSY -> IDLE
2022-02-17 10:14:28.731 FINE: [54] WebhookClient$updateStatus$1.invokeSuspend#107: Updating 0 subscribers of status
2022-02-17 10:14:28.732 INFO: [54] XmppApi.updatePresence#144: Jibri reports its status is now JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), publishing presence to connections
2022-02-17 10:14:34.345 FINE: [17] WebhookClient$updateStatus$1.invokeSuspend#107: Updating 0 subscribers of status

Answer 1 · 2022-02-17T10:49:51.000Z

@bbaldino @damencho

Answer 2 · 2022-02-17T17:03:51.000Z

You'd have more luck in community.jitsi.org for something like this. 2022-02-17 10:14:28.435 SEVERE: [54] CallPage.visit#65: Timed out waiting for call page to load is in the logs, I'd search the community for that; there are a couple different things that can cause it. If it never works, you probably have an auth config problem. If it sometimes works, it could be that this is happening on first jibri boot, which can be a problem (chrome starts up slow the first time).

Answer 3 · 2022-02-18T06:07:18.000Z

Thanks for your response @bbaldino

I installed Jitsi and Jibri on same instance.
Server Details
Instance Size : t2.xlarge
RAM : 16 GB
OS: Ubuntu 18.04
vCPU : 4

I tried in community as well. please find my configurations below, If I do anything wrong please correct me.

Jibri config
jibri {
// A unique identifier for this Jibri
// TODO: eventually this will be required with no default
id = ""
// Whether or not Jibri should return to idle state after handling
// (successfully or unsuccessfully) a request. A value of 'true'
// here means that a Jibri will NOT return back to the IDLE state
// and will need to be restarted in order to be used again.
single-use-mode = false
api {
http {
external-api-port = 2222
internal-api-port = 3333
}
xmpp {
// See example_xmpp_envs.conf for an example of what is expected here
environments = [
{
name = "prod environment"
xmpp-server-hosts = ["jitsi.mydomain.com"]
xmpp-domain = "jitsi.mydomain.com"

            control-muc {
                domain = "internal.auth.jitsi.mydomain.com"
                room-name = "JibriBrewery"
                nickname = "jibri"
            }

            control-login {
                domain = "auth.jitsi.mydomain.com"
                username = "jibri"
                password = "jibri1234"
            }

            call-login {
                domain = "recorder.jitsi.mydomain.com"
                username = "recorder"
                password = "recorder1234"
            }

            strip-from-room-domain = "conference."
            usage-timeout = 0
            trust-all-xmpp-certs = true
        }]
}

}
recording {
recordings-directory = "/recordings"
# TODO: make this an optional param and remove the default
finalize-script = "/finalize_recording.sh"
}
streaming {
// A list of regex patterns for allowed RTMP URLs. The RTMP URL used
// when starting a stream must match at least one of the patterns in
// this list.
rtmp-allow-list = [
// By default, all services are allowed
".*"
]
}
chrome {
// The flags which will be passed to chromium when launching
flags = [
"--use-fake-ui-for-media-stream",
"--start-maximized",
"--kiosk",
"--enabled",
"--disable-infobars",
"--autoplay-policy=no-user-gesture-required",
"--headless",
"--no-sandbox",
"--log-file=/var/log/jitsi/jibri/chromedriver.log"
"--ignore-certificate-errors",
"--disable-setuid-sandbox",
"--disable-web-security",
"--disable-dev-shm-usage"
]
}
stats {
enable-stats-d = true
}
webhook {
// A list of subscribers interested in receiving webhook events
subscribers = []
}
jwt-info {
// The path to a .pem file which will be used to sign JWT tokens used in webhook
// requests. If not set, no JWT will be added to webhook requests.
# signing-key-path = "/path/to/key.pem"

// The kid to use as part of the JWT
# kid = "key-id"

// The issuer of the JWT
# issuer = "issuer"

// The audience of the JWT
# audience = "audience"

// The TTL of each generated JWT.  Can't be less than 10 minutes.
# ttl = 1 hour

}
call-status-checks {
// If all clients have their audio and video muted and if Jibri does not
// detect any data stream (audio or video) comming in, it will stop
// recording after NO_MEDIA_TIMEOUT expires.
no-media-timeout = 30 seconds

// If all clients have their audio and video muted, Jibri consideres this
// as an empty call and stops the recording after ALL_MUTED_TIMEOUT expires.
all-muted-timeout = 10 minutes

// When detecting if a call is empty, Jibri takes into consideration for how
// long the call has been empty already. If it has been empty for more than
// DEFAULT_CALL_EMPTY_TIMEOUT, it will consider it empty and stop the recording.
default-call-empty-timeout = 30 seconds

}
}

browser log
, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:14.041Z" "[JitsiMeetJS.js]" "\u003CObject.getGlobalOnErrorHandler>: " "UnhandledError: Strophe: BOSH-Connection...",
"source": "console-api",
"timestamp": 1.645163834042e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:14.041Z" "[modules/xmpp/strophe.util.js]" "\u003CObject.Br.ot.Strophe.log>: " "Strophe: BOSH-Connection failed:...",
"source": "console-api",
"timestamp": 1.645163834042e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/app.bundle.min.js?v=5818 137:840652 "2022-02-18T05:57:14.044Z" "[connection.js]" "\u003Cr.o>: " "CONNECTION FAILED:" "connection.otherError"",
"source": "console-api",
"timestamp": 1.645163834044e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/app.bundle.min.js?v=5818 137:840652 "2022-02-18T05:57:14.052Z" "[features/base/connection]" "connection.otherError"",
"source": "console-api",
"timestamp": 1.645163834053e+12
}, {
"level": "WARNING",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:14.119Z" "[modules/RTC/RTCUtils.js]" "Failed to get access to local media. NotFoundError: Requested device not ...",
"source": "console-api",
"timestamp": 1.645163834119e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/app.bundle.min.js?v=5818 137:840652 "2022-02-18T05:57:14.120Z" "[features/base/tracks]" "Failed to create local tracks" Array(1) DOMException: Requested device not f...",
"source": "console-api",
"timestamp": 1.64516383412e+12
}, {
"level": "WARNING",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.078Z" "[modules/xmpp/strophe.util.js]" "\u003CObject.Br.ot.Strophe.log>: " "Strophe: Disconnect was called b...",
"source": "console-api",
"timestamp": 1.645163847319e+12
}, {
"level": "WARNING",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.079Z" "[modules/xmpp/strophe.util.js]" "\u003CObject.Br.ot.Strophe.log>: " "Strophe: Disconnect was called b...",
"source": "console-api",
"timestamp": 1.645163847319e+12
}, {
"level": "WARNING",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.303Z" "[JitsiMeetJS.js]" "\u003CObject.init>: " "Analytics disabled, disposing."",
"source": "console-api",
"timestamp": 1.645163847324e+12
}, {
"level": "WARNING",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.304Z" "[modules/statistics/AnalyticsAdapter.js]" "\u003CObject.dispose>: " "Disposing of analytics adapter."",
"source": "console-api",
"timestamp": 1.645163847324e+12
}, {
"level": "WARNING",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.307Z" "[modules/statistics/AnalyticsAdapter.js]" "\u003CObject.dispose>: " "Disposing of analytics adapter."",
"source": "console-api",
"timestamp": 1.645163847325e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.506Z" "[JitsiMeetJS.js]" "\u003CObject.getGlobalOnErrorHandler>: " "UnhandledError: Strophe: BOSH-Connection...",
"source": "console-api",
"timestamp": 1.645163847509e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/lib-jitsi-meet.min.js?v=5818 1:3281 "2022-02-18T05:57:27.506Z" "[modules/xmpp/strophe.util.js]" "\u003CObject.Br.ot.Strophe.log>: " "Strophe: BOSH-Connection failed:...",
"source": "console-api",
"timestamp": 1.645163847509e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/app.bundle.min.js?v=5818 137:840652 "2022-02-18T05:57:27.507Z" "[connection.js]" "\u003Cr.o>: " "CONNECTION FAILED:" "connection.otherError"",
"source": "console-api",
"timestamp": 1.64516384751e+12
}, {
"level": "SEVERE",
"message": "https://jitsi.mydomain.com/libs/app.bundle.min.js?v=5818 137:840652 "2022-02-18T05:57:27.512Z" "[features/base/connection]" "connection.otherError"",
"source": "console-api",
"timestamp": 1.645163847513e+12
}, "..." ]

2022-02-18 05:57:44.357 INFO: [56] JibriSelenium.leaveCallAndQuitBrowser#348: [2022-02-18T05:57:44+0000] [INFO] [ac87537906dbe65ac2e0db3cf3d66ff4] COMMAND GetLog {
"type": "driver"
}

2022-02-18 05:57:44.357 INFO: [56] JibriSelenium.leaveCallAndQuitBrowser#348: [2022-02-18T05:57:44+0000] [FINE] DevTools WebSocket Command: Runtime.evaluate (id=242) 09196120ADD77AD976F0BE90FAC6B25B {
"awaitPromise": false,
"expression": "1",
"returnByValue": true
}

2022-02-18 05:57:44.357 INFO: [56] JibriSelenium.leaveCallAndQuitBrowser#348: [2022-02-18T05:57:44+0000] [FINE] DevTools WebSocket Response: Runtime.evaluate (id=242) 09196120ADD77AD976F0BE90FAC6B25B {
"result": {
"description": "1",
"type": "number",
"value": 1
}
}