no results returned with postgres when using json flag v0.38 ???

[c-nv-s]

Describe the bug
version 0.38.0 using json flag hangs/crashes the tool???
OS: debian
release: 0.38.0 release binary
data source: postgres 15

works: sq '.users' - results displayed
fails: sq '.users' --json - no results just hangs indefinitely
fails: sq -j '.users' - no results just hangs indefinitely

[neilotoole]

@c-nv-s Thanks for the quick report.

• What platform are you on? (e.g. MacOS Ventura x86)
• What happens when you do sq '.users' --yaml?
• Is this only for Postgres?
• Can you enable logging (see https://sq.io/docs/config/#logging ), and attach the log file (typically found in ~/.config/sq/sq.log. Note that the log file hides/redacts passwords from connection strings. But if you'd prefer not to post the log publicly, could you email it to me: neilotoole@apache.org.

[c-nv-s]

• os is Debian Buster
• --yaml flag returns results fine it seems
• only tested with local dev postgres instance

[c-nv-s]

{"time":"2023-06-18T18:33:29.486338295Z","level":"DEBUG","source":"yamlstore/yamlstore.go:66","msg":"Loading config from file","pid":18032,"path":"/home/admin/.config/sq/sq.yml"}
{"time":"2023-06-18T18:33:29.486666662Z","level":"DEBUG","source":"yamlstore/upgrade.go:164","msg":"Found config version in file","pid":18032,"version":"v0.38.0","path":"/home/admin/.config/sq/sq.yml"}
{"time":"2023-06-18T18:33:29.486904191Z","level":"DEBUG","source":"cli/logging.go:211","msg":"Using log 'enabled' specified via config","pid":18032,"key":"log","value":true}
{"time":"2023-06-18T18:33:29.486915741Z","level":"DEBUG","source":"cli/logging.go:295","msg":"Log file not explicitly set in config; using default","pid":18032,"key":"log.file","path":"/home/admin/.cache/sq/sq.log"}
{"time":"2023-06-18T18:33:29.486923443Z","level":"DEBUG","source":"cli/logging.go:261","msg":"Using log level specified via config","pid":18032,"key":"log.level","value":"DEBUG"}
{"time":"2023-06-18T18:33:29.486929Z","level":"DEBUG","source":"cli/logging.go:77","msg":"Logging: enabled","pid":18032,"path":"/home/admin/.cache/sq/sq.log"}
{"time":"2023-06-18T18:33:29.487199194Z","level":"DEBUG","source":"cli/cli.go:81","msg":"EXECUTE","pid":18032,"args":".authorizer_users ) -j"}
{"time":"2023-06-18T18:33:29.487210861Z","level":"DEBUG","source":"cli/cli.go:82","msg":"Build info","pid":18032,"build":{"version":"v0.38.0","commit":"955e56e","timestamp":"2023-06-18T13:17:59Z"}}
{"time":"2023-06-18T18:33:29.48722527Z","level":"DEBUG","source":"cli/cli.go:83","msg":"Config","pid":18032,"config.version":"v0.38.0","path":"/home/admin/.config/sq"}
{"time":"2023-06-18T18:33:29.487789407Z","level":"DEBUG","source":"cli/output.go:375","msg":"Constructed output.Printing","pid":18032,"value":{"verbose":false,"header":true,"monochrome":false,"compact":false,"redact":true,"flush-threshold":1000,"indent":"  ","format.datetime.number":true,"format.date.number":true,"format.time.number":true}}
{"time":"2023-06-18T18:33:29.4905916Z","level":"DEBUG","source":"driver/driver.go:413","msg":"Open source","pid":18032,"src":{"handle":"@postgres","driver":"postgres","loc":"postgres://xxxxx:xxxxx@127.0.0.1:5432/postgres","opts":{"log":true}}}
{"time":"2023-06-18T18:33:29.490690112Z","level":"DEBUG","source":"postgres/postgres.go:143","msg":"Open source","pid":18032,"src":{"handle":"@postgres","driver":"postgres","loc":"postgres://xxxxx:xxxxx@127.0.0.1:5432/postgres","opts":{"log":true}}}
{"time":"2023-06-18T18:33:29.49100245Z","level":"DEBUG","source":"driver/driver.go:37","msg":"Setting config on DB conn","pid":18032,"config":{"conn.max-lifetime":"10m0s","conn.max-open":0,"conn.max-idle":2,"conn.max-idle-time":"2s"}}
{"time":"2023-06-18T18:33:29.495644126Z","level":"DEBUG","source":"libsq/engine.go:85","msg":"Execute SQL query","pid":18032,"src":{"handle":"@postgres","driver":"postgres","loc":"postgres://xxxxx:xxxxx@127.0.0.1:5432/postgres","opts":{"log":true}},"sql":"SELECT * FROM \"authorizer_users\""}
{"time":"2023-06-18T18:34:05.114777792Z","level":"DEBUG","source":"yamlstore/yamlstore.go:66","msg":"Loading config from file","pid":18050,"path":"/home/admin/.config/sq/sq.yml"}
{"time":"2023-06-18T18:34:05.115255371Z","level":"DEBUG","source":"yamlstore/upgrade.go:164","msg":"Found config version in file","pid":18050,"version":"v0.38.0","path":"/home/admin/.config/sq/sq.yml"}
{"time":"2023-06-18T18:34:05.115617905Z","level":"DEBUG","source":"cli/logging.go:211","msg":"Using log 'enabled' specified via config","pid":18050,"key":"log","value":true}
{"time":"2023-06-18T18:34:05.115628093Z","level":"DEBUG","source":"cli/logging.go:295","msg":"Log file not explicitly set in config; using default","pid":18050,"key":"log.file","path":"/home/admin/.cache/sq/sq.log"}
{"time":"2023-06-18T18:34:05.115639224Z","level":"DEBUG","source":"cli/logging.go:261","msg":"Using log level specified via config","pid":18050,"key":"log.level","value":"DEBUG"}
{"time":"2023-06-18T18:34:05.115650033Z","level":"DEBUG","source":"cli/logging.go:77","msg":"Logging: enabled","pid":18050,"path":"/home/admin/.cache/sq/sq.log"}
{"time":"2023-06-18T18:34:05.115992278Z","level":"DEBUG","source":"cli/cli.go:81","msg":"EXECUTE","pid":18050,"args":"config get log.file -v"}
{"time":"2023-06-18T18:34:05.116010808Z","level":"DEBUG","source":"cli/cli.go:82","msg":"Build info","pid":18050,"build":{"version":"v0.38.0","commit":"955e56e","timestamp":"2023-06-18T13:17:59Z"}}
{"time":"2023-06-18T18:34:05.116031961Z","level":"DEBUG","source":"cli/cli.go:83","msg":"Config","pid":18050,"config.version":"v0.38.0","path":"/home/admin/.config/sq"}
{"time":"2023-06-18T18:34:05.116768085Z","level":"DEBUG","source":"cli/output.go:375","msg":"Constructed output.Printing","pid":18050,"value":{"verbose":true,"header":true,"monochrome":false,"compact":false,"redact":true,"flush-threshold":1000,"indent":"  ","format.datetime.number":true,"format.date.number":true,"format.time.number":true}}
{"time":"2023-06-18T18:34:05.117347801Z","level":"DEBUG","source":"driver/driver.go:504","msg":"Closing databases(s)...","pid":18050,"count":0}
{"time":"2023-06-18T18:34:05.117406869Z","level":"DEBUG","source":"source/files.go:318","msg":"Files.Close invoked: executing clean funcs","pid":18050,"count":1}

[neilotoole]

@c-nv-s thanks, will look into it now. A few more questions:

• x86 or arm?
• Does —jsonl work?

[c-nv-s]

• x86
• --jsonl returns results as expected it seems

[neilotoole]

@c-nv-s It seems to be working for me on a debian buster container, on a fresh install.

Looking at your log file, I see this:

{"time":"2023-06-18T18:33:29.487199194Z","level":"DEBUG","source":"cli/cli.go:81","msg":"EXECUTE","pid":18032,"args":".authorizer_users ) -j"}

Note the .authorizer_users ) -j. That's an unclosed parentheses.

