Mobilink synchronization - unknown crypto error

[former_SQLA_member1694889]

Hello everybody,

We're running a project using SQLAnywhere 17.0.10.5923 where devices running on Android synchronise on a mobilink server that is configured to use HTTPS and a self generated certificate.

Most of synchronisations go well but in some cases we can observe an error message returned by the mobilink server:

11:04:24[-10117] Stream Error: An unknown crypto error occurred: 0x20000422

We checked the mobilink server logs and we could observe this error can occur at different stages of the synchronization: right after authentication, or right after download phase ended.

We have two mobilink servers running under a load balancer. Both servers start command refer to the same certificate that is on a shared drive.

-x https(port=3440;identity=\\\\5148\\java\\certif\\server.id;identity_password=server_pw) -zs mlserv

Any idea where can this error could come from?

Thanks in advance,

Alex

UPDATE This is the beginning of the logfile, showing the start parameters:

Log file start:

I. 2019-11-06 13:18:27. SQL Anywhere MobiLink Synchronization Server Version 17.0.10.5923
I. 2019-11-06 13:18:27.
I. 2019-11-06 13:18:27. Copyright © 2019 SAP SE or an SAP affiliate company.
I. 2019-11-06 13:18:27. All rights reserved.
I. 2019-11-06 13:18:27. Use of this software is governed by the SAP Software Use Rights Agreement.
I. 2019-11-06 13:18:27. Refer to http://www.sap.com/about/agreements.html.
I. 2019-11-06 13:18:27.
I. 2019-11-06 13:18:27. This server is licensed to:
I. 2019-11-06 13:18:27.     ITD
I. 2019-11-06 13:18:27. Running Windows 2012R2 Build 9600  on X86_64
I. 2019-11-06 13:18:27. Server built for X86_64 processor architecture
I. 2019-11-06 13:18:27. <Main> Option 1: -c
I. 2019-11-06 13:18:27. <Main> Option 2: DSN=SAM_p;uid=samprd;pwd=********
I. 2019-11-06 13:18:27. <Main> Option 3: -ot
I. 2019-11-06 13:18:27. <Main> Option 4: \\\\SERV5148\\sam\\logs\\ml\\SERV5150.txt
I. 2019-11-06 13:18:27. <Main> Option 5: -vm
I. 2019-11-06 13:18:27. <Main> Option 6: -os
I. 2019-11-06 13:18:27. <Main> Option 7: 20m
I. 2019-11-06 13:18:27. <Main> Option 8: -sl
I. 2019-11-06 13:18:27. <Main> Option 9: java(-cp
I. 2019-11-06 13:18:27. <Main> Option 10: \\\\SERV5148\\java
I. 2019-11-06 13:18:27. <Main> Option 11: )
I. 2019-11-06 13:18:27. <Main> Option 12: -ftr
I. 2019-11-06 13:18:27. <Main> Option 13: \\\\SERV5148\\sam\\download
I. 2019-11-06 13:18:27. <Main> Option 14: -ftru
I. 2019-11-06 13:18:27. <Main> Option 15: \\\\SERV5148\\sam\\upload
I. 2019-11-06 13:18:27. <Main> Option 16: -x
I. 2019-11-06 13:18:27. <Main> Option 17: http(port=3439)
I. 2019-11-06 13:18:27. <Main> Option 18: -x
I. 2019-11-06 13:18:27. <Main> Option 19: tcpip(port=2439)
I. 2019-11-06 13:18:27. <Main> Option 20: -x
I. 2019-11-06 13:18:27. <Main> Option 21: https(port=3440;identity=\\\\SERV5148\\sam\\java\\certif\\server.id;identity_password=********)
I. 2019-11-06 13:18:27. <Main> Option 22: -zs
I. 2019-11-06 13:18:27. <Main> Option 23: sam
I. 2019-11-06 13:18:27. <Main> Cache size: 52428800 bytes
I. 2019-11-06 13:18:27. <Main> Download cache directory size: 10485760 bytes
I. 2019-11-06 13:18:27. <Main> Local file for remote synchronization logs: 'mlsrv.mle'
I. 2019-11-06 13:18:27. <Main> Maximum number of BLOB bytes to compare: 4294967295
I. 2019-11-06 13:18:27. <Main> Maximum number of database connections: 5
I. 2019-11-06 13:18:27. <Main> Rowset size: 10
I. 2019-11-06 13:18:27. <Main> Number of database worker threads: 5
I. 2019-11-06 13:18:27. <Main> Individual database connections will be closed after synchronization errors
I. 2019-11-06 13:18:27. <Main> Maximum number of deadlock retries: 10
I. 2019-11-06 13:18:27. <Main> Timeout for inactive database connections: 60 minutes
I. 2019-11-06 13:18:27. <Main> Maximum delay between retries after deadlock: 30 seconds
I. 2019-11-06 13:18:27. <Main> Unknown users will be rejected (when there is no authenticate_user script)
I. 2019-11-06 13:18:28. <Main> ODBC DBMS Name: Oracle
I. 2019-11-06 13:18:28. <Main> ODBC DBMS Version: 12.01.0000
I. 2019-11-06 13:18:28. <Main> ODBC DBMS Driver Version: 17.00.0010
I. 2019-11-06 13:18:28. <Main> ODBC Version supported by the driver: 3.51
I. 2019-11-06 13:18:28. <Main> ODBC DBMS Type: ORACLE
I. 2019-11-06 13:18:28. <Main> Shared administrative connection with connection ID 'SID 1147, SERIAL# 7906' has been established
I. 2019-11-06 13:18:28. <Main> ODBC isolation set to: Read Committed
I. 2019-11-06 13:18:28. <Main> Unable to access JVM config file: C:\\Program Files\\SQL Anywhere 17\\bin64\\jre180\\lib\\jvm.cfg. Assuming default JVM config file
I. 2019-11-06 13:18:28. <Main> Java VM path: C:\\Program Files\\SQL Anywhere 17\\bin64\\jre180\\bin\\server\\jvm.dll
I. 2019-11-06 13:18:28. <Main> Loading support JAR: C:\\Program Files\\SQL Anywhere 17\\java\\mlscript.jar
I. 2019-11-06 13:18:28. <Main> Loading support JAR: C:\\Program Files\\SQL Anywhere 17\\java\\jodbc4.jar
I. 2019-11-06 13:18:28. <Main> Loading support JAR: C:\\Program Files\\SQL Anywhere 17\\java\\mlnotif.jar
I. 2019-11-06 13:18:28. <Main> Loading support JAR: C:\\Program Files\\SQL Anywhere 17\\java\\mlsupport.jar
I. 2019-11-06 13:18:28. <Main> Loading support JAR: C:\\Program Files\\SQL Anywhere 17\\java\\mlstream.jar
I. 2019-11-06 13:18:28. <Main> Loading support JAR: C:\\Program Files\\SQL Anywhere 17\\java\\jsyblib1700.jar
I. 2019-11-06 13:18:29. <Main> Synchronization server started

