Joan, Thank you for your response. In answer to your questions.
It does NOT happen with forceSingleInstance="off" With that setting, my program starts and stays running and I don't see the bad file descriptor errors. With forceSingleInstance="on", I could reproduce the errors 100% of the time that I started rsyslog in daemon mode. As you suggested, I opened a github issue #4247 and uploaded a debug log. Thank you for your help, Derek On Tue, Apr 14, 2020 at 4:15 PM Joan Sala <[email protected]> wrote: > This problem reminds me of this issue (which was corrected): > https://github.com/rsyslog/rsyslog/issues/2787#issuecomment-403227370 > > And could also be related to this problem (the reporter didn't follow up): > https://github.com/rsyslog/rsyslog/issues/3361#issuecomment-481631043 > > One point to consider is that when starting rsyslog as a daemon (i.e. when > the -n option is NOT given), stdin, stdout and stderr are not assigned, and > hence other specific file descriptors (specifically, the ones used for the > pipes with omprog) could potentially reuse these fd numbers. After a quick > glance in how omprog handles the pipe fds, I haven't seen a possible bug > related to this, but obviously we can't rule this out... > > I will try to reproduce the problem using the testbench (not sure when > though, don't count on a quick response...). AFAIK the testbench always > launches rsyslog in non-daemon mode. Rainer, is there an easy way to run > the testbench in daemon mode? > > Derek, a couple of questions for you: > - Does it happen with forceSingleInstance="off"? (this would definitely > point to a possible bug in omprog) > - Can you reproduce it consistently? (when starting rsyslog in daemon > mode) Or sometimes works? > > Also I would recommend opening a github issue. (Even if it's not a bug in > rsyslog/omprog, the resolution could be useful to other users having the > same problem.) Attaching a debug log could also be useful. > > Regarding this: > >> I have tried adding 'output' to the action configuration, thinking I >> would get messages, but haven't gotten anything. >> > That's expected: omprog is not able to communicate to the program (the > pipe fd's are broken/unusable), so its output can't be captured either. > > Regards > Joan > > > On Tue, Apr 14, 2020 at 4:46 PM Derek Dresser via rsyslog < > [email protected]> wrote: > >> Rainer, >> Thank you for the response. I agree that it sounds like a system problem, >> not necessarily syslogd or omprog. This is an embedded system and doesn't >> have any selinux. I have disabled all cgroup functionality as well. >> Debug >> logging, etc. hasn't provided any clues. Given that it is the root user >> starting rsyslog in both cases, what is different when rsyslogd is started >> with the -n flag? Also with your deep understanding of omprog, do you >> have >> any tips that might help me get more insight into what is happening? >> Thank you, >> Derek >> >> On Tue, Apr 14, 2020 at 5:34 AM Rainer Gerhards <[email protected] >> > >> wrote: >> >> > This sounds like a problem with SELinux or a similar hardening system. >> > >> > HTH >> > Rainer >> > >> > El lun., 13 abr. 2020 a las 4:20, Derek Dresser via rsyslog >> > (<[email protected]>) escribió: >> > > >> > > Hello, >> > > >> > > I am troubleshooting an issue on a Yocto based distribution with >> sending >> > > logs >> > > to a python program '/usr/bin/logoutput' via omprog. If rsyslogd is >> > started >> > > by init script, or by me (as root) on the command line, I get the >> > following >> > > errors. >> > > >> > > apr 12 21:35:02.865327 RSYSLO action 'action-1-omprog' resumed >> (module >> > > 'omprog') [v8.2002.0 try https://www.rsyslog.com/e/2359 ] >> > > apr 12 21:35:02.865350 RSYSLO omprog: error sending message to >> program: >> > Bad >> > > file descriptor [v8.2002.0 try https://www.rsyslog.com/e/2119 ] >> > > apr 12 21:35:02.865365 RSYSLO action 'action-1-omprog' suspended >> (module >> > > 'omprog'), retry 0. There should be messages before this one giving >> the >> > > reason f >> > > or suspension. [v8.2002.0 try https://www.rsyslog.com/e/2007 ] >> > > apr 12 21:35:03.866356 RSYSLO action 'action-1-omprog' suspended >> (module >> > > 'omprog'), next retry is Sun Apr 12 21:35:33 2020, retry nbr 0. There >> > should >> > > be >> > > messages before this one giving the reason for suspension. [v8.2002.0 >> try >> > > https://www.rsyslog.com/e/2007 ] >> > > >> > > >> > > and I never see 'logoutput' in the process listing. However, if I >> start >> > > rsyslogd with '-n' (foreground), my program is started and messages >> are >> > > delivered as expected. Even if I start it with -n and send it to the >> > > background it is fine (rsyslogd -n &) I don't have selinux or >> anything >> > > enabled. >> > > >> > > I have tried adding 'output' to the action configuration, thinking I >> > would >> > > get messages, but haven't gotten anything. >> > > >> > > action(type="omprog" >> > > binary="/usr/bin/logoutput" >> > > forceSingleInstance="on" >> > > output="/tmp/omprog.out" >> > > template="output") >> > > >> > > here are the lsof listings rsyslogd being started by init script >> > > >> > > root@zcu102-zynqmp:/tmp/bin# lsof -p 6204 >> > > COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE >> > NAME >> > > rsyslogd 6204 root cwd DIR 179,2 4096 2 >> / >> > > rsyslogd 6204 root rtd DIR 179,2 4096 2 >> / >> > > rsyslogd 6204 root txt REG 179,2 678072 19325 >> > > /usr/sbin/rsyslogd >> > > rsyslogd 6204 root mem REG 179,2 27208 19316 >> > > /usr/lib/rsyslog/omprog.so >> > > rsyslogd 6204 root mem REG 179,2 14528 19312 >> > > /usr/lib/rsyslog/mmjsonparse.so >> > > rsyslogd 6204 root mem REG 179,2 19680 19292 >> > > /usr/lib/rsyslog/imklog.so >> > > rsyslogd 6204 root mem REG 179,2 32912 19298 >> > > /usr/lib/rsyslog/imuxsock.so >> > > rsyslogd 6204 root mem REG 179,2 46984 907 >> > /lib/ >> > > libnss_files-2.30.so >> > > rsyslogd 6204 root mem REG 179,2 23416 19300 >> > > /usr/lib/rsyslog/lmnet.so >> > > rsyslogd 6204 root mem REG 179,2 1400792 874 >> > /lib/ >> > > libc-2.30.so >> > > rsyslogd 6204 root mem REG 179,2 27000 935 >> > > /lib/libuuid.so.1.3.0 >> > > rsyslogd 6204 root mem REG 179,2 43496 10991 >> > > /usr/lib/libfastjson.so.4.2.0 >> > > rsyslogd 6204 root mem REG 179,2 14168 10983 >> > > /usr/lib/libestr.so.0.0.0 >> > > rsyslogd 6204 root mem REG 179,2 14208 884 >> > /lib/ >> > > libdl-2.30.so >> > > rsyslogd 6204 root mem REG 179,2 113104 915 >> > /lib/ >> > > libpthread-2.30.so >> > > rsyslogd 6204 root mem REG 179,2 88304 939 >> > > /lib/libz.so.1.2.11 >> > > rsyslogd 6204 root mem REG 179,2 136752 862 >> > /lib/ >> > > ld-2.30.so >> > > rsyslogd 6204 root 0r CHR 1,9 0t0 1032 >> > > /dev/urandom >> > > rsyslogd 6204 root 1u unix 0xffffffc05fdda000 0t0 40009 >> > > type=DGRAM >> > > rsyslogd 6204 root 2w REG 179,4 10350 131078 >> > > /data/log/syslog.log >> > > rsyslogd 6204 root 3u unix 0xffffffc05fdda480 0t0 40006 >> > > /dev/log type=DGRAM >> > > rsyslogd 6204 root 4r REG 0,4 0 4026531950 >> > > /proc/kmsg >> > > >> > > and when started in the foreground (rsyslogd -n &) >> > > >> > > root@zcu102-zynqmp:/tmp/bin# lsof -p 6239 >> > > COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE >> > NAME >> > > rsyslogd 6239 root cwd DIR 179,2 4096 2 >> / >> > > rsyslogd 6239 root rtd DIR 179,2 4096 2 >> / >> > > rsyslogd 6239 root txt REG 179,2 678072 19325 >> > > /usr/sbin/rsyslogd >> > > rsyslogd 6239 root mem REG 179,2 27208 19316 >> > > /usr/lib/rsyslog/omprog.so >> > > rsyslogd 6239 root mem REG 179,2 14528 19312 >> > > /usr/lib/rsyslog/mmjsonparse.so >> > > rsyslogd 6239 root mem REG 179,2 19680 19292 >> > > /usr/lib/rsyslog/imklog.so >> > > rsyslogd 6239 root mem REG 179,2 32912 19298 >> > > /usr/lib/rsyslog/imuxsock.so >> > > rsyslogd 6239 root mem REG 179,2 46984 907 >> > /lib/ >> > > libnss_files-2.30.so >> > > rsyslogd 6239 root mem REG 179,2 23416 19300 >> > > /usr/lib/rsyslog/lmnet.so >> > > rsyslogd 6239 root mem REG 179,2 1400792 874 >> > /lib/ >> > > libc-2.30.so >> > > rsyslogd 6239 root mem REG 179,2 27000 935 >> > > /lib/libuuid.so.1.3.0 >> > > rsyslogd 6239 root mem REG 179,2 43496 10991 >> > > /usr/lib/libfastjson.so.4.2.0 >> > > rsyslogd 6239 root mem REG 179,2 14168 10983 >> > > /usr/lib/libestr.so.0.0.0 >> > > rsyslogd 6239 root mem REG 179,2 14208 884 >> > /lib/ >> > > libdl-2.30.so >> > > rsyslogd 6239 root mem REG 179,2 113104 915 >> > /lib/ >> > > libpthread-2.30.so >> > > rsyslogd 6239 root mem REG 179,2 88304 939 >> > > /lib/libz.so.1.2.11 >> > > rsyslogd 6239 root mem REG 179,2 136752 862 >> > /lib/ >> > > ld-2.30.so >> > > rsyslogd 6239 root 0u CHR 253,0 0t0 1522 >> > > /dev/ttyPS0 >> > > rsyslogd 6239 root 1u CHR 253,0 0t0 1522 >> > > /dev/ttyPS0 >> > > rsyslogd 6239 root 2u CHR 253,0 0t0 1522 >> > > /dev/ttyPS0 >> > > rsyslogd 6239 root 3r CHR 1,9 0t0 1032 >> > > /dev/urandom >> > > rsyslogd 6239 root 4r FIFO 0,9 0t0 39109 >> > pipe >> > > rsyslogd 6239 root 5w FIFO 0,9 0t0 39109 >> > pipe >> > > rsyslogd 6239 root 6u unix 0xffffffc05c6524c0 0t0 39111 >> > > /dev/log type=DGRAM >> > > rsyslogd 6239 root 7w FIFO 0,9 0t0 39110 >> > pipe >> > > rsyslogd 6239 root 8r REG 0,4 0 4026531950 >> > > /proc/kmsg >> > > rsyslogd 6239 root 9u unix 0xffffffc05c652040 0t0 39114 >> > > type=DGRAM >> > > rsyslogd 6239 root 10w REG 179,4 10484 131078 >> > > /data/log/syslog.log >> > > >> > > and here are pstree listings for each case. first when started by >> init >> > > script >> > > >> > > root@zcu102-zynqmp:/tmp/bin# pstree -ps 6318 >> > > init(1)---rsyslogd(6318)-+-{rsyslogd}(6319) >> > > |-{rsyslogd}(6320) >> > > `-{rsyslogd}(6322) >> > > >> > > and when started with rsyslogd -n & >> > > root@zcu102-zynqmp:/tmp/bin# pstree -ps 6351 >> > > >> > >> init(1)---start_getty(3688)---login(3715)---sh(3752)---rsyslogd(6351)-+-logoutput(6353)---{logoutput}(6357) >> > > >> > > |-{rsyslogd}(6352) >> > > >> > > |-{rsyslogd}(6354) >> > > >> > > |-{rsyslogd}(6355) >> > > >> > > `-{rsyslogd}(6356) >> > > >> > > you can see that when I start it with the '-n' flag, my program gets >> > started >> > > and rsyslogd has a pipe to it. Can someone help me understand why >> this >> > is >> > > only working for me when I use the '-n' flag. In both cases, it is >> > started >> > > as root, so it doesn't seem like a permissions issue. >> > > >> > > Thanks >> > > _______________________________________________ >> > > rsyslog mailing list >> > > https://lists.adiscon.net/mailman/listinfo/rsyslog >> > > http://www.rsyslog.com/professional-services/ >> > > What's up with rsyslog? Follow https://twitter.com/rgerhards >> > > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a >> myriad >> > of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you >> > DON'T LIKE THAT. >> > >> _______________________________________________ >> rsyslog mailing list >> https://lists.adiscon.net/mailman/listinfo/rsyslog >> http://www.rsyslog.com/professional-services/ >> What's up with rsyslog? Follow https://twitter.com/rgerhards >> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad >> of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you >> DON'T LIKE THAT. > > _______________________________________________ rsyslog mailing list https://lists.adiscon.net/mailman/listinfo/rsyslog http://www.rsyslog.com/professional-services/ What's up with rsyslog? Follow https://twitter.com/rgerhards NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.
