search

vitalif / vitastor

Simplified distributed block and file storage with strong consistency, like in Ceph (repository mirror)
https://vitastor.io
Other
128 stars 22 forks source link

[QEMU and vitastor-mon] qemu-img: Unknown protocol 'vitastor' and Type Error #23

Closed moly7x closed 2 years ago

moly7x commented 2 years ago

Hi @vitalif, I hope you can help me solve this Issues soon 😢😢 . I really don’t know what should I do now. Host:

lsb_release -a
Distributor ID: Ubuntu
Description:    Ubuntu 21.04
Release:        21.04
Codename:       hirsute

dpkg -l | grep vitastor
ii  qemu                                  1:5.2+dfsg-10+vitastor1                                              amd64        fast processor emulator, dummy package
ii  vitastor                              0.6.5-1bullseye                                                      amd64        Vitastor, a fast software-defined clustered block storage

Cinder_volume (Inside container):

lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.3 LTS
Release:        20.04
Codename:       focal

dpkg -l | grep qemu
ii  qemu                           1:5.2+dfsg-10+vitastor1           amd64        fast processor emulator, dummy package
ii  qemu-block-extra:amd64         1:4.2-3ubuntu6.17                 amd64        extra block backend modules for qemu-system and qemu-utils
ii  qemu-utils                     1:4.2-3ubuntu6.17                 amd64        QEMU utilities

dpkg -l | grep vitastor
ii  qemu                           1:5.2+dfsg-10+vitastor1           amd64        fast processor emulator, dummy package
ii  vitastor                       0.6.5-1bullseye                   amd64        Vitastor, a fast software-defined clustered block storage

Problem 1 (QEMU):

Before rebuilding QEMU: I already installed vitastor-cli inside Cinder_volume but when I try using qemu-img (Inside Cinder_volume container). It always has a problem (Both 2 method)

qemu-img convert -f raw cirros-0.4.0-x86_64-disk.img -p -O raw 'vitastor:etcd_host=127.0.0.1\:2379/v3:image=testimg'
qemu-img: Unknown protocol 'vitastor'

LD_PRELOAD=/usr/lib/x86_64-linux-gnu/qemu/block-vitastor.so qemu-img convert -f raw cirros-0.4.0-x86_64-disk.img -p -O raw 'vitastor:etcd_host=127.0.0.1\:2379/v3:image=testimg'
qemu-img: Unknown protocol 'vitastor'

After building QEMU: I rebuilded QEMU (1:4.2-3ubuntu6.17) and applying a Patch in vitastor/patch/ qemu-4.2-vitastor.patch But it still got same problem.

qemu-img convert -f raw cirros-0.4.0-x86_64-disk.img -p -O raw 'vitastor:etcd_host=127.0.0.1\:2379/v3:image=testimg'
Failed to initialize module: /usr/lib/x86_64-linux-gnu/qemu/block-vitastor.so
Note: only modules from the same build can be loaded.
Failed to open module: /var/run/qemu/Debian_1_4.2-3ubuntu6.17/block-vitastor.so: failed to map segment from shared object
qemu-img: Unknown protocol 'vitastor'

