Windows Workflows that restart themselves?

A few weeks ago I got assigned a fun bug. We have a WF-based order system and it seems that occasionally orders that had been send earlier would start all over by themselves.
And sure enough, when looking at the logging I saw that the order would start over. So how did this happen?

First off I noticed it only happened with orders that required a callback in their process. So orders that, at one point or another, would be idle and waiting for an external event. All other orders never gave a problem.
Then I also noticed that the orders restarted themselves after the system itself had been idle for around 30 minutes.
So workflows that were idle were restarting after 30 minutes of system inactivity. They were re-processed when a new order was sent (you'd then see a whole slew of old orders restarting).

Whenever something happens on IIS after around 30 minuted of inactivity I assume it's always related to the fact that after 20 minutes of inactivity (by default) IIS will stop the web service/application to spare resources. The next request that comes in will cause IIS to startup the web service/application again. So it's pretty much safe to assume the problem is related to the web service stopping and restarting.

So why would an order start all over again, after the web service is being restarted. The most likely reason would be that the Workflow Runtime was unable to save its state. So without knowing where the workflow left off, but knowing that the worklfow does exist, it seems logical the workflow would just restart.

We checked the config and it did have the WorkflowPersistenceService configured and loaded. However, it's "UnloadOnIdle" setting was missing. Meaning it defaults to false. Meaning workflows don't unload when they are idle. And more importantly: a workflow is only persisted when you explicitly tell it to, or when it is unloaded.
Since neither happened on our system the workflows never stored their state and restarted when the web service restarted.

Of course this was not figured out that quickly. I assumed the operational engineers would use the configuration we'd send them, so I never bothered to check it. If I had, I would have solved this bug in a matter of minutes. Now it took us days of prodding, testing and praying. Until another developer mentioned he had noticed the config looked almost the same, but not quite the same. *sigh*.
Bugtracking rule #1: Always check the config!

SOAP logging for webservices

If you wish to log incoming SOAP requests to your ASMX webservice, you can write a SOAP extension that does just that.

You’ll need to create a class that inherits from SoapExtension and you should override the methods GetInitializer, Initialize, ChainStream and ProcessMessage.
It’s not that hard, you can find an working example at the MSDN site: How to: Implement a SOAP Extension. It works for both the server (who accepts incoming SOAP requests) and a client (who sends SOAP requests to servers).

All you need to do is add this to your web.config (or app.config) and it will work:

<system.web>
    <webServices>
        <soapExtensionTypes>
            <add type="MySoapLogger, MyNamespace.SoapLogger" priority="1" group="High" />
        </soapExtensionTypes>
    </webServices>
</system.web>

If you wish to create a SOAP logger for a WCF webservice, that’s both easier and harder. It’s simpler to write the extension for, but now you must write different things for a server and a client. And making it configurable requires some more work then the ASMX version.

In WCF you don’t write a SOAP Extension, but rather a Message Interceptor. And you won’t need to inherit from a base class, but you’ll need to implement certain interfaces to make it work.
To be able to see incoming (server) messages you’ll need to implement IDispatchMessageInspector and for outgoing (client) messages you’ll need to implement IClientMessageInspector. It's worth mentioning that nothing prevents you from implementing these interfaces both on the same class. That's what I did.

Both interfaces require you implement two functions:

object IDispatchMessageInspector.AfterReceiveRequest(ref Message request, IClientChannel channel, InstanceContext instanceContext);
void IDispatchMessageInspector.BeforeSendReply(ref Message reply, object correlationState);

And:

object IClientMessageInspector.BeforeSendRequest(ref Message request, IClientChannel channel);
void IClientMessageInspector.AfterReceiveReply(ref Message reply, object correlationState);

For IDispatchMessageInspector you have AfterReceiveRequest for when the request is received, before your normal code will run and BeforeSendReply, which is directly before the response will be send to the requester, after all your normal code has run.
For IClientMessageInspector you have BeforeSendRequest which is right before the request is send to the server, after all your normal code has run and AfterReceiveReply for when the response from the server has been received, before your normal code will run.

Basically you can do anything to the request you want at those points, even alter the data. One of the examples I found was to validate incoming requests to an XSD. Another was to do some translations for backwards compatibility sake. But in this case we just want to log the data.

So what we can do in each of these functions, is the following:

try
{
    // Only try to parse the message if it is not empty.
    if(message.IsEmpty == false)
    {
        string xml = message.ToString();
        XDocument xmlDocument = XDocument.Parse(xml);

        StringBuilder sb = new StringBuilder();
        XmlWriter writer = XmlWriter.Create(sb, new XmlWriterSettings { Encoding = Encoding.ASCII, Indent = true });
        xmlDocument.WriteTo(writer);
        writer.Close();

        sb.Append("\r\n");
        this.soapLogger.Log(sb.ToString());
    }
}
catch(Exception e)
{
    if(System.Diagnostics.Debugger.IsAttached == true)
    {
        System.Diagnostics.Debugger.Break();
    }
}

In this case the "message" variable contains the SOAP message. I wrote one function to do the logging and have it called from the 4 functions mentioned above. Also the "soapLogger" class variable is the logger I use. It's not particulary important which logger this specifically is, but if you want to know, I use Log4NET.

The use of the XDocument and the XmlWriter is absolutely not necessary, but I use them to make the XML look pretty (indented) in the log. It is a lot slower then just directly logging it to the logfile, but that would result in the whole XML message to appear on 1 line.
The stuff in the try/catch clause is a neat trick I use to catch the unexpected exceptions.

If you want the most simple solution, you can also do it like this:

// Only try to parse the message if it is not empty.
if(message.IsEmpty == false)
{
    string xml = message.ToString();
    this.soapLogger.Log(xml);
}

Problems with Visual Studio 2008 SP1

I installed VS2008 SP1 the week after it came out. I used the prepare tool first, then installed the service pack and everything seemed to work perfectly. I haven't really checked out all of the new features, but I really like the fact that all the TODOs in your solution now show up, in stead of only the TODOs in the files you currently have opened. And I also like the VB-esque background compiling (or however they implemented it) and showing you selected compiler errors before you compile. If you create a function that returns a value, but haven't put in the return statement yet, the IDE will already inform you that the function doesn't return a value.

So all was fine and perfect, until I tried to debug an ASP.NET application. Then the IDE would freeze and prompt me with a window that told be VS2008 had an internal error and must close. I could then close VS2008 or close it and look for a solution online. Whichever I would choose, the window would disappear, but VS2008 would remain, taking up 100% CPU on one core. The other core would be pwned by WerFault.exe and it would not end until I'd manually end-tasked DevEnv.exe.

I had my ASP.NET development set up to use IIS, so I switched so Cassini (the internal ASP.NET development server), but that didn't work. I then tried to run the application from IIS again and attach the debugger. Still hanging.
I then searched on Google for a bit and tried some work-arounds for similar problems I found there, I also tried the repair option in the VS2008 installer, but debugging still hung the IDE. So I reported it at Microsoft Connect and went home (I was at work at the time).

That evening at home I completely removed VS2008 and everything related from my laptop and reinstalled it. I verified debugging worked and when it did I installed SP1 again. But this time debugging kept working. So I have no idea what was wrong, but it's all working again now. So if anyone runs into similar problems, just uninstall and install again.

SecuROM strikes again

I've posted about DRM before and I've mentioned SecuROM before. So today I was uninstalling a program that left a shortcut on my desktop. So I wanted to right-click on it and delete it. But when I right-clicked on it, Explorer crashed. Thinking it might be a fluke I tried again and Explorer crashed again. Hmmm...so I figured that it might be the shortcut itself, so I selected it and pressed "delete", but...Explorer crashed again. So I opened a command prompt and deleted the shortcut from there. That worked.

Then I right-clicked another shortcut and Explorer crashed again. Clicked another shortcut and Explorer crashed. So I rebooted Windows to solve the problem, only it wasn't solved. Explorer still crashed if I right-clicked a shortcut.

I suspected it might have something to do with Shell Extensions. And when I googled the problem I found a program called ShellExView. This program shows you all the Shell Extensions that are currently loaded and let's you disable them. So I started the program, selected all the "Context Menu" type extensions and tried to disable them. Nothing happened. I figured it might be because I wasn't running the program as administrator.

So this was interesting. I couldn't run the program as administrator by right-clicking on it (that would just crash Explorer), the CTRL-Shift-Enter method of starting an elevated program would also cause Explorer to crash, so I had a problem. But then I remembered something about how Vista determines when to elevate a program even when it's not asked to. You see for installers you'd need to run them elevated or they wouldn't be able to install anything, but older installers won't have a manifest that Vista can use to determine they need elevation. I read on one of the many developer blogs I read, that Vista can also decide to elevate based on the name of the executable. So I renamed "shexview.exe" to "shexviewsetup.exe" and I got a nice elevation prompt.

So I disabled all the "Context Menu" extension and tried to right-click a shortcut. No crash. Great! But which extension caused the problem. I wanted to enable them all one-by-one when I saw an extension that I immediately suspected of being the culprit. The extension was called "CmdLineContextMenu Class" and it's description read: "SecuROM context menu for Explorer."

Why would I need a SecuROM extension installed? What does it do? And why was it installed without my consent? The only thing I installed right before I started noticing crashes was the new Space Siege demo. But why would you want a freely available demo to have copy protected? Oh wait, it's not the first time they've done that. But I already uninstalled Space Siege so why wasn't SecuROM removed? Why would companies want to leave a rootkit behind on my system? Then again, I'm not absolutely sure it came from the Space Siege demo (UPDATE: it didn't, see below), but it was the last thing I installed before Explorer started crashing. I tried looking in the installer files of the demo, but those are InstallShield cabinet files and I can't look into them.

Aside from being some nasty piece of DRM, the extension was installed in a very peculiar location. Not in "Program Files" or maybe the "Windows" directory like you'd expect. No, it was installed in the temp directory of my user profile! It's called "CmdLineExt.dll" and when I looked in the temp directory I also noticed the file "drm_dyndata_7370010.dll" of which the file details also mentioned being part of SecuROM.

Ofcourse the question is, why did it crash? Now I'm happy it did, otherwise I wouldn't have found out, but I'm still curious as to why it crashes Explorer whenever I right-click a shortcut.
I'm a big fan of Mark Russinovich's blog and his "The case of..." series of blog post. I have WinDBG installed, however I'm mainly a C# developer and have not done any real Win32 C++ programming for years and even when I did, it's wasn't at the low level that Mark understands. But, I did do some basic stuff with WinDBG.

I attached WinDBG to Explorer, I enabled the extension and I made Explorer crash. So now I'm in WinDBG and it's telling me Explorer has crashed. I run the !analyze command and I get the following feedback: "Probably caused by : heap_corruption ( heap_corruption!heap_corruption )".

I get the callstack and I see these as the last lines:

77b39790 04800fd8 00250000 ntdll!DbgBreakPoint
c0000374 77c4c030 000ee1ac ntdll!RtlReportCriticalFailure+0x2e
00000002 77b39754 00000000 ntdll!RtlpReportHeapFailure+0x21
00000008 00250000 04800fd8 ntdll!RtlpLogHeapFailure+0xa1
00250000 00000000 04800fe0 ntdll!RtlFreeHeap+0x60
04800fe0 000ee408 00000000 kernel32!GlobalFree+0x47
000ee240 00000001 04800fe0 ole32!ReleaseStgMedium+0x124
WARNING: Stack unwind information not available. Following frames may be wrong.
03d41cdc 00000000 0030db98 CmdLineExt!DllUnregisterServer+0x3c1c
02640e60 0030db98 00000004 SHELL32!HDXA_QueryContextMenu+0x1b5
055c2ee8 00f902ef 00000000 SHELL32!CDefFolderMenu::QueryContextMenu+0x38b

Looks about right, although I can't be absolutely sure since I don't have de debug symbols for the SecuROM DLL.

So looking at the stacktrace I get the idea the SecuROM extension is trying to free some object COM twice. I don't know what object and I don't know why, my low-level knowledge ends about here. I'm just happy I found the problem and make my system right-clickable again.

Oh and one interesting thing I've learned tonight. When you have Explorer.exe crashed in the debugger, you can't use ALT-TAB (which wasn't unexpected), but you can use WIN-TAB (Flip3D). That made switching back and forth between windows a whole lot easier.

UPDATE:
It apears it wasn't the Space Siege demo that infected me with the DRM rootkit, it was the Mass Effect 1.01 update that did. I installed it, but installed the Space Siege demo right after it. So even though I did't get infected by their rootkit the first time, I was stupid enough to fall for it anyways.