PGCopyOutputStream close() v. endCopy()

Rob Sargent <[email protected]> Thu, 10 Jan 2019 09:27:27 -0700
Newsgroups gmane.comp.db.postgresql.jdbc
Message-ID <[email protected]>
This is a repost of original on pgsql-general.

As is often the case, I'm unsure of which of these methods to use, or if 
I'm using them correctly.

PG10.5, jooq-3.10.8, postgresql-42.1.4, linux (redhat 6.9) and logback 
to a file.

I have been using close() for a while but thought I would make use of 
either the returned long from endCopy() or perhaps getHandledRowCount().

Both work perfectly, but when I use endCopy() I always get the exception 
shown near the bottom of this log excerpt. The COPY is on its own thread 
from the same connection as the direct jooq writes also listed.  Again, 
the data is all saved but I am worried that I'm not closing properly 
even if I use close(). The data here doesn't warrant bulk copy but it's 
just a quick example to repeat.

    13:32:55.785 [pool-1-thread-1] DEBUG
    edu.utah.camplab.jx.PayloadFromMux - STAGING TABLE CREATED:
    bulk."flk_g16-forcing very long name to trigger truncation_22_8045c0"
    13:32:55.786 [pool-1-thread-1] INFO
    edu.utah.camplab.jx.PayloadFromMux -
    8045c057-99ec-490b-90c1-85875269afee: started COPY work at 1546979575786
    13:32:55.789 [pool-1-thread-1] INFO
    edu.utah.camplab.jx.PayloadFromMux -
    8045c057-99ec-490b-90c1-85875269afee: Total segment save took 22 ms
    13:32:55.790 [pool-1-thread-1] INFO
    edu.utah.camplab.jx.AbstractPayload -
    8045c057-99ec-490b-90c1-85875269afee: closing process
    8045c057-99ec-490b-90c1-85875269afee
    13:32:55.790 [8045c057-99ec-490b-90c1-85875269afee] INFO
    e.u.camplab.jx.PayloadWriterThread - bulk."flk_g16-forcing very long
    name to trigger truncation_22_8045c0": Begin bulk copy segment
    13:32:55.793 [8045c057-99ec-490b-90c1-85875269afee] INFO
    e.u.camplab.jx.PayloadWriterThread - bulked up to 89, maybe?
    13:32:55.793 [pool-1-thread-1] DEBUG org.jooq.tools.LoggerListener -
    Executing batch query    : insert into "process_input" ("id",
    "process_id", "input_type", "input_ref") values (?, ?, ?, ?)
    13:32:55.795 [8045c057-99ec-490b-90c1-85875269afee] INFO
    e.u.camplab.jx.PayloadWriterThread - bulked up to 197, maybe?
    13:32:55.797 [8045c057-99ec-490b-90c1-85875269afee] INFO
    e.u.camplab.jx.PayloadWriterThread - bulked up to 318, maybe?
    13:32:55.798 [8045c057-99ec-490b-90c1-85875269afee] INFO
    e.u.camplab.jx.PayloadWriterThread - bulked up to 393, maybe?
    13:32:55.799 [8045c057-99ec-490b-90c1-85875269afee] INFO
    e.u.camplab.jx.PayloadWriterThread - 393/393 segments delivered in 9 ms
    13:32:55.799 [8045c057-99ec-490b-90c1-85875269afee] DEBUG
    e.u.camplab.jx.PayloadWriterThread - staged in 9 ms
    13:32:55.800 [pool-1-thread-1] DEBUG org.jooq.tools.LoggerListener -
    Executing batch query    : insert into "process_output" ("id",
    "process_id", "output_type", "output_ref") values (?, ?, ?, ?)
    13:32:55.805 [8045c057-99ec-490b-90c1-85875269afee] ERROR
    e.u.camplab.jx.PayloadWriterThread - bulk."flk_g16-forcing very long
    name to trigger truncation_22_8045c0": i/o trouble
    java.io.IOException: Ending write to copy failed.
         at
    org.postgresql.copy.PGCopyOutputStream.close(PGCopyOutputStream.java:107)
    ~[postgresql-42.1.4.jar:42.1.4]
         at
    edu.utah.camplab.jx.PayloadWriterThread.run(PayloadWriterThread.java:75)
    ~[transport/:na]
    Caused by: org.postgresql.util.PSQLException: Tried to write to an
    inactive copy operation
         at
    org.postgresql.core.v3.QueryExecutorImpl.writeToCopy(QueryExecutorImpl.java:978)
    ~[postgresql-42.1.4.jar:42.1.4]
         at
    org.postgresql.core.v3.CopyInImpl.writeToCopy(CopyInImpl.java:35)
    ~[postgresql-42.1.4.jar:42.1.4]
         at
    org.postgresql.copy.PGCopyOutputStream.endCopy(PGCopyOutputStream.java:166)
    ~[postgresql-42.1.4.jar:42.1.4]
         at
    org.postgresql.copy.PGCopyOutputStream.close(PGCopyOutputStream.java:105)
    ~[postgresql-42.1.4.jar:42.1.4]
         ... 1 common frames omitted
    13:32:55.810 [pool-1-thread-1] DEBUG org.jooq.tools.LoggerListener -
    Executing batch query    : insert into "process_arg" ("id",
    "process_id", "argname", "argvalue_int", "argvalue_float",
    "argvalue_text") values (?, ?, ?, ?, ?, ?)

The class doing the bulk work, PayloadWriterThread extends Thread, the 
thread name is set from the caller, itself in an executor, with the 
critical parts as follows:

         @Override
         public void run() {
             try (PGCopyOutputStream writer = new
    PGCopyOutputStream(copyIn)) {
                 long startAt = System.currentTimeMillis();
                 deliverSegments(writer);
                 long postDeliver = System.currentTimeMillis();
                 logger.debug("staged in {} ms", postDeliver - startAt);
             }
             catch (SQLException sqle) {
                 sqle.printStackTrace();
                 logger.error("{}: sql trouble", tableName, sqle);
                 throw new RuntimeException("Bulk copy failed on sql",
    sqle);
             }
             catch (IOException ioe) {
                 ioe.printStackTrace();
                 logger.error("{}: i/o trouble", tableName, ioe);
                 throw new RuntimeException("Bulk copy failed on i/o", ioe);
             }
         }
         private void deliverSegments(PGCopyOutputStream writer) throws
    IOException, SQLException {
             logger.info("{}: Begin bulk copy segment", tableName);

             long counter = 0;
             long copied = 0;
             //These had better end up the same number
             long st = System.currentTimeMillis();
             for (Map.Entry<String, List<Segment>> seglistME :
    segmentListMap.entrySet()) {
                 String pbsCSV = seglistME.getKey();
                 UUID currentPbsId = probandsetIdMap.get(pbsCSV);
                 if (currentPbsId == null) {
                     throw new RuntimeException("Could not find pbsId by
    " + pbsCSV);
                 }
                 counter += seglistME.getValue().size();
                 for (Segment segment : seglistME.getValue()) {
                     String segmentCSV = makeCSV(segment, currentPbsId);
                     writer.write(segmentCSV.getBytes());
                 }
                 logger.info("bulked up to {}, maybe?", counter);
             }
             copied = writer.endCopy();
             logger.info("{}/{} segments delivered in {} ms", copied,
    counter, System.currentTimeMillis() - st);
         }

Also, the stack trace always references the line of the closing brace of 
the try-with-resources in the run() method and not on the call to 
endCopy. Because it's a caught exception? Or it's closing a closed 
writer? Or injection from somewhere?