Question Re: Invalid sync sequence ID for remote ID 'X' [2] in Technology Q&A

Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Fri, 03 Mar 2017 13:06:35 GMT

Hello guys,

Just to put everyone in the same page, I've already opened a question about this, but I decided to open another one with a new scenario, following Chris Keating suggestion.

We've facing this issue since Sybase 16.0.0 migration, and we've never got rid of it entirelly. Some other scenarios were already been fixed after I post a question here, while others remain unsolved.

Besides the fact I could not reproduce this scenario yet, I could conclude the cause based on a log analysis.

In my project we use a load balance which distribute the requests to two Mobilink services, each one installed in different machines. In a specific case, it seems the Mobilink requests are duplicated between the two machines. We still don't know if this is a load balance fault or if the Mobilink replicates the request and, in a very bad luck scenario, the load balance divides them, distributing each one for each machine, independently.

Here are the logs:

*********** CLIENT *************
2017-03-02 07:12:54.000 UltraLiteJ Error[-857]: Synchronization failed due to an error on the MobiLink server: [-10244] The MobiLink server has encountered an error and the synchro (DB0012)
2017-03-02 07:18:12.000 UltraLiteJ Error[-794]: Synchronization server failed to commit the upload (DB0184)

*********** SERVER 22222222222 *************
I. 2017-03-02 07:12:54. <307962> Request from "UL 16.0.2193" for: remote ID: 1018, user name: 1109, version: MSERIES.007.037.0000
I. 2017-03-02 07:12:54. <307962> The current synchronization is using a connection with connection ID 'SPID 68'
I. 2017-03-02 07:12:54. <307962> The authenticate_parameters script returned 1000
I. 2017-03-02 07:12:54. <307962> COMMIT Transaction: Authenticate user
I. 2017-03-02 07:12:54. <307962> COMMIT Transaction: Begin synchronization
I. 2017-03-02 07:12:54. <307962> COMMIT Transaction: Upload
I. 2017-03-02 07:12:57. <307962> COMMIT Transaction: Prepare for download
I. 2017-03-02 07:13:01. <307962> Sending the download to the remote database
I. 2017-03-02 07:13:01. <307962> COMMIT Transaction: Download
I. 2017-03-02 07:13:16. <307962> COMMIT Transaction: End synchronization
E. 2017-03-02 07:17:15. <307962> [-10279] Connection was dropped due to lack of network activity
I. 2017-03-02 07:17:15. <307962> Synchronization complete

*********** SERVER 1111111111 *************
I. 2017-03-02 07:12:54. <158257> Request from "UL 16.0.2193" for: remote ID: 1018, user name: 1109, version: MSERIES.007.037.0000
I. 2017-03-02 07:12:54. <158257> The current synchronization is using a connection with connection ID 'SPID 63'
E. 2017-03-02 07:12:54. <158257> [-10002] Consolidated database server or ODBC error:  ODBC: [Microsoft][SQL Server Native Client 11.0][SQL Server]Lock request time out period exceeded. (ODBC State = 42000, Native error code = 1222)
E. 2017-03-02 07:12:54. <158257> [-10002] Consolidated database server or ODBC error:  ODBC: [Microsoft][SQL Server Native Client 11.0][SQL Server]The cursor was not declared. (ODBC State = 42000, Native error code = 16945)
E. 2017-03-02 07:12:54. <158257> [-10343] The remote database identified by remote ID '1018' is already synchronizing or the database connection is unusable: unable to access the lock for that remote ID
I. 2017-03-02 07:12:54. <158257> Synchronization failed
...
I. 2017-03-02 07:18:12. <158351> Request from "UL 16.0.2193" for: remote ID: 1018, user name: 1109, version: MSERIES.007.037.0000
I. 2017-03-02 07:18:12. <158351> The current synchronization is using a connection with connection ID 'SPID 51'
I. 2017-03-02 07:18:12. <158351> The authenticate_parameters script returned 1000
I. 2017-03-02 07:18:12. <158351> COMMIT Transaction: Authenticate user
I. 2017-03-02 07:18:12. <158351> The sync sequence ID in the consolidated database: f9ecb9e6fedc11e68000a59a4ec320d7; the remote previous sequence ID: 00958646fed411e68000a59a4ec320d7, and the current sequence ID: b7e33ff6fedd11e68000a59a4ec320d7
E. 2017-03-02 07:18:12. <158351> [-10400] Invalid sync sequence ID for remote ID '1018'
I. 2017-03-02 07:18:12. <158351> Synchronization failed

