Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

hub: TypeError: opts.cb is not a function #5269

Closed
haraldschilly opened this issue Apr 11, 2021 · 4 comments
Closed

hub: TypeError: opts.cb is not a function #5269

haraldschilly opened this issue Apr 11, 2021 · 4 comments
Labels
A-hub stacktrace

Comments

@haraldschilly
Copy link
Contributor

haraldschilly commented Apr 11, 2021 •
edited
Loading

I found this in a private cocalc deployment's hub. I thin kthis is a follow up of a problem with connecting to the database. In any case, this exception shouldn't happen. I'll study the logs in more detail.

2021-04-11T11:59:10.368Z - debug: BUG UNHANDLED REJECTION *********************************************************
2021-04-11T11:59:10.368Z - debug: Unhandled Rejection at: Promise {
  <rejected> TypeError: opts.cb is not a function
      at cb (/cocalc/src/smc-hub/postgres-base.js:695:27)
      at Object.cb (/cocalc/src/smc-hub/postgres-base.js:301:15)
      at /cocalc/src/smc-util/misc.ts:1444:76
      at /cocalc/src/smc-hub/postgres-base.js:575:45
      at /cocalc/src/smc-hub/node_modules/async/lib/async.js:726:13
      at /cocalc/src/smc-hub/node_modules/async/lib/async.js:52:16
      at /cocalc/src/smc-hub/node_modules/async/lib/async.js:264:21
      at /cocalc/src/smc-hub/node_modules/async/lib/async.js:44:16
      at /cocalc/src/smc-hub/node_modules/async/lib/async.js:723:17
      at /cocalc/src/smc-hub/node_modules/async/lib/async.js:167:37
      at /cocalc/src/smc-hub/postgres-base.js:487:20
  
} reason: message=opts.cb is not a function, stack=TypeError: opts.cb is not a function
    at cb (/cocalc/src/smc-hub/postgres-base.js:695:27)
    at Object.cb (/cocalc/src/smc-hub/postgres-base.js:301:15)
    at /cocalc/src/smc-util/misc.ts:1444:76
    at /cocalc/src/smc-hub/postgres-base.js:575:45
    at /cocalc/src/smc-hub/node_modules/async/lib/async.js:726:13
    at /cocalc/src/smc-hub/node_modules/async/lib/async.js:52:16
    at /cocalc/src/smc-hub/node_modules/async/lib/async.js:264:21
    at /cocalc/src/smc-hub/node_modules/async/lib/async.js:44:16
    at /cocalc/src/smc-hub/node_modules/async/lib/async.js:723:17
    at /cocalc/src/smc-hub/node_modules/async/lib/async.js:167:37
    at /cocalc/src/smc-hub/postgres-base.js:487:20

2021-04-11T11:59:10.368Z - debug: BUG UNHANDLED REJECTION *********************************************************
2021-04-11T11:59:10.369Z - debug: BUG UNHANDLED REJECTION *********************************************************
2021-04-11T11:59:10.369Z - debug: Unhandled Rejection at: Promise { <rejected> 'database is down (please try later)' } reason: database is down (please try later)

the stacktrace in smc-hub/postgres-base.coffee is in connect(...) → retry_until_success

for cb in v
    cb?(err)

so, which callback? postgres-base at the top is return opts.cb("database is down (please try later)"); in _query(...)
@haraldschilly
Copy link
Contributor Author

Earlier in the log, at some point many "error_listener fired" show up. So, somehow this must be related to the DB connection. I don't see anything suspicious in the log, though. Strange. Restarting the pod worked, so at least it should mark itself as being unhealthy...

