microsoft / AttackSurfaceAnalyzer

Attack Surface Analyzer can help you analyze your operating system's security configuration for changes during software installation.
MIT License
2.68k stars 271 forks source link

After update to 2.3.305: Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 13: 'database or disk is full' #710

Closed jachstet-sea closed 5 months ago

jachstet-sea commented 5 months ago

Describe the bug We recently updated our CI builders from v2.3.298 to v2.3.305 (alongside installing dotnet 8 runtime via Visual Studio installer). Since then, we are getting following errors on SECOND scan (first scan is fine), errors keep repeating:

[2024-02-05T08:32:00.968Z] [00:32:00 INF] Starting RegistryCollector.
[2024-02-05T08:33:23.329Z] [00:33:11 WRN] Error writing to database.
[2024-02-05T08:33:23.329Z] Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 13: 'database or disk is full'.
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteDataReader.NextResult()
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
[2024-02-05T08:33:23.329Z]    at Microsoft.CST.AttackSurfaceAnalyzer.Objects.SqlConnectionHolder.WriteNext() in D:\a\_work\1\s\Lib\Objects\SqlConnectionHolder.cs:line 150

To be honest, I cannot directly see the "disk space free" when it occurs since we are using ephemeral runners/VMs and I can not easily monitor disk space while the build is running. However, after reverting to v2.3.298, all is fine again.

To Reproduce Steps to reproduce the behavior:

  1. Update to v2.3.305
  2. Run same workload as before
  3. See error

Expected behavior Works as before (with v2.3.298)

Screenshots See log outputs below

System Configuration (please complete the following information):

Additional Context Log of first scan with v2.3.298:

$ asa collect -a --overwrite --runid baseline
[2024-02-05T09:43:42.637Z] [01:43:42 INF] AttackSurfaceAnalyzer v.2.3.298+b0059c467b
[2024-02-05T09:43:46.792Z] [01:43:46 INF] Begin baseline.
[2024-02-05T09:43:46.792Z] [01:43:46 INF] Starting 14 Collectors.
[2024-02-05T09:43:46.792Z] [01:43:46 INF] Starting FileSystemCollector.
[2024-02-05T09:43:46.792Z] [01:43:46 INF] Scanning root C:\
[2024-02-05T10:08:49.488Z] [02:08:36 INF] Completed FileSystemCollector in 00h:24m:49s:994ms.
[2024-02-05T10:08:49.488Z] [02:08:36 INF] Starting OpenPortCollector.
[2024-02-05T10:08:49.488Z] [02:08:36 INF] Completed OpenPortCollector in 00h:00m:00s:143ms.
[2024-02-05T10:08:49.488Z] [02:08:36 INF] Starting ServiceCollector.
[2024-02-05T10:08:49.488Z] [02:08:41 INF] Completed ServiceCollector in 00h:00m:04s:203ms.
[2024-02-05T10:08:49.488Z] [02:08:41 INF] Starting UserAccountCollector.
[2024-02-05T10:08:49.488Z] [02:08:42 INF] Completed UserAccountCollector in 00h:00m:01s:566ms.
[2024-02-05T10:08:49.488Z] [02:08:43 INF] Starting RegistryCollector.
[2024-02-05T10:09:37.095Z] [02:09:32 INF] Completed RegistryCollector in 00h:00m:48s:816ms.
[2024-02-05T10:09:37.095Z] [02:09:32 INF] Starting CertificateCollector.
[2024-02-05T10:09:37.095Z] [02:09:32 INF] Completed CertificateCollector in 00h:00m:00s:247ms.
[2024-02-05T10:09:37.095Z] [02:09:32 INF] Starting FirewallCollector.
[2024-02-05T10:09:37.095Z] [02:09:34 INF] Completed FirewallCollector in 00h:00m:01s:498ms.
[2024-02-05T10:09:37.095Z] [02:09:34 INF] Starting ComObjectCollector.
[2024-02-05T10:09:52.123Z] [02:09:51 INF] Completed ComObjectCollector in 00h:00m:16s:795ms.
[2024-02-05T10:09:52.123Z] [02:09:51 INF] Starting EventLogCollector.
[2024-02-05T10:10:00.240Z] [02:09:59 INF] Completed EventLogCollector in 00h:00m:07s:720ms.
[2024-02-05T10:10:00.240Z] [02:09:59 INF] Starting TpmCollector.
[2024-02-05T10:10:00.240Z] [02:09:59 INF] Completed TpmCollector in 00h:00m:00s:009ms.
[2024-02-05T10:10:00.240Z] [02:09:59 INF] Starting CryptographicKeyCollector.
[2024-02-05T10:10:00.240Z] [02:09:59 INF] Completed CryptographicKeyCollector in 00h:00m:00s:000ms.
[2024-02-05T10:10:00.240Z] [02:09:59 INF] Starting ProcessCollector.
[2024-02-05T10:10:02.748Z] [02:10:02 INF] Completed ProcessCollector in 00h:00m:03s:366ms.
[2024-02-05T10:10:03.010Z] [02:10:02 INF] Starting DriverCollector.
[2024-02-05T10:10:13.028Z] [02:10:12 INF] Completed DriverCollector in 00h:00m:09s:551ms.
[2024-02-05T10:10:13.028Z] [02:10:12 INF] Starting WifiCollector.
[2024-02-05T10:10:13.284Z] [02:10:13 INF] Completed WifiCollector in 00h:00m:00s:862ms.

