dbremote internal error

[bgreiman]

We are using SQL Anywhere v12.0.1.4436 on a Windows Server 2016 box. We are trying to create a remote database that will sync using dbremote on one end with a consolidated database (1) running SQL Anywhere v12. On the other end it will sync with another consolidated database (2) running SQL Server using Mobilink.

Setup steps: 1. Extract database and sync up using dbremote. 2. Setup publication, user for Mobilink to sync with SQL Server. 3. Run Mobilink to sync with SQL Server. 4. The very next time we run dbremote, it crashes with an "Internal Error - dbremote" popup window when it is "scanning logs starting at offset..." 5. We are now in a place where we can no longer sync from consolidated database (1).

Any ideas of where to go next or what may be causing our issues.

Thanks, Brian

[regdomaratzki]

Can you run dbtran against the transaction log that dbremote is scanning when it crashes?

[bgreiman]

Yes I can successfully translate all log files without issue.

[bgreiman]

I am able to reproduce on a different server as well.

[regdomaratzki]

We're likely going to need more details. I have no trouble creating a database that is both a remote database in the MobiLink environment and and consolidated database in a SQL Remote environment.

The script I run to create tables and MobiLink Client definitions :

set option public.Global_database_id = 1;
set option public.delete_old_logs = 'ON';

create table Admin (
  admin_id bigint default global autoincrement(1000000) primary key,
  data     varchar(64)
);

create publication p1 ( table Admin );
create synchronization user "rem1";
create synchronization subscription to p1 for "rem1" 
  type 'http' address 'host=localhost;port=8071' script version 'v17';
create synchronization profile sp1 'mp=sql;u=rem1;n=p1;verbosity=high';

The script I run to make the same database a consolidated database for SQL Remote :

GRANT CONNECT TO srcons IDENTIFIED BY sql;
GRANT PUBLISH TO srcons;
CREATE REMOTE MESSAGE TYPE FILE ADDRESS 'srcons';

GRANT CONNECT TO srrem1 IDENTIFIED BY 'sql';
GRANT REMOTE TO srrem1 TYPE FILE ADDRESS 'srrem1';
GRANT REMOTE DBA TO srrem1;
CREATE SUBSCRIPTION TO p1 FOR srrem1;
START SUBSCRIPTION TO p1 FOR srrem1;

I then run dbmlsync and synchronize the database from the MobiLink consolidated database, and then run SQL Remote, and it generates messages to send to the 'srrem1' remote user.

Reg

[bgreiman]

What is slightly different in our environment is that our database is a remote database for both SQL Remote and DB Mobilink.

I run the statements described for Mobilink with exception of the create synchronization profile.

SQL Remote statements are similar to what you are suggesting.

Brian

[bgreiman]

I have been doing more testing with no luck yet. Here is output log from dbremote session. Just prior to this I had run dbmlsync and it must have written something to the log file to cause the internal error. The last line of this outout is when the dbremote internal error is triggered and then I am dead in the water.