My analysis about what happened:

At 07:12:54 the client starts a sync
Service 2 receives the request
Service 1 receives the request right after Service 2 (milliseconds of difference)
Service 1 takes the ownership of the connection, but fails to sync (At 07:12:54), since Server 2 is locking the database
At 07:12:54 (again, milliseconds of difference) the client receives the error and log it
Meanwhile, the Service 1 continues operating in a ghost mode, until dye (At 07:17:15) with no response from the client
It seems this ghost execution from Service 1 left the sync completely inconsistent
At 07:18:12 the client tries another sync, in which Service 2 receives it. But it fails with sequence id error.

Any ideas about what could be happening here? No explicit simultaneous sync calls were made from client. Otherwise it would be logged.

Version 16.0.0 Build 2193 - Microsoft Windows Server 2012

Thank you in advance for your help!

--- UPDATE ---

One of the servers logs a strange disconnect/connect message. It seems the connection keeps alive between the syncs. Is that an usual proceeding?

I. 2017-02-22 12:50:37. <85686> Request from "UL 16.0.2193" for: remote ID: 587, user name: 630, version: MSERIES.007.030.0000
I. 2017-02-22 12:50:37. <85686> COMMIT Transaction: End connection
I. 2017-02-22 12:50:37. <85686> Synchronization connection with connection ID 'SPID 55' has been disconnected
I. 2017-02-22 12:50:37. <85686> Synchronization connection with connection ID 'SPID 51' has been established

--- UPDATE 2 ---

Example of subsequent syncs in a same server, where the sequence id error don't occur.

*********** CLIENT *************
2017-03-06 09:05:51.000 UltraLiteJ Error[-857]: Synchronization failed due to an error on the MobiLink server: [-10244] The MobiLink server has encountered an error and the synchro (DB0012)

*********** SERVER 1111111111 *************
I. 2017-03-06 09:05:37. <77422> Request from "UL 16.0.2193" for: remote ID: 541, user name: 724, version: MSERIES.007.030.0000
I. 2017-03-06 09:05:37. <77422> The current synchronization is using a connection with connection ID 'SPID 63'
I. 2017-03-06 09:05:37. <77422> The authenticate_parameters script returned 1000
I. 2017-03-06 09:05:37. <77422> COMMIT Transaction: Authenticate user
W. 2017-03-06 09:05:37. <77422> [10115] Performance warning: Column '28' in the remote table 'slOrderHistory' has been remapped from 'varchar' to 'text'
I. 2017-03-06 09:05:37. <77422> COMMIT Transaction: Begin synchronization
W. 2017-03-06 09:05:37. <77422> [10081] Unable to retrieve the column data types for table 'bzVisitInstance' from the consolidated database
W. 2017-03-06 09:05:37. <77422> [10081] Unable to retrieve the column data types for table 'bzVisitInstance' from the consolidated database
I. 2017-03-06 09:05:37. <77422> COMMIT Transaction: Upload
I. 2017-03-06 09:05:41. <77422> COMMIT Transaction: Prepare for download
I. 2017-03-06 09:05:44. <77422> Sending the download to the remote database
I. 2017-03-06 09:05:44. <77422> COMMIT Transaction: Download
I. 2017-03-06 09:06:01. <77422> COMMIT Transaction: End synchronization
E. 2017-03-06 09:09:47. <77422> [-10279] Connection was dropped due to lack of network activity
I. 2017-03-06 09:09:47. <77422> Synchronization complete
...
I. 2017-03-06 09:05:51. <77431> Request from "UL 16.0.2193" for: remote ID: 541, user name: 724, version: MSERIES.007.030.0000
I. 2017-03-06 09:05:51. <77431> The current synchronization is using a connection with connection ID 'SPID 94'
I. 2017-03-06 09:05:51. <77432> COMMIT Transaction: Upload
E. 2017-03-06 09:05:51. <77431> [-10002] Consolidated database server or ODBC error:  ODBC: [Microsoft][SQL Server Native Client 11.0][SQL Server]Lock request time out period exceeded. (ODBC State = 42000, Native error code = 1222)
E. 2017-03-06 09:05:51. <77431> [-10002] Consolidated database server or ODBC error:  ODBC: [Microsoft][SQL Server Native Client 11.0][SQL Server]The cursor was not declared. (ODBC State = 42000, Native error code = 16945)
E. 2017-03-06 09:05:51. <77431> [-10343] The remote database identified by remote ID '541' is already synchronizing or the database connection is unusable: unable to access the lock for that remote ID
I. 2017-03-06 09:05:51. <77431> Synchronization failed

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Fri, 03 Mar 2017 14:53:35 GMT

