search

jcnelson / vdev

A device-file manager for *nix
GNU General Public License v3.0
101 stars 13 forks source link

Users log at warn level #94

Closed suedi closed 8 years ago

suedi commented 8 years ago

A kind user sent me logs for vdev at the warn level. Remember I cannot meself reproduce these and don't know if user is willing to debug further but they may be of use?

Log

01908:00007FE11E996700: [          vdev.c:0395] vdev_error_thread_main: ERROR: [helpers] [WARN]: Could not find pvs in /sbin/pvs.  LVM physical volume symlinks in /dev/disk/by-id will not be created.
01908:00007FE11E195700: [        action.c:1281] vdev_action_daemonlet_send_command: ERROR: vdev_action_daemonlet_read_int64('/etc/vdev/actions/disk.act') rc = -11
01908:00007FE11E195700: [        action.c:1341] vdev_action_run_daemonlet: ERROR: vdev_action_daemonlet_send_command('/etc/vdev/actions/disk.act') rc = -1
01908:00007FE11E195700: [        action.c:1707] vdev_action_run_commands: ERROR: vdev_action_run_daemonlet('/usr/lib/vdev/disk.sh') rc = -1
01908:00007FE11E195700: [        device.c:0977] vdev_device_add: ERROR: vdev_action_run_commands(ADD sr0, dev=(11, 0)) rc = -1
01908:00007FE11E996700: [          vdev.c:0395] vdev_error_thread_main: ERROR: /usr/lib/vdev/disk.sh: line 328: VDEV_ATA_SERIAL_SHORT: unbound variable
01908:00007FE11E195700: [        action.c:1243] vdev_action_daemonlet_send_command: ERROR: vdev_write_uninterrupted(27) to daemonlet '/etc/vdev/actions/disk.act' rc = -32
01908:00007FE11E195700: [        action.c:1341] vdev_action_run_daemonlet: ERROR: vdev_action_daemonlet_send_command('/etc/vdev/actions/disk.act') rc = -11

The VDEV_ATA_SERIAL_SHORT: unbound variable could possibly mean that ATA_SERIAL_SHORT contains special characters?

jcnelson commented 8 years ago

Hi @suedi,

Thanks for letting me know. I fixed something related to this a couple commits back (31c34ed45275c54026781c71486d8a6d620964ee), that forces all stat_* tools to single-quote the values of the variables they emit. Do you know if the user was running from this commit? If not, then I think you're right--the bug is probably due to an unescaped special character that prevents proper evaluation.

I pushed a more immediate fix that explicitly sets VDEV_ATA_SERIAL_SHORT to an empty string before trying to use it (4883e6dc8a5aad8a226587010c65c3729c9e1e99).

Thanks!

suedi commented 8 years ago

I compiled that vdev with a fresh clone on Feb 2 so yes that fix should be included.

I have sent the user your updated disk.sh and await what it yields

Here is the users log at debug level https://www.dropbox.com/s/f567c65qsn3dhuq/vdevd_aou1.log?dl=1

posting two interesting sections, These seem to be the source of most of the ERROR's

  1. (these lines come after each other in vdevd.log i.e I only added blanklines)
24029:00007FE6F1697700: [        action.c:1228] vdev_action_daemonlet_send_command: DEBUG: run daemonlet (async=0): '/etc/vdev/actions/disk.act'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MOUNTPOINT=/mnt/live/tmp/dev'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_ACTION=add'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_PATH=sr0'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_METADATA=/mnt/live/tmp/dev/metadata//dev/sr0'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_GLOBAL_METADATA=/mnt/live/tmp/dev/metadata/'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_CONFIG_FILE=/tmp/vdevconf.tmp'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MAJOR=11'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MINOR=0'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MODE=block'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_HELPERS=/usr/lib/vdev'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_LOGFILE=/tmp/vdevd.log'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_INSTANCE=KO2M0L6P87M135848952841287O78521K49M962729OMO0P2983184ML016L14N8'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_DAEMONLET=1'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_LOGLEVEL=debug'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVNAME=sr0'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVPATH=/devices/pci0000:00/0000:00:1f.2/ata4/host3/target3:0:0/3:0:0:0/block/sr0'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVTYPE=disk'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_SUBSYSTEM=block'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_SYSFS_MOUNTPOINT=/sys'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_VAR_DISK_GROUP=disk'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_VAR_DISK_MODE=0660'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_VAR_DISK_OWNER=root'
24029:00007FE6F1697700: [        action.c:1281] vdev_action_daemonlet_send_command: ERROR: vdev_action_daemonlet_read_int64('/etc/vdev/actions/disk.act') rc = -11
24029:00007FE6F1697700: [        action.c:1341] vdev_action_run_daemonlet: ERROR: vdev_action_daemonlet_send_command('/etc/vdev/actions/disk.act') rc = -1
24029:00007FE6F1697700: [        action.c:1707] vdev_action_run_commands: ERROR: vdev_action_run_daemonlet('/usr/lib/vdev/disk.sh') rc = -1
24029:00007FE6F1697700: [        device.c:0977] vdev_device_add: ERROR: vdev_action_run_commands(ADD sr0, dev=(11, 0)) rc = -1
24029:00007FE6F1697700: [        device.c:0863] vdev_device_add: DEBUG: ADD device: type 'unknown' at 'UNKNOWN' ('UNKNOWN' 0:0)

