tekartik / sqflite

SQLite flutter plugin
BSD 2-Clause "Simplified" License
2.88k stars 527 forks source link

Help with sqflite_logger #1076

Closed mateusfsilva closed 9 months ago

mateusfsilva commented 9 months ago

Hi @alextekartik!

I have some more questions about the logs.

First of all, I couldn't fire the SqfliteLoggerDatabaseDeleteEvent event using the function deleteDatabase(). And I couldn't test it. Maybe because it isn't firing.

Second, I couldn't get the transaction value from the events SqfliteLoggerSqlEvent, SqfliteLoggerDatabaseCloseEvent, and SqfliteLoggerBatchEvent. Unless I import the source code to access the class SqfliteDatabaseExecutorMixin.

import 'package:sqflite_common/src/database_mixin.dart';

final txnId = (_event.client as SqfliteDatabaseExecutorMixin).txn?.transactionId;

And for last, I had the same situation with the database ID.

import 'package:sqflite_common/src/database.dart';

final dbID = (_event.client.database as SqfliteDatabase).id;

I made a lib to use on my projects to log the SQL queries. I think it can be useful to somebody else. If you could take a look I'll appreciate it. The problematic test for the database deletion can be found here:

https://github.com/mateusfsilva/talker_sqflite_logger/blob/edc0edd78156003a179d40fac233b737986813b9/test/src/talker_sqflite_logger_test.dart#L403-L482

A full example can be found here.

sqflite: 2.3.0 sqflite_common: 2.5.2-1 sqflite_common_ffi: 2.3.2 sqlite3: 2.3.0

alextekartik commented 9 months ago

Thanks for the report. The logger is still an experimental feature so feedback is always welcome. I was not able to run only the incriminated test/group. You might put

sqfliteFfiInit();
databaseFactory = databaseFactoryFfi;

at the beginning of your main and make sure db is initialized in all the tests in the group SqfliteLoggerDatabaseCloseEvent otherwise the main tearDown (db.close) will complain about an unitiliazed db.

, I couldn't fire the SqfliteLoggerDatabaseDeleteEvent event using the function deleteDatabase(). And I couldn't test it. Maybe because it isn't firing.

The deleteEvent is tested fine here: https://github.com/tekartik/sqflite/blob/cd0ca4e89acd130705cdefd8b715980cc67f7431/sqflite_common_test/test/sqflite_ffi_no_isolate_logger_various_test.dart#L33-L59

That is said, it is still experimental and I can be wrong. Do you have a simple test I can run that I can investigate.

Second, I couldn't get the transaction value from the events SqfliteLoggerSqlEvent, SqfliteLoggerDatabaseCloseEvent, and SqfliteLoggerBatchEvent. Unless I import the source code to access the class SqfliteDatabaseExecutorMixin.

