Description of problem: We figured out that hypervkvpd dies from time to time with "KVP: Failed to open file, pool: 1" at our customers. Unfortunately the paid Red Hat support was not helpful so far (mentioning that hypervkvpd would be unsupported 3rd party software and queries for core dumps - while the service seems to exit somehow "regulary" instead of really crashing). Version-Release number of selected component (if applicable): hypervkvpd-0-0.7.el5 How reproducible: Everytime, just run hypervkvpd on fully up-to-date RHEL 5 which is a Hyper-V virtual machine on Microsoft Windows Server 2008 R2 for example. Actual results: hypervkvpd dies from time to time with "KVP: Failed to open file, pool: 1". Expected results: Running hypervkvpd daemon all the time.
Case 00812951 is the cross reference in the Red Hat customer portal.
Upstream developers were quite much more responsive and thus did strace(1): [...] fcntl(5, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0 open("/var/opt/hyperv/.kvp_pool_1", O_RDONLY) = -1 EMFILE (Too many open files) fcntl(5, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 sendto(3, "<11>Apr 6 12:15:43 KVP: Failed to open file, pool: 1", 53, MSG_NOSIGNAL, NULL, 0) = 53
Upstream recommendation was something like this, however O_CLOEXEC does not seem to be available on RHEL 5, because it fails simply building with "error: 'O_CLOEXEC' undeclared (first use in this function)". And a grep(1) through /usr/include did not bring any result, while it does e.g. on RHEL 6 here... --- snipp --- --- hv_kvp_daemon.c 2012-09-13 12:29:33.000000000 +0200 +++ hv_kvp_daemon.c.o_cloexec 2013-04-08 19:19:50.034311080 +0200 @@ -134,7 +134,7 @@ */ kvp_acquire_lock(pool); - filep = fopen(kvp_file_info[pool].fname, "w"); + filep = fopen(kvp_file_info[pool].fname, "we"); if (!filep) { kvp_release_lock(pool); syslog(LOG_ERR, "Failed to open file, pool: %d", pool); @@ -160,7 +160,7 @@ kvp_acquire_lock(pool); - filep = fopen(kvp_file_info[pool].fname, "r"); + filep = fopen(kvp_file_info[pool].fname, "re"); if (!filep) { kvp_release_lock(pool); syslog(LOG_ERR, "Failed to open file, pool: %d", pool); @@ -218,13 +218,13 @@ records_read = 0; num_blocks = 1; sprintf(fname, "/var/opt/hyperv/.kvp_pool_%d", i); - fd = open(fname, O_RDWR | O_CREAT, S_IRUSR | S_IWUSR | S_IROTH); + fd = open(fname, O_RDWR | O_CREAT | O_CLOEXEC, S_IRUSR | S_IWUSR | S_IROTH); if (fd == -1) return 1; - filep = fopen(fname, "r"); + filep = fopen(fname, "re"); if (!filep) return 1; --- snapp ---
Upstream as in K. Y. Srinivasan from Microsoft.
As per upstream recommendation, we are right now testing the following: --- snipp --- --- hv_kvp_daemon.c 2012-09-13 12:29:33.000000000 +0200 +++ hv_kvp_daemon.c.o_cloexec 2013-04-08 20:14:30.178518793 +0200 @@ -43,6 +43,10 @@ #include <sys/stat.h> #include <fcntl.h> +#ifndef O_CLOEXEC +#define O_CLOEXEC 02000000 /* set close_on_exec */ +#endif + /* * KVP protocol: The user mode component first registers with the * the kernel component. Subsequently, the kernel component requests, data @@ -134,7 +138,7 @@ */ kvp_acquire_lock(pool); - filep = fopen(kvp_file_info[pool].fname, "w"); + filep = fopen(kvp_file_info[pool].fname, "we"); if (!filep) { kvp_release_lock(pool); syslog(LOG_ERR, "Failed to open file, pool: %d", pool); @@ -160,7 +164,7 @@ kvp_acquire_lock(pool); - filep = fopen(kvp_file_info[pool].fname, "r"); + filep = fopen(kvp_file_info[pool].fname, "re"); if (!filep) { kvp_release_lock(pool); syslog(LOG_ERR, "Failed to open file, pool: %d", pool); @@ -218,13 +222,13 @@ records_read = 0; num_blocks = 1; sprintf(fname, "/var/opt/hyperv/.kvp_pool_%d", i); - fd = open(fname, O_RDWR | O_CREAT, S_IRUSR | S_IWUSR | S_IROTH); + fd = open(fname, O_RDWR | O_CREAT | O_CLOEXEC, S_IRUSR | S_IWUSR | S_IROTH); if (fd == -1) return 1; - filep = fopen(fname, "r"); + filep = fopen(fname, "re"); if (!filep) return 1; --- snapp ---
Hi Robert. I will have look at this issue and let you know how it can be possibly fixed. Regards, Tomas
Hi Robert. I'm trying to reproduce the hypervkvpd behaviour on RHEL-5.9 but with no luck so far. Do you use any specific system settings? Can you please add some more detailed steps to reproduce your issue? When I install hypervkvpd on RHEL-5.9 Guest running on Windows Server with Hyper-V hypervkvpd works just fine. I also tried to restart the daemon for couple of thousands time, but it worked, too. Have you already tested the solution from comment #5?
I think I know what is the problem here. I think O_CLOEXEC will not help and it makes no sense to me why it should at all. hypervkvpd packed in RHEL-5 is very early version of the daemon and we fixed a lot of bug since then. And there is one particular problem that can be causing this and I'm more than convinced that it is. In shipped hypervkvpd daemon there is a Resource Leak of file descriptor in function kvp_update_mem_state(). The pool file is opened on line 163 but is never closed. Having enough time and enough requests from the Host it can lead to exhaustion of file descriptors. So the fix should be just to close the file descriptor in the end of function. Can you please also check number of opened file descriptors by hypervkvpd (hv_kvp_daemon) using 'lsof' after some time? If it is increasing then it is for sure the file descriptor issue. Thank you.
Created attachment 733717 [details] Patch for the file descriptor leak
$ lsof | grep hv_kvp_da | tail hv_kvp_da 18040 root 909r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 910r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 911r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 912r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 913r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 914r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 915r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 916r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 917r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 18040 root 918r REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 $ $ lsof | grep -c hv_kvp_da 927 $ Something like two minutes later: $ lsof | grep -c hv_kvp_da 934 $ Something like another minute later: $ lsof | grep -c hv_kvp_da 934 $ Is it possible that the O_CLOEXEC patch solves the issue somehow half? I might be wrong, but this time number of leaked file descriptors leaked a bit slower than without (max. 24 hours without the patch, nearly 48 hours with the patch).
$ lsof | grep -c hv_kvp_da 937 $ So it's still increasing. Shall I test the patch? Do you think O_CLOEXEC has at least some influence or are the different times not related to that?
Let me clarify: Patch mentioned in comment #10 and #11 refer to comment #5. I would test the patch from comment #9 / attachment #733717 [details] tomorrow or so.
(In reply to comment #11) > So it's still increasing. Shall I test the patch? Do you think O_CLOEXEC has > at least some influence or are the different times not related to that? It should have no influence at all, because the daemon does not forks itself. O_CLOEXEC should just ensure that when you open some file(s), then fork() and call exec() those previously opened file descriptors are closed on exec() and not leaked if the child does not close them. The difference in time might be caused by different amount of requests from the Windows Server Host. Please test my attached patch. I think it will solve this issue. As we can see from your comment #10 the file descriptor is obviously leaking.
Okay, your patch has been applied and the daemon runs so far for 10+ hours with about 18 open files (lsof | grep -c hv_kvp_da). Let's wait till tonight at least just to be sure to see how or if the number increases. Anyway...how fast would we get your patch into RHEL 5.9? The support guys cry about the time of life-cycle and RHEL 5.10 while I expect this very soon (if this patch is the solution). Can you figure out meanwhile if a regular bug-fix update will be possible before RHEL 5.10? This affects at least two of our customers.
Robert, I understand this is problem and hyperkvpd package is pretty new - for RHEL-5.9 there is no chance without communication with our support. As you probably know, bugzilla is not a support tool - it is engineering bug tracking tool. That being said, this bug tracking system is not a mechanism for requesting support, and we are not able to guarantee the timeliness or suitability of a resolution. If this issue is critical or in any way time sensitive, please raise a ticket through your regular Red Hat support channels to make certain it receives the proper attention and prioritization to assure a timely resolution. For information on how to contact the Red Hat production support team, please visit: https://www.redhat.com/support/process/production/#howto We are now in production phase 2 and all the fixes/updates are driven by the support requests or internal needs. TBH without pushing through right channels, chances for fix in RHEL-5 is low...
(In reply to comment #14) > Okay, your patch has been applied and the daemon runs so far for 10+ hours > with about 18 open files (lsof | grep -c hv_kvp_da). Let's wait till tonight > at least just to be sure to see how or if the number increases. Great, but 18 seems to me too much anyway. But we'll see after some time. > Anyway...how fast would we get your patch into RHEL 5.9? The support guys > cry about the time of life-cycle and RHEL 5.10 while I expect this very soon > (if this patch is the solution). Can you figure out meanwhile if a regular > bug-fix update will be possible before RHEL 5.10? This affects at least two > of our customers. As Ondrej said in comment #15 the best thing you can do is to try escalate your ticket through customer portal. I'm sorry but I'm not the person making decisions what will get updated.
(In reply to comment #16) > Great, but 18 seems to me too much anyway. But we'll see after some time. $ lsof | grep hv_kvp_da hv_kvp_da 2571 root cwd DIR 8,1 4096 6782977 /root hv_kvp_da 2571 root rtd DIR 8,1 4096 2 / hv_kvp_da 2571 root txt REG 8,1 15136 7014932 /usr/sbin/hv_kvp_daemon hv_kvp_da 2571 root mem REG 8,1 144776 1966263 /lib64/ld-2.5.so hv_kvp_da 2571 root mem REG 8,1 1726320 1966283 /lib64/libc-2.5.so hv_kvp_da 2571 root mem REG 8,1 92816 1966394 /lib64/libresolv-2.5.so hv_kvp_da 2571 root mem REG 8,1 53880 1966258 /lib64/libnss_files-2.5.so hv_kvp_da 2571 root mem REG 8,1 27832 1966256 /lib64/libnss_dns-2.5.so hv_kvp_da 2571 root 0u CHR 1,3 0t0 1588 /dev/null hv_kvp_da 2571 root 1u CHR 1,3 0t0 1588 /dev/null hv_kvp_da 2571 root 2u CHR 1,3 0t0 1588 /dev/null hv_kvp_da 2571 root 3u unix 0xffff8102ab820140 0t0 36859431 socket hv_kvp_da 2571 root 4u REG 8,1 0 6881283 /var/opt/hyperv/.kvp_pool_0 hv_kvp_da 2571 root 5u REG 8,1 0 6881284 /var/opt/hyperv/.kvp_pool_1 hv_kvp_da 2571 root 6u REG 8,1 0 6881285 /var/opt/hyperv/.kvp_pool_2 hv_kvp_da 2571 root 7u REG 8,1 7680 6881286 /var/opt/hyperv/.kvp_pool_3 hv_kvp_da 2571 root 8u REG 8,1 0 6881287 /var/opt/hyperv/.kvp_pool_4 hv_kvp_da 2571 root 9u sock 0,5 0t0 36859432 can't identify protocol $ So the real number of open files is less, but grep(1) returns also the other lines. Ondrej, I already was in touch with your colleagues from the support team via case #00812951 before I opened this RHBZ. Due to the IMHO not so professional handling of that ticket, I simply contacted upstream and asked them for hints or suggestions. Thanks to them, I got more closer to the issue and also opened up this RHBZ. Thus you can simply treat this RHBZ existence only due to my desperation with the Red Hat support team. The job that has been done by the upstream guys would have purely been the job of the paid Red Hat support team! You can believe me, I will still kick the support guys a lot.
(In reply to comment #17) > (In reply to comment #16) > > Great, but 18 seems to me too much anyway. But we'll see after some time. > > $ lsof | grep hv_kvp_da > hv_kvp_da 2571 root cwd DIR 8,1 4096 > 6782977 /root > hv_kvp_da 2571 root rtd DIR 8,1 4096 > 2 / > hv_kvp_da 2571 root txt REG 8,1 15136 > 7014932 /usr/sbin/hv_kvp_daemon > hv_kvp_da 2571 root mem REG 8,1 144776 > 1966263 /lib64/ld-2.5.so > hv_kvp_da 2571 root mem REG 8,1 1726320 > 1966283 /lib64/libc-2.5.so > hv_kvp_da 2571 root mem REG 8,1 92816 > 1966394 /lib64/libresolv-2.5.so > hv_kvp_da 2571 root mem REG 8,1 53880 > 1966258 /lib64/libnss_files-2.5.so > hv_kvp_da 2571 root mem REG 8,1 27832 > 1966256 /lib64/libnss_dns-2.5.so > hv_kvp_da 2571 root 0u CHR 1,3 0t0 > 1588 /dev/null > hv_kvp_da 2571 root 1u CHR 1,3 0t0 > 1588 /dev/null > hv_kvp_da 2571 root 2u CHR 1,3 0t0 > 1588 /dev/null > hv_kvp_da 2571 root 3u unix 0xffff8102ab820140 0t0 > 36859431 socket > hv_kvp_da 2571 root 4u REG 8,1 0 > 6881283 /var/opt/hyperv/.kvp_pool_0 > hv_kvp_da 2571 root 5u REG 8,1 0 > 6881284 /var/opt/hyperv/.kvp_pool_1 > hv_kvp_da 2571 root 6u REG 8,1 0 > 6881285 /var/opt/hyperv/.kvp_pool_2 > hv_kvp_da 2571 root 7u REG 8,1 7680 > 6881286 /var/opt/hyperv/.kvp_pool_3 > hv_kvp_da 2571 root 8u REG 8,1 0 > 6881287 /var/opt/hyperv/.kvp_pool_4 > hv_kvp_da 2571 root 9u sock 0,5 0t0 > 36859432 can't identify protocol > $ > > So the real number of open files is less, but grep(1) returns also the other > lines. This looks good. Please let me know how it looks after day or two, but I think the patch is solving this issue. After that I will change status of this Bugzilla so it reflects we have a working solution. Thanks!
We are running the patched daemon now for about 24 hours and the output is still the same like in comment #17. If it's still fine in another 24 hours, I would treat this as the working solution. I'll let you know.
Okay...more than 24 hours later: $ lsof | grep -c hv_kvp 18 $ So yes, comment #9 / attachment #733717 [details] definately solves the issue. Thank you!
Cross-filed case 00820052 in the Red Hat customer portal for another customer.
Just to have it publically documented: On a less frequently via KVP asked virtual machine this takes about a week until the issue gets visible if the daemon is unpatched. That's what we at least see at another machine here...
I'm glad to hear that the fix works. Thank you Robert for your feedback.
Hi, Tomas, I think there is another file descriptor issue existed, just like the below scenario i described: When you reboot a guest rhel5.9 with the up-to-date, when the guest boot up, check the hypervkvpd file descriptor status by `lsmod|grep hv_kvp_da`, there will be file descriptor issue of "pool_3",output like the attachment "pool_3_issue.txt"display. NOTE:I have confirmed with you about the issue, to comment this to record the issue.
Created attachment 738925 [details] pool_3_issue
(In reply to comment #29) > Hi, Tomas, > > I think there is another file descriptor issue existed, just like the > below scenario i described: > > When you reboot a guest rhel5.9 with the up-to-date, when the guest boot > up, check the hypervkvpd file descriptor status by `lsmod|grep hv_kvp_da`, > there will be file descriptor issue of "pool_3",output like the attachment > "pool_3_issue.txt"display. > > > > NOTE:I have confirmed with you about the issue, to comment this to record > the issue. Yes, thank you for catching this issue. I checked the source with Coverity and there was one more file descriptor leak in another function. It is the last one that can result in situation when the daemon doesn't close opened file descriptor and keeps running. I will update the patch to fix also the second leak. NOTE: The new patch has been already tested by Bian Jinwei and confirmed it works.
Created attachment 738930 [details] Patch for the file descriptor leak Patch with fix for another file descriptor leak.