Error No. 2013 – Inconsistent Sync Experience

[Rich]

Hello,

I've been using SQLYog synchronization quite successfully for a few years now.

However recently I've run into problems that I need some help troubleshooting.

I have searched and read threads concerning this with no resolution. Not saying it's not out there, just didn't find in after 2 hours of looking.

___

– server is on LAN behind firewall, sync is over SSH

– PK is two-tuple of timestamp and varchar (source and target)

– table has ~1.5M rows of hourly data

– only PK fields are spec'd for sync job (column selection)

– where clause is used to limit scope to past 24 hours (DATATIME > CURRENT_TIMESTAMP – INTERVAL 24 HOUR)

– each hourly sync should add 69 rows to the target

– Source is using v8.2 on Windows 2000 MySql 5.1

– Target is Win2008Server MySql 5.1

– Set FOREIGN_KEY_CHECKS=0 for target is checked

Following log sequence is typical:

Sync started at Sun Apr 11 08:00:00 2010

`tag_data60mins` 1507871 1507802 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 09:00:00 2010

`tag_data60mins` 1507940 1507802 138 0 0

Sync started at Sun Apr 11 10:00:00 2010

`tag_data60mins` 1508009 1507940 69 0 0

Sync started at Sun Apr 11 11:00:00 2010

`tag_data60mins` 1508078 1508009 69 0 0

Sync started at Sun Apr 11 12:00:00 2010

`tag_data60mins` 1508147 1508078 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 13:00:00 2010

`tag_data60mins` 1508216 1508078 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 14:00:00 2010

`tag_data60mins` 1508285 1508078 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 15:00:00 2010

`tag_data60mins` 1508354 1508078 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 16:00:00 2010

`tag_data60mins` 1508423 1508078 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 17:00:00 2010

`tag_data60mins` 1508492 1508078 414 0 0

Sync started at Sun Apr 11 18:00:00 2010

`tag_data60mins` 1508561 1508492 69 0 0

Sync started at Sun Apr 11 19:00:00 2010

`tag_data60mins` 1508630 1508561 69 0 0

Sync started at Sun Apr 11 20:00:00 2010

`tag_data60mins` 1508699 1508630 69 0 0

Sync started at Sun Apr 11 21:00:00 2010

`tag_data60mins` 1508768 1508699 69 0 0

Sync started at Sun Apr 11 22:00:00 2010

`tag_data60mins` 1508837 1508768 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Sun Apr 11 23:00:00 2010

`tag_data60mins` 1508906 1508768 138 0 0

Sync started at Mon Apr 12 00:00:00 2010

`tag_data60mins` 1508975 1508906 69 0 0

Sync started at Mon Apr 12 01:00:00 2010

`tag_data60mins` 1509044 1508975 69 0 0

Sync started at Mon Apr 12 02:00:00 2010

`tag_data60mins` 1509113 1509044 69 0 0

Sync started at Mon Apr 12 03:00:00 2010

`tag_data60mins` 1509182 1509113 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Mon Apr 12 04:00:00 2010

`tag_data60mins` 1509251 1509113 Error No. 2013

Lost connection to MySQL server during query

Error No. 1231

Variable 'sql_notes' can't be set to the value of 'NULL'

Sync started at Mon Apr 12 05:00:00 2010

`tag_data60mins` 1509320 1509113 207 0 0

Sync started at Mon Apr 12 06:00:00 2010

`tag_data60mins` 1509389 1509320 69 0 0

Sync started at Mon Apr 12 07:00:00 2010

`tag_data60mins` 1509458 1509389 69 0 0

Sync started at Mon Apr 12 08:00:00 2010

`tag_data60mins` 1509527 1509458 69 0 0

Sync started at Mon Apr 12 09:00:00 2010

`tag_data60mins` 1509596 1509527 69 0 0

Sync started at Mon Apr 12 10:00:00 2010

`tag_data60mins` 1509665 1509596 69 0 0

Sync started at Mon Apr 12 11:10:00 2010

`tag_data60mins` 1509734 1509665 Sync started at Mon Apr 12 12:10:00 2010

`tag_data60mins` 1509803 1509665

_____

The last two log entries above show what happened when the 11:10 job hung up until it was terminated and the 12:10 job started.

Can I get some assistance with this?

Thanks,

Rich

[Rich]

Just a follow-up note.

The following query executes against the target server in just over two seconds:

SELECT * FROM tag_data60mins

WHERE DATATIME > CURRENT_TIMESTAMP – INTERVAL 24 HOUR

I am running the sync job manually from the UI for the case were there are no new rows, and it has been calculating checksum for over eight minutes.

The screen shot shows a weird result: 37 rows inserted even the the source and target had the same number of rows. Note the time of 585 seconds.

Does this spark any ideas?

Thanks,

Rich

[peterlaursen]

You did not tell the SQLyog version.  This is important.  I believe the 'sql_mode cannot be set to NULL' issue is solved in recent versions. It is also important whether you use HTTP-tunnel or not.

Note that you first get “Lost connection to MySQL server during query”.  After that we reconnect automatically but the user variable used to stored the old sql_mode gets reset to NULL (user variables have a session-wide scope only).  We did not handle user variables properly when reconnecting.  Next we try to SET the sql_mode + the value of the user vraible, but as it has become NULL with a reconnection it returns an error.

