Tim Mattison

Hardcore tech

Hacking Together a Super Simple Webserver With Netcat on a Raspberry Pi

| Comments

A few months ago I wanted to get some data out of WeatherGoose II Climate Monitor so I could convert it into JSON and consume it in another application. I hacked something together and converted their format to JSON in a few hours as a proof-of-concept and the code sat for a few months.

A co-worker recently asked me if they could hook up to my script with a browser to try to do some visualization. I didn’t want to install Apache or nginx as a front end and I didn’t want to modify the script to run its own webserver so I came up with a one-liner that uses netcat to get the output of my script into their browser.

But wait! netcat has an option for this. However, on the Raspberry Pi it is not available and I didn’t want to start downloading new versions.

Here it is:

1
SCRIPT="./weathergoose.py 192.168.1.99" && PORT="8080" && while true; do $SCRIPT | nc -l -p $PORT; done

You’ll need to set SCRIPT to the script you want to run (including any parameters it needs) and PORT to the port you want to listen on.

Be careful! This is not a real webserver. This just spits your scripts output back to the browser. Anything the browser sends to the script is ignored.

Also, the script runs first and pipes its output to netcat. This happens before netcat accepts a connection and can cause some confusion. Here’s a concrete example.

Assume I wrote a script that just returns the time. If I use the above snippet and start it at 5:00 PM but I hit it with my web browser at 5:15 PM the time that I get back will be 5:00 PM. The next time I hit it it will be 5:15 PM. The easiest way to think about it is that you get the data from when the script started or at the time of the previous request, whichever is later.

I hope to come up with a fix for this issue but I haven’t had the time yet. Do you have a fix? Does this work for you? Post in the comments below.

Rid Yourself of Smart Quotes, Smart Dashes, and Automatic Spelling Correction on Mac OS

| Comments

Have you ever pasted working a bash script or piece of code into a text editor and had it fail to work when you copied it back out later? You’ve probably fallen victim to smart quotes, smart dashes, or automatic spelling correction.

For example, during development I write scripts in Evernote and two very common things happen:

  • aws is persistently and annoyingly replaced by the word “was”
  • Commands that include double or single quotes have those quotes replaced with scripting hostile quotes that shells don’t understand

In Mac OS we can fix this in a few steps:

  1. Open System Preferences and click on Keyboard Keyboard
  2. Click “Text” Keyboard
  3. Uncheck “Use smart quotes and dashes” Keyboard
  4. Uncheck “Correct spelling automatically” Keyboard

You’re done! Now your settings should look like this and these “smart” features will never bother you again:

Keyboard

Using SSH Agent to Simplify Connecting to EC2

| Comments

TL;DR – Jump to the bottom and look for the eval $(ssh-agent) snippet!

Once you start using EC2 you’ll probably need to do a lot of things that involve SSH. A common frustration is having to specify your identity file when connecting to your EC2 instance. Instead of doing this:

1
ssh ubuntu@my-ec2-instance

You end up doing this:

1
ssh -i ~/.ssh/identity-file.pem ubuntu@my-ec2-instance

This gets even more complex when tools based on SSH are brought into the mix. Some of these tools don’t have a mechanism to even specify the identity file. If they do sometimes it makes the command-line really ugly and it almost always makes the script custom to a specific user. For example:

1
rsync -avz -e "ssh -p1234  -i /home/username/.ssh/identity-file.pem" ...

Is only going to work for the user username.

How do we make this a lot easier? It turns out there is a very simple way to make all of that pain go away. Whether you use rsync, unison, mosh, scp, or any of a number of other tools that make use of SSH under the hood there is a standard mechanism for SSH to manage your identity. That mechanism is called ssh-agent.

If I try to rsync directly to my EC2 instance I get this:

1
2
3
4
$ rsync -avzP ubuntu@my-ec2-instance:file-on-ec2.txt local-file.txt
Permission denied (publickey).
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: unexplained error (code 255) at io.c(226) [Receiver=3.1.1]

