Bug 1431376

Summary: "/sys$DEVPATH/device/timeout" does not expand to a path
Product: [Fedora] Fedora Reporter: Harald Reindl <h.reindl>
Component: open-vm-toolsAssignee: Ravindra Kumar <ravindrakumar>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 27CC: bugs, h.reindl, negativo17, ravindrakumar, rjones
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: open-vm-tools-10.2.5-2.fc28 open-vm-tools-10.2.5-2.fc26 open-vm-tools-10.2.5-2.fc27 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-05-12 18:21:03 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Harald Reindl 2017-03-11 20:56:30 UTC Comment hidden (abuse)
Comment 1 Richard W.M. Jones 2017-03-13 16:41:54 UTC
I have no idea what you're talking about.  Could you please describe
the problem you think you are observing.

Comment 2 Harald Reindl 2017-03-13 16:56:30 UTC Comment hidden (abuse)
Comment 3 Richard W.M. Jones 2017-03-13 17:01:02 UTC
Apparently the problem is that /sys$DEVPATH does not expand to
a real path.  The udev rules in the package are:

ACTION=="add", SUBSYSTEMS=="scsi", ATTRS{vendor}=="VMware*" , ATTRS{model}=="Virtual disk*", RUN+="/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'"
ACTION=="add", SUBSYSTEMS=="scsi", ATTRS{vendor}=="VMware*" , ATTRS{model}=="VMware Virtual S", RUN+="/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'"

Comment 4 Harald Reindl 2017-03-13 17:09:55 UTC Comment hidden (abuse)
Comment 5 Ravindra Kumar 2017-04-04 22:25:50 UTC
In my testing on Rawhide, I also see the logs "failed with exit code 1." but /sys/block/sda/device/timeout is getting updated as well. I made it a different value and after reboot it got updated to 180. So, it looks like udev is able to update the timeout as expected.

Harald, could you please confirm if you observed the same behavior?

