Merge lp://qastaging/~tkluck/simple-scan/autosaves into lp://qastaging/~simple-scan-team/simple-scan/trunk

Hi,

Thanks for working on this!

The patch seems generally good, but I'm not able to confirm it working. I can confirm the database gets written, but if I do a "killall -9 simple-scan" and then restart it the existing book is not recovered. What steps should I take to confirm the patch works?

> // FIXME: this only works on linux
> string current_pids;
> Process.spawn_command_line_sync ("pidof simple-scan | sed \"s/ /,/g\"", out current_pids);
This is a bit gross, but don't know if we can get around it.

> public void on_page_changed (Page page)
> {
> /* we don't update the database as it is to slow to do so each time
> * a scan line is received.
> */
> //update_page (page);
> }
Please remove this if it doesn't do anything.

> if (number_of_instances > 0)
> {
> assert_not_reached ();
> }
We don't use curly braces if there's just one line in a branch.

> /* FIXME: we would like to connect to a scan_fished signal on a page,
> * but it does not exist. Updating the database every time a scanline
> * has changed is much to slow. We choose to update the database every
> * now and then, instead.
Let's add that signal then.

Hi Robert,

Thanks for your detailed feedback.

> The patch seems generally good, but I'm not able to confirm it working. I can confirm the database gets written, but if I do a "killall -9 simple-scan" and then restart it the existing book is not recovered. What steps should I take to confirm the patch works?

I don't have access to a scanner atm, so I cannot make a document like you're doing. However, it did work for me as far as I remember. What does work for me right now, is to add an autosave page manually, by

sqlite3 ~/.cache/simple-scan/autosaves/autosaves.db
INSERT INTO "pages" VALUES(1,1,1,1,1,1,150,150,150,8,3,450,'',0,0,10,10,0,randomblob(150*150*3));

and then starting simple-scan. The window will open with a very colourful page. Can you confirm that this works for you?

I will put your other remarks into work soon.

Hi Timo,

If you ever want to test simple-scan you can pass the name of the scanner as an argument to simple-scan. Conveniently SANE has a test driver so the following:

$ simple-scan test

Works without any scanner attached!

If you ever want to test simple-scan you can pass the name of the scanner as an argument to simple-scan. Conveniently SANE has a test driver so the following:

$ simple-scan test

Works without any scanner attached!
Thanks, that's very helpful! I now see that the first scanned page is not correctly stored in the database. The next one is, and it is also being correctly recovered on my machine. A clue is that I'm getting some of those warn_if_fails failing. Are you seeing the same behaviour?

I will have to look into it later.

I've pushed some changes that seem to deal with the issues I could reproduce. Can you test the new version?

I tried the following:

1. Run simple-scan with test driver:
bob@alchemy:~/bzr/simple-scan$ ./src/simple-scan test
2. Scan a single page with text mode
3. Kill simple-scan with 'killall simple-scan':
Terminated
4. Run simple-scan again
bob@alchemy:~/bzr/simple-scan$ ./src/simple-scan

** (simple-scan:8023): CRITICAL **: autosave_manager_recover_book: assertion `SQLITE_OK == _tmp8_' failed

Doesn't recover the book and gives the above error.

> I tried the following:
>
> 1. Run simple-scan with test driver:
> bob@alchemy:~/bzr/simple-scan$ ./src/simple-scan test
> 2. Scan a single page with text mode
> 3. Kill simple-scan with 'killall simple-scan':
> Terminated
> 4. Run simple-scan again
> bob@alchemy:~/bzr/simple-scan$ ./src/simple-scan
>
> ** (simple-scan:8023): CRITICAL **: autosave_manager_recover_book: assertion
> `SQLITE_OK == _tmp8_' failed
>
> Doesn't recover the book and gives the above error.

I'm doing the exact same thing (either first removing ~/.cache/simple-scan/autosaves/autosaves.db or not) and it works for me. I'm also puzzled by the error you're getting. It seems to be the prepare_v2 call that's failing. I cannot see how that can work on one machine and fail on the other. Are you on Precise with sqlite3 version 3.7.9-2ubuntu1 ?

Could you help me debug this? There's no way I can do that without seeing it happen for myself. Can you recover the exit code of the prepare_v2 call? And can you recover the sql string after it has been formatted?

Thanks!

Could you update it to log the error codes? That way it will be safer in the future.

I've just pushed a version that logs all the query strings and the resulting error codes. It would be great if you could send me the resulting logfile. (don't forget to specify --debug on the command line).

It doesn't crash anymore but I get the following error:

[+0.00s] DEBUG: simple-scan.vala:582: Starting Simple Scan 3.6.0, PID=5391
[+0.00s] DEBUG: Connecting to session manager
[+0.03s] WARNING: g_object_set_valist: invalid object type `GtkAdjustment' for value type `GtkWidget'
[+0.03s] DEBUG: ui.vala:1463: Restoring window to 774x607 pixels
[+0.03s] DEBUG: ui.vala:1468: Restoring window to maximized
[+0.03s] DEBUG: autosave-manager.vala:214: Executing query "
            CREATE TABLE IF NOT EXISTS pages (
                id integer PRIMARY KEY,
                process_id integer,
                page_hash integer,
                book_hash integer,
                book_revision integer,
                page_number integer,
                dpi integer,
                width integer,
                height integer,
                depth integer,
                n_channels integer,
                rowstride integer,
                color_profile string,
                crop_x integer,
                crop_y integer,
                crop_width integer,
                crop_height integer,
                scan_direction integer,
                pixels binary
            )"
[+0.04s] DEBUG: autosave-manager.vala:113: preparing query "
                   SELECT process_id, book_hash, book_revision FROM pages
                   WHERE NOT process_id IN (5391)
                   LIMIT 1
                "
[+0.04s] DEBUG: autosave-manager.vala:134: Executing query "
                        UPDATE pages
                           SET process_id = 5391
                         WHERE process_id = 5359
                           AND book_hash = 11118128
                           AND book_revision = 0"
[+0.23s] DEBUG: autosave-manager.vala:396: preparing query "
            SELECT process_id,
                page_hash,
                book_hash,
                book_revision,
                page_number,
                dpi,
                width,
                height,
                depth,
                n_channels,
                rowstride,
                color_profile,
                crop_x,
                crop_y,
                crop_width,
                crop_height,
                scan_direction,
                pixels,
                id
            FROM pages
            WHERE process_id = 5391
              AND book_revision = (
                  SELECT MAX(book_revision) WHERE process_id = 5391
              )
            ORDER BY page_number
        "
[+0.23s] WARNING: autosave-manager.vala:399: error 1 while preparing statement
[+0.28s] DEBUG: scanner.vala:1419: sane_init () -> SANE_STATUS_GOOD
[+0.28s] DEBUG: scanner.vala:1425: SANE version 1.0.23
[+0.28s] DEBUG: scanner.vala:1486: Requesting redetection of scan devices
[+0.28s] DEBUG: scanner.vala:776: Processing request
[+2.69s] DEBUG: scanner.vala:338: sane_get_devices () -> SANE_STATUS_GOOD
[+3.30s] DEBUG: scanner.vala:1559: Stopping scan thread
[+3.30s] DEBUG: scanner.vala:776: Processing request
[+3.31s] DEBUG: scanner.vala:1567: sane_exit ()

It seems to be this part - removing it makes it work.
AND book_revision = ( SELECT MAX(book_revision) WHERE process_id = 5391 )

Is a particular version of SQLite required for this syntax to be supported?

I could reproduce this error now (!). I'm surprised that it worked before, because the subquery misses a FROM clause. I just pushed a fix. Can you let me know your results?

That fixes that error, but still not books being restored.

I am running the following:
1. $ simple-scan test -d
2. Pressing scan
3. Killing simple-scan with ctrl-C (or killall simple-scan)
4. $ simple-scan

No pages are restored.

Can you add some debugging messages that note what the the autosave manager is doing? I would expect to see the following in the log

"Restoring book with 5 pages"
"No book to restore"
"Failed to restore book: Error Sqlite.ERROR when getting pages"
"Autosaving book to ~/.cache/simple-scan/autosaves/autosaves.db"

I just pushed some extra verbose logging. Could you post your log for when it is failing? And, just to make sure, can you also

    rm -rf ~/.cache/simple-scan/autosaves

before testing?

Did the following:
0. $ ~/.cache/simple-scan/autosaves/autosaves.db
1. $ simple-scan test
2. Pressing scan
3. Ctrl+C
4. $ simple-scan

It worked some times but not always. The log from a failure is:
[+0.00s] DEBUG: simple-scan.vala:582: Starting Simple Scan 3.6.0, PID=11515
[+0.00s] DEBUG: Connecting to session manager
[+0.04s] WARNING: g_object_set_valist: invalid object type `GtkAdjustment' for value type `GtkWidget'
[+0.04s] DEBUG: ui.vala:1463: Restoring window to 774x607 pixels
[+0.04s] DEBUG: autosave-manager.vala:87: creating a new instance of the autosave manager
[+0.04s] DEBUG: autosave-manager.vala:220: Executing query "
            CREATE TABLE IF NOT EXISTS pages (
                id integer PRIMARY KEY,
                process_id integer,
                page_hash integer,
                book_hash integer,
                book_revision integer,
                page_number integer,
                dpi integer,
                width integer,
                height integer,
                depth integer,
                n_channels integer,
                rowstride integer,
                color_profile string,
                crop_x integer,
                crop_y integer,
                crop_width integer,
                crop_height integer,
                scan_direction integer,
                pixels binary
            )"
[+0.06s] DEBUG: autosave-manager.vala:117: preparing query "
                   SELECT process_id, book_hash, book_revision FROM pages
                   WHERE NOT process_id IN (11515)
                   LIMIT 1
                "
[+0.06s] DEBUG: autosave-manager.vala:123: found at least one autosave page, taking ownership
[+0.06s] DEBUG: autosave-manager.vala:139: Executing query "
                        UPDATE pages
                           SET process_id = 11515
                         WHERE process_id = 11505
                           AND book_hash = -671049168
                           AND book_revision = 0"
[+0.06s] DEBUG: autosave-manager.vala:404: preparing query "
            SELECT process_id,
                page_hash,
                book_hash,
                book_revision,
                page_number,
                dpi,
                width,
                height,
                depth,
                n_channels,
                rowstride,
                color_profile,
                crop_x,
                crop_y,
                crop_width,
                crop_height,
                scan_direction,
                pixels,
                id
            FROM pages
            WHERE process_id = 11515
              AND book_revision = (
                  SELECT MAX(book_revision) FROM pages WHERE process_id = 11515
              )
            ORDER BY page_number
        "
[+0.06s] DEBUG: autosave-manager.vala:474: no pages found to recover
[+0.06s] DEBUG: autosave-manager.vala:57: setting book to autosave
[+0.06s] DEBUG: autosave-manager.vala:72: connecting to signals of new book
[+0.10s] DEBUG: scanner.vala:1419: sane_init () -> SANE_STATUS_GOOD
[+0.10s] DEBUG: scanner.vala:1425: SANE version 1.0.23
[+0.10s] DEBUG: scanner.vala:1486: Requesting redetection of scan devices
[+0....

Log when the database was created:
[+0.00s] DEBUG: simple-scan.vala:582: Starting Simple Scan 3.6.0, PID=11458
[+0.00s] DEBUG: Connecting to session manager
[+0.03s] WARNING: g_object_set_valist: invalid object type `GtkAdjustment' for value type `GtkWidget'
[+0.03s] DEBUG: ui.vala:1463: Restoring window to 774x607 pixels
[+0.03s] DEBUG: autosave-manager.vala:87: creating a new instance of the autosave manager
[+0.03s] DEBUG: autosave-manager.vala:220: Executing query "
            CREATE TABLE IF NOT EXISTS pages (
                id integer PRIMARY KEY,
                process_id integer,
                page_hash integer,
                book_hash integer,
                book_revision integer,
                page_number integer,
                dpi integer,
                width integer,
                height integer,
                depth integer,
                n_channels integer,
                rowstride integer,
                color_profile string,
                crop_x integer,
                crop_y integer,
                crop_width integer,
                crop_height integer,
                scan_direction integer,
                pixels binary
            )"
[+0.23s] DEBUG: autosave-manager.vala:117: preparing query "
                   SELECT process_id, book_hash, book_revision FROM pages
                   WHERE NOT process_id IN (11458)
                   LIMIT 1
                "
[+0.23s] DEBUG: autosave-manager.vala:57: setting book to autosave
[+0.23s] DEBUG: autosave-manager.vala:72: connecting to signals of new book
[+0.23s] DEBUG: autosave-manager.vala:300: adding an autosave for a new page
[+0.23s] DEBUG: autosave-manager.vala:313: Executing query "
            INSERT INTO pages
                (process_id,
                page_hash,
                book_hash,
                book_revision)
                VALUES
                (11458,
                20112144,
                1744869936,
                0)
        "
[+0.39s] DEBUG: autosave-manager.vala:322: updating the autosave for a page
[+0.39s] DEBUG: autosave-manager.vala:351: preparing query "
            UPDATE pages
                SET
                page_number=0,
                dpi=300,
                width=2362,
                height=2362,
                depth=0,
                n_channels=0,
                rowstride=0,
                crop_x=0,
                crop_y=0,
                crop_width=0,
                crop_height=0,
                scan_direction=0,
                color_profile=?1,
                pixels=?2
                WHERE process_id = 11458
                  AND page_hash = 20112144
                  AND book_hash = 1744869936
                  AND book_revision = 0
            "
[+0.58s] DEBUG: scanner.vala:1419: sane_init () -> SANE_STATUS_GOOD
[+0.58s] DEBUG: scanner.vala:1425: SANE version 1.0.23
[+0.58s] DEBUG: scanner.vala:1486: Requesting redetection of scan devices
[+0.58s] DEBUG: scanner.vala:776: Processing request
[+1.73s] DEBUG: simple-scan.vala:310: Requesting scan at 150 dpi from device 'test'
[+1.73s] DEBUG: scanner.vala:1532: Scanner.scan ("test", dpi=150, scan_mode=ScanMode.GRAY, depth=2, type=ScanType...

I think I've got it. The book_hash parameter may be formatted as a signed
int by vala into the query, and then it doesn't match unsigned value in the
record.

I'll do the proper thing and use bind_int for these things. I'll let you
know as soon as I've pushed an updated version.

Thanks for the extensive logs and testing!

Could you test again? I could reproduce the problems with your database but I can't generate the same erroneous database on my machine, so I can't be 100% sure this last commit tackled the problem.

Pushed with some coding style changes, thanks for the patience!