Thread: BUG #15240: JDBC driver sometimes hangs on copy out; suspect Json

On Tue, Jun 12, 2018 at 6:02 PM, PG Bug reporting form <noreply@postgresql.org> wrote:

The following bug has been logged on the website:

Bug reference:      15240
Logged by:          Byron Weber Becker
Email address:      bwbecker@uwaterloo.ca
PostgreSQL version: 10.3
Operating system:   Mac OS 10.13.5
Description:       

I use the following Scala code to copy the results of a query to a stream
for further processing.

            Class.forName(config.get[String]("db.default.driver"))

            val con = DriverManager.getConnection(
              config.get[String]("db.default.url"),
              config.get[String]("db.default.user"),
              config.get[String]("db.default.password")
            ).asInstanceOf[PGConnection]

            val cm: CopyManager = con.getCopyAPI
            logger.debug("executeCSV.30")

            val qryText = s"""COPY ($queryString) TO STDOUT (FORMAT CSV,
HEADER)"""
            cm.copyOut(qryText, stream)
            logger.debug("executeCSV.40")

This code has worked well hundreds of times but recently began failing for
one particular query.  The query is new and the only difference between it
and others that I can see is that it uses JSON -->> notation.  From both the
debugging output and tracing in a debugger the program enters
cm.copyOut(qryText, stream) but does not exit.

Tracing with the debugger into copyOut:

  public long copyOut(final String sql, OutputStream to) throws
