[DRBD-user] [proxmox 5.4]Cannot create VM, cannot restore : timeout linstor sp l...

Christophe NOUVEL christophe.nouvel at gmail.com
Tue Feb 4 09:48:20 CET 2020


Ok, tried to trace.

No error so far, but long response time and no visible call to 'vgs', 'lvs'
and so on :



linstor sp l generates following trace :

Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.768 [grizzly-http-server-14]
DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from
'RestClient(127.0.0.1; 'PythonLinstor/1.0.11 (API1.0.4)')'
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.769 [grizzly-http-server-14]
TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(127.0.0.1;
'PythonLinstor/1.0.11 (API1.0.4)'), Background operation 'LstStorPool'
scope 'Fetch thin capacity info' start
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.769 [grizzly-http-server-14]
TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(127.0.0.1;
'PythonLinstor/1.0.11 (API1.0.4)'), Background operation 'LstStorPool'
scope 'Fetch thin capacity info' end
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.769 [grizzly-http-server-14]
TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7070
'RequestThinFreeSpace' send
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.769 [grizzly-http-server-14]
TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7070
'RequestThinFreeSpace' send
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.770 [MainWorkerPool-8] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7070 answer
received (seq 21247)
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.770 [MainWorkerPool-8] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7070 answer
received (seq 21248)
Feb  4 09:37:01 px1 Controller[6784]: 09:37:01.770 [MainWorkerPool-8] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7070 complete
received (seq 21249)
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.471 [grizzly-http-server-15]
DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from
'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.471 [grizzly-http-server-15]
TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin
capacity info' start
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.471 [grizzly-http-server-15]
TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin
capacity info' end
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.471 [grizzly-http-server-15]
TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7071
'RequestThinFreeSpace' send
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.472 [grizzly-http-server-15]
TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7071
'RequestThinFreeSpace' send
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.473 [MainWorkerPool-7] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7071 answer
received (seq 21250)
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.473 [MainWorkerPool-7] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7071 answer
received (seq 21251)
Feb  4 09:37:03 px1 Controller[6784]: 09:37:03.473 [MainWorkerPool-7] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7071 complete
received (seq 21252)
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.039 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7069 answer
received (seq 21249)
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.039 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7069 answer
received (seq 21250)
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.039 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7069 complete
received (seq 21251)
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.039 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble
storage pool list' start
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.040 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble
storage pool list' end
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.189 [grizzly-http-server-0]
DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from
'RestClient(192.168.1.2; 'REST::Client/273')'
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.189 [grizzly-http-server-0]
TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin
capacity info' start
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.189 [grizzly-http-server-0]
TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin
capacity info' end
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.189 [grizzly-http-server-0]
TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7072
'RequestThinFreeSpace' send
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.189 [grizzly-http-server-0]
TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7072
'RequestThinFreeSpace' send
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.190 [MainWorkerPool-6] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7072 answer
received (seq 21253)
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.190 [MainWorkerPool-6] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7072 answer
received (seq 21254)
Feb  4 09:37:05 px1 Controller[6784]: 09:37:05.190 [MainWorkerPool-6] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 7072 complete
received (seq 21255)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.486 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7070 answer
received (seq 21252)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.486 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7070 answer
received (seq 21253)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.486 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7070 complete
received (seq 21254)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.486 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer RestClient(127.0.0.1;
'PythonLinstor/1.0.11 (API1.0.4)'), Background operation 'LstStorPool'
scope 'Assemble storage pool list' start
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.487 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer RestClient(127.0.0.1;
'PythonLinstor/1.0.11 (API1.0.4)'), Background operation 'LstStorPool'
scope 'Assemble storage pool list' end
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.494 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7071 answer
received (seq 21255)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.494 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7071 answer
received (seq 21256)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.494 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 7071 complete
received (seq 21257)
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.494 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble
storage pool list' start
Feb  4 09:37:13 px1 Controller[6784]: 09:37:13.494 [MainWorkerPool-2] TRACE
LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1;
'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble
storage pool list' end

About 13 seconds.