This is what I remember right now.  So you please tell 

1) SQLyog version

2) HTTP tunnel or not

.. and I will check if we have more details about this

[Rich]

Thank you for responding Peter:

Bullet 1 – server is on LAN behind firewall, sync is over SSH (I am not using HTTP-tunnel, I am using SSH tunnel)

Bullet 7 – Source is using v8.2 on Windows 2000 MySql 5.1 (sorry if this wasn't more clear; SQLYog 8.2/Win 2000 Server/MySql 5.1)

I will appreciate any light you can shed on this.

Is there any issue with 1.5M rows in the table since I am only sync'ing on last 24 hrs?

Rich

'peterlaursen' wrote on '12:

You did not tell the SQLyog version.  This is important.  I believe the 'sql_mode cannot be set to NULL' issue is solved in recent versions. It is also important whether you use HTTP-tunnel or not.

Note that you first get “Lost connection to MySQL server during query”.  After that we reconnect automatically but the user variable used to stored the old sql_mode gets reset to NULL (user variables have a session-wide scope only).  We did not handle user variables properly when reconnecting.  Next we try to SET the sql_mode + the value of the user vraible, but as it has become NULL with a reconnection it returns an error.

This is what I remember right now.  So you please tell 

1) SQLyog version

2) HTTP tunnel or not

.. and I will check if we have more details about this

[peterlaursen]

It looks very much like you have a problem with your server.  You tell it used to work OK, but now problems occur and as time goes it becomes worse,  correct? Of curse if tables grow every day then each sync will take longer time.  That could be one explanation.  But I think this is not the primary problem here.  One issue could be that your hosting are 'packing' more users on the same server. It also is not the physical connection that causes the 'lsot conenction' as job would simply abort if physical connection was connection was lost with a SSH-connection.

I will also explain the log for you: what reads 

Quote:

…

`tag_data60mins` 1509596 1509527 69 0 0

Sync started at Mon Apr 12 10:00:00 2010

`tag_data60mins` 1509665 1509596 69 0 0

Sync started at Mon Apr 12 11:10:00 2010

`tag_data60mins` 1509734 1509665 Sync started at Mon Apr 12 12:10:00 2010

should look like 

Quote:

..

`tag_data60mins` 1509596 1509527 69 0 0

Sync started at Mon Apr 12 10:00:00 2010

`tag_data60mins` 1509665 1509596 69 0 0

Sync started at Mon Apr 12 11:10:00 2010

`tag_data60mins` 1509734 1509665 

Sync started at Mon Apr 12 12:10:00 2010…

.. and it does with recent versions.  But your version does not insert linebreaks before 'Sync started …'. It makes reading the log confusing.

Now let us take the problems the log tell about:

1) some sync's return 'lost connection' followed by 'sql_mode cannot be NULL'.  This error can in 99.99% of cases be ignored. There will be some very special situations (example if '0' is stored in an auto_increment column) where this error could indicate that some data may have been sync'ed wrong from the 'lost connection' error happened and onwards.  But do you experience any problems with the result of the sync (when it succeeds)?

2) the two last syncs started were not completed.  This shows (cleaned up):

Quote:

Sync started at Mon Apr 12 11:10:00 2010

`tag_data60mins` 1509734 1509665

Sync started at Mon Apr 12 12:10:00 2010

`tag_data60mins` 1509803 1509665

Can you explain “when the 11:10 job hung up until it was terminated and the 12:10 job started” .  One SJA job does not automatically get terminated when another starts.  Nothing prevents several identical jobs to run at the same time (but the log may then loook very confusing as records for each job will not be seperated). Unless of course that you killed some the log shows that two jobs were running when you copied the log (There alos should be 2 SJA instances displayed in Task Manger).  There is no information about how far each job had progressed through the table.  But neither had finished as values for INSERTED, UPDATED and DELETED were logged for any.  In my opinion this tells about a server slowness issue lasting for the last couple of hours (I understand you run sync at hourly interval).

Now .. please read what I have been writing and next tell what help you expect from us here.  We may for instance provide a build that logs more details. Say something like 10000 rows done .. 20000 rows done …etc. But again with more simultaneously jobs it may be hard to understand.

[Rich]

Hi Peter,

I'm sorry for delaying here, I had responded last week and somehow that response never made it into this thread. (maybe I never clicked the Reply button)

A version update to 8.3 seemed to largely resolve the inconsistency per the log output originally posted.

Can you verify that the WHERE clause limits the sync activity to the rows that meet the condition?

If I can get the last 24 rows out of 1.5M using SqlYog in under 2 seconds, why does the sync operation take several minutes?

I would like to have a binary with more detailed log output to see where all the time is being spent. Maybe it would be helpful for you as well. I would be happy to report back or send you log files to help you.

Thanks,

Rich

'peterlaursen' wrote on '14:

Now .. please read what I have been writing and next tell what help you expect from us here.  We may for instance provide a build that logs more details. Say something like 10000 rows done .. 20000 rows done …etc. But again with more simultaneously jobs it may be hard to understand.

[Author]

Posts