atlas @3.10.1_3: log file contents missing when -k option used

[jdgleeson]

When I use "sudo port -k upgrade atlas" and the installation terminates without error, the only output in the log file is the activate phase. I've since tried other successful installs with the -k option, and the full log file is saved, so i think it is an issue with the atlas port and not my MacPorts installation.

[ryandesign (Ryan Carsten Schmidt)]

This is not a problem specific to the atlas port; I've seen it before with other ports, and I was not using the -k option. I am not yet sure how to reproduce the problem consistently.

[Veence (Vincent)]

I was wondering how Atlas could be responsible somehow of this, but found it to be a conundrum. Ryan conclusion is logicial, since Atlas has no special provisions for log handling. It should behave exactly like other ports in this respect, so the bug is likely in MacPorts TCL code itself rather than in the Portfile.

[cooljeanius (Eric Gallager)]

As a temporary workaround until this is fixed, try setting keeplogs to yes in your macports.conf.

[jdgleeson]

Replying to egall@…:

As a temporary workaround until this is fixed, try setting keeplogs to yes in your macports.conf.

I tried that, and it didn't make any difference. It does have the expected effect of keeping log files in general, but when I upgrade atlas in particular, I still get only the tail end of the log output.

[jdgleeson]

Since I have a case where this problem is reproducible, I'm trying to think of ways to help debug it. I came across the iosnoop script, which I thought could make it clear what system I/O operations cause the data loss. I've tried many variations on

sudo iosnoop -av -f `port logfile atlas`

but I get no trace output.

I'd welcome any debugging ideas.

NB: It takes 12 hours for this atlas install to run, so it is a rather inconvenient reproducible case. I don't know how much I can perturb it and still see the log file bug. I've tried a trivial "port -f uninstall atlas...; port -k upgrade atlas" without an intermediate clean, but the resulting log file was complete. I'm now looking into making and using my own architectural defaults, which I hope will reduce the build time to about 30 min. Any other ideas would be welcome (for purposes of debugging, I don't care if they give poor atlas libraries).

[jdgleeson]

I get a complete log file when I run the command

sudo port -kd upgrade atlas

(the -d option added). I also appended &> termout.txt to the command; I suppose I shouldn't dismiss the possibility that redirecting output has some kind of side effect.

[jdgleeson]

If anyone thinks the complete log file might hold some clues about this problem, it is attached to ticket:38602

attachment:ticket:38602:main.log.bz2​

[cooljeanius (Eric Gallager)]

Cc Me!

[jmroot (Joshua Root)]

The log is always overwritten on each run. It's not specific to -k. If you run

sudo port build foo
sudo port destroot foo

then the log for foo will only have the destroot output, and show "skipping completed" for the prior phases.

[jdgleeson]

Replying to jmr@…:

The log is always overwritten on each run. It's not specific to -k. If you run

I'm confused. If the log is always overwritten, then why do I sometimes get a complete log? For example, the log linked to in comment:7.

[jdgleeson]

Replying to jdgleeson@…:

Replying to jmr@…:

The log is always overwritten on each run. It's not specific to -k. If you run

I'm confused. If the log is always overwritten, then why do I sometimes get a complete log? For example, the log linked to in comment:7.

I realize now that I missed your point. Yes, the log file would always be overwritten in the situation you describe. However, this problem is happening within a single run. After one run of sudo port -k foo there is a complete logfile, then on the next run of sudo port -k foo there is an incomplete logfile that contains only the activation output.

[jmroot (Joshua Root)]

That's exactly the same situation. Running the same action twice doesn't change the fact that a new log is started for each run.

[jdgleeson]

Replying to jmr@…:

That's exactly the same situation. Running the same action twice doesn't change the fact that a new log is started for each run.

That is not the idea I'm trying to communicate, though. The point is that I run the same commands twice and get different result. One time I run it, and get a log file that has logging output from all phases. Another time I run the same command and I get a log file that has output from only the activate phase. I have no problem with the fact that the a new run clobbers the log file from the previous run. The problem is that the new run may produce a new log file that is incomplete.

[jmroot (Joshua Root)]

How could the new run produce a complete log if it overwrites the previous log and you didn't clean in between (which is what -k requests)? Already completed phases are skipped, by design. So yes, running the same command twice without cleaning in between will do something different.

I'm not saying that the logging behaviour is ideal, just that it is consistent even when -k is used.

[jdgleeson]

Sorry, I should have been explicit about about my experimental setup. Here is a typical command sequence I use in an attempt to create the same initial conditions for each run:

$ history
...
282  sudo port uninstall -f atlas @3.10.1_3+gcc47
283  sudo port clean atlas
284  sudo port -kd upgrade atlas
...

[jdgleeson]

I have started to systematically collect log files and debug output when I do "sudo port -kd upgrade foo" or "sudo port -kd install foo" under different circumstances.

So far I have looked carefully at only the case where an outdated port is upgraded after "sudo port selfupdate". I am happy to report that the results are extremely consistent across about 30 upgrades. But they are not what I expected: I expected to see logging of all phases of the upgrades, but I always see only the activation phase.

I've attached the log (svmain.log) and debug output (svtermout.txt) from "sudo port -kd upgrade postgresql92 &> svtermout.txt". I expected all of the phases of the upgrade to be present in svmain.log, much like they are in svtermout.txt. But svmain.log has only the activate phase. Should the upgrade log be roughly as complete as the debug output, or not?

Keep in mind that the new version postgresql92@9.2.4_0 was not previously fetched, built, installed, upgraded, uninstalled, etc. Furthermore, all of its dependencies are installed and up-to-date (otherwise there would be more variables introduced into the problem that i'd rather not deal with).

I noticed that "DEBUG: Starting logging for postgresql92" occurs 3 times in svtermout.txt:
LINE 399: at the start of the dependency check phase
LINE 6477: at the start another dependency check phase
LINE 6514: at the start of the activation phase

Is it true that each time we see "Starting logging for foo" in the debug output, any previous logging for foo during that same run of "port upgrade" is lost?

In the single instance of upgrading atlas where I have both the debug output and a log file that contains all phases, "Starting logging for atlas" occurs exactly once near the beginning of the debug output. It has an activation phase, too, but so there is some condition under which log file do not get clobbered at the start of the activation phase. This was run under different circumstances (after uninstall -f and clean).