Instead what I want to do is start the ssh-agent, tell it about my identity file, and have the agent worry about providing my identity file when necessary. To do that I do this:

1
eval $(ssh-agent) && ssh-add ~/.ssh/identity-file.pem

Once you do that SSH will use that identity file to connect to EC2 automatically. You just need to run that in each shell you are using to connect to EC2 and you are set.

Do you have more than one identity file? You can keep running ssh-add with additional identity files and it will manage them all.

Do you want to be really lazy and load all of your identities at once? Try this:

1
eval $(ssh-agent) && ssh-add ~/.ssh/*.pem

Enjoy!

NOTE: Your pem files need to have the permission set to 400 so they can only be read by your user and not written to. Otherwise ssh-agent and ssh may refuse to use them.

Full Example Code Showing How to Use Guice and Jetty

| Comments

Today I spent a significant amount of time wrestling Jetty and Guice in order to get a very simple configuration up and running. Many articles I found on this topic are incomplete or out of date so here is a start to finish example of how to get Guice and Jetty working together without any web.xml.

Step 1 – Create a module that describes your servlet configuration. Assume we have three servlets. One is called FooServlet and is served on the “/foo” path. One is called BarServlet and is served on the “/bar” path. One is called IndexServlet and is served for all other paths.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
import com.google.inject.servlet.ServletModule;

public class ApplicationServletModule extends ServletModule {
    @Override
    protected void configureServlets() {
        bind(FooServlet.class);
        bind(BarServlet.class);
        bind(IndexServlet.class);

        serve("/foo").with(FooServlet.class);
        serve("/bar").with(BarServlet.class);
        serve("/*").with(IndexServlet.class);
    }
}

Step 2 – Create a module that contains your Guice bindings. We’ll assume you have something called NonServletImplementation you want bound to NonServletInterface that you’ll need to have injected into your servlets.

1
2
3
4
5
6
7
import com.google.inject.AbstractModule;

public class NonServletModule extends AbstractModule {
    protected void configure() {
        bind(NonServletInterface.class).to(NonServletImplementation.class);
    }
}

Step 3 – Instantiate your injector with all of your modules in the code where you want to create the server. If you have other modules you want to include you should include those as well.

1
2
3
NonServletModule nonServletModule = new NonServletModule();
ApplicationServletModule applicationServletModule = new ApplicationServletModule();
Injector injector = Guice.createInjector(nonServletModule, applicationServletModule);

Step 4 – Instantiate the server. You do not need to pass it the injector explicitly. Guice will handle that for you but you MUST instantiate the injector before this code runs.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
int port = 8080;
Server server = new Server(port);

ServletContextHandler servletContextHandler = new ServletContextHandler(server, "/", ServletContextHandler.SESSIONS);
servletContextHandler.addFilter(GuiceFilter.class, "/*", EnumSet.allOf(DispatcherType.class));

// You MUST add DefaultServlet or your server will always return 404s
servletContextHandler.addServlet(DefaultServlet.class, "/");

// Start the server
server.start();

// Wait until the server exits
server.join();

Step 5 – Make sure your servlets are setup to use Guice and use the @Singleton annotation. Only the FooServlet skeleton is shown here but you should create the BarServlet and the IndexServlet as well.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
import javax.inject.Inject;
import javax.inject.Singleton;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;

/**
 * Created by timmattison on 8/4/14.
 */
@Singleton
public class FooServlet extends HttpServlet {
    private final NonServletInterface nonServletInterface;

    @Inject
    public DescribeServlet(NonServletInterface nonServletInterface) {
        this.nonServletInterface = nonServletInterface;
    }

    protected void doPost(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
        // Do whatever you need to do with POSTs
        ...
    }

    protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
        // Do whatever you need to do with GETs
        ...
    }
}

If all goes well then everything will be wired up with Guice and your Jetty server is ready to rock. It turns out to be a lot simpler than working with the web.xml in my opinion since everything is mapped out explicitly in one place.

