Details
-
Bug
-
Resolution: Fixed
-
Major
-
7.6.0
-
7.6.0-1966
-
Untriaged
-
0
-
Unknown
Description
Query service does not start due to jsevaluator.
Repro steps
1. Start the cluster with the Query service
2. Try executing a query. It will fail due to being unable to connect to the query service.
Executing a query via the UI returns a “Failure contacting server” error.
The initialisation of the JS engines hangs & never returns. This causes the query service initialization to be stalled.
FYI - On my local setup I reverted this commit in eventing-ee - https://github.com/couchbase/eventing-ee/commit/e37920cf4df495444b26cddc4bfab4f08ebc8e68 and the query service starts up.
Query.log
2023-12-22T10:48:28.521+05:30 [INFO] cbq-engine starting version=7.6.0-N1QL go-version=go1.21.3 pid=84258 |
2023-12-22T10:48:28.522+05:30 [INFO] Current nofiles rlimit: 4096 (max: 4096) |
2023-12-22T10:48:28.522+05:30 [INFO] Waiting for initial settings |
2023-12-22T10:48:28.525+05:30 [INFO] New settings received: {"cleanupclientattempts":true,"cleanuplostattempts":true,"cleanupwindow":"60s","completed-limit":4000,"completed-max-plan-size":262144,"completed-threshold":1000,"loglevel":"info","max-parallelism":1,"memory-quota":0,"n1ql-feat-ctrl":76,"node-quota":0,"node-quota-val-percent":67,"num-cpus":0,"numatrs":1024,"pipeline-batch":16,"pipeline-cap":512,"prepared-limit":16384,"query.settings.curl_whitelist":{"all_access":false,"allowed_urls":[],"disallowed_urls":[]},"query.settings.tmp_space_dir":"/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp","query.settings.tmp_space_size":5120,"scan-cap":512,"timeout":0,"txtimeout":"0ms","use-cbo":true,"use-replica":"unset"} |
2023-12-22T10:48:28.525+05:30 [INFO] Initial settings received |
2023-12-22T10:48:28.525+05:30 [INFO] Soft memory limit: 28.8 GiB (90% of total) |
2023-12-22T10:48:28.525+05:30 [INFO] FFDC: Capture path: /Users/dhanyagowrish/elixir/trinity-test/install/var/lib/couchbase/logs |
2023-12-22T10:48:28.533+05:30 [INFO] FFDC: Found 120 existing dump file(s); 1657109 bytes. |
2023-12-22T10:48:28.533+05:30 [Info] GSIClient DeploymentModel is set to: default, input: default |
2023-12-22T10:48:28.533+05:30 [INFO] Temporary file path set to: /var/folders/6m/s3lxt_gx0wdcsrrw53srldr00000gp/T/, quota: 0 |
2023-12-22T10:48:28.535+05:30 [INFO] Initialization of cbauth succeeded |
2023-12-22T10:48:28.537+05:30 [Info] Receive security change notification. encryption=false |
2023-12-22T10:48:28.537+05:30 [Warn] certifcate location is missing. Cannot refresh certifcate |
2023-12-22T10:48:28.537+05:30 [INFO] New store created with url http://127.0.0.1:9000 |
2023-12-22T10:48:28.537+05:30 [INFO] n1fty: Receive security change notification |
2023-12-22T10:48:28.537+05:30 [WARN] n1fty: cannot refresh certificate, certificate location is missing |
2023-12-22T10:48:28.539+05:30 [INFO] Bucket N1QL_SYSTEM_BUCKET not found: No bucket named N1QL_SYSTEM_BUCKET |
2023-12-22T10:48:28.541+05:30 [INFO] New Value for curl allowed list <ud>map[all_access:false allowed_transformed_urls:[] allowed_urls:[] disallowed_transformed_urls:[] disallowed_urls:[]]</ud> |
2023-12-22T10:48:28.552+05:30 [Info] GSIC - Setting config map[query_tmpspace_dir:/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp query_tmpspace_limit:5120] |
2023-12-22T10:48:28.552+05:30 [INFO] GSI indexer settings have been updated map[query_tmpspace_dir:/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp query_tmpspace_limit:5120] |
2023-12-22T10:48:28.553+05:30 [INFO] n1fty indexer settings have been updated map[query_tmpspace_dir:/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp query_tmpspace_limit:5120] |
2023-12-22T10:48:28.553+05:30 [INFO] Temporary file path set to: /Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp, quota: 0 |
2023-12-22T10:48:28.553+05:30 [INFO] num-cpus updated to 0. Change will take place on restart. |
2023-12-22T10:48:28.553+05:30 [INFO] Temporary file path set to: /Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp, quota: 5368709120 (5.0 GiB) |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for atrcollection. New value is |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for auto-prepare. New value is false |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for cleanupclientattempts. New value is true |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for cleanuplostattempts. New value is true |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for cleanupwindow. New value is 1m0s |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for completed-limit. New value is 4000 |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for completed-max-plan-size. New value is 262144 |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for completed-threshold. New value is 1s |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for controls. New value is false |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for cpuprofile. New value is |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for debug. New value is false |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for duration-style. New value is legacy |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for functions-limit. New value is 16384 |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for gc-percent. New value is 0 |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for keep-alive-length. New value is 0 |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for loglevel. New value is INFO |
2023-12-22T10:48:28.553+05:30 [INFO] Query Configuration changed for max-index-api. New value is 4 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for max-parallelism. New value is 1 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for memory-quota. New value is 0 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for memprofile. New value is |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for mutexprofile. New value is false |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for n1ql-feat-ctrl. New value is 76 (0x4c), Encoded Plans (0x4) disabled, Golang UDFs (0x8) disabled, (Reserved for future use) (0x40) disabled |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for node-quota. New value is 0 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for node-quota-val-percent. New value is 67 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for num-cpus. New value is 10 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for numatrs. New value is 1024 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for pipeline-batch from 512 to 16 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for pipeline-cap. New value is 512 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for plus-servicers. New value is 160 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for prepared-limit. New value is 16384 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for pretty. New value is false |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for profile. New value is off |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for request-error-limit. New value is 0 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for request-size-cap. New value is 0 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for scan-cap. New value is 512 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for servicers. New value is 40 |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for timeout. New value is 0s |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for txtimeout. New value is 0s |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for use-cbo. New value is true |
2023-12-22T10:48:28.554+05:30 [INFO] Query Configuration changed for use-replica. New value is unset |
2023-12-22T10:48:28.556+05:30 [INFO] Changing GC percent from 0 to 200 |
2023-12-22T10:48:28.557+05:30 [INFO] Query Engine Stats {"cores":10,"cpu.sys.percent":0,"cpu.user.percent":0,"ffdc.total":0,"gc.num":19125440,"gc.pause.percent":0,"gc.pause.time":"370.001µs","healthy":true,"host.memory.free":2743779328,"host.memory.quota":0,"host.memory.total":34359738368,"host.memory.value_quota":0,"load":0,"loadfactor":33,"local.time":"2023-12-22T10:48:28.557+05:30","memory.system":24806664,"memory.total":15351632,"memory.usage":12402232,"node.allocated.values":1,"node.memory.usage":209715200,"process.memory.usage":1,"process.percore.cpupercent":0.1,"process.rss":50806784,"process.service.usage":0,"request.active.count":0,"request.completed.count":0,"request.per.sec.15min":0,"request.per.sec.1min":0,"request.per.sec.5min":0,"request.prepared.percent":0,"request.queued.count":0,"request_time.80percentile":"0s","request_time.95percentile":"0s","request_time.99percentile":"0s","request_time.mean":"0s","request_time.median":"0s","servicers.paused.count":0,"servicers.paused.total":0,"temp.hwm":0,"temp.usage":0,"total.threads":77,"uptime":"17.884792ms","version":"7.6.0-N1QL"} |
2023-12-22T10:48:28.558+05:30 [INFO] New settings received: {"cleanupclientattempts":true,"cleanuplostattempts":true,"cleanupwindow":"60s","completed-limit":4000,"completed-max-plan-size":262144,"completed-threshold":1000,"loglevel":"info","max-parallelism":1,"memory-quota":0,"n1ql-feat-ctrl":76,"node-quota":0,"node-quota-val-percent":67,"num-cpus":0,"numatrs":1024,"pipeline-batch":16,"pipeline-cap":512,"prepared-limit":16384,"query.settings.curl_whitelist":{"all_access":false,"allowed_urls":[],"disallowed_urls":[]},"query.settings.tmp_space_dir":"/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp","query.settings.tmp_space_size":5120,"scan-cap":512,"timeout":0,"txtimeout":"0ms","use-cbo":true,"use-replica":"unset"} |
2023-12-22T10:48:28.558+05:30 [INFO] Settings notifier from metakv |
2023-12-22T10:48:28.559+05:30 [INFO] GSI indexer settings have been updated map[query_tmpspace_dir:/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp query_tmpspace_limit:5120] |
2023-12-22T10:48:28.559+05:30 [INFO] n1fty indexer settings have been updated map[query_tmpspace_dir:/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp query_tmpspace_limit:5120] |
2023-12-22T10:48:28.558+05:30 [Info] GSIC - Setting config map[query_tmpspace_dir:/Users/dhanyagowrish/elixir/trinity-test/ns_server/tmp query_tmpspace_limit:5120] |
2023-12-22T10:48:28.559+05:30 [INFO] num-cpus updated to 0. Change will take place on restart. |
2023-12-22T10:48:28.557+05:30 [INFO] audit: created new audit service |
2023-12-22T10:48:28.559+05:30 [INFO] cbq-engine started version=7.6.0-N1QL ds_version=7.6.0-0000-enterprise datastore=http://127.0.0.1:9000 max-concurrency=10 loglevel=INFO servicers=40 plus-servicers=160 scan-cap=512 pipeline-cap=512 pipeline-batch=16 request-cap=256 request-size-cap=67108864 max-index-api=4 max-parallelism=1 n1ql-feat-ctrl=76 use-cbo=true timeout=0s txtimeout=0s gc-percent=200 node-quota=0 node-quota-val-percent=67 use-replica=unset |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 5 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 1 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 2 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 3 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 4 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 8 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 6 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 7 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 10 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit worker 9 |
2023-12-22T10:48:28.559+05:30 [INFO] Starting audit settings worker 1. |
2023-12-22T10:48:28.562+05:30 [INFO] Unable to initialize functions cache monitor Could not access functions change counter because <nil> |
2023-12-22T10:48:28.562+05:30 [INFO] jsevaluator: impl::Engine::Initialize: Completed v8wrapper.engine creation. |
2023-12-22T10:48:29.394+05:30 [INFO] jsevaluator: impl::Engine::Initialize: Completed v8wrapper.engine initialization. |
2023-12-22T10:48:29.394+05:30 [INFO] jsevaluator: impl::Engine::Initialize: Completed setting up engine storage ops' log config. |
2023-12-22T10:48:29.394+05:30 [INFO] jsevaluator: impl::Engine::Initialize: Completed setting evaluator's system log config. |
2023-12-22T10:48:29.445+05:30 DEBU REGU.impl.init.0.func1() at aggrecorder.go:57 [id 71] will report aggregate recorder stats every 5m0s |
2023-12-22T10:48:29.560+05:30 [INFO] Starting audit update stream |
2023-12-22T10:48:58.492+05:30 [INFO] Query Engine Stats {"cores":10,"cpu.sys.percent":0.0015,"cpu.user.percent":0.0015,"ffdc.total":0,"gc.num":19125440,"gc.pause.percent":0,"gc.pause.time":"370.001µs","healthy":true,"host.memory.free":2767093760,"host.memory.quota":0,"host.memory.total":34359738368,"host.memory.value_quota":0,"load":0,"loadfactor":33,"local.time":"2023-12-22T10:48:58.491+05:30","memory.system":29000968,"memory.total":16102136,"memory.usage":13152736,"node.allocated.values":1,"node.memory.usage":209715200,"process.memory.usage":1,"process.percore.cpupercent":0,"process.rss":52281344,"process.service.usage":0,"request.active.count":0,"request.completed.count":0,"request.per.sec.15min":0,"request.per.sec.1min":0,"request.per.sec.5min":0,"request.prepared.percent":0,"request.queued.count":0,"request_time.80percentile":"0s","request_time.95percentile":"0s","request_time.99percentile":"0s","request_time.mean":"0s","request_time.median":"0s","servicers.paused.count":0,"servicers.paused.total":0,"temp.hwm":0,"temp.usage":0,"total.threads":94,"uptime":"30.020288958s","version":"7.6.0-N1QL"} |