You just showed the trace logs from the controller, not the satellite, whereas the satellite is the one executing all interesting external commands
On Tue, Feb 4, 2020 at 9:48 AM Christophe NOUVEL < [email protected]> wrote: > 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 <[email protected]> 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 >> [email protected] >> https://lists.linbit.com/mailman/listinfo/drbd-user >> > -- Best regards, Gabor Hernadi
_______________________________________________ Star us on GITHUB: https://github.com/LINBIT drbd-user mailing list [email protected] https://lists.linbit.com/mailman/listinfo/drbd-user