2021-04-11T10:50:59.513Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT value, expire FROM remember_me',id='158617'): "query='SELECT value, expire FROM remember_me WHERE hash = $1::CHAR(127) (concurrent=39)'"
2021-04-11T10:50:59.522Z - ESC[34mdebugESC[39m: PostgreSQL.test_query: "starting"
2021-04-11T10:50:59.522Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT NOW()',id='948774'): "query='SELECT NOW() (concurrent=40)'"
2021-04-11T10:50:59.536Z - ESC[34mdebugESC[39m: Client(vDwyRxXKQwBHXPDKwKj_a).handle_json_message_from_client: hub <-- client: {"metrics":"[object]","event":"metrics"}
2021-04-11T10:50:59.536Z - ESC[34mdebugESC[39m: Client(vDwyRxXKQwBHXPDKwKj_a).mesg_metrics:
2021-04-11T10:50:59.739Z - ESC[34mdebugESC[39m: Client(rDd34kuO-3rDO4I8MxZ78).push_to_client: [0 mesg_time_ms]  [859 mesg_avg_ms] -- mesg.id=a5e28d48-095f-4325-b896-ba4e141af802
2021-04-11T10:50:59.797Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT settings FROM projects',id='a9e6ce'): "query='SELECT settings FROM projects WHERE project_id = $1::UUID (concurrent=41)'"
2021-04-11T10:51:00.085Z - ESC[34mdebugESC[39m: register_hub
2021-04-11T10:51:00.085Z - ESC[34mdebugESC[39m: register_hub -- doing db query
2021-04-11T10:51:00.085Z - ESC[34mdebugESC[39m: PostgreSQL._query('INSERT INTO hub_servers',id='6e6f98'): "query='INSERT INTO hub_servers (\"host\",\"port\",\"clients\",\"expire\") VALUES  ($1::TEXT,$2::INTEGER,$3::INTEGER,$4::TIM…D.\"host\" , \"port\"=EXCLUDED.\"port\" , \"clients\
"=EXCLUDED.\"clients\" , \"expire\"=EXCLUDED.\"expire\" (concurrent=42)'"
2021-04-11T10:51:01.369Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=d70726): "{\"projects\":{\"project_id\":\"f33d004f-09c1-45e7-8689-aba7fa1d7483\",\"status\":{\"time\":1618138261353,\"memory\":{\"rss…\"disk_MB\":58155,\"cpu\":{\"usage\":31.753009333},\"start_ts\":16181328605
10,\"processes\":{\"count\":4},\"oom_kills\":0}}}"
2021-04-11T10:51:01.369Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=d70726): "do a set query"
2021-04-11T10:51:01.369Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=d70726): "user_set_query"
2021-04-11T10:51:01.369Z - ESC[34mdebugESC[39m: PostgreSQL.user_set_query(project_id='f33d004f-09c1-45e7-8689-aba7fa1d7483', table='projects'): "{\"project_id\":\"f33d004f-09c1-45e7-8689-aba7fa1d7483\",\"status\":{\"time\":1618138261353,\"memory\":{\"rss\":98736,\"cac…,\"disk_MB\":5
8155,\"cpu\":{\"usage\":31.753009333},\"start_ts\":1618132860510,\"processes\":{\"count\":4},\"oom_kills\":0}}"
2021-04-11T10:51:01.372Z - ESC[34mdebugESC[39m: PostgreSQL.user_set_query(project_id='f33d004f-09c1-45e7-8689-aba7fa1d7483', table='projects'): "options=[]"
2021-04-11T10:51:01.373Z - ESC[34mdebugESC[39m: PostgreSQL.user_set_query(project_id='f33d004f-09c1-45e7-8689-aba7fa1d7483', table='projects'): "options = {}"
2021-04-11T10:51:01.373Z - ESC[34mdebugESC[39m: PostgreSQL.user_set_query(project_id='f33d004f-09c1-45e7-8689-aba7fa1d7483', table='projects'): "_user_set_query_main_query"
2021-04-11T10:51:01.373Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT COUNT(*) FROM projects',id='5a1ee4'): "query='SELECT COUNT(*) FROM projects WHERE project_id=$1::UUID (concurrent=43)'"
2021-04-11T10:51:01.900Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT settings FROM projects',id='99dd94'): "query='SELECT settings FROM projects WHERE project_id = $1::UUID (concurrent=44)'"
2021-04-11T10:51:02.030Z - ESC[34mdebugESC[39m: PostgreSQL._do_connect: "error -- timeout"
2021-04-11T10:51:02.031Z - ESC[34mdebugESC[39m: PostgreSQL.connect: "will try to connect"
2021-04-11T10:51:02.031Z - ESC[34mdebugESC[39m: PostgreSQL.connect: "until successful"
2021-04-11T10:51:02.031Z - ESC[34mdebugESC[39m: PostgreSQL.connect: "retry_until_success() -- try 1"
2021-04-11T10:51:02.031Z - ESC[34mdebugESC[39m: PostgreSQL._do_connect: "connect to db"
2021-04-11T10:51:02.032Z - ESC[34mdebugESC[39m: PostgreSQL._do_connect: "first make sure db exists"
2021-04-11T10:51:02.032Z - ESC[34mdebugESC[39m: PostgreSQL._ensure_database_exists: "ensure database 'smc' exists"
2021-04-11T10:51:02.032Z - ESC[34mdebugESC[39m: PostgreSQL._ensure_database_exists: "psql --user postgres --host db --port 5432 --list --tuples-only"
2021-04-11T10:51:02.032Z - ESC[34mdebugESC[39m: execute_code: "psql --user postgres --host db --port 5432 --list --tuples-only"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE projects',id='6e18fa'): "error_listener fired"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE projects',id='6e18fa'): "done (concurrent=-1), (query_time_ms=60004) -- error: error"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=7fb9e7): "returned postgresql error"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE projects',id='6e18fa'): "QUERY_ALERT_THRESH: query_time_ms=60004\nQUERY_ALERT_THRESH: query='UPDATE projects SET status=JSONB_SET(JSONB_SET(JSONB_SE…0\",\"1676\",\"1024000\",\"58155\",\"22.308342569\",\"161813
5371499\",\"4\",\"0\",\"151e8216-49fd-486e-8d84-d340c47ce1d2\"]'"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT COUNT(*) FROM syncstrings',id='49d876'): "error_listener fired"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT COUNT(*) FROM syncstrings',id='49d876'): "done (concurrent=-2), (query_time_ms=60003) -- error: error"
2021-04-11T10:51:02.034Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=7ca805): "returned postgresql error"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._query('SELECT COUNT(*) FROM syncstrings',id='49d876'): "QUERY_ALERT_THRESH: query_time_ms=60003\nQUERY_ALERT_THRESH: query='SELECT COUNT(*) FROM syncstrings WHERE string_id=$1::CHAR(40)'\nQUERY_ALERT_THRESH: params='[\"3ddd
c358a010f210b9511acb372145837cc8cf8c\"]'"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE projects',id='bd5c7b'): "error_listener fired"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE projects',id='bd5c7b'): "done (concurrent=-3), (query_time_ms=60002) -- error: error"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=f19cb0): "returned postgresql error"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE projects',id='bd5c7b'): "QUERY_ALERT_THRESH: query_time_ms=60002\nQUERY_ALERT_THRESH: query='UPDATE projects SET status=JSONB_SET(JSONB_SET(JSONB_SE…0376\",\"1652\",\"1024000\",\"58155\",\"25.662657\",\"161813
3696758\",\"3\",\"0\",\"2adcb0f8-6a17-4c07-8a04-03e3759752d6\"]'"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE file_use',id='40854f'): "error_listener fired"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._query('UPDATE file_use',id='40854f'): "done (concurrent=-4), (query_time_ms=60000) -- error: error"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL._user_query(id=177246): "returned postgresql error"
2021-04-11T10:51:02.035Z - ESC[34mdebugESC[39m: PostgreSQL.user_query_queue: "_do_one_query(client_id='rDd34kuO-3rDO4I8MxZ78', query_id='5bfa75') -- done; time=62401ms"

@haraldschilly
Copy link
Contributor Author

haraldschilly commented Apr 11, 2021 •
edited
Loading

another follow up exception:

that's part of monitoring, and yes, that's something I should know how to fix. @query_time_histogram.observe ...

2021-04-11T10:51:02.262Z - ESC[34mdebugESC[39m: BUG ****************************************************************************
2021-04-11T10:51:02.262Z - ESC[34mdebugESC[39m: Uncaught exception: TypeError: Cannot read property 'observe' of undefined
2021-04-11T10:51:02.262Z - ESC[34mdebugESC[39m: TypeError: Cannot read property 'observe' of undefined
    at module.exports.query_cb (/cocalc/src/smc-hub/postgres-base.js:1152:37)
    at after (/cocalc/src/smc-hub/node_modules/pg/lib/native/query.js:128:12)
    at module.exports.Client._onReadyForQuery (/cocalc/src/smc-hub/node_modules/pg-native/index.js:323:5)
    at module.exports.emit (events.js:315:20)
    at module.exports.Client._read (/cocalc/src/smc-hub/node_modules/pg-native/index.js:230:8)
    at PQ.emit (events.js:315:20)

2021-04-11T10:51:02.262Z - ESC[34mdebugESC[39m: BUG ****************************************************************************

@williamstein
Copy link
Contributor

I pushed a possibly helpful fix. I don't know if this fixes the problem or not, but the "requires" allowed for opts.cb to be undefined in some cases, but actually assumed it was defined in the code.

@haraldschilly
Copy link
Contributor Author

I'm reopening this, because ecbf1d7 doesn't address the 2nd exception, which happens earlier.

@haraldschilly haraldschilly reopened this Apr 12, 2021
@haraldschilly haraldschilly mentioned this issue Apr 12, 2021
Merged
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-hub stacktrace
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@haraldschilly @williamstein