search

xstevens / decoderbufs

INACTIVE: A PostgreSQL logical decoder output plugin to deliver data as Protocol Buffers
MIT License
124 stars 59 forks source link

call to decoderbufs__row_message__get_packed_size() in pg_decode_change() crashes #6

Open nacivida opened 7 years ago

nacivida commented 7 years ago

This was seen when I was using a fork of decoderbufs in debezium project, please see the issue. Basically, I start with empty database and run django migrations, then the first insert causes this. Any idea what may be going on?

xstevens commented 7 years ago

Only thing I can think of is Protocol Buffers and/or protobuf-c are possibly out of sync. I haven't touched this code in a couple of years, but I was able to upgrade to latest versions, re-generate the src/proto/*.{h,c} code and push through some samples.

I'm not super familiar with Django so I'm not using it here to test. I did try to guess at what I thought their table definition might look like. If you have a specific CREATE TABLE statement or just drop the output of \d accounts_user from psql for the account_users table, I'd be happy to try it out.

UPDATE: Forgot my versions locally are: Protocol Buffers 3.2, upgraded to proto syntax to 3 and using protobuf-c latest (1.2.1). I hope this helps!

nacivida commented 7 years ago

@xstevens, thanks for looking into this. The schema is:

➜  sally psql -U naci -h localhost testdb
psql (9.6.2)
Type "help" for help.

testdb=# \d accounts_user
                                           Table "public.accounts_user"
          Column          |           Type           |                         Modifiers
--------------------------+--------------------------+------------------------------------------------------------
 id                       | integer                  | not null default nextval('accounts_user_id_seq'::regclass)
 password                 | character varying(128)   | not null
 last_login               | timestamp with time zone |
 is_superuser             | boolean                  | not null
 stripe_customer_id       | character varying(50)    |
 stripe_subscription_data | text                     |
 uuid                     | uuid                     | not null
 created                  | timestamp with time zone | not null
 modified                 | timestamp with time zone | not null
 email                    | character varying(254)   | not null
 first_name               | character varying(50)    | not null
 last_name                | character varying(50)    | not null
 image                    | character varying(100)   |
 is_staff                 | boolean                  | not null
 is_active                | boolean                  | not null
 date_joined              | timestamp with time zone | not null
 facebook_access_token    | text                     |
 timezone                 | character varying(100)   | not null
 allow_phi_in_emails      | boolean                  | not null
 phone                    | character varying(20)    |
 subscription_status      | character varying(10)    | not null
 last_opened              | timestamp with time zone |
 cancel_at_period_end     | boolean                  | not null
 zip_code                 | character varying(20)    |
 cancel_date              | timestamp with time zone |
 google_api_credentials   | text                     |
 google_auth_flow         | text                     |
Indexes:
    "accounts_user_pkey" PRIMARY KEY, btree (id)
    "accounts_user_email_key" UNIQUE CONSTRAINT, btree (email)
    "accounts_user_created_60aaad7fa460bf0d_uniq" btree (created)
    "accounts_user_ef7c876f" btree (uuid)
    "accounts_user_email_70e5d3371c73dba5_like" btree (email varchar_pattern_ops)
    "accounts_user_f75b7600" btree (stripe_customer_id)
    "accounts_user_stripe_customer_id_432175d47de43b8_like" btree (stripe_customer_id varchar_pattern_ops)
Referenced by:
    TABLE "accounts_appinstall" CONSTRAINT "accounts_appinstal_user_id_2efebd4daac225dd_fk_accounts_user_id" FOREIGN KEY (user_id) REFERENCES accounts_user(id) DEFERRABLE INITIALLY DEFERRED
    TABLE "accounts_physicaldevice_users" CONSTRAINT "accounts_physicald_user_id_3363922469a54657_fk_accounts_user_id" FOREIGN KEY (user_id) REFERENCES accounts_user(id) DEFERRABLE INITIALLY DEFERRED
    TABLE "accounts_user_groups" CONSTRAINT "accounts_user_grou_user_id_5304ac17525e2eca_fk_accounts_user_id" FOREIGN KEY (user_id) REFERENCES accounts_user(id) DEFERRABLE INITIALLY DEFERRED
    TABLE "accounts_user_user_permissions" CONSTRAINT "accounts_user_user_user_id_36acf6a3f4222c20_fk_accounts_user_id" FOREIGN KEY (user_id) REFERENCES accounts_user(id) DEFERRABLE INITIALLY DEFERRED
    TABLE "django_admin_log" CONSTRAINT "django_admin_log_user_id_52fdd58701c5f563_fk_accounts_user_id" FOREIGN KEY (user_id) REFERENCES accounts_user(id) DEFERRABLE INITIALLY DEFERRED
    TABLE "reversion_revision" CONSTRAINT "reversion_revision_user_id_53d027e45b2ec55e_fk_accounts_user_id" FOREIGN KEY (user_id) REFERENCES accounts_user(id) DEFERRABLE INITIALLY DEFERRED

