Which scenario can lead to Requested X bytes but got Y bytes ?

[Former Member]

Hey everyone,

We are encountering weird issues with our v16 Mobilink server that we can't explain. Here's the symptom (as log messages) :

I. 2017-06-01 04:27:36. # rows deleted in table TABLE_XY : 0
I. 2017-06-01 04:27:36. # rows updated in table TABLE_XY : 0
I. 2017-06-01 04:27:37. Waiting for MobiLink to apply upload
I. 2017-06-01 04:34:00. MobiLink server supported communication protocols:  0x1 to 0x1
I. 2017-06-01 04:34:00. MobiLink server version: 16.0.0 (build 2234)
I. 2017-06-01 04:34:00. Server side liveness timeout is 60 seconds.
I. 2017-06-01 04:34:00. The user authentication value is 1000.
I. 2017-06-01 04:34:00. Setting last upload time to 2017-06-01 04:27:36.279612.
I. 2017-06-01 04:34:00. Setting generation number for subscription ***** to 1.
I. 2017-06-01 04:34:00. COMMIT
E. 2017-06-01 04:35:18. Data read failed.  Requested 28596 bytes but got 2058 bytes.

We tried to synchronize a v17 sqlanywhere client with dbmlsync using 'HTTPS' as protocol and we get regularly this message. In the above example, it happened after

The topology : 2 VMs running in the same LAN. SQLA client runs on the same machine as the mlsrv process.

This results in a 404 Error.

On the server side, we see the following log outputs :

I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: nonblocking_download_ack: 0
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: connect_for_download_ack: 0
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: get_db_worker_for_download_ack: 0
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: wait_for_download_ack: 0
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: send_download: 77766
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: end_sync: 14
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: fetch_download: 383049
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: prepare_for_download: 32
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: apply_upload: 47
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: begin_sync: 33
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: authenticate_user: 137
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: connect: 7
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: get_db_worker: 0
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: receive_upload: 1
I. 2017-06-01 04:35:16. <1588728> ( ****) PHASE: sync_request: 278
I. 2017-06-01 04:35:16. <1588728> ( ****) Synchronization complete
E. 2017-06-01 04:35:15. <1588728> ( ****) [-10279] Connection was dropped due to lack of network activity
I. 2017-06-01 04:33:58. <1588728> ( ****) COMMIT Transaction: End synchronization
I. 2017-06-01 04:33:58. <1588728> ( ****) time_statistics <connection> (no script)
I. 2017-06-01 04:33:58. <1588728> ( ****) synchronization_statistics <connection> (no script)
I. 2017-06-01 04:33:58. <1588728> ( ****) end_synchronization <connection> (no script)
I. 2017-06-01 04:33:58. <1588728> ( ****) end_publication <connection> (no script)
I. 2017-06-01 04:33:58. <1588728> ( ****) COMMIT Transaction: Download
I. 2017-06-01 04:32:33. <1588728> ( ****) Sending the download to the remote database
I. 2017-06-01 04:32:33. <1588728> ( ****) download_statistics <connection> (no script)
I. 2017-06-01 04:32:33. <1588728> ( ****) # rows downloaded to remote from table TABLE_Y : 0
...
I. 2017-06-01 04:32:33. <1588728> ( ****) # rows downloaded for insert/update from table TABLE_X : 0
I. 2017-06-01 04:32:33. <1588728> ( ****) # rows downloaded for delete from table TABLE_X : 0
I. 2017-06-01 04:32:33. <1588728> ( ****) end_download <connection> (no script)
I. 2017-06-01 04:32:33. <1588728> ( ****) modify_next_last_download_timestamp <connection> (no script)
I. 2017-06-01 04:32:33. <1588728> ( ****) download_cursor TABLE_V
...
I. 2017-06-01 04:27:35. <1588728> ( ****) download_cursor TABLE_W
I. 2017-06-01 04:27:35. <1588728> ( ****) handle_DownloadData <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) begin_download <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) COMMIT Transaction: Prepare for download
I. 2017-06-01 04:27:35. <1588728> ( ****) prepare_for_download <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) modify_last_download_timestamp <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) COMMIT Transaction: Upload
I. 2017-06-01 04:27:35. <1588728> ( ****) upload_statistics <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) # rows ignored in table TABLE_Y : 0
...
I. 2017-06-01 04:27:35. <1588728> ( ****) # rows inserted into table TABLE_X : 0
I. 2017-06-01 04:27:35. <1588728> ( ****) # rows uploaded into table TABLE_X : 0
I. 2017-06-01 04:27:35. <1588728> ( ****) 2 row(s) were ignored in uploading data into table TABLE_Z
I. 2017-06-01 04:27:35. <1588728> ( ****) end_upload <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) handle_UploadData <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) begin_upload <connection>
I. 2017-06-01 04:27:35. <1588728> ( ****) COMMIT Transaction: Begin synchronization
I. 2017-06-01 04:27:35. <1588728> ( ****) begin_publication <connection> (no script)
I. 2017-06-01 04:27:35. <1588728> ( ****) begin_synchronization <connection>
I. 2017-06-01 04:27:35. <1588728> (d90d102e-bb04-48a3-a99c-87f04727223b                                                                                             ****) User '****' has been successfully authenticated against LDAP server 'ebiz'
I. 2017-06-01 04:27:35. <1588728> (d90d102e-bb04-48a3-a99c-87f04727223b                                                                                             ****) The current synchronization is using a connection with connection ID 'Unknown'
I. 2017-06-01 04:27:35. <1588728> (d90d102e-bb04-48a3-a99c-87f04727223b                                                                                             ****) Request from "Dbmlsync 17.0.2100" for: remote ID: d90d102e-bb04-48a3-a99c-87f04727223b                                                                                           
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: nonblocking_download_ack: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: connect_for_download_ack: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: get_db_worker_for_download_ack: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: wait_for_download_ack: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: send_download: 265
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: end_sync: 9
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: fetch_download: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: prepare_for_download: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: apply_upload: 55
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: begin_sync: 27
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: authenticate_user: 252
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: connect: 12
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: get_db_worker: 0
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: receive_upload: 224
I. 2017-06-01 04:27:32. <1588721> ( ****) PHASE: sync_request: 307
I. 2017-06-01 04:27:32. <1588721> ( ****) Synchronization complete
I. 2017-06-01 04:27:31. <1588721> ( ****) COMMIT Transaction: End synchronization
I. 2017-06-01 04:27:31. <1588721> ( ****) time_statistics <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) synchronization_statistics <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) end_synchronization <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) end_publication <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) COMMIT Transaction: Upload
I. 2017-06-01 04:27:31. <1588721> ( ****) upload_statistics <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) # rows ignored in table TABLE_Y : 0
...
I. 2017-06-01 04:27:31. <1588721> ( ****) # rows inserted into table TABLE_X : 0
I. 2017-06-01 04:27:31. <1588721> ( ****) # rows uploaded into table TABLE_X : 0
I. 2017-06-01 04:27:31. <1588721> ( ****) end_upload <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) handle_UploadData <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) begin_upload <connection>
I. 2017-06-01 04:27:31. <1588721> ( ****) COMMIT Transaction: Begin synchronization
I. 2017-06-01 04:27:31. <1588721> ( ****) begin_publication <connection> (no script)
I. 2017-06-01 04:27:31. <1588721> ( ****) begin_synchronization <connection>
I. 2017-06-01 04:27:31. <1588721> (d90d102e-bb04-48a3-a99c-87f04727223b                                                                                             ****) User '****' has been successfully authenticated against LDAP server 'ebiz'
I. 2017-06-01 04:27:31. <1588721> (d90d102e-bb04-48a3-a99c-87f04727223b                                                                                             ****) The current synchronization is using a connection with connection ID 'Unknown'
I. 2017-06-01 04:27:31. <1588721> (d90d102e-bb04-48a3-a99c-87f04727223b                                                                                             ****) Request from "Dbmlsync 17.0.2100" for: remote ID: d90d102e-bb04-48a3-a99c-87f04727223b

