Alvaro Herrera <alvherre at commandprompt.com> writes:

> Christopher Browne wrote:
>
>> There are no notable compiler complaints about
>> src/backend/slony_funcs.c, so the mismatch must be at a subtler level
>> than that of an up-front API change for something.
>> 
>> I suppose a next step might be to kick off gdb against the backend when
>> processing this.
>
> Yeah, let's see a backtrace.  Maybe we need to break an API somewhere so
> that this becomes more obvious at compile time.

Cool.

Hooked up gdb to an appropriate backend process...

- psql session:
slonyregress1=# delete from table1;

(which will fire the log trigger twice)

... and gdb tells me...

(gdb) continue
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x081b8d6e in SPI_getbinval ()
(gdb) where
#0  0x081b8d6e in SPI_getbinval ()
#1  0xb5c7c7bd in _Slony_I_logTrigger (fcinfo=0xbfdfbbd0) at slony1_funcs.c:487
#2  0x083101ac in fmgr_security_definer ()
#3  0x0817efec in ExecCallTriggerFunc ()
#4  0x0817f43f in afterTriggerInvokeEvents ()
#5  0x08180461 in AfterTriggerEndQuery ()
#6  0x08252de3 in ProcessQuery ()
#7  0x08252f7b in PortalRunMulti ()
#8  0x082536bc in PortalRun ()
#9  0x0824fba0 in exec_simple_query ()
#10 0x08250d3e in PostgresMain ()
#11 0x0821d598 in ServerLoop ()
#12 0x0821fe87 in PostmasterMain ()
#13 0x081c6887 in main ()
(gdb) 

I set a breakpoint at _Slony_I_logTrigger, and stepped thru, with the
following output:

(gdb) break _Slony_I_logTrigger
Function "_Slony_I_logTrigger" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (_Slony_I_logTrigger) pending.
(gdb) continue
Continuing.

