SQL Remote and Missing messages

[thelmacottage]

We have on remote site that is causing is a headache with replication to the consolidated.

I the consolidated logs I can see the following error message. Subsequently the remote site starts re-sending many many messages - yesterday we had over 35,000 messages sitting on the remote site waiting to be sent to the consolidated DB - it seems the consolidated can not keep up ? and keeps asking for more re-sends.

To fix this I had to stop both remote services on the consolidate and remote and manually move over all 35,000 messages to the consolidated. It then process on the consolidated with lot's of 'not applying messages already sent' log entries. Once this had processed I sent back the generated messages back to the remote site, ran SQL remote which then generated 4000 messages - stopped the remote service again and moved back onto the consolidated and ran the remote service again on the consolidated. Only then was everything up to date !

The remote site seems to generate too many messages ? (other sites are fine)

How can I overcome this ? I have seen the parameters -rp and -rd would this help at the consolidated end ?

Could I increase the message size at the remote end ?

Any help would be appreciated.

I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-5)
I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-6)
E. 2018-08-15 11:27:11. Missing message from "STORE18" (1185-0146025996339-0146025996339-7)
I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-7)
I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-8)
I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-9)

CONSOLIDATED SQLREMOTE LOG (THELMA)

I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146010491871-0146025996339-0) I. 2018-08-15 11:26:06. Applying message from "STORE18" (1185-0146010491871-0146025996339-0) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-0) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-1) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-2) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-3) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-4) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-5) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-6) I. 2018-08-15 11:26:06. Received message from "STORE99" (0-0491193910-0491193910-0) I. 2018-08-15 11:26:06. Applying message from "STORE99" (0-0491193910-0491193910-0) E. 2018-08-15 11:27:11. Missing message from "STORE18" (1185-0146025996339-0146025996339-7) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-7) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-8) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-9) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-10)

I. 2018-08-15 11:35:57. Received message from "STORE18" (1185-0146025996339-0146025996339-341) E. 2018-08-15 11:37:02. Missing message from "STORE18" (1185-0146025996339-0146025996339-0) I. 2018-08-15 11:37:02. Sending message to "STORE18" (0-0656829574195-0656829574195-0)

W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-343) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-344) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-345) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-346) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-347) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-348) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-349) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-350) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-351) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-352)

REMOTE SQL LOG (STORE18)

I. 2018-08-15 11:33:42. Sending message to "THELMA1" (1185-0146066512533-0146066573816-2) I. 2018-08-15 11:35:45. Received message from "THELMA1" (0-0656787964325-0656829574195-0) I. 2018-08-15 11:35:45. Applying message from "THELMA1" (0-0656787964325-0656829574195-0) I. 2018-08-15 11:40:56. Received message from "THELMA1" (0-0656829574195-0656829574195-0) I. 2018-08-15 11:40:56. Applying message from "THELMA1" (0-0656829574195-0656829574195-0) I. 2018-08-15 11:40:56. Resend requests are being queued I. 2018-08-15 11:45:59. Received message from "THELMA1" (0-0656829574195-0656853033002-0) I. 2018-08-15 11:45:59. Applying message from "THELMA1" (0-0656829574195-0656853033002-0) I. 2018-08-15 11:50:06. Scanning logs starting at offset 0146025996339 I. 2018-08-15 11:50:06. Transaction log "c:/sdata/store18.log" starts at offset 0145838045786 I. 2018-08-15 11:50:06. Processing transaction logs from directory "c:\\sdata" I. 2018-08-15 11:50:06. Processing transactions from active transaction log I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-0) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-1) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-2) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-3) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-4) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-5) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-6) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-7) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-8)

[Breck_Carter]

Much more information is necessary to even begin to investigate this problem... you are very familiar with your situation, but WE don't have a clue.

Please show snippets of the diagnostic log from BOTH the consolidated AND the remote, and be very clear which one is which.

Please tell us what version and builds of both SQL Anywhere and Mobilink components (mlsrv and dbmlsync) on both sides, consolidated and remote.

Please be prepared for more requests for information...

