From c889461eef3d59a3a438191fddf1afb65e5b2e4f Mon Sep 17 00:00:00 2001
From: Scott Lamb <slamb@slamb.org>
Date: Fri, 19 Jun 2020 22:36:45 -0700
Subject: [PATCH] improve logging in deserialize path and tests

* Log the depth of elements as they're fetched
* Log the starting depth of structs/enums and their Rust symbol names
  (not just XML element names, which may differ significantly)
* Log every element in the struct/enum match loop at trace level.
* Log file/line numbers at a few key points in the tests.
  This is helpful in finding failures happen in some of the longer
  tests.

This logging helps me understand the data flow as I play with changes
for #76.
---
 yaserde/src/de/mod.rs                  |  2 +-
 yaserde/src/lib.rs                     |  2 ++
 yaserde/tests/deserializer.rs          |  2 ++
 yaserde_derive/src/de/expand_enum.rs   | 11 +++++++----
 yaserde_derive/src/de/expand_struct.rs |  8 ++++++--
 5 files changed, 18 insertions(+), 7 deletions(-)

diff --git a/yaserde/src/de/mod.rs b/yaserde/src/de/mod.rs
index a894d28..e88832a 100644
--- a/yaserde/src/de/mod.rs
+++ b/yaserde/src/de/mod.rs
@@ -85,7 +85,7 @@ impl<'de, R: Read> Deserializer<R> {
       }
       _ => {}
     }
-    debug!("Fetched {:?}", next_event);
+    debug!("Fetched {:?}, new depth {}", next_event, self.depth);
     Ok(next_event)
   }
 
diff --git a/yaserde/src/lib.rs b/yaserde/src/lib.rs
index 5e55a3f..d5d737b 100644
--- a/yaserde/src/lib.rs
+++ b/yaserde/src/lib.rs
@@ -213,6 +213,7 @@ mod testing {
   #[macro_export]
   macro_rules! deserialize_and_validate {
     ($content: expr, $model: expr, $struct: tt) => {
+      log::debug!("deserialize_and_validate @ {}:{}", file!(), line!());
       let loaded: Result<$struct, String> = yaserde::de::from_str($content);
       assert_eq!(loaded, Ok($model));
     };
@@ -221,6 +222,7 @@ mod testing {
   #[macro_export]
   macro_rules! serialize_and_validate {
     ($model: expr, $content: expr) => {
+      log::debug!("serialize_and_validate @ {}:{}", file!(), line!());
       let data: Result<String, String> = yaserde::ser::to_string(&$model);
 
       let content = String::from(r#"<?xml version="1.0" encoding="utf-8"?>"#) + &$content;
diff --git a/yaserde/tests/deserializer.rs b/yaserde/tests/deserializer.rs
index ea031e4..f0ddbda 100644
--- a/yaserde/tests/deserializer.rs
+++ b/yaserde/tests/deserializer.rs
@@ -3,6 +3,7 @@ extern crate yaserde;
 #[macro_use]
 extern crate yaserde_derive;
 
+use log::debug;
 use std::io::{Read, Write};
 use yaserde::de::from_str;
 use yaserde::{YaDeserialize, YaSerialize};
@@ -13,6 +14,7 @@ fn init() {
 
 macro_rules! convert_and_validate {
   ($content: expr, $struct: tt, $model: expr) => {
+    debug!("convert_and_validate @ {}:{}", file!(), line!());
     let loaded: Result<$struct, String> = from_str($content);
     assert_eq!(loaded, Ok($model));
   };
diff --git a/yaserde_derive/src/de/expand_enum.rs b/yaserde_derive/src/de/expand_enum.rs
index dba1625..d6dcd12 100644
--- a/yaserde_derive/src/de/expand_enum.rs
+++ b/yaserde_derive/src/de/expand_enum.rs
@@ -29,7 +29,7 @@ pub fn parse(
     use yaserde::Visitor;
     #[allow(unknown_lints, unused_imports)]
     use std::str::FromStr;
-    use log::debug;
+    use log::{debug, trace};
 
     impl YaDeserialize for #name {
       #[allow(unused_variables)]
@@ -41,7 +41,8 @@ pub fn parse(
             (String::from(#root), None)
           };
 
-        debug!("Enum: start to parse {:?}", named_element);
+        let start_depth = reader.depth();
+        debug!("Enum {} @ {}: start to parse {:?}", stringify!(#name), start_depth, named_element);
 
         #namespaces_matching
 
@@ -49,9 +50,10 @@ pub fn parse(
         let mut enum_value = None;
 
         loop {
-          match reader.peek()?.to_owned() {
+          let event = reader.peek()?.to_owned();
+          trace!("Enum {} @ {}: matching {:?}", stringify!(#name), start_depth, event);
+          match event {
             XmlEvent::StartElement{ref name, ref attributes, ..} => {
-              // trace!("{:?}", name.local_name.as_str());
               match name.local_name.as_str() {
                 #match_to_enum
                 _named_element => {
@@ -88,6 +90,7 @@ pub fn parse(
           }
         }
 
+        debug!("Enum {} @ {}: success", stringify!(#name), start_depth);
         match enum_value {
           Some(value) => Ok(value),
           None => {
diff --git a/yaserde_derive/src/de/expand_struct.rs b/yaserde_derive/src/de/expand_struct.rs
index 9dfe8f2..32c154f 100644
--- a/yaserde_derive/src/de/expand_struct.rs
+++ b/yaserde_derive/src/de/expand_struct.rs
@@ -311,7 +311,7 @@ pub fn parse(
     use yaserde::Visitor;
     #[allow(unknown_lints, unused_imports)]
     use std::str::FromStr;
-    use log::debug;
+    use log::{debug, trace};
 
     impl YaDeserialize for #name {
       #[allow(unused_variables)]
@@ -322,7 +322,9 @@ pub fn parse(
           } else {
             (String::from(#root), None)
           };
-        debug!("Struct: start to parse {:?}", named_element);
+        let start_depth = reader.depth();
+        debug!("Struct {} @ {}: start to parse {:?}", stringify!(#name), start_depth,
+               named_element);
 
         if reader.depth() == 0 {
           #namespaces_matching
@@ -336,6 +338,7 @@ pub fn parse(
 
         loop {
           let event = reader.peek()?.to_owned();
+          trace!("Struct {} @ {}: matching {:?}", stringify!(#name), start_depth, event);
           match event {
             XmlEvent::StartElement{ref name, ref attributes, ..} => {
               let mut skipped = false;
@@ -389,6 +392,7 @@ pub fn parse(
 
         #visit_unused
 
+        debug!("Struct {} @ {}: success", stringify!(#name), start_depth);
         Ok(#name{#struct_builder})
       }
     }