Opened 12 years ago

Last modified 9 years ago

#38586 new defect

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

Reported by: jdgleeson Owned by: macports-tickets@…
Priority: Normal Milestone:
Component: base Version: 2.1.3
Keywords: Cc: Veence (Vincent), cooljeanius (Eric Gallager)
Port:

Description

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.

Attachments (3)

main.log (22.8 KB) - added by jdgleeson 12 years ago.
svmain.log (3.2 KB) - added by jdgleeson 12 years ago.
svtermout.txt (528.3 KB) - added by jdgleeson 12 years ago.

Download all attachments as: .zip

Change History (19)

Changed 12 years ago by jdgleeson

Attachment: main.log added

comment:1 Changed 12 years ago by ryandesign (Ryan Carsten Schmidt)

Component: portsbase
Port: atlas removed

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.

comment:2 Changed 12 years ago by 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.

comment:3 Changed 12 years ago by cooljeanius (Eric Gallager)

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

comment:4 in reply to:  3 Changed 12 years ago by 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.

comment:5 Changed 12 years ago by 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).

comment:6 Changed 12 years ago by 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.

Last edited 12 years ago by jdgleeson (previous) (diff)

comment:7 Changed 12 years ago by 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

Last edited 9 years ago by ryandesign (Ryan Carsten Schmidt) (previous) (diff)

comment:8 Changed 12 years ago by cooljeanius (Eric Gallager)

Cc: egall@… added

Cc Me!

comment:9 Changed 12 years ago by 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.

comment:10 in reply to:  9 ; Changed 12 years ago by 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.

comment:11 in reply to:  10 Changed 12 years ago by 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.

Version 0, edited 12 years ago by jdgleeson (next)

comment:12 Changed 12 years ago by 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.

comment:13 in reply to:  12 Changed 12 years ago by 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.

comment:14 Changed 12 years ago by 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.

comment:15 Changed 12 years ago by 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
...

comment:16 Changed 12 years ago by 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).

Changed 12 years ago by jdgleeson

Attachment: svmain.log added

Changed 12 years ago by jdgleeson

Attachment: svtermout.txt added
Note: See TracTickets for help on using tickets.