Bug #37313 BINLOG Contains Incorrect server id
Submitted: 10 Jun 2008 16:11 Modified: 18 Mar 2009 15:16
Reporter: Gregory Haase Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1.24/5.0/6.0 OS:Linux (x86_64)
Assigned to: Andrei Elkin CPU Architecture:Any
Tags: binlog, server_id
Triage: Triaged: D3 (Medium)

[10 Jun 2008 16:11] Gregory Haase
Description:
The server id as it appears in mysqlbinlog is not using proper unsigned int. Therefore, server ids greater than 2147483647 are showing up as a negative integer in mysqlbinlog.

This is a problem for people who want their server_id to be set as
inet_aton('<ip_address>') to ensure they are always unique in large data centers.

Although the data as it appears in mysqlbinlog is incorrect, there is no evidence that this has any adverse affects.

How to repeat:
in mysql:
> flush logs;
> set global server_id = 2147483647;
> create table test (id   INT);
> flush logs;
> set global server_id = 2147483648;
> insert into test values (1);
> flush logs;

mysql> show binlog events in 'bin-logs.000001';
+-----------------+-----+-------------+------------+-------------+----------------------------------------------------+
| Log_name        | Pos | Event_type  | Server_id  | End_log_pos | Info                                               |
+-----------------+-----+-------------+------------+-------------+----------------------------------------------------+
| bin-logs.000001 |   4 | Format_desc |          1 |         106 | Server ver: 5.1.24-rc-community-log, Binlog ver: 4 | 
| bin-logs.000001 | 106 | Query       | 2147483647 |         197 | use `test`; create table test (id   INT)           | 
| bin-logs.000001 | 197 | Rotate      | 2147483647 |         239 | bin-logs.000002;pos=4                              | 
+-----------------+-----+-------------+------------+-------------+----------------------------------------------------+
3 rows in set (0.00 sec)

mysql> show binlog events in 'bin-logs.000047';
+-----------------+-----+-------------+------------+-------------+----------------------------------------------------+
| Log_name        | Pos | Event_type  | Server_id  | End_log_pos | Info                                               |
+-----------------+-----+-------------+------------+-------------+----------------------------------------------------+
| bin-logs.000002 |   4 | Format_desc | 2147483647 |         106 | Server ver: 5.1.24-rc-community-log, Binlog ver: 4 | 
| bin-logs.000002 | 106 | Query       | 2147483648 |         174 | use `test`; BEGIN                                  | 
| bin-logs.000002 | 174 | Query       | 2147483648 |         264 | use `test`; insert into test values (1)            | 
| bin-logs.000002 | 264 | Xid         | 2147483648 |         291 | COMMIT /* xid=3773881 */                           | 
| bin-logs.000002 | 291 | Rotate      | 2147483648 |         333 | bin-logs.000003;pos=4                              | 
+-----------------+-----+-------------+------------+-------------+----------------------------------------------------+
5 rows in set (0.00 sec)

So far so good... these values are correct.

Now look at the same events through mysqlbinlog:

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#080610 15:59:30 server id 1  end_log_pos 106   Start: binlog v 4, server v 5.1.24-rc-community-log created 080610 15:59:30
BINLOG '
4qROSA8BAAAAZgAAAGoAAAAAAAQANS4xLjI0LXJjLWNvbW11bml0eS1sb2cAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 106
#080610 16:00:16 server id 2147483647  end_log_pos 197  Query   thread_id=539   exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1213113616/*!*/;
SET @@session.pseudo_thread_id=539/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table test (id   INT)
/*!*/;
# at 197
#080610 16:00:23 server id 2147483647  end_log_pos 239  Rotate to bin-logs.000002  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#080610 16:00:23 server id 2147483647  end_log_pos 106  Start: binlog v 4, server v 5.1.24-rc-community-log created 080610 16:00:23
BINLOG '
F6VOSA////9/ZgAAAGoAAAAAAAQANS4xLjI0LXJjLWNvbW11bml0eS1sb2cAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 106
#080610 16:00:44 server id -2147483648  end_log_pos 174         Query   thread_id=539   exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1213113644/*!*/;
SET @@session.pseudo_thread_id=539/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 174
#080610 16:00:44 server id -2147483648  end_log_pos 264         Query   thread_id=539   exec_time=0     error_code=0
SET TIMESTAMP=1213113644/*!*/;
insert into test values (1)
/*!*/;
# at 264
#080610 16:00:44 server id -2147483648  end_log_pos 291         Xid = 3773881
COMMIT/*!*/;
# at 291
#080610 16:00:48 server id -2147483648  end_log_pos 333         Rotate to bin-logs.000003  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Notice the server id in the second report shows a negative number.
[11 Jun 2008 1:42] Miguel Solorzano
Thank you for the bug report.

mysql 5.0 > show binlog events in 'hegel.000003';
+--------------+-----+-------------+------------+-------------+------------------------------------------+
| Log_name     | Pos | Event_type  | Server_id  | End_log_pos | Info                                     |
+--------------+-----+-------------+------------+-------------+------------------------------------------+
| hegel.000003 |   4 | Format_desc | 2147483647 |          98 | Server ver: 5.0.64-nt-log, Binlog ver: 4 |
| hegel.000003 |  98 | Query       | 2147483648 |         188 | use `test`; insert into test values (1)  |
| hegel.000003 | 188 | Rotate      | 2147483648 |         227 | hegel.000004;pos=4                       |
+--------------+-----+-------------+------------+-------------+------------------------------------------+
3 rows in set (0.00 sec)

mysql 5.0 > exit
Bye