I. 2019-03-20 13:53:48. SQL Remote Message Agent Version 12.0.1.4436
I. 2019-03-20 13:53:48. 
I. 2019-03-20 13:53:48. Copyright © 2001-2015, iAnywhere Solutions, Inc.
I. 2019-03-20 13:53:48. Portions copyright © 1988-2015, Sybase, Inc. All rights reserved.
I. 2019-03-20 13:53:48. Use of this software is governed by the Sybase License Agreement.
I. 2019-03-20 13:53:48. Refer to http://www.sybase.com/softwarelicenses.
I. 2019-03-20 13:53:48. 
I. 2019-03-20 13:53:48. Received message from "dbo" (0-015916402066102-015916405123573-0)
I. 2019-03-20 13:53:48. Applying message from "dbo" (0-015916402066102-015916405123573-0)
I. 2019-03-20 13:53:48. Scanning logs starting at offset 0005177386
I. 2019-03-20 13:53:48. Processing transaction logs from directory "c:\\bersys"
W. 2019-03-20 13:53:48. Internal Error: The truncation offset '0004945625' is greater than the minimum of progress offsets or the minimum of confirm_sent offsets '0003811350'.  Old log file(s) will not be deleted
I. 2019-03-20 13:53:48. Processing transactions from active transaction log
I. 2019-03-20 13:53:48. Transaction log renamed to: c:\\bersys\\190320AH.LOG
I. 2019-03-20 13:53:48. Sending message to "dbo" (0-0005177386-0005177386-0)
I. 2019-03-20 13:53:49. Execution completed
I. 2019-03-20 13:55:23. SQL Remote Message Agent Version 12.0.1.4436
I. 2019-03-20 13:55:23. 
I. 2019-03-20 13:55:23. Copyright © 2001-2015, iAnywhere Solutions, Inc.
I. 2019-03-20 13:55:23. Portions copyright © 1988-2015, Sybase, Inc. All rights reserved.
I. 2019-03-20 13:55:23. Use of this software is governed by the Sybase License Agreement.
I. 2019-03-20 13:55:23. Refer to http://www.sybase.com/softwarelicenses.
I. 2019-03-20 13:55:23. 
I. 2019-03-20 13:55:23. Received message from "dbo" (0-015916405123573-015916409284143-0)
I. 2019-03-20 13:55:23. Applying message from "dbo" (0-015916405123573-015916409284143-0)
I. 2019-03-20 13:55:23. Scanning logs starting at offset 0005177386
I. 2019-03-20 13:55:23. Processing transaction logs from directory "c:\\bersys"
I. 2019-03-20 13:55:23. Transaction log "c:\\bersys\\190320AH.LOG" starts at offset 0005177386
I. 2019-03-20 13:55:23. Processing transactions from transaction log "c:\\bersys\\190320AH.LOG"
I. 2019-03-20 13:55:23. Transaction log ends at offset 0005199013
I. 2019-03-20 13:55:23. Processing transactions from active transaction log
I. 2019-03-20 13:59:29. SQL Remote Message Agent Version 12.0.1.4436
I. 2019-03-20 13:59:29. 
I. 2019-03-20 13:59:29. Copyright © 2001-2015, iAnywhere Solutions, Inc.
I. 2019-03-20 13:59:29. Portions copyright © 1988-2015, Sybase, Inc. All rights reserved.
I. 2019-03-20 13:59:29. Use of this software is governed by the Sybase License Agreement.
I. 2019-03-20 13:59:29. Refer to http://www.sybase.com/softwarelicenses.
I. 2019-03-20 13:59:29. 
I. 2019-03-20 13:59:29. Received message from "dbo" (0-015916409284143-015916413224119-0)
I. 2019-03-20 13:59:29. Applying message from "dbo" (0-015916409284143-015916413224119-0)
I. 2019-03-20 13:59:30. Received message from "dbo" (0-015916413224119-015916416524252-0)
I. 2019-03-20 13:59:30. Applying message from "dbo" (0-015916413224119-015916416524252-0)
I. 2019-03-20 13:59:30. Scanning logs starting at offset 0005177386
I. 2019-03-20 13:59:30. Processing transaction logs from directory "c:\\bersys"
I. 2019-03-20 13:59:30. Transaction log "c:\\bersys\\190320AH.LOG" starts at offset 0005177386
I. 2019-03-20 13:59:30. Processing transactions from transaction log "c:\\bersys\\190320AH.LOG"
I. 2019-03-20 13:59:30. Transaction log ends at offset 0005199013
I. 2019-03-20 13:59:30. Transaction log "c:\\bersys\\localold.log" starts at offset 0005199013
I. 2019-03-20 13:59:30. Processing transactions from transaction log "c:\\bersys\\localold.log"

[regdomaratzki]

