RMG_backup.log is always same as RMG.log

[rwest]

It is meant to be a saved copy of the PREVIOUS run's log, but it seems to be an exact duplicate of the currently running log file. Is it being copied over and deleted constantly, or do we have two file handles pointing to the same thing, or what? I'm not sure, but it seems wrong. Perhaps we don't need it anyway.

[rwest]

@stroiano did you figure out what could cause the described problem? (or manage to reproduce it?)
It looks like b81cb8f9f36e009b31a972e4424e7440f153689f creates an infinite number of previous backups (which is a valid thing to suggest) but I'm not sure that it tackles the issue @faribas and I discovered running on opportunity. (I haven't tried it though.)

[stroiano]

Hmm, this is bizarre. I didn't originally delve too far into the root of the problem, but I was able to reproduce the problem.. once.

I ran the minimal example and canceled immediately after the log header loaded, then ran it again to completion. The resulting RMG.log and RMG_backup.log files both contained the full run. I thought maybe os.remove was causing some problem so I modified it to just rename the files to the next increment. This resulted in any number of unique log files, so I thought I'd fixed the problem with the added bonus of storing more backups.

However, I just reverted my "fix" and, sure enough, the log files are now unique. So, I have no idea what was causing your problem or how I was able to recreate it once, but I can confirm that logging works fine for me now, with or without 88225ee.

You haven't seen this anywhere besides Opportunity?

[rwest]

I think I've only run into it on Opportunity.

On Jul 21, 2012, at 11:30 PM, "Sean Troiano" reply@reply.github.com wrote:

Hmm, this is bizarre. I didn't originally delve too far into the root of the problem, but I was able to reproduce the problem.. once.

I ran the minimal example and canceled immediately after the log header loaded, then ran it again to completion. The resulting RMG.log and RMG_backup.log files both contained the full run. I thought maybe os.remove was causing some problem so I modified it to just rename the files to the next increment. This resulted in any number of unique log files, so I thought I'd fixed the problem with the added bonus of storing more backups.

However, I just reverted my "fix" and, sure enough, the log files are now unique. So, I have no idea what was causing your problem or how I was able to recreate it once, but I can confirm that logging works fine for me now, with or without b81cb8f9f36e009b31a972e4424e7440f153689f.

You haven't seen this anywhere besides Opportunity?

---

Reply to this email directly or view it on GitHub:
#92 (comment)

[stroiano]

I just tried two runs on Opportunity without my "fix" and still got two unique logs. Not sure how else to try to reproduce the problem.

I'll remove the "Closes" tag from b81cb8f9f36e009b31a972e4424e7440f153689f since I clearly haven't tracked down the source of this issue.

[rwest]

@faribas, I have just realized what must have been happening here.
The command being run (via the queue job file) was something like:

python rmg.py examples/rmg/methylformate/input.py > RMG.log

This immediately wipes whatever was in RMG.log and starts piping the STDOUT from the job into the RMG.log file.
Early on in the execution, this file is renamed to RMG_backup.log but the file object remains the same and the OS continues to pipe the STDOUT into it. Then a new RMG.log file is created, into which the RMG logging module prints a copy of everything it is logged. That is why the RMG_backup.log and the RMG.log appear to contain the same thing, except that if something gets printed to STDOUT and not sent through the logging module (eg via a print "message" rather than logging.info("message")) this would only appear in the RMG_backup.log file.

Less confusing behaviour would be achieved by doing something like:

python rmg.py examples/rmg/methylformate/input.py > RMG.stdout.log