I'm stuck on pool.import_on_boot

[agent]

I'm stuck from a week. I tried to reboot many times but my system stuck and apps never startup.
In my jobs list have pool.dataset.unlock 0% and pool.import_on_boot stuck ad 80% (many days).
What can I do?

TrueNas scale Bluefish 22.12.2
ryzen 3200g 32gb ram

 

[Arwen]

Can you log into the server using SSH?

If so, please supply the output of the following commands in code tags;
zpool list zpool import zpool status

Also, a more complete hardware list per forum rules can help.

 

[agent]

Can you log into the server using SSH?

If so, please supply the output of the following commands in code tags;
zpool list zpool import zpool status

Also, a more complete hardware list per forum rules can help.

zpool list:
root@truenas[~]# zpool list

NAME SIZE ALLOC FREE CKPOINT EXPANDSZ FRAG CAP DEDUP HEALTH ALTROOT
boot-pool 1.80T 6.91G 1.79T - - 0% 0% 1.00x ONLINE -
pool01 116T 19.8T 96.6T - - 15% 17% 1.00x ONLINE /mnt

zpool status:
root@truenas[~]# zpool status
pool: boot-pool
state: ONLINE
status: Some supported and requested features are not enabled on the pool.
The pool can still be used, but some features are unavailable.
action: Enable all features using 'zpool upgrade'. Once this is done,
the pool may no longer be accessible by software that does not support
the features. See zpool-features(7) for details.
scan: scrub repaired 0B in 00:00:09 with 0 errors on Mon Apr 17 03:49:24 2023
config:

NAME STATE READ WRITE CKSUM
boot-pool ONLINE 0 0 0
nvme0n1p3 ONLINE 0 0 0

errors: No known data errors

Stuck after this..

zpool import:
root@truenas[~]# zpool import
no pools available to import

During "zpool status" the system does not give me the prompt again and stuck after "errors: No known data errors". Ctrl+C doesn't work.
Cannot see the pool of 8 hdd in raidz1

I see all hard drives with lsblk command

EDIT:
After about 30minutes I have zpool status complete response:

pool: pool01
state: ONLINE
scan: scrub repaired 0B in 9 days 17:31:19 with 0 errors on Tue Mar 21 17:31:27 2023
config:

NAME STATE READ WRITE CKSUM
pool01 ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
8cad8248-6d2b-4e39-b955-b74bcbc14c08 ONLINE 0 0 0
b379e6af-2220-4200-bdd4-ac63774bd0bc ONLINE 0 0 0
6db6d7e8-6ce7-4784-8dbc-ea75562c7535 ONLINE 0 0 0
15c6178c-abc0-4fa0-8728-d4e9d924e595 ONLINE 0 0 0
fee6cc44-ba0a-4161-8614-4073c4476fb6 ONLINE 0 0 0
a0f1f1e8-f81c-4684-973c-1fcf9488dc7f ONLINE 0 0 0
bb60a1f9-9624-4f0f-a2b7-e5f5f1d23582 ONLINE 0 0 0
d2f497ab-a97e-46e2-83e1-3ff6b6cdd518 ONLINE 0 0 0

errors: No known data errors

Hardware:

Asus PRIME B450M-A II
Ryzen 3200g
32gb Ram
8hdd in raidz1
1 nvme for truenas

 

[Arwen]

You still have not listed your whole hardware. Please list the hard disk manufacturer and model, as well as how they are connected to the system board. Like system board SATA port or HBA PCIe card port.

Certain hard disk drives are completely and totally un-suitable for ZFS. The hint that you might have such drives is that your scrub took 9 days and 17 hours.

 

[agent]

I just received critical error:

CRITICAL
Failed to check for alert VolumeStatus: concurrent.futures.process._RemoteTraceback: """ Traceback (most recent call last): File "/usr/lib/python3.9/concurrent/futures/process.py", line 243, in _process_worker r = call_item.fn(*call_item.args, **call_item.kwargs) File "/usr/lib/python3/dist-packages/middlewared/worker.py", line 115, in main_worker res = MIDDLEWARE._run(*call_args) File "/usr/lib/python3/dist-packages/middlewared/worker.py", line 46, in _run return self._call(name, serviceobj, methodobj, args, job=job) File "/usr/lib/python3/dist-packages/middlewared/worker.py", line 34, in _call with Client(f'ws+unix://{MIDDLEWARE_RUN_DIR}/middlewared-internal.sock', py_exceptions=True) as c: File "/usr/lib/python3/dist-packages/middlewared/client/client.py", line 326, in __init__ self._ws.connect() File "/usr/lib/python3/dist-packages/middlewared/client/client.py", line 129, in connect rv = super(WSClient, self).connect() File "/usr/lib/python3/dist-packages/ws4py/client/__init__.py", line 222, in connect bytes = self.sock.recv(128) socket.timeout: timed out """ The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/middlewared/plugins/alert.py", line 776, in __run_source alerts = (await alert_source.check()) or [] File "/usr/lib/python3/dist-packages/middlewared/alert/source/volume_status.py", line 19, in check for pool in await self.middleware.call("pool.query"): File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1386, in call return await self._call( File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1335, in _call return await methodobj(*prepared_call.args) File "/usr/lib/python3/dist-packages/middlewared/schema.py", line 1186, in nf res = await f(*args, **kwargs) File "/usr/lib/python3/dist-packages/middlewared/schema.py", line 1318, in nf return await func(*args, **kwargs) File "/usr/lib/python3/dist-packages/middlewared/service.py", line 927, in query result = await self.middleware.call( File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1386, in call return await self._call( File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1335, in _call return await methodobj(*prepared_call.args) File "/usr/lib/python3/dist-packages/middlewared/schema.py", line 1318, in nf return await func(*args, **kwargs) File "/usr/lib/python3/dist-packages/middlewared/plugins/datastore/read.py", line 165, in query result = await self._queryset_serialize( File "/usr/lib/python3/dist-packages/middlewared/plugins/datastore/read.py", line 217, in _queryset_serialize return [ File "/usr/lib/python3/dist-packages/middlewared/plugins/datastore/read.py", line 218, in await self._extend(data, extend, extend_context, extend_context_value, select) File "/usr/lib/python3/dist-packages/middlewared/plugins/datastore/read.py", line 231, in _extend data = await self.middleware.call(extend, data, extend_context_value) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1386, in call return await self._call( File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1346, in _call return await self.run_in_executor(prepared_call.executor, methodobj, *prepared_call.args) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1249, in run_in_executor return await loop.run_in_executor(pool, functools.partial(method, *args, **kwargs)) File "/usr/lib/python3.9/concurrent/futures/thread.py", line 52, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3/dist-packages/middlewared/plugins/pool.py", line 605, in pool_extend pool |= self.middleware.call_sync('pool.pool_normalize_info', pool['name']) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1405, in call_sync return self.run_coroutine(methodobj(*prepared_call.args)) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1445, in run_coroutine return fut.result() File "/usr/lib/python3.9/concurrent/futures/_base.py", line 433, in result return self.__get_result() File "/usr/lib/python3.9/concurrent/futures/_base.py", line 389, in __get_result raise self._exception File "/usr/lib/python3/dist-packages/middlewared/schema.py", line 1318, in nf return await func(*args, **kwargs) File "/usr/lib/python3/dist-packages/middlewared/schema.py", line 1186, in nf res = await f(*args, **kwargs) File "/usr/lib/python3/dist-packages/middlewared/plugins/pool.py", line 565, in pool_normalize_info if info := await self.middleware.call('zfs.pool.query', [('name', '=', pool_name)]): File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1386, in call return await self._call( File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1343, in _call return await self._call_worker(name, *prepared_call.args) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1349, in _call_worker return await self.run_in_proc(main_worker, name, args, job) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1264, in run_in_proc return await self.run_in_executor(self.__procpool, method, *args, **kwargs) File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1249, in run_in_executor return await loop.run_in_executor(pool, functools.partial(method, *args, **kwargs)) socket.timeout: timed out
2023-04-23 22:21:48 (Europe/Rome)
Dismiss

Hardware details:
8x Toshiba MG08ACA16TE
4 attached to motherboard sata. 4 attached on pci sata multiplier 4x

root@truenas[~]# lsblk
NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
sda 8:0 0 14.6T 0 disk
├─sda1 8:1 0 2G 0 part
│ └─md127 9:127 0 2G 0 raid1
│ └─md127 253:1 0 2G 0 crypt [SWAP]
└─sda2 8:2 0 14.6T 0 part
sdb 8:16 0 14.6T 0 disk
├─sdb1 8:17 0 2G 0 part
│ └─md127 9:127 0 2G 0 raid1
│ └─md127 253:1 0 2G 0 crypt [SWAP]
└─sdb2 8:18 0 14.6T 0 part
sdc 8:32 0 14.6T 0 disk
├─sdc1 8:33 0 2G 0 part
│ └─md126 9:126 0 2G 0 raid1
│ └─md126 253:3 0 2G 0 crypt [SWAP]
└─sdc2 8:34 0 14.6T 0 part
sdd 8:48 0 14.6T 0 disk
├─sdd1 8:49 0 2G 0 part
│ └─md126 9:126 0 2G 0 raid1
│ └─md126 253:3 0 2G 0 crypt [SWAP]
└─sdd2 8:50 0 14.6T 0 part
sde 8:64 0 14.6T 0 disk
├─sde1 8:65 0 2G 0 part
│ └─md124 9:124 0 2G 0 raid1
│ └─md124 253:0 0 2G 0 crypt [SWAP]
└─sde2 8:66 0 14.6T 0 part
sdf 8:80 0 14.6T 0 disk
├─sdf1 8:81 0 2G 0 part
│ └─md125 9:125 0 2G 0 raid1
│ └─md125 253:2 0 2G 0 crypt [SWAP]
└─sdf2 8:82 0 14.6T 0 part
sdg 8:96 0 14.6T 0 disk
├─sdg1 8:97 0 2G 0 part
│ └─md125 9:125 0 2G 0 raid1
│ └─md125 253:2 0 2G 0 crypt [SWAP]
└─sdg2 8:98 0 14.6T 0 part
sdh 8:112 0 14.6T 0 disk
├─sdh1 8:113 0 2G 0 part
│ └─md124 9:124 0 2G 0 raid1
│ └─md124 253:0 0 2G 0 crypt [SWAP]
└─sdh2 8:114 0 14.6T 0 part
nvme0n1 259:0 0 1.8T 0 disk
├─nvme0n1p1 259:1 0 1M 0 part
├─nvme0n1p2 259:2 0 512M 0 part
├─nvme0n1p3 259:3 0 1.8T 0 part
└─nvme0n1p4 259:4 0 16G 0 part
root@truenas[~]#

 

[Samuel Tai]

Your drives are enterprise helium drives, which are excellent. You're using a SATA multiplier, which is very unfortunate, and most likely the cause of your problems.

Multiply your problems with SATA Port Multipliers and cheap SATA controllers

In the last year or two, we've had a resurgence of users asking about SATA Port Multipliers and cheap SATA controllers. Please, do NOT use port multipliers, and use cheap SATA controllers only after extensive research. SATA controllers and SATA...

www.truenas.com

 

[agent]

I lost all k3s apps Can I try to recover catalog manually?

 

[agent]

root@truenas[~]# systemctl status docker.service
● docker.service - Docker Application Container Engine
Loaded: loaded (/lib/systemd/system/docker.service; disabled; vendor preset: disabled)
Drop-In: /etc/systemd/system/docker.service.d
└─override.conf
Active: failed (Result: resources) since Tue 2023-04-25 01:24:51 CEST; 11s ago
TriggeredBy: ● docker.socket
Docs: https://docs.docker.com
CPU: 0

Apr 25 01:24:51 truenas systemd[1]: docker.service: Failed to load environment files: No such file or directory
Apr 25 01:24:51 truenas systemd[1]: docker.service: Failed to run 'start' task: No such file or directory
Apr 25 01:24:51 truenas systemd[1]: docker.service: Failed with result 'resources'.
Apr 25 01:24:51 truenas systemd[1]: Failed to start Docker Application Container Engine.
Apr 25 01:24:51 truenas systemd[1]: docker.service: Scheduled restart job, restart counter is at 3.
Apr 25 01:24:51 truenas systemd[1]: Stopped Docker Application Container Engine.
Apr 25 01:24:51 truenas systemd[1]: docker.service: Start request repeated too quickly.
Apr 25 01:24:51 truenas systemd[1]: docker.service: Failed with result 'resources'.
Apr 25 01:24:51 truenas systemd[1]: Failed to start Docker Application Container Engine.

 

[agent]

Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Starting k3s v1.25.3+k3s-9afcd6b9-dirty (9afcd6b9)"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Configuring sqlite3 database connection pooling: maxIdleConns=2, maxOpenConns=0, connMaxLifetime=0s"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Configuring database table schema and indexes, this may take a moment..."
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Database tables and indexes are up to date"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Kine available at unix://kine.sock"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Reconciling bootstrap data between datastore and disk"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Tunnel server egress proxy mode: agent"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Tunnel server egress proxy waiting for runtime core to become available"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Running kube-apiserver --advertise-port=6443 --allow-privileged=true --anonymous-auth=false --api-audiences=https://kubernetes.default.svc.cluster.lo>
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Running kube-scheduler --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/scheduler.kubeconfig --authorization-kubeconfig=/var/lib/rancher/>
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Waiting for API server to become available"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Running kube-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/controller.kubeconfig --autho>
Apr 25 01:14:58 truenas k3s[2458964]: I0425 01:14:58.174296 2458964 server.go:581] external host was not specified, using 192.168.1.26
Apr 25 01:14:58 truenas k3s[2458964]: I0425 01:14:58.174535 2458964 server.go:171] Version: v1.25.3+k3s-9afcd6b9-dirty
Apr 25 01:14:58 truenas k3s[2458964]: I0425 01:14:58.174553 2458964 server.go:173] "Golang settings" GOGC="" GOMAXPROCS="" GOTRACEBACK=""
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Running cloud-controller-manager --allocate-node-cidrs=true --authentication-kubeconfig=/var/lib/rancher/k3s/server/cred/cloud-controller.kubeconfig >
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Server node token is available at /var/lib/rancher/k3s/server/token"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="To join server node to cluster: k3s server -s https://192.168.1.26:6443 -t ${SERVER_NODE_TOKEN}"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Agent node token is available at /var/lib/rancher/k3s/server/agent-token"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="To join agent node to cluster: k3s agent -s https://192.168.1.26:6443 -t ${AGENT_NODE_TOKEN}"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Wrote kubeconfig /etc/rancher/k3s/k3s.yaml"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Run: k3s kubectl"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="certificate CN=ix-truenas signed by CN=k3s-server-ca@1682378062: notBefore=2023-04-24 23:14:22 +0000 UTC notAfter=2024-04-23 23:14:58 +0000 UTC"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="certificate CN=system:node:ix-truenas,O=system:nodes signed by CN=k3s-client-ca@1682378062: notBefore=2023-04-24 23:14:22 +0000 UTC notAfter=2024-04->
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Module overlay was already loaded"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Module nf_conntrack was already loaded"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Module br_netfilter was already loaded"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=info msg="Module iptable_nat was already loaded"
Apr 25 01:14:58 truenas k3s[2458964]: time="2023-04-25T01:14:58+02:00" level=fatal msg="failed to get docker runtime info: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?"
Apr 25 01:14:58 truenas systemd[1]: k3s.service: Main process exited, code=exited, status=1/FAILURE