diff options
Diffstat (limited to 'tools/journaldriver/src')
| -rw-r--r-- | tools/journaldriver/src/main.rs | 665 | ||||
| -rw-r--r-- | tools/journaldriver/src/tests.rs | 95 |
2 files changed, 760 insertions, 0 deletions
diff --git a/tools/journaldriver/src/main.rs b/tools/journaldriver/src/main.rs new file mode 100644 index 000000000000..a57bb3505ddc --- /dev/null +++ b/tools/journaldriver/src/main.rs @@ -0,0 +1,665 @@ +// Copyright (C) 2018 Vincent Ambo <mail@tazj.in> +// +// journaldriver is free software: you can redistribute it and/or +// modify it under the terms of the GNU General Public License as +// published by the Free Software Foundation, either version 3 of the +// License, or (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with this program. If not, see <http://www.gnu.org/licenses/>. + +//! This file implements journaldriver, a small application that +//! forwards logs from journald (systemd's log facility) to +//! Stackdriver Logging. +//! +//! Log entries are read continously from journald and are forwarded +//! to Stackdriver in batches. +//! +//! Stackdriver Logging has a concept of monitored resources. In the +//! simplest case this monitored resource will be the GCE instance on +//! which journaldriver is running. +//! +//! Information about the instance, the project and required security +//! credentials are retrieved from Google's metadata instance on GCP. +//! +//! To run journaldriver on non-GCP machines, users must specify the +//! `GOOGLE_APPLICATION_CREDENTIALS`, `GOOGLE_CLOUD_PROJECT` and +//! `LOG_NAME` environment variables. + +#[macro_use] extern crate failure; +#[macro_use] extern crate log; +#[macro_use] extern crate serde_derive; +#[macro_use] extern crate serde_json; +#[macro_use] extern crate lazy_static; + +extern crate chrono; +extern crate env_logger; +extern crate medallion; +extern crate serde; +extern crate systemd; +extern crate ureq; + +use chrono::offset::LocalResult; +use chrono::prelude::*; +use failure::ResultExt; +use serde_json::{from_str, Value}; +use std::env; +use std::fs::{self, File, rename}; +use std::io::{self, Read, ErrorKind, Write}; +use std::mem; +use std::path::PathBuf; +use std::process; +use std::time::{Duration, Instant}; +use systemd::journal::*; + +#[cfg(test)] +mod tests; + +const LOGGING_SERVICE: &str = "https://logging.googleapis.com/google.logging.v2.LoggingServiceV2"; +const ENTRIES_WRITE_URL: &str = "https://logging.googleapis.com/v2/entries:write"; +const METADATA_TOKEN_URL: &str = "http://metadata.google.internal/computeMetadata/v1/instance/service-accounts/default/token"; +const METADATA_ID_URL: &str = "http://metadata.google.internal/computeMetadata/v1/instance/id"; +const METADATA_ZONE_URL: &str = "http://metadata.google.internal/computeMetadata/v1/instance/zone"; +const METADATA_PROJECT_URL: &str = "http://metadata.google.internal/computeMetadata/v1/project/project-id"; + +/// Convenience type alias for results using failure's `Error` type. +type Result<T> = std::result::Result<T, failure::Error>; + +/// Representation of static service account credentials for GCP. +#[derive(Debug, Deserialize)] +struct Credentials { + /// PEM encoded private key + private_key: String, + + /// `kid` of this private key + private_key_id: String, + + /// "email" address of the service account + client_email: String, +} + +lazy_static! { + /// ID of the GCP project to which to send logs. + static ref PROJECT_ID: String = get_project_id(); + + /// Name of the log to write to (this should only be manually + /// configured if not running on GCP): + static ref LOG_NAME: String = env::var("LOG_NAME") + .unwrap_or("journaldriver".into()); + + /// Service account credentials (if configured) + static ref SERVICE_ACCOUNT_CREDENTIALS: Option<Credentials> = + env::var("GOOGLE_APPLICATION_CREDENTIALS").ok() + .and_then(|path| File::open(path).ok()) + .and_then(|file| serde_json::from_reader(file).ok()); + + /// Descriptor of the currently monitored instance. Refer to the + /// documentation of `determine_monitored_resource` for more + /// information. + static ref MONITORED_RESOURCE: Value = determine_monitored_resource(); + + /// Path to the directory in which journaldriver should persist + /// its cursor state. + static ref CURSOR_DIR: PathBuf = env::var("CURSOR_POSITION_DIR") + .unwrap_or("/var/lib/journaldriver".into()) + .into(); + + /// Path to the cursor position file itself. + static ref CURSOR_FILE: PathBuf = { + let mut path = CURSOR_DIR.clone(); + path.push("cursor.pos"); + path + }; + + /// Path to the temporary file used for cursor position writes. + static ref CURSOR_TMP_FILE: PathBuf = { + let mut path = CURSOR_DIR.clone(); + path.push("cursor.tmp"); + path + }; +} + +/// Convenience helper for retrieving values from the metadata server. +fn get_metadata(url: &str) -> Result<String> { + let response = ureq::get(url) + .set("Metadata-Flavor", "Google") + .timeout_connect(5000) + .timeout_read(5000) + .call(); + + if response.ok() { + // Whitespace is trimmed to remove newlines from responses. + let body = response.into_string() + .context("Failed to decode metadata response")? + .trim().to_string(); + + Ok(body) + } else { + let status = response.status_line().to_string(); + let body = response.into_string() + .unwrap_or_else(|e| format!("Metadata body error: {}", e)); + bail!("Metadata failure: {} ({})", body, status) + } +} + +/// Convenience helper for determining the project ID. +fn get_project_id() -> String { + env::var("GOOGLE_CLOUD_PROJECT") + .map_err(Into::into) + .or_else(|_: failure::Error| get_metadata(METADATA_PROJECT_URL)) + .expect("Could not determine project ID") +} + +/// Determines the monitored resource descriptor used in Stackdriver +/// logs. On GCP this will be set to the instance ID as returned by +/// the metadata server. +/// +/// On non-GCP machines the value is determined by using the +/// `GOOGLE_CLOUD_PROJECT` and `LOG_STREAM` environment variables. +/// +/// [issue #4]: https://github.com/tazjin/journaldriver/issues/4 +fn determine_monitored_resource() -> Value { + if let Ok(log) = env::var("LOG_STREAM") { + // The special value `global` is recognised as a log stream name that + // results in a `global`-type resource descriptor. This is useful in + // cases where Stackdriver Error Reporting is intended to be used on + // a non-GCE instance. See [issue #4][] for details. + if log == "global" { + return json!({ + "type": "global", + "labels": { + "project_id": PROJECT_ID.as_str(), + } + }); + } + + json!({ + "type": "logging_log", + "labels": { + "project_id": PROJECT_ID.as_str(), + "name": log, + } + }) + } else { + let instance_id = get_metadata(METADATA_ID_URL) + .expect("Could not determine instance ID"); + + let zone = get_metadata(METADATA_ZONE_URL) + .expect("Could not determine instance zone"); + + json!({ + "type": "gce_instance", + "labels": { + "project_id": PROJECT_ID.as_str(), + "instance_id": instance_id, + "zone": zone, + } + }) + } +} + +/// Represents the response returned by the metadata server's token +/// endpoint. The token is normally valid for an hour. +#[derive(Deserialize)] +struct TokenResponse { + expires_in: u64, + access_token: String, +} + +/// Struct used to store a token together with a sensible +/// representation of when it expires. +struct Token { + token: String, + fetched_at: Instant, + expires: Duration, +} + +impl Token { + /// Does this token need to be renewed? + fn is_expired(&self) -> bool { + self.fetched_at.elapsed() > self.expires + } +} + +/// Retrieves a token from the GCP metadata service. Retrieving these +/// tokens requires no additional authentication. +fn get_metadata_token() -> Result<Token> { + let body = get_metadata(METADATA_TOKEN_URL)?; + let token: TokenResponse = from_str(&body)?; + + debug!("Fetched new token from metadata service"); + + Ok(Token { + fetched_at: Instant::now(), + expires: Duration::from_secs(token.expires_in / 2), + token: token.access_token, + }) +} + +/// Signs a token using static client credentials configured for a +/// service account. This service account must have been given the +/// `Log Writer` role in Google Cloud IAM. +/// +/// The process for creating and signing these tokens is described +/// here: +/// +/// https://developers.google.com/identity/protocols/OAuth2ServiceAccount#jwt-auth +fn sign_service_account_token(credentials: &Credentials) -> Result<Token> { + use medallion::{Algorithm, Header, Payload}; + + let iat = Utc::now(); + let exp = iat.checked_add_signed(chrono::Duration::seconds(3600)) + .ok_or_else(|| format_err!("Failed to calculate token expiry"))?; + + let header = Header { + alg: Algorithm::RS256, + headers: Some(json!({ + "kid": credentials.private_key_id, + })), + }; + + let payload: Payload<()> = Payload { + iss: Some(credentials.client_email.clone()), + sub: Some(credentials.client_email.clone()), + aud: Some(LOGGING_SERVICE.to_string()), + iat: Some(iat.timestamp() as u64), + exp: Some(exp.timestamp() as u64), + ..Default::default() + }; + + let token = medallion::Token::new(header, payload) + .sign(credentials.private_key.as_bytes()) + .context("Signing service account token failed")?; + + debug!("Signed new service account token"); + + Ok(Token { + token, + fetched_at: Instant::now(), + expires: Duration::from_secs(3000), + }) +} + +/// Retrieve the authentication token either by using static client +/// credentials, or by talking to the metadata server. +/// +/// Which behaviour is used is controlled by the environment variable +/// `GOOGLE_APPLICATION_CREDENTIALS`, which should be configured to +/// point at a JSON private key file if service account authentication +/// is to be used. +fn get_token() -> Result<Token> { + if let Some(credentials) = SERVICE_ACCOUNT_CREDENTIALS.as_ref() { + sign_service_account_token(credentials) + } else { + get_metadata_token() + } +} + +/// This structure represents the different types of payloads +/// supported by journaldriver. +/// +/// Currently log entries can either contain plain text messages or +/// structured payloads in JSON-format. +#[derive(Debug, Serialize, PartialEq)] +#[serde(untagged)] +enum Payload { + TextPayload { + #[serde(rename = "textPayload")] + text_payload: String, + }, + JsonPayload { + #[serde(rename = "jsonPayload")] + json_payload: Value, + }, +} + +/// Attempt to parse a log message as JSON and return it as a +/// structured payload. If parsing fails, return the entry in plain +/// text format. +fn message_to_payload(message: Option<String>) -> Payload { + match message { + None => Payload::TextPayload { text_payload: "empty log entry".into() }, + Some(text_payload) => { + // Attempt to deserialize the text payload as a generic + // JSON value. + if let Ok(json_payload) = serde_json::from_str::<Value>(&text_payload) { + // If JSON-parsing succeeded on the payload, check + // whether we parsed an object (Stackdriver does not + // expect other types of JSON payload) and return it + // in that case. + if json_payload.is_object() { + return Payload::JsonPayload { json_payload } + } + } + + Payload::TextPayload { text_payload } + } + } +} + +/// Attempt to parse journald's microsecond timestamps into a UTC +/// timestamp. +/// +/// Parse errors are dismissed and returned as empty options: There +/// simply aren't any useful fallback mechanisms other than defaulting +/// to ingestion time for journaldriver's use-case. +fn parse_microseconds(input: String) -> Option<DateTime<Utc>> { + if input.len() != 16 { + return None; + } + + let seconds: i64 = (&input[..10]).parse().ok()?; + let micros: u32 = (&input[10..]).parse().ok()?; + + match Utc.timestamp_opt(seconds, micros * 1000) { + LocalResult::Single(time) => Some(time), + _ => None, + } +} + +/// Converts a journald log message priority to a +/// Stackdriver-compatible severity number. +/// +/// Both Stackdriver and journald specify equivalent +/// severities/priorities. Conveniently, the names are the same. +/// Inconveniently, the numbers are not. +/// +/// For more information on the journald priorities, consult these +/// man-pages: +/// +/// * systemd.journal-fields(7) (section 'PRIORITY') +/// * sd-daemon(3) +/// * systemd.exec(5) (section 'SyslogLevelPrefix') +/// +/// Note that priorities can be logged by applications via the prefix +/// concept described in these man pages, without interfering with +/// structured JSON-payloads. +/// +/// For more information on the Stackdriver severity levels, please +/// consult Google's documentation: +/// +/// https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity +/// +/// Any unknown priority values result in no severity being set. +fn priority_to_severity(priority: String) -> Option<u32> { + match priority.as_ref() { + "0" => Some(800), // emerg + "1" => Some(700), // alert + "2" => Some(600), // crit + "3" => Some(500), // err + "4" => Some(400), // warning + "5" => Some(300), // notice + "6" => Some(200), // info + "7" => Some(100), // debug + _ => None, + } +} + +/// This structure represents a log entry in the format expected by +/// the Stackdriver API. +#[derive(Debug, Serialize)] +#[serde(rename_all = "camelCase")] +struct LogEntry { + labels: Value, + + #[serde(skip_serializing_if = "Option::is_none")] + timestamp: Option<DateTime<Utc>>, + + #[serde(flatten)] + payload: Payload, + + // https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity + #[serde(skip_serializing_if = "Option::is_none")] + severity: Option<u32>, +} + +impl From<JournalRecord> for LogEntry { + // Converts from the fields contained in a journald record to the + // representation required by Stackdriver Logging. + // + // The fields are documented in systemd.journal-fields(7). + fn from(mut record: JournalRecord) -> LogEntry { + // The message field is technically just a convention, but + // journald seems to default to it when ingesting unit + // output. + let payload = message_to_payload(record.remove("MESSAGE")); + + // Presumably this is always set, but who can be sure + // about anything in this world. + let hostname = record.remove("_HOSTNAME"); + + // The unit is seemingly missing on kernel entries, but + // present on all others. + let unit = record.remove("_SYSTEMD_UNIT"); + + // The source timestamp (if present) is specified in + // microseconds since epoch. + // + // If it is not present or can not be parsed, journaldriver + // will not send a timestamp for the log entry and it will + // default to the ingestion time. + let timestamp = record + .remove("_SOURCE_REALTIME_TIMESTAMP") + .and_then(parse_microseconds); + + // Journald uses syslogd's concept of priority. No idea if this is + // always present, but it's optional in the Stackdriver API, so we just + // omit it if we can't find or parse it. + let severity = record + .remove("PRIORITY") + .and_then(priority_to_severity); + + LogEntry { + payload, + timestamp, + labels: json!({ + "host": hostname, + "unit": unit.unwrap_or_else(|| "syslog".into()), + }), + severity, + } + } +} + +/// Attempt to read from the journal. If no new entry is present, +/// await the next one up to the specified timeout. +fn receive_next_record(timeout: Duration, journal: &mut Journal) + -> Result<Option<JournalRecord>> { + let next_record = journal.next_record()?; + if next_record.is_some() { + return Ok(next_record); + } + + Ok(journal.await_next_record(Some(timeout))?) +} + +/// This function starts a double-looped, blocking receiver. It will +/// buffer messages for half a second before flushing them to +/// Stackdriver. +fn receiver_loop(mut journal: Journal) -> Result<()> { + let mut token = get_token()?; + + let mut buf: Vec<LogEntry> = Vec::new(); + let iteration = Duration::from_millis(500); + + loop { + trace!("Beginning outer iteration"); + let now = Instant::now(); + + loop { + if now.elapsed() > iteration { + break; + } + + if let Ok(Some(entry)) = receive_next_record(iteration, &mut journal) { + trace!("Received a new entry"); + buf.push(entry.into()); + } + } + + if !buf.is_empty() { + let to_flush = mem::replace(&mut buf, Vec::new()); + flush(&mut token, to_flush, journal.cursor()?)?; + } + + trace!("Done outer iteration"); + } +} + +/// Writes the current cursor into `/var/journaldriver/cursor.pos`. To +/// avoid issues with journaldriver being terminated while the cursor +/// is still being written, this will first write the cursor into a +/// temporary file and then move it. +fn persist_cursor(cursor: String) -> Result<()> { + // This code exists to aid in tracking down if there are other + // causes of issue #2 than what has already been taken care of. + // + // One theory is that journald (or the Rust library to interface + // with it) may occasionally return empty cursor strings. If this + // is ever the case, we would like to know about it. + if cursor.is_empty() { + error!("Received empty journald cursor position, refusing to persist!"); + error!("Please report this message at https://github.com/tazjin/journaldriver/issues/2"); + return Ok(()) + } + + let mut file = File::create(&*CURSOR_TMP_FILE) + .context("Failed to create cursor file")?; + + write!(file, "{}", cursor).context("Failed to write cursor file")?; + + rename(&*CURSOR_TMP_FILE, &*CURSOR_FILE) + .context("Failed to move cursor file") + .map_err(Into::into) +} + +/// Flushes all drained records to Stackdriver. Any Stackdriver +/// message can at most contain 1000 log entries which means they are +/// chunked up here. +/// +/// In some cases large payloads seem to cause errors in Stackdriver - +/// the chunks are therefore made smaller here. +/// +/// If flushing is successful the last cursor position will be +/// persisted to disk. +fn flush(token: &mut Token, + entries: Vec<LogEntry>, + cursor: String) -> Result<()> { + if token.is_expired() { + debug!("Refreshing Google metadata access token"); + let new_token = get_token()?; + mem::replace(token, new_token); + } + + for chunk in entries.chunks(750) { + let request = prepare_request(chunk); + if let Err(write_error) = write_entries(token, request) { + error!("Failed to write {} entries: {}", chunk.len(), write_error) + } else { + debug!("Wrote {} entries to Stackdriver", chunk.len()) + } + } + + persist_cursor(cursor) +} + +/// Convert a slice of log entries into the format expected by +/// Stackdriver. This format is documented here: +/// +/// https://cloud.google.com/logging/docs/reference/v2/rest/v2/entries/write +fn prepare_request(entries: &[LogEntry]) -> Value { + json!({ + "logName": format!("projects/{}/logs/{}", PROJECT_ID.as_str(), LOG_NAME.as_str()), + "resource": &*MONITORED_RESOURCE, + "entries": entries, + "partialSuccess": true + }) +} + +/// Perform the log entry insertion in Stackdriver Logging. +fn write_entries(token: &Token, request: Value) -> Result<()> { + let response = ureq::post(ENTRIES_WRITE_URL) + .set("Authorization", format!("Bearer {}", token.token).as_str()) + // The timeout values are set relatively high, not because of + // an expectation of Stackdriver being slow but just to + // eventually hit an error case in case of network troubles. + // Presumably no request in a functioning environment will + // ever hit these limits. + .timeout_connect(2000) + .timeout_read(5000) + .send_json(request); + + if response.ok() { + Ok(()) + } else { + let status = response.status_line().to_string(); + let body = response.into_string() + .unwrap_or_else(|_| "no response body".into()); + bail!("Write failure: {} ({})", body, status) + } +} + +/// Attempt to read the initial cursor position from the configured +/// file. If there is no initial cursor position set, read from the +/// tail of the log. +/// +/// The only "acceptable" error when reading the cursor position is +/// the cursor position file not existing, other errors are fatal +/// because they indicate a misconfiguration of journaldriver. +fn initial_cursor() -> Result<JournalSeek> { + let read_result: io::Result<String> = (|| { + let mut contents = String::new(); + let mut file = File::open(&*CURSOR_FILE)?; + file.read_to_string(&mut contents)?; + Ok(contents.trim().into()) + })(); + + match read_result { + Ok(cursor) => Ok(JournalSeek::Cursor { cursor }), + Err(ref err) if err.kind() == ErrorKind::NotFound => { + info!("No previous cursor position, reading from journal tail"); + Ok(JournalSeek::Tail) + }, + Err(err) => { + (Err(err).context("Could not read cursor position"))? + } + } +} + +fn main () { + env_logger::init(); + + // The directory in which cursor positions are persisted should + // have been created: + if !CURSOR_DIR.exists() { + error!("Cursor directory at '{:?}' does not exist", *CURSOR_DIR); + process::exit(1); + } + + let cursor_position_dir = CURSOR_FILE.parent() + .expect("Invalid cursor position file path"); + + fs::create_dir_all(cursor_position_dir) + .expect("Could not create directory to store cursor position in"); + + let mut journal = Journal::open(JournalFiles::All, false, true) + .expect("Failed to open systemd journal"); + + let seek_position = initial_cursor() + .expect("Failed to determine initial cursor position"); + + match journal.seek(seek_position) { + Ok(cursor) => info!("Opened journal at cursor '{}'", cursor), + Err(err) => { + error!("Failed to set initial journal position: {}", err); + process::exit(1) + } + } + + receiver_loop(journal).expect("log receiver encountered an unexpected error"); +} diff --git a/tools/journaldriver/src/tests.rs b/tools/journaldriver/src/tests.rs new file mode 100644 index 000000000000..779add7a7012 --- /dev/null +++ b/tools/journaldriver/src/tests.rs @@ -0,0 +1,95 @@ +use super::*; +use serde_json::to_string; + +#[test] +fn test_text_entry_serialization() { + let entry = LogEntry { + labels: Value::Null, + timestamp: None, + payload: Payload::TextPayload { + text_payload: "test entry".into(), + }, + severity: None, + }; + + let expected = "{\"labels\":null,\"textPayload\":\"test entry\"}"; + let result = to_string(&entry).expect("serialization failed"); + + assert_eq!(expected, result, "Plain text payload should serialize correctly") +} + +#[test] +fn test_json_entry_serialization() { + let entry = LogEntry { + labels: Value::Null, + timestamp: None, + payload: Payload::JsonPayload { + json_payload: json!({ + "message": "JSON test" + }) + }, + severity: None, + }; + + let expected = "{\"labels\":null,\"jsonPayload\":{\"message\":\"JSON test\"}}"; + let result = to_string(&entry).expect("serialization failed"); + + assert_eq!(expected, result, "JSOn payload should serialize correctly") +} + +#[test] +fn test_plain_text_payload() { + let message = "plain text payload".into(); + let payload = message_to_payload(Some(message)); + let expected = Payload::TextPayload { + text_payload: "plain text payload".into(), + }; + + assert_eq!(expected, payload, "Plain text payload should be detected correctly"); +} + +#[test] +fn test_empty_payload() { + let payload = message_to_payload(None); + let expected = Payload::TextPayload { + text_payload: "empty log entry".into(), + }; + + assert_eq!(expected, payload, "Empty payload should be handled correctly"); +} + +#[test] +fn test_json_payload() { + let message = "{\"someKey\":\"someValue\", \"otherKey\": 42}".into(); + let payload = message_to_payload(Some(message)); + let expected = Payload::JsonPayload { + json_payload: json!({ + "someKey": "someValue", + "otherKey": 42 + }) + }; + + assert_eq!(expected, payload, "JSON payload should be detected correctly"); +} + +#[test] +fn test_json_no_object() { + // This message can be parsed as valid JSON, but it is not an + // object - it should be returned as a plain-text payload. + let message = "42".into(); + let payload = message_to_payload(Some(message)); + let expected = Payload::TextPayload { + text_payload: "42".into(), + }; + + assert_eq!(expected, payload, "Non-object JSON payload should be plain text"); +} + +#[test] +fn test_parse_microseconds() { + let input: String = "1529175149291187".into(); + let expected: DateTime<Utc> = "2018-06-16T18:52:29.291187Z" + .to_string().parse().unwrap(); + + assert_eq!(Some(expected), parse_microseconds(input)); +} |