Random client disconnect issues (comes from VSS)

deajan commented 6 years ago

Hello,

I have multiple burp servers, and often encounter the same issue between them.

Clients connect and suddently get disconnected after a couple of seconds in phase 1.

Client log (server side)

0000205 2018-08-27 14:32:02 +0200

Last 1000 lines of /storage/burp-protocol1/some.pro.local/working/log:

2018-08-27 14:32:02 +0200: burp[17996] Client version: 2.2.4
2018-08-27 14:32:02 +0200: burp[17996] Protocol: 1
2018-08-27 14:32:02 +0200: burp[17996] Client is Windows
2018-08-27 14:32:02 +0200: burp[17996] Begin phase1 (file system scan)
2018-08-27 14:32:05 +0200: burp[17996] main socket 4: Peer closed SSL session
2018-08-27 14:32:05 +0200: burp[17996] error in async_read
2018-08-27 14:32:05 +0200: burp[17996] error in phase 1

burp server logs

Aug 27 14:32:02 storagemaster burp[17996]: Logging to /storage/burp-protocol1/some.pro.local/0000205 2018-08-27 14:32:02 +0200/log
Aug 27 14:32:05 storagemaster burp[17996]: main socket 4: network write problem in asfd_do_write_ssl: 1 - 0=Success
Aug 27 14:32:05 storagemaster journal: 139921596196784:error:140D00CF:SSL routines:SSL_write:protocol is shutdown:ssl_lib.c:1052:
Aug 27 14:32:05 storagemaster burp[17996]: This is probably caused by the peer exiting.
Aug 27 14:32:05 storagemaster burp[17996]: Please check the peer's logs.
Aug 27 14:32:05 storagemaster burp[17996]: MESSAGE: Running notify script: sophie.pro.local /storage/burp-protocol1/sophie.pro.local /storage/burp-protocol1/some.pro.local/current log backup 0 sendmail -t To: me@mydomain.tld From: STM burp Subject: %b failed: %c %w Content-Type: text/plain; charset=utf-8
Aug 27 14:32:05 storagemaster burp[17996]: main socket 4: network write problem in asfd_do_write_ssl: 1 - 0=Success
Aug 27 14:32:05 storagemaster journal: 139921596196784:error:140D00CF:SSL routines:SSL_write:protocol is shutdown:ssl_lib.c:1052:
Aug 27 14:32:05 storagemaster burp[17996]: This is probably caused by the peer exiting.
Aug 27 14:32:05 storagemaster burp[17996]: Please check the peer's logs.
Aug 27 14:32:05 storagemaster burp[17996]: MESSAGE:
Aug 27 14:32:05 storagemaster burp[17996]: /usr/share/burp/scripts/notify_script returned: 0
Aug 27 14:32:05 storagemaster burp[17996]: main socket 4: Peer closed SSL session
Aug 27 14:32:05 storagemaster burp[17996]: exit child

This happens regardless of protocol 1 or 2 usage. It also happens randomly with all my burp servers. I use different firewall brands depending on my servers, and I also have a home server behind a consumer grade router, which happens to have the same issue.

The only things I can think of which are identical are:

All my servers run CentOS 7 x64 (with different burp server versions, but always 2.2.x builds)
All of the clients that happen to have that problem are laptops

Now sure some could say that laptops can have connection issues, but this happens way to often, with phase 1 being shut down after only a couple of seconds, with different laptops on different locations.

I'm a bit clueless of what tests to perform in order to find the culprit of that issue. Any ideas ?

Best regards.

grke commented 6 years ago

Have you been with one of the laptops when this has happened? Are the laptops going into sleep/suspend mode?

deajan commented 6 years ago

Thanks for your anwer. No, those are not my laptops, I'm usually not around them (mine works fine btw...) What I know is that it happens right after a friend powers on her laptop, which is not set to sleep mode, and has a stable wifi connection.

Is there a way to get debug logs from the client ? I might then have a script that launches burp along with a ping to let's say Google in order to make sure internet works while backing up.

I asked this on github because I thought maybe someone had encountered some similar issue. Someone ?

pablodav commented 6 years ago

I don't use burp 2.2 yet, just migrating now to 2.1.32.