Hi Alex,

To help diagnose the "Invalid sync sequence ID" error, can you add the -vp option to your MobiLink servers? That will put the progress values in the MobiLink server logs for every synchronization.

In the ideal case, with the -vp turned on, we'd like to see the history of all synchronizations for a given remote database up to the point where it fails with the "Invalid sync sequence ID" error.

Best Regards,

Russ

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Mon, 06 Mar 2017 09:00:04 GMT

Thanks Russ. I'll check that. Just another question, I've seen some strange logs in only one server (I've updated the question with it). Is that something I should be worried about?

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Mon, 06 Mar 2017 09:51:04 GMT

Russ, I think I found a way to reproduce it. 1) Start a Sync, 2) Kill the app during download commit, 3) Start the App and sync again. The Mobilink will throw an error saying there is another sync running. If these two syncs happen in different services (that's where the load balance enters) the "sequence id error" will be reproduced. In the past we had an issue regarding the sync cancellation (check the associated question).

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Mon, 06 Mar 2017 10:12:00 GMT

Hi Alex,

The re-connection is normal. At the start of a sync, a connection is taken from the pool and tested. If it was previously used from a failed sync, and you are not using the -a option, the connection will be closed and a new connection made. If the unpooled connection doesn't seem to work anymore, it will be closed and a new connection made.

Can you provide the log lines that indicate there is another sync running?

Can you confirm that when the two synchronizations go to the same MobiLink server you don't see this problem?

Best Regards,

Russ

Re: Invalid sync sequence ID for remote ID 'X' [2]

chris_keating — Mon, 06 Mar 2017 10:15:49 GMT

Can you please describe specifically how you approach killing the application? Can you please collect the -vp log output as requested on these two servers.

Do you have a support plan. If so, I would encourage you to open a new issue and advise the support rep assigned that you raised this issue on the forum.

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Mon, 06 Mar 2017 11:20:16 GMT

Hi @Chris Keating, I just kill the process (in Android, exiting the application and swyping it left from recent apps to stop it completely).

The log verbosity is on the way. First, I need to update the production environments and wait some time so the error can occur again. I'll see if I can reproduce it locally, maybe hardcoding the things a little.

I'm not sure if we have support plan. I'd say no. But I'm going to check and I let you know. Thanks.

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Mon, 13 Mar 2017 09:28:11 GMT

@RussC_FromSAP thank you for your explanation. I'm working on the new logs with the -vp verbosity. I'll open a support ticket as soon as I have it. I updated the question with an example of subsequent syncs in a same server which doesn't lead to a sequence id error.

Re: Invalid sync sequence ID for remote ID 'X' [2]

Former Member — Wed, 12 Apr 2017 01:46:00 GMT

When I was reading the problem that occurred to you, an idea with question with an example of subsequent syncs in a same server came to my mind. I knew it because I recalled that my friend had same issue and this is what he was told to do by one [blogger][1].

Re: Invalid sync sequence ID for remote ID 'X' [2]

Vlad — Wed, 12 Apr 2017 02:46:11 GMT

Sounds like a spam or ads?

Re: Invalid sync sequence ID for remote ID 'X' [2]

VolkerBarth — Wed, 12 Apr 2017 03:22:40 GMT

Has been reported as the former already...

Though I kind of like these vague "answers"... does someone simply use copy and paste from the original posting merged with some general phrases to build such postings, or is it done by bots?

Re: Invalid sync sequence ID for remote ID 'X' [2]

Vlad — Wed, 12 Apr 2017 04:28:03 GMT

It is difficult to answer, Volker. Sometimes I like to investigate to fulfil my curiosity. E.g. I'd look at the email address (fake domain, or not). If not - then probably this person might exist somewhere in Web. It is also interesting to look at its UserAgent, to see who sent the request (browser, or a library from the code). The user agent (and IP) can be used to scan other requests that the server handled to see other suspicious activity.

Yes, this is what I'd like to do when I am lazy to do my job 🙂

Re: Invalid sync sequence ID for remote ID 'X' [2]

regdomaratzki — Wed, 12 Apr 2017 10:32:01 GMT

Awesome. We're popular enough for spam. 🙂 I was expecting the last sentence of this post to be "You won't believe what happened next...".