Using Amazon STS Credentials Inside of a Properties File

| Comments

Amazon provides several credentials providers in their Java API that let you use IAM user credentials various ways. The credentials can come from IMDS, environment variables, or a properties file, just to name a few.

If you’re developing and debugging and you need to use STS credentials your options are a bit more limited. To help deal with this I came up with a few bits of code that, for me at least, make it significantly easier.

First, there’s an awscredentials.properties file format you need to follow that looks like this:

1
2
3
aws.accessKeyId=XXXXXXXXXXXXXXXXXXX
aws.secretAccessKey=YYYYYYYYYYYYYYYYYYY
aws.sessionToken=ZZZZZZZZZZZZZZZZZZZ

Replace the X, Y, and Z strings with your credentials and put them in your resources directory where the classloader can find them. DO NOT COMMIT THEM TO SOURCE CONTROL!

Next, there’s a method that loads these credentials into the system properties:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
private static final String AWSCREDENTIALS_PROPERTIES = "awscredentials.properties";

void loadAwsCredentialsProperties() throws IOException {
  InputStream inputStream = this.getClass().getClassLoader().getResourceAsStream(AWSCREDENTIALS_PROPERTIES);
  
  // Was there a properties file?
  if (inputStream == null) {
      // No, just return
      return;
  }
  
  Properties properties = new Properties(System.getProperties());
  properties.load(inputStream);
  
  // set the system properties
  System.setProperties(properties);
}

Finally, there’s the credentials provider:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
import com.amazonaws.AmazonClientException;
import com.amazonaws.auth.AWSCredentials;
import com.amazonaws.auth.AWSCredentialsProvider;
import com.amazonaws.auth.BasicSessionCredentials;
import com.amazonaws.services.securitytoken.model.Credentials;
import com.amazonaws.util.StringUtils;

/**
 * Created by timmattison on 9/2/14.
 */
public class SystemPropertiesStsCredentialsProvider implements AWSCredentialsProvider {
    private static final String ACCESS_KEY_ID_SYSTEM_PROPERTY = "aws.accessKeyId";
    private static final String SECRET_ACCESS_KEY_SYSTEM_PROPERTY = "aws.secretAccessKey";
    private static final String SESSION_TOKEN_SYSTEM_PROPERTY = "aws.sessionToken";

    public AWSCredentials getCredentials() {
        // Get the access key ID
        String accessKeyId = StringUtils.trim(System.getProperty(ACCESS_KEY_ID_SYSTEM_PROPERTY));

        // Get the secret access key
        String secretAccessKey = StringUtils.trim(System.getProperty(SECRET_ACCESS_KEY_SYSTEM_PROPERTY));

        // Get the session token
        String sessionToken = StringUtils.trim(System.getProperty(SESSION_TOKEN_SYSTEM_PROPERTY));

        // Are we missing any of the necessary values?
        if (StringUtils.isNullOrEmpty(accessKeyId)
                || StringUtils.isNullOrEmpty(secretAccessKey)
                || StringUtils.isNullOrEmpty(sessionToken)) {
            // Yes, throw an exception like the Amazon code does
            throw new AmazonClientException(
                    "Unable to load AWS credentials from Java system "
                            + "properties (" + ACCESS_KEY_ID_SYSTEM_PROPERTY + ", "
                            + SECRET_ACCESS_KEY_SYSTEM_PROPERTY + ", and "
                            + SESSION_TOKEN_SYSTEM_PROPERTY + ")");
        }

        // Create the credentials
        Credentials sessionCredentials = new Credentials();
        sessionCredentials.setAccessKeyId(accessKeyId);
        sessionCredentials.setSecretAccessKey(secretAccessKey);
        sessionCredentials.setSessionToken(sessionToken);

        // Convert them to basic session credentials
        BasicSessionCredentials basicSessionCredentials = new BasicSessionCredentials(
                sessionCredentials.getAccessKeyId(),
                sessionCredentials.getSecretAccessKey(),
                sessionCredentials.getSessionToken());

        return basicSessionCredentials;
    }