I think it's good idea to have it on github, as is easier to collaborate, at least for me it is easier and I'm try to follow up every issue and change (not possible to answer all of them, sometimes because spare time is not enough, sometimes I just don't have enough technical skill to add an answer).

Checking on my client error logs ( I receive for every client that fails), most of the errors I see are:

2018-08-28 07:57:12: burp[22522] Client version: 2.0.54
2018-08-28 07:57:12: burp[22522] Protocol: 1
2018-08-28 07:57:12: burp[22522] Client is Windows
2018-08-28 07:57:12: burp[22522] Begin phase1 (file system scan)
2018-08-28 07:58:20: burp[22522] End phase1 (file system scan)
2018-08-28 07:58:20: burp[22522] Begin phase2 (receive file data)
2018-08-28 08:37:56: burp[22522] main socket: no activity for 1200 seconds.
2018-08-28 08:37:56: burp[22522] error in do_stuff_to_receive
2018-08-28 08:37:59: burp[22522] End phase2 (receive file data)
2018-08-28 08:37:59: burp[22522] error in backup phase 2

Some of them:

2018-08-28 05:40:51: burp[18794] Client version: 2.0.54
2018-08-28 05:40:51: burp[18794] Protocol: 1
2018-08-28 05:40:51: burp[18794] Client is Windows
2018-08-28 05:40:51: burp[18794] Begin phase1 (file system scan)
2018-08-28 06:02:08: burp[18794] main socket: no activity for 1200 seconds.
2018-08-28 06:02:08: burp[18794] error in async_read
2018-08-28 06:02:08: burp[18794] error in phase 1

And others just connection reset by peer:

2018-08-27 16:43:16: burp[8227] Client version: 2.0.54
2018-08-27 16:43:16: burp[8227] Protocol: 1
2018-08-27 16:43:16: burp[8227] Client is Windows
2018-08-27 16:43:16: burp[8227] Begin phase1 (file system scan)
2018-08-27 16:56:24: burp[8227] main socket: Got SSL_ERROR_SYSCALL
2018-08-27 16:56:24: burp[8227] main socket: SSL read problem in asfd_do_read_ssl: 5 - 104=Connection reset by peer
2018-08-27 16:56:24: burp[8227] error in async_read
2018-08-27 16:56:24: burp[8227] error in phase 1

Also connection reset by peer in phase2.

I'm have not made any effort to diagnose it before, but thinking in possibilities:

I'm could try something in this way:

Start pre-script that just starts pinging the server (in a independent process, so it will be pinging also while backup is running) and saves result to some logfile.

Have post-script that in case the backup fails, also gets more data like:

output for: netsh wlan show interfaces
output for Netsh WLAN show WLANreport
some eventlog information
netsh wlan show drivers
any other more useful log
Stop the ping process openned before, and attach log
send all them by email. (You will need some smtp in your network here, or just add to some other place)

I have some useful powershell scripts with more commands and could start writing some kind of thing like this, I think it could help.

Windows laptops use to have problems with wireless, and is normal to have such kind of disconnections, you must have drivers up to date to avoid such kind of disconnections. Also APs should be properly setup to avoid slow speeds enabled (like less than 5mbps). Signal is important also when talking about wifi. Laptops in windows have set by default possible to reduce power consumption, it also affects connectivity on wifi so it's good to disable the option to allow windows to reduce power.

Ofrouce this shouldn't be enabled on every laptop, only on few of them to help get some diagnostics info.

pablodav commented 6 years ago

Also in your case, as you have it on phase1 we should add more logs from other sides, like:

See if there is some disk power saving activated
See if there is any VSS issue
Get logs from antivirus used, to see if it is affecting phase1

I think phase1 could be affected by those kind of things because it is all about scanning the filesystem.

deajan commented 6 years ago

@pablodav thanks, this gives me some hints where I didn't search yet. I think I'll first go with wireless power on the laptop.

I'll have

powercfg /SETDCVALUEINDEX SCHEME_CURRENT 19cbb8fa-5279-450e-9fac-8a3d5fedd0c1 12bbebe6-58d6-4636-95bb-3217ef867c1a 0

powercfg /SETACVALUEINDEX SCHEME_CURRENT 19cbb8fa-5279-450e-9fac-8a3d5fedd0c1 12bbebe6-58d6-4636-95bb-3217ef867c1a 0

Which sets maximal performance on the wireless adapters on battery and plugged-in (works on Win7 & Win10).

If this fails, I'll try to make a burp wrapper script in order to diagnose what could be the issue. Actually I'm quite sure that it's not AP related, it usually happens when the laptop gets powered on (maybe when resuming from sleep mode, must ask my friend). Also, my laptop does never trigger that issue, on the same AP. We have the same OS (win10 x64) and share the same burp server too.

If I happen to resolve that issue on her computer, I might get a chance to resolve the issue on my customer base.

Anyway, thanks alot for your time,

Oh, I just thought when reading your logs, I've set my network_timeout value to 300 seconds instead of the default. I can also try to set it back to defaults, even if I couldn't imagine a scenario where this would have any interference.

pablodav commented 6 years ago

Good command, But I have some doubt about how windows will use that settings, I was thinking in something that prevents windows from trying to manage power to save power, like this:

https://www.ingmarverheij.com/disable-allow-computer-turn-device-save-power-wifi-adapters/

Also using 5Ghz band as prefered band, sometimes helps, but it is better to ensure wifi drivers are up to date. (I have script to set 5GHz band prefered too, if needed).

pablodav commented 6 years ago

@deajan Could you attach the logs from client side too?

I have noticed in our environment it was wrong binary installation in some cases, so in client log got it:

2018-08-31 11:06:13: C:\Program Files\burp\bin\burp.exe[4532] VSS was not initialized properly.
2018-08-31 11:06:13: C:\Program Files\burp\bin\burp.exe[4532] VSS support is disabled. ERR=The operation completed successfully.

But in client config we had wrong line for 64 bit system.

It should be

autoupgrade_os = win64

But someone copy & pasted win32 on it, so it was an error during upgrade and had to change this line and reinstall client with 64bit version.

@grke Do you think it is viable to have a feature to send the client log and keep it on server side? like have client_log file in server? (it is not really necessary, but if it is something easy to do could be good to have such feature).

grke commented 6 years ago

Hello, I think it is possible, but the client would need to write it to a file to save it too. That is viable, but not something that happens right now. If the client is disconnecting though, it doesn't do you any good.

deajan commented 6 years ago

@pablodav Well it's not power scheme related, I set the laptop to use full power, and not stop wifi device for power saving. Still happens. I'll have to write that script that pings, and catches the output of burp client in order to diagnose whatever happens there. Also, it does not have to do with VSS, since manually run burp always works.

pablodav commented 6 years ago

Interesting, I will try to get some information from my clients too. (For now I suspect only on some disconnects).

deajan commented 6 years ago

Ok, made a quite dirty debug script that is now installed my friend's laptop. You may find the script gist here https://gist.github.com/deajan/06ab233c528421d7ff74ce128cc7326c In order to work, it needs mailsend.exe from https://github.com/muquit/mailsend/releases/ (rename the current one to mailsend.exe in burp\bin directory). The script itself drops into the burp\bin directory too, and the scheduled task needs to run the burpdiag.cmd without any arguments.

The script creates two ping instances (one to google.com, one to the burp server), and collects the burp client logs. It also generates output from @pablodav netsh commands, along with netstat routes and all events that happened during execution.

I'll report back if this happens to catch something fishy.

deajan commented 6 years ago

Btw, thinking of some ugly antivirus that could try to analyze https traffic... Maybe ?

deajan commented 6 years ago

Well well well.... Got the client logs from a failed run and the winner is rolling drums.... VSS (sh*t, I thought this one was outruled) !

Server log from client:

2018-09-06 10:12:05 +0200: burp[20444] Client version: 2.2.4
2018-09-06 10:12:05 +0200: burp[20444] Protocol: 1
2018-09-06 10:12:05 +0200: burp[20444] Client is Windows
2018-09-06 10:12:05 +0200: burp[20444] Begin phase1 (file system scan)
2018-09-06 10:12:07 +0200: burp[20444] main socket 4: Peer closed SSL session
2018-09-06 10:12:07 +0200: burp[20444] error in async_read
2018-09-06 10:12:07 +0200: burp[20444] error in phase 1

Client log:

2018/09/06 - 10:12:01 Beginning new run 
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] Connecting to myburpserver:4971
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] auth ok
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] Server version: 2.2.4
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] nocsr ok
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] SSL is using cipher: DHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=DH       Au=RSA  Enc=AESGCM(256) Mac=AEAD

