Use log and env_logger for logging

4 files changed, 136 insertions, 9 deletions

diff --git a/Cargo.lock b/Cargo.lock
index be0b367869..16382a5c4f 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -3,8 +3,18 @@ name = "talpid_openvpn_plugin"
 version = "0.1.0"
 dependencies = [
  "assert_matches 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "env_logger 0.4.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "error-chain 0.8.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "lazy_static 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)",
+ "log 0.3.6 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "aho-corasick"
+version = "0.6.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "memchr 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
 [[package]]
@@ -83,6 +93,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "env_logger"
+version = "0.4.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "log 0.3.6 (registry+https://github.com/rust-lang/crates.io-index)",
+ "regex 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
 name = "error-chain"
 version = "0.7.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -125,6 +144,14 @@ version = "0.3.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
+name = "memchr"
+version = "1.0.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "libc 0.2.20 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
 name = "metadeps"
 version = "1.1.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -140,6 +167,23 @@ version = "0.3.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
+name = "regex"
+version = "0.2.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "aho-corasick 0.6.2 (registry+https://github.com/rust-lang/crates.io-index)",
+ "memchr 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "regex-syntax 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "thread_local 0.3.3 (registry+https://github.com/rust-lang/crates.io-index)",
+ "utf8-ranges 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+
+[[package]]
 name = "rustc-demangle"
 version = "0.1.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -189,6 +233,24 @@ dependencies = [
 ]
 
 [[package]]
+name = "thread-id"
+version = "3.0.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "kernel32-sys 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)",
+ "libc 0.2.20 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "thread_local"
+version = "0.3.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "thread-id 3.0.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "unreachable 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
 name = "toml"
 version = "0.2.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -204,11 +266,29 @@ version = "0.1.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
+name = "unreachable"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "void 1.0.2 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "utf8-ranges"
+version = "1.0.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+
+[[package]]
 name = "vec_map"
 version = "0.6.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
+name = "void"
+version = "1.0.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+
+[[package]]
 name = "winapi"
 version = "0.2.8"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -238,6 +318,7 @@ dependencies = [
 ]
 
 [metadata]
+"checksum aho-corasick 0.6.2 (registry+https://github.com/rust-lang/crates.io-index)" = "0638fd549427caa90c499814196d1b9e3725eb4d15d7339d6de073a680ed0ca2"
 "checksum ansi_term 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)" = "23ac7c30002a5accbf7e8987d0632fa6de155b7c3d39d0067317a391e00a2ef6"
 "checksum assert_matches 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)" = "9aa85694f8820620d0df15526544e1c3fbbac7ba3874781d874d7d6499a53724"
 "checksum backtrace 0.3.0 (registry+https://github.com/rust-lang/crates.io-index)" = "f551bc2ddd53aea015d453ef0b635af89444afa5ed2405dd0b2062ad5d600d80"