testdb=#

How I get this is: I run python manage.py migrate, which creates all tables, constraints, etc, adding some records. Then I drop a lot of tables for the sake of privacy and simplicity.

nacivida commented 7 years ago

BTW, it is actually crashing when it is in protobuf_c.c:protobuf_c_message_get_packed_size(). But not sure what causes it. The strange thing is, after I ran migrations, I do a pg_dumpall, drop the db, restore it from that pg_dumpall, then it doesn't crash, not at first time at least, may be later. I put some printf's to at the entry and exit of that function. See the attached logs from postgres server in debug mode. It looks like when it is evaluating 17th column, which is facebook_access_token, it fails. It is null. The DDL that fails it:

INSERT INTO "accounts_user" ("password", "last_login", "is_superuser", "stripe_customer_id", "stripe_subscription_data",
    "subscription_status", "cancel_at_period_end", "cancel_date", "uuid", "created", "modified", "email", "first_name",
    "last_name", "image", "is_staff", "is_active", "date_joined", "facebook_access_token", "timezone", "phone", "zip_code",
    "allow_phi_in_emails", "last_opened", "google_auth_flow", "google_api_credentials")
VALUES ('', NULL, false, NULL, NULL, 'canceled', false, NULL, '46b82ef3-52c7-4113-8a60-4dbd9f7cbca1'::uuid,
    '2017-04-17T19:43:54.722483+00:00'::timestamptz, '2017-04-17T19:43:54.722501+00:00'::timestamptz, 'naci20@test.com',
    'naci', 'ishak', '', false, true, '2017-04-17T19:43:54.708325+00:00'::timestamptz, NULL, 'America/Los_Angeles', NULL,
    NULL, false, NULL, NULL, NULL) RETURNING "id";
nacivida commented 7 years ago

Fail log:

DEBUG:  sending replication keepalive
DEBUG:  write 0/4D1BF08 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  write 0/4D1BF08 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  write 0/4D1BF08 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG:  Entering decode_change  callback
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  decoding INSERT for table public.accounts_user; relation is selective
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  decoding new tuple information
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing tuple with 31 columns
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 1 with name id
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 2 with name password
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 3 with name last_login
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column last_login is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 4 with name is_superuser
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 5 with name stripe_customer_id
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column stripe_customer_id is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 6 with name stripe_subscription_data
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column stripe_subscription_data is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 7 with name uuid
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 8 with name created
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 9 with name modified
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 10 with name email
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 11 with name first_name
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 12 with name last_name
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 13 with name image
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 14 with name is_staff
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 15 with name is_active
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 16 with name date_joined
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  skipping column 17 because it's a dropped column
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  skipping column 18 because it's a dropped column
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 19 with name facebook_access_token
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column facebook_access_token is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 20 with name timezone
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  skipping column 21 because it's a dropped column
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 22 with name allow_phi_in_emails
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  skipping column 23 because it's a dropped column
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 24 with name phone
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column phone is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 25 with name subscription_status
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 26 with name last_opened
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column last_opened is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 27 with name cancel_at_period_end
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 28 with name zip_code
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column zip_code is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 29 with name cancel_date
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column cancel_date is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 30 with name google_api_credentials
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column google_api_credentials is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  processing column 31 with name google_auth_flow
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  column google_auth_flow is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  NACI: processed tuple done.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  NACIPG: Entering OutputPluginPrepareWrite
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  NACIPG: leaving OutputPluginPrepareWrite
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  NACI: OutputPluginPrepareWrite done.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
DEBUG:  NACI: calling decoderbufs__row_message__get_packed_size.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/4D1C058
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: entering repeated_field_get_packed_size
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 8
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 15
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 15
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 18
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 23
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 28
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 47
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 21
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 22
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 27
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 21
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 21
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 12
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 14
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 15
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 25
PROTOBUF_C: entering protobuf_c_message_get_packed_size
DEBUG:  server process (PID 17131) was terminated by signal 11: Segmentation fault
LOG:  server process (PID 17131) was terminated by signal 11: Segmentation fault
LOG:  terminating any other active server processes
DEBUG:  sending SIGQUIT to process 17813
DEBUG:  sending SIGQUIT to process 16418
DEBUG:  sending SIGQUIT to process 16417
DEBUG:  sending SIGQUIT to process 16419
DEBUG:  sending SIGQUIT to process 16420
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  sending SIGQUIT to process 16421
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
DEBUG:  writing stats file "pg_stat/global.stat"
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
DEBUG:  writing stats file "pg_stat/db_29341.stat"
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
DEBUG:  server process (PID 17813) exited with exit code 2
DETAIL:  Failed process was running: INSERT INTO "accounts_user" ("password", "last_login", "is_superuser", "stripe_customer_id", "stripe_subscription_data", "subscription_status", "cancel_at_period_end", "cancel_date", "uuid", "created", "modified", "email", "first_name", "last_name", "image", "is_staff", "is_active", "date_joined", "facebook_access_token", "timezone", "phone", "zip_code", "allow_phi_in_emails", "last_opened", "google_auth_flow", "google_api_credentials") VALUES ('', NULL, false, NULL, NULL, 'canceled', false, NULL, '46b82ef3-52c7-4113-8a60-4dbd9f7cbca1'::uuid, '2017-04-17T19:43:54.722483+00:00'::timestamptz, '2017-04-17T19:43:54.722501+00:00'::timestamptz, 'naci75@test.com', 'naci', 'ishak', '', false, true, '2017-04-17T19:43:54.708325+00:00'::timestamptz, NULL, 'America/Los_Angeles', NULL, NULL, false, NULL, NULL, NULL) RETURNING "id";
DEBUG:  removing temporary stats file "pg_stat_tmp/db_29341.stat"
DEBUG:  writing stats file "pg_stat/db_0.stat"
DEBUG:  removing temporary stats file "pg_stat_tmp/db_0.stat"
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
LOG:  all server processes terminated; reinitializing
DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
DEBUG:  cleaning up dynamic shared memory control segment with ID 1632341530
DEBUG:  invoking IpcMemoryCreate(size=148455424)
DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
DEBUG:  removing file "pg_notify/0000"
DEBUG:  dynamic shared memory system will support 288 segments
DEBUG:  created dynamic shared memory control segment 569292035 (2316 bytes)
LOG:  database system was interrupted; last known up at 2017-05-03 17:23:23 PDT
DEBUG:  checkpoint record is at 0/4D1BE60
DEBUG:  redo record is at 0/4D1BE60; shutdown TRUE
DEBUG:  next transaction ID: 0:6304; next OID: 34216
DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
DEBUG:  oldest unfrozen transaction ID: 858, in database 1
DEBUG:  oldest MultiXactId: 1, in database 1
DEBUG:  commit timestamp Xid oldest/newest: 0/0
DEBUG:  transaction ID wrap limit is 2147484505, limited by database with OID 1
DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
DEBUG:  starting up replication slots
DEBUG:  restoring replication slot from "pg_replslot/debezium/state"
DEBUG:  starting up replication origin progress state
LOG:  database system was not properly shut down; automatic recovery in progress
DEBUG:  resetting unlogged relations: cleanup 1 init 0
LOG:  redo starts at 0/4D1BED0
LOG:  invalid record length at 0/4D1CA78: wanted 24, got 0
LOG:  redo done at 0/4D1CA48
LOG:  last completed transaction was at log time 2017-05-03 17:26:55.125833-07
DEBUG:  resetting unlogged relations: cleanup 0 init 1
DEBUG:  performing replication slot checkpoint
DEBUG:  attempting to remove WAL segments older than log file 000000000000000000000003
DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
LOG:  MultiXact member wraparound protections are now enabled
DEBUG:  MultiXact member stop limit is now 4294914944 based on MultiXact 1
DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(0): 3 on_shmem_exit callbacks to make
DEBUG:  proc_exit(0): 2 callbacks to make
DEBUG:  exit(0)
DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 0 callbacks to make
LOG:  database system is ready to accept connections
DEBUG:  checkpointer updated shared memory configuration values
LOG:  autovacuum launcher started
DEBUG:  InitPostgres
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:
nacivida commented 7 years ago