Log of second/comparison scan with v2.3.298:

$ asa collect -a --overwrite --runid product_installed
[2024-02-05T10:11:01.043Z] [02:11:00 INF] AttackSurfaceAnalyzer v.2.3.298+b0059c467b
[2024-02-05T10:11:04.304Z] [02:11:03 INF] Begin product_installed.
[2024-02-05T10:11:04.304Z] [02:11:04 INF] Starting 14 Collectors.
[2024-02-05T10:11:04.304Z] [02:11:04 INF] Starting FileSystemCollector.
[2024-02-05T10:11:04.304Z] [02:11:04 INF] Scanning root C:\
[2024-02-05T10:34:04.654Z] [02:33:55 INF] Completed FileSystemCollector in 00h:22m:51s:563ms.
[2024-02-05T10:34:04.654Z] [02:33:55 INF] Starting OpenPortCollector.
[2024-02-05T10:34:04.654Z] [02:33:55 INF] Completed OpenPortCollector in 00h:00m:00s:087ms.
[2024-02-05T10:34:04.654Z] [02:33:55 INF] Starting ServiceCollector.
[2024-02-05T10:34:04.654Z] [02:34:00 INF] Completed ServiceCollector in 00h:00m:04s:750ms.
[2024-02-05T10:34:04.654Z] [02:34:00 INF] Starting UserAccountCollector.
[2024-02-05T10:34:04.654Z] [02:34:02 INF] Completed UserAccountCollector in 00h:00m:01s:906ms.
[2024-02-05T10:34:04.654Z] [02:34:02 INF] Starting RegistryCollector.
[2024-02-05T10:35:26.892Z] [02:35:26 INF] Completed RegistryCollector in 00h:01m:23s:978ms.
[2024-02-05T10:35:27.152Z] [02:35:26 INF] Starting CertificateCollector.
[2024-02-05T10:35:27.152Z] [02:35:27 INF] Completed CertificateCollector in 00h:00m:00s:216ms.
[2024-02-05T10:35:27.414Z] [02:35:27 INF] Starting FirewallCollector.
[2024-02-05T10:35:33.930Z] [02:35:33 INF] Completed FirewallCollector in 00h:00m:05s:984ms.
[2024-02-05T10:35:33.930Z] [02:35:33 INF] Starting ComObjectCollector.
[2024-02-05T10:36:12.990Z] [02:36:07 INF] Completed ComObjectCollector in 00h:00m:34s:199ms.
[2024-02-05T10:36:12.990Z] [02:36:07 INF] Starting EventLogCollector.
[2024-02-05T10:36:31.197Z] [02:36:29 INF] Completed EventLogCollector in 00h:00m:22s:011ms.
[2024-02-05T10:36:31.197Z] [02:36:29 INF] Starting TpmCollector.
[2024-02-05T10:36:31.197Z] [02:36:29 INF] Completed TpmCollector in 00h:00m:00s:010ms.
[2024-02-05T10:36:31.197Z] [02:36:29 INF] Starting CryptographicKeyCollector.
[2024-02-05T10:36:31.197Z] [02:36:29 INF] Completed CryptographicKeyCollector in 00h:00m:00s:000ms.
[2024-02-05T10:36:31.197Z] [02:36:29 INF] Starting ProcessCollector.
[2024-02-05T10:36:32.557Z] [02:36:32 INF] Completed ProcessCollector in 00h:00m:02s:719ms.
[2024-02-05T10:36:32.557Z] [02:36:32 INF] Starting DriverCollector.
[2024-02-05T10:36:44.832Z] [02:36:43 INF] Completed DriverCollector in 00h:00m:11s:407ms.
[2024-02-05T10:36:44.832Z] [02:36:43 INF] Starting WifiCollector.
[2024-02-05T10:36:44.832Z] [02:36:44 INF] Completed WifiCollector in 00h:00m:00s:159ms.

