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

c-nv-s commented 1 year ago

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 commented 1 year ago

@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 commented 1 year ago

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

c-nv-s commented 1 year ago

{"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 commented 1 year ago

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

x86 or arm?
Does —jsonl work?

c-nv-s commented 1 year ago

x86
--jsonl returns results as expected it seems

neilotoole commented 1 year ago

@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 commented 1 year ago

that's odd.

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

neilotoole commented 1 year ago

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

c-nv-s commented 1 year ago

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

neilotoole commented 1 year ago

Does it happen with any other table name?

c-nv-s commented 1 year ago

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 commented 1 year ago

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

neilotoole commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

sq .actor --json

works perfectly

c-nv-s commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

Yes:

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

neilotoole commented 1 year ago

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 commented 1 year ago

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

c-nv-s commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

ok give me a moment

c-nv-s commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

neilotoole commented 1 year ago

@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 commented 1 year ago

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

Now to track this down.

neilotoole commented 1 year ago

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

c-nv-s commented 1 year ago

ok let me check

c-nv-s commented 1 year ago

yes that seems to have fixed it :-)

c-nv-s commented 1 year ago

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 commented 1 year ago

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

neilotoole / sq

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