Can you try adding -hd (it's a hidden switch) to the dbremote command line? It will print extra information into the dbremote log for the log scanning layer. You should hopefully see the last operation it successfully scans, then run dbtran on the tranasction log, and you should be able to see the next operation in the log that caused the problem. I'm curious what it is.

Reg

PS: Please surround the next log file you post with <pre> and </pre> so line breaks show up nicely.

[bgreiman]

Here is the end of the output log with -hd flag:

I. 2019-03-20 14:15:06. Transaction log ends at offset 0005199013
I. 2019-03-20 14:15:06. Transaction log "c:\\bersys\\localold.log" starts at offset 0005199013
I. 2019-03-20 14:15:06. Processing transactions from transaction log "c:\\bersys\\localold.log"
I. 2019-03-20 14:15:06. Temporary file pages allocated in lifetime: 45
I. 2019-03-20 14:15:06. Temporary file pages freed in lifetime:     45
I. 2019-03-20 14:15:06. Temporary file current page count:          0
I. 2019-03-20 14:15:06. Temporary file biggest page count:          5
I. 2019-03-20 14:15:06. 0005203129 Startup         5  10 727
I. 2019-03-20 14:15:06. 0005203134 Connect        11   8 727
I. 2019-03-20 14:15:06. 0005203145 Begin_Transaction       3   8 727
I. 2019-03-20 14:15:06. 0005203148 Remote         24   8 727
I. 2019-03-20 14:15:06. 0005203172 Commit          3   8 727
I. 2019-03-20 14:15:06. 0005203175 Release         7   8 727
I. 2019-03-20 14:15:06. 0005203182 Connect        18  15 727
I. 2019-03-20 14:15:06. 0005203200 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203249 Generic_OP         54  15 727
I. 2019-03-20 14:15:06. 0005203303 Commit          3  15 727
I. 2019-03-20 14:15:06. 0005203306 Generic_OP         54  15 727
I. 2019-03-20 14:15:06. 0005203360 Commit          3  15 727
I. 2019-03-20 14:15:06. 0005203363 Generic_OP         79  15 727
I. 2019-03-20 14:15:06. 0005203442 Generic_OP         57  15 727
I. 2019-03-20 14:15:06. 0005203499 Commit          3  15 727
I. 2019-03-20 14:15:06. 0005203502 Generic_OP         54  15 727
I. 2019-03-20 14:15:06. 0005203556 Commit          3  15 727
I. 2019-03-20 14:15:06. 0005203559 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203608 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203657 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203706 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203755 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203804 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203853 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203902 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005203951 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204000 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204049 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204098 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204147 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204196 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204245 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204294 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204343 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204392 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204441 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204490 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204539 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204588 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204637 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204686 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204735 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204784 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204833 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204882 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204931 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005204980 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005205029 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005205078 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005205127 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005205176 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005205225 Generic_OP         49  15 727
I. 2019-03-20 14:15:06. 0005205274 Generic_OP         49  15 727

Here is from translated log file --APPLICATION CONNECTION REGISTRATION STAMP:-1015-0005205274 -- app_Name = sybase.asa.dbmlsync -- app_info_str = uid=dbmisc_new; -- conn_label = Main -- status = 0x3

[regdomaratzki]

Are there 46 --APPLICATION CONNECTION REGISTRATION STAMP entries in a row in the transaction log?

What's the operation at offset 5205223?

[bgreiman]

I am only seeing 43 of these statements together.

No operation at offset 5205223:

--APPLICATION CONNECTION REGISTRATION STAMP:-1015-0005205176
--  app_Name = sybase.asa.dbmlsync
--  app_info_str = uid=dbmisc_new;
--  conn_label = Main
--  status = 0x3
--APPLICATION CONNECTION REGISTRATION STAMP:-1015-0005205225
--  app_Name = sybase.asa.dbmlsync
--  app_info_str = uid=dbmisc_new;
--  conn_label = Main
--  status = 0x1000003

[regdomaratzki]

Typo. I meant which operation is at offset 5205323 (5205274 + 49) ?

[bgreiman]

--APPLICATION CONNECTION REGISTRATION STAMP:-1015-0005205323
--  app_Name = sybase.asa.dbmlsync
--  app_info_str = uid=dbmisc_new;
--  conn_label = Main
--  status = 0x1000003
 and 

[bgreiman]

I re-extracted a new remote database. I upgraded my environment to SAv17. I ran dbremote to sync with my consolidated SQL Anywhere DB (only downloaded messages, did not upload), then ran Mobilink to sync with my SQL Server consolidated db, then ran dbremote again. The result is that dbremote crashed again and at exactly the same spot in the log file (different offsets of course because it is a new db).

Here is last line of dbremote output log at the point it crashed with an internal error:

 
I. 2019-03-21 14:54:58. 0004377629 Generic_OP         49  16   0

 
Here are statements from log file surrounding offset 0004377629:
--APPLICATION CONNECTION REGISTRATION STAMP:-1016-0004377580
--  app_Name = sybase.asa.dbmlsync
--  app_info_str = uid=dbmisc_new;
--  conn_label = Main
--  status = 0x1000003
--APPLICATION CONNECTION REGISTRATION STAMP:-1016-0004377629
--  app_Name = sybase.asa.dbmlsync
--  app_info_str = uid=dbmisc_new;
--  conn_label = Main
--  status = 0x3
--APPLICATION CONNECTION REGISTRATION STAMP:-1016-0004377678
--  app_Name = sybase.asa.dbmlsync
--  app_info_str = uid=dbmisc_new;
--  conn_label = Main
--  status = 0x1000003

So I can get this to fail in both v12 and v17.

Is there one table that is causing the issue seeing that it fails at the same point (36th instance of "APPLICATION CONNECTION REGISTRATION STAMP" from the translated log file)?

Any further suggestions?

Thanks, Brian

[regdomaratzki]

It's not really answer, I'm trying to start a new "thread". I'll convert it to a comment on the main question eventually, but I just want to clear up some assumptions I've made and highlight the post.

Question : When you say "I'm using v12" or "I'm using v17" I've assumed that everything is the same version. The SQL Anywhere database engines, the version of SQL Remote, dbmlsync and the ML Server and even the version of dbinit used to create your databases are all the same version. Is that correct?

Question : I want to be clear what you mean by crash and internal error. I've assumed you mean that the SQL Remote process GPFs and stops, which is why the last line in the dbremote log is just about scanning the active transaction log. Are crash dump files being created in "%ALLUSERSPROFILE%\\SQL Anywhere 17\\diagnostics" ?

Comment/Question : I'm confused on why you have so many --APPLICATION CONNECTION REGISTRATION STAMP entries in the transaction log in a row, with nothing else between them. Did you define a schedule in your synchronization subscription to synchronize "EVERY:00:00"? Does the problem go away if you use a less aggressive schedule, or remove the schedule outright and physically run dbmlsync every time you want to synchronize?

I might need to get the database and transaction log in house and run dbremote against the database myself to get to the bottom of these. Let's get answers to the questions above before we go that route though.

Reg

PS : My responses are delayed and sporadic here because paying customers are getting a lot of my attention right now.

[bgreiman]

Everything in my environment is the same version.  I am using version 12.01 with the latest and greatest ebf and encountering the issue.  I thought I would try to use v17 latest ebf to see if maybe this issue was fixed somewhere along the way or did not encounter the same behavior.  I am moving back to v12 to eliminate any further confusion.  We would like to stay with v12 anyways as that is what all of our production systems are using.  For v12, everything we are using is v12 including dbremote, dbmlsync, dbinit, etc.

To recap my steps:
1. Run extraction from production database to create a remote SQL Anywhere database.

2. Copy over and start new remote database and successfully replicate with SQL Anywhere consolidated using dbremote.

dbremote.exe -hd -l 500000 -k -x -o c:\\bersys\\1191_dbremote.txt -c "dbn=sa;eng=sa;uid=xxx;pwd=xxx" c:\\bersys

3. Add new publication pub_ml_audits containing 21 tables and ml user to remote database.
CREATE PUBLICATION "DBA"."pub_ml_audits" (
    TABLE "DBA"."cn_chain",
    TABLE "DBA"."company",
    TABLE "DBA"."customer",
    TABLE "DBA"."py_employee",
    TABLE "DBA"."rt_category",
    TABLE "DBA"."rt_request",
    TABLE "DBA"."rt_request_asset",
    TABLE "DBA"."rt_request_group",
    TABLE "DBA"."rt_request_part",
    TABLE "DBA"."rt_request_survey",
    TABLE "DBA"."rt_request_survey_category",
    TABLE "DBA"."rt_request_survey_category_include",
    TABLE "DBA"."rt_request_survey_machine_type",
    TABLE "DBA"."rt_request_survey_response_description",
    TABLE "DBA"."rt_request_survey_responses",
    TABLE "DBA"."rt_request_survey_topics",
    TABLE "DBA"."rt_request_type",
    TABLE "DBA"."sy_next_record_key",
    TABLE "DBA"."sy_work_group",
    TABLE "DBA"."vn_machine",
    TABLE "DBA"."vn_machine_type"
);
CREATE SYNCHRONIZATION USER "bersys_realm_audits" TYPE 'TCPIP';
CREATE SYNCHRONIZATION SUBSCRIPTION TO "DBA"."pub_ml_audits" FOR "bersys_realm_audits" TYPE 'TCPIP' SCRIPT VERSION 'v1';


4. Start Mobilink v12 server running against SQL Server database.

5. Run dbmlsync to sync data from remote database to SQL Server consolidated database:
dbmlsync -k -c "dbn=sa;eng=sa;uid=xxx;xxx=2afrup5a;" -u "bersys_realm_audits" -vno -e "LockTables=OFF;FT=off;sv=v1;adr='host=192.168.0.252;port=2440'" -n "pub_ml_audits" -o c:\\bersys\\ml_sync.txt c:\\bersys

Everything ran as normal.  No errors.

Re: dbmlsync – we are only triggering once, there is no schedule.  


6. Run dbremote to once again replicate data from remote SQL Anywhere database to SQL Anywhere consolidated database.  New messages are read in, then log files are scanned to send messages and this is when we get crash.  A small popup window in top left corner saying Internal Error – dbremote with the options of View Error Report, Send Error Report, Don’t Send.  I have been clicking the Send Error Report to send data to SAP/Sybase.  Crash dump file are being created.  At this point we can no longer replicate.

Let me know what information you may need.  I sincerely appreciate all of your help as we try to get over this hurdle.

Thanks,
Brian

[regdomaratzki]

I would like to get the following from you :

1) The output log from when you ran dbmlsync (c:\\bersys\\ml_sync.txt)

