Problem: Visual Studio 2008 has long (20 - 30 seconds) program load time.
It appears that after installation of some software packages, Comodo opens the file, “c:\windows\inf\setupapi.app.log” and doesn’t release the file handle. It hangs on to the handle even through multiple boot cycles. This occurred with Firewall Security Level = DISABLED and Defense+ permanently DISABLED. The problem also occurs with Firewall Security Level = in Custom Policy Mode.
This was also a problem in 3.0.15.277 and causes the startup time of programs which access this file to slow down to a crawl with a “SHARING VIOLATION” error (as shown by Sysinternals “Process Monitor”). Using Sysinternals “Process Explorer” I found that Cmdagent.exe was holding the file handle. Doing a force release of the handle restores program load time (specifically, Visual Studio) to normal. In the past, running this version (3.0.25), I always ran Defense+ permanently disabled and this problem still occurred. I was hoping this bug would be fixed in the release, but it was not to be.
This disturbing behavior raises the following questions:
How does a supposedly DISABLED firewall and permanently DISABLED Defense+ (which I never enable) manage to open a setup log (TEXT) file?
If Defense+ is truly DISABLED (which I doubt), what is a firewall utility doing mucking around with a setup log file?
Is that setupapi.app.log handle involved into exclusive access file operations or shared access?
[b]Using the SetupAPI Logs[/b]
SetupAPI logs are plain-text files that maintain the information that SetupAPI records about device installation. Specifically, the files maintain a record of device and driver changes, with the most recent Windows installation at the top of the log.
Major changes were made to SetupAPI logging for Windows Vista. The Setupapi.log used in Windows XP and Windows Server™ 2003 has been replaced with two new files:
Setupapi.dev.log. This file contains logging information from Device Management and Installation (DMI) components specific to device installs. This is the primary log that should be used for most troubleshooting investigations. Setupapi.app.log. This file contains legacy Setupapi logging information unrelated to device installs, such as associated application events.
Is there anything written to that log soon after a logon?
Please re-read my post carefully and you’ll see that I stated in the first paragraph that I “permanently disabled Defense+” and that the problem persists through “multiple boot cycles”.
Do you mean “uncheck all items that are now checked” in Monitor Settings? There is no “disable” checkbox.
If checking “permanently disable” doesn’t disable these monitor functions, then that is an extremely misleading name for that checkbox.
Is that setupapi.app.log handle involved into exclusive access file operations or shared access?
Visual Studio [i]attempts[/i] to open it as shared (Generic Read/Write). However, it can't open the file because Cmdagent has most likely opened it with exclusive access. This is not the proper way to open a logging file. What will happen is that any program that attempts to open this file for write operations will stall at this operation until it times out or until it exhausts it's retry count. I suspect that in Cmdagent's call to Createfile, it is leaving the [i]dwShareMode[/i] flags at "0". This is not good practice and will lock the file for any access--READ or WRITE. It should set the FILE_SHARE_READ & FILE_SHARE_WRITE bits in this flag when opening the file. This would allow it to keep the file open, but would also permit the system and programs to access it for logging puposes.
Is there anything written to that log soon after a logon?
It's a logging file, so there are accesses at bootup, logon, and during some program startups (like Visual Studio), when Cab files are accessed and files extracted. Of course, if Cmdagent locks the file this operation can not occur until the file is released.
The problem is intermittent, but seems to occur following the installation of new programs.
That description is ambiguous enough to be interpreted as setting Defense+ to disabled mode permanently. Rebooting doesn’t affect that.
That’s why I asked toi confirm you choose to deactivate it.
Yes unchecking them disable monitor trapping on these entities.
This is a less restrictive way than deactivating Defense+ and in theory there should be no difference like you said but testing this too could provide more info just in case.
Please test it without deactivating D+.
Thanks for confirming this.
Is there any way to reproduce this in a non intermittent way?
Do you have any other security or utility software tha use kernel drivers or system hooks?
Do you use any unofficial patch like uxtheme patcher?
Forgot to include the following system info in original post:
Vista Home Premium 32-bit
Comodo 3.0.25.378 X32
I tried to repeat it with installation of a very small program, but the problem didn’t repeat. The last time I saw it happen was after installing SQL Server Express 2008 and that install process is far too complicated to repeat. I will try to find a smaller install or maybe write something to test it.
Do you have any other security or utility software tha use kernel drivers or system hooks?
No. I think it's important to note here that when the "locked file" problem appears, the only program that shows an open file handle on it is cmdagent.exe.
Do you use any unofficial patch like uxtheme patcher?
No.
Have you investigated whether cmdagent is opening the file (setupapi.app.log) at any time in exclusive mode?
I’m not a developer nor a Comodo employee. Since I have an XP box I cannot attempt to reproduce this issue.
Please post as much info it is possible so when devs will look at this they will be able to reproduce it.
These info could be also useful to find a common pattern with other members who can reproduce this.
At least in one unrelated old issue with cmdagent high CPU load few users reported they installed an uxtheme patch later on.
There is always a chance that seemingly unrelated info could prove useful later on.
In case an issue is not reproducible at the dev lab, Devs can only guess what code part could be involved.
Anyway even if they recode some functions there would have no way to test these if they cannot reproduce a specific issue.
If even there is a chance that some info could raise the reproducibility of a specific issue this will prove undoubtedly useful to have an issue fixed faster.
I thought possibly the “file locking” could be a problem with Vista not properly closing the file, since it is highly unlikely that another program could open the file and then make it appear to Process Explorer that “cmdagent.exe” opened it. I trust SysInternals Process Monitor and Process Explorer utilities to report accurate information.
I ran a test loop in which I opening the file and then released the file 50,000 times and did not see a failure to release. If I intentionally opened the file and then aborted the program, Process Explorer reported that it was my program that was indeed holding the file handle.
I ran a boot log with Process Monitor and it showed that during boot up, “cmdagent” is indeed opening the file in a mode that locks WRITE requests from any other process until it releases (closes) the file. It appears that it is closing the file as it should. However, if there are problems during cmdagent’s boot cycle, (like a thread assigned to this task hanging or aborting incorrectly) then this file would be left in a locked state, preventing write access by any other process. This would not only add significant delays to the startup time of any program that required write access, but would also add significant delays to the Windows boot process.
A quick workaround would be for “cmdagent” to open the file by setting shared flags to READ/WRITE permission for subsequent file opens on this file.
Update.
The problem with Cmdagent.exe locking the file, Windows\inf\setupapi.app.log, still exists after disabling Defense+ (Permanently) as well as disabling all monitoring by unchecking ALL entries in the Advanced/Defense+Settings/Monitor Settings.
Here is how I was able to duplicate the problem:
Install the program “WORDVIEW.EXE” a free program from MS to view MS Word documents.
shut system down after install completes.
start system.
After system is completly booted up, run the SysInternals program, “Process Explorer”. In Process Explorer
Click View and check “Show Lower Pane”.
Select View again. Go down to Lower Pain View and select Handles.
Highlight the process “cmdagent.exe”.
In the lower pane, you can see that the file handle for “setupapi.app.log” is being held. Every program (including the boot process) that requires access to this file will slow to a crawl during its startup.
So, I repeat the question that I asked when I first pointed out this bug:
With Defense+ completely disabled, why does cmdagent.exe require ANY type of access to a setup log file?
I’ve attached a screen shot of what Process Monitor shows on my system.