Here are examples of two synchronizations:

Error after download:
 13:18:44 Synchronization connection with connection ID 'SID 1715, SERIAL# 12008' has been established
13:18:44 COMMIT Transaction: Begin connection
13:18:44 The current synchronization is using a connection with connection ID 'SID 1715, SERIAL# 12008'
13:18:46 The authenticate_user script returned 1000
13:18:46 [-10133] SAM - authenticateUserWithParams - user e0010991 - syncMode - M
13:18:46 The authenticate_parameters script returned 1000
13:18:46 COMMIT Transaction: Authenticate user
13:18:46 COMMIT Transaction: Begin synchronization
13:18:46 [-10133] SAM - handleUpload - end 2
13:18:47 COMMIT Transaction: Upload
13:18:48 COMMIT Transaction: Prepare for download
13:18:48 Sending the download to the remote database
13:18:48 COMMIT Transaction: Download
13:18:48 COMMIT Transaction: End synchronization
13:18:48 Synchronization complete
13:18:48 PHASE: sync_request: 1641
13:18:48 PHASE: receive_upload: 94
13:18:48 PHASE: get_db_worker: 0
13:18:48 PHASE: connect: 677
13:18:48 PHASE: authenticate_user: 1672
13:18:48 PHASE: begin_sync: 391
13:18:48 PHASE: apply_upload: 547
13:18:48 PHASE: prepare_for_download: 1203
13:18:48 PHASE: fetch_download: 78
13:18:48 PHASE: end_sync: 94
13:18:48 PHASE: send_download: 47
13:18:48 PHASE: wait_for_download_ack: 0
13:18:48 PHASE: get_db_worker_for_download_ack: 0
13:18:48 PHASE: connect_for_download_ack: 0
13:18:48 PHASE: nonblocking_download_ack: 0
13:18:54 [-10117] Stream Error: An unknown crypto error occurred: 0x20000422