2) The database and all transaction logs from the database that you run dbremote against to generate the crash.

3) The dbremote command line (including userid and password) used when dbremote runs and crashes scanning the transaction log.

If the files aren't too large, just email them to me. My email address is firstname.lastname@sap.com (you should clearly replace "firstname" and "lastname" with my actual first and last name). If the files are large, email me and we'll figure some other way for you to get me the files.

Reg

[regdomaratzki]

Brian and I followed up offline since I needed his database to reproduce the issue. I though I should come back to the forum and share our progress since we figured out the root cause of the crash and were able to workaround the problem.

dbremote was crashing because it scanned a large number of consecutive APPLICATION CONNECTION REGISTRATION STAMP entries in the transaction log. I believe (but still need to confirm) that "large" in this case means more than 32. It's still not clear why dbremote is crashing, and why dbtran and dbmlsync do not crash when scanning the same section of the log, and fixing the crash is still a work in progress. More importantly for Brian, we were able to find a workaround, allowing him to stay at v12.

What is an APPLICATION CONNECTION REGISTRATION STAMP log entry?

An APPLICATION CONNECTION REGISTRATION STAMP is placed in the transaction log by dbmlsync as a placeholder so that dbmlsync knows when scanning the log to send operation to the MobiLink Server to ignore operations in the transaction log for this connection, since it is dbmlsync applying the download stream. In most cases, you see two of these entries for a synchronization, the first indicating that operations should be ignored, and a second to indicate that operations should no longer be ignored. However, if you have defined hooks procedures that fire during the download (for example sp_hook_dbmlsync_download_table_begin), dbmlsync writes APPLICATION CONNECTION REGISTRATION STAMP entries into the log surrounding the execution of the hook procedure, to make sure the operations executed in the hook are not ignored. If you've defined a single hook procedure that fires for every table, and you have "x" tables, you will end up with "2x+2" APPLICATION CONNECTION REGISTRATION STAMP entries in the transaction log for each synchronization.

Now imagine that your download stream from the MobiLink Server contains no data, and the execution of the hook procedure does not result in any operations being written to the transaction log. If you have 22 tables in your remote database, you end up with 46 consecutive APPLICATION CONNECTION REGISTRATION STAMP log entries in a row, and dbremote (but NOT dbmlsync or dbtran) will crash processing these operations in the transaction log.

There are two workarounds to avoid the issue :

1. Remove the hook procedures.
2. Ensure that the hook procedure always writes something to the transaction log. This will make sure that we never end up with consecutive APPLICATION CONNECTION REGISTRATION STAMP log entries, avoiding the crash.

An example for workaround #2 might look something like :

create procedure sp_hook_dbmlsync_download_table_begin()
begin
  declare @uuid varchar(128);
  set @uuid = UUIDTOSTR(newid());
  set option PUBLIC.logSomething = @uuid;
  message 'sp_hook_dbmlsync_download_table_begin does stuff now';
end;

Setting an option will be logged, as long as the option changes, which is why I've gone to trouble of using a GUID value in the example above.

Reg