'Column families not opened' when open RocksDB

[Anantharaman Gopalakrishnan]

Hi Team,

I am facing Column families not opened exception when trying to open a RocksDB.

For analysis purposes, I have shared the RocksDB data directory and code to reproduce this inconsistency. As it can be seen from the code is that column family details obtained from RocksDB.listColumnFamilies is different from that of the one obtained from OptionsUtil.loadLatestOptions. 

Need your help in resolving this inconstancy.

Also, how to configure RocksDB such that this issue can be avoided.

Thanks & Regards,

Anantharaman G.

[Alan Paxton]

Hi Anantharaman,

Thanks for the report. It looks like the options file is not up to date with the current set of column families. If I open the DB with the column families in `listColumnFamilies()`

then the situation resolves, as on open() the options get updated and saved to match the column families:

public void repairColumnFamilies() throws RocksDBException {
String dbPath = getDBPath();

List<byte[]> columnFamilies;
try (Options o = new Options())
{
columnFamilies = RocksDB.listColumnFamilies(o, dbPath);
}

List<ColumnFamilyDescriptor> columnFamilyDescriptors = new ArrayList<>();
for (byte[] cfBytes : columnFamilies) {
columnFamilyDescriptors.add(new ColumnFamilyDescriptor(cfBytes));
}
List<ColumnFamilyHandle> columnFamilyHandles = new ArrayList<>();
try (RocksDB db = RocksDB.open(dbPath, columnFamilyDescriptors, columnFamilyHandles)) {

List<ColumnFamilyDescriptor> columnFamilyDescriptorsFromOptions = new ArrayList<>();
DBOptions dbOptions = new DBOptions().setCreateIfMissing(true).setCreateMissingColumnFamilies(true);
try (ConfigOptions configOptions = new ConfigOptions().setIgnoreUnknownOptions(false).setInputStringsEscaped(true).setEnv(Env.getDefault()))
{
OptionsUtil.loadLatestOptions(configOptions, dbPath, dbOptions, columnFamilyDescriptorsFromOptions);
}

List<String> columnFamilyNames = columnFamilies.stream().map(String::new).collect(Collectors.toList());
System.err.println("columnFamilyNames = " + columnFamilyNames);
List<String> columnDescriptorNames = columnFamilyDescriptorsFromOptions.stream().map(ColumnFamilyDescriptor::getName).map(String::new).collect(Collectors.toList());
System.err.println("columnDescriptorNames = " + columnDescriptorNames);

assertThat(columnFamilyNames).containsExactlyInAnyOrderElementsOf(columnDescriptorNames);
}
}

It is my understanding that the options file gets written at specific points in time, but I don't think that is under transactional control, so I imagine that it is 

possible to be unlucky, as you have been, and end up with an out of date options file, perhaps on a forced quit of the database ? So I suggest that you use

the pattern above to make the DB and the options consistent again before using the options.

see also https://github.com/facebook/rocksdb/wiki/RocksDB-Options-File

---Alan

--

Kind regards,

Alan Paxton

Senior Engineer

--
You received this message because you are subscribed to the Google Groups "rocksdb" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rocksdb+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/rocksdb/63103bdf-6f3c-41b9-a666-0739b6eb867fn%40googlegroups.com.

[Anantharaman Gopalakrishnan]

Hi Alan / Team,

Thanks for the reply.

We have checked and ensured that this is not a forced quit case since this issue is occurring somewhat frequently in our testing environment. For our case, __serverD-serverA-taskengine is a column that was actually deleted but is still present in the OPTIONS file. So, we are planning to use the following code snippet to cleanup the missing CFs to resolve the inconsistencies. Kindly share your inputs on this.

List<byte[]> columnFamilies;
try (Options o = new Options()) {
  columnFamilies = RocksDB.listColumnFamilies(o, dbPath);
}

DBOptions dbOptions = new DBOptions().setCreateIfMissing(true).setCreateMissingColumnFamilies(true);

List<ColumnFamilyDescriptor> columnFamilyDescriptors = new ArrayList<>();

try (ConfigOptions configOptions = new ConfigOptions().setIgnoreUnknownOptions(false).setInputStringsEscaped(true).setEnv(Env.getDefault())) {

  OptionsUtil.loadLatestOptions(configOptions, dbPath, dbOptions, columnFamilyDescriptors);
}

try (ColumnFamilyOptions defaultOptions = new ColumnFamilyOptions()) {
  List<byte[]> inconsistentColumns = columnFamilies.stream()
      .filter(name -> columnFamilyDescriptors.stream().noneMatch(cfd -> Arrays.equals(cfd.getName(), name)))

      .collect(Collectors.toList());

  inconsistentColumns.forEach(name -> columnFamilyDescriptors.add(new ColumnFamilyDescriptor(name, defaultOptions)));

  List<ColumnFamilyHandle> columnFamilyHandles = new ArrayList<>();

  try (RocksDB rocksDB = RocksDB.open(dbOptions, dbPath, columnFamilyDescriptors, columnFamilyHandles)) {
    for (byte[] inconsistentColumn : inconsistentColumns) {

      for (ColumnFamilyHandle handle : columnFamilyHandles) {

        if (Arrays.equals(handle.getName(), inconsistentColumn)) {

          rocksDB.dropColumnFamily(handle);

        }

      }

    }

  }
}