Breakpoint 1, _Slony_I_logTrigger (fcinfo=0xbfdfbbd0) at slony1_funcs.c:402
402	{
(gdb) step
403		TransactionId newXid = GetTopTransactionId();
(gdb) step
418		if (!CALLED_AS_TRIGGER(fcinfo))
(gdb) step
425		if (!TRIGGER_FIRED_AFTER(tg->tg_event))
(gdb) step
427		if (!TRIGGER_FIRED_FOR_ROW(tg->tg_event))
(gdb) step
429		if (tg->tg_trigger->tgnargs != 3)
(gdb) step
435		if ((rc = SPI_connect()) < 0)
(gdb) step
441		cluster_name = DatumGetName(DirectFunctionCall1(namein,
(gdb) step
443		tab_id = strtol(tg->tg_trigger->tgargs[1], NULL, 10);
(gdb) step
441		cluster_name = DatumGetName(DirectFunctionCall1(namein,
(gdb) step
443		tab_id = strtol(tg->tg_trigger->tgargs[1], NULL, 10);
(gdb) step
444		attkind = tg->tg_trigger->tgargs[2];
(gdb) step
450		cs = getClusterStatus(cluster_name, PLAN_INSERT_LOG);
(gdb) step
443		tab_id = strtol(tg->tg_trigger->tgargs[1], NULL, 10);
(gdb) step
444		attkind = tg->tg_trigger->tgargs[2];
(gdb) step
450		cs = getClusterStatus(cluster_name, PLAN_INSERT_LOG);
(gdb) step
getClusterStatus (cluster_name=0xa1e59a0, need_plan_mask=4) at slony1_funcs.c:1262
1262	{
(gdb) step
1274		for (cs = clusterStatusList; cs; cs = cs->next)
(gdb) step
1298			cs = (Slony_I_ClusterStatus *) malloc(sizeof(Slony_I_ClusterStatus));
(gdb) step
1299			memset(cs, 0, sizeof(Slony_I_ClusterStatus));
(gdb) step
1298			cs = (Slony_I_ClusterStatus *) malloc(sizeof(Slony_I_ClusterStatus));
(gdb) step
1299			memset(cs, 0, sizeof(Slony_I_ClusterStatus));
(gdb) step
1316			snprintf(query, 1024, "select last_value::int4 from %s.sl_local_node_id",
(gdb) step
1304			strncpy(NameStr(cs->clustername), NameStr(*cluster_name), NAMEDATALEN);
(gdb) step
1309			cs->clusterident = strdup(DatumGetCString(DirectFunctionCall1(textout,
(gdb) step
1316			snprintf(query, 1024, "select last_value::int4 from %s.sl_local_node_id",
(gdb) step
1318			rc = SPI_exec(query, 0);
(gdb) step
1319			if (rc < 0 || SPI_processed != 1)
(gdb) step
1321			cs->localNodeId = DatumGetInt32(
(gdb) step
1323			SPI_freetuptable(SPI_tuptable);
(gdb) step
1324			if (cs->localNodeId < 0)
(gdb) step
1330			cs->currentXid = InvalidTransactionId;
(gdb) step
1335			cs->next = clusterStatusList;
(gdb) step
1330			cs->currentXid = InvalidTransactionId;
(gdb) step
1335			cs->next = clusterStatusList;
(gdb) step
1336			clusterStatusList = cs;
(gdb) step
1342		if ((need_plan_mask & PLAN_NOTIFY_EVENT) != 0 &&
(gdb) step
1356		if ((need_plan_mask & PLAN_INSERT_EVENT) != 0 &&
(gdb) step
1444		if ((need_plan_mask & PLAN_INSERT_LOG) != 0 &&
(gdb) step
1445			(cs->have_plan & PLAN_INSERT_LOG) == 0)
(gdb) step
1450			xxid_typename = makeNode(TypeName);
(gdb) step
1453						makeString("xxid"));
(gdb) step
1452				lappend(lappend(NIL, makeString(NameStr(cs->clustername))),
(gdb) step
1451			xxid_typename->names =
(gdb) step
1455	                xxid_typid = typenameTypeId(NULL, xxid_typename,NULL);
(gdb) step
1467			sprintf(query, "INSERT INTO %s.sl_log_1 "
(gdb) step
1455	                xxid_typid = typenameTypeId(NULL, xxid_typename,NULL);
(gdb) step
1467			sprintf(query, "INSERT INTO %s.sl_log_1 "
(gdb) step
1473			plan_types[0] = xxid_typid;
(gdb) step
1478			cs->plan_insert_log_1 = SPI_saveplan(SPI_prepare(query, 4, plan_types));
(gdb) step
1474			plan_types[1] = INT4OID;
(gdb) step
1475			plan_types[2] = TEXTOID;
(gdb) step
1473			plan_types[0] = xxid_typid;
(gdb) step
1476			plan_types[3] = TEXTOID;
(gdb) step
1478			cs->plan_insert_log_1 = SPI_saveplan(SPI_prepare(query, 4, plan_types));
(gdb) step
1479			if (cs->plan_insert_log_1 == NULL)
(gdb) step
1478			cs->plan_insert_log_1 = SPI_saveplan(SPI_prepare(query, 4, plan_types));
(gdb) step
1479			if (cs->plan_insert_log_1 == NULL)
(gdb) step
1482			sprintf(query, "INSERT INTO %s.sl_log_2 "
(gdb) step
1488			plan_types[0] = xxid_typid;
(gdb) step
1493			cs->plan_insert_log_2 = SPI_saveplan(SPI_prepare(query, 4, plan_types));
(gdb) step
1489			plan_types[1] = INT4OID;
(gdb) step
1490			plan_types[2] = TEXTOID;
(gdb) step
1488			plan_types[0] = xxid_typid;
(gdb) step
1491			plan_types[3] = TEXTOID;
(gdb) step
1493			cs->plan_insert_log_2 = SPI_saveplan(SPI_prepare(query, 4, plan_types));
(gdb) step
1494			if (cs->plan_insert_log_2 == NULL)
(gdb) step
1493			cs->plan_insert_log_2 = SPI_saveplan(SPI_prepare(query, 4, plan_types));
(gdb) step
1494			if (cs->plan_insert_log_2 == NULL)
(gdb) step
1501			cs->cmdtype_I = malloc(VARHDRSZ + 1);
(gdb) step
1502			SET_VARSIZE(cs->cmdtype_I, VARHDRSZ + 1);
(gdb) step
1503			*VARDATA(cs->cmdtype_I) = 'I';
(gdb) step
1504			cs->cmdtype_U = malloc(VARHDRSZ + 1);
(gdb) step
1505			SET_VARSIZE(cs->cmdtype_U, VARHDRSZ + 1);
(gdb) step
1506			*VARDATA(cs->cmdtype_U) = 'U';
(gdb) step
1507			cs->cmdtype_D = malloc(VARHDRSZ + 1);
(gdb) step
1508			SET_VARSIZE(cs->cmdtype_D, VARHDRSZ + 1);
(gdb) step
1509			*VARDATA(cs->cmdtype_D) = 'D';
(gdb) step
1514			sprintf(query, "SELECT last_value::int4 FROM %s.sl_log_status",
(gdb) step
1516			cs->plan_get_logstatus = SPI_saveplan(SPI_prepare(query, 0, NULL));
(gdb) step
1518			cs->cmddata_size = 8192;
(gdb) step
1516			cs->plan_get_logstatus = SPI_saveplan(SPI_prepare(query, 0, NULL));
(gdb) step
1519			cs->cmddata_buf = (text *) malloc(8192);
(gdb) step
1521			cs->have_plan |= PLAN_INSERT_LOG;
(gdb) step
1519			cs->cmddata_buf = (text *) malloc(8192);
(gdb) step
1525	}
(gdb) step
_Slony_I_logTrigger (fcinfo=0xbfdfbbd0) at slony1_funcs.c:455
455		switch (cs->session_role)
(gdb) step
458				cs->session_role = SLON_ROLE_NORMAL;
(gdb) step
475		if (!TransactionIdEquals(cs->currentXid, newXid))
(gdb) step
482			if(SPI_execp(cs->plan_get_logstatus, NULL, NULL, 0) < 0)
(gdb) step
484			if (SPI_processed != 1)
(gdb) step
487			log_status = DatumGetInt32(SPI_getbinval(SPI_tuptable->vals[0],
(gdb) step


That's not "line 487" as I see it...  The full function call was...

log_status = DatumGetInt32(SPI_getbinval(SPI_tuptable->vals[0],
SPI_tuptable->tupdesc, 1, NULL));

Some possibly useful data:

(gdb) print SPI_tuptable
$1 = (SPITupleTable *) 0xa202a68
(gdb) print SPI_tuptable->tupdesc
$2 = (struct tupleDesc *) 0xa202c98
(gdb) print SPI_tuptable->vals[0]
$3 = (HeapTuple) 0xa202da0

Nothing's leaping out at me, but that's certainly more information than
I had before.
-- 
(reverse (concatenate 'string "ofni.sailifa.ac" "@" "enworbbc"))
Christopher Browne
"Bother,"  said Pooh,  "Eeyore, ready  two photon  torpedoes  and lock
phasers on the Heffalump, Piglet, meet me in transporter room three"