Merge #773: gui: don't read bitcoind's stdout to avoid a deadlock

d0065898f70fbe14be7d269a686110e3bbbe7af8 loader: don't read bitcoind's stdout to avoid a deadlock (edouardparis)

Pull request description:

  "Forward port" of #770.

  It was possible to get into a state where we were waiting for lianad to start, which was waiting on a response from bitcoind which in turn was waiting on the GUI to make room in its piped stdout buffer. Deadlock.

  Instead of getting its logs from stdout, read its debug.log file.

ACKs for top commit:
  edouardparis:
    ACK d0065898f70fbe14be7d269a686110e3bbbe7af8

Tree-SHA512: 0c66190ba87b56b883d15463ad24e152e43b33bf235ba8fb2cab6978c6eace1fdf3b6280377548a92248b18b0fa05bd4ad698cb65beac92bb5f11bc8a4662052
This commit is contained in:
Antoine Poinsot 2023-11-01 16:28:32 +01:00
commit cf9404558f
No known key found for this signature in database
GPG Key ID: E13FC145CD3F4304
2 changed files with 77 additions and 30 deletions

View File

@ -6,7 +6,6 @@ use std::path::{Path, PathBuf};
use std::sync::Arc;
use std::thread;
use std::time;
use tokio::sync::Mutex;
use tracing::{info, warn};
@ -96,6 +95,16 @@ pub fn internal_bitcoind_cookie_path(bitcoind_datadir: &Path, network: &Network)
cookie_path
}
/// Path of the cookie file used by internal bitcoind on a given network.
pub fn internal_bitcoind_debug_log_path(lianad_datadir: &PathBuf, network: Network) -> PathBuf {
let mut debug_log_path = internal_bitcoind_datadir(lianad_datadir);
if let Some(dir) = bitcoind_network_dir(&network) {
debug_log_path.push(dir);
}
debug_log_path.push("debug.log");
debug_log_path
}
pub fn bitcoind_network_dir(network: &Network) -> Option<String> {
let dir = match network {
Network::Bitcoin => {
@ -152,7 +161,6 @@ impl std::fmt::Display for StartInternalBitcoindError {
pub struct Bitcoind {
_process: Arc<std::process::Child>,
pub config: BitcoindConfig,
pub stdout: Option<Arc<Mutex<std::process::ChildStdout>>>,
}
impl Bitcoind {
@ -206,8 +214,8 @@ impl Bitcoind {
let mut process = command
.args(&args)
.stdout(std::process::Stdio::piped())
.stderr(std::process::Stdio::piped())
// FIXME: can we pipe stderr to our logging system somehow?
.stdout(std::process::Stdio::null())
.spawn()
.map_err(|e| StartInternalBitcoindError::CommandError(e.to_string()))?;
@ -220,14 +228,6 @@ impl Bitcoind {
Err(e) => log::error!("Error while trying to wait for bitcoind: {}", e),
Ok(Some(status)) => {
log::error!("Bitcoind exited with status '{}'", status);
match process.wait_with_output() {
Err(e) => {
tracing::error!("Error while waiting for bitcoind to finish: {}", e)
}
Ok(o) => {
tracing::error!("stderr: {}", String::from_utf8_lossy(&o.stderr));
}
}
return Err(StartInternalBitcoindError::CookieFileNotFound(
config.cookie_path.to_string_lossy().into_owned(),
));
@ -248,7 +248,6 @@ impl Bitcoind {
.map_err(|e| StartInternalBitcoindError::BitcoinDError(e.to_string()))?;
Ok(Self {
stdout: process.stdout.take().map(|s| Arc::new(Mutex::new(s))),
config,
_process: Arc::new(process),
})

View File

@ -1,9 +1,9 @@
use std::convert::From;
use std::io::BufRead;
use std::io::ErrorKind;
use std::ops::DerefMut;
use std::fs::File;
use std::io::{BufRead, BufReader, ErrorKind, Seek, SeekFrom};
use std::path::{Path, PathBuf};
use std::sync::Arc;
use std::time::Duration;
use iced::{Alignment, Command, Length, Subscription};
use tracing::{debug, info, warn};
@ -27,7 +27,9 @@ use crate::{
config::Config as GUIConfig,
wallet::{Wallet, WalletError},
},
bitcoind::{stop_bitcoind, Bitcoind, StartInternalBitcoindError},
bitcoind::{
internal_bitcoind_debug_log_path, stop_bitcoind, Bitcoind, StartInternalBitcoindError,
},
daemon::{client, embedded::EmbeddedDaemon, model::*, Daemon, DaemonError},
};
@ -79,6 +81,7 @@ pub enum Message {
Loaded(Result<Arc<dyn Daemon + Sync + Send>, Error>),
BitcoindLog(Option<String>),
Failure(DaemonError),
None,
}
impl Loader {
@ -231,8 +234,12 @@ impl Loader {
}
}
if let Some(bitcoind) = &self.internal_bitcoind {
// NOTE: we take() the internal_bitcoind here to make sure the debug.log reader
// subscription is dropped.
if let Some(bitcoind) = self.internal_bitcoind.take() {
log::info!("Stopping managed bitcoind..");
bitcoind.stop();
log::info!("Managed bitcoind stopped.");
} else if self.waiting_daemon_bitcoind && self.gui_config.start_internal_bitcoind {
if let Ok(config) = Config::from_file(self.gui_config.daemon_config_path.clone()) {
if let Some(bitcoind_config) = &config.bitcoind_config {
@ -270,25 +277,64 @@ impl Loader {
self.daemon_started = false;
Command::none()
}
Message::None => Command::none(),
_ => Command::none(),
}
}
pub fn subscription(&self) -> Subscription<Message> {
if let Some(Some(bitcoind_stdout)) =
self.internal_bitcoind.as_ref().map(|b| b.stdout.clone())
{
iced::subscription::unfold(0, bitcoind_stdout, move |stdout| async {
let msg = {
let mut s = stdout.lock().await;
let mut s = std::io::BufReader::new(s.deref_mut());
let mut buffer = String::new();
match s.read_line(&mut buffer) {
Err(e) => Message::BitcoindLog(Some(e.to_string())),
Ok(_) => Message::BitcoindLog(Some(buffer)),
if self.internal_bitcoind.is_some() {
let log_path = internal_bitcoind_debug_log_path(&self.datadir_path, self.network);
iced::subscription::unfold(0, log_path, move |log_path| async move {
// Reduce the io load.
tokio::time::sleep(Duration::from_millis(500)).await;
// Open the log file and seek to its end, with some breathing room to make sure
// we don't skip all "UpdateTip" lines. This is to avoid making BufReader read
// the whole file every single time below.
let mut file = match File::open(&log_path) {
Ok(file) => file,
Err(e) => {
log::warn!("Opening bitcoind log file: {}", e);
return (Message::None, log_path);
}
};
(msg, stdout)
match file.metadata() {
Ok(m) => {
let file_len = m.len();
let offset = 1024 * 1024;
if file_len > offset {
if let Err(e) =
file.seek(SeekFrom::Start(file_len.saturating_sub(offset)))
{
log::error!("Seeking to end of bitcoind log file: {}", e);
}
}
}
Err(e) => {
log::error!("Getting bitcoind log file metadata: {}", e);
}
};
// Find the latest tip update line in bitcoind's debug.log. BufReader is only
// used to facilitates searching through the lines.
let reader = BufReader::new(file);
let last_update_tip = reader
.lines()
.into_iter()
.filter(|l| l.as_ref().map(|l| l.contains("UpdateTip")).unwrap_or(false))
.last();
match last_update_tip {
Some(Ok(line)) => (Message::BitcoindLog(Some(line)), log_path),
res => {
if let Some(Err(e)) = res {
log::error!("Reading bitcoind log file: {}", e);
} else {
log::warn!("Couldn't find an UpdateTip line in bitcoind log file.");
}
(Message::None, log_path)
}
}
})
} else {
Subscription::none()
@ -490,6 +536,7 @@ pub enum Error {
Config(ConfigError),
Daemon(DaemonError),
Bitcoind(StartInternalBitcoindError),
BitcoindLogs(std::io::Error),
}
impl std::fmt::Display for Error {
@ -499,6 +546,7 @@ impl std::fmt::Display for Error {
Self::Wallet(e) => write!(f, "Wallet error: {}", e),
Self::Daemon(e) => write!(f, "Liana daemon error: {}", e),
Self::Bitcoind(e) => write!(f, "Bitcoind error: {}", e),
Self::BitcoindLogs(e) => write!(f, "Bitcoind logs error: {}", e),
}
}
}