SQLException, IOException {
    byte[] buf;
    CopyOut cp = copyOut(sql);
    try {
      while ((buf = cp.readFromCopy()) != null) {
        to.write(buf);
      }
      return cp.getHandledRowCount();
    } catch (IOException ioEX) {
   ....

the program executes the while loop a number of times but will not stop at a
breakpoint set on the return statement.  I've not been able to get it to
fail on a small enough sample that makes stepping through to see the ending
behaviour practical. The call to copyOut is enclosed in a try-catch block
but nothing is caught.

I'm using version 42.2.2 of the database driver.

The query in question is

SELECT
      submitter_userid               AS userid
    , uw_id
    , office_use_data ->> 'decision' AS decision
    , data ->> 'first_choice'        AS first_choice
    , data ->> 'second_choice'       AS second_choice
    , course_grade
    , class_id
FROM _oat.form_data
    JOIN _quest.std_student AS ss ON (userid = submitter_userid)
    JOIN _quest.std_term_course USING (uw_id)

WHERE form_id = 'mathInternalXfer'

****
This is the only query I have that makes use of the json ->> notation.
****

The table definitions are:

CREATE TABLE IF NOT EXISTS form_data
(
    form_id          TEXT    NOT NULL,
    version          INTEGER NOT NULL,
    submitter_userid TEXT    NOT NULL,
    seq              INTEGER NOT NULL,
    state            TEXT    NOT NULL,
    data             JSONB   NOT NULL,
    office_use_data  JSONB,
    date_added       TIMESTAMP,
    ranking          DOUBLE PRECISION,
    CONSTRAINT form_data_pkey
    PRIMARY KEY (form_id, version, submitter_userid, seq)
);

COMMENT ON TABLE form_data IS 'Data for a specified form, as provided by the
submitter.';

CREATE TABLE IF NOT EXISTS std_student
(
    uw_id                 _quest.QUEST_UW_ID NOT NULL
        CONSTRAINT std_student_pkey
        PRIMARY KEY,
    gender_code           TEXT               NOT NULL
        CONSTRAINT std_student_gender_code_fkey
        REFERENCES uw_gender,
    birthdate             DATE,
    deathdate             DATE,
    userid                _quest.QUEST_USERID,
    email                 TEXT,
    wlu_id                TEXT,
    privacy_flag          BOOLEAN            NOT NULL,
    aboriginal_flag       BOOLEAN,
    visible_minority_code TEXT
        CONSTRAINT std_student_visible_minority_code_fkey
        REFERENCES uw_visible_minority
);

CREATE TABLE IF NOT EXISTS std_term_course
(
    uw_id                         _quest.QUEST_UW_ID           NOT NULL,
    term_id                       _quest.QUEST_TERM_ID         NOT NULL,
    class_id                      INTEGER                      NOT NULL,
    course_grade                  TEXT,
    earn_credit                   BOOLEAN                      NOT NULL,
    include_in_gpa                BOOLEAN                      NOT NULL,
    requirement_designation       TEXT,
    requirement_designation_grade TEXT,
    units_attempted_code          _quest.QUEST_COMPLETION_CODE NOT NULL,
    grade_points                  NUMERIC(9, 3)                NOT NULL,
    student_take_units            NUMERIC(5, 2)                NOT NULL,
    student_ap_units              NUMERIC(5, 2)                NOT NULL,
    grading_basis                 TEXT                         NOT NULL,
    valid_attempt                 BOOLEAN,
    grade_category                TEXT,
    grade_submission_date         DATE,
    transcript_note               TEXT,
    CONSTRAINT std_term_course_pkey
    PRIMARY KEY (uw_id, term_id, class_id),
    CONSTRAINT std_term_course_uw_id_fkey
    FOREIGN KEY (uw_id, term_id) REFERENCES std_term,
    CONSTRAINT std_term_course_term_id_fkey
    FOREIGN KEY (term_id, class_id) REFERENCES off_course
);

CREATE INDEX IF NOT EXISTS std_term_course_term_id_class_id_idx
    ON std_term_course (term_id, class_id);

The activity while the application is hung:
t08_dev=# SELECT *
FROM pg_stat_activity where pid = 8713;
 datid | datname | pid  | usesysid | usename  |    application_name    |
client_addr | client_hostname | client_port |         backend_start       
| xact_start |          query_start          |         state_change       
| wait_event_type | wait_event | state | backend_xid | backend_xmin |       
                       query                                |  backend_type

-------+---------+------+----------+----------+------------------------+-------------+-----------------+-------------+-------------------------------+------------+-------------------------------+------------------------------+-----------------+------------+-------+-------------+--------------+--------------------------------------------------------------------+----------------
 16404 | t08_dev | 8713 |       10 | bwbecker | PostgreSQL JDBC Driver |
127.0.0.1   |                 |       58184 | 2018-06-12 11:34:21.641199-04
|            | 2018-06-12 11:34:21.646087-04 | 2018-06-12 11:34:21.64978-04
| Client          | ClientRead | idle  |             |              | COPY
(SELECT\r                                                    +| client
backend
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     
submitter_userid               AS userid\r                  +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     ,
uw_id\r                                                     +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     ,
office_use_data ->> 'decision' AS decision\r                +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     , data
->> 'first_choice'        AS first_choice\r            +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     , data
->> 'second_choice'       AS second_choice\r           +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |      ,
course_grade\r                                             +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     ,
class_id\r                                                  +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              | FROM
_oat.form_data\r                                             +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     JOIN
_quest.std_student AS ss ON (userid = submitter_userid)\r+|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              |     JOIN
_quest.std_term_course USING (uw_id)\r                   +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              | \r         
                                                     +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              | WHERE
form_id = 'mathInternalXfer'\r                              +|
       |         |      |          |          |                        |   
        |                 |             |                               |   
        |                               |                              |   
            |            |       |             |              | ) TO STDOUT
(FORMAT CSV, HEADER)                                   |
(1 row)


The query output is
\i 1203_mathXfer.sql
userid,uw_id,decision,first_choice,second_choice,course_grade,class_id
meconway,104,,pmath,pmath,57,4590
meconway,104,,pmath,pmath,66,4598
meconway,104,,pmath,pmath,45,5053
meconway,104,,pmath,pmath,70,5335
meconway,104,,pmath,pmath,67,5506
meconway,104,,pmath,pmath,81,6548
meconway,104,,pmath,pmath,50,4612
meconway,104,,pmath,pmath,66,4619
meconway,104,,pmath,pmath,57,5283
meconway,104,,pmath,pmath,41,5393
meconway,104,,pmath,pmath,68,5401
meconway,104,,pmath,pmath,,6447
meconway,104,,pmath,pmath,CR,4119
meconway,104,,pmath,pmath,CR,4357
meconway,104,,pmath,pmath,51,4761
meconway,104,,pmath,pmath,50,4768
meconway,104,,pmath,pmath,52,5486
meconway,104,,pmath,pmath,60,5580
meconway,104,,pmath,pmath,60,5588
meconway,104,,pmath,pmath,,6663
meconway,104,,pmath,pmath,CR,4092
meconway,104,,pmath,pmath,CR,4180
meconway,104,,pmath,pmath,68,3417
meconway,104,,pmath,pmath,50,5385
meconway,104,,pmath,pmath,69,5627
meconway,104,,pmath,pmath,44,5746
meconway,104,,pmath,pmath,50,5998
meconway,104,,pmath,pmath,CR,6941
meconway,104,,pmath,pmath,CR,7152
meconway,104,,pmath,pmath,62,2124
meconway,104,,pmath,pmath,62,3528
meconway,104,,pmath,pmath,56,3731
meconway,104,,pmath,pmath,77,4459
meconway,104,,pmath,pmath,50,4525
meconway,104,,pmath,pmath,WD,5708
meconway,104,,pmath,pmath,66,6205
meconway,104,,pmath,pmath,53,6242
meconway,104,,pmath,pmath,85,7335
meconway,104,,pmath,pmath,66,7703
meconway,104,,pmath,pmath,35,5792
meconway,104,,pmath,pmath,30,5830
meconway,104,,pmath,pmath,WD,6189
tmjvasig,20000001,,amath,pmath,72,2343
tmjvasig,20000001,,amath,pmath,87,2425
tmjvasig,20000001,,amath,pmath,77,2553
tmjvasig,20000001,,amath,pmath,,2559
tmjvasig,20000001,,amath,pmath,80,3137
tmjvasig,20000001,,amath,pmath,71,3161
tmjvasig,20000001,,amath,pmath,63,4010
tmjvasig,20000001,,amath,pmath,NCR,2811
tmjvasig,20000001,,amath,pmath,CR,4397
tmjvasig,20000001,,amath,pmath,88,1442
tmjvasig,20000001,,amath,pmath,94,2197
tmjvasig,20000001,,amath,pmath,84,2226
tmjvasig,20000001,,amath,pmath,80,2234
tmjvasig,20000001,,amath,pmath,62,2694
tmjvasig,20000001,,amath,pmath,CR,4484
tmjvasig,20000001,,amath,pmath,92,1454
tmjvasig,20000001,,amath,pmath,83,1757
tmjvasig,20000001,,amath,pmath,82,3336
tmjvasig,20000001,,amath,pmath,92,3366
tmjvasig,20000001,,amath,pmath,92,3375
tmjvasig,20000001,,amath,pmath,84,5123
tmjvasig,20000001,,amath,pmath,CR,2735
tmjvasig,20000001,,amath,pmath,67,2920
tmjvasig,20000001,,amath,pmath,83,1451
tmjvasig,20000001,,amath,pmath,90,3431
tmjvasig,20000001,,amath,pmath,92,3435
tmjvasig,20000001,,amath,pmath,67,3545
tmjvasig,20000001,,amath,pmath,90,3665
tmjvasig,20000001,,amath,pmath,83,5204
tmjvasig,20000001,,amath,pmath,74,1801
tmjvasig,20000001,,amath,pmath,80,2566
tmjvasig,20000001,,amath,pmath,69,2589
tmjvasig,20000001,,amath,pmath,74,2594
tmjvasig,20000001,,amath,pmath,82,2744
tmjvasig,20000001,,amath,pmath,CR,5062
tmjvasig,20000001,,amath,pmath,74,6858
tmjvasig,20000001,,amath,pmath,88,2138
tmjvasig,20000001,,amath,pmath,80,2444
tmjvasig,20000001,,amath,pmath,86,2854
tmjvasig,20000001,,amath,pmath,80,4301
tmjvasig,20000001,,amath,pmath,79,7480
tmjvasig,20000001,,amath,pmath,96,7874
tmjvasig,20000001,,amath,pmath,CR,3794
tmjvasig,20000001,,amath,pmath,76,2514
tmjvasig,20000001,,amath,pmath,79,2515
tmjvasig,20000001,,amath,pmath,86,3216
tmjvasig,20000001,,amath,pmath,85,3496
tmjvasig,20000001,,amath,pmath,92,4898
tmjvasig,20000001,,amath,pmath,87,7385
t08_dev=#

I've tried reducing the number of rows of data output by adding "WHERE
class_id between 1 and 4500".  That continues to hang.    But "between 1 and
2501" and "between 2500 and 4500" both return the expected results without
hanging.

I'd very much appreciate pointers next steps.

Thanks,
Byron