@@ -247,6 +328,7 @@ dependencies = [
 "checksum clap 2.20.3 (registry+https://github.com/rust-lang/crates.io-index)" = "f89819450aa94325998aa83ce7ea142db11ad24c725d6bc48459845e0d6d9f18"
 "checksum clonablechild 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "4a4946a850c1e921fbdd9a1f92bf1298c41a301c0f6e9bacbabf95ea7d6d0225"
 "checksum dbghelp-sys 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "97590ba53bcb8ac28279161ca943a924d1fd4a8fb3fa63302591647c4fc5b850"
+"checksum env_logger 0.4.1 (registry+https://github.com/rust-lang/crates.io-index)" = "ed39959122ea027670b704fb70539f4286ddf4a49eefede23bf0b4b2a069ec03"
 "checksum error-chain 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)" = "318cb3c71ee4cdea69fdc9e15c173b245ed6063e1709029e8fd32525a881120f"
 "checksum error-chain 0.8.1 (registry+https://github.com/rust-lang/crates.io-index)" = "6930e04918388a9a2e41d518c25cf679ccafe26733fb4127dbf21993f2575d46"
 "checksum gcc 0.3.42 (registry+https://github.com/rust-lang/crates.io-index)" = "291055c78f59ca3d84c99026c9501c469413d386bb46be1e1cf1d285cd1db3b0"
@@ -254,15 +336,23 @@ dependencies = [
 "checksum lazy_static 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)" = "6abe0ee2e758cd6bc8a2cd56726359007748fbf4128da998b65d0b70f881e19b"
 "checksum libc 0.2.20 (registry+https://github.com/rust-lang/crates.io-index)" = "684f330624d8c3784fb9558ca46c4ce488073a8d22450415c5eb4f4cfb0d11b5"
 "checksum log 0.3.6 (registry+https://github.com/rust-lang/crates.io-index)" = "ab83497bf8bf4ed2a74259c1c802351fcd67a65baa86394b6ba73c36f4838054"
+"checksum memchr 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)" = "1dbccc0e46f1ea47b9f17e6d67c5a96bd27030519c519c9c91327e31275a47b4"
 "checksum metadeps 1.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "829fffe7ea1d747e23f64be972991bc516b2f1ac2ae4a3b33d8bea150c410151"
 "checksum pkg-config 0.3.9 (registry+https://github.com/rust-lang/crates.io-index)" = "3a8b4c6b8165cd1a1cd4b9b120978131389f64bdaf456435caa41e630edba903"
+"checksum regex 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "4278c17d0f6d62dfef0ab00028feb45bd7d2102843f80763474eeb1be8a10c01"
+"checksum regex-syntax 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)" = "2f9191b1f57603095f105d317e375d19b1c9c5c3185ea9633a99a6dcbed04457"
 "checksum rustc-demangle 0.1.3 (registry+https://github.com/rust-lang/crates.io-index)" = "1430d286cadb237c17c885e25447c982c97113926bb579f4379c0eca8d9586dc"
 "checksum strsim 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)" = "b4d15c810519a91cf877e7e36e63fe068815c678181439f2f29e2562147c3694"
 "checksum term_size 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)" = "71662702fe5cd2cf95edd4ad655eea42f24a87a0e44059cbaa4e55260b7bc331"
+"checksum thread-id 3.0.0 (registry+https://github.com/rust-lang/crates.io-index)" = "4437c97558c70d129e40629a5b385b3fb1ffac301e63941335e4d354081ec14a"
+"checksum thread_local 0.3.3 (registry+https://github.com/rust-lang/crates.io-index)" = "c85048c6260d17cf486ceae3282d9fb6b90be220bf5b28c400f5485ffc29f0c7"
 "checksum toml 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "736b60249cb25337bc196faa43ee12c705e426f3d55c214d73a4e7be06f92cb4"
 "checksum unicode-segmentation 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)" = "7baebdc1df1363fa66161fca2fe047e4f4209011cc7e045948298996afdf85df"
 "checksum unicode-width 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)" = "bf3a113775714a22dcb774d8ea3655c53a32debae63a063acc00a91cc586245f"
+"checksum unreachable 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "1f2ae5ddb18e1c92664717616dd9549dde73f539f01bd7b77c2edb2446bdff91"
+"checksum utf8-ranges 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)" = "662fab6525a98beff2921d7f61a39e7d59e0b425ebc7d0d9e66d316e55124122"
 "checksum vec_map 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)" = "cac5efe5cb0fa14ec2f84f83c701c562ee63f6dcc680861b21d65c682adfb05f"
+"checksum void 1.0.2 (registry+https://github.com/rust-lang/crates.io-index)" = "6a02e4885ed3bc0f2de90ea6dd45ebcbb66dacffe03547fadbb0eeae2770887d"
 "checksum winapi 0.2.8 (registry+https://github.com/rust-lang/crates.io-index)" = "167dc9d6949a9b857f3451275e911c3f44255842c1f7a76f33c55103a909087a"
 "checksum winapi-build 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "2d315eee3b34aca4797b2da6b13ed88266e6d612562a0c46390af8299fc699bc"
 "checksum zmq 0.8.1 (registry+https://github.com/rust-lang/crates.io-index)" = "9623581b345b8a85fb72cae9b2cb67116d73ccb141e6c02f689e311962b74f9c"
diff --git a/talpid_openvpn_plugin/Cargo.toml b/talpid_openvpn_plugin/Cargo.toml
index 1a740a7491..44fd3e0112 100644
--- a/talpid_openvpn_plugin/Cargo.toml
+++ b/talpid_openvpn_plugin/Cargo.toml
@@ -10,6 +10,8 @@ crate-type = ["dylib"]
 [dependencies]
 lazy_static = "0.2"
 error-chain = "0.8"
+log = "0.3"
+env_logger = "0.4"
 
 [dev-dependencies]
 assert_matches = "1.0"
diff --git a/talpid_openvpn_plugin/src/lib.rs b/talpid_openvpn_plugin/src/lib.rs
index cff9430d61..a63e82e8ad 100644
--- a/talpid_openvpn_plugin/src/lib.rs
+++ b/talpid_openvpn_plugin/src/lib.rs
@@ -4,6 +4,10 @@ extern crate lazy_static;
 #[macro_use]
 extern crate error_chain;
 
+#[macro_use]
+extern crate log;
+extern crate env_logger;
+
 #[cfg(test)]
 #[macro_use]
 extern crate assert_matches;
@@ -47,16 +51,21 @@ pub extern "C" fn openvpn_plugin_open_v3(_version: c_int,
                                          _args: *const ffi::openvpn_plugin_args_open_in,
                                          retptr: *mut ffi::openvpn_plugin_args_open_return)
                                          -> c_int {
-    println!("openvpn_plugin_open_v3()");
-    // TODO(linus): Add logging of errors
+    if init_logger().is_err() {
+        return ffi::OPENVPN_PLUGIN_FUNC_ERROR;
+    }
     match openvpn_plugin_open_v3_internal(retptr) {
         Ok(_) => ffi::OPENVPN_PLUGIN_FUNC_SUCCESS,
-        Err(_) => ffi::OPENVPN_PLUGIN_FUNC_ERROR,
+        Err(e) => {
+            log_error("Unable to initialize plugin", e);
+            ffi::OPENVPN_PLUGIN_FUNC_ERROR
+        }
     }
 }
 
 fn openvpn_plugin_open_v3_internal(retptr: *mut ffi::openvpn_plugin_args_open_return)
                                    -> Result<()> {
+    debug!("Initializing plugin");
     let handle = Box::new(EventProcessor::new().chain_err(|| ErrorKind::InitHandleFailed)?);
     unsafe {
         (*retptr).type_mask = ffi::events_to_bitmask(INTERESTING_EVENTS);
@@ -72,7 +81,7 @@ fn openvpn_plugin_open_v3_internal(retptr: *mut ffi::openvpn_plugin_args_open_re
 /// deallocate any `handle` initialized by the plugin in `openvpn_plugin_open_v3`
 #[no_mangle]
 pub extern "C" fn openvpn_plugin_close_v1(handle: *const c_void) {
-    println!("openvpn_plugin_close_v1()");
+    debug!("Unloading plugin");
     // IMPORTANT: Bring the handle object back from a raw pointer. This will cause the handle
     // object to be properly deallocated right here.
     let _ = unsafe { Box::from_raw(handle as *mut EventProcessor) };
@@ -86,18 +95,20 @@ pub extern "C" fn openvpn_plugin_func_v3(_version: c_int,
                                          args: *const ffi::openvpn_plugin_args_func_in,
                                          _retptr: *const ffi::openvpn_plugin_args_func_return)
                                          -> c_int {
-    // TODO(linus): Add logging of errors
     match openvpn_plugin_func_v3_internal(args) {
         Ok(_) => ffi::OPENVPN_PLUGIN_FUNC_SUCCESS,
-        Err(_) => ffi::OPENVPN_PLUGIN_FUNC_ERROR,
+        Err(e) => {
+            log_error("Error while processing event", e);
+            ffi::OPENVPN_PLUGIN_FUNC_ERROR
+        }
     }
 }
 
 fn openvpn_plugin_func_v3_internal(args: *const ffi::openvpn_plugin_args_func_in) -> Result<()> {
     let event_type = unsafe { (*args).event_type };
     let event = OpenVpnPluginEvent::from_int(event_type).chain_err(|| ErrorKind::InvalidEventType)?;
+    debug!("Received event: {:?}", event);
     let env = unsafe { ffi::parse::env((*args).envp) }.chain_err(|| ErrorKind::ParseEnvFailed)?;
-    println!("openvpn_plugin_func_v3({:?})", event);
 
     let mut handle = unsafe { Box::from_raw((*args).handle as *mut EventProcessor) };
     handle.process_event(event, env);
@@ -106,3 +117,26 @@ fn openvpn_plugin_func_v3_internal(args: *const ffi::openvpn_plugin_args_func_in
 
     Ok(())
 }
+
+
+
+pub fn init_logger() -> ::std::result::Result<(), ()> {
+    env_logger::init().or_else(|e| {
+        use std::io::Write;
+        let mut stderr = ::std::io::stderr();
+        writeln!(&mut stderr, "Unable to initialize logging: {}", e)
+            .expect("Unable to write to stderr");
+        Err(())
+    })
+}
+
+pub fn log_error(msg: &str, e: ::Error) {
+    error!("{}", msg);
+    for e in e.iter() {
+        error!("caused by: {}", e);
+    }
+    // When running with RUST_BACKTRACE=1, print backtrace.
+    if let Some(backtrace) = e.backtrace() {
+        error!("backtrace: {:?}", backtrace);
+    }
+}
diff --git a/talpid_openvpn_plugin/src/processing.rs b/talpid_openvpn_plugin/src/processing.rs
index 405e279896..337030744e 100644
--- a/talpid_openvpn_plugin/src/processing.rs
+++ b/talpid_openvpn_plugin/src/processing.rs
@@ -12,18 +12,19 @@ pub struct EventProcessor;
 
 impl EventProcessor {
     pub fn new() -> Result<EventProcessor> {
+        debug!("Creating EventProcessor");
         Ok(EventProcessor)
     }
 
     pub fn process_event(&mut self, event: OpenVpnPluginEvent, _env: HashMap<String, String>) {
         // TODO(linus): This is where we should send events to core.
-        println!("Hello from EventProcessor: {:?}", event);
+        trace!("Hello from EventProcessor: {:?}", event);
     }
 }
 
 impl Drop for EventProcessor {
     fn drop(&mut self) {
         // TODO(linus): If we need, this is where we send some shutdown event or similar to core.
-        println!("Dropping EventProcessor!");
+        debug!("Dropping EventProcessor");
     }
 }