Success case log:

DEBUG:  sending replication keepalive
DEBUG:  write 0/5BDB1B8 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  write 0/5BDB1B8 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  write 0/5BDB1B8 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  StartTransactionCommand
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG:  ProcessQuery
DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/5BDB420 oldest xid 10149 latest complete 10148 next xid 10150)
DEBUG:  CommitTransactionCommand
DEBUG:  CommitTransaction
DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 10149/1/0 (used), nestlvl: 1, children:
DEBUG:  serializing snapshot to pg_logical/snapshots/0-5BDB3E8.snap
DEBUG:  purged committed transactions from 0 to 0, xmin: 10149, xmax: 10147
DEBUG:  xmin: 10149, xmax: 10147, oldestrunning: 10149
DEBUG:  failed to increase restart lsn: proposed 0/5BDB1E8, after 0/5BDB3E8, current candidate 0/5BDB180, current after 0/5BDB180, flushed up to 0/5BDAE18
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG:  Entering decode_change  callback
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  decoding INSERT for table public.accounts_user; relation is selective
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  decoding new tuple information
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing tuple with 27 columns
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 1 with name id
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 2 with name password
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 3 with name last_login
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column last_login is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 4 with name is_superuser
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 5 with name stripe_customer_id
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column stripe_customer_id is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 6 with name stripe_subscription_data
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column stripe_subscription_data is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 7 with name uuid
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 8 with name created
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 9 with name modified
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 10 with name email
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 11 with name first_name
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 12 with name last_name
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 13 with name image
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 14 with name is_staff
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 15 with name is_active
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 16 with name date_joined
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 17 with name facebook_access_token
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column facebook_access_token is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 18 with name timezone
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 19 with name allow_phi_in_emails
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 20 with name phone
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column phone is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 21 with name subscription_status
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 22 with name last_opened
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column last_opened is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 23 with name cancel_at_period_end
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 24 with name zip_code
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column zip_code is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 25 with name cancel_date
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column cancel_date is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 26 with name google_api_credentials
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column google_api_credentials is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  processing column 27 with name google_auth_flow
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  column google_auth_flow is null, ignoring value
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: processed tuple done.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACIPG: Entering OutputPluginPrepareWrite
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACIPG: leaving OutputPluginPrepareWrite
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: OutputPluginPrepareWrite done.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: calling decoderbufs__row_message__get_packed_size.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: entering repeated_field_get_packed_size
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 8
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 15
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 15
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 18
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 23
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 28
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 47
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 21
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 22
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 27
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 21
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 21
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 12
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 14
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 15
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 25
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 25
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 34
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 25
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 10
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 34
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 16
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 26
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 13
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 16
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 26
PROTOBUF_C: entering protobuf_c_message_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 20
PROTOBUF_C: leaving repeated_field_get_packed_size header_size=27, rv=604
PROTOBUF_C: entering repeated_field_get_packed_size
PROTOBUF_C: exiting protobuf_c_message_get_packed_size with rv= 667
DEBUG:  NACI: calling palloc.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: calling decoderbufs__row_message__pack.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: calling appendBinaryStringInfo.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: calling pfree.
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: calling OutputPluginWrite
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: calling row_message_destroy
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  NACI: exiting decode_change
CONTEXT:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/5BDB2F0
DEBUG:  write 0/5BDB1B8 flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  write 0/5BDB58B flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
DEBUG:  write 0/5BDB58B flush 0/0 apply 0/0
DEBUG:  sending replication keepalive
nacivida commented 7 years ago

Since pg_dumpall doesn't re-produce the problem, if you can, you can try untar'ing the whole data tree in where the data files are located. I had tar'ed /usr/local/var/postgres where homebrew install, but after I re-built postgres in debug mode, in the above examples it was in /usr/local/pgsql/data.

xstevens commented 7 years ago

I did this locally on a fresh Postgres 9.6 and it doesn't crash.

CREATE SEQUENCE accounts_user_id_seq;

