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
//! A logger implementation which outputs log messages from CasperLabs crates to the terminal.

mod settings;
mod structured_message;
mod terminal_logger;

use std::{
    collections::BTreeMap,
    time::{Duration, SystemTime, UNIX_EPOCH},
};

use log::{self, Level, LevelFilter, Log, Metadata, Record, SetLoggerError};

pub use self::terminal_logger::TerminalLogger;
use crate::newtypes::CorrelationId;
pub use settings::{Settings, Style};

#[doc(hidden)]
pub const PAYLOAD_KEY: &str = "payload=";
pub(crate) const METRIC_METADATA_TARGET: &str = "METRIC";
pub(crate) const CASPERLABS_METADATA_TARGET: &str = "casperlabs_";
pub(crate) const MESSAGE_TEMPLATE_KEY: &str = "message_template";
pub(crate) const DEFAULT_MESSAGE_TEMPLATE: &str = "{message}";
pub(crate) const DEFAULT_MESSAGE_KEY: &str = "message";

/// Initializes the global logger using the given settings.
///
/// The logger will write all log messages from crates prefixed with "casperlabs_" to stdout, and
/// can also log internal metrics generated by the Execution Engine.
///
/// Returns an error if the global logger has already been set in this process.
pub fn initialize(settings: Settings) -> Result<(), SetLoggerError> {
    let logger = Box::new(TerminalLogger::new(&settings));
    initialize_with_logger(logger, settings)
}

/// This and the `TerminalLogger` are public but undocumented to allow functional testing of this
/// crate, e.g. by passing a logger composed of a `TerminalLogger`.
#[doc(hidden)]
pub fn initialize_with_logger(
    logger: Box<dyn Log>,
    settings: Settings,
) -> Result<(), SetLoggerError> {
    if settings.max_level() == LevelFilter::Off && !settings.enable_metrics() {
        // No logging required
        return Ok(());
    }

    log::set_boxed_logger(logger)?;
    log::set_max_level(settings.max_level());
    Ok(())
}

/// Logs a message using the given format and properties.
///
/// # Arguments
///
/// * `log_level` - log level of the message to be logged
/// * `message_format` - a message template to apply over properties by key
/// * `properties` - a collection of machine readable key / value properties which will be logged
#[inline]
pub fn log_details(
    log_level: Level,
    message_format: String,
    mut properties: BTreeMap<&str, String>,
) {
    let logger = log::logger();

    let metadata = Metadata::builder()
        .target(CASPERLABS_METADATA_TARGET)
        .level(log_level)
        .build();

    if !logger.enabled(&metadata) {
        return;
    }

    properties.insert(MESSAGE_TEMPLATE_KEY, message_format);

    let record = Record::builder()
        .metadata(metadata)
        .key_values(&properties)
        .build();

    logger.log(&record);
}

/// Logs the duration of a specific operation.
///
/// # Arguments
///
/// * `correlation_id` - a shared identifier used to group metrics
/// * `metric` - the name of the metric
/// * `tag` - a grouping tag for the metric
/// * `duration` - in seconds
#[inline]
pub fn log_duration(correlation_id: CorrelationId, metric: &str, tag: &str, duration: Duration) {
    let duration_in_seconds: f64 = duration.as_secs_f64();

    log_metric(
        correlation_id,
        metric,
        tag,
        "duration_in_seconds",
        duration_in_seconds,
    )
}

/// Logs the details of the specified metric.
///
/// # Arguments
///
/// * `correlation_id` - a shared identifier used to group metrics
/// * `metric` - the name of the metric
/// * `tag` - a grouping tag for the metric
/// * `metric_key` - property key for metric's value
/// * `metric_value` - numeric value of metric
#[inline]
pub fn log_metric(
    correlation_id: CorrelationId,
    metric: &str,
    tag: &str,
    metric_key: &str,
    metric_value: f64,
) {
    let logger = log::logger();

    let metadata = Metadata::builder()
        .target(METRIC_METADATA_TARGET)
        .level(Level::Info)
        .build();

    if !logger.enabled(&metadata) {
        return;
    }

    let from_epoch = SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .expect("UNIX EPOCH ERROR");

    let milliseconds_since_epoch = from_epoch.as_millis() as i64;

    // https://prometheus.io/docs/instrumenting/exposition_formats/
    let tsd_metric = format!(
        "{}{{tag=\"{}\"}} {} {:?}",
        metric, tag, metric_value, milliseconds_since_epoch
    );

    let mut properties = BTreeMap::new();
    properties.insert("correlation_id", correlation_id.to_string());
    properties.insert("time-series-data", tsd_metric);
    properties.insert(metric_key, format!("{:?}", metric_value));
    properties.insert(
        DEFAULT_MESSAGE_KEY,
        format!("{} {} {}", metric, tag, metric_value),
    );

    let record = Record::builder()
        .metadata(metadata)
        .key_values(&properties)
        .build();

    logger.log(&record);
}