Skip to content

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

Open

Description

@nacivida

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?

Activity

  1. xstevens commented on May 3, 2017

    @xstevens
    Owner

    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!

  2. nacivida commented on May 4, 2017

    @nacivida
    Author

    @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.

  3. nacivida commented on May 4, 2017

    @nacivida
    Author

    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";
    
  4. nacivida commented on May 4, 2017

    @nacivida
    Author

    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:  
    
  5. nacivida commented on May 4, 2017

    @nacivida
    Author

    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
    
  6. nacivida commented on May 4, 2017

    @nacivida
    Author

    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.

  7. xstevens commented on May 4, 2017

    @xstevens
    Owner

    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!

  8. nacivida commented on May 5, 2017

    @nacivida
    Author

    @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.

  9. xstevens commented on May 5, 2017

    @xstevens
    Owner

    @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.

  10. jmealo commented on Aug 26, 2017

    @jmealo

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

  11. nacivida commented on Aug 28, 2017

    @nacivida
    Author

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

  12. jsyvanen commented on Aug 2, 2018

    @jsyvanen

    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.

  13. nacivida commented on Aug 3, 2018

    @nacivida
    Author
  14. jsyvanen commented on Aug 4, 2018

    @jsyvanen

    Thanks @nacivida

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions