Recording deleted after upgrading to v5.1.1 (2023101900)

[LGPoly]

Hi :)

We upgraded last Friday morning to v5.1.1 (2023101900) as we were eager to get the fix #517 as you can imagine.

Unfortunately we had to rollback this morning due to many recordings disappearing from the database during the weekend. They were still properly listed in Zoom, but not in the plugin, so not in Moodle.
We rolled back to the previous 5.1.0 version, and 521 recordings were added back by launching the task

These recordings were not created over the weekend but in the weeks before, hence this post, to hopefully get some help and figure out the issue.

At some point it means the task to delete the recordings did something unexpected, but probably on Friday or during the weekend, and we don't have the full log being "old" so can't point out the moment.

We tried to replicate the issue in a staging area but the task not rolling as often has proven to be difficult.
Still, if we manually delete a recording from weeks ago in staging, it's not fetched by the task, unless we change the delay in get_meeting_recordings.php to something like:
$from = gmdate('Y-m-d', strtotime('-1 year', $now));
$to = gmdate('Y-m-d', strtotime('+1 week', $now));
Which makes sense, but doesn't explain the deletions that happened..

Could it be a difference between the API calls get_recording_url_list() and get_user_recordings()? Which are used in the task to delete vs the task to get of the meeting recordings?

Also, are we the only experiencing this issue?

Thanks for your help,

Lucas

[jrchamp]

Thanks @LGPoly for reporting this issue. I'll have to take a closer look, because I didn't intend to change the delete task's behavior (because it already was using meeting UUIDs).

[jrchamp]

So far, I haven't been able to reproduce the issue. My recording entries are successfully located. Which scopes have you granted for recordings?

[LGPoly]

Many thanks for the follow-up @jrchamp!
We've only enabled the scope /recording:read:admin for the recordings, as it seems to be the only one necessary.
We've actually enabled every scopes, except the one to Recycle licenses (zoom | utmost), (zoom | recycleonjoin) user:write:admin as we're not looking for this feature.
We'll have to fully duplicate our production and try to reproduce the issue.
Thanks for your help :)

[jrchamp]

It sounds like your permission setup is correct. I'm very interested to know if you can provide more details about the issue.

[LGPoly]

Hi! We upgraded to v5.1.6 and did not encounter that issue again, so won't be able to give more details.
Are you ok if we close that issue?

[mjleblanc]

Hello @jrchamp, so my colleague Lucas spoke too soon last week. Last Friday (March 15th), we experience the same problem as before with the zoom plugin version v5.1.6. 783 recordings got delete from Moodle when the task delete_meeting_recordings was executed at 11 p.m.

This time, we were able to download the task log file. Here is the log file: mod_zoom_task_delete_meeting_recordings-16581430.pdf. As you can see, everything looks normal from the beginning. But at one point, it starts to delete all the recordings.

After those deletions, the cron task rolled normally, deleting 0, 1 or 2 recordings every now or then. Which is the normal for us.

Twenty recordings deleted came back without any actions from our part.

For the other ones, the only way to get the recordings back in Moodle, was to roll back the files mod\zoom\classes\task\delete_meeting_recordings.php, mod\zoom\classes\task\get_meeting_recordings.php and roll back the code of function get_recording_url_list in mod\zoom\classes\webservice.php with the 5.1.0 version of the zoom plugin.

Here is the log file of this task:
mod_zoom_task_get_meeting_recordings-16656000.pdf

By doing that, we got 458 recordings back. There is still 305 recordings missing.

We aren't able to reproduce the problem. Would it be possible that the Zoom API went down while the delete task was executing on Friday night? That would maybe explain why everything was fine from the start, but then started deleting everything at one point.

We never experience something like this with the 5.1.0 version.

If it changes anything, please note that the task get_meeting_recordings and delete_meeting_recordings roll every hour on our server.

[jrchamp]

It is possible!

1. Maybe the API is hitting the rate limit.
2. Then get_recording_url_list() is catching the rate limit exception and returning an empty array.
3. Which causes the delete_meeting_recordings() task to remove the items.

Since get_recording_url_list() is only really used by delete_meeting_recordings, we should probably allow the exception to bubble up to the task loop and avoid deleting the meeting recordings.

Add a try/catch within the loop:

moodle-mod_zoom/classes/task/delete_meeting_recordings.php

