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
use cu29_clock::{ClockProvider, RobotClock};
use cu29_intern_strs::read_interned_strings;
use cu29_log::CuLogEntry;
use cu29_traits::{CuResult, WriteStream};
use kanal::{bounded, Sender};
use log::{Log, Record};
use once_cell::sync::OnceCell;
use std::path::PathBuf;
use std::sync::Arc;
use std::thread;
use std::thread::{sleep, JoinHandle};
use std::time::Duration;

// The logging system is basically a global queue.
static QUEUE: OnceCell<Sender<CuLogEntry>> = OnceCell::new();

/// The lifetime of this struct is the lifetime of the logger.
pub struct LoggerRuntime {
    clock: RobotClock,
    handle: Option<JoinHandle<()>>,
    extra_text_logger: Option<ExtraTextLogger>,
}

impl ClockProvider for LoggerRuntime {
    fn get_clock(&self) -> RobotClock {
        self.clock.clone()
    }
}

impl LoggerRuntime {
    /// destination is the binary stream in which we will log the structured log.
    /// extra_text_logger is the logger that will log the text logs in real time. This is slow and only for debug builds.
    pub fn init(
        clock_source: RobotClock,
        destination: impl WriteStream<CuLogEntry> + 'static,
        extra_text_logger: Option<ExtraTextLogger>,
    ) -> Self {
        if (!cfg!(debug_assertions)) && extra_text_logger.is_some() {
            eprintln!("Extra text logger is only available in debug builds. Ignoring the extra text logger.");
        };

        let mut runtime = LoggerRuntime {
            clock: clock_source,
            extra_text_logger,
            handle: None,
        };
        let (s, handle) = runtime.initialize_queue(destination);
        QUEUE
            .set(s)
            .expect("Failed to initialize the logger queue.");
        runtime.handle = Some(handle);
        runtime
    }

    fn initialize_queue(
        &self,
        mut destination: impl WriteStream<CuLogEntry> + 'static,
    ) -> (Sender<CuLogEntry>, JoinHandle<()>) {
        let (sender, receiver) = bounded::<CuLogEntry>(100);

        #[cfg(debug_assertions)]
        let (index, extra_text_logger) = if let Some(extra) = &self.extra_text_logger {
            let index = Some(
                read_interned_strings(extra.path_to_index.as_path())
                    .expect("Failed to read the interned strings"),
            );
            let logger = Some(extra.logger.clone());
            (index, logger)
        } else {
            (None, None)
        };
        let clock = self.clock.clone();

        let handle = thread::spawn(move || {
            let receiver = receiver.clone();
            loop {
                if let Ok(mut cu_log_entry) = receiver.recv() {
                    // We don't need to be precise on this clock.
                    // If the user wants to really log a clock they should add it as a structured field.
                    cu_log_entry.time = clock.now();
                    if let Err(err) = destination.log(&cu_log_entry) {
                        eprintln!("Failed to log data: {}", err);
                    }

                    // This is only for debug builds with standard textual logging implemented.
                    #[cfg(debug_assertions)]
                    if let Some(index) = &index {
                        if let Some(ref logger) = extra_text_logger {
                            let stringified = cu29_log::rebuild_logline(index, &cu_log_entry);
                            match stringified {
                                Ok(s) => {
                                    let s = format!("[{}] {}", cu_log_entry.time, s);
                                    logger.log(
                                        &Record::builder()
                                            // TODO: forward this info in the CuLogEntry
                                            .level(log::Level::Debug)
                                            // .target("copper")
                                            //.module_path_static(Some("cu29_log"))
                                            //.file_static(Some("cu29_log"))
                                            //.line(Some(0))
                                            .args(format_args!("{}", s))
                                            .build(),
                                    ); // DO NOT TRY to split off this statement.
                                       // format_args! has to be in the same statement per structure and scoping.
                                }
                                Err(e) => {
                                    eprintln!("Failed to rebuild log line: {}", e);
                                }
                            }
                        }
                    }
                } else {
                    // means that the sender has disconnected, we can stop the thread.
                    break;
                }
            }
        });
        (sender, handle)
    }
    pub fn is_alive(&self) -> bool {
        QUEUE.get().is_some()
    }

    pub fn flush(&self) {
        if let Some(queue) = QUEUE.get() {
            loop {
                if queue.is_empty() {
                    break;
                }
                println!("Waiting for the queue to empty.");
                sleep(Duration::from_millis(1));
            }
        }
    }

    pub fn close(&mut self) {
        let queue = QUEUE.get();
        if queue.is_none() {
            eprintln!("Logger closed before it was initialized.");
            return;
        }
        self.flush();
        queue.unwrap().close();
        if let Some(handle) = self.handle.take() {
            handle.join().expect("Failed to join the logger thread.");
            self.handle = None;
        }
    }
}

impl Drop for LoggerRuntime {
    fn drop(&mut self) {
        self.close();
    }
}

/// This is to basically be able to see the logs in text format in real time.
/// THIS WILL SLOW DOWN THE LOGGING SYSTEM by an order of magnitude.
/// This will only be active for debug builds.
pub struct ExtraTextLogger {
    path_to_index: PathBuf,
    logger: Arc<dyn Log>,
}
impl ExtraTextLogger {
    pub fn new(path_to_index: PathBuf, logger: Box<dyn Log>) -> Self {
        ExtraTextLogger {
            path_to_index,
            logger: Arc::new(logger),
        }
    }
}

/// Function called from generated code to log data.
/// It moves entry by design, it will be absorbed in the queue.
#[inline]
pub fn log(entry: CuLogEntry) -> CuResult<()> {
    if let Some(queue) = QUEUE.get() {
        let err = queue
            .send(entry)
            .map_err(|e| format!("Failed to send data to the logger, did you hold the reference to the logger long enough? {:?}", e).into());
        err
    } else {
        Err("Logger not initialized.".into())
    }
}

#[cfg(test)]
mod tests {
    use crate::CuLogEntry;
    use bincode::config::standard;
    use cu29_log::value::Value;

    #[test]
    fn test_encode_decode_structured_log() {
        let log_entry = CuLogEntry {
            time: 0.into(),
            msg_index: 1,
            paramname_indexes: vec![2, 3],
            params: vec![Value::String("test".to_string())],
        };
        let encoded = bincode::encode_to_vec(&log_entry, standard()).unwrap();
        println!("{:?}", encoded);
        let decoded_tuple: (CuLogEntry, usize) =
            bincode::decode_from_slice(&encoded, standard()).unwrap();
        assert_eq!(log_entry, decoded_tuple.0);
    }
}