Adding logging to backup downloads

Author: bwmarkle

admin/class-boldgrid-backup-admin-core.php

@@ -2670,28 +2670,39 @@ public function boldgrid_backup_now_callback() {
 	 * @see Boldgrid_Backup_File::send_file()
 	 */
 	public function download_archive_file_callback() {
+		$log = new Boldgrid_Backup_Admin_Log( $this );
+		$log->init( 'backup-download.log' );
+		$log->add_separator();
+		$log->add( 'Attempting ajax download...' );
+
 		// Verify nonce, or die.
 		check_ajax_referer( 'archive_auth', 'wpnonce' );
 
 		// Check user capabilities.
 		if ( ! current_user_can( 'update_plugins' ) ) {
-			esc_html_e( 'Security violation (not authorized).', 'boldgrid-backup' );
+			$error = __( 'Security violation (not authorized).', 'boldgrid-backup' );
+			echo esc_html( $error );
+			$log->add( $error );
 			wp_die();
 		}
 
 		// Validate download_key.
 		if ( isset( $_POST['download_key'] ) && is_numeric( $_POST['download_key'] ) ) {
 			$download_key = (int) $_POST['download_key'];
 		} else {
-			esc_html_e( 'INVALID DOWNLOAD KEY', 'boldgrid-backup' );
+			$error = __( 'INVALID DOWNLOAD KEY', 'boldgrid-backup' );
+			echo esc_html( $error );
+			$log->add( $error );
 			wp_die();
 		}
 
 		// Validate download_filename.
 		if ( ! empty( $_POST['download_filename'] ) ) {
 			$download_filename = sanitize_file_name( $_POST['download_filename'] );
 		} else {
-			esc_html_e( 'INVALID DOWNLOAD FILENAME', 'boldgrid-backup' );
+			$error = __( 'INVALID DOWNLOAD FILENAME', 'boldgrid-backup' );
+			echo esc_html( $error );
+			$log->add( $error );
 			wp_die();
 		}
 
@@ -2700,7 +2711,9 @@ public function download_archive_file_callback() {
 
 		// Check WP_Filesystem method; ensure it is "direct".
 		if ( 'direct' !== $access_type ) {
-			esc_html_e( 'WP_Filesystem method is not "direct"', 'boldgrid-backup' );
+			$error = __( 'WP_Filesystem method is not "direct"', 'boldgrid-backup' );
+			echo esc_html( $error );
+			$log->add( $error );
 			wp_die();
 		}
 
@@ -2709,7 +2722,9 @@ public function download_archive_file_callback() {
 
 		// If no files were found, then abort.
 		if ( empty( $archives ) ) {
-			esc_html_e( 'NO BACKUP ARCHIVES FOUND', 'boldgrid-backup' );
+			$error = __( 'NO BACKUP ARCHIVES FOUND', 'boldgrid-backup' );
+			echo esc_html( $error );
+			$log->add( $error );
 			wp_die();
 		}
 
@@ -2721,7 +2736,9 @@ public function download_archive_file_callback() {
 
 		// Verify filename.
 		if ( $download_filename !== $filename ) {
-			esc_html_e( 'FILE NOT FOUND', 'boldgrid-backup' );
+			$error = __( 'FILE NOT FOUND', 'boldgrid-backup' );
+			echo esc_html( $error );
+			$log->add( $error );
 			wp_die();
 		}
 
@@ -2734,6 +2751,7 @@ public function download_archive_file_callback() {
 		}
 
 		// Send the file and die nicely.
+		$log->add( 'Request validated successfully. Now on to sending the file...' );
 		Boldgrid_Backup_File::send_file( $filepath, $filesize );
 	}
 

includes/class-boldgrid-backup-file.php

@@ -30,27 +30,34 @@ class Boldgrid_Backup_File {
 	 * @param int    $filesize File size (optional).
 	 */
 	public static function send_file( $filepath, $filesize = null ) {
-		WP_Filesystem();
-		global $wp_filesystem;
+		$core = apply_filters( 'boldgrid_backup_get_core', null );
+		$log  = new Boldgrid_Backup_Admin_Log( $core );
+		$log->init( 'backup-download.log' );
+		$log->add( 'Initializing send_file() method...' );
 
-		if ( empty( $filepath ) || ! $wp_filesystem->exists( $filepath ) ) {
+		if ( empty( $filepath ) || ! $core->wp_filesystem->exists( $filepath ) ) {
+			$log->add( 'Invalid filepath.' );
 			wp_redirect( get_site_url(), 404 );
 		}
 
 		$filename = basename( $filepath );
 
 		if ( empty( $filesize ) ) {
-			$filesize = $wp_filesystem->size( $filepath );
+			$filesize = $core->wp_filesystem->size( $filepath );
 		}
 
 		// Send header.
+		$log->add( 'Sending headers...' );
 		header( 'Content-Disposition: attachment; filename="' . $filename . '"' );
 		header( 'Content-Transfer-Encoding: binary' );
 		header( 'Content-Type: binary/octet-stream' );
 		header( 'Content-Length: ' . $filesize );
 
 		// Check and flush output buffer if needed.
-		if ( 0 !== ob_get_level() ) {
+		$ob_level = ob_get_level();
+		$log->add( 'Output buffering level: ' . $ob_level );
+		if ( 0 !== $ob_level ) {
+			$log->add( 'Calling ob_end_flush().' );
 			ob_end_flush();
 		}
 
@@ -78,17 +85,36 @@ public static function send_file( $filepath, $filesize = null ) {
 		// If we can't open the file, abort.
 		$handle = fopen( $filepath, 'rb' ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_fopen
 		if ( false === $handle ) {
+			$log->add( 'Invalid handle. fopen failed.' );
 			wp_die();
 		}
 
 		// Loop through the file and send it 1MB at a time.
+		$buffer_size = 1024 * 1024;
+		$log->add( 'Beginnig to send file... Buffer size: ' . size_format( $buffer_size, 2 ) );
 		while ( ! feof( $handle ) ) {
-			$buffer = fread( $handle, 1024 * 1024 ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_fread
+			$log->add( 'Reading buffer...' );
+			$time_start = microtime( true );
+			$buffer     = fread( $handle, $buffer_size ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_fread
+			$duration   = microtime( true ) - $time_start;
+			$log->add( 'Buffer read in ' . round( $duration, 4 ) . ' seconds.' );
+
+			$log->add( 'Sending buffer...' );
+			$time_start = microtime( true );
 			echo $buffer; // phpcs:ignore WordPress.XSS.EscapeOutput.OutputNotEscaped
+			$duration = microtime( true ) - $time_start;
+			$log->add( 'Buffer sent in ' . round( $duration, 4 ) . ' seconds.' );
 		}
+		$log->add( 'Finished sending file.' );
 
-		fclose( $handle ); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_fclose
+		$log->add( 'Closing file...' );
+		if ( fclose( $handle ) ) { // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_fclose
+			$log->add( 'File closed successfully.' );
+		} else {
+			$log->add( 'Error closing file.' );
+		}
 
+		$log->add( 'send_file() method complete. Ending with wp_die().' );
 		wp_die();
 	}
 }