Lines 75 to 89 in a6dddce

	// Now check which recordings still exist on Zoom.
	$recordinglist = $service->get_recording_url_list($meetinguuid);
	foreach ($recordinglist as $recordinginfo) {
	$zoomrecordingid = trim($recordinginfo->recordingid);
	if (isset($recordings[$zoomrecordingid])) {
	mtrace('Recording id: ' . $zoomrecordingid . ' exist(s)...skipping');
	unset($recordings[$zoomrecordingid]);
	}
	}
	// If recordings are in Moodle but not in Zoom, we need to remove them from Moodle as well.
	foreach ($recordings as $zoomrecordingid => $recording) {
	mtrace('Deleting recording with id: ' . $zoomrecordingid . ' as corresponding record on zoom has been removed.');
	$DB->delete_records('zoom_meeting_recordings', ['zoomrecordingid' => $zoomrecordingid]);
	}

To get this:

            try {
                // Now check which recordings still exist on Zoom.
                $recordinglist = $service->get_recording_url_list($meetinguuid);
                foreach ($recordinglist as $recordinginfo) {
                    $zoomrecordingid = trim($recordinginfo->recordingid);
                    if (isset($recordings[$zoomrecordingid])) {
                        mtrace('Recording id: ' . $zoomrecordingid . ' exist(s)...skipping');
                        unset($recordings[$zoomrecordingid]);
                    }
                }

                // If recordings are in Moodle but not in Zoom, we need to remove them from Moodle as well.
                foreach ($recordings as $zoomrecordingid => $recording) {
                    mtrace('Deleting recording with id: ' . $zoomrecordingid . ' as corresponding record on zoom has been removed.');
                    $DB->delete_records('zoom_meeting_recordings', ['zoomrecordingid' => $zoomrecordingid]);
                }
            } catch (moodle_exception $e) {
                    mtrace('Exception occurred: ' . $e->getMessage());
            }

And remove the try/catch from this:

moodle-mod_zoom/classes/webservice.php

Lines 999 to 1022 in a6dddce

	try {
	$url = 'meetings/' . $this->encode_uuid($meetingid) . '/recordings';
	$response = $this->make_call($url);
	if (!empty($response->recording_files)) {
	foreach ($response->recording_files as $recording) {
	if (!empty($recording->play_url) && isset($allowedrecordingtypes[$recording->file_type])) {
	$recordinginfo = new stdClass();
	$recordinginfo->recordingid = $recording->id;
	$recordinginfo->meetinguuid = $response->uuid;
	$recordinginfo->url = $recording->play_url;
	$recordinginfo->filetype = $recording->file_type;
	$recordinginfo->recordingtype = $allowedrecordingtypes[$recording->file_type];
	$recordinginfo->passcode = $response->password;
	$recordinginfo->recordingstart = strtotime($recording->recording_start);
	$recordings[$recording->id] = $recordinginfo;
	}
	}
	}
	} catch (moodle_exception $error) {
	// No recordings found for this meeting id.
	$recordings = [];
	}

To get this:

            $url = 'meetings/' . $this->encode_uuid($meetingid) . '/recordings';
            $response = $this->make_call($url);

            if (!empty($response->recording_files)) {
                foreach ($response->recording_files as $recording) {
                    if (!empty($recording->play_url) && isset($allowedrecordingtypes[$recording->file_type])) {
                        $recordinginfo = new stdClass();
                        $recordinginfo->recordingid = $recording->id;
                        $recordinginfo->meetinguuid = $response->uuid;
                        $recordinginfo->url = $recording->play_url;
                        $recordinginfo->filetype = $recording->file_type;
                        $recordinginfo->recordingtype = $allowedrecordingtypes[$recording->file_type];
                        $recordinginfo->passcode = $response->password;
                        $recordinginfo->recordingstart = strtotime($recording->recording_start);

                        $recordings[$recording->id] = $recordinginfo;
                    }
                }
            }

Also, you may want to reduce the frequency of the delete_meeting_recordings task, because it's not as time-sensitive as the get_meeting_recordings task.

[smbader]

Whether this relates to the issue or not, @jrchamp's suggestions make a lot of sense to incorporate. You don't want to continue work after an exception with bad data, instead you should halt.

Any suggestions on how we can recreate the issue for testing outside of production?

[jrchamp]

Hi @LGPoly @mjleblanc,

I've opened #593 that should help address the issue. If you are able to try it, that would help confirm that the issue is closer to being resolved.