Do you guys see any way for these data read failed ? sound super weird to me !

Thanks for your help 🙂

[Breck_Carter]

Not enough information.

Is it a local network connection, or across the interwebs?

[VolkerBarth]

Ah, Breck is requesting more bytes, too:)

[Breck_Carter]

The V17 MobiLink server can surely handle V16 clients, but... can the V16 MobiLink server handle V17 clients? (I do not know)

[Former Member]

Yes, mlsrv16 can handle v17 clients. This works in our productive environment since January 😉

[regdomaratzki]

You've posted the output from dbmlsync that reports the read timeout waiting for a response from the ML Server after sending the upload. Can you also post the log from the ML Server from the same timeframe?

Also, what does "regularly" mean? Every time? Once a day?

Thanks, Reg

[Former Member]

Hey Reg ! Please find enclosed the server-side logs in the question description

[Breck_Carter]

The timestamps are in apparent reverse order in the server-side log... is that what the file actually contains? (sorting the file is not a good idea since the timestamps are not unique)

[Former Member]

No. For the server-side log, we use a tool to consolidate all logs and that's the default order. I also got rid of redundant information. It's marked as "..." 🙂

[Former Member]

Hey Reg, got news ?

[regdomaratzki]

This looks like a loss of network connectivity between the ML Server and dbmlsync. It looks to me like it took a LONG time to generate the download, since there is a five minute delay between these two lines in your output.

I. 2017-06-01 04:32:33. <1588728> ( ****) download_cursor TABLE_V
...
I. 2017-06-01 04:27:35. <1588728> ( ****) download_cursor TABLE_W

Dbmlsync and the Mobilink server will maintain a liveness over the HTTPS protocol when dbmlsync is waiting for the download stream, so it's likely an HTTP intermediary between dbmlsync and the MobiLink that is terminating the connection.

Reg