VTest is failing to start a OWASP ZAP process with code 1

Question

I have been trying to get the OWASP ZAP tool to run against my code in an automated fashion. I have been successful in writing a method that works consistently through the Text Explorer interface of Visual Studio 2017 on my local machine. However, whenever I try to have one of my automated test boxes run it using the remote testing command line tool triggered by TFS, then it always fails with Code 1, and no other error text.

I am running the same version of windows 10 locally and on the test box. I have the same version of visual studio installed on each, so I would expect them to be using the same version of VTest to run the tests. I'm not actually sure VTest is involved since I have converted to Selenium, and this is being run as a unit test anyway without a GUI component.

I have tried setting security on the .bat file and the .exe file it calls to Authenticated Users full access because I thought it could be a permissions issue.

I have looked in the event log, but there is are no details showing up in there. It is like it never happened.

I watch the test box while it is attempting to run this particular test, and it never even tries to start up a separate command window for the new zap process, it fails before that ever happens. However, it is definitely finding the correct file to run on the test box because I have tried altering the URL and get a specific error saying it can no longer be found.

I have also tried manually executing the command I am trying to run via command line and when I do it manually on the test box then it works perfectly. The TFS box is logged in and running as the user I tried the manual test as, and that user is a local admin on the box.

Because this works locally on my machine, and because I am able to successfully run the command manually on the test box, the problem component seems to be the TFS remote agent. The remote agent is successful in launching two other processes for Selenium testing, one of which is the IE driver, and the other is the WinAppDriver; the WinAppDriver has a separate command window associate with it when it launches. However, both of these processes are launched by the Selenium wrapper, I am not launching the processes myself directly.

You can see an excerpt below of the code I am using to launch the zap process. Does anyone know why it might be failing on my best box?

        string ZapBatLocation = @"C:\Program Files\OWASP\Zed Attack Proxy\zap.bat";
        var last_idx = ZapBatLocation.LastIndexOf('\\');

        var _ZapProc = new System.Diagnostics.Process();
        _ZapProc.StartInfo = new System.Diagnostics.ProcessStartInfo(ZapBatLocation.Substring(last_idx + 1), "-daemon") { WorkingDirectory = ZapBatLocation.Substring(0, last_idx), UseShellExecute = true, CreateNoWindow = false };
        _ZapProc.ErrorDataReceived += ErrOutputHandler;

        _ZapProc.Start();
        System.Threading.Thread.Sleep(2000); // give it time to launch and die if it is going to
        if (_ZapProc.HasExited)
            throw new Exception($"Unable to launch ZAP process, exited with code {_ZapProc.ExitCode}.");

EDIT: The log file seems to indicate some sort of config corruption. perhaps a security issue on a config file somewhere? Here is an extract of what appears to be the main error that appears frequently in the log:

2019-05-30 16:26:34,178 [AWT-EventQueue-0] INFO Control - New Session 2019-05-30 16:26:34,209 [AWT-EventQueue-0] INFO Control - Create and Open Untitled Db 2019-05-30 16:26:34,240 [AWT-EventQueue-0] INFO ENGINE - dataFileCache commit start 2019-05-30 16:26:34,240 [AWT-EventQueue-0] INFO ENGINE - dataFileCache commit end 2019-05-30 16:26:34,256 [AWT-EventQueue-0] INFO ENGINE - Database closed 2019-05-30 16:26:34,396 [AWT-EventQueue-0] INFO ENGINE - open start - state not modified 2019-05-30 16:26:34,459 [AWT-EventQueue-0] INFO ENGINE - dataFileCache open start 2019-05-30 16:26:34,475 [AWT-EventQueue-0] INFO ENGINE - dataFileCache open end 2019-05-30 16:26:35,615 [ZAP-cfu] ERROR ExtensionAutoUpdate - Unable to load the configuration org.apache.commons.configuration.ConfigurationException: Unable to load the configuration at org.apache.commons.configuration.XMLConfiguration.load(XMLConfiguration.java:955) at org.apache.commons.configuration.XMLConfiguration.load(XMLConfiguration.java:908) at org.apache.commons.configuration.XMLConfiguration$XMLFileConfigurationDelegate.load(XMLConfiguration.java:1583) at org.apache.commons.configuration.AbstractFileConfiguration.load(AbstractFileConfiguration.java:324) at org.apache.commons.configuration.AbstractFileConfiguration.load(AbstractFileConfiguration.java:261) at org.apache.commons.configuration.AbstractFileConfiguration.load(AbstractFileConfiguration.java:238) at org.apache.commons.configuration.AbstractHierarchicalFileConfiguration.load(AbstractHierarchicalFileConfiguration.java:184) at org.zaproxy.zap.utils.ZapXmlConfiguration.(ZapXmlConfiguration.java:88) at org.zaproxy.zap.extension.autoupdate.ExtensionAutoUpdate.getPreviousVersionInfo(ExtensionAutoUpdate.java:883) at org.zaproxy.zap.extension.autoupdate.ExtensionAutoUpdate.getNewAddOns(ExtensionAutoUpdate.java:902) at org.zaproxy.zap.extension.autoupdate.ExtensionAutoUpdate.gotLatestData(ExtensionAutoUpdate.java:1139) at org.zaproxy.zap.extension.autoupdate.ExtensionAutoUpdate$8.run(ExtensionAutoUpdate.java:983) Caused by: com.sun.org.apache.xerces.internal.impl.io.MalformedByteSequenceException: Invalid byte 2 of 3-byte UTF-8 sequence. at com.sun.org.apache.xerces.internal.impl.io.UTF8Reader.invalidByte(Unknown Source) at com.sun.org.apache.xerces.internal.impl.io.UTF8Reader.read(Unknown Source) at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(Unknown Source) at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.skipChar(Unknown Source) at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(Unknown Source) at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(Unknown Source) at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source) at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source) at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source) at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(Unknown Source) at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(Unknown Source) at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(Unknown Source) at org.apache.commons.configuration.XMLConfiguration.load(XMLConfiguration.java:942) ... 11 more 2019-05-30 16:26:45,052 [Thread-10] INFO ENGINE - dataFileCache commit start 2019-05-30 16:26:45,052 [Thread-10] INFO ENGINE - dataFileCache commit end 2019-05-30 16:26:45,084 [Thread-10] INFO ENGINE - Database closed 2019-05-30 16:26:45,193 [Thread-10] INFO Control - OWASP ZAP 2.7.0 terminated.

I cleared out the log file, and tried to run the automated test, it failed as expected but did not put anything in the log file. I then tried manually running ZAP from the command prompt, and it filled the log file after I exited the program, including the above error.

So it looks like the ZAP log file is not actually created until after a successful start, or at least more of a start than I am getting in the automation.

Are there any errors logged in the zap.log file? github.com/zaproxy/zaproxy/wiki/FAQhelp#check-the-log-file — Simon Bennetts
Thanks @SimonBennetts, that does help. I put part of the log in my question now. I just need to figure out what it means. — Jereme Guenther
I just tried clearing the log file, then running the failing test again. The log file did not populate with anything this time. — Jereme Guenther
If theres nothing in the log then ZAP is not starting - if it starts then it will start logging straight away. I'd try debuging your script to make sure that it does start ZAP successfully. — Simon Bennetts
It does start it perfectly on my local machine every time I run it, so I know the code should be able to do it; which is why my first thought was security on the remote machine. — Jereme Guenther

Jereme Guenther Jereme Guenther · Accepted Answer · 2019-06-26T20:34:56

I'm not really sure this can be called an answer, but the problem no longer exists, so here goes.

After a week of fighting that rather odd issue, I got pulled away on other tasks and could no longer focus on it. After two weeks I finally had time to resume looking into the problem, and to my surprise it was no longer an issue. The .bat file is now launching correctly every time, with no changes on my part.

My best guess is that windows may have gotten stuck and some windows update caused a reboot sometime over the past two weeks causing things to start working. Why I never tried a basic system reboot during all of my troubleshooting I don't know, chalk that up to stupidity.

On a side note, if anyone else is struggling with a similar issue, my next trouble shooting step was to create a custom .bat file with these contents:

echo 'hi'
pause

Then insert a call to it in code right above the call to start the ZAP .bat file. Just to see if the code could start anything at all, or if it were something specific to the ZAP .bat file.

var bt = new System.Diagnostics.Process();
bt.StartInfo = new System.Diagnostics.ProcessStartInfo("C:\\selenium\\test.bat");
bt.Start();

VTest is failing to start a OWASP ZAP process with code 1

1 Answers