diff --git a/modules/cache.js b/modules/cache.js index f335cb3..5838a80 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, uuid) { +function update_file_date(rid, hash) { if (hash) { var path = config.faces_dir + hash + ".png"; fs.exists(path, function(exists) { @@ -45,11 +45,11 @@ function update_file_date(hash, uuid) { var date = new Date(); fs.utimes(path, date, date, function(err){ if (err) { - logging.error(uuid + " Error: " + err); + logging.error(rid + "Error: " + err.stack); } }); } else { - logging.error(uuid + " tried to update " + path + " date, but it does not exist"); + logging.error(rid + "tried to update " + path + " date, but it does not exist"); } }); } @@ -93,19 +93,19 @@ exp.info = function(callback) { }; // sets the timestamp for +uuid+ and its face file's date to now -exp.update_timestamp = function(uuid, hash) { - logging.log(uuid + " cache: updating timestamp"); +exp.update_timestamp = function(rid, uuid, hash) { + logging.log(rid + "cache: updating timestamp"); var time = new Date().getTime(); // store uuid in lower case if not null uuid = uuid && uuid.toLowerCase(); redis.hmset(uuid, "t", time); - update_file_date(hash, uuid); + update_file_date(rid, hash); }; -// create the key +uuid+, store +hash+ and time -exp.save_hash = function(uuid, skin, cape) { - logging.log(uuid + " cache: saving hash"); - logging.log("skin:" + skin + " cape:" + cape); +// create the key +uuid+, store +skin+ hash, +cape+ hash and time +exp.save_hash = function(rid, uuid, skin, cape) { + logging.log(rid + "cache: saving hash"); + logging.log(rid + "skin:" + skin + " cape:" + cape); var time = new Date().getTime(); // store shorter null byte instead of "null" skin = skin || "."; @@ -115,8 +115,8 @@ exp.save_hash = function(uuid, skin, cape) { redis.hmset(uuid, "s", skin, "c", cape, "t", time); }; -exp.remove_hash = function(uuid) { - logging.log(uuid + " cache: deleting hash"); +exp.remove_hash = function(rid, uuid) { + logging.log(rid + "cache: deleting hash"); redis.del(uuid.toLowerCase(), "h", "t"); }; diff --git a/modules/helpers.js b/modules/helpers.js index 5648dc8..08b8f6b 100644 --- a/modules/helpers.js +++ b/modules/helpers.js @@ -15,35 +15,35 @@ function get_hash(url) { return hash_pattern.exec(url)[0].toLowerCase(); } -function store_skin(uuid, profile, details, callback) { - networking.get_skin_url(uuid, profile, function(url) { +function store_skin(rid, uuid, profile, details, callback) { + networking.get_skin_url(rid, uuid, profile, function(url) { if (url) { var hash = get_hash(url); if (details && details.skin === hash) { - cache.update_timestamp(uuid, hash); + cache.update_timestamp(rid, uuid, hash); callback(null, hash); } else { - logging.log(uuid + " new skin hash: " + hash); + logging.log(rid + "new skin hash: " + hash); var facepath = __dirname + "/../" + config.faces_dir + hash + ".png"; var helmpath = __dirname + "/../" + config.helms_dir + hash + ".png"; fs.exists(facepath, function(exists) { if (exists) { - logging.log(uuid + " skin already exists, not downloading"); + logging.log(rid + "skin already exists, not downloading"); callback(null, hash); } else { - networking.get_from(url, function(img, response, err) { + networking.get_from(rid, url, function(img, response, err) { if (err || !img) { callback(err, null); } else { skins.extract_face(img, facepath, function(err) { if (err) { - logging.error(err); + logging.error(rid + err.stack); callback(err, null); } else { - logging.log(uuid + " face extracted"); - skins.extract_helm(uuid, facepath, img, helmpath, function(err) { - logging.log(uuid + " helm extracted"); - logging.debug(helmpath); + logging.log(rid + "face extracted"); + skins.extract_helm(rid, facepath, img, helmpath, function(err) { + logging.log(rid + "helm extracted"); + logging.debug(rid + helmpath); callback(err, hash); }); } @@ -59,28 +59,28 @@ function store_skin(uuid, profile, details, callback) { }); } -function store_cape(uuid, profile, details, callback) { - networking.get_cape_url(uuid, profile, function(url) { +function store_cape(rid, uuid, profile, details, callback) { + networking.get_cape_url(rid, uuid, profile, function(url) { if (url) { var hash = get_hash(url); if (details && details.cape === hash) { - cache.update_timestamp(uuid, hash); + cache.update_timestamp(rid, uuid, hash); callback(null, hash); } else { - logging.log(uuid + " new cape hash: " + hash); + logging.log(rid + "new cape hash: " + hash); var capepath = __dirname + "/../" + config.capes_dir + hash + ".png"; fs.exists(capepath, function(exists) { if (exists) { - logging.log(uuid + " cape already exists, not downloading"); + logging.log(rid + "cape already exists, not downloading"); callback(null, hash); } else { - networking.get_from(url, function(img, response, err) { + networking.get_from(rid, url, function(img, response, err) { if (err || !img) { - logging.error(err); + logging.error(rid + err.stack); callback(err, null); } else { skins.save_image(img, capepath, function(err) { - logging.log(uuid + " cape saved"); + logging.log(rid + "cape saved"); callback(err, hash); }); } @@ -103,7 +103,7 @@ function callback_for(uuid, type, err, hash) { for (var i = 0; i < currently_running.length; i++) { var current = currently_running[i]; if (current.uuid === uuid && current.type === type) { - logging.debug(uuid + " now completing queued " + type + " request"); + logging.debug(current.rid + "now completing queued " + type + " request"); current.callback(err, hash); currently_running.splice(i, 1); // remove from array i--; @@ -120,31 +120,32 @@ function array_has_obj(arr, property, value) { return false; } -function store_images(uuid, details, type, callback) { +function store_images(rid, uuid, details, type, callback) { var is_uuid = uuid.length > 16; var new_hash = { + rid: rid, uuid: uuid, type: type, callback: callback }; if (!array_has_obj(currently_running, "uuid", uuid)) { currently_running.push(new_hash); - networking.get_profile((is_uuid ? uuid : null), function(err, profile) { + networking.get_profile(rid, (is_uuid ? uuid : null), function(err, profile) { if (err || (is_uuid && !profile)) { callback_for(uuid, type, err, null); } else { - store_skin(uuid, profile, details, function(err, skin_hash) { - cache.save_hash(uuid, skin_hash, null); + store_skin(rid, uuid, profile, details, function(err, skin_hash) { + cache.save_hash(rid, uuid, skin_hash, null); callback_for(uuid, "skin", err, skin_hash); - store_cape(uuid, profile, details, function(err, cape_hash) { - cache.save_hash(uuid, skin_hash, cape_hash); + store_cape(rid, uuid, profile, details, function(err, cape_hash) { + cache.save_hash(rid, uuid, skin_hash, cape_hash); callback_for(uuid, "cape", err, cape_hash); }); }); } }); } else { - logging.log(uuid + " ID already being processed, adding to queue"); + logging.log(rid + "ID already being processed, adding to queue"); currently_running.push(new_hash); } } @@ -165,28 +166,28 @@ exp.uuid_valid = function(uuid) { // 1: "cached" - found on disk // 2: "downloaded" - profile downloaded, skin downloaded from mojang servers // 3: "checked" - profile re-downloaded (was too old), but it has either not changed or has no skin -exp.get_image_hash = function(uuid, raw_type, callback) { +exp.get_image_hash = function(rid, uuid, raw_type, callback) { cache.get_details(uuid, function(err, details) { var type = (details !== null ? (raw_type === "skin" ? details.skin : details.cape) : null); if (err) { callback(err, -1, null); } else { if (details && details.time + config.local_cache_time * 1000 >= new Date().getTime()) { - logging.log(uuid + " uuid cached & recently updated"); + logging.log(rid + "uuid cached & recently updated"); callback(null, (type ? 1 : 0), type); } else { if (details) { - logging.log(uuid + " uuid cached, but too old"); + logging.log(rid + "uuid cached, but too old"); } else { - logging.log(uuid + " uuid not cached"); + logging.log(rid + "uuid not cached"); } - store_images(uuid, details, raw_type, function(err, hash) { + store_images(rid, uuid, details, raw_type, function(err, hash) { if (err) { callback(err, -1, details && type); } else { var status = details && (type === hash) ? 3 : 2; - logging.debug(uuid + " old hash: " + (details && type)); - logging.log(uuid + " hash: " + hash); + logging.debug(rid + "old hash: " + (details && type)); + logging.log(rid + "hash: " + hash); callback(null, status, hash); } }); @@ -200,9 +201,8 @@ exp.get_image_hash = function(uuid, raw_type, callback) { // callback contains error, status, image buffer, hash // 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, "skin", function(err, status, hash) { +exp.get_avatar = function(rid, uuid, helm, size, callback) { + exp.get_image_hash(rid, uuid, "skin", function(err, status, hash) { if (hash) { var facepath = __dirname + "/../" + config.faces_dir + hash + ".png"; var helmpath = __dirname + "/../" + config.helms_dir + hash + ".png"; @@ -230,18 +230,18 @@ 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, "skin", function(err, status, hash) { +exp.get_skin = function(rid, uuid, callback) { + logging.log(rid + "skin request"); + exp.get_image_hash(rid, uuid, "skin", function(err, status, hash) { var skinpath = __dirname + "/../" + config.skins_dir + hash + ".png"; - fs.exists(skinpath, function (exists) { + fs.exists(skinpath, function(exists) { if (exists) { - logging.log(uuid + " skin already exists, not downloading"); + logging.log(rid + "skin already exists, not downloading"); skins.open_skin(uuid, skinpath, function(err, img) { callback(err, hash, img); }); } else { - networking.save_texture(uuid, hash, skinpath, function(err, img) { + networking.save_texture(rid, uuid, hash, skinpath, function(err, response, img) { callback(err, hash, img); }); } @@ -256,8 +256,8 @@ 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) { - exp.get_skin(uuid, function(err, hash, img) { +exp.get_render = function(rid, uuid, scale, helm, body, callback) { + exp.get_skin(rid, uuid, function(err, hash, img) { if (!hash) { callback(err, -1, hash, null); return; @@ -265,7 +265,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(uuid, renderpath, function(err, img) { + renders.open_render(rid, renderpath, function(err, img) { callback(err, 1, hash, img); }); return; @@ -274,7 +274,7 @@ exp.get_render = function(uuid, scale, helm, body, callback) { callback(err, 0, hash, null); return; } - renders.draw_model(uuid, img, scale, helm, body, function(err, img) { + renders.draw_model(rid, img, scale, helm, body, function(err, img) { if (err) { callback(err, -1, hash, null); } else if (!img) { @@ -282,7 +282,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(rid + err.stack); } callback(null, 2, hash, img); }); @@ -293,33 +293,11 @@ exp.get_render = function(uuid, scale, helm, body, 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, "skin", 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(uuid, skinpath, function(err, img) { - callback(err, hash, img); - }); - } else { - networking.save_texture(uuid, hash, skinpath, function(err, response, img) { - callback(err, hash, img); - }); - } - }); - }); -}; - // handles requests for +uuid+ capes // callback contains error, hash, image buffer -exp.get_cape = function(uuid, callback) { - logging.log(uuid + " cape request"); - exp.get_image_hash(uuid, "cape", function(err, status, hash) { +exp.get_cape = function(rid, uuid, callback) { + logging.log(rid + "cape request"); + exp.get_image_hash(rid, uuid, "cape", function(err, status, hash) { if (!hash) { callback(err, null, null); return; @@ -327,12 +305,12 @@ exp.get_cape = function(uuid, callback) { var capepath = __dirname + "/../" + config.capes_path + hash + ".png"; fs.exists(capepath, function(exists) { if (exists) { - logging.log("cape already exists, not downloading"); + logging.log(rid + "cape already exists, not downloading"); skins.open_skin(uuid, capepath, function(err, img) { callback(err, hash, img); }); } else { - networking.save_texture(uuid, hash, capepath, function(err, response, img) { + networking.save_texture(rid, uuid, hash, capepath, function(err, response, img) { if (response && response.statusCode === 404) { callback(err, hash, null); } else { diff --git a/modules/networking.js b/modules/networking.js index 094c23d..c2970eb 100644 --- a/modules/networking.js +++ b/modules/networking.js @@ -40,7 +40,7 @@ exp.extract_cape_url = function(profile) { // encoding and timeouts, defaults are already // specified. +callback+ contains the body, response, // and error buffer. get_from helper method is available -exp.get_from_options = function(url, options, callback) { +exp.get_from_options = function(rid, url, options, callback) { request.get({ url: url, headers: { @@ -54,29 +54,29 @@ exp.get_from_options = function(url, options, callback) { // 200 or 301 depending on content type if (!error && (response.statusCode === 200 || response.statusCode === 301)) { // response received successfully - logging.log(url + " url received"); + logging.log(rid + url + " url received"); callback(body, response, null); } else if (error) { callback(body || null, response, error); } else if (response.statusCode === 404) { // page does not exist - logging.log(url + " url does not exist"); + logging.log(rid + url + " url does not exist"); callback(null, response, null); } else if (response.statusCode === 429) { // Too Many Requests exception - code 429 - logging.warn(body || "Too many requests"); + logging.warn(rid + body || "Too many requests"); callback(body || null, response, error); } else { - logging.error(url + " Unknown error:"); - //logging.error(response); + logging.error(rid + url + " Unknown error:"); + logging.error(rid + response); callback(body || null, response, error); } }); }; // helper method for get_from_options, no options required -exp.get_from = function(url, callback) { - exp.get_from_options(url, {}, function(body, response, err) { +exp.get_from = function(rid, url, callback) { + exp.get_from_options(rid, url, {}, function(body, response, err) { callback(body, response, err); }); }; @@ -90,8 +90,8 @@ var mojang_url_types = { // make a request to skins.miencraft.net // the skin url is taken from the HTTP redirect // type reference is above -exp.get_username_url = function(name, type, callback) { - exp.get_from(mojang_url_types[type] + name + ".png", function(body, response, err) { +exp.get_username_url = function(rid, name, type, callback) { + exp.get_from(rid, mojang_url_types[type] + name + ".png", function(body, response, err) { if (!err) { callback(err, response ? (response.statusCode === 404 ? null : response.headers.location) : null); } else { @@ -114,21 +114,21 @@ exp.get_uuid_url = function(profile, type, callback) { // make a request to sessionserver // profile is returned as json -exp.get_profile = function(uuid, callback) { +exp.get_profile = function(rid, uuid, callback) { if (!uuid) { callback(null, null); } else { - exp.get_from_options(session_url + uuid, { encoding: "utf8" }, function(body, response, err) { + exp.get_from_options(rid, session_url + uuid, { encoding: "utf8" }, function(body, response, err) { callback(err || null, (body !== null ? JSON.parse(body) : null)); - }); + }); } }; // +uuid+ is likely a username and if so // +uuid+ is used to get the url, otherwise // +profile+ will be used to get the url -exp.get_skin_url = function(uuid, profile, callback) { - getUrl(uuid, profile, 1, function(url) { +exp.get_skin_url = function(rid, uuid, profile, callback) { + getUrl(rid, uuid, profile, 1, function(url) { callback(url); }); }; @@ -136,16 +136,16 @@ exp.get_skin_url = function(uuid, profile, callback) { // +uuid+ is likely a username and if so // +uuid+ is used to get the url, otherwise // +profile+ will be used to get the url -exp.get_cape_url = function(uuid, profile, callback) { - getUrl(uuid, profile, 2, function(url) { +exp.get_cape_url = function(rid, uuid, profile, callback) { + getUrl(rid, uuid, profile, 2, function(url) { callback(url); }); }; -function getUrl(uuid, profile, type, callback) { +function getUrl(rid, uuid, profile, type, callback) { if (uuid.length <= 16) { //username - exp.get_username_url(uuid, type, function(err, url) { + exp.get_username_url(rid, uuid, type, function(err, url) { callback(url || null); }); } else { @@ -155,25 +155,17 @@ function getUrl(uuid, profile, type, callback) { } } -// downloads skin file from +url+ -// callback contains error, image -exp.get_skin = function(url, uuid, callback) { - exp.get_from(url, function(body, response, err) { - callback(body, err); - }); -}; - -exp.save_texture = function(uuid, hash, outpath, callback) { +exp.save_texture = function(rid, uuid, hash, outpath, callback) { if (hash) { var textureurl = "http://textures.minecraft.net/texture/" + hash; - exp.get_from(textureurl, function(img, response, err) { + exp.get_from(rid, textureurl, function(img, response, err) { if (err) { - logging.error(uuid + "error while downloading texture"); + logging.error(rid + "error while downloading texture"); callback(err, response, null); } else { fs.writeFile(outpath, img, "binary", function(err) { if (err) { - logging.log(uuid + " error: " + err); + logging.log(rid + "error: " + err.stack); } callback(err, response, img); }); @@ -184,10 +176,4 @@ exp.save_texture = function(uuid, hash, outpath, callback) { } }; -exp.get_cape = function(url, callback) { - exp.get_from(url, function(body, response, err) { - callback(err, body); - }); -}; - -module.exports = exp; +module.exports = exp; \ No newline at end of file diff --git a/modules/renders.js b/modules/renders.js index 5d922e6..4f1776e 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(uuid, skin_canvas, model_ctx, scale) { +exp.draw_body = function(rid, skin_canvas, model_ctx, scale) { if (skin_canvas.height == 32 * scale) { - logging.log(uuid + " old skin"); + logging.debug(rid + "uses old skin format"); //Left Leg //Left Leg - Front model_ctx.setTransform(1,-0.5,0,1.2,0,0); @@ -85,7 +85,7 @@ exp.draw_body = function(uuid, 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(uuid + " new skin"); + logging.debug(rid + "uses new skin format"); //Left Leg //Left Leg - Front model_ctx.setTransform(1,-0.5,0,1.2,0,0); @@ -127,14 +127,14 @@ exp.draw_body = function(uuid, skin_canvas, model_ctx, scale) { }; // sets up the necessary components to draw the skin model -// uses the +img+ skin from the +uuid+ with options of drawing +// uses the +img+ skin with options of drawing // the +helm+ and the +body+ // callback contains error, image buffer -exp.draw_model = function(uuid, img, scale, helm, body, callback) { +exp.draw_model = function(rid, img, scale, helm, body, callback) { var image = new Image(); image.onerror = function(err) { - logging.error(uuid + " render error: " + err); + logging.error(rid + "render error: " + err.stack); 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(uuid + " drawing body"); - exp.draw_body(uuid, skin_canvas, model_ctx, scale); + logging.log(rid + "drawing body"); + exp.draw_body(rid, skin_canvas, model_ctx, scale); } - logging.log(uuid + " drawing head"); + logging.log(rid + "drawing head"); exp.draw_head(skin_canvas, model_ctx, scale); if (helm) { - logging.log(uuid + " drawing helmet"); + logging.log(rid + "drawing helmet"); exp.draw_helmet(skin_canvas, model_ctx, scale); } model_canvas.toBuffer(function(err, buf){ if (err) { - logging.log(uuid + " error creating buffer: " + err); + logging.log(rid + "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(uuid, renderpath, callback) { +exp.open_render = function(rid, renderpath, callback) { fs.readFile(renderpath, function (err, buf) { if (err) { - logging.error(uuid + " error while opening skin file: " + err); + logging.error(rid + "error while opening skin file: " + err); } callback(err, buf); }); diff --git a/modules/skins.js b/modules/skins.js index 4dacb6d..de7af35 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(uuid, facefile, buffer, outname, callback) { +exp.extract_helm = function(rid, facefile, buffer, outname, callback) { lwip.open(buffer, "png", function(err, skin_img) { if (err) { callback(err); @@ -53,7 +53,7 @@ exp.extract_helm = function(uuid, facefile, buffer, outname, callback) { callback(err); }); } else { - logging.log(uuid + " helm image is the same as face image, not storing!"); + logging.log(rid + "helm image is the same as face image, not storing!"); callback(null); } }); @@ -62,10 +62,10 @@ exp.extract_helm = function(uuid, facefile, buffer, outname, callback) { } }); }); -} -}); -} -}); + } + }); + } + }); }; // resizes the image file +inname+ to +size+ by +size+ pixels @@ -98,7 +98,7 @@ exp.default_skin = function(uuid) { exp.open_skin = function(uuid, skinpath, callback) { fs.readFile(skinpath, function(err, buf) { if (err) { - logging.error(uuid + " error while opening skin file: " + err); + logging.error(rid + "error while opening skin file: " + err); callback(err, null); } else { callback(null, buf); diff --git a/routes/avatars.js b/routes/avatars.js index cb343d6..d8ccf99 100644 --- a/routes/avatars.js +++ b/routes/avatars.js @@ -20,6 +20,7 @@ module.exports = function(req, res) { var def = req.url.query.default; var helm = req.url.query.hasOwnProperty("helm"); var etag = null; + var rid = req.id; // Prevent app from crashing/freezing if (size < config.min_size || size > config.max_size) { @@ -42,14 +43,16 @@ module.exports = function(req, res) { // strip dashes uuid = uuid.replace(/-/g, ""); + logging.log(rid + "uuid: " + uuid); try { - helpers.get_avatar(uuid, helm, size, function(err, status, image, hash) { - logging.log(uuid + " - " + human_status[status]); + helpers.get_avatar(rid, uuid, helm, size, function(err, status, image, hash) { + logging.log(rid + "storage type: " + human_status[status]); if (err) { - logging.error(uuid + " " + err); + logging.error(rid + err); if (err.code === "ENOENT") { - cache.remove_hash(uuid); + // no such file + cache.remove_hash(rid, uuid); } } etag = image && hash && hash.substr(0, 32) || "none"; @@ -61,25 +64,26 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.debug(uuid + " etag: " + req.headers["if-none-match"]); - logging.debug(uuid + " matches: " + matches); - sendimage(http_status, status, image, uuid); + logging.debug(rid + "etag: " + req.headers["if-none-match"]); + logging.debug(rid + "matches: " + matches); + sendimage(rid, http_status, status, image); } else { - handle_default(404, status, uuid); + handle_default(rid, 404, status, uuid); } }); } catch(e) { - logging.error(uuid + " error: " + e); - handle_default(500, status, uuid); + logging.error(rid + "error: " + e.stack); + handle_default(rid, 500, -1, uuid); } - function handle_default(http_status, img_status, uuid) { + function handle_default(rid, http_status, img_status, uuid) { if (def && def !== "steve" && def !== "alex") { - logging.log(uuid + " status: 301"); + logging.log(rid + "status: 301"); res.writeHead(301, { "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": human_status[img_status], + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Location": def }); @@ -87,18 +91,19 @@ module.exports = function(req, res) { } else { def = def || skins.default_skin(uuid); skins.resize_img("public/images/" + def + ".png", size, function(err, image) { - sendimage(http_status, img_status, image, uuid); + sendimage(rid, http_status, img_status, image); }); } } - function sendimage(http_status, img_status, image, uuid) { - logging.log(uuid + " status: " + http_status); + function sendimage(rid, http_status, img_status, image) { + logging.log(rid + "status: " + http_status); res.writeHead(http_status, { "Content-Type": "image/png", "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": human_status[img_status], + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Etag": '"' + etag + '"' }); diff --git a/routes/capes.js b/routes/capes.js index efbb8fd..9070fa9 100644 --- a/routes/capes.js +++ b/routes/capes.js @@ -15,6 +15,7 @@ module.exports = function(req, res) { var start = new Date(); var uuid = (req.url.pathname.split("/")[2] || "").split(".")[0]; var etag = null; + var rid = req.id; if (!helpers.uuid_valid(uuid)) { res.writeHead(422, { @@ -27,12 +28,17 @@ module.exports = function(req, res) { // strip dashes uuid = uuid.replace(/-/g, ""); + logging.log(rid + "uuid: " + uuid); try { - helpers.get_cape(uuid, function(err, status, image, hash) { - logging.log(uuid + " - " + human_status[status]); + helpers.get_cape(rid, uuid, function(err, status, image, hash) { + logging.log(rid + "storage type: " + human_status[status]); if (err) { - logging.error(uuid + " " + err); + logging.error(rid + err); + if (err.code == "ENOENT") { + // no such file + cache.remove_hash(rid, uuid); + } } etag = hash && hash.substr(0, 32) || "none"; var matches = req.headers["if-none-match"] === '"' + etag + '"'; @@ -43,10 +49,10 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.debug("Etag: " + req.headers["if-none-match"]); - logging.debug("matches: " + matches); - logging.log("status: " + http_status); - sendimage(http_status, status, image); + logging.debug(rid + "etag: " + req.headers["if-none-match"]); + logging.debug(rid + "matches: " + matches); + logging.log(rid + "status: " + http_status); + sendimage(rid, http_status, status, image); } else { res.writeHead(404, { "Content-Type": "text/plain", @@ -56,8 +62,7 @@ module.exports = function(req, res) { } }); } catch(e) { - logging.error(uuid + " error:"); - logging.error(e); + logging.error(rid + "error:" + e.stack); res.writeHead(500, { "Content-Type": "text/plain", "Response-Time": new Date() - start @@ -65,12 +70,13 @@ module.exports = function(req, res) { res.end("500 server error"); } - function sendimage(http_status, img_status, image) { + function sendimage(rid, http_status, img_status, image) { res.writeHead(http_status, { "Content-Type": "image/png", "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": human_status[img_status], + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Etag": '"' + etag + '"' }); diff --git a/routes/renders.js b/routes/renders.js index d6e4986..712fb7a 100644 --- a/routes/renders.js +++ b/routes/renders.js @@ -21,6 +21,7 @@ var human_status = { module.exports = function(req, res) { var start = new Date(); var raw_type = (req.url.path_list[2] || ""); + var rid = req.id; // validate type if (raw_type !== "body" && raw_type !== "head") { @@ -57,12 +58,17 @@ module.exports = function(req, res) { // strip dashes uuid = uuid.replace(/-/g, ""); + logging.log(rid + "uuid: " + uuid); try { - helpers.get_render(uuid, scale, helm, body, function(err, status, hash, image) { - logging.log(uuid + " - " + human_status[status]); + helpers.get_render(rid, uuid, scale, helm, body, function(err, status, hash, image) { + logging.log(rid + "storage type: " + human_status[status]); if (err) { - logging.error(uuid + " " + err); + logging.error(rid + err); + if (err.code == "ENOENT") { + // no such file + cache.remove_hash(rid, uuid); + } } etag = hash && hash.substr(0, 32) || "none"; var matches = req.headers["if-none-match"] === '"' + etag + '"'; @@ -73,29 +79,30 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.debug(uuid + " etag: " + req.headers["if-none-match"]); - logging.debug(uuid + " matches: " + matches); - sendimage(http_status, status, image, uuid); + logging.debug(rid + "etag: " + req.headers["if-none-match"]); + logging.debug(rid + "matches: " + matches); + sendimage(rid, http_status, status, image); } else { - logging.log(uuid + " image not found, using default."); - handle_default(404, status, uuid); + logging.log(rid + "image not found, using default."); + handle_default(rid, 404, status, uuid); } }); } catch(e) { - logging.error(uuid + " error: " + e); - handle_default(500, status, uuid); + logging.error(rid + "error: " + e.stack); + handle_default(rid, 500, -1, uuid); } // default alex/steve images can be rendered, but // custom images will not be - function handle_default(http_status, img_status, uuid) { + function handle_default(rid, http_status, img_status, uuid) { if (def && def !== "steve" && def !== "alex") { - logging.log(uuid + " status: 301"); + logging.log(rid + "status: 301"); res.writeHead(301, { "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": human_status[img_status], + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Location": def }); @@ -105,26 +112,27 @@ 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(uuid + "error loading default render image: " + err); + logging.error(rid + "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) { + renders.draw_model(rid, buf, scale, helm, body, function(err, def_img) { if (err) { - logging.log(uuid + "error while rendering default image: " + err); + logging.log(rid + "error while rendering default image: " + err); } - sendimage(http_status, img_status, def_img, uuid); + sendimage(rid, http_status, img_status, def_img); }); }); } } - function sendimage(http_status, img_status, image, uuid) { - logging.log(uuid + " status: " + http_status); + function sendimage(rid, http_status, img_status, image) { + logging.log(rid + "status: " + http_status); res.writeHead(http_status, { "Content-Type": "image/png", "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": human_status[img_status], + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Etag": '"' + etag + '"' }); diff --git a/routes/skins.js b/routes/skins.js index 3abb2d4..8563d8e 100644 --- a/routes/skins.js +++ b/routes/skins.js @@ -10,6 +10,7 @@ module.exports = function(req, res) { var uuid = (req.url.path_list[2] || "").split(".")[0]; var def = req.url.query.default; var etag = null; + var rid = req.id; if (!helpers.uuid_valid(uuid)) { res.writeHead(422, { @@ -22,12 +23,12 @@ module.exports = function(req, res) { // strip dashes uuid = uuid.replace(/-/g, ""); + logging.log(rid + "uuid: " + uuid); try { - helpers.get_skin(uuid, function(err, hash, image) { - logging.log(uuid); + helpers.get_skin(rid, uuid, function(err, hash, image) { if (err) { - logging.error(uuid + " " + err); + logging.error(rid + err); } etag = hash && hash.substr(0, 32) || "none"; var matches = req.headers["if-none-match"] === '"' + etag + '"'; @@ -38,25 +39,26 @@ module.exports = function(req, res) { } else if (err) { http_status = 503; } - logging.debug(uuid + " etag: " + req.headers["if-none-match"]); - logging.debug(uuid + " matches: " + matches); - sendimage(http_status, image, uuid); + logging.debug(rid + "etag: " + req.headers["if-none-match"]); + logging.debug(rid + "matches: " + matches); + sendimage(rid, http_status, image); } else { - handle_default(404, uuid); + handle_default(rid, 404, uuid); } }); } catch(e) { - logging.error(uuid + " error: " + e); - handle_default(500, uuid); + logging.error(rid + "error: " + e.stack); + handle_default(rid, 500, uuid); } - function handle_default(http_status, uuid) { + function handle_default(rid, http_status, uuid) { if (def && def !== "steve" && def !== "alex") { - logging.log(uuid + " status: 301"); + logging.log(rid + "status: 301"); res.writeHead(301, { "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": "downloaded", + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Location": def }); @@ -65,19 +67,20 @@ module.exports = function(req, res) { def = def || skins.default_skin(uuid); lwip.open("public/images/" + def + "_skin.png", function(err, image) { image.toBuffer("png", function(err, buffer) { - sendimage(http_status, buffer, uuid); + sendimage(rid, http_status, buffer); }); }); } } - function sendimage(http_status, image, uuid) { - logging.log(uuid + " status: " + http_status); + function sendimage(rid, http_status, image) { + logging.log(rid + "status: " + http_status); res.writeHead(http_status, { "Content-Type": "image/png", "Cache-Control": "max-age=" + config.browser_cache_time + ", public", "Response-Time": new Date() - start, "X-Storage-Type": "downloaded", + "X-Request-ID": rid, "Access-Control-Allow-Origin": "*", "Etag": '"' + etag + '"' }); diff --git a/server.js b/server.js index a028896..f0b81f2 100644 --- a/server.js +++ b/server.js @@ -44,8 +44,11 @@ function requestHandler(req, res) { } request.url.path_list = path_list; + // generate 12 character random string + request.id = Math.random().toString(36).substring(2,14) + " "; + var local_path = request.url.path_list[1]; - logging.log(request.method + " " + request.url.href); + logging.log(request.id + request.method + " " + request.url.href); if (request.method === "GET" || request.method === "HEAD") { try { switch (local_path) { @@ -69,7 +72,7 @@ function requestHandler(req, res) { } } catch(e) { var error = JSON.stringify(req.headers) + "\n" + e.stack; - logging.error("Error: " + error); + logging.error(request.id + "Error: " + error); res.writeHead(500, { "Content-Type": "text/plain" }); diff --git a/test/test.js b/test/test.js index 7fba6b8..0f81b56 100644 --- a/test/test.js +++ b/test/test.js @@ -86,7 +86,7 @@ describe("Crafatar", function() { }); it("should not exist (uuid)", function(done) { var number = getRandomInt(0, 9).toString(); - networking.get_profile(Array(33).join(number), function(err, profile) { + networking.get_profile("testreq", Array(33).join(number), function(err, profile) { assert.strictEqual(profile, null); done(); }); @@ -106,7 +106,7 @@ describe("Crafatar", function() { var steven_uuid = "b8ffc3d37dbf48278f69475f6690aabd"; it("uuid's account should exist, but skin should not", function(done) { - networking.get_profile(alex_uuid, function(err, profile) { + networking.get_profile("testreq", alex_uuid, function(err, profile) { assert.notStrictEqual(profile, null); networking.get_uuid_url(profile, 1, function(url) { assert.strictEqual(url, null); @@ -127,7 +127,7 @@ describe("Crafatar", function() { it("should time out on uuid info download", function(done) { var original_timeout = config.http_timeout; config.http_timeout = 1; - networking.get_profile("069a79f444e94726a5befca90e38aaf5", function(err, profile) { + networking.get_profile("testreq", "069a79f444e94726a5befca90e38aaf5", function(err, profile) { assert.strictEqual(err.code, "ETIMEDOUT"); config.http_timeout = original_timeout; done(); @@ -161,7 +161,7 @@ describe("Crafatar", function() { }); it("should ignore file updates on invalid files", function(done) { assert.doesNotThrow(function() { - cache.update_timestamp("0123456789abcdef0123456789abcdef", "invalid-file.png"); + cache.update_timestamp("testreq", "0123456789abcdef0123456789abcdef", "invalid-file.png"); }); done(); }); @@ -176,13 +176,13 @@ describe("Crafatar", function() { // we have to make sure that we test both a 32x64 and 64x64 skin describe("Networking: Render", function() { it("should not fail (username, 32x64 skin)", function(done) { - helpers.get_render("md_5", 6, true, true, function(err, hash, img) { + helpers.get_render("testreq", "md_5", 6, true, true, function(err, hash, img) { assert.strictEqual(err, null); done(); }); }); it("should not fail (username, 64x64 skin)", function(done) { - helpers.get_render("Jake0oo0", 6, true, true, function(err, hash, img) { + helpers.get_render("testreq", "Jake0oo0", 6, true, true, function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -191,7 +191,7 @@ describe("Crafatar", function() { describe("Networking: Cape", function() { it("should not fail (guaranteed cape)", function(done) { - helpers.get_cape("Dinnerbone", function(err, hash, img) { + helpers.get_cape("testreq", "Dinnerbone", function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -200,13 +200,13 @@ describe("Crafatar", function() { before(function() { cache.get_redis().flushall(); }); - helpers.get_cape("Dinnerbone", function(err, hash, img) { + helpers.get_cape("testreq", "Dinnerbone", function(err, hash, img) { assert.strictEqual(err, null); done(); }); }); it("should not be found", function(done) { - helpers.get_cape("Jake0oo0", function(err, hash, img) { + helpers.get_cape("testreq", "Jake0oo0", function(err, hash, img) { assert.strictEqual(img, null); done(); }); @@ -215,7 +215,7 @@ describe("Crafatar", function() { describe("Networking: Skin", function() { it("should not fail", function(done) { - helpers.get_cape("Jake0oo0", function(err, hash, img) { + helpers.get_cape("testreq", "Jake0oo0", function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -224,7 +224,7 @@ describe("Crafatar", function() { before(function() { cache.get_redis().flushall(); }); - helpers.get_cape("Jake0oo0", function(err, hash, img) { + helpers.get_cape("testreq", "Jake0oo0", function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -245,13 +245,13 @@ describe("Crafatar", function() { }); it("should be downloaded", function(done) { - helpers.get_avatar(id, false, 160, function(err, status, image) { + helpers.get_avatar("testreq", id, false, 160, function(err, status, image) { assert.strictEqual(status, 2); done(); }); }); it("should be cached", function(done) { - helpers.get_avatar(id, false, 160, function(err, status, image) { + helpers.get_avatar("testreq", id, false, 160, function(err, status, image) { assert.strictEqual(status === 0 || status === 1, true); done(); }); @@ -262,7 +262,7 @@ describe("Crafatar", function() { it("should be checked", function(done) { var original_cache_time = config.local_cache_time; config.local_cache_time = 0; - helpers.get_avatar(id, false, 160, function(err, status, image) { + helpers.get_avatar("testreq", id, false, 160, function(err, status, image) { assert.strictEqual(status, 3); config.local_cache_time = original_cache_time; done(); @@ -273,7 +273,7 @@ describe("Crafatar", function() { describe("Networking: Skin", function() { it("should not fail (uuid)", function(done) { - helpers.get_skin(id, function(err, hash, img) { + helpers.get_skin("testreq", id, function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -282,13 +282,13 @@ describe("Crafatar", function() { describe("Networking: Render", function() { it("should not fail (full body)", function(done) { - helpers.get_render(id, 6, true, true, function(err, hash, img) { + helpers.get_render("testreq", id, 6, true, true, function(err, hash, img) { assert.strictEqual(err, null); done(); }); }); it("should not fail (only head)", function(done) { - helpers.get_render(id, 6, true, false, function(err, hash, img) { + helpers.get_render("testreq", id, 6, true, false, function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -297,7 +297,7 @@ describe("Crafatar", function() { describe("Networking: Cape", function() { it("should not fail (possible cape)", function(done) { - helpers.get_cape(id, function(err, hash, img) { + helpers.get_cape("testreq", id, function(err, hash, img) { assert.strictEqual(err, null); done(); }); @@ -312,14 +312,14 @@ describe("Crafatar", function() { if (id_type == "uuid") { it("uuid should be rate limited", function(done) { - networking.get_profile(id, function(err, profile) { + networking.get_profile("testreq", id, function(err, profile) { assert.strictEqual(profile.error, "TooManyRequestsException"); done(); }); }); } else { it("username should NOT be rate limited (username)", function(done) { - helpers.get_avatar(id, false, 160, function(err, status, image) { + helpers.get_avatar("testreq", id, false, 160, function(err, status, image) { assert.strictEqual(err, null); done(); });