Merge with 0.4

7 files changed, 69 insertions, 28 deletions

diff --git a/core/loggingmanager.lua b/core/loggingmanager.lua
index 5dff6a34..13b091cc 100644
--- a/core/loggingmanager.lua
+++ b/core/loggingmanager.lua
@@ -6,7 +6,7 @@ local tostring, setmetatable, rawset, pairs, ipairs, type =
 	tostring, setmetatable, rawset, pairs, ipairs, type;
 local io_open, io_write = io.open, io.write;
 local math_max, rep = math.max, string.rep;
-local os_getenv = os.getenv;
+local os_date, os_getenv = os.date, os.getenv;
 local getstyle, getstring = require "util.termcolours".getstyle, require "util.termcolours".getstring;
 
 local config = require "core.configmanager";
@@ -20,7 +20,7 @@ module "loggingmanager"
 -- The log config used if none specified in the config file
 local default_logging = { { to = "console" } };
 local default_file_logging = { { to = "file", levels = { min = "info" } } };
-
+local default_timestamp = "%b %d %T";
 -- The actual config loggingmanager is using
 local logging_config = config.get("*", "core", "log") or default_logging;
 
@@ -130,9 +130,18 @@ end
 local sourcewidth = 20;
 
 function log_sink_types.stdout()