CREATE TABLE accounts_user (
    id integer not null default nextval('accounts_user_id_seq'::regclass),
    password character varying(128) not null,
    last_login timestamp with time zone,
    is_superuser boolean not null,
    stripe_customer_id character varying(50),
    stripe_subscription_data text,
    uuid uuid not null,
    created timestamp with time zone not null,
    modified timestamp with time zone not null,
    email character varying(254) not null,
    first_name character varying(50) not null,
    last_name character varying(50) not null,
    image character varying(100),
    is_staff boolean not null,
    is_active boolean not null,
    date_joined timestamp with time zone not null,
    facebook_access_token text,
    timezone character varying(100) not null,
    allow_phi_in_emails boolean not null,
    phone character varying(20),
    subscription_status character varying(10) not null,
    last_opened timestamp with time zone,
    cancel_at_period_end boolean not null,
    zip_code character varying(20),
    cancel_date timestamp with time zone,
    google_api_credentials text,
    google_auth_flow text
);

Then your INSERT statement from above:

INSERT INTO "accounts_user" ("password", "last_login", "is_superuser", "stripe_customer_id", "stripe_subscription_data",
    "subscription_status", "cancel_at_period_end", "cancel_date", "uuid", "created", "modified", "email", "first_name",
    "last_name", "image", "is_staff", "is_active", "date_joined", "facebook_access_token", "timezone", "phone", "zip_code",
    "allow_phi_in_emails", "last_opened", "google_auth_flow", "google_api_credentials")
VALUES ('', NULL, false, NULL, NULL, 'canceled', false, NULL, '46b82ef3-52c7-4113-8a60-4dbd9f7cbca1'::uuid,
    '2017-04-17T19:43:54.722483+00:00'::timestamptz, '2017-04-17T19:43:54.722501+00:00'::timestamptz, 'naci20@test.com',
    'naci', 'ishak', '', false, true, '2017-04-17T19:43:54.708325+00:00'::timestamptz, NULL, 'America/Los_Angeles', NULL,
    NULL, false, NULL, NULL, NULL) RETURNING "id";

I am running my version of the plugin and not the Debezium version on macOS 10.12.4. I still suspect its some sort of mismatch between Protocol Buffers, protobuf-c and possibly the version compiled when the Debezium plugin was made. I would update to the latest and re-compile all three of those if you haven't tried that already.

Best of luck!

nacivida commented 7 years ago

@xstevens, I have the fix. Could you give permission for pull request? It is not allowing me to push the local branch to origin. Thanks.

xstevens commented 7 years ago

@nacivida Try creating a fork first and then you should be able to PR here from your fork. Side note: If you're modifying the debezium version you may want to PR their repo instead.

jmealo commented 7 years ago

@xstevens @nacivida: Great team work. Is this issue resolved?

nacivida commented 7 years ago

@xstevens, yes, it was merged to debezium fork.

jsyvanen commented 6 years ago

Hi @xstevens @nacivida I've filed a bug report to the debezium fork of this repo for an error in the same function but in a different context.

You can see it here: https://issues.jboss.org/browse/DBZ-790

It also causes the DB to crash and I'm not able to controllably reproduce it, yet. It happens in a live environment that has turned out to be hard to replicate.

The error from the logs is: protobuf-c/protobuf-c.c:643: protobuf_c_message_get_packed_size: Assertion `((message)->descriptor)->magic == 0x28aaeef9' failed.

Would you guys be able to take a look at the description in the link and give any advice on what might be going on?

Thanks in advance.

nacivida commented 6 years ago

I haven't been working on this since then, but I couldn't understand what's wrong in your case.

Naci

On Thu, Aug 2, 2018 at 6:56 AM jsyvanen notifications@github.com wrote:

Hi @xstevens https://github.com/xstevens @nacivida https://github.com/nacivida I've filed a bug report to the debezium branch of this repo for an error in the same function but in a different context.

You can see it here: https://issues.jboss.org/browse/DBZ-790

It also causes the DB to crash and I'm not able to controllably reproduce it, yet. It happens in a live environment that has turned out to be hard to replicate.

The error from the logs is: protobuf-c/protobuf-c.c:643: protobuf_c_message_get_packed_size: Assertion `((message)->descriptor)->magic == 0x28aaeef9' failed.

Would you guys be able to take a look at the description in the link and give any advice on what might be going on?

Thanks in advance.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/xstevens/decoderbufs/issues/6#issuecomment-409934979, or mute the thread https://github.com/notifications/unsubscribe-auth/AS_eqW1fU1t7DJvuSmGg0J9dOBeDzbveks5uMwUggaJpZM4NPuy6 .

jsyvanen commented 6 years ago

Thanks @nacivida