    @Override
    public void refresh() {
        // Do nothing
    }
}

This should make things quite a bit easier if you don’t have access to a real IAM user and must use STS for your application.

Simple Snippets for Using AWS Credentials While Debugging

| Comments

While debugging and developing using the AWS SDK you’ll find that sometimes you just need to use real credentials on a box that lives outside of EC2. You should always be using Instance Metadata for your credentials inside of EC2 though. Never use this pattern inside EC2!

Also, make sure you never commit your credentials. That can be an expensive mistake when they show up on Github and people snag them to use them for Bitcoin mining.

NOTE: These snippets include @Inject and @Assisted annotations used by Guice. If you’re not using Guice remove those and the related imports.

Anyway, if you want to use static IAM user credentials you can use a credentials provider like this:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
import com.amazonaws.auth.AWSCredentials;
import com.amazonaws.auth.AWSCredentialsProvider;
import com.google.inject.Inject;
import com.google.inject.assistedinject.Assisted;

/**
 * Created by timmattison on 9/2/14.
 */
public class TempNonStsCredentialsProvider implements AWSCredentialsProvider {
    private final String awsAccessKeyId;
    private final String awsSecretKey;

    @Inject
    public TempNonStsCredentialsProvider(@Assisted("awsAccessKeyId") String awsAccessKeyId,
                                         @Assisted("awsSecretKey") String awsSecretKey) {
        this.awsAccessKeyId = awsAccessKeyId;
        this.awsSecretKey = awsSecretKey;
    }

    @Override
    public AWSCredentials getCredentials() {
        return new AWSCredentials() {
            @Override
            public String getAWSAccessKeyId() {
                return awsAccessKeyId;
            }

            @Override
            public String getAWSSecretKey() {
                return awsSecretKey;
            }
        };
    }

    @Override
    public void refresh() {
        // Do nothing
    }
}

Pass in your credentials and you’re good to go. If you’re using STS it requires a little bit more work. Use this instead:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
import com.amazonaws.auth.AWSCredentials;
import com.amazonaws.auth.AWSCredentialsProvider;
import com.amazonaws.auth.BasicSessionCredentials;
import com.amazonaws.services.securitytoken.model.Credentials;
import com.google.inject.assistedinject.Assisted;

import javax.inject.Inject;

/**
 * Created by timmattison on 9/2/14.
 */
public class TempStsCredentialsProvider implements AWSCredentialsProvider {
    private final String awsAccessKeyId;
    private final String awsSecretAccessKey;
    private final String awsSessionToken;

    @Inject
    public TempStsCredentialsProvider(@Assisted("awsAccessKeyId") String awsAccessKeyId,
                                      @Assisted("awsSecretAccessKey") String awsSecretAccessKey,
                                      @Assisted("awsSessionToken") String awsSessionToken) {
        this.awsAccessKeyId = awsAccessKeyId;
        this.awsSecretAccessKey = awsSecretAccessKey;
        this.awsSessionToken = awsSessionToken;
    }

    @Override
    public AWSCredentials getCredentials() {
        Credentials sessionCredentials = new Credentials();
        sessionCredentials.setAccessKeyId(awsAccessKeyId);
        sessionCredentials.setSecretAccessKey(awsSecretAccessKey);
        sessionCredentials.setSessionToken(awsSessionToken);

        BasicSessionCredentials basicSessionCredentials = new BasicSessionCredentials(
                sessionCredentials.getAccessKeyId(),
                sessionCredentials.getSecretAccessKey(),
                sessionCredentials.getSessionToken());

        return basicSessionCredentials;
    }

    @Override
    public void refresh() {
      // Do nothing
    }
}

Now you just need to pass in the extra session token parameter and then you can use this to provide credentials to your AWS calls.

Checking PostgreSQL to See if an Index Already Exists

