2025807 - mach commands output jj snapshot logs

Status: RESOLVED FIXED

(Firefox Build System :: General, defect, P3)

Description

[Dave Townsend [:mossop] (PTO until July 20)]

Since I'm not sure how recently running various mach commands now output jj displaying messages about taking snapshots. Sometimes it even does this after the mach command has completed.

Steps to reproduce:

1. Run ./mach try --help

This prints out the help for the try command and then returns to the prompt for a moment. Then jj starts outputting snapshotting information.

The specific jj command being run appears to be the one getting a list of changed files.

This is annoying because the logging is often interleaved in amongst the actual mach output, which can make the output of things like test runs harder to read. It also adds some confusion to AI agents executing mach commands, e.g. codex just told me "The mach wrapper also printed unrelated environment noise afterward about failing to snapshot the working copy".

I also wonder if we should be triggering snapshotting at all?

Comment 1

[Dave Townsend [:mossop] (PTO until July 20)]

Actually it turns out to be more of a pain than just logs. By default commands run by codex are not allowed to write to the .git directory, so if codex has made changes to the code and then tries to run tests via mach the call to jj will fail to snapshot the changes (because it needs to write to the .git directory) and so the test run will fail.

Comment 2

[Alex Hochheiden [:ahochheiden] [he/him]]

Caused by bug 2023740, but I can't seem to reproduce (The snapshotting being interleaved with mach output part). Maybe due to a config difference?

Comment 3

[Alex Hochheiden [:ahochheiden] [he/him]]

(In reply to Dave Townsend [:mossop] from comment #1)

Actually it turns out to be more of a pain than just logs. By default commands run by codex are not allowed to write to the .git directory, so if codex has made changes to the code and then tries to run tests via mach the call to jj will fail to snapshot the changes (because it needs to write to the .git directory) and so the test run will fail.

Can you not give Codex permissions for where it can and can't write to? (I'm a Claude user and have never had this problem)

Comment 4

[Alex Hochheiden [:ahochheiden] [he/him]]

I can't reproduce the interleaved output.

My config:

[revset-aliases]
"trunk()" = "main@origin"
"immutable_heads()" = "builtin_immutable_heads() | remote_bookmarks(glob:'*', remote=exact:'origin')"

[user]
name = "Alex Hochheiden"
email = "[e-mail]"

[colors]
bookmarks = "green"
change_id = "blue"
commit_id = "yellow"
"diff removed token" = { underline = false }
"diff added token" = { underline = false }
"node immutable" = "red"
"working_copy bookmarks" = "green"
"working_copy change_id" = "blue"

[templates]
draft_commit_description = '''
concat(
  coalesce(description, "Bug ### - description r?#build", "\n"),
  surround(
    "\n\n\n\nJJ: This commit contains the following changes:\n", "",
    indent("JJ:     ", diff.stat(72)),
  ),
  "JJ: ignore-rest\n",
  diff.git(),
)
'''

[snapshot]
max-new-file-size=50000000 
auto-update-stale = true

[fsmonitor]
backend = "watchman"

[fsmonitor.watchman]
register-snapshot-trigger = false

[fix.tools.mozlint]
command = ["python3", "D:/mozilla-source/firefox/tools/lint/pipelint", "$path"]
patterns = ["glob:**/*"]

I tried with and without backend = "watchman", and with and without register-snapshot-trigger = false.

Comment 5

[Dave Townsend [:mossop] (PTO until July 20)]