Extract of /var/log/linstor-controller/rest-access.log :
localhost.localdomain - - [2020/Feb/04:09:37:01 +0100] "GET
/v1/controller/version HTTP/1.1" 200 142 "" ""
localhost.localdomain - - [2020/Feb/04:09:37:01 +0100] "GET
/v1/controller/version HTTP/1.1" 200 142 "" "PythonLinstor/1.0.11
(API1.0.4)"
192.168.1.1 - - [2020/Feb/04:09:36:43 +0100] "GET /v1/view/storage-pools
HTTP/1.1" 200 1471 "" "REST::Client/273"
192.168.1.2 - - [2020/Feb/04:09:36:55 +0100] "GET /v1/view/storage-pools
HTTP/1.1" 200 1471 "" "REST::Client/273"
localhost.localdomain - - [2020/Feb/04:09:37:01 +0100] "GET
/v1/view/storage-pools HTTP/1.1" 200 - "" "PythonLinstor/1.0.11 (API1.0.4)"
192.168.1.1 - - [2020/Feb/04:09:37:03 +0100] "GET /v1/view/storage-pools
HTTP/1.1" 200 1471 "" "REST::Client/273"
192.168.1.2 - - [2020/Feb/04:09:37:05 +0100] "GET /v1/view/storage-pools
HTTP/1.1" 200 1471 "" "REST::Client/273"
192.168.1.1 - - [2020/Feb/04:09:37:15 +0100] "GET /v1/view/storage-pools
HTTP/1.1" 200 1471 "" "REST::Client/273"
192.168.1.2 - - [2020/Feb/04:09:37:20 +0100] "GET /v1/view/storage-pools
HTTP/1.1" 200 1471 "" "REST::Client/273"


