prepend uuid to all logs

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

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

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

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

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

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

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

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

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