Comment 6 Harald Reindl 2017-04-06 19:17:50 UTC Comment hidden (abuse)
Comment 7 Richard W.M. Jones 2017-04-06 21:18:29 UTC
(In reply to Harald Reindl from comment #6)
> what about all you guys building package sstart to filter your systemlogs
> and dmesg for the words "error", "fail" and "warn" as i do for a decade?

Ravindra is trying sincerely to help you to fix this bug.  Please
be polite to him.

Comment 8 Harald Reindl 2017-04-06 21:39:38 UTC Comment hidden (abuse)
Comment 9 Ravindra Kumar 2017-04-07 00:15:32 UTC
I'm able to see the error messages on my Fedora installation, but I'm also noticing that udev rules are taking effect. So, I'm wondering if path is the real issue here? If path is the issue then how udev rules are getting applied? I'm trying to understand if you observed the same issue or not.

Comment 10 Ravindra Kumar 2017-04-07 00:18:23 UTC
To be clear, my question is, did you check if /sys/block/sda/device/timeout was updated to the value in the udev rule on your Fedora despite the system error messages?

Comment 11 Harald Reindl 2017-04-07 06:53:03 UTC Comment hidden (abuse)
Comment 12 Harald Reindl 2017-04-07 06:55:33 UTC
another option would be ExecStopPost=/usr/local/bin/disk-timeout.sh in /usr/lib/systemd/system/vmtoolsd.service

Comment 13 Harald Reindl 2017-04-07 06:56:45 UTC
-ExecStopPost
-ExecStartPost

Comment 14 Ravindra Kumar 2017-04-13 00:58:09 UTC
(In reply to Harald Reindl from comment #11)
> looks so
> 
> [root@rawhide ~]# cat /sys/block/sda/device/timeout
> 180

Thanks for the info. So far it seems to be just the log spew.

> probably when you already build a ugly constrcut like "/bin/sh" extend it
> with 2> /dev/null

Thanks for the suggestion. VMware Tools has been using $DEVPATH in udev rules for a very long time without any issues reported by any customers, please see https://kb.vmware.com/kb/1009465. I'm suspecting something has changed in udev or Linux kernel. I'd like to root cause it before applying any fixes.

> but what i don't understand from the very begin is why
> nobody takes notice of such errors in the logiles when write that stuff
> because a reasonable sysadmin is scanning his logs after every reboot for
> "error", "warn" and "fail" which makes it annoying

Sorry for the inconvenience. This was a testing gap on my side. Also, the udev rule comes from open-vm-tools package and we are using it as is in Fedora. When I updated the packages in Fedora I did test that timeout was getting applied, the only thing I did not check was system logs. I will add system logs checking to my testing of the package going forward. I have made a note of your suggestion for future changes.

> anyways, that works without spit errors in logfiles

I think there are benefits of using udev rules over a script. udev rules do not require another service to be maintained and rules are better integrated with udev events. So, I'd like to fix the rule if possible.

Comment 15 Ravindra Kumar 2017-04-18 01:35:34 UTC
Harald, could you please try following rules?

ACTION=="add", SUBSYSTEMS=="scsi", ENV{DEVTYPE}=="disk", ATTRS{vendor}=="VMware*" , ATTRS{model}=="Virtual disk*", RUN+="/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'"
ACTION=="add", SUBSYSTEMS=="scsi", ENV{DEVTYPE}=="disk", ATTRS{vendor}=="VMware*" , ATTRS{model}=="VMware Virtual S", RUN+="/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'"

Comment 16 Fedora End Of Life 2017-11-16 19:00:46 UTC
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '25'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 25 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

Comment 17 Fedora End Of Life 2017-12-12 10:48:46 UTC
Fedora 25 changed to end-of-life (EOL) status on 2017-12-12. Fedora 25 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 18 Harald Reindl 2017-12-12 10:56:34 UTC Comment hidden (abuse)
Comment 19 Patrick Bänziger 2018-03-23 16:40:05 UTC
Hi Ravindra

Made my account here just for this:
At our company we ran into the exact same issue on Ubuntu 16.04.3 (Kernel 4.4.0-116). I tested your suggested changes from Comment 15 and they worked like a charm!

In the end I slightly adjusted it to better match my (Ubuntu) file (instead of ACTION=="add", I used ACTION="add|change").
I was able to easily reproduce the error in the log (starting "parted" was sufficient).

Hope this helps you fix it :) Have a nice day!

(Crossreference to Launchpad bug: https://bugs.launchpad.net/ubuntu/+source/open-vm-tools/+bug/1668244)

Comment 20 Harald Reindl 2018-03-23 16:48:15 UTC
even the vmware tools running on vCenter appliance 6.5 (see below) are showing the same errors but VMware does not seem to read system logs at all otherwise they would notice a ton of error in the vcenter appliance and the fact that every update breaks sendmail config

https://www.reddit.com/r/vmware/comments/7mmh3o/vcenter_server_appliance_65_update_1cd_email/

_________________________________________

[root@vcenter:~]$ cat /usr/local/bin/system-erros.sh
#!/bin/bash
dmesg | grep -i warn
dmesg | grep -i fail
dmesg | grep -i error
cat /var/log/messages | grep -i warn
cat /var/log/messages | grep -i fail
cat /var/log/messages | grep -i error
_________________________________________

[root@vcenter:~]$ system-erros.sh | grep sendmail
2018-03-23T13:42:33.227130+01:00 vcenter sendmail[46836]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:44:22.883122+01:00 vcenter sendmail[47256]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:44:23.178154+01:00 vcenter sendmail[47264]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:50:03.174377+01:00 vcenter sendmail[48857]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:50:27.950703+01:00 vcenter sendmail[48943]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T14:29:43.031145+01:00 vcenter systemd[1]: sendmail.service: Unit entered failed state.
2018-03-23T14:29:43.031465+01:00 vcenter systemd[1]: sendmail.service: Failed with result 'exit-code'.
2018-03-23T14:34:49.233531+01:00 vcenter sendmail[6848]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
_________________________________________

[root@vcenter:~]$ system-erros.sh
2018-03-23T14:28:50.633977+01:00 vcenter cloud-init[850]: 2018-03-23 14:28:50,633 - util.py[WARNING]: Unable to change the ownership of /var/log/cloud-init.log to user syslog, group adm
2018-03-23T14:28:53.055846+01:00 vcenter cloud-init[1030]: 2018-03-23 14:28:52,651 - util.py[WARNING]: Unable to change the ownership of /var/log/cloud-init.log to user syslog, group adm
2018-03-23T14:28:56.189530+01:00 vcenter cloud-init[1170]: 2018-03-23 14:28:56,189 - templater.py[WARNING]: Cheetah not available as the default renderer for unknown template, reverting to the basic renderer.
2018-03-23T14:28:56.190478+01:00 vcenter cloud-init[1170]: 2018-03-23 14:28:56,190 - cc_final_message.py[WARNING]: Used fallback datasource
2018-03-23T13:42:33.227130+01:00 vcenter sendmail[46836]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:44:22.883122+01:00 vcenter sendmail[47256]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:44:23.178154+01:00 vcenter sendmail[47264]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:50:03.174377+01:00 vcenter sendmail[48857]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T13:50:27.950703+01:00 vcenter sendmail[48943]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T14:22:20.659137+01:00 vcenter vami-lighttp[57796]: Error: Failed to open the store.
2018-03-23T14:22:20.659946+01:00 vcenter vami-lighttp[57796]: vecs-cli failed. Error 1021: Cannot connect to vmafd service.
2018-03-23T14:22:20.661925+01:00 vcenter vami-lighttp[57796]: Failed to retrieve certificate from VECS
2018-03-23T14:22:43.221466+01:00 vcenter useradd[57983]: failed adding user 'imagebuilder', data deleted
2018-03-23T14:22:43.222897+01:00 vcenter imagebuilder: failed to add user imagebuilder
2018-03-23T14:22:44.044253+01:00 vcenter useradd[57998]: failed adding user 'netdumper', data deleted
2018-03-23T14:22:44.576376+01:00 vcenter useradd[58040]: failed adding user 'cm', data deleted
2018-03-23T14:22:45.887034+01:00 vcenter useradd[58053]: failed adding user 'deploy', data deleted
2018-03-23T14:28:48.573080+01:00 vcenter systemd-udevd[396]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573086+01:00 vcenter systemd-udevd[397]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573091+01:00 vcenter systemd-udevd[402]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573096+01:00 vcenter systemd-udevd[395]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573100+01:00 vcenter systemd-udevd[394]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573105+01:00 vcenter systemd-udevd[398]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573113+01:00 vcenter systemd-udevd[400]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573119+01:00 vcenter systemd-udevd[399]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573124+01:00 vcenter systemd-udevd[391]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573128+01:00 vcenter systemd-udevd[401]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573133+01:00 vcenter systemd-udevd[403]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573140+01:00 vcenter systemd-udevd[404]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573149+01:00 vcenter systemd-udevd[400]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573154+01:00 vcenter systemd-udevd[398]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573158+01:00 vcenter systemd-udevd[394]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573224+01:00 vcenter systemd-udevd[395]: Process '/bin/sh -c 'echo 180 >/sys$DEVPATH/device/timeout'' failed with exit code 1.
2018-03-23T14:28:48.573798+01:00 vcenter augenrules[813]: failure 1
2018-03-23T14:28:52.510204+01:00 vcenter systemd[1]: xinetd.service: Failed to read PID from file /var/run/xinetd.pid: Invalid argument
2018-03-23T14:29:43.031145+01:00 vcenter systemd[1]: sendmail.service: Unit entered failed state.
2018-03-23T14:29:43.031465+01:00 vcenter systemd[1]: sendmail.service: Failed with result 'exit-code'.
2018-03-23T14:29:51.145183+01:00 vcenter vmware-stsd[1630]: Starting vmware-stsd.  Request for http://localhost:7080/afd failed after 1 seconds. Status: /usr/bin/curl status. Response: 000. Host: .  Request for http://localhost:7080/afd failed after 1 seconds. Status: /usr/bin/curl status. Response: 000. Host: .  Request for http://localhost:7080/afd failed after 1 seconds. Status: /usr/bin/curl status. Response: 000. Host:   Increasing the timeout window to 2 seconds..  Request for http://localhost:7080/afd failed after 2 seconds. Status: /usr/bin/curl status. Response: 000. Host:   Increasing the timeout window to 3 seconds..  Request for http://localhost:7080/afd failed after 3 seconds. Status: /usr/bin/curl status. Response: 000. Host:   Increasing the timeout window to 4 seconds..  Request for http://localhost:7080/afd failed after 4 seconds. Status: /usr/bin/curl status. Response: 000. Host:   Increasing the timeout window to 5 seconds..  Request for http://localhost:7080/afd failed after 5 seconds. Status: /usr/bin/curl status. Response: 000. Host:   Increasing the timeout window to 6 seconds..  Request for http://localhost:7080/afd failed after 6 seconds. Status: /usr/bin/curl status. Response: 000. Host:   Increasing the timeout window to 7 seconds.........done
2018-03-23T14:34:49.233531+01:00 vcenter sendmail[6848]: STARTTLS=client, relay=[10.0.0.15], version=TLSv1.2, verify=FAIL, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256/256
2018-03-23T14:21:57.070483+01:00 vcenter lsassd[1179]: 0x7f0e6614c700:Dropping 0 events after 225907 send attempts due to error 67 while trying to talk to the eventlog.
2018-03-23T14:22:20.659137+01:00 vcenter vami-lighttp[57796]: Error: Failed to open the store.
2018-03-23T14:22:20.659946+01:00 vcenter vami-lighttp[57796]: vecs-cli failed. Error 1021: Cannot connect to vmafd service.
2018-03-23T14:28:48.573244+01:00 vcenter systemd-udevd[396]: error opening ATTR{/sys/devices/system/cpu/cpu0/online} for writing: Permission denied
2018-03-23T14:28:48.573778+01:00 vcenter augenrules[813]: Error sending add rule data request (Rule exists)
2018-03-23T14:28:48.573783+01:00 vcenter augenrules[813]: There was an error in line 91 of /etc/audit/audit.rules
    raise CannotListenError(self.interface, self.port, le)
CannotListenError: Couldn't listen on ::1:8201: [Errno 99] Cannot assign requested address.

Comment 21 Ravindra Kumar 2018-03-27 02:34:40 UTC
It got closed automatically due to EOL status of Fedora 25. Re-opening it because it is not fixed yet.

Thanks Harald and Patrick. A patch for this will be released in next update of open-vm-tools. Unfortunately, a modified version of my proposed changes in #15 was  included in open-vm-tools 10.2.0, but that did not fix it.

Comment 22 Fedora Update System 2018-05-09 20:07:22 UTC
open-vm-tools-10.2.5-2.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-c97904a30a

Comment 23 Fedora Update System 2018-05-09 20:21:13 UTC
open-vm-tools-10.2.5-2.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-7ea12a5bc4

Comment 24 Fedora Update System 2018-05-09 20:22:07 UTC
open-vm-tools-10.2.5-2.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2018-082f8985de

Comment 25 Fedora Update System 2018-05-10 20:01:02 UTC
open-vm-tools-10.2.5-2.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-7ea12a5bc4

Comment 26 Fedora Update System 2018-05-11 00:48:22 UTC
open-vm-tools-10.2.5-2.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-082f8985de

Comment 27 Fedora Update System 2018-05-11 01:59:20 UTC
open-vm-tools-10.2.5-2.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-c97904a30a

Comment 28 Fedora Update System 2018-05-12 18:21:03 UTC
open-vm-tools-10.2.5-2.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.

Comment 29 Fedora Update System 2018-05-13 19:52:36 UTC
open-vm-tools-10.2.5-2.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.

Comment 30 Fedora Update System 2018-05-13 20:17:58 UTC
open-vm-tools-10.2.5-2.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.