Decision engine log files get split between several different processes with several different versions open

[StevenCTimm]

on hepcsvc03.fnal.gov which is running decisionengine 1.7.0 release:

-rw-r--r-- 1 decisionengine decisionengine 199989092 Sep 22 02:03 decisionengine_structlog_debug.log.6 -rw-r--r-- 1 decisionengine decisionengine 199999772 Sep 22 10:59 decisionengine_structlog_debug.log.5 -rw-r--r-- 1 decisionengine decisionengine 199997383 Sep 22 20:24 decisionengine_structlog_debug.log.4 -rw-r--r-- 1 decisionengine decisionengine 199999994 Sep 23 07:39 decisionengine_structlog_debug.log.3 -rw-r--r-- 1 decisionengine decisionengine 10507629 Sep 23 11:04 decisionengine_debug.log -rw-r--r-- 1 decisionengine decisionengine 305722 Sep 23 11:09 decisionengine_debug.log.2 -rw-r--r-- 1 decisionengine decisionengine 34837 Sep 23 11:12 decisionengine_debug.log.1 -rw-r--r-- 1 decisionengine decisionengine 19709992 Sep 23 11:56 decisionengine_debug.log.4 -rw-r--r-- 1 decisionengine decisionengine 44771025 Sep 23 11:58 decisionengine_structlog_debug.log.2 -rw-r--r-- 1 decisionengine decisionengine 19371954 Sep 23 11:58 decisionengine_debug.log.6 -rw-r--r-- 1 decisionengine decisionengine 5810641 Sep 23 11:58 decisionengine_debug.log.3 -rw-r--r-- 1 decisionengine decisionengine 25636040 Sep 23 11:59 decisionengine_debug.log.5 -rw-r--r-- 1 decisionengine decisionengine 18895916 Sep 23 11:59 decisionengine_structlog_debug.log.1 -rw-r--r-- 1 decisionengine decisionengine 59197393 Sep 23 11:59 decisionengine.log -rw-r--r-- 1 decisionengine decisionengine 65090811 Sep 23 11:59 decisionengine_structlog_debug.log

---

All decisionengine_structlog_debug.log* that are open right now according to lsof [root@hepcsvc03 decisionengine]# lsof | grep decisionengine_structlog_debug.log decisione 9650 decisionengine 5w REG 8,2 10495284 6004205 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9650 9667 decisionengine 5w REG 8,2 10495284 6004205 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9669 decisionengine 12w REG 8,2 190518160 6002651 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9669 9670 decisionengine 12w REG 8,2 190517774 6002651 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9669 9671 decisionengine 12w REG 8,2 190517774 6002651 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9669 9672 decisionengine 12w REG 8,2 190517774 6002651 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9669 9673 decisionengine 12w REG 8,2 190518160 6002651 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9693 decisionengine 14w REG 8,2 32785292 721077 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 9693 9694 decisionengine 14w REG 8,2 32785292 721077 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10736 decisionengine 16w REG 8,2 44861156 721065 /var/log/decisionengine/decisionengine_structlog_debug.log.2 decisione 10736 10737 decisionengine 16w REG 8,2 44861156 721065 /var/log/decisionengine/decisionengine_structlog_debug.log.2 decisione 10736 10738 decisionengine 16w REG 8,2 44861156 721065 /var/log/decisionengine/decisionengine_structlog_debug.log.2 decisione 10736 10739 decisionengine 16w REG 8,2 44861156 721065 /var/log/decisionengine/decisionengine_structlog_debug.log.2 decisione 10754 decisionengine 18w REG 8,2 180329725 720916 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10754 10756 decisionengine 18w REG 8,2 180329725 720916 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10754 10757 decisionengine 18w REG 8,2 180329725 720916 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10754 10758 decisionengine 18w REG 8,2 180329725 720916 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10754 10759 decisionengine 18w REG 8,2 180329725 720916 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10815 decisionengine 20w REG 8,2 64015582 6000753 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10815 10816 decisionengine 20w REG 8,2 64015582 6000753 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 10831 decisionengine 5w REG 8,2 18922966 721074 /var/log/decisionengine/decisionengine_structlog_debug.log.1 decisione 10831 10832 decisionengine 5w REG 8,2 18922966 721074 /var/log/decisionengine/decisionengine_structlog_debug.log.1 decisione 10848 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10849 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10850 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10851 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10852 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10853 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10854 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10855 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10856 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10857 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10858 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10859 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10860 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10861 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 10848 10862 decisionengine 5w REG 8,2 65324208 723275 /var/log/decisionengine/decisionengine_structlog_debug.log decisione 11142 decisionengine 5w REG 8,2 23209088 721076 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted) decisione 11142 11143 decisionengine 5w REG 8,2 23209088 721076 /var/log/decisionengine/decisionengine_structlog_debug.log.6 (deleted)

---

