Date: Tue, 6 Sep 2022 18:40:49 -0500
From: Jaime Casanova <jcasanov@systemguards.com.ec>
To: pgsql-hackers@postgresql.org
Subject: START_REPLICATION SLOT causing a crash in an assert build
Message-ID: <YxfagaTXUNa9ggLb@ahch-to>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="Tl+lrq7s8EKEoo5r"
Content-Disposition: inline
Archived-At: 
 <https://www.postgresql.org/message-id/YxfagaTXUNa9ggLb%40ahch-to>
Precedence: bulk


--Tl+lrq7s8EKEoo5r
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Hi,

I'm not sure what is causing this, but I have seen this twice. The
second time without activity after changing the set of tables in a
PUBLICATION.

gdb says that debug_query_string contains:

"""
START_REPLICATION SLOT "sub_pgbench" LOGICAL 0/0 (proto_version '3', publication_names '"pub_pgbench"')START_REPLICATION SLOT "sub_pgbench" LOGICAL 0/0 (proto_version '3', publication_names '"pub_pgbench"')
"""

attached the backtrace.


-- 
Jaime Casanova
Director de Servicios Profesionales
SystemGuards - Consultores de PostgreSQL

--Tl+lrq7s8EKEoo5r
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment;
	filename="gdb_start_replication_slot_crash.txt"

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
        set = {__val = {4194304, 140731069195120, 2, 6, 6807736, 93843951759568, 
            4611686018427388799, 140276820691622, 0, 281470681751456, 0, 0, 0, 0, 0, 0}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007f94bdd51535 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {
              0, 0, 0, 0, 0, 140276818190325, 2, 4122259537847870528, 7018350267711514210, 
              93843951759568, 7003715780713148896, 0, 14048801432222296576, 140731069195360, 0, 
              140731069196224}}, sa_flags = -1083658032, sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00005559bfd4f0ed in ExceptionalCondition (
    conditionName=0x5559bff30e20 "namestrcmp(&statent->slotname, NameStr(slot->data.name)) == 0", errorType=0x5559bff30e0d "FailedAssertion", fileName=0x5559bff30dbb "pgstat_replslot.c", 
    lineNumber=89) at assert.c:69
No locals.
#3  0x00005559bfbd4353 in pgstat_report_replslot (slot=0x7f94bd839280, 
    repSlotStat=0x7ffe81636820) at pgstat_replslot.c:89
        entry_ref = 0x5559c0876130
        shstatent = 0x7f94b48f2000
        statent = 0x7f94b48f2018
#4  0x00005559bfb09f76 in UpdateDecodingStats (ctx=0x5559c091ca50) at logical.c:1862
        rb = 0x5559c093f5c0
        repSlotStat = {slotname = {
            data = "\300\365\223\300YU\000\000X\206\227\300YU\000\000\250\031\225\300YU\000\000\225\257\261\277\000\000\000\000\240hc\201\376\177\000\000aT\261\277YU", '\000' <repeats 17 times>}, spill_txns = 0, spill_count = 0, spill_bytes = 0, stream_txns = 0, stream_count = 0, 
          stream_bytes = 0, total_txns = 1, total_bytes = 684, 
          stat_reset_timestamp = 140731069196560}
        __func__ = "UpdateDecodingStats"
#5  0x00005559bfb03d2e in DecodeCommit (ctx=0x5559c091ca50, buf=0x7ffe81636b30, 
    parsed=0x7ffe81636930, xid=74033, two_phase=false) at decode.c:706
        origin_lsn = 0
        commit_time = 715805149160794
        origin_id = 0
        i = 0
#6  0x00005559bfb03055 in xact_decode (ctx=0x5559c091ca50, buf=0x7ffe81636b30) at decode.c:216
        xlrec = 0x5559c095b608
        parsed = {xact_time = 715805149160794, xinfo = 73, dbId = 65390, tsId = 1663, 
          nsubxacts = 0, subxacts = 0x0, nrels = 0, xnodes = 0x0, nstats = 0, stats = 0x0, 
          nmsgs = 5, msgs = 0x5559c095b620, twophase_xid = 0, 
          twophase_gid = '\000' <repeats 199 times>, nabortrels = 0, abortnodes = 0x0, 
          nabortstats = 0, abortstats = 0x0, origin_lsn = 0, origin_timestamp = 0}
        xid = 74033
        two_phase = false
        builder = 0x5559c0951640
        reorder = 0x5559c093f5c0
        r = 0x5559c091ce10
        info = 0 '\000'
        __func__ = "xact_decode"
