Merge pull request #246 from dhardy/log-feature

Add log feature

Author: dhardy

.travis.yml

@@ -28,7 +28,7 @@ matrix:
 script:
   - cargo test
   - cargo test --tests --no-default-features
-  - cargo test --features serde-1
+  - cargo test --features serde-1,log
   - cargo test --tests --no-default-features --features=serde-1
   - cargo test --manifest-path rand-derive/Cargo.toml
 

Cargo.toml

@@ -32,6 +32,8 @@ libc = { version = "0.2", optional = true }
 winapi = { version = "0.3", features = ["minwindef", "ntsecapi", "profileapi", "winnt"], optional = true }
 
 [dependencies]
+log = { version = "0.4", optional = true }
+
 serde = {version="1",optional=true}
 serde_derive = {version="1", optional=true}
 

README.md

@@ -33,8 +33,7 @@ changes since the `0.3` series, but nevertheless contains some significant
 new code, including a new "external" entropy source (`JitterRng`) and `no_std`
 support.
 
-Version `0.5` is in development and contains significant performance
-improvements for the ISAAC random number generators.
+Version `0.5` is in development and will contain significant breaking changes.
 
 ## Examples
 
@@ -68,21 +67,22 @@ println!("i32: {}, u32: {}", rng.gen::<i32>(), rng.gen::<u32>())
 By default, `rand` is built with all stable features available. The following
 optional features are available:
 
+-   `alloc` can be used instead of `std` to provide `Vec` and `Box`
 -   `i128_support` enables support for generating `u128` and `i128` values
+-   `log` enables some logging via the `log` crate
 -   `nightly` enables all unstable features (`i128_support`)
+-   `serde-1` enables serialisation for some types, via Serde version 1
 -   `std` enabled by default; by setting "default-features = false" `no_std`
     mode is activated; this removes features depending on `std` functionality:
-
-        -   `OsRng` is entirely unavailable
-        -   `JitterRng` code is still present, but a nanosecond timer must be
-            provided via `JitterRng::new_with_timer`
-        -   Since no external entropy is available, it is not possible to create
-            generators with fresh seeds (user must provide entropy)
-        -   `thread_rng`, `weak_rng` and `random` are all disabled
-        -   exponential, normal and gamma type distributions are unavailable
-            since `exp` and `log` functions are not provided in `core`
-        -   any code requiring `Vec` or `Box`
--   `alloc` can be used instead of `std` to provide `Vec` and `Box`
+    -   `OsRng` is entirely unavailable
+    -   `JitterRng` code is still present, but a nanosecond timer must be
+        provided via `JitterRng::new_with_timer`
+    -   Since no external entropy is available, it is not possible to create
+        generators with fresh seeds (user must provide entropy)
+    -   `thread_rng`, `weak_rng` and `random` are all disabled
+    -   exponential, normal and gamma type distributions are unavailable
+        since `exp` and `log` functions are not provided in `core`
+    -   any code requiring `Vec` or `Box`
 
 ## Testing
 

src/jitter.rs

@@ -142,6 +142,7 @@ impl JitterRng {
             // This allows the timer test to run multiple times; we don't care.
             rounds = ec.test_timer()?;
             JITTER_ROUNDS.store(rounds as usize, Ordering::Relaxed);
+            info!("JitterRng: using {} rounds per u64 output", rounds);
         }
         ec.set_rounds(rounds);
         Ok(ec)