2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] extra_comms_begin ok:autoupgrade:incexc:orig_client:uname:sincexc:counters_json:msg:forceproto=1:
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] Server is setting includes/excludes.
2018-09-06 10:12:05: C:\Program Files\Burp\bin\burp.exe[2204] Client accepts.
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] Server is forcing protocol 1
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] Server is overriding the configuration
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] with the following settings:
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/SomeFolder
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/Users/Sophie/AppData/Local/Microsoft/Outlook
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/Users/SomeUser/Desktop
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/Users/SomeUser/Documents
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/Users/SomeUser/Downloads
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/Users/SomeUser/Pictures
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] include = C:/Users/SomeUser/Videos
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] nobackup = .nobackup
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_ext = tmp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = C:/Windows/Downloaded Program Files
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = C:/Windows/SoftwareDistribution/Download
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = C:/Windows/Temp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/$WINDOWS.~BT
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/*/Config.Msi
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/*/MSOCache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/*Thumbs.db
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Documents and Settings/[^/]+/Cookies
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Documents and Settings/[^/]+/Local Settings/Temp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Documents and Settings/[^/]+/Recent
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/RECYCLER
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/System Volume Information
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Application Data
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Google/Chrome/User Data/Default/Cache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/History
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Microsoft/Internet Explorer
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Microsoft/Windows/AppCache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Microsoft/Windows/InetCache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Microsoft/Windows/Temporary Internet Files
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Microsoft/Windows/WER
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Microsoft/Windows/WebCache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Mozilla/Firefox/Profiles/[^/]+/Cache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Opera/Opera/profile/cache4
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Opera Software/Opera Stable/Cache
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Temp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Temp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Local/Temporary Internet Files
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/AppData/Roaming/Microsoft/Windows/Cookies
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/Cookies
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/LocalService
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/NetHood
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/NetworkService
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/PrintHood
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/Recent
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Users/[^/]+/SendTo
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/Windows.old$
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/pagefile.sys
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = [A-Z]:/swapfile.sys
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = \.DS_Store
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = ^[A-Z]:/\$recycle\.bin$
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_regex = ^[A-Z]:/hiberfil\.sys$
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = 264
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = 3gp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = 7z
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = aac
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = aac
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = ac3
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = ace
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = apk
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = arc
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = asf
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = avchd
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = avi
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = bz
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = bz2
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = cab
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = cdda
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = cdr
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = divx
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = dmg
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = dv4
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = f4v
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = flac
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = flv
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = gif
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = gz
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = h263
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = h264
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = jar
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = jpeg
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = jpg
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = kgb
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = lha
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = lz
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = lzh
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = lzma
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = lzo
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = lzx
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mjpeg
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mkf
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mkv
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mov
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = movie
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mp3
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mp4
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mpeg
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mpeg4
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mpg3
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mpga
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = mpgv
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = ogg
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = pak
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = png
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = qt
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = rar
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = rz
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = sfx
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = tgz
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = tif
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = tiff
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = video
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = webp
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = wma
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = wmv
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = wmv3
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = xvid
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = xz
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] exclude_comp = zip
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] cross_all_filesystems = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] read_all_fifos = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] read_all_blockdevs = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] min_file_size = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] max_file_size = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] split_vss = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] strip_vss = 1
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] acl = 1
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] xattr = 1
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] atime = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] scan_problem_raises_error = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] overwrite = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] strip = 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] Compression level: 0
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] do backup client
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] Using librsync hash md4
2018-09-06 10:12:06: C:\Program Files\Burp\bin\burp.exe[2204] Control handler registered.
Generate VSS snapshots.
Driver="VSS Vista", Drive(s)="C"
2018-09-06 10:12:08: C:\Program Files\Burp\bin\burp.exe[2204] Generate VSS snapshots failed.

Now the odd part is that the is no event logs in system and application logs. The same job ran 20 minutes later, with success

2018/09/06 - 10:32:01 Beginning new run 
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] Connecting to myburpserver:4971
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] auth ok
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] Server version: 2.2.4
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] nocsr ok
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] SSL is using cipher: DHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=DH       Au=RSA  Enc=AESGCM(256) Mac=AEAD

2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] extra_comms_begin ok:autoupgrade:incexc:orig_client:uname:sincexc:counters_json:msg:forceproto=1:
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] Server is setting includes/excludes.
2018-09-06 10:32:02: C:\Program Files\Burp\bin\burp.exe[8236] Client accepts.
2018-09-06 10:32:03: C:\Program Files\Burp\bin\burp.exe[8236] Server is forcing protocol 1
2018-09-06 10:32:03: C:\Program Files\Burp\bin\burp.exe[8236] Server is overriding the configuration
2018-09-06 10:32:03: C:\Program Files\Burp\bin\burp.exe[8236] with the following settings:
[...]
2018-09-06 10:32:03: C:\Program Files\Burp\bin\burp.exe[8236] do backup client
2018-09-06 10:32:03: C:\Program Files\Burp\bin\burp.exe[8236] Using librsync hash md4
2018-09-06 10:32:03: C:\Program Files\Burp\bin\burp.exe[8236] Control handler registered.
Generate VSS snapshots.
Driver="VSS Vista", Drive(s)="C"
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS drive letters: 0
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "Task Scheduler Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "VSS Metadata Store Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "Performance Counters Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "System Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "Shadow Copy Optimization Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "ASR Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "Registry Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "COM+ REGDB Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "WMI Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "MSMQ Writer (MSMQ)", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "MSSearch Service Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (PrepareForBackup): "IIS Config Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] Set thread_mode_background_begin
2018-09-06 10:32:34: C:\Program Files\Burp\bin\burp.exe[8236] Phase 1 begin (file system scan)

dffddfffffffffddffffdfffffffffffffffffffffffffffffffffffffffffff 64
[...]
ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff 93952
ffffffffdf 93962

2018-09-06 10:33:30: C:\Program Files\Burp\bin\burp.exe[8236] Phase 1 end (file system scan)
2018-09-06 10:33:30: C:\Program Files\Burp\bin\burp.exe[8236] Phase 2 begin (send backup data)

zzzfzffffffffffffffffzfzfzzfzfffffffffffffffffffffffffffzfffzzff 64
fffffff 71

--------------------------------------------------------------------------------
Start time: 2018-09-06 10:32:02
  End time: 2018-09-06 10:39:27
Time taken: 07:25
                         New   Changed Duplicate   Deleted     Total |  Scanned
                   ------------------------------------------------------------
             Files:       59        12         0         0        71 |    83808
       Directories:        0         0         0         0         0 |    10154
       Grand total:       71        12         0         0        83 |    93962
                   ------------------------------------------------------------

             Messages:             0
             Warnings:             0

      Bytes estimated:   107448695941 (100.07 GB)
      Bytes in backup:   16914442456 (15.75 GB)
       Bytes received:       5334689 (5.09 MB)
           Bytes sent:      58509370 (55.80 MB)
--------------------------------------------------------------------------------
2018-09-06 10:39:27: C:\Program Files\Burp\bin\burp.exe[8236] Phase 2 end (send file data)
2018-09-06 10:39:27: C:\Program Files\Burp\bin\burp.exe[8236] Set thread_mode_background_end
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "Task Scheduler Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "VSS Metadata Store Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "Performance Counters Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "System Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "Shadow Copy Optimization Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "ASR Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "MSMQ Writer (MSMQ)", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "WMI Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "COM+ REGDB Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "Registry Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "MSSearch Service Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] VSS Writer (BackupComplete): "IIS Config Writer", State: 0x1 (VSS_WS_STABLE)
2018-09-06 10:39:30: C:\Program Files\Burp\bin\burp.exe[8236] backup finished ok

The computer I've pulled the logs from is a i5 with an SSD (no problems or defect sectors shown with smart), the filesystem is clean (chkdsk shows no problem). I've looked at the event logs, nothing happens at 10:12:xx. The best event I have in application log at 10:12:20 (seconds after burp fails to initialize VSS):

Volume ?? (\Device\HarddiskVolumeShadowCopy63) est sain. Aucune action n’est nécessaire

I happen to have the exact same application log at 10:32:20 (when second burp attempt works).

Additionnal info:

C:\WINDOWS\system32>vssadmin list providers
vssadmin 1.1 - Outil ligne de commande d’administration du service de cliché instantané de volume
(C) Copyright 2001-2013 Microsoft Corp.

Fournisseur : 'Microsoft Software Shadow Copy provider 1.0'
   Type de fournisseur : Système
   ID du fournisseur : {b5946137-7b9f-4925-af80-51abd60b20d5}
   Version : 1.0.0.7

vssadmin list writers shows no writers with errors. wmic shadowcopy does not show any subsisting old snapshot.

@grke I can't guess what happens here, but I know multiple clients (different hardware, location,etc) have that issue. Looking at the VSS source, I see that the CreateSnapshot function does not return an error number, but maybe the function VSSClientGeneric::CheckWriterStatus() could return a VSS state in order to know what actually happened.

Any other people experiencing intermittent VSS troubles ?

pablodav commented 6 years ago

Very interesting issue.

I haven't noticed such error yet, but I'm checking client's log from time to time accessing directly to \client\c$ so don't really need the script now.

I couldn't get into https://gist.github.com/deajan/ec576f67a706f911d3dd60c41828dfa4, it just doesn't exist.

With powershell you don't need mailsend.exe.

I haven't noticed the issue in our environment, but there is something special done in our environment that maybe does a "workaround" without knowing it?

On every post backup, I do some things with burp_eclient script, like checking client's log and also creating a vss_snapshot on disk, but before that I resize the vss shadow storage available size for snapshots:

https://github.com/pablodav/burp_eclient/blob/master/SupportFiles/scripts/burp_clientconfig3.ps1#L237

vssadmin resize shadowstorage /For=C: /On=C: /MaxSize=6%

So it could be related to the fact I don't have this issue?

I do the local snapshot, just to let the clients have direct restore on disk. (right click, restore previous version on explorer)

pablodav commented 6 years ago

There are some interesting comments about VSS in this post:

https://blog.storagecraft.com/looking-common-vss-myths/

Myth: VSS commonly produces failures: If you’ve ever used VSS before, you’re probably familiar with the dreaded “Backup aborted! – Failed to Create Volume Snapshot …” error. This error and others pop up all too frequently and have a wide range of causes.

The real story: There are specific rules that govern activity within the OS. This is why it is called an “operating system”. When an event occurs outside the bounds of those rules then an error is thrown. Typically an error like the one described above refers to a situation where VSS was not able to successfully create a snapshot. Without knowing the specific cause of this error, users are left guessing about valid reasons why this error would occur.

The reason for this type of error varies, though typically they have to do with conflicts between one or more installed software. For example, an anti-virus software that stops OS activity while checking files for virus patterns may require a priority level access over other applications within the operating system. This affects backup systems which leverage VSS and are bound to complete processes within the given time limits. Basically, VSS will only work with one process at a time so if two processes are requesting VSS services one of the processes will probably have problems. When conflicts like this are discovered, most software vendors will work to patch/fix their application to work with other applications.

Not sure if anti-virus could be your case, but it is good to check logs from antivirus too, or change it to another one just to test?

deajan commented 6 years ago

@pablodav Hmmm... Try https://gist.github.com/deajan/06ab233c528421d7ff74ce128cc7326c as I stated above (updated the gist, but should not change the link) Made the script powershell independant in order to run ony any system :)

As for the VSS, multiple machines that happen to have the same issues don't share the same antivirus. Also, I have no known program that could use VSS on my friend's computer (no other backup software, no previous versions). What bothers me here is that I've read the burp vss code, it seems to have a 10 min timeout, but burp fails on VSS after only 2 seconds so the API just returns an error at that time. Though I can't diagnose this since I don't have any eventlogs about VSS or even other os operations at that time.

I might add some more output to my debug script like: vssadmin list writers vssadmin list providers wmic shadowcopy

just to see what happens with VSS before burp runs.

deajan commented 6 years ago

@grke: Do you think that the client could send the error to the server before exiting ? Headache saver :)

grke commented 6 years ago

Yes, very good idea. That code is using 'printf' instead of burp's normal 'logp' or 'loge', probably because it was stuff originally from bacula.

grke commented 6 years ago

There is a change in master now to do that, and will be in the next release.

deajan commented 6 years ago

Wow, thanks alot ! I also thought that maybe there could be a way to get the actual error behind "Generate VSS Failure". I tried something here https://github.com/deajan/burp/commit/b947cb4400706bf76ad2dddc5dd86b32ba77c681 but my C isn't really fluent. Could this work ? I've seen that CreateSnapshot fills errno, but I am using berrno to try to recover the error.

grke commented 6 years ago

Hello, I have always been a bit confused about how berrno works, as it comes from bacula. It looks like it could work. To be sure, we would need to test it. I could try plugging your patch into my build system and then I can send you the resultant windows installers?

grke commented 6 years ago

^ The GetWriterInfo(i) and GetWriterState(i) bits don't make sense, because that bit of code is not iterating over writers and 'i' is not defined. The berrno bit looks OK though.

grke commented 6 years ago

It is a mistake that the existing GetWriterState(i) section doesn't log anything if < 1 though, I will add a log message there.

deajan commented 6 years ago

Of course you can send me the resultant installer, I can also build it myself if needed.

grke commented 6 years ago

Try this: https://burp.grke.org/downloads/test/burp-win64-installer-2.2.11.exe

deajan commented 6 years ago

Well, the specific version is installed, but as of today the client computers don't reproduce the VSS error for whatever reason. I'll keep the 2.2.11 version on my friend's computer for another two weeks, hoping to see the error again.

deajan commented 6 years ago

In the meantime I could try 2.2.12 on my own laptop, trying to backup a non VSS-able drive, and can confirm that I get the VSS error written to the client log on the server. I still keep the 2.2.11 running on my friend's computer to diagnose whatever happens there with the VSS.

deajan commented 6 years ago

Seems to work like it should:

0000234 2018-11-07 22:52:02 +0100

Last 1000 lines of /storage/burp-protocol2/global/clients/someclient.pro.local/working/log:

2018-11-07 22:52:02 +0100: burp[16049] Backup started
2018-11-07 22:52:02 +0100: burp[16049] Client version: 2.2.12
2018-11-07 22:52:02 +0100: burp[16049] Protocol: 2
2018-11-07 22:52:02 +0100: burp[16049] Client is Windows
2018-11-07 22:52:02 +0100: burp[16049] Begin phase1 (file system scan)
2018-11-07 22:56:36 +0100: burp[16049] End phase1 (file system scan)
2018-11-07 22:56:36 +0100: burp[16049] forked champ chooser pid 21510
2018-11-07 22:56:39 +0100: burp[16049] Connected to champ chooser.
2018-11-07 22:56:39 +0100: burp[16049] Phase 2 begin (recv backup data)
2018-11-07 23:02:39 +0100: burp[16049] main socket 4: no activity for 180 seconds.
2018-11-07 23:02:39 +0100: burp[16049] error from as->read_write in do_backup_phase2_server_protocol2
2018-11-07 23:02:39 +0100: burp[16049]   last tried file: f:0014:C:/some/archive.pst
2018-11-07 23:02:39 +0100: burp[16049] End backup
2018-11-07 23:02:39 +0100: burp[16049] error in backup phase 2
2018-11-07 23:02:39 +0100: burp[16049] Backup failed
2018-11-08 09:52:02 +0100: burp[2695] Found interrupted backup.
2018-11-08 09:52:02 +0100: burp[2695] Will resume on the next backup request.
2018-11-08 09:52:02 +0100: burp[2695] Backup resumed
2018-11-08 09:52:02 +0100: burp[2695] Client version: 2.2.12
2018-11-08 09:52:02 +0100: burp[2695] Protocol: 2
2018-11-08 09:52:02 +0100: burp[2695] Client is Windows
2018-11-08 09:52:02 +0100: burp[2695] forked champ chooser pid 2724
2018-11-08 09:52:05 +0100: burp[2695] Connected to champ chooser.
2018-11-08 09:52:05 +0100: burp[2695] Phase 2 begin (recv backup data)
2018-11-08 09:52:06 +0100: burp[2695] Begin phase1 (read previous file system scan)
2018-11-08 09:52:06 +0100: burp[2695] Setting up resume positions...
2018-11-08 09:52:07 +0100: burp[2695]   last good entry:    f:0008:C:/some
2018-11-08 09:52:18 +0100: burp[2695] End phase1 (read previous file system scan)
2018-11-08 09:54:04 +0100: burp[2695] WARNING: Generate VSS snapshots failed.
2018-11-08 09:54:04 +0100: burp[2695] unexpected command in deal_with_read(): e:0011:Problem with VSS

2018-11-08 09:54:04 +0100: burp[2695]   last tried file: f:0014:C:/some/archive.pst
2018-11-08 09:54:04 +0100: burp[2695] End backup
2018-11-08 09:54:05 +0100: burp[2695] error in backup phase 2

pablodav commented 6 years ago

great! amazing.

What is not clear for me: why this error with VSS snapshot happens in this case?

deajan commented 6 years ago

VSS is some kind of hellbound mystery. There are no errors in the event log when this happens, so there is no easy diag. I have to reboot the computer in order for VSS to work again, event if it's a Win10 laptop with no other software using VSS except of Windows itself.

grke commented 6 years ago

OK, I will merge those changes into the next release. Thanks for testing!

deajan commented 5 years ago

Just in case someone will find this issue someday with the same problem. I've found that on a computer where burp regulary fails with VSS, there's the Windows Backup service failing in the eventlogs, and this even when NO backup schedule is set ! I've ended up disabling the service with sc config sdrsvc start= Disabled

grke commented 5 years ago

There's more logging for VSS in master. I think this issue can be closed now.

deajan commented 5 years ago

To be perfectly honest, more VSS logging didn't improve to a point where it's usable for me, but at least I know it's VSS related :)

2019-02-21 10:31:59 +0100: burp[15119] Backup started
2019-02-21 10:31:59 +0100: burp[15119] Client version: 2.3.0
2019-02-21 10:31:59 +0100: burp[15119] Protocol: 2
2019-02-21 10:31:59 +0100: burp[15119] Client is Windows
2019-02-21 10:31:59 +0100: burp[15119] Begin phase1 (file system scan)
2019-02-21 10:32:03 +0100: burp[15119] WARNING: Generate VSS snapshots failed.ERR=Lopration a russi.
2019-02-21 10:32:03 +0100: burp[15119] got error: Problem with VSS

2019-02-21 10:32:03 +0100: burp[15119] error in phase 1
2019-02-21 10:32:03 +0100: burp[15119] Backup failed

But I guess that's not on burp, since the warning litteraly says "Failure: operation succeed".

pierre-guillot commented 4 years ago

For information, Burp client on Windows Server 2016 (burp client version 2.2.18). I have the same problem :

2020-01-07 18:00:02 +0100: burp[1999] Client version: 2.2.18
2020-01-07 18:00:02 +0100: burp[1999] Protocol: 1
2020-01-07 18:00:02 +0100: burp[1999] Client is Windows
2020-01-07 18:00:02 +0100: burp[1999] Begin phase1 (file system scan)
2020-01-07 18:00:03 +0100: burp[1999] WARNING: Generate VSS snapshots failed.ERR=L�op�ration a r�ussi.
2020-01-07 18:00:03 +0100: burp[1999] got error: Problem with VSS
2020-01-07 18:00:03 +0100: burp[1999] error in phase 1

Initialy, the problem was on many scheduled tasks at the same time. Then I decide to uninstall Windows Backup Service (because @deajan said that resolve his problem), and the problem disapered. But sometime, one taks can be stucked. If you look on the server with burp -a s, the task with the problem is show has "ok", but on the backup folder, you can see 2 folder : "current" and "working".

Do you want I install the last version for more test?

deajan commented 4 years ago

Since the client failed with VSS, it's normal that you see the current folder and a working folder, the latter being the one burp tries to backup to before promoting it to next current backup.

You must search on your server what happens with VSS. You can begin by trying the following to see where your problem might be.

vssadmin list writers
vssadmin list providers
wmic shadowcopy

This problem is not burp related, but is a Windows VSS problem for all I know.

grke / burp

Random client disconnect issues (comes from VSS) #753