Can you show me the exact output of executing this:

$ sq 1 --json

For me I see (on debian buster):

$ sq 1 --json
[
  {
    "1": 1
  }
]

[c-nv-s]

that's odd.

• sq 1 --json returns correctly
• sq '.authorizer_users )' --jsonl - returns correctly
• sq '.authorizer_users' --json - still does not work ??

[neilotoole]

Weird. What’s the output of sq inspect .authorizer_users —-json

[c-nv-s]

yes that work... haha... how weird

[neilotoole]

Does it happen with any other table name?

[c-nv-s]

yes all other tables names also hang with just the --json flag.

• sq '.authorizer_envs' --json - hangs indefinitely

yet works with --jsonl

[c-nv-s]

also curious why this didn't throw an error sq '.authorizer_users )' --jsonl if it is malformed.

[neilotoole]

How bizarre. Let's try to eliminate variables. Could you do the following:

# Move your config folder to a temporary location (so you
# start with a fresh config)
$ sq config location
/root/.config/sq
$ mv /root/.config/sq /root/.config/sq_bak

# Download and add the sqlite sakila database file
$ wget https://sq.io/testdata/sakila.db
$ sq add ./sakila.db

# Test JSON output
$ sq .actor --json

[neilotoole]

also curious why this didn't throw an error sq '.authorizer_users )' --jsonl if it is malformed.

