prepend request IDs instead of UUIDs, fixes #77

also cleaned up a few other things I noticed when looking over the files

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");
 };
 

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 {

modules/networking.js

@@ -21,7 +21,7 @@ function extract_url(profile, property) {
     });
   }
   return url;
-};
+}
 
 // exracts the skin url of a +profile+ object
 // returns null when no url found (user has no skin)
@@ -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;

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);
   });

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);

routes/avatars.js

@@ -21,6 +21,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) {
@@ -43,14 +44,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";
@@ -62,25 +65,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
       });
@@ -88,18 +92,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 + '"'
     });

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 + '"'
     });

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 + '"'
     });

routes/skins.js

@@ -11,6 +11,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, {
@@ -23,12 +24,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 + '"';
@@ -39,25 +40,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
       });
@@ -66,19 +68,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 + '"'
     });

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"
       });

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();
             });