1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
// Copyright (c) 2007 Nicholas Marriott <nicholas.marriott@gmail.com>
//
// Permission to use, copy, modify, and distribute this software for any
// purpose with or without fee is hereby granted, provided that the above
// copyright notice and this permission notice appear in all copies.
//
// THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
// WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
// MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
// ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
// WHATSOEVER RESULTING FROM LOSS OF MIND, USE, DATA OR PROFITS, WHETHER
// IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING
// OUT OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
use std::io::BufWriter;
use std::{
fs::File,
io::{LineWriter, Write},
sync::atomic::{AtomicI32, Ordering},
};
use crate::compat::{stravis, vis_flags};
use crate::event_::event_set_log_callback;
use crate::*;
macro_rules! log_debug {
($($arg:tt)*) => {$crate::log::log_debug_rs(format_args!($($arg)*))};
}
pub(crate) use log_debug;
// can't use File because it's open before fork which causes issues with how file works
static LOG_FILE: Mutex<Option<LineWriter<File>>> = Mutex::new(None);
static LOG_LEVEL: AtomicI32 = AtomicI32::new(0);
const DEFAULT_ORDERING: Ordering = Ordering::SeqCst;
/// C `vendor/tmux/log.c:34`: `static void log_event_cb(__unused int severity, const char *msg)`
unsafe extern "C-unwind" fn log_event_cb(_severity: c_int, msg: *const u8) {
unsafe { log_debug!("{}", _s(msg)) }
}
/// C `vendor/tmux/log.c:41`: `void log_add_level(void)`
pub fn log_add_level() {
LOG_LEVEL.fetch_add(1, DEFAULT_ORDERING);
}
/// C `vendor/tmux/log.c:48`: `int log_get_level(void)`
pub fn log_get_level() -> i32 {
LOG_LEVEL.load(DEFAULT_ORDERING)
}
/// C `vendor/tmux/log.c:55`: `void log_open(const char *name)`
pub fn log_open(name: &CStr) {
if LOG_LEVEL.load(DEFAULT_ORDERING) == 0 {
return;
}
log_close();
let pid = std::process::id();
let Ok(file) = std::fs::File::options()
.read(false)
.append(true)
.create(true)
.open(format!("tmux-{}-{}.log", name.to_str().unwrap(), pid))
else {
return;
};
*LOG_FILE.lock().unwrap() = Some(LineWriter::new(file));
unsafe { event_set_log_callback(Some(log_event_cb)) };
}
/// C `vendor/tmux/log.c:75`: `void log_toggle(const char *name)`
pub fn log_toggle(name: &CStr) {
if LOG_LEVEL.fetch_xor(1, DEFAULT_ORDERING) == 0 {
log_open(name);
log_debug!("log opened");
} else {
log_debug!("log closed");
log_close();
}
}
/// C `vendor/tmux/log.c:90`: `void log_close(void)`
pub fn log_close() {
// If we drop the file when it's already closed it will panic in debug mode.
// Because of this and our use of fork, extra care has to be made when closing the file.
// see std::sys::pal::unix::fs::debug_assert_fd_is_open;
use std::os::fd::AsRawFd;
if let Some(mut old_handle) = LOG_FILE.lock().unwrap().take() {
let _flush_err = old_handle.flush(); // TODO
match old_handle.into_inner() {
Ok(file) => unsafe {
libc::close(file.as_raw_fd());
std::mem::forget(file);
},
Err(err) => {
let lw = err.into_inner();
// TODO this is invalid, and compiler version dependent, but prevents a memory leak
// need a way to properly get out the file and drop the buffer
unsafe {
let bw = std::mem::transmute::<
std::io::LineWriter<std::fs::File>,
BufWriter<File>,
>(lw);
let (file, _) = bw.into_parts();
std::mem::forget(file);
}
}
}
unsafe {
event_set_log_callback(None);
}
}
}
#[track_caller]
pub fn log_debug_rs(args: std::fmt::Arguments) {
// Fast path when logging is disabled: a single atomic load, matching C
// tmux's `if (log_level == 0) return;`. Must not take the LOG_FILE mutex
// here - log_debug! is called thousands of times per frame on the hot
// parse/redraw path, and locking a mutex per call saturates CPU under
// heavy TUI output (the pane-freeze bug).
if LOG_LEVEL.load(DEFAULT_ORDERING) == 0 {
return;
}
log_vwrite_rs(args, "");
}
#[track_caller]
fn log_vwrite_rs(args: std::fmt::Arguments, prefix: &str) {
unsafe {
if LOG_FILE.lock().unwrap().is_none() {
return;
}
let msg = CString::new(format!("{args}")).unwrap();
let mut out = null_mut();
if stravis(
&mut out,
msg.as_ptr().cast(),
vis_flags::VIS_OCTAL | vis_flags::VIS_CSTYLE | vis_flags::VIS_TAB | vis_flags::VIS_NL,
) == -1
{
return;
}
let duration = std::time::SystemTime::now()
.duration_since(std::time::SystemTime::UNIX_EPOCH)
.unwrap_or_default();
let secs = duration.as_secs();
let micros = duration.subsec_micros();
let str_out = CStr::from_ptr(out.cast()).to_string_lossy();
if let Some(f) = LOG_FILE.lock().unwrap().as_mut() {
let location = std::panic::Location::caller();
let file = location.file();
let line = location.line();
let _ = f.write_fmt(format_args!(
"{secs}.{micros:06} {file}:{line} {prefix}{str_out}\n"
));
}
crate::free_(out);
}
}
/// C `vendor/tmux/log.c:140`: `__dead void fatal(const char *msg, ...)`
pub fn fatal(msg: &str) -> ! {
let os_error = std::io::Error::last_os_error();
let error_msg = os_error.to_string();
let prefix = format!("fatal: {error_msg}: ");
log_vwrite_rs(format_args!("{msg}"), &prefix);
std::process::exit(1)
}
macro_rules! fatalx_ {
($fmt:literal $(, $args:expr)* $(,)?) => {
crate::log::fatalx_c(format_args!($fmt $(, $args)*))
};
}
pub(crate) use fatalx_;
pub fn fatalx_c(args: std::fmt::Arguments) -> ! {
log_vwrite_rs(args, "fatal: ");
std::process::exit(1)
}
#[track_caller]
/// C `vendor/tmux/log.c:157`: `__dead void fatalx(const char *msg, ...)`
pub fn fatalx(msg: &str) -> ! {
let location = std::panic::Location::caller();
let file = location.file();
let line = location.line();
log_vwrite_rs(format_args!("{file}:{line} {msg}"), "fatal: ");
std::process::exit(1)
}
#[cfg(test)]
mod tests {
use super::*;
// Both checks below read/mutate the process-global LOG_LEVEL / LOG_FILE, so
// they must run as a single (non-parallel) test to avoid racing each other.
#[test]
fn test_log_level_and_disabled_fast_path() {
// Regression (bug 5): the logging-disabled fast path must gate on the
// LOG_LEVEL atomic ALONE and must not take the LOG_FILE mutex - on the
// hot parse/redraw path that lock, taken thousands of times per frame,
// saturated the CPU and froze panes under heavy TUI output. Prove the
// fast path never touches LOG_FILE by calling log_debug! while holding
// that mutex: with the fix it returns via the atomic check; a regression
// to locking LOG_FILE here would deadlock (std Mutex is not reentrant).
assert_eq!(log_get_level(), 0, "logging must be disabled for this test");
{
let _held = LOG_FILE.lock().unwrap();
log_debug!("hot-path message {} {}", 1, "two");
}
// C `vendor/tmux/log.c`: log_add_level increments and log_get_level
// reads the level counter. Restore it afterwards so the global stays at
// its disabled default for any later use.
log_add_level();
assert_eq!(log_get_level(), 1);
LOG_LEVEL.fetch_sub(1, DEFAULT_ORDERING);
assert_eq!(log_get_level(), 0);
}
}