The parser tries to be forgiving, but maybe it's too forgiving... I need to figure out what's happening in that scenario. I'd like for that to return an error.

[c-nv-s]

sq .actor --json

works perfectly

[c-nv-s]

I then tried:

sq add postgres://user:password@127.0.0.1/postgres
sq src @postgres
sq '.authorizer_users' --json

hangs indefinitely....
let me try a completely different postgres db gimme a moment

[neilotoole]

To verify that we're doing the same thing:

$ docker run -d -p 5432:5432 sakiladb/postgres:12
$ sq add postgres://sakila:p_ssW0rd@localhost/sakila --handle @sakila_pg12
$ sq src @sakila_pg12
$ sq .actor --json

[neilotoole]

Also, for the problematic database, can you show the top part of the output for sq inspect, e.g.

$ sq inspect @sakila_pg12 --json
{
  "handle": "@sakila_pg12",
  "location": "postgres://sakila:xxxxx@localhost/sakila",
  "name": "sakila",
  "name_fq": "sakila.public",
  "schema": "public",
  "driver": "postgres",
  "db_driver": "postgres",
  "db_product": "PostgreSQL 12.13 on aarch64-unknown-linux-musl, compiled by gcc (Alpine 12.2.1_git20220924-r4) 12.2.1 20220924, 64-bit",
  "db_version": "12.13",

[c-nv-s]

this is for my original instance, I'll setup the sakiladb/postgres and also try

{                                                  
  "handle": "@postgres",                                                   
  "location": "postgres://xxxxx:xxxxx@localhost:5432/postgres",                                     
  "name": "postgres",                                                                                      
  "name_fq": "postgres.public",                                                                                    
  "schema": "public",                                                                                  
  "driver": "postgres",                                                                                            
  "db_driver": "postgres",                                                                             
  "db_product": "PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit",
  "db_version": "15.2 (Debian 15.2-1.pgdg110+1)",                                                                                                      
  "size": 8024879,                                                                          

[c-nv-s]

sq .actor --json with @sakila_pg12 works normally... so I suspect it might be a postgres version issue?
is there a sakila version with pg15?

[neilotoole]

Yes:

$ docker run -d -p 5432:5432 sakiladb/postgres:15

[neilotoole]

A couple more questions:

• What was the most recent version of sq you were using that worked with this database?
• Starting with a new configuration (move/rename/delete the config folder), can you try re-adding the problematic DB via sq add?

[neilotoole]

I just tested with pg15, no problems. Weirder and weirder.

[c-nv-s]

yeah also just tested with sakiladb/postgres:latest and it works fine :-(
the machine I'm using right now previously had v.0.34 before I updated via upgrading with the .deb file from the releases

[neilotoole]

This issue is very befuddling. The output writer mechanism (json vs yaml vs text) is independent of the DB query mechanism.

Can you try something else for me? Please try the query for each and every output format (csv, markdown etc). I want to see if it’s ONLY the json format.

[c-nv-s]

ok give me a moment

[c-nv-s]

it is just the --json/-j that is causing it to hang :-(
I've even installed sq fresh on the machine
--csv , --yaml, --markdown, --jsonl all work properly

[c-nv-s]

sq inspect .authorizer_users --json
{                           
  "name": "authorizer_users",
  "name_fq": "postgres.public.authorizer_users",
  "table_type": "table",   
  "table_type_db": "BASE TABLE",
  "row_count": 3,              
  "size": 65536,                  
  "columns": [             
    {                      
      "name": "key",        
      "position": 1,          
      "primary_key": false,
      "base_type": "text", 
      "column_type": "text",
      "kind": "text",       
      "nullable": true                       
    },                     
    {                      
      "name": "id",         
      "position": 2,           
      "primary_key": true,
      "base_type": "bpchar",
      "column_type": "character",
      "kind": "text",       
      "nullable": false    
    },                     
    {                      
      "name": "email",      
      "position": 3,                     
      "primary_key": false,
      "base_type": "text", 
      "column_type": "text",
      "kind": "text",         
      "nullable": true     
    },                     
    {                      
      "name": "email_verified_at",
      "position": 4,          
      "primary_key": false,
      "base_type": "int8", 
      "column_type": "bigint",
      "kind": "int",        
      "nullable": true
    },                     
 {                                                                                                                                                                                [96/1876]
      "name": "password",
      "position": 5,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "signup_methods",
      "position": 6,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "given_name",
      "position": 7,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "family_name",
      "position": 8,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "middle_name",
      "position": 9,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
 {                                                                                                                                                                                [51/1876]
      "name": "nickname",
      "position": 10,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "gender",
      "position": 11,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "birthdate",
      "position": 12,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "phone_number",
      "position": 13,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "phone_number_verified_at",
      "position": 14,
      "primary_key": false,
      "base_type": "int8",
      "column_type": "bigint",
      "kind": "int",
      "nullable": true
    },
 {                                                                                                                                                                                 [6/1876]
      "name": "picture",
      "position": 15,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "roles",
      "position": 16,
      "primary_key": false,
      "base_type": "text",
      "column_type": "text",
      "kind": "text",
      "nullable": true
    },
    {
      "name": "revoked_timestamp",
      "position": 17,
      "primary_key": false,
      "base_type": "int8",
      "column_type": "bigint",
      "kind": "int",
      "nullable": true
    },
    {
      "name": "is_multi_factor_auth_enabled",
      "position": 18,
      "primary_key": false,
      "base_type": "bool",
      "column_type": "boolean",
      "kind": "bool",
      "nullable": true
    },
    {
      "name": "updated_at",
      "position": 19,
      "primary_key": false,
      "base_type": "int8",
      "column_type": "bigint",
      "kind": "int",
      "nullable": true
    },
{
      "name": "created_at",
      "position": 20,
      "primary_key": false,
      "base_type": "int8",
      "column_type": "bigint",
      "kind": "int",
      "nullable": true
    }
  ]
}

[c-nv-s]

hashes for fake passwords redacted but should give you an idea... I'm completely baffled

sq '.authorizer_users' --csv 
key,id,email,email_verified_at,password,signup_methods,given_name,family_name,middle_name,nickname,gender,birthdate,phone_number,phone_number_verified_at,picture,roles,revoked_timestamp,is_multi_factor_auth_enabled,updated_at,created_at
83c2cb1b-0dd2-4472-8ed8-8980e19b1940,83c2cb1b-0dd2-4472-8ed8-8980e19b1940,jenifer@lopez.com,1687112629,$2a$10$9JJh8O6hP1iZOug2G7mj0.MMJ./a,basic_auth,,,,,,,,,,user,,,1687112629,1687112629
37805190-1e2e-483f-9565-3ccc409b068f,37805190-1e2e-483f-9565-3ccc409b068f,adam@sandler.com,1687112653,$2a$10$RhTtLpeMdnM/2YpbZBRbJ.AYxKGvnK,basic_auth,,,,,,,,,,user,,,1687112653,1687112653
1411d982-160d-4d45-a17b-1afd35aab8e0,1411d982-160d-4d45-a17b-1afd35aab8e0,michael@jackson.com,1687124925,$2a$10$AzZncpge/Wtpa,basic_auth,,,,,,,,,,user,,,1687124925,1687124925

sq '.authorizer_users' --markdown
| key | id | email | email_verified_at | password | signup_methods | given_name | family_name | middle_name | nickname | gender | birthdate | phone_number | phone_number_verified_at | picture | roles | revoked_timestamp | is_multi_factor_auth_enabled | updated_at | created_at |
| --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | --- |
| 83c2cb1b-0dd2-4472-8ed8-8980e19b1940 | 83c2cb1b-0dd2-4472-8ed8-8980e19b1940 | jenifer@lopez.com | 1687112629 | $2a$10$9JJh8O6hP1iZOug2a | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | user | user | user | 1687112629 | 1687112629 |
| 37805190-1e2e-483f-9565-3ccc409b068f | 37805190-1e2e-483f-9565-3ccc409b068f | adam@sandler.com | 1687112653 | $2a$10$RhTtLpeMdnM/2K | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | user | user | user | 1687112653 | 1687112653 |
| 1411d982-160d-4d45-a17b-1afd35aab8e0 | 1411d982-160d-4d45-a17b-1afd35aab8e0 | michael@jackson.com | 1687124925 | $2a$10$AzZncpg2/bVzKm8a | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | basic_auth | user | user | user | 1687124925 | 1687124925 |

sq '.authorizer_users' --json
...nothing

[c-nv-s]

I was thinking perhaps there might be an issue rendering valid json with the password field, but then if that was the case the --jsonl would not have worked either :-(
anyway this is the project that created the database https://github.com/authorizerdev/authorizer if you want to fully replicate.

[neilotoole]

Thanks, I was about to ask! I’ll see if I can replicate the issue locally.

[neilotoole]

@c-nv-s I took a look at that authorizer repo... I might be blind, but where can I find the Postgres container? In the Makefile, I see:

test-all-db:
	rm -rf server/test/test.db server/test/test.db-shm server/test/test.db-wal && rm -rf test.db test.db-shm test.db-wal
	docker run -d --name authorizer_scylla_db -p 9042:9042 scylladb/scylla
	docker run -d --name authorizer_mongodb_db -p 27017:27017 mongo:4.4.15
	docker run -d --name authorizer_arangodb -p 8529:8529 -e ARANGO_NO_AUTH=1 arangodb/arangodb:3.10.3
	docker run -d --name dynamodb-local-test  -p 8000:8000 amazon/dynamodb-local:latest
	docker run -d --name couchbase-local-test  -p 8091-8097:8091-8097 -p 11210:11210 -p 11207:11207 -p 18091-18095:18091-18095 -p 18096:18096 -p 18097:18097 couchbase:latest
	sh scripts/couchbase-test.sh

How are you creating the Postgres container?

[neilotoole]

@c-nv-s NM, figured it out. I can confirm I'm seeing the same issue.

Now to track this down.

[neilotoole]

@c-nv-s: I've pushed a new release: can you try this again with v0.38.1?

[c-nv-s]

ok let me check

[c-nv-s]

yes that seems to have fixed it :-)

[c-nv-s]

Thanks Neil I'm happy to close this.
I won't raise a new ticket for the below because it wasn't technically a bug.

also curious why this didn't throw an error sq '.authorizer_users )' --jsonl if it is malformed.

The parser tries to be forgiving, but maybe it's too forgiving... I need to figure out what's happening in that scenario. I'd like for that to return an error.

[neilotoole]

@c-nv-s Glad that resolved it. The old adage premature optimization is the root of all evil strikes again 🤦