How introducing a state in Azure Functions punches you in the face

This post is a bit longer explanation of an issue I reported a few days ago. To make a long story short - I was trying to find a way to fix a bug in my function, where almost each call resulted in an error logged to Application Insights. The exception was a simple Collection was modified; enumeration operation may not execute - I knew what was failing and where but I couldn't find an answer why. I'll try to explain this a little bit and - on the occasion - tell you why state in Azure Functions is a bad, bad thing.

As you can see, each call of my function was polluted by an exception

The background

As you probably know(and if now - you'll get it in a second), before Azure Function can be actually triggered, it has to be initialized. There's a ScriptHostManager class, which is created at the very beginning of the first call to your function - it's responsible for handling the whole host. Once initialized, it waits and listens for one of three things:

  • incoming calls(triggers)
  • a signal for restart
  • an exception(which by the way will cause a restart)

This host will be kept alive for a fixed amount of time and if it's not triggered, it will be closed. Of course it can be scaled if needed, but it's not the case now.

A host is also responsible for digesting all metadata and description related to your functions. It will read function.json file to get information about bindings, find an entry point and validate it against a configuration file. All this operations happen only why time, when host is created, and once it knows everything what it needs, it can invoke your function again and again. However, this is where problem could occur.

The habits

Let's consider following function:

/
public class FooFunction 
{	
	public static void Run(string myQueueItem,
		ICollector<EventLog> fooTable,
		TraceWriter log)
	{
		// Do some processing...	
		fooTable.Add(new FooTable());
	}
}

So far so good - nothing unexpected happens. In fact - this example will work just fine. But let's say we'd like to refactor it a little and extract logic responsible for processing an item:

/
public class FooFunction 
{
	private static ICollector<FooTable> _fooTable;
	
	public static void Run(string myQueueItem,
		ICollector<EventLog> fooTable,
		TraceWriter log)
	{

		_fooTable = fooTable;

		Proc(myQueueItem);
	}
	
	private static void Proc(string myQueueItem) {
		// Do some processing...
		
		_fooTable.Add(new FooTable());
	}
}

Initially there's nothing wrong with this design. On the other hand, we've just introduced a some kind of state, which will last as long as our function is alive. It still could work though and we can live unaware of this flaw. This is how I introduced this bug into my system - I was refactoring my functions as always with a little help of Resharper and in some point just moved ICollector<T> parameter to a static field. 

The problem

As I mentioned, initially you could live with a state in your function and even don't see any problems. If you're using e.g. TimerTrigger, for sure it'll work - you need just a one instance of a function called at specific interval. However, what about triggering a function for each queue item? Per each HTTP request? Or even an event in ServiceBus? In those scenarios, your function will be called concurrently and will simultaneously access your static field, overwriting what other calls have added to a collection. Sooner than later you'll end up with a pretty Collection was modified; enumeration operation may not execute everywhere in your logs. This is why initially this problem won't affect you - if traffic is low enough, it won't trigger a function fast enough to actually make this exception happen.

Please have in mind, that documentation of Azure Functions makes this rather clear, that state should be avoided so introducing it is, well... you deserve to be punished :)

The solution

The solution of this problem is pretty simple - just pass input of your entry point as parameters to other methods in your function. This will help keep your logs clean(interesting fact is that Monitor tab in your function won't show this problem - each call will be marked as successful while the error count will grow!!) and save you from potential other problems related to sharing a state within a function.

 

Digging deeper again - querying Application Insights data

In the one of the previous post I presented you the basics of using Analytics in Application Insights. Just to remind you - it's a tool, which allows you to get much more detailed information regarding how your application perform and behaves. In this post I'll try to encourage you to use this tool on daily basis, especially when something is clearly wrong and you don't want to click through all those tabs in Azure Portal.

Quickly finding an exception

Let's consider following example - you're informed by your client, that he or she got an error saying Object reference not set to an instance of an object. You know the time and assume, that we're facing NullReferenceException here. What could you do to quickly find more details regarding this exception? Let's consider following query:

/
exceptions
    | where timestamp >= ago(24h) 
        and type == "System.NullReferenceException" 
        and outerAssembly 
            contains "MyProject" 
    | project method, details, timestamp 

This query will project a simple result containing a method in which an exception was thrown, details(like inner stack) and the exact time when it occurred. You can modify it and use different timestamp to get results, which will satisfy you the most.

Finding pages which are loading too slow

This is another example - you have a SPA and you'd like to know, which pages are loading longer, that a fixed threshold. Fortunately we can use a really simple query, which can help us here:

/
pageViews
    | where duration > 500

Yes, this is really it. Of course you can extend this query and use other metrics to further filter the data like:

/
pageViews
    | where duration > 50
        and operation_Name == "some_operation"
        and timestamp > ago(1h)  

Or even visualize your data to be aware which slower requests are really the slowest ones:

/
pageViews
    | where duration >= 250
    | render piechart  

Custom metrics

You can use predefined metrics to gather some information about your application, but where this tool really shines is the possibility to query custom metric. This allows you to easily build your own reports and really focus on what you're interested in.

For example I'd like to know how many times given method is called so I can be aware of all potential hot-paths and focus my optimization efforts on it. To do this I need two things:

  • a tool, which will decorate methods calls with a custom metrics logging(AOP/assembly weaving will help here)
  • custom query in Application Insights Analytics

Let's say, that this decorator will log one thing - a method name. Now in Analytics we could create a query, which would use this custom metric to show us which method is called the most.