Fix Event Viewer errors caused by qemu-ga

PATCH Superseded Sameeh Jubran 2 participants 5 messages Mar 21, 2017 – Apr 5, 2017

Share & tools

Sameeh Jubran

author

2017-03-21 10:50 UTC #0 lore raw

PATCH 1/1 Fix Event Viewer errors caused by qemu-ga

When the command "guest-fsfreeze-freeze" is executed it causes the VSS service to log the errors below in the Event Viewer.

These errors are caused by two issues in the function "CommitSnapshots" in provider.cpp:

1. When VSS_TIMEOUT_MSEC expires the funtion returns E_ABORT. This causes the error #12293.

2. The VSS_TIMEOUT_MSEC value is too big. According to msdn the "Flush & Hold" operation has 10 seconds timeout not configurable, The "CommitSnapshots" is a part of the "Flush & Hold" process and thus any timeout bigger than 10 seconds would cause the error #12298 and anything bigger than 40 seconds causes the error #12340. All this info can be found here:
https://msdn.microsoft.com/en-us/library/windows/desktop/aa384589(v=vs.85).aspx

|event id|                           error                               |
* 12293  : Volume Shadow Copy Service error: Error calling a routine on a
           Shadow Copy Provider {00000000-0000-0000-0000-000000000000}.
       Routine details CommitSnapshots [hr = 0x80004004, Operation
       aborted.

* 12340 : Volume Shadow Copy Error: VSS waited more than 40 seconds for all volumes to be flushed. This caused volume \\?\Volume{62a171da-32ec-11e4-80b1-806e6f6e6963}\ to timeout while waiting for the release-writes phase of shadow copy creation. Trying again when disk activity is lower may solve this problem.

* 12298 : Volume Shadow Copy Service error: The I/O writes cannot be held during the shadow copy creation period on volume \\?\Volume{62a171d9-32ec-11e4-80b1-806e6f6e6963}\. The volume index in the shadow copy set is 0. Error details:
Open[0x00000000, The operation completed successfully. ], Flush[0x00000000, The operation completed successfully.], Release[0x00000000, The operation completed successfully.], OnRun[0x80042314, The shadow copy provider timed out while holding writes to the volume being shadow copied. This is probably due to excessive activity on the volume by an application or a system service. Try again later when activity on the volume is reduced.

Signed-off-by Sameeh Jubran <[email protected]>

---
 qga/vss-win32/provider.cpp | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

qga/vss-win32/provider.cpp +1 -2

index ef94669..d72f4d4 100644
@@ -15,7 +15,7 @@
 #include <inc/win2003/vscoordint.h>
 #include <inc/win2003/vsprov.h>
 
-#define VSS_TIMEOUT_MSEC (60*1000)
+#define VSS_TIMEOUT_MSEC (9 * 1000)
 
 static long g_nComObjsInUse;
 HINSTANCE g_hinstDll;

@@ -377,7 +377,6 @@ STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID SnapshotSetId)
     if (WaitForSingleObject(hEventThaw, VSS_TIMEOUT_MSEC) != WAIT_OBJECT_0) {
         /* Send event to qemu-ga to notify the provider is timed out */
         SetEvent(hEventTimeout);
-        hr = E_ABORT;
     }
 
     CloseHandle(hEventThaw);

Signature · 1 line

2.9.3

Michael Roth

2017-03-21 16:09 UTC #1 lore raw

Quoting Sameeh Jubran (2017-03-21 05:49:52)

Quoted 9 lines

When the command "guest-fsfreeze-freeze" is executed it causes the VSS service to log the errors below in the Event Viewer.
These errors are caused by two issues in the function "CommitSnapshots" in provider.cpp:
1. When VSS_TIMEOUT_MSEC expires the funtion returns E_ABORT. This causes the error #12293.

Quoted 6 lines

2. The VSS_TIMEOUT_MSEC value is too big. According to msdn the "Flush & Hold" operation has 10 seconds timeout not configurable, The "CommitSnapshots" is a part of the "Flush & Hold" process and thus any timeout bigger than 10 seconds would cause the error #12298 and anything bigger than 40 seconds causes the error #12340. All this info can be found here:
https://msdn.microsoft.com/en-us/library/windows/desktop/aa384589(v=vs.85).aspx

Not sure how best to deal with this. Technically our CommitSnapshots interface is driven by the backup job being run by QGA/QEMU management side. If that amount of time exceeds the VSS limits then I think it's appropriate for VSS to log the error accordingly. VSS_TIMEOUT_MSEC here doesn't actually have too much correlation with the VSS-set timeout, IIRC it's specifically picked to exceed both the 10 and 40 second timeouts and acts more as a fail-safe timeout.

Are the event logs causing issues? FWIW, on the posix side we also opt for gratuitous logging to syslog and such, the idea there being that cooperative guests would prefer transparency on how the agent is being used.

That said, I do think error 12293 is unecessary, since IIUC it would always be paired with the actual VSS-reported error. So avoiding the E_ABORT seems reasonable either way.

Quoted 56 lines

|event id|                           error                               |
* 12293  : Volume Shadow Copy Service error: Error calling a routine on a
           Shadow Copy Provider {00000000-0000-0000-0000-000000000000}.
       Routine details CommitSnapshots [hr = 0x80004004, Operation
       aborted.
* 12340 : Volume Shadow Copy Error: VSS waited more than 40 seconds for all volumes to be flushed. This caused volume \\?\Volume{62a171da-32ec-11e4-80b1-806e6f6e6963}\ to timeout while waiting for the release-writes phase of shadow copy creation. Trying again when disk activity is lower may solve this problem.
* 12298 : Volume Shadow Copy Service error: The I/O writes cannot be held during the shadow copy creation period on volume \\?\Volume{62a171d9-32ec-11e4-80b1-806e6f6e6963}\. The volume index in the shadow copy set is 0. Error details:
Open[0x00000000, The operation completed successfully. ], Flush[0x00000000, The operation completed successfully.], Release[0x00000000, The operation completed successfully.], OnRun[0x80042314, The shadow copy provider timed out while holding writes to the volume being shadow copied. This is probably due to excessive activity on the volume by an application or a system service. Try again later when activity on the volume is reduced.
Signed-off-by Sameeh Jubran <[email protected]>
---
 qga/vss-win32/provider.cpp | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)
qga/vss-win32/provider.cpp +1 -2
index ef94669..d72f4d4 100644
@@ -15,7 +15,7 @@
 #include <inc/win2003/vscoordint.h>
 #include <inc/win2003/vsprov.h>
 
-#define VSS_TIMEOUT_MSEC (60*1000)
+#define VSS_TIMEOUT_MSEC (9 * 1000)
 
 static long g_nComObjsInUse;
 HINSTANCE g_hinstDll;
@@ -377,7 +377,6 @@ STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID SnapshotSetId)
     if (WaitForSingleObject(hEventThaw, VSS_TIMEOUT_MSEC) != WAIT_OBJECT_0) {
         /* Send event to qemu-ga to notify the provider is timed out */
         SetEvent(hEventTimeout);
-        hr = E_ABORT;
     }
 
     CloseHandle(hEventThaw);
Signature · 1 line
2.9.3

Sameeh Jubran

author

2017-03-22 08:14 UTC #2 lore raw

Quoted 20 lines · Michael Roth

Quoting Sameeh Jubran (2017-03-21 05:49:52)
Quoted 4 lines
When the command "guest-fsfreeze-freeze" is executed it causes the VSS service to log the errors below in the Event Viewer.
These errors are caused by two issues in the function "CommitSnapshots"
in
Quoted 10 lines
provider.cpp:
1. When VSS_TIMEOUT_MSEC expires the funtion returns E_ABORT. This causes the error #12293.
2. The VSS_TIMEOUT_MSEC value is too big. According to msdn the "Flush & Hold" operation has 10 seconds timeout not configurable, The "CommitSnapshots" is a part of the "Flush & Hold" process and thus any timeout bigger than 10 seconds would cause the error #12298 and anything bigger than 40 seconds causes the error #12340. All this info can be
found here:
Quoted 1 line
https://msdn.microsoft.com/en-us/library/windows/desktop/
aa384589(v=vs.85).aspx

Quoted 7 lines

Not sure how best to deal with this. Technically our CommitSnapshots interface is driven by the backup job being run by QGA/QEMU management side. If that amount of time exceeds the VSS limits then I think it's appropriate for VSS to log the error accordingly. VSS_TIMEOUT_MSEC here doesn't actually have too much correlation with the VSS-set timeout, IIRC it's specifically picked to exceed both the 10 and 40 second timeouts and acts more as a fail-safe timeout.

The timeout was added in #commit: b39297aedfabe9b2c426cd540413be991500da25 There is no point in setting the TIMEOUT for this long as the actual freeze
- Fush and Hold Writes -
is limited to 10 seconds ( not configurable) according to msdn
https://msdn.microsoft.com/en-us/library/windows/desktop/aa384589%28v=vs.85%29.aspx

Quoted 6 lines

Are the event logs causing issues? FWIW, on the posix side we also opt for gratuitous logging to syslog and such, the idea there being that cooperative guests would prefer transparency on how the agent is being used.

Apparently, these error logs are annoying to some (
https://bugzilla.redhat.com/show_bug.cgi?id=1387125),
moreover I don't think that our implementation to the freeze operation - which is a workaround in a way -
should log errors even though we know they are false alarm.

Quoted 67 lines

That said, I do think error 12293 is unecessary, since IIUC it would always be paired with the actual VSS-reported error. So avoiding the E_ABORT seems reasonable either way.
Quoted 2 lines
|event id| error
|
Quoted 5 lines
* 12293 : Volume Shadow Copy Service error: Error calling a routine on a
           Shadow Copy Provider {00000000-0000-0000-0000-000000000000}.
       Routine details CommitSnapshots [hr = 0x80004004, Operation
       aborted.
Quoted 8 lines
* 12340 : Volume Shadow Copy Error: VSS waited more than 40 seconds for all volumes to be flushed. This caused volume \\?\Volume{62a171da-32ec-11e4-80b1-806e6f6e6963}\ to timeout while waiting for the release-writes phase of shadow copy creation. Trying again when disk activity is lower may solve this problem.
* 12298 : Volume Shadow Copy Service error: The I/O writes cannot be
held
qga/vss-win32/provider.cpp STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID
Quoted 31 lines
during the shadow copy creation period on volume \\?\Volume{62a171d9-32ec-11e4-80b1-806e6f6e6963}\. The volume
index in the shadow copy set is 0. Error details:
Open[0x00000000, The operation completed successfully. ], Flush[0x00000000, The operation completed successfully.], Release[0x00000000, The operation completed successfully.], OnRun[0x80042314, The shadow copy provider timed out while holding writes to the volume being shadow copied. This is probably due to excessive activity on the volume by an application or a system service. Try again later when activity on the volume is reduced.
Signed-off-by Sameeh Jubran <[email protected]>
---
 qga/vss-win32/provider.cpp | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)
qga/vss-win32/provider.cpp +1 -1
index ef94669..d72f4d4 100644
@@ -15,7 +15,7 @@
 #include <inc/win2003/vscoordint.h>
 #include <inc/win2003/vsprov.h>
 
-#define VSS_TIMEOUT_MSEC (60*1000)
+#define VSS_TIMEOUT_MSEC (9 * 1000)
 
 static long g_nComObjsInUse;
 HINSTANCE g_hinstDll;
@@ -377,7 +377,6 @@ STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID
SnapshotSetId)
qga/vss-win32/provider.cpp STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID · line 377
Quoted 1 line
qga/vss-win32/provider.cpp +0 -0
     if (WaitForSingleObject(hEventThaw, VSS_TIMEOUT_MSEC) !=
WAIT_OBJECT_0) {
Quoted 9 lines
qga/vss-win32/provider.cpp +0 -2
         /* Send event to qemu-ga to notify the provider is timed out */
         SetEvent(hEventTimeout);
-        hr = E_ABORT;
     }
 
     CloseHandle(hEventThaw);
--
2.9.3

Signature · 4 lines

Respectfully,
*Sameeh Jubran*
*Linkedin <https://il.linkedin.com/pub/sameeh-jubran/87/747/a8a>*
*Software Engineer @ Daynix <http://www.daynix.com>.*

Sameeh Jubran

author

2017-04-02 07:31 UTC #3 lore raw

Ping.

Quoted 130 lines · Sameeh Jubran

Quoted 21 lines · Michael Roth
Quoting Sameeh Jubran (2017-03-21 05:49:52)
Quoted 4 lines
When the command "guest-fsfreeze-freeze" is executed it causes the VSS service to log the errors below in the Event Viewer.
These errors are caused by two issues in the function "CommitSnapshots"
in
Quoted 3 lines
provider.cpp:
1. When VSS_TIMEOUT_MSEC expires the funtion returns E_ABORT. This
causes
Quoted 7 lines
the error #12293.
2. The VSS_TIMEOUT_MSEC value is too big. According to msdn the "Flush & Hold" operation has 10 seconds timeout not configurable, The "CommitSnapshots" is a part of the "Flush & Hold" process and thus any timeout bigger than 10 seconds would cause the error #12298 and anything bigger than 40 seconds causes the error #12340. All this info can be
found here:
Quoted 1 line
https://msdn.microsoft.com/en-us/library/windows/desktop/aa3
84589(v=vs.85).aspx
Quoted 7 lines
Not sure how best to deal with this. Technically our CommitSnapshots interface is driven by the backup job being run by QGA/QEMU management side. If that amount of time exceeds the VSS limits then I think it's appropriate for VSS to log the error accordingly. VSS_TIMEOUT_MSEC here doesn't actually have too much correlation with the VSS-set timeout, IIRC it's specifically picked to exceed both the 10 and 40 second timeouts and acts more as a fail-safe timeout.
The timeout was added in #commit: b39297aedfabe9b2c426cd540413be991500da25 There is no point in setting the TIMEOUT for this long as the actual freeze - Fush and Hold Writes -
is limited to 10 seconds ( not configurable) according to msdn
https://msdn.microsoft.com/en-us/library/windows/
desktop/aa384589%28v=vs.85%29.aspx
Quoted 6 lines
Are the event logs causing issues? FWIW, on the posix side we also opt for gratuitous logging to syslog and such, the idea there being that cooperative guests would prefer transparency on how the agent is being used.
Apparently, these error logs are annoying to some (
https://bugzilla.redhat.com/show_bug.cgi?id=1387125),
moreover I don't think that our implementation to the freeze operation - which is a workaround in a way -
should log errors even though we know they are false alarm.
Quoted 52 lines
That said, I do think error 12293 is unecessary, since IIUC it would always be paired with the actual VSS-reported error. So avoiding the E_ABORT seems reasonable either way.
Quoted 2 lines
|event id| error
|
Quoted 1 line
* 12293 : Volume Shadow Copy Service error: Error calling a routine on
a
Quoted 4 lines
           Shadow Copy Provider {00000000-0000-0000-0000-000000000000}.
       Routine details CommitSnapshots [hr = 0x80004004, Operation
       aborted.
Quoted 8 lines
* 12340 : Volume Shadow Copy Error: VSS waited more than 40 seconds for all volumes to be flushed. This caused volume \\?\Volume{62a171da-32ec-11e4-80b1-806e6f6e6963}\ to timeout while waiting for the release-writes phase of shadow copy creation. Trying again when disk activity is lower may solve this problem.
* 12298 : Volume Shadow Copy Service error: The I/O writes cannot be
held
Quoted 2 lines
during the shadow copy creation period on volume \\?\Volume{62a171d9-32ec-11e4-80b1-806e6f6e6963}\. The
volume
Quoted 26 lines
index in the shadow copy set is 0. Error details:
Open[0x00000000, The operation completed successfully. ], Flush[0x00000000, The operation completed successfully.], Release[0x00000000, The operation completed successfully.], OnRun[0x80042314, The shadow copy provider timed out while holding writes to the volume being shadow copied. This is probably due to excessive activity on the volume by an application or a system service. Try again later when activity on the volume is reduced.
Signed-off-by Sameeh Jubran <[email protected]>
---
 qga/vss-win32/provider.cpp | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)
qga/vss-win32/provider.cpp +1 -1
index ef94669..d72f4d4 100644
@@ -15,7 +15,7 @@
 #include <inc/win2003/vscoordint.h>
 #include <inc/win2003/vsprov.h>
 
-#define VSS_TIMEOUT_MSEC (60*1000)
+#define VSS_TIMEOUT_MSEC (9 * 1000)
 
Quoted 17 lines
qga/vss-win32/provider.cpp STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID
Quoted 3 lines
qga/vss-win32/provider.cpp +0 -0
 static long g_nComObjsInUse;
 HINSTANCE g_hinstDll;
@@ -377,7 +377,6 @@ STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID
SnapshotSetId)
qga/vss-win32/provider.cpp STDMETHODIMP CQGAVssProvider::CommitSnapshots(VSS_ID · line 377
Quoted 1 line
qga/vss-win32/provider.cpp +0 -0
     if (WaitForSingleObject(hEventThaw, VSS_TIMEOUT_MSEC) !=
WAIT_OBJECT_0) {
Quoted 9 lines
qga/vss-win32/provider.cpp +0 -2
         /* Send event to qemu-ga to notify the provider is timed out */
         SetEvent(hEventTimeout);
-        hr = E_ABORT;
     }
 
     CloseHandle(hEventThaw);
--
2.9.3
--
Respectfully,
*Sameeh Jubran*
*Linkedin <https://il.linkedin.com/pub/sameeh-jubran/87/747/a8a>*
*Software Engineer @ Daynix <http://www.daynix.com>.*

Signature · 4 lines

Respectfully,
*Sameeh Jubran*
*Linkedin <https://il.linkedin.com/pub/sameeh-jubran/87/747/a8a>*
*Software Engineer @ Daynix <http://www.daynix.com>.*

Michael Roth

2017-04-05 00:13 UTC #4 lore raw

In reply to Sameeh Jubran

Quoting Sameeh Jubran (2017-03-22 03:14:53)

Quoted 37 lines

Quoted 24 lines · Michael Roth
Quoting Sameeh Jubran (2017-03-21 05:49:52)
Quoted 5 lines
When the command "guest-fsfreeze-freeze" is executed it causes the VSS service to log the errors below in the Event Viewer.
These errors are caused by two issues in the function "CommitSnapshots"
in
Quoted 6 lines
provider.cpp:
1. When VSS_TIMEOUT_MSEC expires the funtion returns E_ABORT. This causes
the error #12293.
Quoted 7 lines
2. The VSS_TIMEOUT_MSEC value is too big. According to msdn the "Flush & Hold" operation has 10 seconds timeout not configurable, The "CommitSnapshots" is a part of the "Flush & Hold" process and thus any
timeout bigger than 10 seconds would cause the error #12298 and anything
bigger than 40 seconds causes the error #12340. All this info can be
found here:
Quoted 1 line
https://msdn.microsoft.com/en-us/library/windows/desktop/
aa384589(v=vs.85).aspx
Quoted 8 lines
Not sure how best to deal with this. Technically our CommitSnapshots interface is driven by the backup job being run by QGA/QEMU management side. If that amount of time exceeds the VSS limits then I think it's appropriate for VSS to log the error accordingly. VSS_TIMEOUT_MSEC here
doesn't actually have too much correlation with the VSS-set timeout, IIRC it's specifically picked to exceed both the 10 and 40 second timeouts and acts more as a fail-safe timeout.

Quoted 7 lines

The timeout was added in #commit:
b39297aedfabe9b2c426cd540413be991500da25
There is no point in setting the TIMEOUT for this long as the actual freeze
- Fush and Hold Writes -
is limited to 10 seconds ( not configurable) according to msdn
https://msdn.microsoft.com/en-us/library/windows/desktop/aa384589%28v=vs.85%29.aspx

The reason it's set that long is because the VSS service is perfectly capable of telling us exactly when it has timed out. I think racing with it because we don't like how it chooses to log errors is an ugly approach, and in the process of doing that we lose an extra second of time that management might have been able to make use of to complete the snapshot successfully. 10s is already small as is, losing 10% of that to avoid Event Log messages seems like a poor trade-off.

Quoted 9 lines

Quoted 7 lines
Are the event logs causing issues? FWIW, on the posix side we also opt for gratuitous logging to syslog and such, the idea there being that cooperative guests would prefer transparency on how the agent is being used.
Apparently, these error logs are annoying to some (
https://bugzilla.redhat.com/show_bug.cgi?id=1387125),

It seems more like users were complaining about a different event log error dealing with permissions issues. I don't really see anyone concerned with the timeout errors once it was apparent how they factored into the overall snapshot operation.

Quoted 3 lines

moreover I don't think that our implementation to the freeze operation - which is a workaround in a way -
should log errors even though we know they are false alarm.

These aren't really false alarms. I think there's a good reason the VSS service was designed to log failures to hold writes in the event log, and we primarily use it for the same reason those errors would be
relevant: creating reliable snapshots.

Users who don't care about the errors can use the filtering facilities built into the event log viewer. Users who do care probably feel a bit more strongly about keeping that information logged.

Quoted 72 lines

Quoted 72 lines
That said, I do think error 12293 is unecessary, since IIUC it would always be paired with the actual VSS-reported error. So avoiding the E_ABORT seems reasonable either way.
Quoted 2 lines
|event id| error
|
Quoted 15 lines
* 12293 : Volume Shadow Copy Service error: Error calling a routine on a
           Shadow Copy Provider
           {00000000-0000-0000-0000-000000000000}.
       Routine details CommitSnapshots [hr = 0x80004004, Operation
       aborted.
* 12340 : Volume Shadow Copy Error: VSS waited more than 40 seconds for
all volumes to be flushed. This caused volume
\\?\Volume{62a171da-32ec-11e4-80b1-806e6f6e6963}\ to timeout while waiting for the release-writes phase of shadow copy creation. Trying again when disk activity is lower may solve this problem.
Quoted 1 line
* 12298 : Volume Shadow Copy Service error: The I/O writes cannot be
held
Quoted 32 lines
during the shadow copy creation period on volume \\?\Volume{62a171d9-32ec-11e4-80b1-806e6f6e6963}\. The volume
index in the shadow copy set is 0. Error details:
Open[0x00000000, The operation completed successfully. ], Flush[0x00000000, The operation completed successfully.], Release[0x00000000, The operation completed successfully.], OnRun[0x80042314, The shadow copy provider timed out while holding writes to the volume being shadow copied. This is probably due to excessive activity on the volume by an application or a system service. Try again later when activity on the volume is reduced.
Signed-off-by Sameeh Jubran <[email protected]>
---
 qga/vss-win32/provider.cpp | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)
qga/vss-win32/provider.cpp +1 -1
index ef94669..d72f4d4 100644
@@ -15,7 +15,7 @@
 #include <inc/win2003/vscoordint.h>
 #include <inc/win2003/vsprov.h>
 
-#define VSS_TIMEOUT_MSEC (60*1000)
+#define VSS_TIMEOUT_MSEC (9 * 1000)
 
 static long g_nComObjsInUse;
 HINSTANCE g_hinstDll;
@@ -377,7 +377,6 @@ STDMETHODIMP
Quoted 1 line
CQGAVssProvider::CommitSnapshots(VSS_ID
SnapshotSetId)
Quoted 1 line
     if (WaitForSingleObject(hEventThaw, VSS_TIMEOUT_MSEC) !=
WAIT_OBJECT_0) {
Quoted 10 lines
         /* Send event to qemu-ga to notify the provider is timed out
         */
         SetEvent(hEventTimeout);
-        hr = E_ABORT;
     }

     CloseHandle(hEventThaw);
--
2.9.3