+	local timestamps = config.timestamps;
+	
+	if timestamps == true then
+		timestamps = default_timestamp; -- Default format
+	end
+	
 	return function (name, level, message, ...)
 		sourcewidth = math_max(#name+2, sourcewidth);
 		local namelen = #name;
+		if timestamps then
+			io_write(os_date(timestamps), " ");
+		end
 		if ... then 
 			io_write(name, rep(" ", sourcewidth-namelen), level, "\t", format(message, ...), "\n");
 		else
@@ -156,9 +165,18 @@ do
 			return log_sink_types.stdout(config);
 		end
 		
+		local timestamps = config.timestamps;
+
+		if timestamps == true then
+			timestamps = default_timestamp; -- Default format
+		end
+
 		return function (name, level, message, ...)
 			sourcewidth = math_max(#name+2, sourcewidth);
 			local namelen = #name;
+			if timestamps then
+				io_write(os_date(timestamps), " ");
+			end
 			if ... then 
 				io_write(name, rep(" ", sourcewidth-namelen), getstring(logstyles[level], level), "\t", format(message, ...), "\n");
 			else
@@ -175,8 +193,17 @@ function log_sink_types.file(config)
 		return function () end
 	end
 
+	local timestamps = config.timestamps;
+
+	if timestamps == true then
+		timestamps = default_timestamp; -- Default format
+	end
+
 	local write, format, flush = logfile.write, format, logfile.flush;
 	return function (name, level, message, ...)
+		if timestamps then
+			write(logfile, os_date(timestamps), " ");
+		end
 		if ... then 
 			write(logfile, name, "\t", level, "\t", format(message, ...), "\n");
 		else
diff --git a/core/modulemanager.lua b/core/modulemanager.lua
index a1d3bef3..cc48c2f6 100644
--- a/core/modulemanager.lua
+++ b/core/modulemanager.lua
@@ -123,6 +123,10 @@ function load(host, module_name, config)
 	-- Use modified host, if the module set one
 	modulemap[api_instance.host][module_name] = pluginenv;
 	
+	if api_instance.host == "*" and host ~= "*" then
+		api_instance:set_global();
+	end
+		
 	return true;
 end
 
@@ -260,6 +264,10 @@ end
 
 function api:set_global()
 	self.host = "*";
+	-- Update the logger
+	local _log = logger.init("mod_"..self.name);
+	self.log = function (self, ...) return _log(...); end;
+	self._log = _log;
 end
 
 local function _add_handler(module, origin_type, tag, xmlns, handler)
diff --git a/core/presencemanager.lua b/core/presencemanager.lua
index db6bbf9a..ae73d676 100644
--- a/core/presencemanager.lua
+++ b/core/presencemanager.lua
@@ -144,7 +144,7 @@ function send_presence_of_available_resources(user, host, jid, recipient_session
 			end
 		end
 	end
-	log("info", "broadcasted presence of "..count.." resources from "..user.."@"..host.." to "..jid);
+	log("debug", "broadcasted presence of "..count.." resources from "..user.."@"..host.." to "..jid);
 	return count;
 end
 
diff --git a/core/s2smanager.lua b/core/s2smanager.lua
index a16f8b02..b14f0e96 100644
--- a/core/s2smanager.lua
+++ b/core/s2smanager.lua
@@ -48,7 +48,7 @@ local function compare_srv_priorities(a,b) return a.priority < b.priority or a.w
 local function bounce_sendq(session)
 	local sendq = session.sendq;
 	if sendq then
-		session.log("debug", "sending error replies for "..#sendq.." queued stanzas because of failed outgoing connection to "..tostring(session.to_host));
+		session.log("info", "sending error replies for "..#sendq.." queued stanzas because of failed outgoing connection to "..tostring(session.to_host));
 		local dummy = {
 			type = "s2sin";
 			send = function(s)
@@ -199,9 +199,9 @@ function attempt_connection(host_session, err)
 		host_session.srv_choice = host_session.srv_choice + 1;
 		local srv_choice = host_session.srv_hosts[host_session.srv_choice];
 		connect_host, connect_port = srv_choice.target or to_host, srv_choice.port or connect_port;
-		host_session.log("debug", "Connection failed (%s). Attempt #%d: This time to %s:%d", tostring(err), host_session.srv_choice, connect_host, connect_port);
+		host_session.log("info", "Connection failed (%s). Attempt #%d: This time to %s:%d", tostring(err), host_session.srv_choice, connect_host, connect_port);
 	else
-		host_session.log("debug", "Out of connection options, can't connect to %s", tostring(host_session.to_host));
+		host_session.log("info", "Out of connection options, can't connect to %s", tostring(host_session.to_host));
 		-- We're out of options
 		return false;
 	end
@@ -216,7 +216,7 @@ function attempt_connection(host_session, err)
 end
 
 function try_connect(host_session, connect_host, connect_port)
-	log("debug", "Beginning new connection attempt to %s (%s:%d)", host_session.to_host, connect_host, connect_port);
+	host_session.log("info", "Beginning new connection attempt to %s (%s:%d)", host_session.to_host, connect_host, connect_port);
 	-- Ok, we're going to try to connect
 	
 	local from_host, to_host = host_session.from_host, host_session.to_host;
@@ -338,7 +338,7 @@ function make_authenticated(session, host)
 	else
 		return false;
 	end
-	session.log("info", "connection is now authenticated");
+	session.log("debug", "connection %s->%s is now authenticated", session.from_host or "(unknown)", session.to_host or "(unknown)");
 	
 	mark_connected(session);
 	
@@ -350,7 +350,7 @@ function mark_connected(session)
 	
 	local from, to = session.from_host, session.to_host;
 	
-	session.log("debug", session.direction.." s2s connection "..from.."->"..to.." is now complete");
+	session.log("info", session.direction.." s2s connection "..from.."->"..to.." complete");
 	
 	local send_to_host = send_to_host;
 	function session.send(data) send_to_host(to, from, data); end
diff --git a/core/sessionmanager.lua b/core/sessionmanager.lua
index 52e418cc..68493d87 100644
--- a/core/sessionmanager.lua
+++ b/core/sessionmanager.lua
@@ -45,7 +45,7 @@ function new_session(conn)
 		getmetatable(session.trace).__gc = function () open_sessions = open_sessions - 1; end;
 	end
 	open_sessions = open_sessions + 1;
-	log("info", "open sessions now: ".. open_sessions);
+	log("debug", "open sessions now: ".. open_sessions);
 	local w = conn.write;
 	session.send = function (t) w(tostring(t)); end
 	session.ip = conn.ip();
@@ -53,7 +53,7 @@ function new_session(conn)
 end
 
 function destroy_session(session, err)
-	(session.log or log)("info", "Destroying session");
+	(session.log or log)("info", "Destroying session for %s (%s@%s)", session.full_jid or "(unknown)", session.username or "(unknown)", session.host or "(unknown)");
 	
 	-- Send unavailable presence
 	if session.presence then
@@ -94,6 +94,7 @@ function make_authenticated(session, username)
 	if session.type == "c2s_unauthed" then
 		session.type = "c2s";
 	end
+	session.log("info", "Authenticated as %s@%s", username or "(unknown)", session.host or "(unknown)");
 	return true;
 end
 
@@ -176,7 +177,7 @@ function streamopened(session, attr)
 	
 	send(features);
 	
-	(session.log or log)("info", "Sent reply <stream:stream> to client");
+	(session.log or log)("debug", "Sent reply <stream:stream> to client");
 	session.notopen = nil;
 end
 
diff --git a/plugins/mod_dialback.lua b/plugins/mod_dialback.lua
index fe65d394..b1bc3ae3 100644
--- a/plugins/mod_dialback.lua
+++ b/plugins/mod_dialback.lua
@@ -13,9 +13,9 @@ local s2s_make_authenticated = require "core.s2smanager".make_authenticated;
 local s2s_verify_dialback = require "core.s2smanager".verify_dialback;
 local s2s_destroy_session = require "core.s2smanager".destroy_session;
 
-local st = require "util.stanza";
+local log = module._log;
 
-local log = require "util.logger".init("mod_dialback");
+local st = require "util.stanza";
 
 local xmlns_dialback = "jabber:server:dialback";
 
@@ -24,7 +24,7 @@ local dialback_requests = setmetatable({}, { __mode = 'v' });
 module:add_handler({"s2sin_unauthed", "s2sin"}, "verify", xmlns_dialback,
 	function (origin, stanza)
 		-- We are being asked to verify the key, to ensure it was generated by us
-		log("debug", "verifying dialback key...");
+		origin.log("debug", "verifying that dialback key is ours...");
 		local attr = stanza.attr;
 		-- FIXME: Grr, ejabberd breaks this one too?? it is black and white in XEP-220 example 34
 		--if attr.from ~= origin.to_host then error("invalid-from"); end
@@ -33,9 +33,9 @@ module:add_handler({"s2sin_unauthed", "s2sin"}, "verify", xmlns_dialback,
 			type = "valid"
 		else
 			type = "invalid"
-			log("warn", "Asked to verify a dialback key that was incorrect. An imposter is claiming to be %s?", attr.to);
+			origin.log("warn", "Asked to verify a dialback key that was incorrect. An imposter is claiming to be %s?", attr.to);
 		end
-		log("debug", "verified dialback key... it is %s", type);
+		origin.log("debug", "verified dialback key... it is %s", type);
 		origin.sends2s(st.stanza("db:verify", { from = attr.to, to = attr.from, id = attr.id, type = type }):text(stanza[1]));
 	end);
 
@@ -48,7 +48,7 @@ module:add_handler({ "s2sin_unauthed", "s2sin" }, "result", xmlns_dialback,
 		
 		if not hosts[attr.to] then
 			-- Not a host that we serve
-			log("info", "%s tried to connect to %s, which we don't serve", attr.from, attr.to);
+			origin.log("info", "%s tried to connect to %s, which we don't serve", attr.from, attr.to);
 			origin:close("host-unknown");
 			return;
 		end
@@ -64,7 +64,7 @@ module:add_handler({ "s2sin_unauthed", "s2sin" }, "result", xmlns_dialback,
 			origin.to_host = attr.to;
 		end
 		
-		log("debug", "asking %s if key %s belongs to them", attr.from, stanza[1]);
+		origin.log("debug", "asking %s if key %s belongs to them", attr.from, stanza[1]);
 		send_s2s(attr.to, attr.from,
 			st.stanza("db:verify", { from = attr.to, to = attr.from, id = origin.streamid }):text(stanza[1]));
 	end);
diff --git a/plugins/mod_saslauth.lua b/plugins/mod_saslauth.lua
index f7b30aab..f27d8060 100644
--- a/plugins/mod_saslauth.lua
+++ b/plugins/mod_saslauth.lua
@@ -21,7 +21,7 @@ local jid_split = require "util.jid".split
 local md5 = require "util.hashes".md5;
 local config = require "core.configmanager";
 
-local log = require "util.logger".init("mod_saslauth");
+local log = module._log;
 
 local xmlns_sasl ='urn:ietf:params:xml:ns:xmpp-sasl';
 local xmlns_bind ='urn:ietf:params:xml:ns:xmpp-bind';
@@ -32,16 +32,16 @@ local new_sasl = require "util.sasl".new;
 local function build_reply(status, ret, err_msg)
 	local reply = st.stanza(status, {xmlns = xmlns_sasl});
 	if status == "challenge" then
-		log("debug", ret or "");
+		log("debug", "%s", ret or "");
 		reply:text(base64.encode(ret or ""));
 	elseif status == "failure" then
 		reply:tag(ret):up();
 		if err_msg then reply:tag("text"):text(err_msg); end
 	elseif status == "success" then
-		log("debug", ret or "");
+		log("debug", "%s", ret or "");
 		reply:text(base64.encode(ret or ""));
 	else
-		error("Unknown sasl status: "..status);
+		module:log("error", "Unknown sasl status: %s", status);
 	end
 	return reply;
 end
@@ -50,7 +50,12 @@ local function handle_status(session, status)
 	if status == "failure" then
 		session.sasl_handler = nil;
 	elseif status == "success" then
-		if not session.sasl_handler.username then error("SASL succeeded but we didn't get a username!"); end -- TODO move this to sessionmanager
+		if not session.sasl_handler.username then -- TODO move this to sessionmanager
+			module:log("warn", "SASL succeeded but we didn't get a username!");
+			session.sasl_handler = nil;
+			session:reset_stream();
+			return;
+		end 
 		sm_make_authenticated(session, session.sasl_handler.username);
 		session.sasl_handler = nil;
 		session:reset_stream();
@@ -89,7 +94,7 @@ local function sasl_handler(session, stanza)
 	local text = stanza[1];
 	if text then
 		text = base64.decode(text);
-		log("debug", text);
+		log("debug", "%s", text);
 		if not text then
 			session.sasl_handler = nil;
 			session.send(build_reply("failure", "incorrect-encoding"));
@@ -99,7 +104,7 @@ local function sasl_handler(session, stanza)
 	local status, ret, err_msg = session.sasl_handler:feed(text);
 	handle_status(session, status);
 	local s = build_reply(status, ret, err_msg); 
-	log("debug", "sasl reply: "..tostring(s));
+	log("debug", "sasl reply: %s", tostring(s));
 	session.send(s);
 end
 
@@ -130,7 +135,7 @@ module:add_event_hook("stream-features",
 					
 module:add_iq_handler("c2s", "urn:ietf:params:xml:ns:xmpp-bind", 
 		function (session, stanza)
-			log("debug", "Client tried to bind to a resource");
+			log("debug", "Client requesting a resource bind");
 			local resource;
 			if stanza.attr.type == "set" then
 				local bind = stanza.tags[1];
@@ -153,6 +158,6 @@ module:add_iq_handler("c2s", "urn:ietf:params:xml:ns:xmpp-bind",
 		
 module:add_iq_handler("c2s", "urn:ietf:params:xml:ns:xmpp-session", 
 		function (session, stanza)
-			log("debug", "Client tried to bind to a resource");
+			log("debug", "Client requesting a session");
 			session.send(st.reply(stanza));
 		end);