And VM creation fails :
TASK ERROR: unable to create VM 999 - error with cfs lock
'storage-drbdstorage': Could not autoplace resource vm-999-disk-1, because:
[{"ret_code":20185089,"message":"Resource 'vm-999-disk-1' successfully
autoplaced on 2 nodes","details":"Used storage pool: 'drbdpool'\nUsed
nodes: 'px1-administration',
'px2-administration'","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":-9223372036834589707,"message":"Could
not find suitable node to automatically create a tie breaking resource for
'vm-999-disk-1'.","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":20185091,"message":"Created
resource 'vm-999-disk-1' on
'px1-administration'","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":20185091,"message":"Created
resource 'vm-999-disk-1' on
'px2-administration'","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":20185089,"message":"Resource
'vm-999-disk-1' on 'px2-administration' ready","details":"Auto-placing
resource:
vm-999-disk-1","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":-4611686018407201818,"message":"Deployed
resource did not appear","details":"Auto-placing resource:
vm-999-disk-1","obj_refs":{"RscDfn":"vm-999-disk-1"}}] at
/usr/share/perl5/PVE/Storage/Custom/LINSTORPlugin.pm line 285.
PVE::Storage::Custom::LINSTORPlugin::alloc_image("PVE::Storage::Custom::LINSTORPlugin",
"drbdstorage", HASH(0x559ccda2eae0), 999, "raw", undef, 1048576) called at
/usr/share/perl5/PVE/Storage.pm line 738 eval {...} called at
/usr/share/perl5/PVE/Storage.pm line 738 PVE::Storage::__ANON__() called at
/usr/share/perl5/PVE/Cluster.pm line 915 eval {...} called at
/usr/share/perl5/PVE/Cluster.pm line 883
PVE::Cluster::__ANON__("storage-drbdstorage", undef, CODE(0x559ccda23250))
called at /usr/share/perl5/PVE/Cluster.pm line 954
PVE::Cluster::cfs_lock_storage("drbdstorage", undef, CODE(0x559ccda23250))
called at /usr/share/perl5/PVE/Storage/Plugin.pm line 390
PVE::Storage::Plugin::cluster_lock_storage("PVE::Storage::Custom::LINSTORPlugin",
"drbdstorage", 1, undef, CODE(0x559ccda23250)) called at
/usr/share/perl5/PVE/Storage.pm line 743
PVE::Storage::vdisk_alloc(HASH(0x559ccda2ef18), "drbdstorage", 999, "raw",
undef, 1048576) called at /usr/share/perl5/PVE/API2/Qemu.pm line 181
PVE::API2::Qemu::__ANON__("scsi0", HASH(0x559cc73adad8)) called at
/usr/share/perl5/PVE/QemuServer.pm line 3288
PVE::QemuServer::foreach_drive(HASH(0x559ccd178788), CODE(0x559ccd9a8b70))
called at /usr/share/perl5/PVE/API2/Qemu.pm line 216 eval {...} called at
/usr/share/perl5/PVE/API2/Qemu.pm line 216
PVE::API2::Qemu::__ANON__(PVE::RPCEnvironment=HASH(0x559cc73adf88),
"root\@pam", HASH(0x559ccd178788), "x86_64", HASH(0x559ccda2ef18), 999,
undef, HASH(0x559ccd178788), ...) called at
/usr/share/perl5/PVE/API2/Qemu.pm line 604 eval {...} called at
/usr/share/perl5/PVE/API2/Qemu.pm line 602 PVE::API2::Qemu::__ANON__()
called at /usr/share/perl5/PVE/Tools.pm line 203 eval {...} called at
/usr/share/perl5/PVE/Tools.pm line 203
PVE::Tools::lock_file_full("/var/lock/qemu-server/lock-999.conf", 1, 0,
CODE(0x559cc73ad4c0)) called at /usr/share/perl5/PVE/Tools.pm line 212
PVE::Tools::lock_file("/var/lock/qemu-server/lock-999.conf", 1,
CODE(0x559cc73ad4c0)) called at /usr/share/perl5/PVE/AbstractConfig.pm line
78 PVE::AbstractConfig::lock_config_full("PVE::QemuConfig", 999, 1,
CODE(0x559cc73ad4c0)) called at /usr/share/perl5/PVE/API2/Qemu.pm line 636
PVE::API2::Qemu::__ANON__() called at /usr/share/perl5/PVE/API2/Qemu.pm
line 659 eval {...} called at /usr/share/perl5/PVE/API2/Qemu.pm line 659
PVE::API2::Qemu::__ANON__("UPID:px1-administration:00007D8A:005B8802:5E392A60:qmcreate:9"...)
called at /usr/share/perl5/PVE/RESTEnvironment.pm line 610 eval {...}
called at /usr/share/perl5/PVE/RESTEnvironment.pm line 601
PVE::RESTEnvironment::fork_worker(PVE::RPCEnvironment=HASH(0x559cc73adf88),
"qmcreate", 999, "root\@pam", CODE(0x559ccda32b88)) called at
/usr/share/perl5/PVE/API2/Qemu.pm line 671
PVE::API2::Qemu::__ANON__(HASH(0x559ccd178788)) called at
/usr/share/perl5/PVE/RESTHandler.pm line 446
PVE::RESTHandler::handle("PVE::API2::Qemu", HASH(0x559ccae42c38),
HASH(0x559ccd178788)) called at /usr/share/perl5/PVE/HTTPServer.pm line 167
eval {...} called at /usr/share/perl5/PVE/HTTPServer.pm line 133
PVE::HTTPServer::rest_handler(PVE::HTTPServer=HASH(0x559ccd9a9860),
"10.31.39.192", "POST", "/nodes/px1-administration/qemu",
HASH(0x559ccd9f6dc8), HASH(0x559ccda3ce50), "extjs") called at
/usr/share/perl5/PVE/APIServer/AnyEvent.pm line 712 eval {...} called at
/usr/share/perl5/PVE/APIServer/AnyEvent.pm line 686
PVE::APIServer::AnyEvent::handle_api2_request(PVE::HTTPServer=HASH(0x559ccd9a9860),
HASH(0x559ccda45600), HASH(0x559ccd9f6dc8), "POST",
"/api2/extjs/nodes/px1-administration/qemu") called at
/usr/share/perl5/PVE/APIServer/AnyEvent.pm line 939 eval {...} called at
/usr/share/perl5/PVE/APIServer/AnyEvent.pm line 931
PVE::APIServer::AnyEvent::handle_request(PVE::HTTPServer=HASH(0x559ccd9a9860),
HASH(0x559ccda45600), HASH(0x559ccd9f6dc8), "POST",
"/api2/extjs/nodes/px1-administration/qemu") called at
/usr/share/perl5/PVE/APIServer/AnyEvent.pm line 1325
PVE::APIServer::AnyEvent::__ANON__(AnyEvent::Handle=HASH(0x559ccda3b460),
"sockets=1\x{26}numa=0\x{26}vmid=999\x{26}name=Test-lenteur-Linstor\x{26}agent=1\x{26}s"...)
called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Handle.pm line 1522
AnyEvent::Handle::__ANON__(AnyEvent::Handle=HASH(0x559ccda3b460)) called at
/usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Handle.pm line 1332
AnyEvent::Handle::_drain_rbuf(AnyEvent::Handle=HASH(0x559ccda3b460)) called
at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Handle.pm line 2032
AnyEvent::Handle::__ANON__(EV::IO=SCALAR(0x559ccda43678), 1) called at
/usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Impl/EV.pm line 88 eval {...}
called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Impl/EV.pm line 88
AnyEvent::CondVar::Base::_wait(AnyEvent::CondVar=HASH(0x559ccd177f18))
called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent.pm line 2026
AnyEvent::CondVar::Base::recv(AnyEvent::CondVar=HASH(0x559ccd177f18))
called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 1612
PVE::APIServer::AnyEvent::run(PVE::HTTPServer=HASH(0x559ccd9a9860)) called
at /usr/share/perl5/PVE/Service/pvedaemon.pm line 52
PVE::Service::pvedaemon::run(PVE::Service::pvedaemon=HASH(0x559cc73bb4d8))
called at /usr/share/perl5/PVE/Daemon.pm line 171 eval {...} called at
/usr/share/perl5/PVE/Daemon.pm line 171
PVE::Daemon::__ANON__(PVE::Service::pvedaemon=HASH(0x559cc73bb4d8)) called
at /usr/share/perl5/PVE/Daemon.pm line 391 eval {...} called at
/usr/share/perl5/PVE/Daemon.pm line 380
PVE::Daemon::__ANON__(PVE::Service::pvedaemon=HASH(0x559cc73bb4d8), undef)
called at /usr/share/perl5/PVE/Daemon.pm line 552 eval {...} called at
/usr/share/perl5/PVE/Daemon.pm line 550
PVE::Daemon::start(PVE::Service::pvedaemon=HASH(0x559cc73bb4d8), undef)
called at /usr/share/perl5/PVE/Daemon.pm line 661
PVE::Daemon::__ANON__(HASH(0x559cc73a1410)) called at
/usr/share/perl5/PVE/RESTHandler.pm line 446
PVE::RESTHandler::handle("PVE::Service::pvedaemon", HASH(0x559cc73bb7f0),
HASH(0x559cc73a1410)) called at /usr/share/perl5/PVE/RESTHandler.pm line
855 eval {...} called at /usr/share/perl5/PVE/RESTHandler.pm line 838
PVE::RESTHandler::cli_handler("PVE::Service::pvedaemon", "pvedaemon start",
"start", ARRAY(0x559cc7660518), ARRAY(0x559cc73bbe68), undef, undef, undef)
called at /usr/share/perl5/PVE/CLIHandler.pm line 580
PVE::CLIHandler::__ANON__(ARRAY(0x559cc73a1638), CODE(0x559cc76212d8),
undef) called at /usr/share/perl5/PVE/CLIHandler.pm line 657
PVE::CLIHandler::run_cli_handler("PVE::Service::pvedaemon", "prepare",
CODE(0x559cc76212d8)) called at /usr/bin/pvedaemon line 27

DRBD resource is correctely created, and synced. drbdtop is ok.
But Proxmox does not finishes VM creation without any Linstor error
report...

Christophe.

Le lun. 3 févr. 2020 à 15:10, Gábor Hernádi <gabor.hernadi at linbit.com> a
écrit :

>
> In that case you might want to increase the log level on the satellite to
> TRACE by adding
>
> [logging]
>    level="TRACE"
>
> to the linstor_satellite.toml file
>
> With trace logging you should see every external command (lvs, vgs,
> lvcreate, ...) linstor executes as well as the time linstor spent waiting
> for the external command to finish.
>
> This might give you more insight about what is taking so long
>
> --
> Best regards,
> Gabor Hernadi
> _______________________________________________
> Star us on GITHUB: https://github.com/LINBIT
> drbd-user mailing list
> drbd-user at lists.linbit.com
> https://lists.linbit.com/mailman/listinfo/drbd-user
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linbit.com/pipermail/drbd-user/attachments/20200204/6e8f31df/attachment-0001.htm>


More information about the drbd-user mailing list