flutter/shorebird-updater
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix: Improve rust logging and error clarity (#63)

Browse Source 
* Improve logging from our rust code.

Fixes https://github.com/shorebirdtech/updater/issues/56
and https://github.com/shorebirdtech/shorebird/issues/779
and https://github.com/shorebirdtech/updater/issues/61

I did not add a test for the log handling when starting a thread
(didn't see an easy way to do so, without mocking the update
call itself?)

I also did not add a test for changing the log verbosity.

Verified both by hand.

* Reduce logging.

Also removed unused assets.rs file.
Also silenced "file not found" error case on first boot.

* Improve coverage
This commit is contained in:
Eric Seidel
2023-07-31 14:51:08 -07:00
committed by GitHub
parent abe4126da5
commit ae85cf5125
8 changed files with 127 additions and 164 deletions
Download Patch File Download Diff File Expand all files Collapse all files
library/src/android.rs
+34
View File
@@ -220,6 +220,40 @@ mod tests {
let tmp_dir = TempDir::new("example").unwrap();
let error = super::find_and_open_lib(tmp_dir.path(), "libapp.so").unwrap_err();
assert!(error.to_string().contains("No such file or directory"));
// Write an empty file (invalid apk) to the base apk.
let base_apk_path = tmp_dir.path().join("base.apk");
std::fs::File::create(&base_apk_path).unwrap();
let error = super::find_and_open_lib(tmp_dir.path(), "libapp.so").unwrap_err();
assert_eq!(error.to_string(), "invalid Zip archive: Invalid zip header");
// Write an empty zip as the base.apk.
let libapp_path = tmp_dir.path().join("libapp.so");
std::fs::File::create(&libapp_path).unwrap();
let base_apk_path = tmp_dir.path().join("base.apk");
let mut zip = zip::ZipWriter::new(std::fs::File::create(&base_apk_path).unwrap());
zip.finish().unwrap();
let error = super::find_and_open_lib(tmp_dir.path(), "libapp.so").unwrap_err();
assert_eq!(error.to_string(), "Library not found in APK");
// Create a valid apk (zip) with an empty libapp.so with the right path.
use std::io::Write;
let tmp_dir = TempDir::new("example").unwrap();
// Write an empty libapp.so and zip it into an apk.
let libapp_path = tmp_dir.path().join("libapp.so");
std::fs::File::create(&libapp_path).unwrap();
let base_apk_path = tmp_dir.path().join("base.apk");
let arch = super::android_arch_names();
let lib_path = format!("lib/{}/libapp.so", arch.lib_dir);
let mut zip = zip::ZipWriter::new(std::fs::File::create(&base_apk_path).unwrap());
zip.start_file(&lib_path, zip::write::FileOptions::default())
.unwrap();
zip.write_all(&std::fs::read(&libapp_path).unwrap())
.unwrap();
zip.finish().unwrap();
let zip_location = super::find_and_open_lib(tmp_dir.path(), "libapp.so").unwrap();
// Success!
assert_eq!(zip_location.internal_path, lib_path);
}
#[test]
library/src/assets.rs
-122
View File
@@ -1,122 +0,0 @@
// Modeled after AAssetManager from Android NDK
use std::fmt::{Debug, Formatter};
use std::io::{Read, Seek};
/// The AssetProvider is a trait which allows the updater to load assets from
/// different sources.
pub struct AssetProvider {
ops: Box<dyn AssetProviderOps>,
}
impl Debug for AssetProvider {
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
f.debug_struct("AssetProvider")
.field("ops", &"Box<dyn AssetProviderOps>")
.finish()
}
}
pub trait AssetProviderOps: Send + Sync + 'static {
fn open(&self, path: &str) -> Option<Asset>;
}
pub struct Asset {
ops: Box<dyn AssetOps>,
}
impl Asset {
pub fn new(ops: Box<dyn AssetOps>) -> Self {
Self { ops }
}
}
pub trait AssetOps: Read + Seek {
fn close(&mut self) {}
}
impl AssetProvider {
pub fn empty() -> Self {
Self {
ops: Box::new(EmptyAssetProviderOps {}),
}
}
pub fn new(ops: Box<dyn AssetProviderOps>) -> Self {
Self { ops }
}
pub fn open(&self, path: &str) -> Option<Asset> {
info!("AssetProvider::open({:?})", path);
self.ops.open(path)
}
}
impl Read for Asset {
fn read(&mut self, buf: &mut [u8]) -> std::io::Result<usize> {
info!("Asset::read({:?})", buf);
self.ops.read(buf)
}
}
impl Seek for Asset {
fn seek(&mut self, pos: std::io::SeekFrom) -> std::io::Result<u64> {
info!("Asset::seek({:?})", pos);
self.ops.seek(pos)
}
}
impl Drop for Asset {
fn drop(&mut self) {
info!("Asset::drop()");
self.ops.close();
}
}
struct EmptyAssetProviderOps {}
impl AssetProviderOps for EmptyAssetProviderOps {
fn open(&self, _path: &str) -> Option<Asset> {
info!("EmptyAssetProviderOps::open({:?})", _path);
None
}
}
// struct FileSystemAssetProviderOps {
// }
// impl AssetProviderOps for FileSystemAssetProviderOps {
// fn open(&self, path: &str) -> Option<Asset> {
// let file = std::fs::File::open(path);
// if file.is_err() {
// return None;
// }
// let file = file.unwrap();
// Some(Asset {
// ops: Box::new(FileSystemAssetOps { file }),
// })
// }
// }
// #[derive(Debug)]
// struct FileSystemAssetOps {
// file: std::fs::File,
// }
// impl AssetOps for FileSystemAssetOps {
// fn close(&self, _asset: &Asset) {
// self.file.sync_all().unwrap();
// }
// }
// impl Read for FileSystemAssetOps {
// fn read(&mut self, buf: &mut [u8]) -> std::io::Result<usize> {
// self.file.read(buf)
// }
// }
// impl Seek for FileSystemAssetOps {
// fn seek(&mut self, pos: std::io::SeekFrom) -> std::io::Result<u64> {
// self.file.seek(pos)
// }
// }
library/src/c_api.rs
+13 -3
View File
@@ -305,6 +305,9 @@ mod test {
testing_reset_config();
// Should log but not crash.
assert_eq!(shorebird_init(std::ptr::null(), std::ptr::null()), false);
// free_string also doesn't crash with null.
shorebird_free_string(std::ptr::null_mut());
}
#[serial]
@@ -347,6 +350,7 @@ mod test {
// Number is 0 and path is empty (but do not crash) when we have an
// empty cache and update has not been called.
assert_eq!(shorebird_current_boot_patch_number(), 0);
assert_eq!(shorebird_next_boot_patch_number(), 0);
assert_eq!(shorebird_next_boot_patch_path(), null_mut());
@@ -410,13 +414,19 @@ mod test {
Ok(patch_bytes)
},
);
// There is an update available.
assert!(shorebird_check_for_update());
// Go ahead and do the update.
shorebird_update();
let version = shorebird_next_boot_patch_number();
assert_eq!(version, 1);
assert_eq!(shorebird_current_boot_patch_number(), 0);
assert_eq!(shorebird_next_boot_patch_number(), 1);
// Read path contents into memory and check against expected.
let path = to_rust(shorebird_next_boot_patch_path()).unwrap();
let c_path = shorebird_next_boot_patch_path();
let path = to_rust(c_path).unwrap();
shorebird_free_string(c_path);
let new = std::fs::read_to_string(path).unwrap();
assert_eq!(new, expected_new);
}
library/src/cache.rs
+33 -9
View File
@@ -16,7 +16,7 @@ use crate::updater::UpdateError;
// https://stackoverflow.com/questions/67087597/is-it-possible-to-use-rusts-log-info-for-tests
#[cfg(test)]
use std::{println as info, println as warn}; // Workaround to use println! for logs.
use std::{println as info, println as warn, println as debug}; // Workaround to use println! for logs.
/// The public interace for talking about patches to the Cache.
#[derive(PartialEq, Debug)]
@@ -70,6 +70,15 @@ impl UpdaterState {
}
}
fn is_file_not_found(error: &anyhow::Error) -> bool {
for cause in error.chain() {
if let Some(io_error) = cause.downcast_ref::<std::io::Error>() {
return io_error.kind() == std::io::ErrorKind::NotFound;
}
}
false
}
impl UpdaterState {
pub fn is_known_good_patch(&self, patch_number: usize) -> bool {
self.successful_patches.iter().any(|v| v == &patch_number)
@@ -88,6 +97,7 @@ impl UpdaterState {
if self.is_known_bad_patch(patch_number) {
return;
}
// This is at least info! since we're in a failure state and want to log.
info!("Marking patch {} as bad", patch_number);
self.failed_patches.push(patch_number);
}
@@ -128,15 +138,15 @@ impl UpdaterState {
}
let validate_result = loaded.validate();
if let Err(e) = validate_result {
info!("Error while validating state: {:#}, clearing state.", e);
warn!("Error while validating state: {:#}, clearing state.", e);
return Self::new(cache_dir.to_owned(), release_version.to_owned());
}
loaded
}
Err(e) => {
// FIXME: Should match on errorKind and display a warning if it's
// not a file not found error.
info!("No cached state, making empty: {:#}", e);
if !is_file_not_found(&e) {
warn!("Error loading state: {:#}, clearing state.", e);
}
Self::new(cache_dir.to_owned(), release_version.to_owned())
}
}
@@ -211,7 +221,7 @@ impl UpdaterState {
fn validate_slot(&self, slot: &Slot) -> bool {
// Check if the patch is known bad.
if self.is_known_bad_patch(slot.patch_number) {
info!("Slot {:?} is known bad.", slot);
debug!("Slot {:?} is known bad.", slot);
return false;
}
let index = self
@@ -220,7 +230,7 @@ impl UpdaterState {
.position(|s| s.patch_number == slot.patch_number);
let patch_path = self.patch_path_for_index(index.unwrap());
if !patch_path.exists() {
info!("Slot {:?} {} does not exist.", slot, patch_path.display());
debug!("Slot {:?} {} does not exist.", slot, patch_path.display());
return false;
}
// TODO: This should also check if the hash matches?
@@ -285,7 +295,7 @@ impl UpdaterState {
}
fn set_slot(&mut self, index: usize, slot: Slot) {
info!("Setting slot {} to {:?}", index, slot);
debug!("Setting slot {} to {:?}", index, slot);
if self.slots.len() < index + 1 {
// Make sure we're not filling with empty slots.
assert!(self.slots.len() == index);
@@ -351,7 +361,7 @@ impl UpdaterState {
patch.number, path
);
} else {
info!("Patch {} installed to {:?}", patch.number, path);
debug!("Patch {} installed to {:?}", patch.number, path);
}
Ok(())
@@ -462,6 +472,20 @@ mod tests {
let mut state = test_state(&tmp_dir);
let bad_patch = fake_patch(&tmp_dir, 1);
state.mark_patch_as_bad(bad_patch.number);
let number = bad_patch.number;
assert!(state.install_patch(bad_patch).is_err());
// Calling a second time should not error.
state.mark_patch_as_bad(number);
}
#[test]
fn is_file_not_found_test() {
use anyhow::Context;
assert!(!super::is_file_not_found(&anyhow::anyhow!("")));
let tmp_dir = TempDir::new("example").unwrap();
let path = tmp_dir.path().join("does_not_exist");
let result = std::fs::File::open(&path).context("foo");
assert!(result.is_err());
assert!(super::is_file_not_found(&result.unwrap_err()));
}
}
library/src/config.rs
+2 -2
View File
@@ -11,7 +11,7 @@ use std::sync::Mutex;
// https://stackoverflow.com/questions/67087597/is-it-possible-to-use-rusts-log-info-for-tests
#[cfg(test)]
use std::println as info; // Workaround to use println! for logs.
use std::println as debug; // Workaround to use println! for logs.
// cbindgen looks for const, ignore these so it doesn't warn about them.
@@ -112,7 +112,7 @@ pub fn set_config(
.to_owned(),
network_hooks,
};
info!("Updater configured with: {:?}", config);
debug!("Updater configured with: {:?}", new_config);
*config = Some(new_config);
Ok(())
library/src/logging.rs
+2 -4
View File
@@ -6,7 +6,7 @@ pub fn init_logging() {
android_logger::Config::default()
// `flutter` tool ignores non-flutter tagged logs.
.with_tag("flutter")
.with_max_level(log::LevelFilter::Debug),
.with_max_level(log::LevelFilter::Info),
);
debug!("Logging initialized");
}
@@ -15,9 +15,7 @@ pub fn init_logging() {
pub fn init_logging() {
// I could not figure out how to get fancier logging set up on iOS
// but logging to stderr seems to work.
use log::LevelFilter;
use std::io;
simple_logging::log_to(io::stderr(), LevelFilter::Info);
simple_logging::log_to(std::io::stderr(), log::LevelFilter::Info);
debug!("Logging initialized");
}
library/src/network.rs
+6 -6
View File
@@ -12,7 +12,7 @@ use crate::config::{current_arch, current_platform, UpdateConfig};
// https://stackoverflow.com/questions/67087597/is-it-possible-to-use-rusts-log-info-for-tests
#[cfg(test)]
use std::println as info; // Workaround to use println! for logs.
use std::println as debug; // Workaround to use println! for logs.
fn patches_check_url(base_url: &str) -> String {
return format!("{}/api/v1/patches/check", base_url);
@@ -162,12 +162,12 @@ pub fn send_patch_check_request(
platform: current_platform().to_string(),
arch: current_arch().to_string(),
};
info!("Sending patch check request: {:?}", request);
debug!("Sending patch check request: {:?}", request);
let url = &patches_check_url(&config.base_url);
let patch_check_request_fn = config.network_hooks.patch_check_request_fn;
let response = patch_check_request_fn(url, request)?;
info!("Patch check response: {:?}", response);
debug!("Patch check response: {:?}", response);
return Ok(response);
}
@@ -176,17 +176,17 @@ pub fn download_to_path(
url: &str,
path: &Path,
) -> anyhow::Result<()> {
info!("Downloading patch from: {}", url);
debug!("Downloading patch from: {}", url);
// Download the file at the given url to the given path.
let download_file_hook = network_hooks.download_file_fn;
let mut bytes = download_file_hook(url)?;
// Ensure the download directory exists.
if let Some(parent) = path.parent() {
info!("Creating download directory: {:?}", parent);
debug!("Creating download directory: {:?}", parent);
std::fs::create_dir_all(parent)?;
}
info!("Writing download to: {:?}", path);
debug!("Writing download to: {:?}", path);
let mut file = File::create(path)?;
file.write_all(&mut bytes)?;
Ok(())
library/src/updater.rs
+37 -18
View File
@@ -6,6 +6,7 @@ use std::fs;
use std::io::{Read, Seek};
use std::path::{Path, PathBuf};
use anyhow::bail;
use anyhow::Context;
use crate::cache::{PatchInfo, UpdaterState};
@@ -19,7 +20,7 @@ use crate::yaml::YamlConfig;
// https://stackoverflow.com/questions/67087597/is-it-possible-to-use-rusts-log-info-for-tests
#[cfg(test)]
use std::{println as info, println as warn, println as error, println as debug}; // Workaround to use println! for logs.
use std::{println as info, println as error, println as debug}; // Workaround to use println! for logs.
#[cfg(test)]
// Expose testing_reset_config for integration tests.
@@ -31,7 +32,6 @@ pub use crate::network::{
pub enum UpdateStatus {
NoUpdate,
UpdateAvailable,
UpdateInstalled,
UpdateHadError,
}
@@ -40,7 +40,6 @@ impl Display for UpdateStatus {
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
match self {
UpdateStatus::NoUpdate => write!(f, "No update"),
UpdateStatus::UpdateAvailable => write!(f, "Update available"),
UpdateStatus::UpdateInstalled => write!(f, "Update installed"),
UpdateStatus::UpdateHadError => write!(f, "Update had error"),
}
@@ -113,7 +112,7 @@ pub fn init(app_config: AppConfig, yaml: &str) -> Result<(), UpdateError> {
.map_err(|err| UpdateError::InvalidArgument("yaml".to_string(), err.to_string()))?;
let libapp_path = libapp_path_from_settings(&app_config.original_libapp_paths)?;
info!("libapp_path: {:?}", libapp_path);
debug!("libapp_path: {:?}", libapp_path);
set_config(app_config, libapp_path, config, NetworkHooks::default())
.map_err(|err| UpdateError::InvalidState(err.to_string()))
}
@@ -132,7 +131,7 @@ pub fn check_for_update() -> anyhow::Result<bool> {
check_for_update_internal().map(|res| res.patch_available)
}
fn check_hash(path: &Path, expected_string: &str) -> anyhow::Result<bool> {
fn check_hash(path: &Path, expected_string: &str) -> anyhow::Result<()> {
let expected = hex::decode(expected_string).context("Invalid hash string from server.")?;
use sha2::{Digest, Sha256}; // Digest is needed for Sha256::new();
@@ -146,17 +145,24 @@ fn check_hash(path: &Path, expected_string: &str) -> anyhow::Result<bool> {
// Check that the length from copy is the same as the file size?
let hash = hasher.finalize();
let hash_matches = hash.as_slice() == expected;
// This is a common error for developers. We could avoid it entirely
// by sending the hash of libapp.so to the server and having the
// server only send updates when the hash matches.
// https://github.com/shorebirdtech/updater/issues/56
if !hash_matches {
warn!(
"Hash mismatch: {:?}, expected: {}, got: {:?}",
bail!(
"Update rejected: hash mismatch. Update was downloaded but \
contents did not match the expected hash. This is most often \
caused by using the same version number with a different app \
binary. Path: {:?}, expected: {}, got: {}",
path,
expected_string,
hex::encode(hash)
);
} else {
info!("Hash match: {:?}", path);
debug!("Hash match: {:?}", path);
}
return Ok(hash_matches);
return Ok(());
}
// This is just a place to put our terrible android hacks.
@@ -233,10 +239,11 @@ fn update_internal(_: &UpdaterLockState) -> anyhow::Result<UpdateStatus> {
prepare_for_install(&config, &download_path, &output_path)?;
// Check the hash before moving into place.
let hash_ok = check_hash(&output_path, &patch.hash)?;
if !hash_ok {
return Err(UpdateError::InvalidState("Hash mismatch. This is most often caused by using the same version number with a different app binary.".to_string()).into());
}
check_hash(&output_path, &patch.hash).context(format!(
"This app reports version {}, but the binary is different from \
the version {} that was submitted to Shorebird.",
config.release_version, config.release_version
))?;
// We're abusing the config lock as a UpdateState lock for now.
// This makes it so we never try to write to the UpdateState file from
@@ -270,12 +277,12 @@ where
{
use comde::de::Decompressor;
use comde::zstd::ZstdDecompressor;
info!("Patch is compressed, inflating...");
debug!("Patch is compressed, inflating...");
use std::io::{BufReader, BufWriter};
// Open all our files first for error clarity. Otherwise we might see
// PipeReader/Writer errors instead of file open errors.
info!("Reading patch file: {:?}", patch_path);
debug!("Reading patch file: {:?}", patch_path);
let compressed_patch_r = BufReader::new(
fs::File::open(patch_path)
.context(format!("Failed to open patch file: {:?}", patch_path))?,
@@ -383,7 +390,14 @@ pub fn report_launch_success() -> anyhow::Result<()> {
/// and install it if available.
pub fn start_update_thread() {
std::thread::spawn(move || {
let status = update().unwrap_or(UpdateStatus::UpdateHadError);
let result = update();
let status = match result {
Ok(status) => status,
Err(err) => {
error!("Update failed: {:?}", err);
UpdateStatus::UpdateHadError
}
};
info!("Update thread finished with status: {}", status);
});
}
@@ -458,11 +472,16 @@ mod tests {
fs::write(&input_path, "hello world").unwrap();
let expected = "b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9";
assert!(super::check_hash(&input_path, expected).unwrap());
assert!(super::check_hash(&input_path, expected).is_ok());
// modify hash to not match
let expected = "a94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9";
assert_eq!(super::check_hash(&input_path, expected).unwrap(), false);
// We don't check the full error string because it contains a path
// which varies on each run.
assert!(super::check_hash(&input_path, expected)
.unwrap_err()
.to_string()
.contains("Update rejected: hash mismatch. Update was downloaded"));
// invalid hashes should not match either
let expected = "foo";