c:\dbs>5.0\bin\mysqlbinlog.exe c:\dbs\5.0\data\hegel.000003
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#080610 22:27:55 server id 2147483647  end_log_pos 98   Start: binlog v 4, server v 5.0.64-nt-log created 080610 22:27:55
# at 98
#080610 22:27:55 server id -2147483648  end_log_pos 188         Query   thread_id=1     exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1213147675/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
insert into test values (1)
/*!*/;
# at 188
#080610 22:27:55 server id -2147483648  end_log_pos 227         Rotate to hegel.000004  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

c:\dbs>
[16 Nov 2008 21:35] Giuseppe Maxia
The problem is in mysqlbinlog code. A simple display error. Patch follows

=== modified file 'sql/log_event.cc'
--- sql/log_event.cc	2008-10-20 18:50:08 +0000
+++ sql/log_event.cc	2008-11-16 21:33:46 +0000
@@ -1257,7 +1257,7 @@
 
   my_b_printf(file, "#");
   print_timestamp(file);
-  my_b_printf(file, " server id %d  end_log_pos %s ", server_id,
+  my_b_printf(file, " server id %lu  end_log_pos %s ", server_id,
               llstr(log_pos,llbuff));
 
   /* mysqlbinlog --hexdump */
[13 Feb 2009 21:39] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/66307

2744 Andrei Elkin	2009-02-13
      Bug #37313  	BINLOG Contains Incorrect server id
      
      Singed integer format specifier forced to print the binlog header with server_id
      negative if the unsigned value set the sign bit ON.
      
      Fixed with correcting the specifier to correspond to typeof(server_id) == ulong.
[20 Feb 2009 11:56] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67019

2757 Andrei Elkin	2009-02-20
      Bug #37313 BINLOG Contains Incorrect server id
        
      Signed integer format specifier forced to print the binlog header with server_id
      negative if the unsigned value sets the sign-bit ON.
        
      Fixed with correcting the specifier to correspond to typeof(server_id) == ulong.
[24 Feb 2009 14:18] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67387

2758 Andrei Elkin	2009-02-24
      fixing compilation warning and adding flush logs to test of bug#37313
[24 Feb 2009 15:01] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67392

2817 Andrei Elkin	2009-02-24 [merge]
      merging bug#37313fixes from 5.0-bt to 5.1-bt
[24 Feb 2009 15:06] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67395

3076 Andrei Elkin	2009-02-24 [merge]
      merging fixes for bug#37313 from 5.0->5.1 bt
[24 Feb 2009 17:26] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/67406

3076 Andrei Elkin	2009-02-24 [merge]
      merging bug#37313fixes from 5.0-bt -> 5.1-bt -> 6.0-bt
[9 Mar 2009 14:14] Bugs System
Pushed into 5.0.79 (revid:joro@sun.com-20090309135922-a0di9ebkxoj4d4wv) (version source revid:aelkin@mysql.com-20090224141734-1fl9i2eosw0rt3kl) (merge vers: 5.0.79) (pib:6)
[10 Mar 2009 13:51] Jon Stephens
Documented bugfix in the 5.0.79 changelog as follows:

        Server IDs greater than 2147483647 (2³²-1) were represented 
        by negative numbers in the binary log.

Set status to NDI pending merges to 5.1 and 6.0 trees.
[13 Mar 2009 19:06] Bugs System
Pushed into 5.1.33 (revid:joro@sun.com-20090313111355-7bsi1hgkvrg8pdds) (version source revid:patrick.crews@sun.com-20090225081629-ent6zn9d1lt6bx68) (merge vers: 5.1.33) (pib:6)
[15 Mar 2009 10:27] Jon Stephens
Fix also noted in 5.1.33 changelog; set back to NDI status pending merge to 6.0 tree.
[18 Mar 2009 13:21] Bugs System
Pushed into 6.0.11-alpha (revid:joro@sun.com-20090318122208-1b5kvg6zeb4hxwp9) (version source revid:aelkin@mysql.com-20090224172530-tciie915ngdb595w) (merge vers: 6.0.10-alpha) (pib:6)
[18 Mar 2009 15:16] Jon Stephens
Fix also noted in 6.0.11 changelog; closed.
[21 Apr 2009 9:49] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/72558

3220 Andrei Elkin	2009-04-21 [merge]
      merging bug#37313fixes from 5.1-bt to 6.0-bt
[6 May 2009 14:11] Bugs System
Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:aelkin@mysql.com-20090421094803-hho7a34gdsby7382) (merge vers: 6.0.11-alpha) (pib:6)
[9 May 2009 16:45] Bugs System
Pushed into 5.1.34-ndb-6.2.18 (revid:jonas@mysql.com-20090508185236-p9b3as7qyauybefl) (version source revid:jonas@mysql.com-20090508100057-30ote4xggi4nq14v) (merge vers: 5.1.33-ndb-6.2.18) (pib:6)
[9 May 2009 17:42] Bugs System
Pushed into 5.1.34-ndb-6.3.25 (revid:jonas@mysql.com-20090509063138-1u3q3v09wnn2txyt) (version source revid:jonas@mysql.com-20090508175813-s6yele2z3oh6o99z) (merge vers: 5.1.33-ndb-6.3.25) (pib:6)
[9 May 2009 18:39] Bugs System
Pushed into 5.1.34-ndb-7.0.6 (revid:jonas@mysql.com-20090509154927-im9a7g846c6u1hzc) (version source revid:jonas@mysql.com-20090509073226-09bljakh9eppogec) (merge vers: 5.1.33-ndb-7.0.6) (pib:6)