Meanwhile, is there anything we can do, such as configuring RocksDB to log more information, so that we can share it and help avoid this inconsistency issue? As mentioned earlier, since this issue occurs randomly in the local environment, we might be able to capture this data for debugging purposes. Is so, do share how it can be done.

[Alan Paxton]

Hi Anantharaman,

Looking at the logs and option files in the data directory you shared, it appears as if the __serverD-serverA-taskengine column has been created, the OPTIONS-000110.dbtmp has been written to contain options for this CF, but the file has not yet been atomically renamed OPTIONS-000110 by the system, which has then stopped, correctly or incorrectly:

2024/08/24-18:01:49.865467 13058211840 [/db_impl/db_impl.cc:3442] Created column family [__serverD-serverA-taskengine] (ID 23)
2024/08/24-18:01:49.865799 13057150976 [/db_impl/db_impl.cc:498] Shutdown: canceling all background work
2024/08/24-18:01:49.866229 13057150976 [/db_impl/db_impl.cc:691] Shutdown complete

So RocksDB has created the column family, but the options are not up to date, and hence RocksDB.listColumnFamilies is correct about the true state of the system;

when my example code runs, which opens the DB with the listed column families, and closes it again, RocksDB updates the options to be consistent. At that point, __serverD-serverA-taskengine is present in the options file, as well as in the list of column families.

So I do not think you should simply `drop()` the column(s) that you find inconsistent; perhaps confirm that you shut down cleanly after creating __serverD-serverA-taskengine. If it

should have been deleted, I don't think that code has been run ?

--

Kind regards,

Alan Paxton

Senior Engineer

To view this discussion on the web visit https://groups.google.com/d/msgid/rocksdb/2638d551-ab61-4be0-846b-91ba32e4d8e9n%40googlegroups.com.

[Anantharaman Gopalakrishnan]

Hi Alan / Team,

In our testing environment, we create CFs and delete them. We log during both creation and deletion from our logs it is clear that the column gets deleted before this exception occurs. 

Do note that, there are no log traces in RocksDB's log by default when a CF gets deleted.

Also, we have double checked that the rocksdb is shutting-down properly.

--------------------------------

Thanks & Regards,

Anantharaman G

[Alan Paxton]

Hi Anantharam,

According to the LOG files posted in rocksdb-meta-mismatch the column family __serverD-serverA-taskengine is created and deleted several times, finally it is created (ID 23),

just before the system shuts down (see the log extract earlier in the thread). So in the TRUE state of RocksDB when it is restarted, the CF __serverD-serverA-taskengine exists. Because the options file is not

written transactionally consistently with the database (if I understand it correctly) then the options read with OptionsUtil.loadLatestOptions are not necessarily consistent,

but RocksDB makes them consistent after opening with the CFs RocksDB.listColumnFamilies has returned. So my advice is

(1) open with the families listed, then

(2) use OptionsUtil.loadLatestOptions to load the now-consistent options.

Does that make any more sense to you ?

Best,

Alan

[Anantharaman Gopalakrishnan]

Hi Alan,

First of all, thanks for replying to my message.

finally it is created (ID 23), just before the system shuts down

Regarding the above, according to our application's code flow and logs, we have deleted the column family before the last shutdown. i.e., We have explicitly logged when a CF is created or deleted and before we faced 'Column families not opened' error, we have deleted the CF. But, it's not reflected in the options file which leads to this incorrect state.

Since there are also no logs from RocksDB for drop-cf, it's hard for me to show that we have actually deleted the cf before its final shutdown.

My requirement is, what more I could do so that I can gather and share additional information to you/team so that we can resolve this issue/inconsistency.

PS : I can understand your argument and feel it's also valid (since we haven't shared our application logs to show that the CF was deleted before the last shutdown), it's hard for us to come to a proper conclusion to resolve this issue properly.

--------------------------------

Thanks & Regards,

Anantharaman G

You received this message because you are subscribed to a topic in the Google Groups "rocksdb" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rocksdb/T4WjTEsZgZs/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rocksdb+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/rocksdb/003a824c-950c-4bb4-9a08-76374c8e41d4n%40googlegroups.com.

[Alan Paxton]

Hi Anantharaman,

I agree the CF gets created and deleted several times. However, the state of the database and logs that you have kindly provided shows that CF __serverD-serverA-taskengine has absolutely just been created an instant before the RocksDB instance stopped. Because of this, the options file has not yet had it added, which RocksDB does automatically

on restart (if you restart it with the list of CFs which it considers correct).

In this case, __serverD-serverA-taskengine is being created for the 4th time (ID 23). 

So I believe the correct solution is to list the CFs using RocksDB.listColumnFamilies and open the DB with those CFs. Once the DB is open, RocksDB will have updated

the options to be consistent. In the case of the logs you provided, __serverD-serverA-taskengine exists in this case. 

If that isn't an application state that agrees with how your application should behave, I would be interested to see application logs that you have that say

"I am about to delete/create CF XYZ" and "I have deleted/created CF XYZ" so that we can correlate them with the RocksDB logs.

Is there anywhere in your application (another thread) that notices the absence of __serverD-serverA-taskengine and automatically recreates it ? I wonder if something like this

is happening at the point where you re deleting it and shutting down ?

--

Kind regards,

Alan Paxton

Senior Engineer