@@ -422,6 +423,8 @@ impl JitterRng {
     }
 
     fn gen_entropy(&mut self) -> u64 {
+        trace!("JitterRng: collecting entropy");
+        
         // Prime `self.prev_time`, and run the noice sources to make sure the
         // first loop round collects the expected entropy.
         let _ = self.measure_jitter();
@@ -444,6 +447,7 @@ impl JitterRng {
     /// to collect 64 bits of entropy. Otherwise a `TimerError` with the cause
     /// of the failure will be returned.
     pub fn test_timer(&mut self) -> Result<u32, TimerError> {
+        debug!("JitterRng: testing timer ...");
         // We could add a check for system capabilities such as `clock_getres`
         // or check for `CONFIG_X86_TSC`, but it does not make much sense as the
         // following sanity checks verify that we have a high-resolution timer.

src/lib.rs

@@ -249,10 +249,18 @@
 
 #[cfg(feature="std")] extern crate std as core;
 #[cfg(all(feature = "alloc", not(feature="std")))] extern crate alloc;
+
 #[cfg(test)] #[cfg(feature="serde-1")] extern crate bincode;
 #[cfg(feature="serde-1")] extern crate serde;
 #[cfg(feature="serde-1")] #[macro_use] extern crate serde_derive;
 
+#[cfg(feature = "log")] #[macro_use] extern crate log;
+#[cfg(not(feature = "log"))] macro_rules! trace { ($($x:tt)*) => () }
+#[cfg(not(feature = "log"))] macro_rules! debug { ($($x:tt)*) => () }
+#[cfg(all(feature="std", not(feature = "log")))] macro_rules! info { ($($x:tt)*) => () }
+#[cfg(all(feature="std", not(feature = "log")))] macro_rules! warn { ($($x:tt)*) => () }
+
+
 use core::{marker, mem};
 #[cfg(feature="std")] use std::cell::RefCell;
 #[cfg(feature="std")] use std::rc::Rc;
@@ -846,9 +854,11 @@ impl<R: SeedableRng> NewRng for R {
             T::from_rng(&mut r)
         }
 
+        trace!("Seeding new RNG");
         new_os().or_else(|e1| {
+            warn!("OsRng failed [falling back to JitterRng]: {:?}", e1);
             new_jitter().map_err(|_e2| {
-                // TODO: log
+                warn!("JitterRng failed: {:?}", _e2);
                 // TODO: can we somehow return both error sources?
                 Error::with_cause(
                     ErrorKind::Unavailable,

src/os.rs

@@ -69,23 +69,35 @@ impl Rng for OsRng {
         const MAX_WAIT: u32 = (10 * 1000) / WAIT_DUR_MS;    // max 10s
         const TRANSIENT_STEP: u32 = MAX_WAIT / 8;
         let mut err_count = 0;
+        let mut log_err = 0;    // log when err_count >= log_err
 
         loop {
             if let Err(e) = self.try_fill_bytes(dest) {
-                // TODO: add logging to explain why we wait and the full cause
+                if log_err == 0 {
+                    warn!("OsRng failed: {:?}", e);
+                }
+                
                 if e.kind().should_retry() {
                     if err_count > MAX_WAIT {
                         panic!("Too many RNG errors or timeout; last error: {}", e.msg());
                     }
 
                     if e.kind().should_wait() {
+                        err_count += 1;
+                        if err_count >= log_err {
+                            log_err += TRANSIENT_STEP;
+                            warn!("OsRng: waiting and retrying ...");
+                        }
                         #[cfg(feature="std")]{
                             let dur = ::std::time::Duration::from_millis(WAIT_DUR_MS as u64);
                             ::std::thread::sleep(dur);
                         }
-                        err_count += 1;
                     } else {
                         err_count += TRANSIENT_STEP;
+                        if err_count >= log_err {
+                            log_err += TRANSIENT_STEP;
+                            warn!("OsRng: retrying ...");
+                        }
                     }
 
                     continue;
@@ -130,6 +142,7 @@ impl ReadRng {
         let mutex = unsafe{ READ_RNG_FILE.as_ref().unwrap() };
         let mut guard = mutex.lock().unwrap();
         if (*guard).is_none() {
+            info!("OsRng: opening random device {}", path.as_ref().display());
             let file = File::open(path).map_err(|err| Error::with_cause(
                     ErrorKind::Unavailable,
                     "error opening random device",
@@ -142,6 +155,7 @@ impl ReadRng {
     }
 
     fn try_fill_bytes(&mut self, dest: &mut [u8]) -> Result<(), Error> {
+        trace!("OsRng: reading {} bytes from random device", dest.len());
         if dest.len() == 0 { return Ok(()); }
 
         // Since we have an instance of Self, we can assume that our memory was
@@ -211,6 +225,7 @@ mod imp {
     fn getrandom(_buf: &mut [u8]) -> libc::c_long { -1 }
 
     fn getrandom_try_fill(v: &mut [u8]) -> Result<(), Error> {
+        trace!("OsRng: reading {} bytes via getrandom", v.len());
         let mut read = 0;
         let len = v.len();
         while read < len {
@@ -253,6 +268,7 @@ mod imp {
         static AVAILABLE: AtomicBool = ATOMIC_BOOL_INIT;
 
         CHECKER.call_once(|| {
+            debug!("OsRng: testing getrandom");
             let mut buf: [u8; 0] = [];
             let result = getrandom(&mut buf);
             let available = if result == -1 {
@@ -262,6 +278,7 @@ mod imp {
                 true
             };
             AVAILABLE.store(available, Ordering::Relaxed);
+            info!("OsRng: using {}", if available { "getrandom" } else { "/dev/urandom" });
         });
 
         AVAILABLE.load(Ordering::Relaxed)
@@ -320,6 +337,7 @@ mod imp {
         }
 
         pub fn try_fill_bytes(&mut self, v: &mut [u8]) -> Result<(), Error> {
+            trace!("OsRng: reading {} bytes via cloadabi::random_get", v.len());
             if unsafe { cloudabi::random_get(v) } == cloudabi::errno::SUCCESS {
                 Ok(())
             } else {
@@ -360,6 +378,7 @@ mod imp {
             Ok(OsRng)
         }
         pub fn try_fill_bytes(&mut self, v: &mut [u8]) -> Result<(), Error> {
+            trace!("OsRng: reading {} bytes via SecRandomCopyBytes", v.len());
             let ret = unsafe {
                 SecRandomCopyBytes(kSecRandomDefault, v.len() as size_t, v.as_mut_ptr())
             };
@@ -395,6 +414,7 @@ mod imp {
             // kern.arandom permits a maximum buffer size of 256 bytes
             for s in v.chunks_mut(256) {
                 let mut s_len = s.len();
+                trace!("OsRng: reading {} bytes via kern.arandom", v.len());
                 let ret = unsafe {
                     libc::sysctl(mib.as_ptr(), mib.len() as libc::c_uint,
                                  s.as_mut_ptr() as *mut _, &mut s_len,
@@ -429,6 +449,7 @@ mod imp {
         pub fn try_fill_bytes(&mut self, v: &mut [u8]) -> Result<(), Error> {
             // getentropy(2) permits a maximum buffer size of 256 bytes
             for s in v.chunks_mut(256) {
+                trace!("OsRng: reading {} bytes via getentropy", s.len());
                 let ret = unsafe {
                     libc::getentropy(s.as_mut_ptr() as *mut libc::c_void, s.len())
                 };
@@ -482,6 +503,7 @@ mod imp {
         }
         pub fn try_fill_bytes(&mut self, v: &mut [u8]) -> Result<(), Error> {
             for s in v.chunks_mut(fuchsia_zircon::sys::ZX_CPRNG_DRAW_MAX_LEN) {
+                trace!("OsRng: reading {} bytes via cprng_draw", s.len());
                 let mut filled = 0;
                 while filled < s.len() {
                     match fuchsia_zircon::cprng_draw(&mut s[filled..]) {
@@ -523,6 +545,7 @@ mod imp {
             // RtlGenRandom takes an ULONG (u32) for the length so we need to
             // split up the buffer.
             for slice in v.chunks_mut(<ULONG>::max_value() as usize) {
+                trace!("OsRng: reading {} bytes via RtlGenRandom", slice.len());
                 let ret = unsafe {
                     RtlGenRandom(slice.as_mut_ptr() as PVOID, slice.len() as ULONG)
                 };

src/reseeding.rs

@@ -47,6 +47,7 @@ impl<R: Rng, Rsdr: Reseeder<R>> ReseedingRng<R, Rsdr> {
     /// generated exceed the threshold.
     pub fn reseed_if_necessary(&mut self) {
         if self.bytes_generated >= self.generation_threshold {
+            trace!("Reseeding RNG after {} bytes", self.bytes_generated);
             self.reseeder.reseed(&mut self.rng).unwrap();
             self.bytes_generated = 0;
         }