Log of first scan with v2.3.305:

$ asa collect -a --overwrite --runid baseline
[2024-02-05T07:46:22.752Z] [23:46:22 INF] AttackSurfaceAnalyzer v.2.3.305+f3d089dfb4
[2024-02-05T07:46:26.914Z] [23:46:26 INF] Begin baseline.
[2024-02-05T07:46:26.914Z] [23:46:26 INF] Starting 14 Collectors.
[2024-02-05T07:46:26.914Z] [23:46:26 INF] Starting FileSystemCollector.
[2024-02-05T07:46:26.914Z] [23:46:26 INF] Scanning root C:\
[2024-02-05T08:05:58.351Z] [00:05:51 INF] Completed FileSystemCollector in 00h:19m:24s:757ms.
[2024-02-05T08:05:58.351Z] [00:05:51 INF] Starting OpenPortCollector.
[2024-02-05T08:05:58.351Z] [00:05:51 INF] Completed OpenPortCollector in 00h:00m:00s:148ms.
[2024-02-05T08:05:58.351Z] [00:05:51 INF] Starting ServiceCollector.
[2024-02-05T08:05:58.351Z] [00:05:52 INF] Completed ServiceCollector in 00h:00m:01s:270ms.
[2024-02-05T08:05:58.351Z] [00:05:53 INF] Starting UserAccountCollector.
[2024-02-05T08:05:58.351Z] [00:05:55 INF] Completed UserAccountCollector in 00h:00m:02s:371ms.
[2024-02-05T08:05:58.351Z] [00:05:55 INF] Starting RegistryCollector.
[2024-02-05T08:08:37.054Z] [00:08:36 INF] Completed RegistryCollector in 00h:02m:40s:960ms.
[2024-02-05T08:08:37.054Z] [00:08:36 INF] Starting CertificateCollector.
[2024-02-05T08:08:37.313Z] [00:08:37 INF] Completed CertificateCollector in 00h:00m:00s:412ms.
[2024-02-05T08:08:37.313Z] [00:08:37 INF] Starting FirewallCollector.
[2024-02-05T08:08:37.921Z] [00:08:37 INF] Completed FirewallCollector in 00h:00m:00s:548ms.
[2024-02-05T08:08:37.921Z] [00:08:37 INF] Starting ComObjectCollector.
[2024-02-05T08:08:59.982Z] [00:08:57 INF] Completed ComObjectCollector in 00h:00m:19s:836ms.
[2024-02-05T08:08:59.982Z] [00:08:57 INF] Starting EventLogCollector.
[2024-02-05T08:09:06.509Z] [00:09:06 INF] Completed EventLogCollector in 00h:00m:08s:435ms.
[2024-02-05T08:09:06.509Z] [00:09:06 INF] Starting TpmCollector.
[2024-02-05T08:09:06.509Z] [00:09:06 INF] Completed TpmCollector in 00h:00m:00s:051ms.
[2024-02-05T08:09:06.509Z] [00:09:06 INF] Starting CryptographicKeyCollector.
[2024-02-05T08:09:06.509Z] [00:09:06 INF] Completed CryptographicKeyCollector in 00h:00m:00s:000ms.
[2024-02-05T08:09:06.509Z] [00:09:06 INF] Starting ProcessCollector.
[2024-02-05T08:09:21.499Z] [00:09:19 INF] Completed ProcessCollector in 00h:00m:12s:991ms.
[2024-02-05T08:09:21.499Z] [00:09:19 INF] Starting DriverCollector.
[2024-02-05T08:09:43.644Z] [00:09:41 INF] Completed DriverCollector in 00h:00m:21s:779ms.
[2024-02-05T08:09:43.644Z] [00:09:41 INF] Starting WifiCollector.
[2024-02-05T08:09:43.644Z] [00:09:41 INF] Completed WifiCollector in 00h:00m:00s:184ms.

