subiquity doesn't appear to log stderr from failed commands

[Luke Tidd]

I am currently creating a `user-data` file for my automatic installs.
If I put a command that fails in the `late-commands` section, I can see that it failed but I can not find output from that command. Am I missing something?

For example, after creating a user, I try to create a user system service for them:

```
- curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user
```

All I can find about this is:
```
subprocess.CalledProcessError: Command '['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.2595', 'sh', '-c', 'curtin in-target --target=/target mkdir -p /home/chrome-bot/.l
ocal/share/systemd/user']' returned non-zero exit status 2.
```

but no output from the command that would indicate why this failed.

More verbose output:

```
2023-02-09 15:32:37,869 DEBUG root:37 start: subiquity/Late/run/command_63: curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user
2023-02-09 15:32:37,869 DEBUG subiquitycore.utils:92 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.2595', 'sh', '-c', 'curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user']
2023-02-09 15:32:38,325 DEBUG subiquitycore.utils:101 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.2595', 'sh', '-c', 'curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user'] exited with code 2
2023-02-09 15:32:38,326 ERROR root:37 finish: subiquity/Late/run/command_63: FAIL: Command '['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.2595', 'sh', '-c', 'curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user']' returned non-zero exit status 2.
2023-02-09 15:32:38,326 ERROR root:37 finish: subiquity/Late/run: FAIL: Command '['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.2595', 'sh', '-c', 'curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user']' returned non-zero exit status 2.
2023-02-09 15:32:38,326 ERROR subiquity.server.server:422 top level error
Traceback (most recent call last):
  File "/snap/subiquity/4229/lib/python3.8/site-packages/subiquity/server/controllers/cmdlist.py", line 141, in _run
    await self.run()
  File "/snap/subiquity/4229/lib/python3.8/site-packages/subiquitycore/context.py", line 148, in decorated_async
    return await meth(self, **kw)
  File "/snap/subiquity/4229/lib/python3.8/site-packages/subiquity/server/controllers/cmdlist.py", line 90, in run
    await arun_command(
  File "/snap/subiquity/4229/lib/python3.8/site-packages/subiquitycore/utils.py", line 105, in arun_command
    raise subprocess.CalledProcessError(proc.returncode, cmd,
subprocess.CalledProcessError: Command '['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.2595', 'sh', '-c', 'curtin in-target --target=/target mkdir -p /home/user/.local/share/systemd/user']' returned non-zero exit status 2.
2023-02-09 15:32:38,327 DEBUG subiquity.common.errorreport:384 generating crash report
2023-02-09 15:32:38,328 INFO subiquity.common.errorreport:406 saving crash report 'unknown error crashed with CalledProcessError' to /var/crash/1675956758.327854633.unknown.crash
2023-02-09 15:32:38,328 INFO root:37 start: subiquity/ErrorReporter/1675956758.327854633.unknown/add_info:
2023-02-09 15:32:38,588 INFO root:37 finish: subiquity/ErrorReporter/1675956758.327854633.unknown/add_info: SUCCESS: written to /var/crash/1675956758.327854633.unknown.crash
2023-02-09 15:32:38,589 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "ERROR", "confirming_tty": "", "error": {"state": "DONE", "base": "...
2023-02-09 15:32:38,590 INFO aiohttp.access:233 [09/Feb/2023:15:30:36 +0000] "GET /meta/status?cur=%22DONE%22 HTTP/1.1" 200 514 "-" "Python/3.8 aiohttp/3.6.2"
```

Am I just missing something? There is so much logging and apparently no stdout or stderr.

[Dan Bungert (dbungert)]

Thanks for the report Luke.

/var/log/install/curtin-install.log should have some more details and may help your particular case, but your premise is correct that we need more logging of stdout/stderr.

[Luke Tidd (lukeisgreat)]

Thanks for taking a look!

I do have a work around in the meantime.

I will create a script and use it to log ;)

    - printf '#!/bin/bash\ndo something 2> /var/log/installer/script1.log\nprintf 'exit code: %s' "$?" >> /var/log/installer/script1.log\n' > /target/tmp/script1
    - chmod +x /target/tmp/script1
    - curtin in-target --target /target -- /tmp/script1

[Rahul Verma (rahulonmars)]

@Luke : Did it work ? I am also trying to log stderror along with stdout when using in-target with d-i.
So, far I've only found that stderr is not provided by in-target, we can only direct stdout using the --pass-stdout flag.

Although, there is an interesting solution here, have a look:
http://www.virtualbox.org/svn/vbox/trunk/src/VBox/Main/UnattendedTemplates/debian_postinstall.sh

[Luke Tidd (lukeisgreat)]

I have a lot of installs to manage, so I wrote some python that generates my USER-DATA. At the beginning of my early and late commands, I create a log dir. I have a list of scripts for early and late install from a template that, similar to the script you posted, writes it's output to the log files and can better handle errors, etc. Each of these scripts are base64 encoded by my python script then written as a set of commands to USER-DATA something like:

```
late-commands:
  - mkdir -p /target/var/log/installer/custom /installer /target/installer
  - echo Running test.sh
  - printf 'IyEvYmluL2Jhc2gKClNDUklQVD0iJChiYXNlbmFtZSAiJHswfSIpIgpMT0dfRElSPScvdmFyL2xvZy9pbnN0YWxlci9jdXN0b20nCkxPRz0iJHtMT0dfRElSfS8ke1NDUklQVH0iCgpmdW5jdGlvbiBsb2coKSB7CiAgcHJpbnRmICclcyAlczogJXNcbicgIiRTQ1JJUFQiICIkKGRhdGUgJyslWSVtJWQgJUglTSVTJykiICIkMSIgPiAiJExPRyIKfQoKZG9fc29tZXRoaW5nIDI+JjEgfCB3aGlsZSByZWFkIGxpbmU7IGRvIGxvZyAiJGxpbmUiOyBkb25lCg==' > /installer/test.sh.b64
  - base64 -d < /installer/test.sh.b64 > /target/installer/test.sh
  - curtin in-target --target /target -- /installer/test.sh
```