Skip to content

Instantly share code, notes, and snippets.

@zehweh

zehweh/logs_mysqld_primary.txt Secret

Created March 17, 2022 15:42
Show Gist options
  • Save zehweh/c55ebe1aedcee5acd498e954baa1cd27 to your computer and use it in GitHub Desktop.
Save zehweh/c55ebe1aedcee5acd498e954baa1cd27 to your computer and use it in GitHub Desktop.
Download ZIP
vitess_v9
Raw
logs_mysqld_primary.txt
I0317 15:33:47.127919 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.127854Z 246 [Note] Aborted connection 246 to db: 'vt_vitesstest' user: 'vt_dba' host: 'localhost' (Got an error reading communication packets)
I0317 15:33:47.136970 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.136905Z 247 [Note] Aborted connection 247 to db: 'vt_vitesstest' user: 'vt_dba' host: 'localhost' (Got an error reading communication packets)
I0317 15:33:47.146364 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.146300Z 248 [Note] Aborted connection 248 to db: 'vt_vitesstest' user: 'vt_dba' host: 'localhost' (Got an error reading communication packets)
I0317 15:33:47.167513 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.167426Z 249 [Note] Aborted connection 249 to db: 'vt_vitesstest' user: 'vt_dba' host: 'localhost' (Got an error reading communication packets)
I0317 15:33:47.475839 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: Killed
I0317 15:33:47.487112 1 mysqld.go:402] Mysqld.Start(1647530981) stdout: 2022-03-17T15:33:47.486529Z mysqld_safe Number of processes running now: 0
I0317 15:33:47.487166 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.486529Z mysqld_safe Number of processes running now: 0
I0317 15:33:47.493240 1 mysqld.go:402] Mysqld.Start(1647530981) stdout: 2022-03-17T15:33:47.492647Z mysqld_safe mysqld restarted
I0317 15:33:47.493319 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.492647Z mysqld_safe mysqld restarted
I0317 15:33:47.732432 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.728265Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
I0317 15:33:47.732465 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.730531Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.31-log) starting as process 663 ...
I0317 15:33:47.734234 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734134Z 0 [Note] InnoDB: PUNCH HOLE support available
I0317 15:33:47.734257 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734155Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
I0317 15:33:47.734265 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734159Z 0 [Note] InnoDB: Uses event mutexes
I0317 15:33:47.734273 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734162Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
I0317 15:33:47.734280 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734165Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
I0317 15:33:47.734288 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734168Z 0 [Note] InnoDB: Using Linux native AIO
I0317 15:33:47.734724 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734641Z 0 [Note] InnoDB: Number of pools: 1
I0317 15:33:47.734802 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.734778Z 0 [Note] InnoDB: Using CPU crc32 instructions
I0317 15:33:47.737090 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.737018Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
I0317 15:33:47.747130 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.747045Z 0 [Note] InnoDB: Completed initialization of buffer pool
I0317 15:33:47.749898 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.749792Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
I0317 15:33:47.769013 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.768949Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
I0317 15:33:47.772574 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.772473Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3035524
I0317 15:33:47.780001 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.779947Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 3204666
I0317 15:33:47.783805 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.783723Z 0 [Note] InnoDB: Database was not shutdown normally!
I0317 15:33:47.783827 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.783738Z 0 [Note] InnoDB: Starting crash recovery.
I0317 15:33:47.811734 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:47.811629Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
I0317 15:33:48.317871 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: InnoDB: Progress in percent: 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
I0317 15:33:48.318262 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.318215Z 0 [Note] InnoDB: Apply batch completed
I0317 15:33:48.318280 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.318253Z 0 [Note] InnoDB: Last MySQL binlog file position 0 1867, file name vt-1728353218-bin.000001
I0317 15:33:48.444881 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.444770Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
I0317 15:33:48.444906 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.444796Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
I0317 15:33:48.444916 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.444875Z 0 [Note] InnoDB: Setting file '/vt/vtdataroot/vt_1728353218/innodb/data/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
I0317 15:33:48.485019 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.484904Z 0 [Note] InnoDB: File '/vt/vtdataroot/vt_1728353218/innodb/data/ibtmp1' size is now 12 MB.
I0317 15:33:48.486136 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.486086Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
I0317 15:33:48.486155 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.486106Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
I0317 15:33:48.486731 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.486676Z 0 [Note] InnoDB: Waiting for purge to start
I0317 15:33:48.536925 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.536840Z 0 [Note] InnoDB: 5.7.31 started; log sequence number 3204666
I0317 15:33:48.537239 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.537199Z 0 [Note] InnoDB: Loading buffer pool(s) from /vt/vtdataroot/vt_1728353218/innodb/data/ib_buffer_pool
I0317 15:33:48.537497 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.537467Z 0 [Note] Plugin 'FEDERATED' is disabled.
I0317 15:33:48.546208 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.546152Z 0 [Note] InnoDB: Buffer pool(s) load completed at 220317 15:33:48
I0317 15:33:48.548471 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.548434Z 0 [Note] Recovering after a crash using /vt/vtdataroot/vt_1728353218/bin-logs/vt-1728353218-bin
I0317 15:33:48.548598 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.548565Z 0 [Note] Starting crash recovery...
I0317 15:33:48.548622 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.548594Z 0 [Note] Crash recovery finished.
I0317 15:33:48.556369 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.556312Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
I0317 15:33:48.556393 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.556343Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
I0317 15:33:48.557753 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.557709Z 0 [Warning] CA certificate ca.pem is self signed.
I0317 15:33:48.557864 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.557808Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
I0317 15:33:48.558279 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.558239Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
I0317 15:33:48.558338 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.558314Z 0 [Note] IPv6 is available.
I0317 15:33:48.558354 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.558328Z 0 [Note] - '::' resolves to '::';
I0317 15:33:48.558380 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.558360Z 0 [Note] Server socket created on IP: '::'.
I0317 15:33:48.595505 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.595380Z 0 [Note] Event Scheduler: Loaded 0 events
I0317 15:33:48.595826 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:48.595779Z 0 [Note] /usr/sbin/mysqld: ready for connections.
I0317 15:33:48.595838 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: Version: '5.7.31-log' socket: '/vt/socket/mysql.sock' port: 3306 MySQL Community Server (GPL)
I0317 15:33:50.070541 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:50.070421Z 5 [Note] Got an error reading communication packets
I0317 15:33:50.714036 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:50.713925Z 6 [Note] Aborted connection 6 to db: '_vt' user: 'vt_filtered' host: 'localhost' (Got an error reading communication packets)
I0317 15:33:52.051572 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:52.051463Z 7 [Note] Got an error reading communication packets
I0317 15:33:54.052480 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:54.052365Z 8 [Note] Got an error reading communication packets
I0317 15:33:56.051889 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:56.051763Z 9 [Note] Got an error reading communication packets
I0317 15:33:57.480043 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:57.479927Z 10 [Note] Start binlog_dump to master_thread_id(10) slave_server(2004361222), pos(, 4)
I0317 15:33:57.480070 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:57.479953Z 10 [Note] Start asynchronous binlog_dump to slave (server_id: 2004361222), pos(, 4)
I0317 15:33:58.052025 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:33:58.051892Z 11 [Note] Got an error reading communication packets
I0317 15:34:00.052629 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:34:00.052528Z 12 [Note] Got an error reading communication packets
I0317 15:34:01.287229 1 mysqld.go:396] Mysqld.Start(1647530981) stderr: 2022-03-17T15:34:01.287093Z 13 [Note] Aborted connection 13 to db: 'vt_vitesstest' user: 'vt_dba' host: 'localhost' (Got an error reading communication packets)
Raw
logs_vtctld.txt
+-----------------------------------------------------------------------------------------------------------------------+
| @@GLOBAL.sql_mode |
+-----------------------------------------------------------------------------------------------------------------------+
| ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION |
+-----------------------------------------------------------------------------------------------------------------------+
+-----------------------------------------------------------------------------------------------------------------------+
| @@GLOBAL.sql_mode |
+-----------------------------------------------------------------------------------------------------------------------+
| ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION |
+-----------------------------------------------------------------------------------------------------------------------+
{
"database_schema": "CREATE DATABASE /*!32312 IF NOT EXISTS*/ {{.DatabaseName}} /*!40100 DEFAULT CHARACTER SET utf8 */",
"table_definitions": [
],
"version": "d41d8cd98f00b204e9800998ecf8427e"
}
I0317 15:33:46.788191 1 schema.go:368] _vt.shard_metadata doesn't exist on the source tablet zone1-2175114085, skipping its copy.
Raw
logs_vttablet_primary.txt
I0317 15:33:47.167305 1 engine.go:367] schema engine created [wp_commentmeta wp_comments wp_links wp_options wp_postmeta wp_posts wp_term_relationships wp_term_taxonomy wp_termmeta wp_terms wp_usermeta wp_users], altered [], dropped []
W0317 15:33:47.475884 1 rpc_server.go:80] TabletManager.GetSchema(include_views:true )(on zone1-1728353218 from ) error: EOF (errno 2013) (sqlstate HY000) during query: SELECT
table_name AS table_name,
ordinal_position AS ordinal_position,
column_name AS column_name
FROM information_schema.key_column_usage
WHERE table_schema = 'vt_vitesstest'
AND table_name IN ('wp_commentmeta', 'wp_comments', 'wp_links', 'wp_options', 'wp_postmeta', 'wp_posts', 'wp_term_relationships', 'wp_term_taxonomy', 'wp_termmeta', 'wp_terms', 'wp_usermeta', 'wp_users')
AND constraint_name='PRIMARY'
ORDER BY table_name, ordinal_position
EOF (errno 2013) (sqlstate HY000) during query: SELECT * FROM `vt_vitesstest`.`wp_commentmeta` WHERE 1=0
EOF (errno 2013) (sqlstate HY000) during query: SELECT * FROM `vt_vitesstest`.`wp_postmeta` WHERE 1=0
EOF (errno 2013) (sqlstate HY000) during query: SELECT * FROM `vt_vitesstest`.`wp_posts` WHERE 1=0
EOF (errno 2013) (sqlstate HY000) during query: SELECT * FROM `vt_vitesstest`.`wp_terms` WHERE 1=0
EOF (errno 2013) (sqlstate HY000) during query: SHOW CREATE TABLE `vt_vitesstest`.`wp_options`
EOF (errno 2013) (sqlstate HY000) during query: SHOW CREATE TABLE `vt_vitesstest`.`wp_term_relationships`
EOF (errno 2013) (sqlstate HY000) during query: SHOW CREATE TABLE `vt_vitesstest`.`wp_term_taxonomy`
EOF (errno 2013) (sqlstate HY000) during query: SHOW CREATE TABLE `vt_vitesstest`.`wp_usermeta`
EOF (errno 2013) (sqlstate HY000) during query: SHOW CREATE TABLE `vt_vitesstest`.`wp_users`
W0317 15:33:47.494901 1 rpc_server.go:80] TabletManager.GetSchema()(on zone1-1728353218 from ) error: net.Dial(/vt/socket/mysql.sock) to local server failed: dial unix /vt/socket/mysql.sock: connect: no such file or directory (errno 2002) (sqlstate HY000)
E0317 15:33:49.333382 1 executor.go:1363] The MySQL server is running with the --read-only option so it cannot execute this statement (errno 1290) (sqlstate HY000) during query: UPDATE _vt.schema_migrations
SET
migration_status='queued',
tablet='zone1-1728353218',
retries=retries + 1,
tablet_failure=0,
ready_timestamp=NULL,
started_timestamp=NULL,
liveness_timestamp=NULL,
completed_timestamp=NULL,
cleanup_timestamp=NULL
WHERE
migration_status IN ('failed', 'cancelled')
AND (
tablet_failure=1
AND migration_status='failed'
AND retries=0
)
LIMIT 1
E0317 15:33:49.387528 1 executor.go:1366] The MySQL server is running with the --read-only option so it cannot execute this statement (errno 1290) (sqlstate HY000) during query: UPDATE _vt.schema_migrations
SET
migration_status='ready',
ready_timestamp=NOW()
WHERE
migration_status='queued'
ORDER BY
requested_timestamp ASC
LIMIT 1
I0317 15:33:50.713936 1 rpc_server.go:84] TabletManager.VReplicationExec(query:"select distinct workflow from _vt.vreplication where state != 'Stopped' and db_name = 'vt_vitesstest'" )(on zone1-1728353218 from ): (*tabletmanagerdata.VReplicationExecResponse)(nil)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment