Hello guys I hope you are doing fine We re writing unit test typesense #community-help

Hello guys, I hope you are doing fine. We're writi...

Mehdi Khlifi

02/21/2022, 2:21 PM

Hello guys, I hope you are doing fine. We're writing unit tests for Typesense functionalities in python, on my end they work fine, but it's returning this error for my colleague. Any idea why? Typesense is running as a docker container.

self = <typesense.api_call.ApiCall object at 0x7fabbfeddaf0>, fn = <function delete at 0x7fabc37655e0>, endpoint = '/collections/vendors', as_json = True

kwargs = {'params': None, 'timeout': 10}, num_tries = 4, last_exception = ServiceUnavailable(503, 'Not Ready or Lagging')

node = <typesense.configuration.Node object at 0x7fabbfeddbe0>, url = '<http://typesense:8108/collections/vendors>', r = <Response [503]>

error_message = 'Not Ready or Lagging'

def make_request(self, fn, endpoint, as_json, **kwargs):

num_tries = 0

last_exception = None

logger.debug('Making {} {}'.format(fn.__name__, endpoint))

while num_tries < (self.config.num_retries + 1):

num_tries += 1

node = self.get_node()

logger.debug('Try {} to node {}:{} -- healthy? {}'.format(num_tries, node.host, node.port, node.healthy))

try:

url = node.url() + endpoint

if kwargs.get('data') and not (isinstance(kwargs['data'], str) or isinstance(kwargs['data'], bytes)):

kwargs['data'] = json.dumps(kwargs['data'])

r = fn(url, headers={ApiCall.API_KEY_HEADER_NAME: self.config.api_key}, **kwargs)

# Treat any status code > 0 and < 500 to be an indication that node is healthy

# We exclude 0 since some clients return 0 when request fails

if 0 < r.status_code < 500:

logger.debug('{}:{} is healthy. Status code: {}'.format(node.host, node.port, r.status_code))

self.set_node_healthcheck(node, True)

# We should raise a custom exception if status code is not 20X

if not 200 <= r.status_code < 300:

error_message = r.json().get('message', 'API error.')

# Raised exception will be caught and retried

>                   raise ApiCall.get_exception(r.status_code)(r.status_code, error_message)

E                   typesense.exceptions.ServiceUnavailable: [Errno 503] Not Ready or Lagging

/usr/local/lib/python3.9/site-packages/typesense/api_call.py:115: ServiceUnavailable

Kishore Nallan

02/21/2022, 2:22 PM

Can you post the last few lines of the Typesense server logs?

Kishore Nallan

02/21/2022, 2:22 PM

Also, what version is this running on?

Mehdi Khlifi

02/21/2022, 2:25 PM

This is the log

DEBUG    typesense.api_call:api_call.py:90 Making delete /collections/vendors

DEBUG    typesense.api_call:api_call.py:96 Try 1 to node typesense:8108 -- healthy? True

DEBUG    urllib3.connectionpool:connectionpool.py:228 Starting new HTTP connection (1): typesense:8108

DEBUG    urllib3.connectionpool:connectionpool.py:456 <http://typesense:8108> "DELETE /collections/vendors HTTP/1.1" 503 None

DEBUG    typesense.api_call:api_call.py:123 Request to typesense:8108 failed because of [Errno 503] Not Ready or Lagging

DEBUG    typesense.api_call:api_call.py:124 Sleeping for 1.0 and retrying...

DEBUG    typesense.api_call:api_call.py:59 No healthy nodes were found. Returning the next node.

DEBUG    typesense.api_call:api_call.py:96 Try 2 to node typesense:8108 -- healthy? False

DEBUG    urllib3.connectionpool:connectionpool.py:228 Starting new HTTP connection (1): typesense:8108

DEBUG    urllib3.connectionpool:connectionpool.py:456 <http://typesense:8108> "DELETE /collections/vendors HTTP/1.1" 503 None

DEBUG    typesense.api_call:api_call.py:123 Request to typesense:8108 failed because of [Errno 503] Not Ready or Lagging

DEBUG    typesense.api_call:api_call.py:124 Sleeping for 1.0 and retrying...

DEBUG    typesense.api_call:api_call.py:59 No healthy nodes were found. Returning the next node.

DEBUG    typesense.api_call:api_call.py:96 Try 3 to node typesense:8108 -- healthy? False

DEBUG    urllib3.connectionpool:connectionpool.py:228 Starting new HTTP connection (1): typesense:8108

DEBUG    urllib3.connectionpool:connectionpool.py:456 <http://typesense:8108> "DELETE /collections/vendors HTTP/1.1" 503 None

DEBUG    typesense.api_call:api_call.py:123 Request to typesense:8108 failed because of [Errno 503] Not Ready or Lagging

DEBUG    typesense.api_call:api_call.py:124 Sleeping for 1.0 and retrying...

DEBUG    typesense.api_call:api_call.py:59 No healthy nodes were found. Returning the next node.

DEBUG    typesense.api_call:api_call.py:96 Try 4 to node typesense:8108 -- healthy? False

DEBUG    urllib3.connectionpool:connectionpool.py:228 Starting new HTTP connection (1): typesense:8108

DEBUG    urllib3.connectionpool:connectionpool.py:456 <http://typesense:8108> "DELETE /collections/vendors HTTP/1.1" 503 None

DEBUG    typesense.api_call:api_call.py:123 Request to typesense:8108 failed because of [Errno 503] Not Ready or Lagging

DEBUG    typesense.api_call:api_call.py:124 Sleeping for 1.0 and retrying...

DEBUG    typesense.api_call:api_call.py:128 No retries left. Raising last exception: [Errno 503] Not Ready or Lagging

Mehdi Khlifi

02/21/2022, 2:25 PM

We're running the latest version 0.22.2

Kishore Nallan

02/21/2022, 2:25 PM

I meant the Typesense server logs from the Docker container.

Mehdi Khlifi

02/21/2022, 2:43 PM

This is it

I20220221 14:31:50.215472     7 typesense_server_utils.cpp:306] Starting Typesense 0.22.2

I20220221 14:31:50.215502     7 typesense_server_utils.cpp:309] Typesense is using jemalloc.

I20220221 14:31:50.215636     7 typesense_server_utils.cpp:358] Thread pool size: 64

I20220221 14:31:50.218214     7 store.h:61] Initializing DB by opening state dir: /data/db

I20220221 14:31:50.234297     7 store.h:61] Initializing DB by opening state dir: /data/meta

I20220221 14:31:50.253165     7 typesense_server_utils.cpp:437] Starting API service...

I20220221 14:31:50.253262   194 typesense_server_utils.cpp:209] Since no --nodes argument is provided, starting a single node Typesense cluster.

I20220221 14:31:50.253296     7 http_server.cpp:172] Typesense has started listening on port 8108

I20220221 14:31:50.253299   195 batched_indexer.cpp:120] Starting batch indexer with 64 threads.

I20220221 14:31:50.254617   195 batched_indexer.cpp:126] BatchedIndexer skip_index: -9999

I20220221 14:31:50.256515   194 server.cpp:1045] Server[braft::RaftStatImpl+braft::FileServiceImpl+braft::RaftServiceImpl+braft::CliServiceImpl] is serving on port=8107.

I20220221 14:31:50.256526   194 server.cpp:1048] Check out <http://9127fad9d2e7:8107> in web browser.

I20220221 14:31:50.256702   194 raft_server.cpp:65] Nodes configuration: 192.168.32.3:8107:8108

I20220221 14:31:50.256916   194 log.cpp:674] Use crc32c as the checksum type of appending entries

I20220221 14:31:50.256942   194 log.cpp:1158] log load_meta /data/state/log/log_meta first_log_index: 79 time: 19

I20220221 14:31:50.256955   194 log.cpp:1098] load open segment, path: /data/state/log first_index: 1

I20220221 14:31:50.257107   194 raft_meta.cpp:521] Loaded single stable meta, path /data/state/meta term 146 votedfor 192.168.16.3:8107:8108 time: 7

I20220221 14:31:50.257315   232 raft_server.cpp:490] on_snapshot_load

I20220221 14:31:50.257735   232 store.h:283] rm /data/db success

I20220221 14:31:50.257833   232 store.h:293] copy snapshot /data/state/snapshot/snapshot_00000000000000000081/db_snapshot to /data/db success

I20220221 14:31:50.257840   232 store.h:61] Initializing DB by opening state dir: /data/db

I20220221 14:31:50.267673   232 store.h:307] DB open success!

I20220221 14:31:50.267688   232 raft_server.cpp:469] Loading collections from disk...

I20220221 14:31:50.267689   232 collection_manager.cpp:117] CollectionManager::load()

I20220221 14:31:50.267756   232 auth_manager.cpp:32] Indexing 0 API key(s) found on disk.

I20220221 14:31:50.267765   232 collection_manager.cpp:137] Loading 32 collections in parallel, 1000 documents at a time.

I20220221 14:31:50.267777   232 collection_manager.cpp:144] Found 1 collection(s) on disk.

I20220221 14:31:50.268390   285 collection_manager.cpp:68] Found collection vendors with 4 memory shards.

I20220221 14:31:50.268489   285 collection_manager.cpp:1064] Loading collection vendors

I20220221 14:31:50.268532   285 collection_manager.cpp:1164] Indexed 0/0 documents into collection vendors

I20220221 14:31:50.268538   285 collection_manager.cpp:184] Loaded 1 collection(s) so far

I20220221 14:31:50.268560   232 collection_manager.cpp:206] Loaded 1 collection(s).

I20220221 14:31:50.268944   232 collection_manager.cpp:210] Initializing batched indexer from snapshot state...

I20220221 14:31:50.268967   232 batched_indexer.cpp:408] Restored 0 in-flight requests from snapshot.

I20220221 14:31:50.268972   232 raft_server.cpp:476] Finished loading collections from disk.

I20220221 14:31:50.268985   232 raft_server.h:251] Configuration of this group is 172.25.0.3:8107:8108

I20220221 14:31:50.269013   232 snapshot_executor.cpp:264] node default_group:192.168.32.3:8107:8108 snapshot_load_done, last_included_index: 81 last_included_term: 132 peers: "172.25.0.3:8107:8108"

I20220221 14:31:50.269066   194 raft_meta.cpp:521] Loaded single stable meta, path /data/state/meta term 146 votedfor 192.168.16.3:8107:8108 time: 15

I20220221 14:31:50.269075   194 node.cpp:576] node default_group:192.168.32.3:8107:8108 init, term: 146 last_log_id: (index=89,term=146) conf: 192.168.16.3:8107:8108 old_conf:

I20220221 14:31:50.269094   194 raft_server.cpp:127] Node last_index: 89

I20220221 14:31:50.269114   194 typesense_server_utils.cpp:260] Typesense peering service is running on 192.168.32.3:8107

I20220221 14:31:50.269119   194 typesense_server_utils.cpp:261] Snapshot interval configured as: 3600s

W20220221 14:31:50.269122   194 controller.cpp:1454] SIGINT was installed with 1

I20220221 14:31:50.269130   194 raft_server.cpp:524] Term: 146, last_index index: 89, committed_index: 0, known_applied_index: 81, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 59

W20220221 14:31:50.269135   194 raft_server.cpp:548] Single-node with no leader. Resetting peers.

W20220221 14:31:50.269138   194 node.cpp:894] node default_group:192.168.32.3:8107:8108 set_peer from 192.168.16.3:8107:8108 to 192.168.32.3:8107:8108

I20220221 14:31:50.270995   194 raft_meta.cpp:546] Saved single stable meta, path /data/state/meta term 147 votedfor 0.0.0.0:0:0 time: 1848

I20220221 14:32:00.272526   194 raft_server.cpp:524] Term: 147, last_index index: 89, committed_index: 0, known_applied_index: 81, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 59

W20220221 14:32:00.272565   194 raft_server.cpp:548] Single-node with no leader. Resetting peers.

I20220221 14:32:00.828796   241 node.cpp:1484] node default_group:192.168.32.3:8107:8108 term 147 start pre_vote

I20220221 14:32:00.828908   241 node.cpp:1549] node default_group:192.168.32.3:8107:8108 term 147 start vote and grant vote self

I20220221 14:32:00.830809   241 raft_meta.cpp:546] Saved single stable meta, path /data/state/meta term 148 votedfor 192.168.32.3:8107:8108 time: 1804

I20220221 14:32:00.830843   241 node.cpp:1783] node default_group:192.168.32.3:8107:8108 term 148 become leader of group 192.168.32.3:8107:8108

I20220221 14:32:00.832605   241 raft_server.h:251] Configuration of this group is 172.26.0.3:8107:8108

I20220221 14:32:00.832639   241 raft_server.h:251] Configuration of this group is 172.27.0.3:8107:8108

I20220221 14:32:00.832681   241 raft_server.h:251] Configuration of this group is 172.28.0.3:8107:8108

I20220221 14:32:00.832696   241 raft_server.h:251] Configuration of this group is 172.29.0.3:8107:8108

I20220221 14:32:00.832712   241 raft_server.h:251] Configuration of this group is 172.30.0.3:8107:8108

I20220221 14:32:00.832727   241 raft_server.h:251] Configuration of this group is 172.31.0.2:8107:8108

I20220221 14:32:00.832744   241 raft_server.h:251] Configuration of this group is 192.168.16.3:8107:8108

I20220221 14:32:00.832757   241 raft_server.h:251] Configuration of this group is 192.168.32.3:8107:8108

I20220221 14:32:00.832767   241 node.cpp:3142] node default_group:192.168.32.3:8107:8108 reset ConfigurationCtx, new_peers: 192.168.32.3:8107:8108, old_peers: 192.168.32.3:8107:8108

I20220221 14:32:00.832787   241 raft_server.h:234] Node becomes leader, term: 148

I20220221 14:32:10.274188   194 raft_server.cpp:524] Term: 148, last_index index: 90, committed_index: 90, known_applied_index: 90, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 61

I20220221 14:32:10.274303   247 raft_server.h:59] Peer refresh succeeded!

I20220221 14:32:20.275915   194 raft_server.cpp:524] Term: 148, last_index index: 90, committed_index: 90, known_applied_index: 90, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 61

I20220221 14:32:20.276075   241 raft_server.h:59] Peer refresh succeeded!

I20220221 14:32:30.277469   194 raft_server.cpp:524] Term: 148, last_index index: 90, committed_index: 90, known_applied_index: 90, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 61

I20220221 14:32:30.277633   241 raft_server.h:59] Peer refresh succeeded!

I20220221 14:32:40.279273   194 raft_server.cpp:524] Term: 148, last_index index: 90, committed_index: 90, known_applied_index: 90, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 61

I20220221 14:32:40.279433   241 raft_server.h:59] Peer refresh succeeded!

I20220221 14:32:50.281031   194 raft_server.cpp:524] Term: 148, last_index index: 90, committed_index: 90, known_applied_index: 90, applying_index: 0, queued_writes: 0, pending_queue_size: 0, local_sequence: 61

I20220221 14:32:50.281188   247 raft_server.h:59] Peer refresh succeeded!

I20220221 14:32:51.264093   195 batched_indexer.cpp:250] Running GC for aborted requests, req map size: 0

Kishore Nallan

02/21/2022, 2:44 PM

Looks fine to me. What happens when the /health endpoint is accessed on the browser?

Mehdi Khlifi

02/21/2022, 2:54 PM

It returns

{"ok": true}

Kishore Nallan

02/21/2022, 2:55 PM

Can you try manually creating a collection on it as well? If that also works j think that the test is trying to write data too fast and when that happens Typesense applies a back pressure.

Kishore Nallan

02/21/2022, 2:56 PM

Your machine probably has better resources so Typesense lags less.

Mehdi Khlifi

02/21/2022, 3:01 PM

That's what I thought too, because she can run the typesense container individually and interact with its API, because the connection fails inside the tests

Kishore Nallan

02/21/2022, 3:02 PM

How do the test create data? Via single inserts in a loop or via import?

Mehdi Khlifi

02/21/2022, 3:11 PM

JSONL file import

Kishore Nallan

02/21/2022, 3:12 PM

Just try adding a short sleep after the import. I've a todo item to handle backpressure during imports.

Mehdi Khlifi

02/21/2022, 3:18 PM

Worked ! Thank you 😃

Kishore Nallan

02/21/2022, 3:19 PM

Welcome!

3 Views

Open in Slack

Previous Next