24029:00007FE6F1697700: [        action.c:1228] vdev_action_daemonlet_send_command: DEBUG: run daemonlet (async=0): '/etc/vdev/actions/hwdb.act'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MOUNTPOINT=/mnt/live/tmp/dev'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_ACTION=add'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_PATH=UNKNOWN'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_METADATA=/mnt/live/tmp/dev/metadata//dev/UNKNOWN'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_GLOBAL_METADATA=/mnt/live/tmp/dev/metadata/'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_CONFIG_FILE=/tmp/vdevconf.tmp'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_HELPERS=/usr/lib/vdev'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_LOGFILE=/tmp/vdevd.log'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_INSTANCE=KO2M0L6P87M135848952841287O78521K49M962729OMO0P2983184ML016L14N8'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_DAEMONLET=1'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_LOGLEVEL=debug'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVPATH=/devices/pci0000:00/0000:00:1f.2/ata3/host2'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVTYPE=scsi_host'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_SUBSYSTEM=scsi'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_SYSFS_MOUNTPOINT=/sys'
24029:00007FE6F1E98700: [          vdev.c:0395] vdev_error_thread_main: ERROR: /usr/lib/vdev/disk.sh: line 328: VDEV_ATA_SERIAL_SHORT: unbound variable
24029:00007FE6F1697700: [        action.c:1386] vdev_action_run_daemonlet: DEBUG: daemonlet '/etc/vdev/actions/hwdb.act' returned 0
24029:00007FE6F1697700: [        action.c:1733] vdev_action_run_commands: DEBUG: Benchmark: action /etc/vdev/actions/hwdb.act succeeded in 21 millis

2 (this is at another place in vdev.log and not connected to 1.)

24029:00007FE6F1697700: [        action.c:1228] vdev_action_daemonlet_send_command: DEBUG: run daemonlet (async=0): '/etc/vdev/actions/disk.act'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MOUNTPOINT=/mnt/live/tmp/dev'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_ACTION=add'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_PATH=sda'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_METADATA=/mnt/live/tmp/dev/metadata//dev/sda'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_GLOBAL_METADATA=/mnt/live/tmp/dev/metadata/'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_CONFIG_FILE=/tmp/vdevconf.tmp'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MAJOR=8'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MINOR=0'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_MODE=block'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_HELPERS=/usr/lib/vdev'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_LOGFILE=/tmp/vdevd.log'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_INSTANCE=KO2M0L6P87M135848952841287O78521K49M962729OMO0P2983184ML016L14N8'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_DAEMONLET=1'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_LOGLEVEL=debug'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVNAME=sda'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVPATH=/devices/pci0000:00/0000:00:1f.2/ata3/host2/target2:0:0/2:0:0:0/block/sda'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_DEVTYPE=disk'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_SUBSYSTEM=block'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_OS_SYSFS_MOUNTPOINT=/sys'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_VAR_DISK_GROUP=disk'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_VAR_DISK_MODE=0660'
24029:00007FE6F1697700: [        action.c:1231] vdev_action_daemonlet_send_command: DEBUG: daemonlet env: 'VDEV_VAR_DISK_OWNER=root'
24029:00007FE6F1697700: [        action.c:1243] vdev_action_daemonlet_send_command: ERROR: vdev_write_uninterrupted(27) to daemonlet '/etc/vdev/actions/disk.act' rc = -32
24029:00007FE6F1697700: [        action.c:1341] vdev_action_run_daemonlet: ERROR: vdev_action_daemonlet_send_command('/etc/vdev/actions/disk.act') rc = -11
24029:00007FE6F1697700: [        action.c:1048] vdev_action_daemonlet_stop: DEBUG: Daemonlet 29587 (/etc/vdev/actions/disk.act) dead
suedi commented 8 years ago

I pushed a more immediate fix that explicitly sets VDEV_ATA_SERIAL_SHORT to an empty string before trying to use it (4883e6d).

This fix seems to fix alot of ERROR's in fact all the ones I highlighted in the previous post. There are some left but they are quite of a different nuance so I will open them in a new issue

closing...