join logs using `,` instead of `+ " " +`

bin/www.js

@@ -5,7 +5,7 @@ var cluster = require("cluster");
 
 if (cluster.isMaster) {
   var cores = config.clusters || require("os").cpus().length;
-  logging.log("Starting " + cores + " workers");
+  logging.log("Starting", cores + " workers");
   for (var i = 0; i < cores; i++) {
     cluster.fork();
   }

lib/cache.js

@@ -45,11 +45,11 @@ function update_file_date(rid, skin_hash) {
         var date = new Date();
         fs.utimes(path, date, date, function(err){
           if (err) {
-            logging.error(rid + "Error: " + err.stack);
+            logging.error(rid, "Error:", err.stack);
           }
         });
       } else {
-        logging.error(rid + "tried to update " + path + " date, but it does not exist");
+        logging.error(rid, "tried to update", path + " date, but it does not exist");
       }
     });
   }
@@ -97,7 +97,7 @@ exp.info = function(callback) {
 // these 60 seconds match the duration of Mojang's rate limit ban
 // callback: error
 exp.update_timestamp = function(rid, userId, hash, temp, callback) {
-  logging.log(rid + "cache: updating timestamp");
+  logging.log(rid, "cache: updating timestamp");
   sub = temp ? (config.local_cache_time - 60) : 0;
   var time = new Date().getTime() - sub;
   // store userId in lower case if not null
@@ -113,7 +113,7 @@ exp.update_timestamp = function(rid, userId, hash, temp, callback) {
 // this feature can be used to write both cape and skin at separate times
 // +callback+ contans error
 exp.save_hash = function(rid, userId, skin_hash, cape_hash, callback) {
-  logging.log(rid + "cache: saving skin:" + skin_hash + " cape:" + cape_hash);
+  logging.log(rid, "cache: saving skin:" + skin_hash + " cape:" + cape_hash);
   var time = new Date().getTime();
   // store shorter null byte instead of "null"
   skin_hash = (skin_hash === null ? "" : skin_hash);
@@ -137,7 +137,7 @@ exp.save_hash = function(rid, userId, skin_hash, cape_hash, callback) {
 
 // removes the hash for +userId+ from the cache
 exp.remove_hash = function(rid, userId) {
-  logging.log(rid + "cache: deleting hash");
+  logging.log(rid, "cache: deleting hash");
   redis.del(userId.toLowerCase(), "h", "t");
 };
 

lib/cleaner.js

@@ -18,7 +18,7 @@ function should_clean_redis(callback) {
         //logging.debug(info.toString());
         logging.debug("used mem:" + info.used_memory);
         var used = parseInt(info.used_memory) / 1024;
-        logging.log("RedisCleaner: " + used + "KB used");
+        logging.log("RedisCleaner:", used + "KB used");
         callback(err, used >= config.cleaning_redis_limit);
       } catch(e) {
         callback(e, false);
@@ -40,7 +40,7 @@ function should_clean_disk(callback) {
       callback(err, false);
     } else {
       var available = response[0].available;
-      logging.log("DiskCleaner: " + available + "KB available");
+      logging.log("DiskCleaner:", available + "KB available");
       callback(err, available < config.cleaning_disk_limit);
     }
   });

lib/helpers.js

@@ -28,12 +28,12 @@ function store_skin(rid, userId, profile, cache_details, callback) {
           callback(err, skin_hash);
         });
       } else {
-        logging.log(rid + "new skin hash: " + skin_hash);
+        logging.log(rid, "new skin hash:", skin_hash);
         var facepath = __dirname + "/../" + config.faces_dir + skin_hash + ".png";
         var helmpath = __dirname + "/../" + config.helms_dir + skin_hash + ".png";
         fs.exists(facepath, function(exists) {
           if (exists) {
-            logging.log(rid + "skin already exists, not downloading");
+            logging.log(rid, "skin already exists, not downloading");
             callback(null, skin_hash);
           } else {
             networking.get_from(rid, url, function(img, response, err1) {
@@ -42,13 +42,13 @@ function store_skin(rid, userId, profile, cache_details, callback) {
               } else {
                 skins.extract_face(img, facepath, function(err2) {
                   if (err2) {
-                    logging.error(rid + err2.stack);
+                    logging.error(rid, err2.stack);
                     callback(err2, null);
                   } else {
-                    logging.debug(rid + "face extracted");
+                    logging.debug(rid, "face extracted");
                     skins.extract_helm(rid, facepath, img, helmpath, function(err3) {
-                      logging.debug(rid + "helm extracted");
-                      logging.debug(rid + helmpath);
+                      logging.debug(rid, "helm extracted");
+                      logging.debug(rid, helmpath);
                       callback(err3, skin_hash);
                     });
                   }
@@ -77,20 +77,20 @@ function store_cape(rid, userId, profile, cache_details, callback) {
           callback(err, cape_hash);
         });
       } else {
-        logging.log(rid + "new cape hash: " + cape_hash);
+        logging.log(rid, "new cape hash:", cape_hash);
         var capepath = __dirname + "/../" + config.capes_dir + cape_hash + ".png";
         fs.exists(capepath, function(exists) {
           if (exists) {
-            logging.log(rid + "cape already exists, not downloading");
+            logging.log(rid, "cape already exists, not downloading");
             callback(null, cape_hash);
           } else {
             networking.get_from(rid, url, function(img, response, err) {
               if (err || !img) {
-                logging.error(rid + err.stack);
+                logging.error(rid, err.stack);
                 callback(err, null);
               } else {
                 skins.save_image(img, capepath, function(err) {
-                  logging.debug(rid + "cape saved");
+                  logging.debug(rid, "cape saved");
                   callback(err, cape_hash);
                 });
               }
@@ -116,7 +116,7 @@ function callback_for(userId, type, err, hash) {
       req_count++;
       if (req_count !== 1) {
         // otherwise this would show up on single/first requests, too
-        logging.debug(current.rid + "queued " + type + " request continued");
+        logging.debug(current.rid, "queued", type + " request continued");
       }
       currently_running.splice(i, 1); // remove from array
       current.callback(err, hash);
@@ -124,7 +124,7 @@ function callback_for(userId, type, err, hash) {
     }
   }
   if (req_count > 1) {
-    logging.debug(req_count + " simultaneous requests for " + userId);
+    logging.debug(req_count + " simultaneous requests for", userId);
   }
 }
 
@@ -194,7 +194,7 @@ function store_images(rid, userId, cache_details, type, callback) {
       }
     });
   } else {
-    logging.log(rid + "ID already being processed, adding to queue");
+    logging.log(rid, "ID already being processed, adding to queue");
     currently_running.push(new_hash);
   }
 }
@@ -223,14 +223,14 @@ exp.get_image_hash = function(rid, userId, type, callback) {
     } else {
       if (cache_details && cache_details[type] !== undefined && cache_details.time + config.local_cache_time * 1000 >= new Date().getTime()) {
         // use cached image
-        logging.log(rid + "userId cached & recently updated");
+        logging.log(rid, "userId cached & recently updated");
         callback(null, (cached_hash ? 1 : 0), cached_hash);
       } else {
         // download image
         if (cache_details) {
-          logging.log(rid + "userId cached, but too old");
+          logging.log(rid, "userId cached, but too old");
         } else {
-          logging.log(rid + "userId not cached");
+          logging.log(rid, "userId not cached");
         }
         store_images(rid, userId, cache_details, type, function(err, new_hash) {
           if (err) {
@@ -241,8 +241,8 @@ exp.get_image_hash = function(rid, userId, type, callback) {
             });
           } else {
             var status = cache_details && (cached_hash === new_hash) ? 3 : 2;
-            logging.debug(rid + "cached hash: " + (cache_details && cached_hash));
-            logging.log(rid + "new hash: " + new_hash);
+            logging.debug(rid, "cached hash:", (cache_details && cached_hash));
+            logging.log(rid, "new hash:", new_hash);
             callback(null, status, new_hash);
           }
         });
@@ -288,7 +288,7 @@ exp.get_skin = function(rid, userId, callback) {
     var skinpath = __dirname + "/../" + config.skins_dir + skin_hash + ".png";
     fs.exists(skinpath, function(exists) {
       if (exists) {
-        logging.log(rid + "skin already exists, not downloading");
+        logging.log(rid, "skin already exists, not downloading");
         skins.open_skin(rid, skinpath, function(err, img) {
           callback(err, skin_hash, img);
         });
@@ -337,7 +337,7 @@ exp.get_render = function(rid, userId, scale, helm, body, callback) {
           } else {
             fs.writeFile(renderpath, img, "binary", function(err) {
               if (err) {
-                logging.error(rid + err.stack);
+                logging.error(rid, err.stack);
               }
               callback(null, 2, skin_hash, img);
             });
@@ -359,7 +359,7 @@ exp.get_cape = function(rid, userId, callback) {
     var capepath = __dirname + "/../" + config.capes_dir + cape_hash + ".png";
     fs.exists(capepath, function(exists) {
       if (exists) {
-        logging.log(rid + "cape already exists, not downloading");
+        logging.log(rid, "cape already exists, not downloading");
         skins.open_skin(rid, capepath, function(err, img) {
           callback(err, cape_hash, img);
         });

lib/logging.js

@@ -21,7 +21,7 @@ function log(level, args, logger) {
   var clid = (cluster.worker && cluster.worker.id || "M");
   var lines = join_args(args).split("\n");
   for (var i = 0, l = lines.length; i < l; i++) {
-    logger(time + clid + " " + level + ": " + lines[i]);
+    logger(time + clid, level + ":", lines[i]);
   }
 }
 

lib/networking.js

@@ -62,7 +62,7 @@ exp.get_from_options = function(rid, url, options, callback) {
       logging.error(url, error);
     } else {
       var logfunc = code && code < 405 ? logging.log : logging.warn;
-      logfunc(rid + url + " " + code + " " + http_code[code]);
+      logfunc(rid, url, code, http_code[code]);
     }
 
     // 200 or 301 depending on content type
@@ -79,8 +79,8 @@ exp.get_from_options = function(rid, url, options, callback) {
       // cause error so the image will not be cached
       callback(body || null, response, (error || "TooManyRequests"));
     } else {
-      logging.error(rid + " Unknown reply:");
-      logging.error(rid + JSON.stringify(response));
+      logging.error(rid, " Unknown reply:");
+      logging.error(rid, JSON.stringify(response));
       callback(body || null, response, error);
     }
   });
@@ -169,12 +169,12 @@ exp.save_texture = function(rid, tex_hash, outpath, callback) {
     var textureurl = textures_url + tex_hash;
     exp.get_from(rid, textureurl, function(img, response, err) {
       if (err) {
-        logging.error(rid + "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.error(rid + "error: " + err.stack);
+            logging.error(rid, "error:", err.stack);
           }
           callback(err, response, img);
         });

lib/renders.js

@@ -43,7 +43,7 @@ exp.draw_head = function(skin_canvas, model_ctx, scale) {
 // parts are labeled as if drawn from the skin's POV
 exp.draw_body = function(rid, skin_canvas, model_ctx, scale) {
   if (skin_canvas.height === 32 * scale) {
-    logging.debug(rid + "uses old skin format");
+    logging.debug(rid, "uses old skin format");
     //Left Leg
     //Left Leg - Front
     model_ctx.setTransform(1,-0.5,0,1.2,0,0);
@@ -84,7 +84,7 @@ exp.draw_body = function(rid, 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.debug(rid + "uses new skin format");
+    logging.debug(rid, "uses new skin format");
     //Left Leg
     //Left Leg - Front
     model_ctx.setTransform(1,-0.5,0,1.2,0,0);
@@ -133,7 +133,7 @@ exp.draw_model = function(rid, img, scale, helm, body, callback) {
   var image = new Image();
 
   image.onerror = function(err) {
-    logging.error(rid + "render error: " + err.stack);
+    logging.error(rid, "render error:", err.stack);
     callback(err, null);
   };
 
@@ -159,7 +159,7 @@ exp.draw_model = function(rid, img, scale, helm, body, callback) {
 
     model_canvas.toBuffer(function(err, buf){
       if (err) {
-        logging.error(rid + "error creating buffer: " + err);
+        logging.error(rid, "error creating buffer:", err);
       }
       callback(err, buf);
     });
@@ -173,7 +173,7 @@ exp.draw_model = function(rid, img, scale, helm, body, callback) {
 exp.open_render = function(rid, renderpath, callback) {
   fs.readFile(renderpath, function (err, buf) {
     if (err) {
-      logging.error(rid + "error while opening skin file: " + err);
+      logging.error(rid, "error while opening skin file:", err);
     }
     callback(err, buf);
   });

lib/skins.js

@@ -53,7 +53,7 @@ exp.extract_helm = function(rid, facefile, buffer, outname, callback) {
                           callback(err);
                         });
                       } else {
-                        logging.log(rid + "helm img == face img, not storing!");
+                        logging.log(rid, "helm img == face img, not storing!");
                         callback(null);
                       }
                     });
@@ -109,7 +109,7 @@ exp.default_skin = function(uuid) {
 exp.open_skin = function(rid, skinpath, callback) {
   fs.readFile(skinpath, function(err, buf) {
     if (err) {
-      logging.error(rid + "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

@@ -43,14 +43,14 @@ module.exports = function(req, res) {
 
   // strip dashes
   userId = userId.replace(/-/g, "");
-  logging.log(rid + "userid: " + userId);
+  logging.log(rid, "userid:", userId);
 
 
   try {
     helpers.get_avatar(rid, userId, helm, size, function(err, status, image, hash) {
-      logging.log(rid + "storage type: " + human_status[status]);
+      logging.log(rid, "storage type:", human_status[status]);
       if (err) {
-        logging.error(rid + err);
+        logging.error(rid, err);
         if (err.code === "ENOENT") {
           // no such file
           cache.remove_hash(rid, userId);
@@ -65,21 +65,21 @@ module.exports = function(req, res) {
         } else if (err) {
           http_status = 503;
         }
-        logging.debug(rid + "etag: " + req.headers["if-none-match"]);
-        logging.debug(rid + "matches: " + matches);
+        logging.debug(rid, "etag:", req.headers["if-none-match"]);
+        logging.debug(rid, "matches:", matches);
         sendimage(rid, http_status, status, image);
       } else {
         handle_default(rid, 404, status, userId);
       }
     });
   } catch(e) {
-    logging.error(rid + "error: " + e.stack);
+    logging.error(rid, "error:", e.stack);
     handle_default(rid, 500, -1, userId);
   }
 
   function handle_default(rid, http_status, img_status, userId) {
     if (def && def !== "steve" && def !== "alex") {
-      logging.log(rid + "status: 301");
+      logging.log(rid, "status: 301");
       res.writeHead(301, {
         "Cache-Control": "max-age=" + config.browser_cache_time + ", public",
         "Response-Time": new Date() - start,
@@ -98,7 +98,7 @@ module.exports = function(req, res) {
   }
 
   function sendimage(rid, http_status, img_status, image) {
-    logging.log(rid + "status: " + http_status);
+    logging.log(rid, "status:", http_status);
     res.writeHead(http_status, {
       "Content-Type": "image/png",
       "Cache-Control": "max-age=" + config.browser_cache_time + ", public",

routes/capes.js

@@ -29,13 +29,13 @@ module.exports = function(req, res) {
 
   // strip dashes
   userId = userId.replace(/-/g, "");
-  logging.log(rid + "userid: " + userId);
+  logging.log(rid, "userid:", userId);
 
   try {
     helpers.get_cape(rid, userId, function(err, status, image, hash) {
-      logging.log(rid + "storage type: " + human_status[status]);
+      logging.log(rid, "storage type:", human_status[status]);
       if (err) {
-        logging.error(rid + err);
+        logging.error(rid, err);
         if (err.code === "ENOENT") {
           // no such file
           cache.remove_hash(rid, userId);
@@ -50,9 +50,9 @@ module.exports = function(req, res) {
         } else if (err) {
           http_status = 503;
         }
-        logging.debug(rid + "etag: " + req.headers["if-none-match"]);
-        logging.debug(rid + "matches: " + matches);
-        logging.log(rid + "status: " + http_status);
+        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, {
@@ -63,7 +63,7 @@ module.exports = function(req, res) {
       }
     });
   } catch(e) {
-    logging.error(rid + "error:" + e.stack);
+    logging.error(rid, "error:" + e.stack);
     res.writeHead(500, {
       "Content-Type": "text/plain",
       "Response-Time": new Date() - start

routes/renders.js

@@ -59,13 +59,13 @@ module.exports = function(req, res) {
 
   // strip dashes
   userId = userId.replace(/-/g, "");
-  logging.log(rid + "userId: " + userId);
+  logging.log(rid, "userId:", userId);
 
   try {
     helpers.get_render(rid, userId, scale, helm, body, function(err, status, hash, image) {
-      logging.log(rid + "storage type: " + human_status[status]);
+      logging.log(rid, "storage type:", human_status[status]);
       if (err) {
-        logging.error(rid + err);
+        logging.error(rid, err);
         if (err.code === "ENOENT") {
           // no such file
           cache.remove_hash(rid, userId);
@@ -80,16 +80,16 @@ module.exports = function(req, res) {
         } else if (err) {
           http_status = 503;
         }
-        logging.debug(rid + "etag: " + req.headers["if-none-match"]);
-        logging.debug(rid + "matches: " + matches);
+        logging.debug(rid, "etag:", req.headers["if-none-match"]);
+        logging.debug(rid, "matches:", matches);
         sendimage(rid, http_status, status, image);
       } else {
-        logging.log(rid + "image not found, using default.");
+        logging.log(rid, "image not found, using default.");
         handle_default(rid, 404, status, userId);
       }
     });
   } catch(e) {
-    logging.error(rid + "error: " + e.stack);
+    logging.error(rid, "error:", e.stack);
     handle_default(rid, 500, -1, userId);
   }
 
@@ -98,7 +98,7 @@ module.exports = function(req, res) {
   // custom images will not be
   function handle_default(rid, http_status, img_status, userId) {
     if (def && def !== "steve" && def !== "alex") {
-      logging.log(rid + "status: 301");
+      logging.log(rid, "status: 301");
       res.writeHead(301, {
         "Cache-Control": "max-age=" + config.browser_cache_time + ", public",
         "Response-Time": new Date() - start,
@@ -113,12 +113,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(rid + "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(rid, buf, scale, helm, body, function(err, def_img) {
           if (err) {
-            logging.error(rid + "error while rendering default image: " + err);
+            logging.error(rid, "error while rendering default image:", err);
           }
           sendimage(rid, http_status, img_status, def_img);
         });
@@ -127,7 +127,7 @@ module.exports = function(req, res) {
   }
 
   function sendimage(rid, http_status, img_status, image) {
-    logging.log(rid + "status: " + http_status);
+    logging.log(rid, "status:", http_status);
     res.writeHead(http_status, {
       "Content-Type": "image/png",
       "Cache-Control": "max-age=" + config.browser_cache_time + ", public",

routes/skins.js

@@ -23,12 +23,12 @@ module.exports = function(req, res) {
 
   // strip dashes
   userId = userId.replace(/-/g, "");
-  logging.log(rid + "userid: " + userId);
+  logging.log(rid, "userid:", userId);
 
   try {
     helpers.get_skin(rid, userId, function(err, hash, image) {
       if (err) {
-        logging.error(rid + err);
+        logging.error(rid, err);
       }
       etag = hash && hash.substr(0, 32) || "none";
       var matches = req.headers["if-none-match"] === '"' + etag + '"';
@@ -39,21 +39,21 @@ module.exports = function(req, res) {
         } else if (err) {
           http_status = 503;
         }
-        logging.debug(rid + "etag: " + req.headers["if-none-match"]);
-        logging.debug(rid + "matches: " + matches);
+        logging.debug(rid, "etag:", req.headers["if-none-match"]);
+        logging.debug(rid, "matches:", matches);
         sendimage(rid, http_status, image);
       } else {
         handle_default(rid, 404, userId);
       }
     });
   } catch(e) {
-    logging.error(rid + "error: " + e.stack);
+    logging.error(rid, "error:", e.stack);
     handle_default(rid, 500, userId);
   }
 
   function handle_default(rid, http_status, userId) {
     if (def && def !== "steve" && def !== "alex") {
-      logging.log(rid + "status: 301");
+      logging.log(rid, "status: 301");
       res.writeHead(301, {
         "Cache-Control": "max-age=" + config.browser_cache_time + ", public",
         "Response-Time": new Date() - start,
@@ -74,7 +74,7 @@ module.exports = function(req, res) {
   }
 
   function sendimage(rid, http_status, image) {
-    logging.log(rid + "status: " + http_status);
+    logging.log(rid, "status:", http_status);
     res.writeHead(http_status, {
       "Content-Type": "image/png",
       "Cache-Control": "max-age=" + config.browser_cache_time + ", public",

server.js

@@ -45,10 +45,10 @@ function requestHandler(req, res) {
   request.url.path_list = path_list;
 
   // generate 12 character random string
-  request.id = Math.random().toString(36).substring(2,14) + " ";
+  request.id = Math.random().toString(36).substring(2,14);
 
   var local_path = request.url.path_list[1];
-  logging.log(request.id + 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) {
@@ -72,7 +72,7 @@ function requestHandler(req, res) {
       }
     } catch(e) {
       var error = JSON.stringify(req.headers) + "\n" + e.stack;
-      logging.error(request.id + "Error: " + error);
+      logging.error(request.id + "Error:", error);
       res.writeHead(500, {
         "Content-Type": "text/plain"
       });