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

From: PG Bug reporting form <noreply(at)postgresql(dot)org>
To: pgsql-bugs(at)lists(dot)postgresql(dot)org
Cc: bwbecker(at)uwaterloo(dot)ca
Subject: BUG #15240: JDBC driver sometimes hangs on copy out; suspect Json
Date: 2018-06-12 16:02:44
Message-ID: 152881936477.32363.9548839791587122085@wrigleys.postgresql.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

The following bug has been logged on the website:

Bug reference: 15240
Logged by: Byron Weber Becker
Email address: bwbecker(at)uwaterloo(dot)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

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message Andrew Gierth 2018-06-13 04:48:50 Re: BUG #15237: I got "ERROR: source for a multiple-column UPDATE item must be a sub-SELECT or ROW() expression"
Previous Message PG Bug reporting form 2018-06-12 15:43:18 BUG #15239: Site is having rendering issues, on Mozilla, Edge, IE and Chrome.