If you’re here, chances are you’re seeing “imfile: wd 25 already in wdmap!” in your rsyslog logs. You know, the logs, for your logging service that also logs logs, would you like some logs with that… anyway where was I, oh right.. logs…
Step #1) Know you’ve got a problem.
Generally, this comes in one of three ways:
- You’re monitoring your systems system resources and usage and found an anomaly, you ran top or htop and find rsyslog is the culprit.
- You’re checking the service and noticed the output of rsyslog service.
- You’re actually looking at the rsyslog logs for some other reason.
In all cases you see this:
journalctl -u rsyslog -b
Step #2) Determine what files are the culprit.
This is easier said than done, cause:
- It depends how your config files are structured.
- The default logging, for some reason will never just simply tell you what file was already defined in the wdmap.
before making any system changes you can get a general idea of what might be the problem by checking what files the service has open handles on:
So, get the PID of rsyslog “service rsyslog status”
lsof -p PID
You can use the FD and TYPE columns to distinguish read/writes and to what files. In my particular case study, the problematic turd comes from vCenter. This alone will not telling you anything about the wd problem. Though I have used this to determine other underlying issue which sure enough stemmed from the config files.
Step 2.1) be confused by the config parser…
rsyslog stops logging to vmdird and messages in vCenter Server 7.0
nm, this is why. for the error below anyway, not the wdmap issue.
rsyslogd -N1 rsyslogd: version 8.2001.0, config validation run (level 1), master config /etc/rsyslog.conf rsyslogd: error during parsing file /etc/rsyslog.conf, on or before line 94: STOP is followed by unreachable statements! [v8.2001.0 try https://www.rsyslog.com/e/2207 ]
To actually figure this out you have to stop rsyslog and run it for a short while in debug mode saving to a custom log file:
systemctl stop rsyslog rsyslogd -dn > /var/log/rsyslog.debug 2>&1
Then to get context run:
grep -n "err.*already in wdmap" /var/log/rsyslog.debug | cut -d: -f1 | while read n; do sed -n "$((n-3)),$((n+1))p" /var/log/rsyslog.debug; echo "----"; done
Now we got some context based on the errors we saw above:
For the above, I cleared out a manual entry I created for a single file:
File=”/storage/log/vmware/vtsdb/postgresql-22.log”
After restarting I only had what was left below (I had another manually created duplicate (on purpose for this post) but pointing to
root@vCenter [ ~ ]# grep -n "err.*already in wdmap" /var/log/rsyslog.debug | cut -d: -f1 | while read n; do sed -n "$((n-3)),$((n+1))p" /var/log/rsyslog.debug; echo "----"; done 6330.967073425:imfile.c : imfile.c: act_obj_add: edge 0x5639e15e7800, name '/var/log/vmware/vtsdb/postgresql-11.log' (source '---') 6330.967076621:imfile.c : imfile.c: need to add new active object '/var/log/vmware/vtsdb/postgresql-11.log' in '/var/log/vmware/vtsdb/postgresql-*.log' - checking if accessible 6330.967082358:imfile.c : imfile.c: add new active object '/var/log/vmware/vtsdb/postgresql-11.log' in '/var/log/vmware/vtsdb/postgresql-*.log' 6330.967092728:imfile.c : errmsg.c: Called LogMsg, msg: imfile: wd 23 already in wdmap! 6330.967096479:imfile.c : operatingstate.c: osf: MSG imfile: wd 23 already in wdmap!: signaling new internal message via SIGTTOU: 'imfile: wd 23 already in wdmap! [v8.2001.0 try https://www.rsyslog.com/e/2175 ]' ---- 6331.013269259:imfile.c : imfile.c: act_obj_add: edge 0x5639e15e3dd0, name '/storage/log/vmware/vsan-health' (source '---') 6331.013272732:imfile.c : imfile.c: need to add new active object '/storage/log/vmware/vsan-health' in '/var/log/vmware/wcp' - checking if accessible 6331.013278242:imfile.c : imfile.c: add new active object '/storage/log/vmware/vsan-health' in '/var/log/vmware/wcp' 6331.013289760:imfile.c : errmsg.c: Called LogMsg, msg: imfile: wd 82 already in wdmap! 6331.013293415:imfile.c : operatingstate.c: osf: MSG imfile: wd 82 already in wdmap!: signaling new internal message via SIGTTOU: 'imfile: wd 82 already in wdmap! [v8.2001.0 try https://www.rsyslog.com/e/2175 ]' ---- 6331.036189358:imfile.c : imfile.c: act_obj_add: edge 0x5639e15e3dd0, name '/storage/log/vmware/vpxd' (source '---') 6331.036193267:imfile.c : imfile.c: need to add new active object '/storage/log/vmware/vpxd' in '/var/log/vmware/wcp' - checking if accessible 6331.036201104:imfile.c : imfile.c: add new active object '/storage/log/vmware/vpxd' in '/var/log/vmware/wcp' 6331.036210037:imfile.c : errmsg.c: Called LogMsg, msg: imfile: wd 88 already in wdmap! 6331.036213414:imfile.c : operatingstate.c: osf: MSG imfile: wd 88 already in wdmap!: signaling new internal message via SIGTTOU: 'imfile: wd 88 already in wdmap! [v8.2001.0 try https://www.rsyslog.com/e/2175 ]' ---- root@vCenter [ ~ ]# grep -n "add new active object '/storage/log/vmware/vsan-health'" /var/log/rsyslog.debug | cut -d: -f1 | while read n; do sed -n "$((n-3)),$((n+1))p" /var/log/rsyslog.debug; echo "----"; done 6331.013260502:imfile.c : main Q: queue.c: MultiEnqObj advised worker start 6331.013265898:imfile.c : imfile.c: process_symlink: adding parent '/storage/log/vmware/vsan-health' of target '/storage/log/vmware/vsan-health/vsanvcmgmtd-13.log' 6331.013269259:imfile.c : imfile.c: act_obj_add: edge 0x5639e15e3dd0, name '/storage/log/vmware/vsan-health' (source '---') 6331.013272732:imfile.c : imfile.c: need to add new active object '/storage/log/vmware/vsan-health' in '/var/log/vmware/wcp' - checking if accessible 6331.013278242:imfile.c : imfile.c: add new active object '/storage/log/vmware/vsan-health' in '/var/log/vmware/wcp' ---- 6331.013265898:imfile.c : imfile.c: process_symlink: adding parent '/storage/log/vmware/vsan-health' of target '/storage/log/vmware/vsan-health/vsanvcmgmtd-13.log' 6331.013269259:imfile.c : imfile.c: act_obj_add: edge 0x5639e15e3dd0, name '/storage/log/vmware/vsan-health' (source '---') 6331.013272732:imfile.c : imfile.c: need to add new active object '/storage/log/vmware/vsan-health' in '/var/log/vmware/wcp' - checking if accessible 6331.013278242:imfile.c : imfile.c: add new active object '/storage/log/vmware/vsan-health' in '/var/log/vmware/wcp' 6331.013289760:imfile.c : errmsg.c: Called LogMsg, msg: imfile: wd 82 already in wdmap!
Pay attention to the end of the line like “add new active object ‘/storage/log/vmware/vsan-health’ in ‘/var/log/vmware/wcp'” that’s the line that exists in a config file somewhere. To help find that:
root@vCenter [ ~ ]# grep -RniE ".*/var/log/vmware/wcp" /etc/rsyslog.conf /etc/rsyslog.d /etc/vmware-syslog 2>/dev/null /etc/vmware-syslog/vmware-services-wcpsvc.conf:3: File="/var/log/vmware/wcp/wcpsvc.log"
cat /etc/vmware-syslog/vmware-services-wcpsvc.conf #wcpsvc log input(type="imfile" File="/var/log/vmware/wcp/wcpsvc.log" Tag="wcpsvc" Severity="info" Facility="local0")
well that’s the file, but it doesn’t explain the duplicate entry attempt.
I cleared out the other duplicate file entry I manually created, and restarted the service, it appeared to be clean, but I was skeptical. Seems you may need to manually kill the debug instance. Verify with:
ps aux | grep rsyslog
Well I manually created duplicate entries, so that I could figure out how to track it down.. now I have legit entries happening, not of my own making.. Oiii this sucks… is what is is I guess? or this?
/storage/log filling up with imfile-state files | rsyslogd