(In reply to Alex Hochheiden [:ahochheiden] [he/him] from comment #3)

(In reply to Dave Townsend [:mossop] from comment #1)

Actually it turns out to be more of a pain than just logs. By default commands run by codex are not allowed to write to the .git directory, so if codex has made changes to the code and then tries to run tests via mach the call to jj will fail to snapshot the changes (because it needs to write to the .git directory) and so the test run will fail.

Can you not give Codex permissions for where it can and can't write to? (I'm a Claude user and have never had this problem)

You can, but I actually don't want it to have permission to write to the .git directory if I can avoid it.

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

:sfink, since you are the author of the regressor, bug 2023740, could you take a look? Also, could you set the severity field?

For more information, please visit BugBot documentation.

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 2023740

Comment 8

[Steve Fink [:sfink] [:s:]]

This seems like a real problem, but I don't actually understand why bug 2023740 regressed it. Wouldn't jj debug snapshot, with or without the deprecation warning message, output the same snapshotting messages?

Comment 9

[Dave Townsend [:mossop] (PTO until July 20)]

This was actually regressed by bug 1983933, specifically https://github.com/mozilla-firefox/firefox/commit/d27c65853d31.

Comment 10

[Dave Townsend [:mossop] (PTO until July 20)]

It's possible this impacts me more than other folks because for reasons I have never been able to figure out jj takes a lot longer to snapshot on my machine than for other folks. 1.5 seconds on my M4 Max MacBook Pro.

Comment 11

[Steve Fink [:sfink] [:s:]]

(In reply to Dave Townsend [:mossop] from comment #9)

This was actually regressed by bug 1983933, specifically https://github.com/mozilla-firefox/firefox/commit/d27c65853d31.

I'm free! Free, I say! Thank you.

This came up on the jj discord recently, though just because someone was annoyed at the flickering "Snapshotting ..." messages (that are apparently updated 30x/sec). I was considering adding a --quiet flag for use in automation, but it appears to already exist and is documented "...it won't tell you if the working copy was snapshotted...."

Uh, so does that work? I'll make a patch.

Comment 12

[Dave Townsend [:mossop] (PTO until July 20)]

(In reply to Steve Fink [:sfink] [:s:] from comment #11)

(In reply to Dave Townsend [:mossop] from comment #9)

This was actually regressed by bug 1983933, specifically https://github.com/mozilla-firefox/firefox/commit/d27c65853d31.

I'm free! Free, I say! Thank you.

This came up on the jj discord recently, though just because someone was annoyed at the flickering "Snapshotting ..." messages (that are apparently updated 30x/sec). I was considering adding a --quiet flag for use in automation, but it appears to already exist and is documented "...it won't tell you if the working copy was snapshotted...."

Uh, so does that work? I'll make a patch.

It might still cause a failure if it can't write to the git directory, but maybe I just need to get over that and let codex do that.

I do wonder why the jj command seems to outlive the mach command. Why are we checking for changed files if mach doesn't do anything with that?

Comment 13

[Steve Fink [:sfink] [:s:]]

Attachment: Bug 2025807 - Suppress snapshotting output, r=ahochheiden

Comment 14

[Steve Fink [:sfink] [:s:]]

(In reply to Dave Townsend [:mossop] from comment #1)

Actually it turns out to be more of a pain than just logs. By default commands run by codex are not allowed to write to the .git directory, so if codex has made changes to the code and then tries to run tests via mach the call to jj will fail to snapshot the changes (because it needs to write to the .git directory) and so the test run will fail.

I think this will need to be split into a separate bug. Unfortunately, https://github.com/jj-vcs/jj/issues/2562 (--no-commit-transaction) is the intended fix for semantically read-only operations, but it still mutates the git store; it just doesn't make the changes visible in the op log.

Comment 15

[Steve Fink [:sfink] [:s:]]

(In reply to Dave Townsend [:mossop] from comment #12)

I do wonder why the jj command seems to outlive the mach command. Why are we checking for changed files if mach doesn't do anything with that?

Yeah, I don't understand that. Perhaps it doesn't, and the output is getting delayed and buffered somehow? Or perhaps it does, and it's some Windows process management thing? Apparently the messages are printed on a separate thread so just that thread might be lingering.

UPDATE: I'm skeptical of the separate thread claim. It's clamped to 30 updates/sec but it does not appear to be on another thread. (I don't know if these discord links even work for other people.)

Comment 16

[Dave Townsend [:mossop] (PTO until July 20)]

(In reply to Steve Fink [:sfink] [:s:] from comment #15)

(In reply to Dave Townsend [:mossop] from comment #12)

I do wonder why the jj command seems to outlive the mach command. Why are we checking for changed files if mach doesn't do anything with that?

Yeah, I don't understand that. Perhaps it doesn't, and the output is getting delayed and buffered somehow? Or perhaps it does, and it's some Windows process management thing? Apparently the messages are printed on a separate thread so just that thread might be lingering.

I'm testing this on macOS with mach try --help && ps ax and the output of ps shows jj still running while of course mach has exited by that point. There is still a glean/_subprocess/_process_dispatcher_helper.py script running though so maybe it is coming from that?

Comment 17

[Dave Townsend [:mossop] (PTO until July 20)]

Oh, is this submitting telemetry in a background process perhaps? It would probably be fine to only suppress the logs in that case

Comment 18

[Dave Townsend [:mossop] (PTO until July 20)]

(In reply to Dave Townsend [:mossop] from comment #17)

Oh, is this submitting telemetry in a background process perhaps? It would probably be fine to only suppress the logs in that case

Sure enough, if I disable telemetry in ~/.mozbuild/machrc the logging goes away. Perhaps in this case we should be redirecting the output to a log file or something?

Comment 19

[Steve Fink [:sfink] [:s:]]

Attachment: Bug 2025807 - For jj, output the (mutable) changes being pushed to try r=ahochheiden

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/cce0123b980d
https://hg.mozilla.org/integration/autoland/rev/ce00bdf416bb
Suppress snapshotting output, r=ahochheiden
https://github.com/mozilla-firefox/firefox/commit/a585dfb914b3
https://hg.mozilla.org/integration/autoland/rev/528978dd6f50
For jj, output the (mutable) changes being pushed to try r=ahochheiden

Comment 21

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/ce00bdf416bb
https://hg.mozilla.org/mozilla-central/rev/528978dd6f50

Comment 22

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:sfink, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
  • See https://wiki.mozilla.org/Release_Management/Requesting_an_Uplift for documentation on how to request an uplift.
• If no, please set status-firefox150 to wontfix.

For more information, please visit BugBot documentation.

Comment 23

[Steve Fink [:sfink] [:s:]]

Attachment: Bug 2025807 - Use --no-graph in favor of -G r=ErichDonGubler

For backwards compatibility as well as understandability.

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/128c3180faf4
https://hg.mozilla.org/integration/autoland/rev/40cd8f01f2fa
Use --no-graph in favor of -G r=ErichDonGubler

Comment 25

[BugBot [:suhaib / :marco/ :calixte]]

A patch has been attached on this bug, which was already closed. Filing a separate bug will ensure better tracking. If this was not by mistake and further action is needed, please alert the appropriate party. (Or: if the patch doesn't change behavior -- e.g. landing a test case, or fixing a typo -- then feel free to disregard this message)

Comment 26

[Silaghi Andreea]

https://hg.mozilla.org/mozilla-central/rev/40cd8f01f2fa