LD_PRELOAD=/usr/lib/x86_64-linux-gnu/qemu/block-vitastor.so qemu-img convert -f raw cirros-0.4.0-x86_64-disk.img -p -O raw 'vitastor:etcd_host=127.0.0.1\:2379/v3:image=testimg'
qemu-img: /home/moly7x/qemu3/qemu-4.2/util/module.c:125: module_load_file: Assertion `QTAILQ_EMPTY(&dso_init_list)' failed.
Aborted (core dumped)

This is how I rebuild QEMU (I build in another VM, Ubuntu 20.04)

sudo apt install dpkg-dev

#Uncomment Deb source
sudo nano /etc/apt/sources.list

sudo apt-update
sudo apt-get source qemu=1:4.2-3ubuntu6.17
cd ./qemu-4.2/
sudo apt build-dep qemu=1:4.2-3ubuntu6.17

export QUILT_PATCHES=debian/patches
export QUILT_REFRESH_ARGS="-p ab --no-timestamps --no-index"
sudo quilt import ../qemu-4.2-vitastor.patch
sudo quilt push -a
sudo quilt refresh

dpkg-buildpackage -rfakeroot -b -uc -us

Problem 2 (BigInt):

Everytime I start my VM (host), I always need to start etcd either. (Not autostart)

systemctl status etcd
● etcd.service - etcd for vitastor
     Loaded: loaded (/etc/systemd/system/etcd.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2021-10-20 04:12:51 UTC; 3h 31min ago
    Process: 12802 ExecStartPre=chown -R etcd /var/lib/etcd0.etcd (code=exited, status=0/SUCCESS)
   Main PID: 12805 (etcd)
      Tasks: 11
     Memory: 113.1M

After I installed vitastor, I started vitastor-mon and vitastor.target services. And run command like example in README.

etcdctl --endpoints=http://127.0.0.1:2379 put /vitastor/config/global '{"immediate_commit":"all"}'

etcdctl --endpoints=http://127.0.0.1:2379 put /vitastor/config/pools '{"1":{"name":"testpool","scheme":"replicated","pg_size":2,"pg_minsize":1,"pg_count":256,"failure_domain":"host"}}'

etcdctl --endpoints=http://127.0.0.1:2379 put /vitastor/config/inode/1/1 '{"name":"testimg","size":2147483648}'

And run fio testing

fio -thread -ioengine=libfio_vitastor.so -name=test -bs=4M -direct=1 -iodepth=16 -rw=write -etcd=127.0.0.1:2379/v3 -image=testimg

test: (g=0): rw=write, bs=(R) 4096KiB-4096KiB, (W) 4096KiB-4096KiB, (T) 4096KiB-4096KiB, ioengine=vitastor_cluster, iodepth=16
fio-3.25
Starting 1 thread
No RDMA devices found
[OSD 0] Couldnt initialize RDMA, proceeding with TCP only
Jobs: 1 (f=1): [W(1)][97.3%][w=23.9MiB/s][w=5 IOPS][eta 00m:01s]
test: (groupid=0, jobs=1): err= 0: pid=28987: Thu Sep 23 03:28:17 2021
  write: IOPS=14, BW=57.7MiB/s (60.5MB/s)(2048MiB/35521msec); 0 zone resets
    slat (usec): min=84, max=1037, avg=188.40, stdev=81.25
    clat (msec): min=380, max=2349, avg=1107.34, stdev=345.66
     lat (msec): min=381, max=2349, avg=1107.53, stdev=345.65
    clat percentiles (msec):
     |  1.00th=[  443],  5.00th=[  600], 10.00th=[  701], 20.00th=[  785],
     | 30.00th=[  894], 40.00th=[  995], 50.00th=[ 1062], 60.00th=[ 1150],
     | 70.00th=[ 1250], 80.00th=[ 1435], 90.00th=[ 1603], 95.00th=[ 1754],
     | 99.00th=[ 1989], 99.50th=[ 2022], 99.90th=[ 2366], 99.95th=[ 2366],
     | 99.99th=[ 2366]
   bw (  KiB/s): min= 8159, max=130549, per=100.00%, avg=62443.09, stdev=28879.73, samples=65
   iops        : min=    1, max=   31, avg=14.60, stdev= 7.06, samples=65
  lat (msec)   : 500=1.17%, 750=13.09%, 1000=27.73%, 2000=57.23%, >=2000=0.78%
  cpu          : usr=0.28%, sys=2.74%, ctx=1105, majf=0, minf=290
  IO depths    : 1=0.2%, 2=0.4%, 4=0.8%, 8=58.2%, 16=40.4%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=95.4%, 8=4.4%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,512,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
  WRITE: bw=57.7MiB/s (60.5MB/s), 57.7MiB/s-57.7MiB/s (60.5MB/s-60.5MB/s), io=2048MiB (2147MB), run=35521-35521msec

But after I restart my VM, and check vitastor-mon status. It got a problem.

systemctl status vitastor-mon
● vitastor-mon.service - Vitastor monitor
     Loaded: loaded (/etc/systemd/system/vitastor-mon.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2021-10-20 07:46:46 UTC; 47s ago
   Main PID: 318383 (node)
      Tasks: 7
     Memory: 15.3M
     CGroup: /system.slice/vitastor-mon.service
             └─318383 node /usr/lib/vitastor/mon/mon-main.js --etcd_url http://127.0.0.1:2379 --etcd_prefix /vitastor --etcd_start_timeou>

Oct 20 07:46:46 controller systemd[1]: Started Vitastor monitor.
Oct 20 07:46:46 controller node[318383]: Waiting to become master
Oct 20 07:46:51 controller node[318383]: Waiting to become master
Oct 20 07:46:56 controller node[318383]: Waiting to become master
Oct 20 07:47:01 controller node[318383]: Waiting to become master
Oct 20 07:47:06 controller node[318383]: Waiting to become master
Oct 20 07:47:11 controller node[318383]: Waiting to become master
Oct 20 07:47:16 controller node[318383]: Waiting to become master
Oct 20 07:47:21 controller node[318383]: Became master
Oct 20 07:47:21 controller node[318383]: Bad key in etcd: /vitastor/pool/stats/1 = {"used_raw_tb":0.001953125,"total_raw_tb":0.01949596405029297,"raw_to_usable":0.5,"space_efficiency":1}

Oct 20 07:50:40 controller node[318383]: TypeError: Do not know how to serialize a BigInt
Oct 20 07:50:40 controller node[318383]:     at JSON.stringify (<anonymous>)
Oct 20 07:50:40 controller node[318383]:     at Mon.update_total_stats (/usr/lib/vitastor/mon/mon.js:1355:33)
Oct 20 07:50:40 controller node[318383]:     at Timeout._onTimeout (/usr/lib/vitastor/mon/mon.js:1380:18)
Oct 20 07:50:40 controller node[318383]:     at listOnTimeout (internal/timers.js:554:17)
Oct 20 07:50:40 controller node[318383]:     at processTimers (internal/timers.js:497:7)
vitalif commented 2 years ago

1) Regarding QEMU: Install all qemu* packages from my repo, not just qemu:

ii  qemu                                                        1:5.2+dfsg-10+vitastor1                 amd64        fast processor emulator, dummy package
ii  qemu-block-extra                                            1:5.2+dfsg-10+vitastor1                 amd64        extra block backend modules for qemu-system and qemu-utils
ii  qemu-system-arm                                             1:5.2+dfsg-10+vitastor1                 amd64        QEMU full system emulation binaries (arm)
ii  qemu-system-common                                          1:5.2+dfsg-10+vitastor1                 amd64        QEMU full system emulation binaries (common files)
ii  qemu-system-data                                            1:5.2+dfsg-10+vitastor1                 all          QEMU full system emulation (data files)
ii  qemu-system-gui:amd64                                       1:5.2+dfsg-10+vitastor1                 amd64        QEMU full system emulation binaries (user interface and audio support)
ii  qemu-system-x86                                             1:5.2+dfsg-10+vitastor1                 amd64        QEMU full system emulation binaries (x86)
ii  qemu-utils                                                  1:5.2+dfsg-10+vitastor1                 amd64        QEMU utilities

Then it will work. I probably should add a dependency on qemu-system-x86 or something like that instead of just the "qemu" package.

P.S: If you rebuild QEMU yourself, then you should also rebuild vitastor, QEMU lacks out-of-tree module build support, so it's a rather ugly scheme by now. I think I'll change that scheme by making a separate vitastor-dev package and moving the driver into the QEMU patch, then it'll be slightly less ugly :)

vitalif commented 2 years ago
  1. Regarding "do not know how to serialize a BigInt":

I've just pushed a fix, can you take mon/mon.js from master branch, put it into /usr/lib/vitastor/mon/ and recheck?

vitalif commented 2 years ago
  1. Regarding the lack of etcd autostart

I'm not sure why it doesn't start automatically in your case, the systemd unit seems enabled. Can you check its logs at the moment when it doesn't start?

moly7x commented 2 years ago
  1. After I apply new mon/mon.js and recheck. I only got bad keys. This is exactly what's going on a few days ago when I'm trying to fix BigInt in mon.js. (Not success, so I created Issues).
Oct 21 13:18:01 controller node[22054]: Became master
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1 = {"used_raw_tb":0.001953125}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1011 = {"used_raw_tb":"1835008"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/104 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/111 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1119 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1187 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1237 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/124 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1240 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1258 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1349 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1354 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1374 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1382 = {"used_raw_tb":"917504"}
Oct 21 13:18:01 controller node[22054]: Bad key in etcd: /vitastor/pool/stats/1434 = {"used_raw_tb":"917504"}
moly7x commented 2 years ago
  1. This is etcd services log after I started manually. I don't know why it doesn't start automatically 🥲🥲 
    -- Boot 61501c002ffb464b9340ea41dcfcff00 --
Oct 21 13:11:13 controller systemd[1]: Starting etcd for vitastor...
Oct 21 13:11:13 controller systemd[1]: Started etcd for vitastor.
Oct 21 13:11:13 controller etcd[12229]: [WARNING] Deprecated '--logger=capnslog' flag is set; use '--logger=zap' flag instead
Oct 21 13:11:13 controller etcd[12229]: etcd Version: 3.4.13
Oct 21 13:11:13 controller etcd[12229]: [WARNING] Deprecated '--logger=capnslog' flag is set; use '--logger=zap' flag instead
Oct 21 13:11:13 controller etcd[12229]: Git SHA: 416381529
Oct 21 13:11:13 controller etcd[12229]: Go Version: go1.14.4
Oct 21 13:11:13 controller etcd[12229]: Go OS/Arch: linux/amd64
Oct 21 13:11:13 controller etcd[12229]: setting maximum number of CPUs to 4, total number of available CPUs is 4
Oct 21 13:11:13 controller etcd[12229]: the server is already initialized as member before, starting as etcd member...
Oct 21 13:11:13 controller etcd[12229]: name = etcd0
Oct 21 13:11:13 controller etcd[12229]: data dir = /var/lib/etcd0.etcd
Oct 21 13:11:13 controller etcd[12229]: member dir = /var/lib/etcd0.etcd/member
Oct 21 13:11:13 controller etcd[12229]: heartbeat = 100ms
Oct 21 13:11:13 controller etcd[12229]: election = 1000ms
Oct 21 13:11:13 controller etcd[12229]: snapshot count = 100000
Oct 21 13:11:13 controller etcd[12229]: advertise client URLs = http://127.0.0.1:2379
Oct 21 13:11:13 controller etcd[12229]: initial advertise peer URLs = http://127.0.0.1:2380
Oct 21 13:11:13 controller etcd[12229]: initial cluster =
Oct 21 13:11:13 controller etcd[12229]: MaxRequestBytes 104857600 exceeds maximum recommended size 10485760
Oct 21 13:11:13 controller etcd[12229]: check file permission: directory "/var/lib/etcd0.etcd" exist, but the permission is "drwxr-xr-x". The recommended permission is "-rwx------" to prevent possible unprivileged access to the data.
Oct 21 13:11:13 controller etcd[12229]: restarting member ffbdd670f3d57de4 in cluster fbe9fd6e26158ef1 at commit index 79
Oct 21 13:11:13 controller etcd[12229]: raft2021/10/21 13:11:13 INFO: ffbdd670f3d57de4 switched to configuration voters=()
Oct 21 13:11:13 controller etcd[12229]: raft2021/10/21 13:11:13 INFO: ffbdd670f3d57de4 became follower at term 2
Oct 21 13:11:13 controller etcd[12229]: raft2021/10/21 13:11:13 INFO: newRaft ffbdd670f3d57de4 [peers: [], term: 2, commit: 79, applied: 0, lastindex: 79, lastterm: 2]
Oct 21 13:11:13 controller etcd[12229]: simple token is not cryptographically signed
Oct 21 13:11:13 controller etcd[12229]: restore compact to 50
Oct 21 13:11:13 controller etcd[12229]: starting server... [version: 3.4.13, cluster version: to_be_decided]
Oct 21 13:11:13 controller etcd[12229]: raft2021/10/21 13:11:13 INFO: ffbdd670f3d57de4 switched to configuration voters=(18428121030885473764)
Oct 21 13:11:13 controller etcd[12229]: added member ffbdd670f3d57de4 [http://127.0.0.1:2380] to cluster fbe9fd6e26158ef1
Oct 21 13:11:13 controller etcd[12229]: set the initial cluster version to 3.4
Oct 21 13:11:13 controller etcd[12229]: enabled capabilities for version 3.4
Oct 21 13:11:13 controller etcd[12229]: listening for peers on 127.0.0.1:2380
Oct 21 13:11:15 controller etcd[12229]: raft2021/10/21 13:11:15 INFO: ffbdd670f3d57de4 is starting a new election at term 2
Oct 21 13:11:15 controller etcd[12229]: raft2021/10/21 13:11:15 INFO: ffbdd670f3d57de4 became candidate at term 3
Oct 21 13:11:15 controller etcd[12229]: raft2021/10/21 13:11:15 INFO: ffbdd670f3d57de4 received MsgVoteResp from ffbdd670f3d57de4 at term 3
Oct 21 13:11:15 controller etcd[12229]: raft2021/10/21 13:11:15 INFO: ffbdd670f3d57de4 became leader at term 3
Oct 21 13:11:15 controller etcd[12229]: raft2021/10/21 13:11:15 INFO: raft.node: ffbdd670f3d57de4 elected leader ffbdd670f3d57de4 at term 3
Oct 21 13:11:15 controller etcd[12229]: ready to serve client requests
Oct 21 13:11:15 controller etcd[12229]: published {Name:etcd0 ClientURLs:[http://127.0.0.1:2379]} to cluster fbe9fd6e26158ef1
Oct 21 13:11:15 controller etcd[12229]: serving insecure client requests on 127.0.0.1:2379, this is strongly discouraged!
Oct 21 13:11:26 controller etcd[12229]: request "header:<ID:9071512588854003227 > lease_revoke:<id:7de47ca2fa208616>" with result

Before I start it:

systemctl status etcd
● etcd.service - etcd for vitastor
     Loaded: loaded (/etc/systemd/system/etcd.service; enabled; vendor preset: enabled)
     Active: inactive (dead)
vitalif commented 2 years ago 
1. After I apply new `mon/mon.js` and recheck. I only got bad keys. This is exactly what's going on a few days ago when I'm trying to fix BigInt in `mon.js`. (Not success, so I created Issues).

Ok I see please take it from master and recheck again :-) It seems to be related to situations when your OSDs have data in pools not listed in config/pools

moly7x commented 2 years ago

Ok I see please take it from master and recheck again :-) It seems to be related to situations when your OSDs have data in pools not listed in config/pools

=)) tks, It works.

Oct 22 03:49:49 controller node[33528]: Waiting to become master
Oct 22 03:49:54 controller node[33528]: Waiting to become master
Oct 22 03:49:59 controller node[33528]: Waiting to become master
Oct 22 03:50:04 controller node[33528]: Became master
Oct 22 03:50:10 controller node[33528]: Data movement: 256 pgs, 512 pg*osds = 66.67 %
Oct 22 03:50:10 controller node[33528]: Total space (raw): 0 TB, space efficiency: 0 %
Oct 22 03:50:10 controller node[33528]: PG configuration successfully changed
Oct 22 03:50:13 controller node[33528]: Data movement: 256 pgs, 512 pg*osds = 66.67 %
Oct 22 03:50:13 controller node[33528]: Total space (raw): 0.02 TB, space efficiency: 100 %
Oct 22 03:50:13 controller node[33528]: PG configuration successfully changed