From 1bb75f40d26ad20381a200e09eaa9f519cffe398 Mon Sep 17 00:00:00 2001 From: Marvin W Date: Sun, 22 Dec 2019 19:28:40 +0100 Subject: [PATCH] Add timing to logs, fix issue of silently ignored I/O errors --- libdino/src/service/message_processor.vala | 3 +-- xmpp-vala/src/core/stanza_writer.vala | 11 ++++++----- xmpp-vala/src/core/xmpp_log.vala | 8 ++++---- xmpp-vala/src/core/xmpp_stream.vala | 15 +++++++++------ .../xep/0313_message_archive_management.vala | 2 -- 5 files changed, 20 insertions(+), 19 deletions(-) diff --git a/libdino/src/service/message_processor.vala b/libdino/src/service/message_processor.vala index fd575bf5..a7d186ef 100644 --- a/libdino/src/service/message_processor.vala +++ b/libdino/src/service/message_processor.vala @@ -218,13 +218,12 @@ public class MessageProcessor : StreamInteractionModule, Object { } while (iq != null) { - debug("MAM: [%s] IN: %s", account.bare_jid.to_string(), iq.stanza.to_string()); string? earliest_id = iq.stanza.get_deep_string_content("urn:xmpp:mam:2:fin", "http://jabber.org/protocol/rsm" + ":set", "first"); if (earliest_id == null) return true; if (!mam_times[account].has_key(earliest_id)) error("wtf"); - debug("MAM: [%s] Update from_id %s\n", account.bare_jid.to_string(), earliest_id); + debug("MAM: [%s] Update from_id %s", account.bare_jid.to_string(), earliest_id); if (!current_catchup_id.has_key(account)) { debug("MAM: [%s] We get our first MAM page", account.bare_jid.to_string()); string? latest_id = iq.stanza.get_deep_string_content("urn:xmpp:mam:2:fin", "http://jabber.org/protocol/rsm" + ":set", "last"); 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); - SourceFuncWrapper? sfw = queue.pop_head(); - if (sfw != null) { - sfw.sfun(); - } } catch (GLib.Error e) { throw new XmlError.IO(@"IOError in GLib: $(e.message)"); } finally { - running = false; + SourceFuncWrapper? sfw = queue.pop_head(); + if (sfw != null) { + sfw.sfun(); + } else { + 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", ""); + log.str("OUT", "", this); yield writer.write(""); 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;