Error after authentication:
 13:18:52 Request from "UL 17.0.9.4838" for: remote ID: 954F79E38A483C27E0531570580A7661,
13:18:52 Synchronization connection with connection ID 'SID 203, SERIAL# 15361' has been established
13:18:52 COMMIT Transaction: Begin connection
13:18:52 The current synchronization is using a connection with connection ID 'SID 203, SERIAL# 15361'
13:18:52 The authenticate_user script returned 1000
13:18:52 The authenticate_parameters script returned 1000
13:18:52 COMMIT Transaction: Authenticate user
13:18:52 Ping request completed
13:18:52 PHASE: sync_request: 1438
13:18:52 PHASE: receive_upload: 0
13:18:52 PHASE: get_db_worker: 0
13:18:52 PHASE: connect: 422
13:18:52 PHASE: authenticate_user: 234
13:18:52 PHASE: begin_sync: 0
13:18:52 PHASE: apply_upload: 0
13:18:52 PHASE: prepare_for_download: 0
13:18:52 PHASE: fetch_download: 0
13:18:52 PHASE: end_sync: 0
13:18:52 PHASE: send_download: 0
13:18:52 PHASE: wait_for_download_ack: 0
13:18:52 PHASE: get_db_worker_for_download_ack: 0
13:18:52 PHASE: connect_for_download_ack: 0
13:18:52 PHASE: nonblocking_download_ack: 0
13:18:54 [-10117] Stream Error: An unknown crypto error occurred: 0x20000422

[regdomaratzki]

Just to be clear, when you say "we can observe an error message returned by the mobilink server", you mean that the error is being posted to the ML log, and not being returned to the UL client, correct? I'm 99% sure it's the ML log, but just wanted to be sure.

[regdomaratzki]

Would you be able to post a full synchronization request that shows the error being returned? Since you say that you see it in different stages, posting a few synchronizations with the error in different locations would be ideal.

[regdomaratzki]

Are you able to reproduce this issue at will, or is it just something that happens from time to time?

Can you reproduce it in a test environment, or only in production?

[regdomaratzki]

Can you please post the full MobiLink Server start line (clearly remove passwords). I'm mostly interested in the current verbosity settings, but the full command line will be helpful.

[former_SQLA_member1694889]

Yes, the error is from the ML log file.

On the UltraLite client we get the error code -9 - Unable to wite %1 bytes

[former_SQLA_member1694889]

Here are two synchronizations with the error at different steps:

Error after download: 13:18:44 Synchronization connection with connection ID 'SID 1715, SERIAL# 12008' has been established 13:18:44 COMMIT Transaction: Begin connection 13:18:44 The current synchronization is using a connection with connection ID 'SID 1715, SERIAL# 12008' 13:18:46 The authenticate_user script returned 1000 13:18:46 [-10133] SAM - authenticateUserWithParams - user e0010991 - syncMode - M 13:18:46 The authenticate_parameters script returned 1000 13:18:46 COMMIT Transaction: Authenticate user 13:18:46 COMMIT Transaction: Begin synchronization 13:18:46 [-10133] SAM - handleUpload - end 2 13:18:47 COMMIT Transaction: Upload 13:18:48 COMMIT Transaction: Prepare for download 13:18:48 Sending the download to the remote database 13:18:48 COMMIT Transaction: Download 13:18:48 COMMIT Transaction: End synchronization 13:18:48 Synchronization complete 13:18:48 PHASE: sync_request: 1641 13:18:48 PHASE: receive_upload: 94 13:18:48 PHASE: get_db_worker: 0 13:18:48 PHASE: connect: 677 13:18:48 PHASE: authenticate_user: 1672 13:18:48 PHASE: begin_sync: 391 13:18:48 PHASE: apply_upload: 547 13:18:48 PHASE: prepare_for_download: 1203 13:18:48 PHASE: fetch_download: 78 13:18:48 PHASE: end_sync: 94 13:18:48 PHASE: send_download: 47 13:18:48 PHASE: wait_for_download_ack: 0 13:18:48 PHASE: get_db_worker_for_download_ack: 0 13:18:48 PHASE: connect_for_download_ack: 0 13:18:48 PHASE: nonblocking_download_ack: 0 13:18:54 [-10117] Stream Error: An unknown crypto error occurred: 0x20000422

Error after authentication: 13:18:52 Request from "UL 17.0.9.4838" for: remote ID: 954F79E38A483C27E0531570580A7661, 13:18:52 Synchronization connection with connection ID 'SID 203, SERIAL# 15361' has been established 13:18:52 COMMIT Transaction: Begin connection 13:18:52 The current synchronization is using a connection with connection ID 'SID 203, SERIAL# 15361' 13:18:52 The authenticate_user script returned 1000 13:18:52 The authenticate_parameters script returned 1000 13:18:52 COMMIT Transaction: Authenticate user 13:18:52 Ping request completed 13:18:52 PHASE: sync_request: 1438 13:18:52 PHASE: receive_upload: 0 13:18:52 PHASE: get_db_worker: 0 13:18:52 PHASE: connect: 422 13:18:52 PHASE: authenticate_user: 234 13:18:52 PHASE: begin_sync: 0 13:18:52 PHASE: apply_upload: 0 13:18:52 PHASE: prepare_for_download: 0 13:18:52 PHASE: fetch_download: 0 13:18:52 PHASE: end_sync: 0 13:18:52 PHASE: send_download: 0 13:18:52 PHASE: wait_for_download_ack: 0 13:18:52 PHASE: get_db_worker_for_download_ack: 0 13:18:52 PHASE: connect_for_download_ack: 0 13:18:52 PHASE: nonblocking_download_ack: 0 13:18:54 [-10117] Stream Error: An unknown crypto error occurred: 0x20000422

[former_SQLA_member1694889]

It happens randomly and at the moment only in the prod environment, we try to reproduce it in dev at the moent

[former_SQLA_member1694889]

I added the first lines of the ML log to the question - it shows all parameters in detail. Also added the failed syncs, easier to read than in my reply.

Thanks for your help Reg!

[regdomaratzki]

This seems to be the error happening at the same time (i.e. end of synch) but for different types of synchronization (ping vs. full synchronization).

Why don't we see the sync id value (or <main>) between the timestamp and the text of the message? I would expect lines from the ML Log to look like :

I. 2019-08-06 19:43:51. <1> Synchronization complete

Are you sure that the unknown crypto error is happening at the end of a synch and not the beginning of the next synch in the log? Without the <sync_id> in the log, we don't know which synchronization the error is associated with.

[regdomaratzki]

Still waiting on answers to the questions I asked in the above reply.