Log of second scan with v2.3.305 (truncated since errors keep coming):

$ asa collect -a --overwrite --runid product_installed
[2024-02-05T08:10:39.202Z] [00:10:38 INF] AttackSurfaceAnalyzer v.2.3.305+f3d089dfb4
[2024-02-05T08:10:42.460Z] [00:10:42 INF] Begin product_installed.
[2024-02-05T08:10:42.460Z] [00:10:42 INF] Starting 14 Collectors.
[2024-02-05T08:10:42.460Z] [00:10:42 INF] Starting FileSystemCollector.
[2024-02-05T08:10:42.460Z] [00:10:42 INF] Scanning root C:\
[2024-02-05T08:31:57.102Z] [00:31:52 INF] Completed FileSystemCollector in 00h:21m:10s:319ms.
[2024-02-05T08:31:57.102Z] [00:31:53 INF] Starting OpenPortCollector.
[2024-02-05T08:31:57.102Z] [00:31:54 INF] Completed OpenPortCollector in 00h:00m:01s:245ms.
[2024-02-05T08:31:57.102Z] [00:31:54 INF] Starting ServiceCollector.
[2024-02-05T08:31:57.102Z] [00:31:55 INF] Completed ServiceCollector in 00h:00m:00s:753ms.
[2024-02-05T08:31:57.102Z] [00:31:55 INF] Starting UserAccountCollector.
[2024-02-05T08:31:58.464Z] [00:31:57 INF] Completed UserAccountCollector in 00h:00m:02s:397ms.
[2024-02-05T08:32:00.968Z] [00:32:00 INF] Starting RegistryCollector.
[2024-02-05T08:33:23.329Z] [00:33:11 WRN] Error writing to database.
[2024-02-05T08:33:23.329Z] Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 13: 'database or disk is full'.
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteDataReader.NextResult()
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
[2024-02-05T08:33:23.329Z]    at Microsoft.CST.AttackSurfaceAnalyzer.Objects.SqlConnectionHolder.WriteNext() in D:\a\_work\1\s\Lib\Objects\SqlConnectionHolder.cs:line 150
[2024-02-05T08:33:23.329Z] [00:33:12 WRN] Error writing to database.
[2024-02-05T08:33:23.329Z] System.InvalidOperationException: This SqliteTransaction has completed; it is no longer usable.
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
[2024-02-05T08:33:23.329Z]    at Microsoft.CST.AttackSurfaceAnalyzer.Objects.SqlConnectionHolder.WriteNext() in D:\a\_work\1\s\Lib\Objects\SqlConnectionHolder.cs:line 150
[2024-02-05T08:33:23.329Z] [00:33:12 WRN] Error writing to database.
[2024-02-05T08:33:23.329Z] System.InvalidOperationException: This SqliteTransaction has completed; it is no longer usable.
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
[2024-02-05T08:33:23.329Z]    at Microsoft.CST.AttackSurfaceAnalyzer.Objects.SqlConnectionHolder.WriteNext() in D:\a\_work\1\s\Lib\Objects\SqlConnectionHolder.cs:line 150
[2024-02-05T08:33:23.329Z] [00:33:12 WRN] Error writing to database.
[2024-02-05T08:33:23.329Z] System.InvalidOperationException: This SqliteTransaction has completed; it is no longer usable.
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
[2024-02-05T08:33:23.329Z]    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
[2024-02-05T08:33:23.329Z]    at Microsoft.CST.AttackSurfaceAnalyzer.Objects.SqlConnectionHolder.WriteNext() in D:\a\_work\1\s\Lib\Objects\SqlConnectionHolder.cs:line 150
...
gfs commented 5 months ago

