MOUNT DATABASE command fails due to ASE error 3404

[neal_stack2]

Hello,

I have two customers experiencing this issue on fairly recent versions of ASE:

15.7 SP138

16.0 SP02 PL05

I'm trying to understand:

1) How can I reproduce it? I do not believe they are using DTM ("enable xact coordination==0"). It appears that they are creating transactions across databases in a single ASE instance. I've tried many combinations of the below (leaving cross database transactions open, committing the transactions, etc).

2) Is the error 3404 actually valid in this situation? It seems like when we do the "LOAD DATABASE", it goes through the same REDO processing as the "MOUNT DATABASE" but it doesn't throw the error during the "LOAD DATABASE" phase.

3) If the error is valid, is there any way to recover from it? Any DBCC commands? Any trace flags? Once the error is thrown, the database is left suspect.

We created a dummy database:

1> sp_helpdb delphix_test
2> go
 name        db_size      owner        dbid created      durability
        lobcomplvl inrowlen status        
 ------------ ------------- ------------ ---- ------------ ----------
        ---------- -------- -------------- 
 delphix_test    1650.0 MB delphixdbstg    8 Sep 06, 2017 full      
                  0        0 no options set 

(1 row affected)

 device_fragments              size          usage    created            
        free_kbytes      
 ------------------------------ ------------- --------- -------------------
        ---------------- 
 AABD$p933bWL1Y3vfdOz_str_dev18      400.0 MB data only Nov 16 2017  2:22PM
                    91968 
 AABE$vv3n7Cv0lqbSmWd_str_dev28      50.0 MB log only  Nov 16 2017  2:22PM
        not applicable  
 AABD$p933bWL1Y3vfdOz_str_dev18    1150.0 MB data only Nov 16 2017  2:22PM
                  950666 
 AABE$vv3n7Cv0lqbSmWd_str_dev28      50.0 MB log only  Nov 16 2017  2:22PM
        not applicable  

 -------------------------------------------------------------------------------------------------------------- 
 log only free kbytes = 101978  

We load the "bad" database dump:

1> load database delphix_test from "/users/db/dump/my_database.db_backup.20171017.110037.693.1"
2> go
Backup Server session id is: 103. Use this value when executing the
'sp_volchanged' system stored procedure after fulfilling any volume change
request from the Backup Server.
Backup Server: 6.28.1.1: Dumpfile name 'd_instr1729009AD5' section number 1
mounted on disk file
'/users/db/dump/my_database.db_backup.20171017.110037.693.1'
Backup Server: 4.188.1.1: Database delphix_test: 17590 kilobytes (1%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 94224 kilobytes (5%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 147570 kilobytes (8%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 156374 kilobytes (9%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 184858 kilobytes (10%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 206366 kilobytes (12%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 227368 kilobytes (13%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 240578 kilobytes (14%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 259328 kilobytes (15%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 277086 kilobytes (16%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 504486 kilobytes (29%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 523844 kilobytes (31%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 744502 kilobytes (44%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 787512 kilobytes (46%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 830522 kilobytes (49%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 873020 kilobytes (51%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 916030 kilobytes (54%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 959040 kilobytes (56%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1000002 kilobytes (59%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1043012 kilobytes (61%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1086022 kilobytes (64%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1128520 kilobytes (66%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1171530 kilobytes (69%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1214540 kilobytes (71%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1257038 kilobytes (74%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1300048 kilobytes (76%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1343058 kilobytes (79%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1385556 kilobytes (82%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1428566 kilobytes (84%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1471576 kilobytes (87%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1514074 kilobytes (89%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1557084 kilobytes (92%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1600094 kilobytes (94%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1642080 kilobytes (97%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1685090 kilobytes (99%) LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1689698 kilobytes (100%)
LOADED.
Backup Server: 4.188.1.1: Database delphix_test: 1689716 kilobytes (100%)
LOADED.
Backup Server: 3.42.1.1: LOAD is complete (database delphix_test).
Started estimating recovery log boundaries for database 'delphix_test'.
Database 'delphix_test', checkpoint=(219624, 14), first=(219624, 14),
last=(219629, 15).
Completed estimating recovery log boundaries for database 'delphix_test'.
Started ANALYSIS pass for database 'delphix_test'.
Completed ANALYSIS pass for database 'delphix_test'.
Started REDO pass for database 'delphix_test'. The total number of log records
to process is 77.
Redo pass of recovery has processed 11 committed and 0 aborted transactions.
Completed REDO pass for database 'delphix_test'.
Use the ONLINE DATABASE command to bring this database online; ASE will not
bring it online automatically.
Object 'dba_table_perm_model' in database 'delphix_test' is owned by login 'wmd'
who does not exist in this server.
Object 'dba_proc_perm_model' in database 'delphix_test' is owned by login 'wmd'
who does not exist in this server.
Object 'dba_view_perm_model' in database 'delphix_test' is owned by login 'wmd'
who does not exist in this server.

Notice it passes the "REDO" part of recovery successfully during the "LOAD DATABASE". We do not bring it online.

Then we unmount the database and remount it but it fails during the same REDO phase:

1> unmount database delphix_test to "/tmp/delphix_test.manifest"
2> go
1> mount database delphix_test from "/tmp/delphix_test.manifest" with listonly
2> go
[database]
delphix_test
[device]
'/users/delphix/toolkit/420880d0-5291-a61b-bd58-d0d240635588-vdb-146/datafile/dxv3Uvuzxf33Is1d5b_str_dev18' = 'AABD$p933bWL1Y3vfdOz_str_dev18'

'/users/delphix/toolkit/420880d0-5291-a61b-bd58-d0d240635588-vdb-146/datafile/dx7vfcv7P9csr3bsV9_str_dev28' = 'AABE$vv3n7Cv0lqbSmWd_str_dev28'

1> mount database delphix_test from "/tmp/delphix_test.manifest" USING
2> '/users/delphix/toolkit/420880d0-5291-a61b-bd58-d0d240635588-vdb-146/datafile/dxv3Uvuzxf33Is1d5b_str_dev18' = 'AABD$p933bWL1Y3vfdOz_str_dev18',
3> 
4> '/users/delphix/toolkit/420880d0-5291-a61b-bd58-d0d240635588-vdb-146/datafile/dx7vfcv7P9csr3bsV9_str_dev28' = 'AABE$vv3n7Cv0lqbSmWd_str_dev28'
5> go
Started estimating recovery log boundaries for database 'delphix_test'.
Database 'delphix_test', checkpoint=(219624, 14), first=(219624, 14),
last=(219629, 15).
Completed estimating recovery log boundaries for database 'delphix_test'.
Started ANALYSIS pass for database 'delphix_test'.
Completed ANALYSIS pass for database 'delphix_test'.
Started REDO pass for database 'delphix_test'. The total number of log records
to process is 77.
Msg 913, Level 22, State 2:
Server 'SQL_X360', Line 1:
Could not find row in sysdatabases with database id 11.
Msg 3404, Level 21, State 1:
Server 'SQL_X360', Line 1:
Rec_complete: Could not open controlling database (id 11) of controlling
database in multi-db transaction.
Msg 145, Level 17, State 10:
Server 'SQL_X360', Line 1:
A subquery with no aggregate functions may only contain expressions in its GROUP
BY clause that are in the select-list.
Msg 145, Level 14, State 10:
Server 'SQL_X360', Line 1:
A subquery with no aggregate functions may only contain expressions in its GROUP
BY clause that are in the select-list.

Thanks in advance,

Neal

[neal_stack2 · Accepted solution]

SAP reproduced this issue and logged it as ASE bug 812086.