AVRO-3522: Better logging in tests

lang/rust/Cargo.toml

@@ -17,6 +17,7 @@
 
 [workspace]
 members = [
+    "avro_test_helper",
     "avro",
     "avro_derive"
 ]

lang/rust/avro/Cargo.toml

@@ -77,10 +77,10 @@ zstd = { default-features = false, version = "0.11.1+zstd.1.5.2", optional = tru
 apache-avro-derive = { default-features = false, version= "0.14.0", path = "../avro_derive", optional = true }
 
 [dev-dependencies]
-md-5 = "0.10.1"
-sha2 = "0.10.2"
-criterion = "0.3.5"
 anyhow = "1.0.56"
+apache-avro-test-helper = { version= "0.1.0", path = "../avro_test_helper" }
+criterion = "0.3.5"
 hex-literal = "0.3.4"
-env_logger = "0.9.0"
-ref_thread_local = "0.1.1"
+md-5 = "0.10.1"
+pretty_assertions = "1.2.1"
+sha2 = "0.10.2"

lang/rust/avro/src/codec.rs

@@ -185,6 +185,7 @@ impl Codec {
 #[cfg(test)]
 mod tests {
     use super::*;
+    use pretty_assertions::{assert_eq, assert_ne};
 
     const INPUT: &[u8] = b"theanswertolifetheuniverseandeverythingis42theanswertolifetheuniverseandeverythingis4theanswertolifetheuniverseandeverythingis2";
 

lang/rust/avro/src/de.rs

@@ -593,6 +593,7 @@ pub fn from_value<'de, D: Deserialize<'de>>(value: &'de Value) -> Result<D, Erro
 
 #[cfg(test)]
 mod tests {
+    use pretty_assertions::assert_eq;
     use serde::Serialize;
     use uuid::Uuid;
 

lang/rust/avro/src/decimal.rs

@@ -102,6 +102,7 @@ impl<T: AsRef<[u8]>> From<T> for Decimal {
 #[cfg(test)]
 mod tests {
     use super::*;
+    use pretty_assertions::assert_eq;
     use std::convert::TryFrom;
 
     #[test]

lang/rust/avro/src/decode.rs

@@ -300,6 +300,7 @@ mod tests {
         },
         Decimal,
     };
+    use pretty_assertions::assert_eq;
     use std::collections::HashMap;
 
     #[test]

lang/rust/avro/src/encode.rs

@@ -244,7 +244,9 @@ pub fn encode_to_vec(value: &Value, schema: &Schema) -> AvroResult<Vec<u8>> {
 #[allow(clippy::expect_fun_call)]
 pub(crate) mod tests {
     use super::*;
+    use pretty_assertions::assert_eq;
     use std::collections::HashMap;
+
     pub(crate) fn success(value: &Value, schema: &Schema) -> String {
         format!(
             "Value: {:?}\n should encode with schema:\n{:?}",

lang/rust/avro/src/lib.rs

@@ -764,6 +764,7 @@ mod tests {
         types::{Record, Value},
         Codec, Reader, Schema, Writer,
     };
+    use pretty_assertions::assert_eq;
 
     //TODO: move where it fits better
     #[test]

lang/rust/avro/src/rabin.rs

@@ -133,6 +133,7 @@ mod tests {
     use super::Rabin;
     use byteorder::{ByteOrder, LittleEndian};
     use digest::Digest;
+    use pretty_assertions::assert_eq;
 
     // See: https://github.com/apache/avro/blob/master/share/test/data/schema-tests.txt
     #[test]

lang/rust/avro/src/reader.rs

@@ -444,6 +444,7 @@ where
 mod tests {
     use super::*;
     use crate::{encode::encode, from_value, types::Record, Reader};
+    use pretty_assertions::assert_eq;
     use serde::Deserialize;
     use std::io::Cursor;
 

lang/rust/avro/src/schema.rs

@@ -1895,6 +1895,7 @@ pub mod derive {
 #[cfg(test)]
 mod tests {
     use super::*;
+    use pretty_assertions::assert_eq;
 
     #[test]
     fn test_invalid_schema() {

lang/rust/avro/src/ser.rs

@@ -485,6 +485,7 @@ pub fn to_value<S: Serialize>(value: S) -> Result<Value, Error> {
 #[cfg(test)]
 mod tests {
     use super::*;
+    use pretty_assertions::assert_eq;
     use serde::{Deserialize, Serialize};
 
     #[derive(Debug, Deserialize, Serialize, Clone)]

lang/rust/avro/src/types.rs

@@ -938,48 +938,10 @@ mod tests {
         schema::{Name, RecordField, RecordFieldOrder, Schema, UnionSchema},
         types::Value,
     };
-    use log::{Level, LevelFilter, Metadata};
+    use apache_avro_test_helper::logger::assert_logged;
+    use pretty_assertions::assert_eq;
     use uuid::Uuid;
 
-    use ref_thread_local::{ref_thread_local, RefThreadLocal};
-
-    ref_thread_local! {
-        // The unit tests run in parallel
-        // We need to keep the log messages in a thread-local variable
-        // and clear them after assertion
-        static managed LOG_MESSAGES: Vec<String> = Vec::new();
-    }
-
-    struct TestLogger;
-
-    impl log::Log for TestLogger {
-        fn enabled(&self, metadata: &Metadata) -> bool {
-            metadata.level() <= Level::Error
-        }
-
-        fn log(&self, record: &log::Record) {
-            if self.enabled(record.metadata()) {
-                let mut msgs = LOG_MESSAGES.borrow_mut();
-                msgs.push(format!("{}", record.args()));
-            }
-        }
-
-        fn flush(&self) {}
-    }
-
-    static TEST_LOGGER: TestLogger = TestLogger;
-
-    fn init() {
-        let _ = log::set_logger(&TEST_LOGGER);
-        log::set_max_level(LevelFilter::Info);
-    }
-
-    fn assert_log_message(expected_message: &str) {
-        let mut msgs = LOG_MESSAGES.borrow_mut();
-        assert_eq!(msgs.pop().unwrap(), expected_message);
-        msgs.clear();
-    }
-
     #[test]
     fn validate() {
         let value_schema_valid = vec![
@@ -1120,8 +1082,6 @@ mod tests {
 
     #[test]
     fn validate_fixed() {
-        init();
-
         let schema = Schema::Fixed {
             size: 4,
             name: Name::new("some_fixed").unwrap(),
@@ -1132,7 +1092,7 @@ mod tests {
         assert!(Value::Fixed(4, vec![0, 0, 0, 0]).validate(&schema));
         let value = Value::Fixed(5, vec![0, 0, 0, 0, 0]);
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             format!(
                 "Invalid value: {:?} for schema: {:?}. Reason: {}",
                 value, schema, "The value's size (5) is different than the schema's size (4)"
@@ -1143,7 +1103,7 @@ mod tests {
         assert!(Value::Bytes(vec![0, 0, 0, 0]).validate(&schema));
         let value = Value::Bytes(vec![0, 0, 0, 0, 0]);
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             format!(
                 "Invalid value: {:?} for schema: {:?}. Reason: {}",
                 value, schema, "The bytes' length (5) is different than the schema's size (4)"
@@ -1154,8 +1114,6 @@ mod tests {
 
     #[test]
     fn validate_enum() {
-        init();
-
         let schema = Schema::Enum {
             name: Name::new("some_enum").unwrap(),
             aliases: None,
@@ -1173,7 +1131,7 @@ mod tests {
 
         let value = Value::Enum(1, "spades".to_string());
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             format!(
                 "Invalid value: {:?} for schema: {:?}. Reason: {}",
                 value, schema, "Symbol 'spades' is not at position '1'"
@@ -1183,7 +1141,7 @@ mod tests {
 
         let value = Value::Enum(1000, "spades".to_string());
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             format!(
                 "Invalid value: {:?} for schema: {:?}. Reason: {}",
                 value, schema, "No symbol at position '1000'"
@@ -1193,7 +1151,7 @@ mod tests {
 
         let value = Value::String("lorem".to_string());
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             format!(
                 "Invalid value: {:?} for schema: {:?}. Reason: {}",
                 value, schema, "'lorem' is not a member of the possible symbols"
@@ -1215,7 +1173,7 @@ mod tests {
 
         let value = Value::Enum(0, "spades".to_string());
         assert!(!value.validate(&other_schema));
-        assert_log_message(
+        assert_logged(
             format!(
                 "Invalid value: {:?} for schema: {:?}. Reason: {}",
                 value, other_schema, "Symbol 'spades' is not at position '0'"
@@ -1226,8 +1184,6 @@ mod tests {
 
     #[test]
     fn validate_record() {
-        init();
-
         // {
         //    "type": "record",
         //    "fields": [
@@ -1280,14 +1236,14 @@ mod tests {
             ("b".to_string(), Value::String("foo".to_string())),
         ]);
         assert!(!value.validate(&schema));
-        assert_log_message("Invalid value: Record([(\"a\", Boolean(false)), (\"b\", String(\"foo\"))]) for schema: Record { name: Name { name: \"some_record\", namespace: None }, aliases: None, doc: None, fields: [RecordField { name: \"a\", doc: None, default: None, schema: Long, order: Ascending, position: 0 }, RecordField { name: \"b\", doc: None, default: None, schema: String, order: Ascending, position: 1 }], lookup: {\"a\": 0, \"b\": 1} }. Reason: Unsupported value-schema combination");
+        assert_logged("Invalid value: Record([(\"a\", Boolean(false)), (\"b\", String(\"foo\"))]) for schema: Record { name: Name { name: \"some_record\", namespace: None }, aliases: None, doc: None, fields: [RecordField { name: \"a\", doc: None, default: None, schema: Long, order: Ascending, position: 0 }, RecordField { name: \"b\", doc: None, default: None, schema: String, order: Ascending, position: 1 }], lookup: {\"a\": 0, \"b\": 1} }. Reason: Unsupported value-schema combination");
 
         let value = Value::Record(vec![
             ("a".to_string(), Value::Long(42i64)),
             ("c".to_string(), Value::String("foo".to_string())),
         ]);
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             "Invalid value: Record([(\"a\", Long(42)), (\"c\", String(\"foo\"))]) for schema: Record { name: Name { name: \"some_record\", namespace: None }, aliases: None, doc: None, fields: [RecordField { name: \"a\", doc: None, default: None, schema: Long, order: Ascending, position: 0 }, RecordField { name: \"b\", doc: None, default: None, schema: String, order: Ascending, position: 1 }], lookup: {\"a\": 0, \"b\": 1} }. Reason: There is no schema field for field 'c'"
         );
 
@@ -1297,7 +1253,7 @@ mod tests {
             ("c".to_string(), Value::Null),
         ]);
         assert!(!value.validate(&schema));
-        assert_log_message(
+        assert_logged(
             r#"Invalid value: Record([("a", Long(42)), ("b", String("foo")), ("c", Null)]) for schema: Record { name: Name { name: "some_record", namespace: None }, aliases: None, doc: None, fields: [RecordField { name: "a", doc: None, default: None, schema: Long, order: Ascending, position: 0 }, RecordField { name: "b", doc: None, default: None, schema: String, order: Ascending, position: 1 }], lookup: {"a": 0, "b": 1} }. Reason: The value's records length (3) is different than the schema's (2)"#,
         );
 
@@ -1317,7 +1273,7 @@ mod tests {
                 .collect()
         )
         .validate(&schema));
-        assert_log_message(
+        assert_logged(
             r#"Invalid value: Map({"c": Long(123)}) for schema: Record { name: Name { name: "some_record", namespace: None }, aliases: None, doc: None, fields: [RecordField { name: "a", doc: None, default: None, schema: Long, order: Ascending, position: 0 }, RecordField { name: "b", doc: None, default: None, schema: String, order: Ascending, position: 1 }], lookup: {"a": 0, "b": 1} }. Reason: Field with name '"a"' is not a member of the map items
 Field with name '"b"' is not a member of the map items"#,
         );

lang/rust/avro/src/util.rs

@@ -155,6 +155,7 @@ pub fn safe_len(len: usize) -> AvroResult<usize> {
 #[cfg(test)]
 mod tests {
     use super::*;
+    use pretty_assertions::assert_eq;
 
     #[test]
     fn test_zigzag() {

lang/rust/avro/src/writer.rs

@@ -524,6 +524,7 @@ mod tests {
         types::Record,
         util::zig_i64,
     };
+    use pretty_assertions::assert_eq;
     use serde::{Deserialize, Serialize};
 
     const AVRO_OBJECT_HEADER_LEN: usize = AVRO_OBJECT_HEADER.len();

lang/rust/avro/tests/io.rs

@@ -18,6 +18,7 @@
 //! Port of https://github.com/apache/avro/blob/release-1.9.1/lang/py/test/test_io.py
 use apache_avro::{from_avro_datum, to_avro_datum, types::Value, Error, Schema};
 use lazy_static::lazy_static;
+use pretty_assertions::assert_eq;
 use std::io::Cursor;
 
 lazy_static! {

lang/rust/avro/tests/schema.rs

@@ -21,15 +21,8 @@ use apache_avro::{
     types::{Record, Value},
     Codec, Error, Reader, Schema, Writer,
 };
+use apache_avro_test_helper::init;
 use lazy_static::lazy_static;
-use log::debug;
-
-fn init() {
-    let _ = env_logger::builder()
-        .filter_level(log::LevelFilter::Trace)
-        .is_test(true)
-        .try_init();
-}
 
 const PRIMITIVE_EXAMPLES: &[(&str, bool)] = &[
     (r#""null""#, true),
@@ -641,7 +634,6 @@ fn test_correct_recursive_extraction() {
 #[test]
 fn test_parse() {
     init();
-
     for (raw_schema, valid) in EXAMPLES.iter() {
         let schema = Schema::parse_str(raw_schema);
         if *valid {
@@ -1176,7 +1168,6 @@ fn test_fullname_name_namespace_and_default_namespace_specified() {
 #[test]
 fn test_doc_attributes() {
     init();
-
     fn assert_doc(schema: &Schema) {
         match schema {
             Schema::Enum { doc, .. } => assert!(doc.is_some()),
@@ -1235,7 +1226,6 @@ fn test_other_attributes() {
 #[test]
 fn test_root_error_is_not_swallowed_on_parse_error() -> Result<(), String> {
     init();
-
     let raw_schema = r#"/not/a/real/file"#;
     let error = Schema::parse_str(raw_schema).unwrap_err();
 
@@ -1257,6 +1247,7 @@ fn test_root_error_is_not_swallowed_on_parse_error() -> Result<(), String> {
 // AVRO-3302
 #[test]
 fn test_record_schema_with_cyclic_references() {
+    init();
     let schema = Schema::parse_str(
         r#"
             {
@@ -1314,7 +1305,7 @@ fn test_record_schema_with_cyclic_references() {
 
     match Reader::new(&mut bytes.as_slice()) {
         Ok(mut reader) => match reader.next() {
-            Some(value) => debug!("{:?}", value.unwrap()),
+            Some(value) => log::debug!("{:?}", value.unwrap()),
             None => panic!("No value was read!"),
         },
         Err(err) => panic!("An error occurred while reading datum: {:?}", err),
@@ -1325,6 +1316,7 @@ fn test_record_schema_with_cyclic_references() {
 // TODO: (#93) add support for logical type and attributes and uncomment (may need some tweaks to compile)
 #[test]
 fn test_decimal_valid_type_attributes() {
+    init();
     let fixed_decimal = Schema::parse_str(DECIMAL_LOGICAL_TYPE_ATTRIBUTES[0]).unwrap();
     assert_eq!(4, fixed_decimal.get_attribute("precision"));
     assert_eq!(2, fixed_decimal.get_attribute("scale"));

lang/rust/avro_test_helper/Cargo.toml

@@ -0,0 +1,30 @@
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements.  See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership.  The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License.  You may obtain a copy of the License at
+#
+#   http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing,
+# software distributed under the License is distributed on an
+# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+# KIND, either express or implied.  See the License for the
+# specific language governing permissions and limitations
+# under the License.
+
+[package]
+name = "apache-avro-test-helper"
+version = "0.1.0"
+edition = "2018"
+description = "Avro test helper. This crate is not supposed to be published!"
+
+[dependencies]
+ctor = "0.1.22"
+color-backtrace = { version = "0.5" }
+env_logger = "0.9.0"
+lazy_static = { default-features = false, version="1.4.0" }
+log = { default-features = false, version="0.4.16" }
+ref_thread_local = "0.1.1"