decisione 9650 decisionengine 3w REG 8,2 10507629 723140 /var/log/decisionengine/decisionengine_debug.log decisione 9650 9667 decisionengine 3w REG 8,2 10507629 723140 /var/log/decisionengine/decisionengine_debug.log decisione 9669 decisionengine 4w REG 8,2 25653449 722506 /var/log/decisionengine/decisionengine_debug.log.5 decisione 9669 9670 decisionengine 4w REG 8,2 25653449 722506 /var/log/decisionengine/decisionengine_debug.log.5 decisione 9669 9671 decisionengine 4w REG 8,2 25653449 722506 /var/log/decisionengine/decisionengine_debug.log.5 decisione 9669 9672 decisionengine 4w REG 8,2 25653449 722506 /var/log/decisionengine/decisionengine_debug.log.5 decisione 9669 9673 decisionengine 4w REG 8,2 25653449 722506 /var/log/decisionengine/decisionengine_debug.log.5 decisione 9693 decisionengine 4w REG 8,2 305722 723436 /var/log/decisionengine/decisionengine_debug.log.2 decisione 9693 9694 decisionengine 4w REG 8,2 305722 723436 /var/log/decisionengine/decisionengine_debug.log.2 decisione 10736 decisionengine 4w REG 8,2 19379654 721079 /var/log/decisionengine/decisionengine_debug.log.6 decisione 10736 10737 decisionengine 4w REG 8,2 19379654 721079 /var/log/decisionengine/decisionengine_debug.log.6 decisione 10736 10738 decisionengine 4w REG 8,2 19379654 721079 /var/log/decisionengine/decisionengine_debug.log.6 decisione 10736 10739 decisionengine 4w REG 8,2 19379654 721079 /var/log/decisionengine/decisionengine_debug.log.6 decisione 10754 decisionengine 4w REG 8,2 19724652 723370 /var/log/decisionengine/decisionengine_debug.log.4 decisione 10754 10756 decisionengine 4w REG 8,2 19724652 723370 /var/log/decisionengine/decisionengine_debug.log.4 decisione 10754 10757 decisionengine 4w REG 8,2 19724652 723370 /var/log/decisionengine/decisionengine_debug.log.4 decisione 10754 10758 decisionengine 4w REG 8,2 19724652 723370 /var/log/decisionengine/decisionengine_debug.log.4 decisione 10754 10759 decisionengine 4w REG 8,2 19724652 723370 /var/log/decisionengine/decisionengine_debug.log.4 decisione 10815 decisionengine 4w REG 8,2 5810641 723376 /var/log/decisionengine/decisionengine_debug.log.3 decisione 10815 10816 decisionengine 4w REG 8,2 5810641 723376 /var/log/decisionengine/decisionengine_debug.log.3 decisione 10831 decisionengine 3w REG 8,2 20651037 721075 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10831 10832 decisionengine 3w REG 8,2 20651037 721075 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10849 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10850 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10851 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10852 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10853 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10854 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10855 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10856 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10857 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10858 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10859 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10860 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10861 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 10848 10862 decisionengine 3w REG 8,2 53568253 721070 /var/log/decisionengine/decisionengine_debug.log.6 (deleted) decisione 11142 decisionengine 3w REG 8,2 34837 723471 /var/log/decisionengine/decisionengine_debug.log.1 decisione 11142 11143 decisionengine 3w REG 8,2 34837 723471 /var/log/decisionengine/decisionengine_debug.log.1

---

It seems to be only the decisionengine_debug.log and decisionengine_structlog_debug.log which are effected. The main decisionengine.log and the individual channel logs are not affected.

It seems to be connected to the restart of channels that causes the logs to rotate out of sync. As you can see some of them are still pointing to files that have already been deleted which means that information is actually being lost.

[StevenCTimm]

A restart of one simple channel didn't do it so there may be more going on than that. I have just restarted the decision engine, we will see how long it goes until we see a forked log again. At startup they are all OK.

[StevenCTimm]

Request that when this fix is available, it be back-ported into the 1.7 branch.

[mambelli]

There are PR #563 for master and PR #572 for branch 1.7

[StevenCTimm]

Thanks for the update. We should also examine if Kyle's work to run each source in a separate process now will confuse the logging of the channel logs in any way.

[StevenCTimm]

The issue reported above is fixed in 1.7.1 and presumably also in master.. but as requested I want to see what the sources-in-separate-channel is doing before we completely close this issue.

[goodenou]

Hi Steve. I was looking through issues and found this one still open. I believe it has been resolved. Are you satisfied with the fix?

[goodenou]

Hi Steve. What is the status of this issue? Do I need to do anything?

[StevenCTimm]

This is still happening in the production DE 1.7.4 that we run in production.
You have root .k5login on hepcsvc03 and you can look at /var/log/decisionengine.

[mambelli]

PR #692 should fix this for branch 1.7 It is in v1.7.5

[StevenCTimm]

This is fixed in 1.7.5 which is now on all our production machines. Closing. Thank you very much