...or not ( if it's too much work 🙂

Oh, and there's this: A money-back guarantee on all free support! 🙂

[regdomaratzki]

At first glance, it looks like the remote database had a massive transaction to send, which means SQL Remote had to generate a large number of multi-part messages. The consolidated database was likely not patient enough to wait for the entire multi-part messages to be written before giving up, saying there was a missing message because it couldn't find the last part of the multi-part message, and then deleting the files and asking for a resend.

What is the SQL Remote command line at the consolidated and remote databases? What is the send frequency for the STORE18 user at the consolidated database? What is the send frequency for the consolidated user at the remote site?

Can you please also describe what you mean when you say you "manually move the messages". Typically, all databases in a SQL Remote system have a shared message they all can access.

Reg

[thelmacottage]

Here are some more details including log files from both the remote and consolidated.

Yes, Reg we do have lot's of large BLOB data being input at the remote site.

The CONSOLIDATED is running SQLRemote V 17.07.3399, the REMOTE is running SQLRemote 17.0.9.4804 Using FILE replication

The SEND frequency at the REMOTE is 15 mins

The SQLRemote parameters are just the connection parameters e.g -c "dbn=STORE_DB;uid=dba;pwd=sql" c:\\sdata (same on the consolidated).

Move files - We have a event set up to run every 5 mins - this moves files from the remote folder to the consolidated folder e.g call "MOVE_FILES"('18','\\\\192.168.18.1\\sdata\\consol\\.','e:\\sdata\\consol');

There is a corresponding one set up to copy messages back (every 5mins)

To sort out my problem with the 35,000 messages on the remote I had to trigger this event manually while not running either SQLRemote service just to get the message onto the consolidated server. (Took 6 hours)

Logs from both the Consolidated and Remote in next comment. We are processing more and more BLOB data do this could well be the problem ?

Hope all this helps and you can guide me in the right direction ?

Thanks

[thelmacottage]

CONSOLIDATED SQLREMOTE LOG (THELMA)

I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146010491871-0146025996339-0) I. 2018-08-15 11:26:06. Applying message from "STORE18" (1185-0146010491871-0146025996339-0) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-0) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-1) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-2) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-3) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-4) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-5) I. 2018-08-15 11:26:06. Received message from "STORE18" (1185-0146025996339-0146025996339-6) I. 2018-08-15 11:26:06. Received message from "STORE99" (0-0491193910-0491193910-0) I. 2018-08-15 11:26:06. Applying message from "STORE99" (0-0491193910-0491193910-0) E. 2018-08-15 11:27:11. Missing message from "STORE18" (1185-0146025996339-0146025996339-7) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-7) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-8) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-9) I. 2018-08-15 11:28:17. Received message from "STORE18" (1185-0146025996339-0146025996339-10)

I. 2018-08-15 11:35:57. Received message from "STORE18" (1185-0146025996339-0146025996339-341) E. 2018-08-15 11:37:02. Missing message from "STORE18" (1185-0146025996339-0146025996339-0) I. 2018-08-15 11:37:02. Sending message to "STORE18" (0-0656829574195-0656829574195-0)

W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-343) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-344) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-345) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-346) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-347) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-348) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-349) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-350) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-351) W. 2018-08-15 11:38:17. Not applying operations with old resend count I. 2018-08-15 11:38:17. Received message from "STORE18" (1185-0146025996339-0146025996339-352)

[thelmacottage]

REMOTE SQL LOG (STORE18)

I. 2018-08-15 11:33:42. Sending message to "THELMA1" (1185-0146066512533-0146066573816-2) I. 2018-08-15 11:35:45. Received message from "THELMA1" (0-0656787964325-0656829574195-0) I. 2018-08-15 11:35:45. Applying message from "THELMA1" (0-0656787964325-0656829574195-0) I. 2018-08-15 11:40:56. Received message from "THELMA1" (0-0656829574195-0656829574195-0) I. 2018-08-15 11:40:56. Applying message from "THELMA1" (0-0656829574195-0656829574195-0) I. 2018-08-15 11:40:56. Resend requests are being queued I. 2018-08-15 11:45:59. Received message from "THELMA1" (0-0656829574195-0656853033002-0) I. 2018-08-15 11:45:59. Applying message from "THELMA1" (0-0656829574195-0656853033002-0) I. 2018-08-15 11:50:06. Scanning logs starting at offset 0146025996339 I. 2018-08-15 11:50:06. Transaction log "c:/sdata/store18.log" starts at offset 0145838045786 I. 2018-08-15 11:50:06. Processing transaction logs from directory "c:\\sdata" I. 2018-08-15 11:50:06. Processing transactions from active transaction log I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-0) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-1) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-2) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-3) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-4) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-5) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-6) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-7) I. 2018-08-15 11:50:09. Sending message to "THELMA1" (1187-0146025996339-0146025996339-8)

[regdomaratzki]

I believe that using the -rd and -rp switches at the consolidated will help. Given that you only seem to transfer files every 15 minutes, changing the receive poll time (-rd) to 15 minutes seems like a good start. Allowing SQL Remote to scan messages a few times before (-rp) giving up on looking for the last message in a multi-part message will provide SQL Remote on the sending side more time to generate all the messages in a multi-part message.

Reg

[thelmacottage]

Hi Reg, sorry mis-typed the time between sending files - it is actually 5 mins.

So if I add at the consolidated -rd 5 and -rp 3 this should help ?

What about increasing compression at the REMOTE site from 6 to say 8 - would this reduce the number of multi-part messages ?

Thanks

Mark

[regdomaratzki]

If new messages are only arriving every 5 minutes, then -rd 5 is a great idea. Right now, the default of one minute is being used, but new messages are arriving every five minutes. Adding -rp will also help in case the external process that transfers messages copies files while SQL Remote is generating a large multi-part message and only gets the first parts of the multi-part message.

Compression may or may not help. The issue isn't the size or number of messages, but the time it takes SQL Remote to generate the messages. While the time to right fewer compressed messages to disk will be faster, the time for SQL Remote to compress the messages may offset that benefit. You will need to test whether compression helps with your data in your environment.

Reg

[former_SQLA_member1694934]

It is also possible to increase the send message size one remote at a time if you run the cons dbremote with distinct send and receive parameters. The trick is to configure the cons to accept larger file sizes without sending them, then configure this remote to send larger files, if you choose to you could then configure each of the remotes to do the same. Key here is never to send files larger than the receiving database expects, which is hardest to do at a cons database since these parameters effect all remote databases. Of course you should validate in a test environment so that you know your config files are set up correctly. We successfully increased our send and receive file sizes to 150 remotes by using this process.

Good Luck

Jim