indeed I try to avoid exposing too much internals (in case they change in the future). Can you tell me which info you need (you don't need everything right?) to see if I can expose it.

Thanks!

mateusfsilva commented 9 months ago

at the beginning of your main and make sure db is initialized in all the tests in the group SqfliteLoggerDatabaseCloseEvent otherwise the main tearDown (db.close) will complain about an unitiliazed db.

I have this code at the beginning of every group. I didn't put it at the beginning of the delete group because you said in issue #814 that it isn't possible to delete in-memory databases. So, I tried it using a file.

Do you have a simple test I can run that I can investigate.

You can find a complete example here. Every button calls the close and delete at the end.

Every command calls the method invokeMethod (sqflite_logger.dart in line 772), except the deleteDatabase(path). I think it should call the method deleteDatabase (sqflite_logger.dart in line 788), but it doesn't.

https://github.com/tekartik/sqflite/blob/cd0ca4e89acd130705cdefd8b715980cc67f7431/sqflite_common/lib/src/logger/sqflite_logger.dart#L771-L802

indeed I try to avoid exposing too much internals (in case they change in the future). Can you tell me which info you need (you don't need everything right?) to see if I can expose it.

I need only the database ID (SqfliteDatabase) and the transaction ID (SqfliteDatabaseExecutorMixin).

alextekartik commented 9 months ago

Try

flutter test --plain-name SqfliteLoggerDatabaseDeleteEvent

You'll that it reports weird error (db not initialized). Can you make sure that each test can run independently before I investigate, thanks

mateusfsilva commented 9 months ago

Ah! The error is because it calls db.close() in the tearDown.

tearDown(() async {
  await db.close();
});

Sorry, I forgot to set the db variable with the Database object. Should be:

db = await factory.openDatabase(
  path: path,
  factory: databaseFactoryFfi,
);

Instead of:

await factory.openDatabase(
  path: path,
  factory: databaseFactoryFfi,
);

I updated the code on GitHub to fix it.

flutter test --plain-name="When log is enabled And the database is deleted And printDatabaseDeleteEvents is true Then call SqfliteDatabaseDeleteEventLog"
00:01 +0 -1: /Users/mateusfsilva/development/flutter/talker_sqflite_logger/test/src/talker_sqflite_logger_test.dart: SqfliteLoggerDatabaseDeleteEvent When log is enabled And the database is deleted And printDatabaseDeleteEvents is true Then call SqfliteDatabaseDeleteEventLog [E]
  No matching calls (actually, no calls at all).
  (If you called `verify(...).called(0);`, please instead use `verifyNever(...);`.)
  package:matcher                                  fail
  package:mocktail/src/mocktail.dart 728:7         _VerifyCall._checkWith
  package:mocktail/src/mocktail.dart 519:18        _makeVerify.<fn>
  test/src/talker_sqflite_logger_test.dart 451:30  main.<fn>.<fn>

To run this test again: /opt/homebrew/Caskroom/flutter/3.16.8/flutter/bin/cache/dart-sdk/bin/dart test /Users/mateusfsilva/development/flutter/talker_sqflite_logger/test/src/talker_sqflite_logger_test.dart -p vm --plain-name 'SqfliteLoggerDatabaseDeleteEvent When log is enabled And the database is deleted And printDatabaseDeleteEvents is true Then call SqfliteDatabaseDeleteEventLog'
00:01 +0 -1: Some tests failed.
alextekartik commented 9 months ago

So indeed deleteDatabase in your test is called using the ffi factory and not using the proper factoryWithLogs that you create during openDatabase which explain why you have no logs here. You might want to add a deleteDatabase method in your TalkerSqfliteDatabaseFactory.

alextekartik commented 9 months ago

I have published sqflite_common 2.5.3 that exposes databaseId and transactionId for open/close and sql events

mateusfsilva commented 9 months ago

So indeed deleteDatabase in your test is called using the ffi factory and not using the proper factoryWithLogs that you create during openDatabase which explain why you have no logs here. You might want to add a deleteDatabase method in your TalkerSqfliteDatabaseFactory.

I didn't understand. I used the TalkerSqfliteDatabaseFactory to open the database.

https://github.com/mateusfsilva/talker_sqflite_logger/blob/7c6b43c9bb8353e466fbf296011fca8b3e34d111/test/src/talker_sqflite_logger_test.dart#L439-L442

It calls the factory created above to open the database openDatabase().

https://github.com/mateusfsilva/talker_sqflite_logger/blob/7c6b43c9bb8353e466fbf296011fca8b3e34d111/test/src/talker_sqflite_logger_test.dart#L444-L447

Of course, the openDatabase method uses the SqfliteDatabaseFactoryLogger with SqfliteLoggerOptions to log the events.

https://github.com/mateusfsilva/talker_sqflite_logger/blob/7c6b43c9bb8353e466fbf296011fca8b3e34d111/lib/src/talker_sqflite_logger_database_factory.dart#L23-L42

And in the SqfliteLoggerEventFunction it checks the SqfliteLoggerDatabaseDeleteEvent.

https://github.com/mateusfsilva/talker_sqflite_logger/blob/7c6b43c9bb8353e466fbf296011fca8b3e34d111/lib/src/talker_sqflite_logger_database_factory.dart#L82-L90

The test logs every event except the database deletion. If you change the test to log the other events it will pass

    test(
        'When log is enabled '
        'And the database is deleted '
        'And printDatabaseDeleteEvents is true '
        'Then call SqfliteDatabaseDeleteEventLog', () async {
      const settings = TalkerSqfliteLoggerSettings(
        printDatabaseOpenEvents: true,
        printDatabaseCloseEvents: true,
        printDatabaseDeleteEvents: true,
      );
      factory = TalkerSqfliteDatabaseFactory(
        talker: talker,
        settings: settings,
      );

      db = await factory.openDatabase(
        path: pathFile,
        factory: databaseFactory,
      );

      await db.close();
      await deleteDatabase(pathFile);

      // final captured = verify(
      //   () => talker.logTyped(
      //     captureAny(
      //       that: isA<SqfliteDatabaseDeleteEventLog>(),
      //     ),
      //   ),
      // ).captured;

      // expect(captured.last, isA<SqfliteDatabaseDeleteEventLog>());

      final captured = verify(() => talker.logTyped(captureAny())).captured;

      expect(captured.first, isA<SqfliteDatabaseOpenEventLog>());
      expect(captured.last, isA<SqfliteDatabaseCloseEventLog>());
    });
alextekartik commented 9 months ago

I didn't understand. I used the TalkerSqfliteDatabaseFactory to open the database.

You need to use the same factory to delete the database.

mateusfsilva commented 9 months ago

I got it. It's working now.

Thanks. I'll test the databaseId and the transactionId.

mateusfsilva commented 9 months ago

The databaseId and the transactionId worked like a charm.

Thank you very much for the help.

Can I suggest putting this in the sqflite_logger.md?