Algunas sentencias no quedan dentro de transacción

Cordial Saludo compañeros:

Tengo un problema de esos extraños y por último me hace pensar que es un error de postgresql (WINDOWS + postgresql 8.3.7).

Básicamente mi aplicación genera un transacción pero al parecer quedó a medias aunque al final se hizo un commit. Ya se que me van a decir que es algo imposible pero revisando el log (había olvidado desactivar el log_statement) puedo apreciar lo siguiente:

***************************************************************************************************************************
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: BEGIN
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select now() as CurrentDateTime
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select * from def_dtransac where id_transac = 89162
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, d.adsrc from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 48201) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select id_unidadalmacen, id_unidadcampo, factorconv_parte, serializado_parte from def_parte where id_parte = 36841
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, d.adsrc from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 48337) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select id_parte, codigo_parte, serial_parte from def_parte where id_parte = 36841
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select id_parte from def_parte where codigo_parte = 'R40000238' AND serial_parte = '0015A2DE04BD'
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 0 LOG: loaded library "$libdir/plugins/plugin_debugger.dll"
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select oid, typbasetype from pg_type where typname = 'lo'
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select * from def_parte where codigo_parte = 'R40000238' AND serial_parte = '0'
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, d.adsrc from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 48337) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: insert into def_parte (codigo_parte, serial_parte, descripcion_parte, abreviatura_parte, id_tipoparte, id_almacen, id_localizacion, codigoalt_parte, serializado_parte, orden_parte, id_unidadalmacen, id_unidadcampo, factorconv_parte, id_fuente, peso_parte, vreposicion_parte, reorden_parte, stockmin_parte, stockdeseado_parte, minreorden_parte, fultentrada_parte, fultsalida_parte, fulttraslado_parte, fultinvfisico_parte, vultimo_parte, vpromedio_parte, qreal_parte, qcomprometida_parte, qtransito_parte, qreal2_parte, activa_parte, terminal, username, ts) values ( 'R40000238', '0015A2DE04BD', 'CABLEMODEM MTA 1 LINEA ARRIS', 'MTA ARRIS 1 LINEA', 6, 1, 1, 'R40000238', 0, 9999, 2, 2, 1, 1, 0, 0, 0, 0, 0, 0, null, null, null, null, 0, 0, 0, 0, 0, 0, 1, '', '', now())
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select lastval()::int4 as NewID
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select id_almacen, id_localizacion from def_existloc where id_parte = 58408 AND qreal_existloc > 0 AND qreal2_existloc > 0
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, d.adsrc from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 48262) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select campo_almacen from def_almacen where id_almacen = 62
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select n.nspname, c.relname, a.attname, a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull, c.relhasrules, c.relkind, c.oid, d.adsrc from (((pg_catalog.pg_class c inner join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid = 48127) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname, attnum
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: select campo_almacen from def_almacen where id_almacen = 999
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 0 LOG: statement: update def_dtransac set id_unidad = 2 where id_transac = 89162 AND id_dtransac = 1
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: insert into def_movimiento(fecha_movimiento, id_transac, id_dtransac, id_traninve, id_parte, id_almacen, id_localizacion, id_tipodocumento, documento_movimiento, itemdocu_movimiento, id_tercero, iduser, id_unidad, cantidad_movimiento, vultimo_movimiento, ts) values ( '2009-10-26T09:02:44' , 89162, 1, 1, 58408, 62, 1, 3, 0, 0, 99999999, 30, 2, 1, 0, now())
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: select lastval()::int4 as NewID
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:44 COT 192.168.170.82 8058520 LOG: statement: select upd_bancos(1062706, 0, 1)
2009-10-26 09:02:45 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:45 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:45 COT 192.168.170.82 8058520 LOG: statement: select campo_almacen from def_almacen where id_almacen = 62
2009-10-26 09:02:45 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:45 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
.
.
.
2009-10-26 09:02:48 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:48 COT 192.168.170.82 8058520 LOG: statement: update def_transac set id_estado = 3, fecha_transac = '2009-10-26T09:02:44' where id_transac = 89162
2009-10-26 09:02:48 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:48 COT 192.168.170.82 8058520 LOG: statement: SAVEPOINT _EXEC_SVP_026E8CC8
2009-10-26 09:02:48 COT 192.168.170.82 8058520 LOG: statement: update def_dtransac set id_estado = 3 where id_transac = 89162
2009-10-26 09:02:49 COT 192.168.170.82 8058520 LOG: statement: RELEASE _EXEC_SVP_026E8CC8
2009-10-26 09:02:49 COT 192.168.170.82 8058520 LOG: statement: COMMIT
***************************************************************************************************************************

El número que aparece posterior a la IP es el transaction Id. Como pueden observar las primeras sentencias se ejecutan aparentemente fuera de una transacción aunque ya se había ejecutado el "BEGIN". Incluso existe un SAVEPOINT que se ejecuta crea fuera de la transacción y se hace release dentro de la transacción.

Aunque no copio todo el log para esta transacción porque es muy extenso, no hay ningún error del motor reportado en el log entre el BEGIN-COMMIT. Incluso el servidor no se reiniciado desde esa fecha.

El resultado en la base de datos fue que solo una parte de las sentencias que cubría la transacción quedaron en firme con las complicaciones que trae una situación de estas. Alguna idea de qué pudo haber pasado?

Aclaro que la aplicación lleva un buen tiempo en funcionamiento y no había tenido este tipo de problemas.

Otra pregunta es que no se porque se generan todos esos savepoints si la aplicación no los esta creando.

Cualquier comentario es bienvenido.

Atentamente,

RAUL DUQUE
Bogootá, Colombia