Thanks for the report. I'll try to investigate today to see if I can reproduce.

gfs commented 5 months ago

I ran two scans locally and was not able to reproduce this. Comparing the two releases I don't see or recall any changes that should have affected collectors in general, the database middleware, or the registry collector other than the update to Microsoft.Data.Sqlite 8.0.0 (vs 7.x previously) - where the error is ultimately thrown. However, I see there is an update for 8.0.1, which should be included with the build from #709 later today. Please let me know if the new build I anticipate releasing later today with the updated dependency resolves the issue.

jachstet-sea commented 5 months ago

Hi @gfs, thanks for the timely investigation. I would also assume that the root cause of the issues doesn't lie in your code but is rather to be looked for in the dotnet runtime. I'll check if I can add some easy debugging stuff to our build process or create a simple project to verify differences between dotnet 7 and 8.

jachstet-sea commented 5 months ago

Okay, maybe an deeper analysis is not required .... The VM we are using has around 6GByte of free space. The latest version of ASA writes 3GB for one run. I'll check if the older versions write less

jachstet-sea commented 5 months ago

Update: The database files of ASA v2.3.298 after one full scan are only 1.28GByte in sum, compared to the 3.00GByte that ASA v2.3.308 creates. So I that definitely hints that the cause or the error message we are getting is disk space (and as such, the error message is valid) but it leaves the question open why the file size differs that much.

gfs commented 5 months ago

Interesting. Thanks for doing the additional investigation. It sounds like you're unblocked for now then. I'm not sure immediately why the database size would have increased by such a large factor either. Perhaps its a difference in how the SQLite library calculates indices? I'll try to find some time to double check that I can reproduce this size difference between versions and see if I can identify anything within our control to shrink them back down a bit. I'll try to get to that later this week, or next week.

jachstet-sea commented 5 months ago

Indeed, we are no longer blocked. I can confirm that ASA works as expected once we gave the build VM some more disk space so it's no longer an issue for us. I'd be very interested if you can confirm the larger database sizses on your end 👍

gfs commented 5 months ago

I can reproduce a significant difference in the number of records collected for the registry collector between 2.3.298 and the latest. However, with further investigation I don't believe this indicates an error in the new code - but rather reflects a bug fix that was previously preventing some data from being collected. PR #701 added a fix for the registry walker bailing out too early if it encountered a null Key, preventing it from fully crawling a the rest of the subkey, thus the new version will have a more complete collection of data and thus the database is subsequently larger.

jachstet-sea commented 5 months ago

Thanks for investigating and the headup, #701 indeed seems like a worthy thing to be fixed :)