| Comments

In my last post I showed you a simple way to check to see if a constraint already existed in PostgreSQL. Now I want to show you how to do the same thing for an index.

Here’s the code but keep in mind that it makes the assumption that everything is in the public schema.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
CREATE OR REPLACE FUNCTION create_index_if_not_exists (t_name text, i_name text, index_sql text) RETURNS void AS $$
DECLARE
  full_index_name varchar;
  schema_name varchar;
BEGIN

full_index_name = t_name || '_' || i_name;
schema_name = 'public';

IF NOT EXISTS (
    SELECT 1
    FROM   pg_class c
    JOIN   pg_namespace n ON n.oid = c.relnamespace
    WHERE  c.relname = full_index_name
    AND    n.nspname = schema_name
    ) THEN

    execute 'CREATE INDEX ' || full_index_name || ' ON ' || schema_name || '.' || t_name || ' ' || index_sql;
END IF;
END
$$
LANGUAGE plpgsql VOLATILE;

You can now use the function like this:

1
SELECT create_index_if_not_exists('table', 'index_name', '(column)');

No duplicated data, no exceptions. Enjoy!

Checking PostgreSQL to See if a Constraint Already Exists

| Comments

Checking to see if a constraint already exists should be easy. H2 and many other database have syntax for it.

For some reason PostgreSQL, my favorite database, doesn’t have this. I looked around and found a decent solution on Stack Overflow that I can add to my default template but something about it bothered me.

I didn’t like the fact that the code asked for the table name and constraint name but then didn’t use it in the SQL statement. Leaving it like this means that someone could write this (note that foo becomes foo2 and bar becomes bar2 in the first two parameters):

1
2
3
4
5
6
7
8
9
SELECT create_constraint_if_not_exists(
        'foo',
        'bar',
        'ALTER TABLE foo ADD CONSTRAINT bar CHECK (foobies < 100);');

SELECT create_constraint_if_not_exists(
        'foo2',
        'bar2',
        'ALTER TABLE foo ADD CONSTRAINT bar CHECK (foobies < 100);');

And they would get an exception rather than having the constraint creation be skipped which could break a lot of things that expect this function to be safe.

They also could do this (note that foo becomes foo2 and bar becomes bar2 in the constraint SQL):

1
2
3
4
5
6
7
8
9
SELECT create_constraint_if_not_exists(
        'foo',
        'bar',
        'ALTER TABLE foo ADD CONSTRAINT bar CHECK (foobies < 100);');

SELECT create_constraint_if_not_exists(
        'foo',
        'bar',
        'ALTER TABLE foo2 ADD CONSTRAINT bar2 CHECK (foobies < 100);');

This could be even worse because a constraint wouldn’t be created.

My solution was to modify this script slightly:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
CREATE OR REPLACE FUNCTION create_constraint_if_not_exists (t_name text, c_name text, constraint_sql text)
  RETURNS void
AS
$BODY$
  begin
    -- Look for our constraint
    if not exists (select constraint_name
                   from information_schema.constraint_column_usage
                   where table_name = t_name  and constraint_name = c_name) then
        execute 'ALTER TABLE ' || t_name || ' ADD CONSTRAINT ' || c_name || ' ' || constraint_sql;
    end if;
end;
$BODY$
LANGUAGE plpgsql VOLATILE;

Now you call it like this:

1
SELECT create_constraint_if_not_exists('foo', 'bar', 'CHECK (foobies < 100);');

And it will check the constraint properly by name. This doesn’t stop you from creating multiple constraints with the same criteria and different names though. That’s something you’ll need to check for manually (for now).

Deal With os_linux_zero.cpp Related JVM Crashes Without Using the Oracle JVM

| Comments

While running some relatively simple Java code on my Raspberry Pi I kept running into complete JVM crashes. These weren’t simple application crashes that I can quickly debug. It really was the JVM that my code was running on that was crashing.