#7  0x00005559bfb02d78 in LogicalDecodingProcessRecord (ctx=0x5559c091ca50, 
    record=0x5559c091ce10) at decode.c:119
        buf = {origptr = 18637212136, endptr = 18637212272, record = 0x5559c091ce10}
        txid = 0
        rmgr = {rm_name = 0x5559bfdf3c45 "Transaction", rm_redo = 0x5559bf792884 <xact_redo>, 
          rm_desc = 0x5559bf75aa12 <xact_desc>, rm_identify = 0x5559bf75ab8f <xact_identify>, 
          rm_startup = 0x0, rm_cleanup = 0x0, rm_mask = 0x0, 
          rm_decode = 0x5559bfb02edd <xact_decode>}
#8  0x00005559bfb3aecd in XLogSendLogical () at walsender.c:3073
        record = 0x5559c095b5d8
        errm = 0x0
        flushPtr = 18637212272
        __func__ = "XLogSendLogical"
#9  0x00005559bfb3a1b4 in WalSndLoop (send_data=0x5559bfb3ae2b <XLogSendLogical>)
    at walsender.c:2503
        __func__ = "WalSndLoop"
#10 0x00005559bfb389fe in StartLogicalReplication (cmd=0x5559c08795d8) at walsender.c:1333
        buf = {data = 0x0, len = 3, maxlen = 1024, cursor = 87}
        qc = {commandTag = 2170776608, nprocessed = 93843959044340}
        __func__ = "StartLogicalReplication"
#11 0x00005559bfb394b0 in exec_replication_command (
    cmd_string=0x5559c08518a0 "START_REPLICATION SLOT \"sub_pgbench\" LOGICAL 0/0 (proto_version '3', publication_names '\"pub_pgbench\"')") at walsender.c:1843
        cmd = 0x5559c08795d8
        parse_rc = 0
        cmd_node = 0x5559c08795d8
        cmdtag = 0x5559bff17e7a "START_REPLICATION"
        cmd_context = 0x5559c0878620
        old_context = 0x5559c0851780
        __func__ = "exec_replication_command"
#12 0x00005559bfbadbbd in PostgresMain (dbname=0x5559c087df10 "pgbench", 
    username=0x5559c087dee8 "jcasanov") at postgres.c:4577
        query_string = 0x5559c08518a0 "START_REPLICATION SLOT \"sub_pgbench\" LOGICAL 0/0 (proto_version '3', publication_names '\"pub_pgbench\"')"
        firstchar = 81
        input_message = {
          data = 0x5559c08518a0 "START_REPLICATION SLOT \"sub_pgbench\" LOGICAL 0/0 (proto_version '3', publication_names '\"pub_pgbench\"')", len = 104, maxlen = 1024, cursor = 104}
        local_sigjmp_buf = {{__jmpbuf = {0, -7936202095441544365, 93843951759568, 
              140731069198816, 0, 0, -7936202095395407021, -4282202453475132589}, 
            __mask_was_saved = 1, __saved_mask = {__val = {4194304, 7816406667250393444, 15679, 
                15680, 979, 18446744073709551536, 0, 0, 140276817146995, 3904, 0, 
                140731069197792, 93843951759568, 140731069198816, 93843959067244, 15616}}}}
        send_ready_for_query = false
        idle_in_transaction_timeout_enabled = false
        idle_session_timeout_enabled = false
        __func__ = "PostgresMain"
#13 0x00005559bfae5887 in BackendRun (port=0x5559c08775b0) at postmaster.c:4504
No locals.
#14 0x00005559bfae51d3 in BackendStartup (port=0x5559c08775b0) at postmaster.c:4232
        bn = 0x5559c0876f60
        pid = 0
        __func__ = "BackendStartup"
#15 0x00005559bfae1618 in ServerLoop () at postmaster.c:1806
        port = 0x5559c08775b0
        i = 2
        rmask = {fds_bits = {128, 0 <repeats 15 times>}}
        selres = 1
        now = 1662433420
        readmask = {fds_bits = {224, 0 <repeats 15 times>}}
        nSockets = 8
        last_lockfile_recheck_time = 1662433408
        last_touch_time = 1662432668
        __func__ = "ServerLoop"
#16 0x00005559bfae0e67 in PostmasterMain (argc=3, argv=0x5559c084aeb0) at postmaster.c:1478
        opt = -1
        status = 0
        userDoption = 0x5559c086e8a0 "data1"
        listen_addr_saved = true
        i = 64
        output_config_variable = 0x0
        __func__ = "PostmasterMain"
#17 0x00005559bf9e0266 in main (argc=3, argv=0x5559c084aeb0) at main.c:202
        do_check_root = true

--Tl+lrq7s8EKEoo5r--