Logfile: Nov 23 14:38:32 dev postgres[23810]: [4-1] user=dev,db=dev ERROR: could not access status of transaction 13514992 Nov 23 14:38:32 dev postgres[23810]: [4-2] user=dev,db=dev DETAIL: Could not open file "pg_subtrans/00CE": Success. Nov 23 14:38:32 dev postgres[23810]: [4-3] user=dev,db=dev CONTEXT: SQL statement "SELECT 1 FROM ONLY "dev"."collection_batches" x WHERE "id" OPERATOR(pg_catalog.=) $1 FOR KEY SHARE OF x" Nov 23 14:38:32 dev postgres[23810]: [4-4] user=dev,db=dev STATEMENT: update provider_listings set deactivated_at=$1, effective_provider_id=$2, first_collection_date=$3, last_modified=$4, latest_collection_batch_id=$5, latest_collection_date=$6, latest_notfound_collection_batch_id=$7, latest_notfound_date=$8, latest_raw_listing_id=$9, latest_raw_listing_hash=$10, latitude=$11, lock_version=$12, longitude=$13, process_state=$14, provider_id=$15, source_listing_key=$16, source_provider_key=$17, status=$18 where id=$19 and lock_version=$20 Backtrace: [jay@dev local]% gdb /usr/pgsql-9.3/bin/postgres core.23810.2013-11-23.14:35:28.EST GNU gdb (GDB) CentOS (7.0.1-45.el5.centos) Copyright (C) 2009 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu". For bug reporting instructions, please see: ... Reading symbols from /usr/pgsql-9.3/bin/postgres...Reading symbols from /usr/lib/debug/usr/pgsql-9.3/bin/postgres.debug...done. done. [New Thread 23810] warning: .dynamic section for "/usr/lib64/libxslt.so.1" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libxml2.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libpam.so.0" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libssl.so.6" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libcrypto.so.6" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libgssapi_krb5.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libcrypt.so.1" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libdl.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libm.so.6" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libldap-2.3.so.0" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libc.so.6" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libkrb5.so.3" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libcom_err.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libz.so.1" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libaudit.so.0" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libk5crypto.so.3" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libkrb5support.so.0" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libkeyutils.so.1" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libresolv.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/ld-linux-x86-64.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/liblber-2.3.so.0" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/usr/lib64/libsasl2.so.2" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libselinux.so.1" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations warning: .dynamic section for "/lib64/libsepol.so.1" is not at the expected address warning: difference appears to be caused by prelink, adjusting expectations Reading symbols from /usr/lib64/libxslt.so.1...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libxslt.so.1 Reading symbols from /usr/lib64/libxml2.so.2...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libxml2.so.2 Reading symbols from /lib64/libpam.so.0...(no debugging symbols found)...done. Loaded symbols for /lib64/libpam.so.0 Reading symbols from /lib64/libssl.so.6...(no debugging symbols found)...done. Loaded symbols for /lib64/libssl.so.6 Reading symbols from /lib64/libcrypto.so.6...(no debugging symbols found)...done. Loaded symbols for /lib64/libcrypto.so.6 Reading symbols from /usr/lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libgssapi_krb5.so.2 Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done. Loaded symbols for /lib64/libcrypt.so.1 Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done. Loaded symbols for /lib64/libdl.so.2 Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done. Loaded symbols for /lib64/libm.so.6 Reading symbols from /usr/lib64/libldap-2.3.so.0...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libldap-2.3.so.0 Reading symbols from /usr/lib/libcoredumper.so.1...(no debugging symbols found)...done. Loaded symbols for /usr/lib/libcoredumper.so.1 Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done. Loaded symbols for /lib64/libc.so.6 Reading symbols from /usr/lib64/libkrb5.so.3...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libkrb5.so.3 Reading symbols from /lib64/libcom_err.so.2...(no debugging symbols found)...done. Loaded symbols for /lib64/libcom_err.so.2 Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done. Loaded symbols for /lib64/libz.so.1 Reading symbols from /lib64/libaudit.so.0...(no debugging symbols found)...done. Loaded symbols for /lib64/libaudit.so.0 Reading symbols from /usr/lib64/libk5crypto.so.3...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libk5crypto.so.3 Reading symbols from /usr/lib64/libkrb5support.so.0...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libkrb5support.so.0 Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done. Loaded symbols for /lib64/libkeyutils.so.1 Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done. Loaded symbols for /lib64/libresolv.so.2 Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done. Loaded symbols for /lib64/ld-linux-x86-64.so.2 Reading symbols from /usr/lib64/liblber-2.3.so.0...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/liblber-2.3.so.0 Reading symbols from /usr/lib64/libsasl2.so.2...(no debugging symbols found)...done. Loaded symbols for /usr/lib64/libsasl2.so.2 Reading symbols from /lib64/libselinux.so.1...(no debugging symbols found)...done. Loaded symbols for /lib64/libselinux.so.1 Reading symbols from /lib64/libsepol.so.1...(no debugging symbols found)...done. Loaded symbols for /lib64/libsepol.so.1 Reading symbols from /usr/pgsql-9.3/lib/plpgsql.so...Reading symbols from /usr/lib/debug/usr/pgsql-9.3/lib/plpgsql.so.debug...done. done. Loaded symbols for /usr/pgsql-9.3/lib/plpgsql.so warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff985fd000 Core was generated by `postgres: dev dev 192.168.2.116(38154) UPDATE '. #0 0x00002b1d15ab3825 in WriteCoreDump () from /usr/lib/libcoredumper.so.1 (gdb) bt full #0 0x00002b1d15ab3825 in WriteCoreDump () from /usr/lib/libcoredumper.so.1 No symbol table info available. #1 0x00000000004a6a0e in SlruReportIOError (ctl=, pageno=, xid=13514992) at slru.c:890 stamp_time = 1385235328 timebuf = "2013-11-23.14:35:28.EST", '\000' , "\030\341\256", '\000' , "ʹb", '\000' "\200, \001\000\000\000\000\000\000\002\000\000\000\000\000\000\000pw]\230\377\177\000" buf = "/var/log/pgsql/core.23810.2013-11-23.14:35:28.EST\000\000\000\000\000\000\000\307\031\000\000\000\000\000\000\000\341\256\000\000\000\000\000\027\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000ۄ\256\375=\000\000\000\060\000\000\000\060\000\000\000Hw]\230\377\177\000\000\200v]\230\377\177\000\000?\361\200\000\000\000\000" offset = path = "pg_subtrans/00CE\000\177G\v\000\000\000\000+\210q\000\000\000\000\000ЋG\v\000\000\000\000\b\206G\v\000\000\000\000ps]\230\377\177\000\000xs]\230\377\177\000\000\310r]\230\377\177\000\000\250\177G\v\000\000\000\000\250\177G\v\000\000\000\000chp\000\000\000\000\000\250\242G\v", '\000' "\301, \234Z", '\000' "\237, $]", '\000' , "\001\000\000\000\000\000\000\000\b\206G\v\000\000\000\000\250\177G\v\000\000\000\000\060\367^\000\000\000\000\000\177\006\000\000\377\177\000\000\b\206G\v\000\000\000\000\b\206G\v", '\000' , " \240G\v\000\000\000\000\370\241G\v\000\000\000\000\b\206G\v", '\000' ... __func__ = "SlruReportIOError" #2 0x00000000004a79be in SimpleLruReadPage (ctl=0xaee100, pageno=6599, write_ok=, xid=13514992) at slru.c:430 slotno = 23 shared = 0x2b1d21133160 #3 0x00000000004a7ee8 in SubTransGetParent (xid=13514992) at subtrans.c:122 slotno = ptr = parent = 0 #4 0x0000000000635dc7 in XactLockTableWait (xid=13514992) at lmgr.c:501 tag = {locktag_field1 = 13514992, locktag_field2 = 0, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 4 '\004', locktag_lockmethodid = 1 '\001'} #5 0x0000000000482223 in heap_lock_updated_tuple_rec (rel=0x2b20f050a8d0, tuple=, ctid=, xid=10260613, mode=LockTupleKeyShare) at heapam.c:4847 mytup = {t_len = 152, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 136}, ip_posid = 31}, t_tableOid = 2116228, t_data = 0x2b1d3110ead8} buf = 20214 new_infomask2 = 0 new_infomask = 0 new_xmax = 0 __func__ = "heap_lock_updated_tuple_rec" #6 heap_lock_updated_tuple (rel=0x2b20f050a8d0, tuple=, ctid=, xid=10260613, mode=LockTupleKeyShare) at heapam.c:4960 No locals. #7 0x0000000000482917 in heap_lock_tuple (relation=0x2b20f050a8d0, tuple=0x7fff985d7e40, cid=1, mode=LockTupleKeyShare, nowait=0 '\000', follow_updates=1 '\001', buffer=0x7fff985d7e78, hufd=0x7fff985d7e60) at heapam.c:4237 xwait = 13514993 infomask = infomask2 = 24607 t_ctid = {ip_blkid = {bi_hi = 0, bi_lo = 136}, ip_posid = 31} result = tid = 0x7fff985d7e44 lp = page = 0x2b1d3110de80 "Y" xid = xmax = new_infomask = new_infomask2 = have_tuple_lock = 1 '\001' __func__ = "heap_lock_tuple" #8 0x00000000005888b5 in ExecLockRows (node=0xb481e10) at nodeLockRows.c:134 aerm = 0xb483720 isNull = 0 '\000' buffer = 20214 erm = 0xb481d90 tuple = {t_len = 152, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 136}, ip_posid = 14}, t_tableOid = 2116228, t_data = 0x2b1d3110f530} lockmode = LockTupleKeyShare copyTuple = datum = hufd = {ctid = {ip_blkid = {bi_hi = 0, bi_lo = 0}, ip_posid = 0}, xmax = 189291712, cmax = 0} test = slot = 0xb482c50 estate = 0xb481c00 outerPlan = 0xb482000 epq_started = 0 '\000' lc = __func__ = "ExecLockRows" #9 0x000000000057629e in ExecProcNode (node=0xb481e10) at execProcnode.c:496 result = __func__ = "ExecProcNode" #10 0x0000000000575514 in ExecutePlan (queryDesc=0xb47de90, direction=367889248, count=1) at execMain.c:1470 No locals. #11 standard_ExecutorRun (queryDesc=0xb47de90, direction=367889248, count=1) at execMain.c:306 estate = 0xb481c00 operation = CMD_SELECT dest = 0xada560 sendTuples = 1 '\001' oldcontext = 0xb412690 #12 0x0000000000595939 in _SPI_execute_plan (plan=0xb442580, paramLI=0xb476bc0, snapshot=, crosscheck_snapshot=0x0, read_only=0 '\000', fire_triggers=0 '\000', tcount=1) at spi.c:2386 stmt = canSetTag = 1 '\001' dest = plansource = 0xb440d40 stmt_list = 0xb47abe0 lc2 = 0xb47ac10 my_res = 0 my_processed = 0 my_lastoid = 0 my_tuptable = 0x0 res = 5 pushed_active_snap = 1 '\001' spierrcontext = {previous = 0x0, callback = 0x593ae0 <_SPI_error_callback>, arg = 0xb4414e0} cplan = 0xb47b758 lc1 = 0xb4425e8 __func__ = "_SPI_execute_plan" #13 0x0000000000595cb9 in SPI_execute_snapshot (plan=0xb442580, Values=0x7fff985d8100, Nulls=0x7fff985d8310 " ", snapshot=0x0, crosscheck_snapshot=0x0, read_only=0 '\000', fire_triggers=0 '\000', tcount=1) at spi.c:488 res = 0 #14 0x00000000006d59df in ri_PerformCheck (riinfo=0xb46e410, qkey=0x7fff985d8480, qplan=0xb442580, fk_rel=0x2b20f0534a80, pk_rel=0x2b20f050a8d0, old_tuple=0x0, new_tuple=0x7fff985d8c40, detectNewRows=0 '\000', expect_OK=5) at ri_triggers.c:3094 query_rel = 0x2b20f050a8d0 source_rel = test_snapshot = 0x0 crosscheck_snapshot = 0x0 spi_result = save_userid = save_sec_context = 0 vals = {46162, 0 , 1072, 266251618888, 140735749652976, 4294967295, 1041, 1024, 16, 2, 0, 0, 0, 4294967295, 5755200, 72057594227184592, 189009216, 4294967296, 309426464816, 189239288, 189009216, 8192, 192, 188818816, 266251618784, 112, 189229968, 188819088, 189221808, 140735749653472, 0, 32, 32, 189140208, 189140064, 1060691528, 7436294, 189140208, 189142992, 1, 189140064, 1060691528, 7437616, 1, 140735749653351, 4483982720, 140735749653632, 140735749653632, 8, 569278163, 0, 0, 4294967296} nulls = " \000\000\000\000\000\000\000\200%D\v\000\000\000\000\001\000\000\000\000\000\000\000\340\203]\230\377\177\000\000\001\000\000\000\000\000\000\000\260KG\v\000\000\000\000\200\204]\230\377\177\000\000+Xm\000\000\000\000" __func__ = "ri_PerformCheck" #15 0x00000000006d8093 in RI_FKey_check (trigdata=) at ri_triggers.c:440 riinfo = 0xb46e410 fk_rel = 0x2b20f0534a80 pk_rel = 0x2b20f050a8d0 new_row = 0x7fff985d8c40 new_row_buf = qkey = {constr_id = 2121555, constr_queryno = 1} qplan = 0x7fff985d7090 i = 1 __func__ = "RI_FKey_check" #16 0x000000000055e7cf in ExecCallTriggerFunc (trigdata=0x7fff985d8c10, tgindx=, finfo=, instr=0x0, per_tuple_context=0xb412470) at trigger.c:1853 save_exception_stack = 0x7fff985d8e10 save_context_stack = 0x0 local_sigjmp_buf = {{__jmpbuf = {188846416, 5006221996264276670, 140735749655568, 5, 189213632, 189213600, 5006265137314193502, 5006221996111987047}, __mask_was_saved = 0, __saved_mask = {__val = { 20, 0, 140735749654448, 188628688, 20, 47420414417128, 7440441, 47420414415952, 4294967295, 189020208, 55, 1, 140735749654576, 189020208, 6515864, 55}}}} fcinfo = {flinfo = 0xb419150, context = 0x7fff985d8c10, resultinfo = 0x0, fncollation = 0, isnull = 0 '\000', nargs = 0, arg = {188976848, 1, 188976848, 47420470660016, 0, 188174176, 188178664, 6511011, 11192686888633, 72057594037927936, 188976848, 4918810402404215296, 0, 7321171, 47420471197632, 47420471197752, 188174176, 2121575, 0, 7321335, 1125891316908032, 0, 6932496, 281483566645432, 2, 0, 187839856, 0, 2121575, 0 , 47420411880736, 47420321750120, 4564840, 187835440, 1755804591, 47420317777536, 7436787, 206158430248, 0, 2556267600, 140735749655200, 47420471197576, 20, 47420471197945, 188976848, 47420471197945, 7159479, 2, 1, 98784247904, 47420470938240, 0, 6450076, 9868, 47420470938240, 47404111214204, 1, 47404111214204, 6453922, 83, 0, 42382737276928, 8070591265441316864, 188628208, 7541123296511692975, 140735749656688, 140735749656688, 1, 140735749655600, 9084959637636735, 2116502, 140733193397900, 72057860287006104, 4222451713, 47420470938240, 0, 0, 9868, 0, 0, 6455912, 140735749655327, 192}, argnull = "\260\001C\v \017\001\000<\207\000\000\000\000\000\000@\214]\230\377\177\000\000<\207\000\000\000\000\000\000<\207\000\000\000\000\000\000<\207\000\000\000\000\000\000@\214]\230\377\177\000\000/ H", '\000' , "`W\256\000\000\000\000\000@\214]\230\377\177\000\000\300+G\v"} fcusage = {fs = 0x0, save_f_total_time = {tv_sec = 6517293, tv_usec = 11454679893689}, save_total = {tv_sec = 8583840, tv_usec = 11192686888633}, f_start = {tv_sec = 72057594037927936, tv_usec = 47416438947841}} result = oldContext = 0xb4301b0 __func__ = "ExecCallTriggerFunc" #17 0x000000000055eb92 in afterTriggerInvokeEvents (events=0xb33b040, firing_id=1, estate=0xb418360, delete_ok=1 '\001') at trigger.c:3436 evtshared = event = 0xb472bc0 all_fired_in_chunk = 1 '\001' all_fired = 1 '\001' chunk = 0xb472ba0 per_tuple_context = 0xb412470 local_estate = 0 '\000' rel = 0x2b20f0534a80 trigdesc = 0xb418580 finfo = 0xb419060 instr = 0x0 __func__ = "afterTriggerInvokeEvents" #18 0x000000000055f56e in AfterTriggerEndQuery (estate=0xb418360) at trigger.c:3805 firing_id = 367889248 events = 0xb33b040 #19 0x0000000000575430 in standard_ExecutorFinish (queryDesc=0xb41e6c0) at execMain.c:378 estate = 0xb418360 oldcontext = 0xb3f9bb8 #20 0x000000000064b6fd in ProcessQuery (plan=0xb343320, sourceText=0xb41e3a0 "update provider_listings set deactivated_at=$1, effective_provider_id=$2, first_collection_date=$3, last_modified=$4, latest_collection_batch_id=$5, latest_collection_date=$6, latest_notfound_collecti"..., params=, dest=0xada4e0, completionTag=0x7fff985d9070 "UPDATE 1") at pquery.c:225 queryDesc = 0xb41e6c0 __func__ = "ProcessQuery" #21 0x000000000064b8e7 in PortalRunMulti (portal=0xb404ef0, isTopLevel=1 '\001', dest=0xada4e0, altdest=0xada4e0, completionTag=0x7fff985d9070 "UPDATE 1") at pquery.c:1279 stmt = 0xb343320 active_snapshot_set = 1 '\001' stmtlist_item = 0xb343300 #22 0x000000000064c392 in PortalRun (portal=0xb404ef0, count=1, isTopLevel=1 '\001', dest=0xb3cc760, altdest=0xb3cc760, completionTag=0x7fff985d9070 "UPDATE 1") at pquery.c:816 save_exception_stack = 0x7fff985d8f50 save_context_stack = 0x0 local_sigjmp_buf = {{__jmpbuf = {188763888, 5006221996117550797, 188532576, 8434458, 0, 188867488, 5006265137314196334, 5006221996115208041}, __mask_was_saved = 0, __saved_mask = {__val = { 188531536, 188716056, 64, 188531536, 266248608331, 472, 266248699661, 80, 3, 140735749656640, 8434458, 188531537, 7515453, 188763888, 3, 3}}}} saveTopTransactionResourceOwner = 0xb3c1f50 saveTopTransactionContext = 0xb3c1e40 saveActivePortal = 0x0 saveResourceOwner = 0xb3c1f50 savePortalContext = 0x0 saveMemoryContext = 0xb322070 __func__ = "PortalRun" #23 0x0000000000649f99 in exec_execute_message (argc=, argv=, dbname=0xb322ad8 "dev", username=) at postgres.c:1931 __func__ = "exec_execute_message" #24 PostgresMain (argc=, argv=, dbname=0xb322ad8 "dev", username=) at postgres.c:4055 portal_name = 0xb3cc350 "" firstchar = input_message = {data = 0xb3cc350 "", len = 5, maxlen = 1024, cursor = 5} local_sigjmp_buf = {{__jmpbuf = {140735749656608, 5006221996269718542, 1, 187989776, 140735749657056, 140735749656928, 5006265137314195518, 5006221996115227276}, __mask_was_saved = 1, __saved_mask = {__val = {0, 0, 266251609184, 0, 7591289, 1, 0, 140735749656648, 266248141456, 0, 8543830, 140735749658256, 0, 187989776, 140735749657056, 140735749656928}}}} send_ready_for_query = 0 '\000' __func__ = "PostgresMain" #25 0x00000000006071b9 in ServerLoop () at postmaster.c:3999 port = rmask = {fds_bits = {8, 0 }} selres = readmask = {fds_bits = {40, 0 }} nSockets = 6 now = last_touch_time = 1385233920 __func__ = "ServerLoop" #26 0x000000000060a335 in PostmasterMain (argc=5, argv=0xb320a70) at postmaster.c:1258 opt = status = userDoption = listen_addr_saved = 1 '\001' __func__ = "PostmasterMain" #27 0x00000000005a6323 in main (argc=5, argv=) at main.c:196 No locals. (gdb)