Add timing to logs, fix issue of silently ignored I/O errors

4 files changed, 18 insertions, 16 deletions

diff --git a/xmpp-vala/src/core/stanza_writer.vala b/xmpp-vala/src/core/stanza_writer.vala
index aa94dec9..c2f589df 100644
--- a/xmpp-vala/src/core/stanza_writer.vala
+++ b/xmpp-vala/src/core/stanza_writer.vala
@@ -26,14 +26,15 @@ public class StanzaWriter {
         running = true;
         try {
             yield output.write_all_async(data, 0, null, null);
+        } catch (GLib.Error e) {
+            throw new XmlError.IO(@"IOError in GLib: $(e.message)");
+        } finally {
             SourceFuncWrapper? sfw = queue.pop_head();
             if (sfw != null) {
                 sfw.sfun();
+            } else {
+                running = false;
             }
-        } catch (GLib.Error e) {
-            throw new XmlError.IO(@"IOError in GLib: $(e.message)");
-        } finally {
-            running = false;
         }
     }
 }
diff --git a/xmpp-vala/src/core/xmpp_log.vala b/xmpp-vala/src/core/xmpp_log.vala
index 921899c4..4790a8ab 100644
--- a/xmpp-vala/src/core/xmpp_log.vala
+++ b/xmpp-vala/src/core/xmpp_log.vala
@@ -108,15 +108,15 @@ public class XmppLog {
         return false;
     }
 
-    public void node(string what, StanzaNode node) {
+    public void node(string what, StanzaNode node, XmppStream stream) {
         if (should_log_node(node)) {
-            stderr.printf("%sXMPP %s [%s]%s\n%s\n", use_ansi ? ANSI_COLOR_WHITE : "", what, ident, use_ansi ? ANSI_COLOR_END : "", use_ansi ? node.to_ansi_string(hide_ns) : node.to_string());
+            stderr.printf("%sXMPP %s [%s %p %s]%s\n%s\n", use_ansi ? ANSI_COLOR_WHITE : "", what, ident, stream, new DateTime.now_local().to_string(), use_ansi ? ANSI_COLOR_END : "", use_ansi ? node.to_ansi_string(hide_ns) : node.to_string());
         }
     }
 
-    public void str(string what, string str) {
+    public void str(string what, string str, XmppStream stream) {
         if (should_log_str(str)) {
-            stderr.printf("%sXMPP %s [%s]%s\n%s\n", use_ansi ? ANSI_COLOR_WHITE : "", what, ident, use_ansi ? ANSI_COLOR_END : "", str);
+            stderr.printf("%sXMPP %s [%s %p %s]%s\n%s\n", use_ansi ? ANSI_COLOR_WHITE : "", what, ident, stream, new DateTime.now_local().to_string(), use_ansi ? ANSI_COLOR_END : "", str);
         }
     }
 
diff --git a/xmpp-vala/src/core/xmpp_stream.vala b/xmpp-vala/src/core/xmpp_stream.vala
index 820d7ce8..97d00004 100644
--- a/xmpp-vala/src/core/xmpp_stream.vala
+++ b/xmpp-vala/src/core/xmpp_stream.vala
@@ -81,7 +81,7 @@ public class XmppStream {
         if (writer == null || reader == null || stream == null) {
             throw new IOStreamError.DISCONNECT("trying to disconnect, but no stream open");
         }
-        log.str("OUT", "</stream:stream>");
+        log.str("OUT", "</stream:stream>", this);
         yield writer.write("</stream:stream>");
         reader.cancel();
         yield stream.close_async();
@@ -107,22 +107,25 @@ public class XmppStream {
         if (reader == null) throw new IOStreamError.READ("trying to read, but no stream open");
         try {
             StanzaNode node = yield ((!)reader).read_node();
-            log.node("IN", node);
+            log.node("IN", node, this);
             return node;
         } catch (XmlError e) {
             throw new IOStreamError.READ(e.message);
         }
     }
 
+    [Version (deprecated = true, deprecated_since = "0.1", replacement = "write_async")]
     public void write(StanzaNode node) {
-        write_async.begin(node);
+        write_async.begin(node, (obj, res) => {
+            write_async.end(res);
+        });
     }
 
     public async void write_async(StanzaNode node) throws IOStreamError {
         StanzaWriter? writer = this.writer;
         if (writer == null) throw new IOStreamError.WRITE("trying to write, but no stream open");
         try {
-            log.node("OUT", node);
+            log.node("OUT", node, this);
             yield ((!)writer).write_node(node);
         } catch (XmlError e) {
             throw new IOStreamError.WRITE(e.message);
@@ -201,7 +204,7 @@ public class XmppStream {
                             .put_attribute("xmlns", "jabber:client")
                             .put_attribute("stream", "http://etherx.jabber.org/streams", XMLNS_URI);
         outs.has_nodes = true;
-        log.node("OUT ROOT", outs);
+        log.node("OUT ROOT", outs, this);
         write(outs);
         received_root_node(this, yield read_root());
     }
@@ -293,7 +296,7 @@ public class XmppStream {
         if (reader == null) throw new IOStreamError.READ("trying to read, but no stream open");
         try {
             StanzaNode node = yield ((!)reader).read_root_node();
-            log.node("IN ROOT", node);
+            log.node("IN ROOT", node, this);
             return node;
         } catch (XmlError.TLS e) {
             throw new IOStreamError.TLS(e.message);
diff --git a/xmpp-vala/src/module/xep/0313_message_archive_management.vala b/xmpp-vala/src/module/xep/0313_message_archive_management.vala
index 247e1b8e..504996e6 100644
--- a/xmpp-vala/src/module/xep/0313_message_archive_management.vala
+++ b/xmpp-vala/src/module/xep/0313_message_archive_management.vala
@@ -60,8 +60,6 @@ public class Module : XmppStreamModule {
         query_node.put_node(create_set_rsm_node(end_id));
         Iq.Stanza iq = new Iq.Stanza.set(query_node);
 
-        debug(@"OUT INIT: %s", iq.stanza.to_string());
-
         Iq.Stanza? result_iq = null;
         stream.get_module(Iq.Module.IDENTITY).send_iq(stream, iq, (stream, iq) => {
             result_iq = iq;