From e437b90b51eb4b4777fe21f10d9f417d4b8f4df0 Mon Sep 17 00:00:00 2001 From: jomo Date: Sun, 11 Jan 2015 02:13:21 +0100 Subject: [PATCH] prepend uuid to all logs --- modules/cache.js | 8 ++++---- modules/helpers.js | 19 ++++++++----------- modules/networking.js | 32 ++++++++++++++++---------------- modules/renders.js | 22 +++++++++++----------- modules/skins.js | 8 ++++---- routes/avatars.js | 8 +++----- routes/renders.js | 13 ++++++------- routes/skins.js | 7 +++---- test/test.js | 4 ++-- 9 files changed, 57 insertions(+), 64 deletions(-) diff --git a/modules/cache.js b/modules/cache.js index 97b5b3a..ba86d44 100644 --- a/modules/cache.js +++ b/modules/cache.js @@ -37,7 +37,7 @@ function connect_redis() { // sets the date of the face file belonging to +hash+ to now // the helms file is ignored because we only need 1 file to read/write from -function update_file_date(hash) { +function update_file_date(hash, uuid) { if (hash) { var path = config.faces_dir + hash + ".png"; fs.exists(path, function(exists) { @@ -45,11 +45,11 @@ function update_file_date(hash) { var date = new Date(); fs.utimes(path, date, date, function(err){ if (err) { - logging.error(err); + logging.error(uuid + " Error: " + err); } }); } else { - logging.error("Tried to update " + path + " date, but it does not exist"); + logging.error(uuid + " tried to update " + path + " date, but it does not exist"); } }); } @@ -99,7 +99,7 @@ exp.update_timestamp = function(uuid, hash) { // store uuid in lower case if not null uuid = uuid && uuid.toLowerCase(); redis.hmset(uuid, "t", time); - update_file_date(hash); + update_file_date(hash, uuid); }; // create the key +uuid+, store +hash+ and time diff --git a/modules/helpers.js b/modules/helpers.js index 63b8719..68bc4fc 100644 --- a/modules/helpers.js +++ b/modules/helpers.js @@ -44,7 +44,7 @@ function store_images(uuid, details, callback) { callback(null, hash); } else { // download skin - networking.get_skin(skin_url, function(err, img) { + networking.get_skin(skin_url, uuid, function(err, img) { if (err || !img) { callback(err, null); } else { @@ -54,10 +54,10 @@ function store_images(uuid, details, callback) { callback(err); } else { logging.log(uuid + " face extracted"); - logging.debug(facepath); - skins.extract_helm(facepath, img, helmpath, function(err) { + logging.debug(uuid + " " + facepath); + skins.extract_helm(uuid, facepath, img, helmpath, function(err) { logging.log(uuid + " helm extracted"); - logging.debug(helmpath); + logging.debug(uuid + " " + helmpath); cache.save_hash(uuid, hash); callback(err, hash); }); @@ -133,7 +133,6 @@ exp.get_image_hash = function(uuid, callback) { // image is the user's face+helm when helm is true, or the face otherwise // for status, see get_image_hash exp.get_avatar = function(uuid, helm, size, callback) { - logging.log("request: " + uuid); exp.get_image_hash(uuid, function(err, status, hash) { if (hash) { var facepath = __dirname + "/../" + config.faces_dir + hash + ".png"; @@ -165,13 +164,12 @@ exp.get_avatar = function(uuid, helm, size, callback) { // handles requests for +uuid+ skins // callback contains error, hash, image buffer exp.get_skin = function(uuid, callback) { - logging.log(uuid + " skin request"); exp.get_image_hash(uuid, function(err, status, hash) { var skinpath = __dirname + "/../" + config.skins_dir + hash + ".png"; fs.exists(skinpath, function (exists) { if (exists) { - logging.log("skin already exists, not downloading"); - skins.open_skin(skinpath, function(err, img) { + logging.log(uuid + " skin already exists, not downloading"); + skins.open_skin(uuid, skinpath, function(err, img) { callback(err, hash, img); }); } else { @@ -191,7 +189,6 @@ function get_type(helm, body) { // handles creations of skin renders // callback contanis error, hash, image buffer exp.get_render = function(uuid, scale, helm, body, callback) { - logging.log(uuid + " render request"); exp.get_skin(uuid, function(err, hash, img) { if (!hash) { callback(err, -1, hash, null); @@ -200,7 +197,7 @@ exp.get_render = function(uuid, scale, helm, body, callback) { var renderpath = __dirname + "/../" + config.renders_dir + hash + "-" + scale + "-" + get_type(helm, body) + ".png"; fs.exists(renderpath, function (exists) { if (exists) { - renders.open_render(renderpath, function(err, img) { + renders.open_render(uuid, renderpath, function(err, img) { callback(err, 1, hash, img); }); return; @@ -217,7 +214,7 @@ exp.get_render = function(uuid, scale, helm, body, callback) { } else { fs.writeFile(renderpath, img, "binary", function(err){ if (err) { - logging.log(err); + logging.log(uuid + " error: " + err); } callback(null, 2, hash, img); }); diff --git a/modules/networking.js b/modules/networking.js index fa859d7..d1067c4 100644 --- a/modules/networking.js +++ b/modules/networking.js @@ -47,11 +47,11 @@ var get_username_url = function(name, callback) { } else if (response.statusCode == 429) { // Too Many Requests // Never got this, seems like skins aren't limited - logging.warn(body || "Too many requests"); + logging.warn(name + body || "Too many requests"); callback(null, null); } else { logging.error(name + " Unknown error:"); - logging.error(response); + logging.error(name + " " + response); callback(body || "Unknown error", null); } }); @@ -82,7 +82,7 @@ var get_uuid_url = function(uuid, callback) { callback(body || "Too many requests", null); } else { logging.error(uuid + " Unknown error:"); - logging.error(response); + logging.error(uuid + " " + response); callback(body || "Unknown error", null); } }); @@ -106,7 +106,7 @@ exp.get_skin_url = function(uuid, callback) { // downloads skin file from +url+ // callback contains error, image -exp.get_skin = function(url, callback) { +exp.get_skin = function(url, uuid, callback) { request.get({ url: url, headers: { @@ -117,23 +117,23 @@ exp.get_skin = function(url, callback) { }, function (error, response, body) { if (!error && response.statusCode == 200) { // skin downloaded successfully - logging.log("downloaded skin"); - logging.debug(url); + logging.log(uuid + " downloaded skin"); + logging.debug(uuid + " " + url); callback(null, body); } else { if (error) { - logging.error("Error downloading '" + url + "': " + error); + logging.error(uuid + " error downloading '" + url + "': " + error); } else if (response.statusCode == 404) { - logging.warn("texture not found (404): " + url); + logging.warn(uuid + " texture not found (404): " + url); } else if (response.statusCode == 429) { // Too Many Requests // Never got this, seems like textures aren't limited - logging.warn("too many requests for " + url); - logging.warn(body); + logging.warn(uuid + " too many requests for " + url); + logging.warn(uuid + " " + body); } else { - logging.error("unknown error for " + url); - logging.error(response); - logging.error(body); + logging.error(uuid + " unknown error for " + url); + logging.error(uuid + " " + response); + logging.error(uuid + " " + body); error = "unknown error"; // Error needs to be set, otherwise null in callback } callback(error, null); @@ -144,14 +144,14 @@ exp.get_skin = function(url, callback) { exp.save_skin = function(uuid, hash, outpath, callback) { if (hash) { var skinurl = "http://textures.minecraft.net/texture/" + hash; - exp.get_skin(skinurl, function(err, img) { + exp.get_skin(skinurl, uuid, function(err, img) { if (err) { - logging.error("error while downloading skin"); + logging.error(uuid + " error while downloading skin"); callback(err, null); } else { fs.writeFile(outpath, img, "binary", function(err){ if (err) { - logging.log(err); + logging.log(uuid + " error: " + err); } callback(null, img); }); diff --git a/modules/renders.js b/modules/renders.js index ecdb976..4df51c7 100644 --- a/modules/renders.js +++ b/modules/renders.js @@ -42,9 +42,9 @@ exp.draw_head = function(skin_canvas, model_ctx, scale) { // draws the body on to the +skin_canvas+ // using the skin from the +model_ctx+ at the +scale+ // parts are labeled as if drawn from the skin's POV -exp.draw_body = function(skin_canvas, model_ctx, scale) { +exp.draw_body = function(uuid, skin_canvas, model_ctx, scale) { if (skin_canvas.height == 32 * scale) { - logging.log("old skin"); + logging.log(uuid + " old skin"); //Left Leg //Left Leg - Front model_ctx.setTransform(1,-0.5,0,1.2,0,0); @@ -85,7 +85,7 @@ exp.draw_body = function(skin_canvas, model_ctx, scale) { model_ctx.scale(-1,1); model_ctx.drawImage(skin_canvas, 44*scale, 16*scale, 4*scale, 4*scale, -16*scale, 16*scale, 4*scale, 4*scale); } else { - logging.log("new skin"); + logging.log(uuid + " new skin"); //Left Leg //Left Leg - Front model_ctx.setTransform(1,-0.5,0,1.2,0,0); @@ -134,7 +134,7 @@ exp.draw_model = function(uuid, img, scale, helm, body, callback) { var image = new Image(); image.onerror = function(err) { - logging.error("render error: " + err); + logging.error(uuid + " render error: " + err); callback(err, null); }; @@ -151,19 +151,19 @@ exp.draw_model = function(uuid, img, scale, helm, body, callback) { //Scale it scale_image(skin_ctx.getImageData(0,0,64,original_height), skin_ctx, 0, 0, scale); if (body) { - logging.log("drawing body"); - exp.draw_body(skin_canvas, model_ctx, scale); + logging.log(uuid + " drawing body"); + exp.draw_body(uuid, skin_canvas, model_ctx, scale); } - logging.log("drawing head"); + logging.log(uuid + " drawing head"); exp.draw_head(skin_canvas, model_ctx, scale); if (helm) { - logging.log("drawing helmet"); + logging.log(uuid + " drawing helmet"); exp.draw_helmet(skin_canvas, model_ctx, scale); } model_canvas.toBuffer(function(err, buf){ if (err) { - logging.log("error creating buffer: " + err); + logging.log(uuid + " error creating buffer: " + err); } callback(err, buf); }); @@ -174,10 +174,10 @@ exp.draw_model = function(uuid, img, scale, helm, body, callback) { // helper method to open a render from +renderpath+ // callback contains error, image buffer -exp.open_render = function(renderpath, callback) { +exp.open_render = function(uuid, renderpath, callback) { fs.readFile(renderpath, function (err, buf) { if (err) { - logging.error("error while opening skin file: " + err); + logging.error(uuid + " error while opening skin file: " + err); } callback(err, buf); }); diff --git a/modules/skins.js b/modules/skins.js index 0681733..669d9cf 100644 --- a/modules/skins.js +++ b/modules/skins.js @@ -29,7 +29,7 @@ exp.extract_face = function(buffer, outname, callback) { // +facefile+ is the filename of an image produced by extract_face // result is saved to a file called +outname+ // +callback+ contains error -exp.extract_helm = function(facefile, buffer, outname, callback) { +exp.extract_helm = function(uuid, facefile, buffer, outname, callback) { lwip.open(buffer, "png", function(err, skin_img) { if (err) { callback(err); @@ -53,7 +53,7 @@ exp.extract_helm = function(facefile, buffer, outname, callback) { callback(err); }); } else { - logging.log("Helm image is the same as face image, not storing!"); + logging.log(uuid + " helm image is the same as face image, not storing!"); callback(null); } }); @@ -95,10 +95,10 @@ exp.default_skin = function(uuid) { // helper method for opening a skin file from +skinpath+ // callback contains error, image buffer -exp.open_skin = function(skinpath, callback) { +exp.open_skin = function(uuid, skinpath, callback) { fs.readFile(skinpath, function (err, buf) { if (err) { - logging.error("error while opening skin file: " + err); + logging.error(uuid + " error while opening skin file: " + err); } callback(err, buf); }); diff --git a/routes/avatars.js b/routes/avatars.js index 2bb68ab..ec1a3ca 100644 --- a/routes/avatars.js +++ b/routes/avatars.js @@ -50,7 +50,6 @@ module.exports = function(req, res) { if (err) { logging.error(uuid + " " + err); if (err.code == "ENOENT") { - logging.warn("Deleting " + uuid + " from cache!"); cache.remove_hash(uuid); } } @@ -63,16 +62,15 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.debug("Etag: " + req.headers["if-none-match"]); - logging.debug("matches: " + matches); + logging.debug(uuid + " etag: " + req.headers["if-none-match"]); + logging.debug(uuid + " matches: " + matches); sendimage(http_status, status, image, uuid); } else { handle_default(404, status, uuid); } }); } catch(e) { - logging.error(uuid + " error:"); - logging.error(e); + logging.error(uuid + " error: " + e); handle_default(500, status, uuid); } diff --git a/routes/renders.js b/routes/renders.js index 9c1d62b..1a1b4ff 100644 --- a/routes/renders.js +++ b/routes/renders.js @@ -73,17 +73,16 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.log("matches: " + matches); - logging.log("Etag: " + req.headers["if-none-match"]); + logging.debug(uuid + " etag: " + req.headers["if-none-match"]); + logging.debug(uuid + " matches: " + matches); sendimage(http_status, status, image, uuid); } else { - logging.log("image not found, using default."); + logging.log(uuid + " image not found, using default."); handle_default(404, status, uuid); } }); } catch(e) { - logging.error(uuid + " error:"); - logging.error(e); + logging.error(uuid + " error: " + e); handle_default(500, status, uuid); } @@ -106,12 +105,12 @@ module.exports = function(req, res) { fs.readFile("public/images/" + def + "_skin.png", function (err, buf) { if (err) { // errored while loading the default image, continuing with null image - logging.error("error loading default render image: " + err); + logging.error(uuid + "error loading default render image: " + err); } // we render the default skins, but not custom images renders.draw_model(uuid, buf, scale, helm, body, function(err, def_img) { if (err) { - logging.log("error while rendering default image: " + err); + logging.log(uuid + "error while rendering default image: " + err); } sendimage(http_status, img_status, def_img, uuid); }); diff --git a/routes/skins.js b/routes/skins.js index 58ef711..bcff7e2 100644 --- a/routes/skins.js +++ b/routes/skins.js @@ -39,16 +39,15 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.debug("Etag: " + req.headers["if-none-match"]); - logging.debug("matches: " + matches); + logging.debug(uuid + " etag: " + req.headers["if-none-match"]); + logging.debug(uuid + " matches: " + matches); sendimage(http_status, image, uuid); } else { handle_default(404, uuid); } }); } catch(e) { - logging.error(uuid + " error:"); - logging.error(e); + logging.error(uuid + " error: " + e); handle_default(500, uuid); } diff --git a/test/test.js b/test/test.js index 605ab7c..5a69fe3 100644 --- a/test/test.js +++ b/test/test.js @@ -135,7 +135,7 @@ describe("Crafatar", function() { it("should time out on skin download", function(done) { var original_timeout = config.http_timeout; config.http_timeout = 1; - networking.get_skin("http://textures.minecraft.net/texture/477be35554684c28bdeee4cf11c591d3c88afb77e0b98da893fd7bc318c65184", function(err, img) { + networking.get_skin("http://textures.minecraft.net/texture/477be35554684c28bdeee4cf11c591d3c88afb77e0b98da893fd7bc318c65184", uuid, function(err, img) { assert.strictEqual(err.code, "ETIMEDOUT"); config.http_timeout = original_timeout; done(); @@ -143,7 +143,7 @@ describe("Crafatar", function() { }); it("should not find the skin", function(done) { assert.doesNotThrow(function() { - networking.get_skin("http://textures.minecraft.net/texture/this-does-not-exist", function(err, img) { + networking.get_skin("http://textures.minecraft.net/texture/this-does-not-exist", uuid, function(err, img) { assert.strictEqual(err, null); // no error here, but it shouldn't throw exceptions done(); });