The error message I received was similar to this:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (os_linux_zero.cpp:285), pid=10344, tid=3061261424
#  fatal error: caught unhandled signal 11
#
# JRE version: OpenJDK Runtime Environment (7.0_65-b32) (build 1.7.0_65-b32)
# Java VM: OpenJDK Zero VM (24.65-b04 mixed mode linux-arm )
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /home/pi/hs_err_pid10344.log
#
# If you would like to submit a bug report, please include
# instructions on how to reproduce the bug and visit:
#   http://icedtea.classpath.org/bugzilla
#
Aborted

I dug and dug and dug and couldn’t figure out what was going on. The most common fix that I saw was to switch to the Oracle JVM. For this project I didn’t want to do that so I scoured the net and came up with the following two options.

For reference, my original command line was very simple. It was just java -jar test.jar.

NOTE: There may be performance issues with both of these options. I have not profiled them to see the difference. Then again, having your JVM crash can arguably be the lowest performance option possible.

Option 1: Add the -XX:+PrintCommandLineFlags option to your command line. This changed my command line to java -XX:+PrintCommandLineFlags -jar test.jar. Immediately the problem went away.

Option 2: Add the -jamvm option to your command line. This changed my command line to java -jamvm -jar test.jar. Again, immediately the problem went away

What is really happening behind the scenes? That gets complex quickly and I still don’t know the full answer. It turns out that this is a known but ignored bug in OpenJDK’s Zero VM. When you run java -version you can see if you’re running Zero VM or not like this:

1
2
3
4
pi@raspberrypi ~ $ java -version
java version "1.7.0_65"
OpenJDK Runtime Environment (IcedTea 2.5.1) (7u65-2.5.1-2~deb7u1+rpi1)
OpenJDK Zero VM (build 24.65-b04, mixed mode)

I don’t know why option 1 works. My guess is that that option disables some kind of optimization. Looking at what I think is the corresponding code in Hotspot on line 283 I can see that pthread_attr_getstack is used. The pthread_attr_getstack documentation says that it can only fail with EINVAL for one reason. It must be that addr “does not refer to an initialized thread attribute object”. I don’t have any clue how to fix this though.

Option 2 works because it switches over to JamVM. You can check your JamVM version like this:

1
2
3
4
pi@raspberrypi ~ $ java -jamvm -version
java version "1.7.0_65"
OpenJDK Runtime Environment (IcedTea 2.5.1) (7u65-2.5.1-2~deb7u1+rpi1)
JamVM (build 1.6.0-devel, inline-threaded interpreter with stack-caching)

So, if you’re in a similar bind and don’t want to install and switch to Oracle’s JVM give these options a try. Post your results in the comments below.

Making Javascript Logging a Little Less Expensive

| Comments

Disclaimer: I am not a Javascript expert. I don’t even play one on TV.

Everybody knows that logging isn’t free, don’t they? Well I don’t think that they do and for a lot of beginner to intermediate level developers I can’t really fault them for it. While you’re debugging it appears that log messages show up instantly so it is easy to forget that there is in fact a cost associated with producing them.

What is less obvious is that even when you “disable” your logging it still incurs a cost and that cost may be significantly larger than you think. The two main issues I’ve seen that often cause this large expense are:

  1. Methods that generate log messages
  2. Inline generation of strings

The first, methods that generate log messages, occurs when you need to do a bit of processing in order to make a meaningful log message. For example, you might need to know how far you are through a loop so you write a function called generateFormattedProgress that takes the number of loops you’re going to go through and the current loop counter as parameters. generateFormattedProgress generates a tidy little string that might loop like this [8% complete (currently on iteration 80,001 of 1,000,000)].

The second, inline generation of strings, happens when you need to do something a bit simpler like displaying a loop counter. You might build a string like this "Loop: " + loop_counter and then log it.

In both of these cases you get bitten by the less obvious issue I mentioned above when you disable logging. To be completely concrete about this imagine your logger is called like this:

Case #1:

1
console.log(generateFormattedProgress(loop_counter, total_loops));

Case #2:

1
console.log("Loop:" + loop_counter);

Even if you replace console.log with a function that just immediately returns you will, in most cases, still be forcing the machine to call generateFormattedProgress and perform the string concatenation only to throw the results away. This is where the overhead comes in.

Borrowing from some other languages I came up with an idea to reduce this burden. Unfortunately it is a bit ugly but it does give you a decent performance boost. The idea is that instead of always calling the logging code at runtime you wrap your logging statements in anonymous functions and pass those to the logger. The logger can then decide if it needs to run them and if it doesn’t then it never calls the code inside of the anonymous function.

Your log statements go from looking like the statements above to statements like this:

Case #1:

1
console.log(function(){ return generateFormattedProgress(loop_counter, total_loops);});

Case #2:

1
console.log(function(){ return "Loop:" + loop_counter; });

Some test code is below to illustrate the difference in performance. On my machine running 100,000 iterations I get the following results in Chrome 37.0.2062.94:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
Console.log enabled
Running: test_normal_console
Total milliseconds: 1921
Milliseconds per log: 0.01921
Running: test_anonymous_function_console
Total milliseconds: 1917
Milliseconds per log: 0.01917
Disabling console.log
Running: test_normal_console
Total milliseconds: 16
Milliseconds per log: 0.00016
Running: test_anonymous_function_console
Total milliseconds: 5
Milliseconds per log: 0.00005

So here we see that we cut the runtime by at least two orders of magnitude going from a little over 1.9 seconds for each case to less than 20 milliseconds for each case. Does logging affect your Javascript application enough to use this pattern? Is this an anti-pattern? Are you already doing this or something similar? Post a message in the comments and lets discuss it!

Sample test code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
var test_count = 100000;

function get_timestamp() {
    return new Date().getTime();
}

function write_newline() {
    document.write("<br/>\n");
}

function display_function_name(caller) {
    var myName = caller.callee.toString();
    myName = myName.substr('function '.length);
    myName = myName.substr(0, myName.indexOf('('));

    document.write("Running: " + myName);
    write_newline();
}

function show_results(start, stop, count) {
    var totalMilliseconds = stop - start;
    var millisecondsPerLog = totalMilliseconds / test_count;

    document.write("Total milliseconds: " + totalMilliseconds);
    write_newline();
    document.write("Milliseconds per log: " + millisecondsPerLog);
    write_newline();
}

function test_normal_console() {
    display_function_name(arguments);

    var start = get_timestamp();

    for (var loop = 0; loop < test_count; loop++) {
        console.log("test! " + loop + "test!");
    }

    var stop = get_timestamp();

    show_results(start, stop, test_count);
}

function test_anonymous_function_console() {
    display_function_name(arguments);

    var start = get_timestamp();

    for (var loop = 0; loop < test_count; loop++) {
        console.log(function () {
            return "test! " + loop + "test!";
        });
    }

    var stop = get_timestamp();

    show_results(start, stop, test_count);
}

// Store the original console.log function
var original_console_log = console.log;

// Call this to enable logging
function enable_console_logging() {
    console.log = function (input) {
        // Why the bind(console)(input)?
        //
        // console.log expects "this" to refer to the console object or it crashes with an invocation exception
        //   See: https://stackoverflow.com/questions/8904782/uncaught-typeerror-illegal-invocation-in-javascript

        // Is this a function?
        if (typeof input == "function") {
            // Yes, call the function to get the data to log to the console
            original_console_log.bind(console)(input());
        }
        else {
            // No, just log it
            original_console_log.bind(console)(input);
        }
    }
}

// Call this to disable logging
function disable_console_logging() {
    console.log = function () {
    };
}

document.write("Console.log enabled");
write_newline();

enable_console_logging();

test_normal_console();
test_anonymous_function_console();

document.write("Disabling console.log");
write_newline();

disable_console_logging();

test_normal_console();
test_anonymous_function_console();