Opened 5 years ago
Closed 5 years ago
#188 closed defect (fixed)
Missing output and garbage in the log when using Windows launcher
| Reported by: | Jan Vrany | Owned by: | Patrik Svestka |
|---|---|---|---|
| Priority: | major | Milestone: | 8.0.0 |
| Component: | default | Keywords: | |
| Cc: | Patrik Svestka | Also affects CVS HEAD (eXept version): | no |
Description
I'm experiencing weird behavior of the launcher, sometimes not showing me
the output on the console and writing a garbage to the log file:
Steps to reproduce
- Run following command:
smalltalk.bat -I --stopOnSIGSEGV -I --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"
- Kill the
stx.comprocess after some time, 5 mins should be safe.
Observed behavior
Until killed, the console output is the following:
"[INFO] PowerShell detected: ->TRUE<-.
"[INFO] The latest latest_powershell_version found: 2.0."
"[INFO] With the runtime being: v2.0.50727."
VERBOSE: [INFO] No log file found turning off the append mode.
VERBOSE:
VERBOSE: [INFO] Executing command: H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\stx.com "--stopOnSIGSEGV" "-I"
"--quick" "--eval" "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1" 2>&1 | Tee-Host | Out-File -Encoding UTF8
-FilePath H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\smalltalk_2017-12-19_utf8.log -Width 150
VERBOSE: Kuk
Then, when killed, it shows:
[ERROR] happned in PowerShell (can be also stx.com) - See log file: H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\smallta lk_2017-12-19_utf8.log. VERBOSE: VERBOSE: [INFO] Exiting from PowerShell with code 1
The contents of the .log file is attached. Note the Powershell error and garbage at the end - actually it's an UTF16 text. Also note, that the information about the segmentation violation shown by the VM is missing completely (se below what I'd expect).
Expected behavior
Running the very same command without launcher produces following output on the console (before it is killed):
> stx --stopOnSIGSEGV -I --quick --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"
Kuk
VM [sigsegv]: sigNo 11 context=6caab08 sp=6caaa70
VM [error] (17-12-19 22:08:05): Got SEGV, stopping for debugger to attach
error occured (see above), waiting 30 mins for debugger to attach
to terminate:
taskkill /F /PID 1564
to attach a debugger:
gdb attach 1564
When using launcher, I'd expect this text to be shown in the console and as well in the .log file.
Version information
This happens on bleeding edge 8.0.0 64bit build. The stx:projects/smalltalk package revision is 09e37fd93f8f, the working copy is clean, smalltalk.cfg unmodified.
Attachments (10)
Change History (32)
Changed 5 years ago by
| Attachment: | smalltalk_2017-12-19_utf8.log added |
|---|
comment:1 follow-up: 2 Changed 5 years ago by
Changed 5 years ago by
| Attachment: | smalltalk.cfg added |
|---|
comment:2 Changed 5 years ago by
Replying to Patrik Svestka:
- Could you post your smalltalk.cfg file?
See attached smalltalk.cfg
- Did you try with logging turned off?
Then it works as expected:
> hg diff smalltalk.cfg
diff -r 09e37fd93f8f smalltalk.cfg
--- a/smalltalk.cfg Tue Nov 28 11:16:24 2017 +0000
+++ b/smalltalk.cfg Wed Dec 20 08:21:01 2017 +0000
@@ -55,7 +55,7 @@
# Note: At least PowerShell 2.0 is required (WindowsXP and newer)
# TRUE - turns on the logging functionality
# FALSE - turns off the logging
-__binary.record_log_file=TRUE
+__binary.record_log_file=FALSE
Then the output is:
> smalltalk --stopOnSIGSEGV -I --quick --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"
"[INFO] PowerShell detected: ->TRUE<-.
"[INFO] The latest latest_powershell_version found: 2.0."
"[INFO] With the runtime being: v2.0.50727."
VERBOSE: [WARN] Your configuration flawed - compensating.
VERBOSE: [WARN] record_log_file=FALSE AND append_to_log=TRUE which makes no sense.
VERBOSE: [WARN] Setting append_to_log=FALSE.
VERBOSE: [WARN] To fix it either set record_log_file=TRUE or append_to_log=FALSE
VERBOSE: [INFO] No log file found turning off the append mode.
VERBOSE: [WARN] NO LOGGING
VERBOSE: [INFO] User disabled or limitation applies.
VERBOSE: [INFO] Executing: cmd.exe /U /C CALL H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\stx.com --stopOnSIGSEGV -I --quick --eval Transcript
VERBOSE: [INFO] Executing: cmd.exe /U /C CALL H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\stx.com --stopOnSIGSEGV -I --quick --eval Transcript
Kuk
VM [sigsegv]: sigNo 11 context=6a6ab08 sp=6a6aa70
VM [error] (17-12-20 08:17:33): Got SEGV, stopping for debugger to attach
error occured (see above), waiting 30 mins for debugger to attach
to terminate:
taskkill /F /PID 5044
to attach a debugger:
gdb attach 5044
comment:3 Changed 5 years ago by
Thank you for posting the information.
The error is caused by powershell.exe being called from cmd.exe (via batch file). Powershell.exe adjusts to cmd.exe for stdout, which makes it really hard to debug.
Anyways, the UTF-16 error is easy to remedy. The tricky part is the logging and the error.
The error and lack of output is caused by the function ExecuteCommand namely Invoke-Expression -Command:$execute_command, which executes the actual command. I'll try to figure out a way to reliably log the stdout.
In meantime, if you want to use stx.com options you will have to live without logging.
comment:4 Changed 5 years ago by
I have tested the solution agains a testing PowerShell file and ruby file. From my testing I can only say something is wrong with the StX output. Both scripts are to be executed from ../project/smalltalk (don't forget to change the path in the scripts).
@Jan could you please test it with these two examples? Thank you.
The testing powershell script:
# inspired and some code used from these sources:
# MSDN:
# https://msdn.microsoft.com/en-us/library/system.diagnostics.process(v=vs.110).aspx
# Stackoverflow:
# https://stackoverflow.com/questions/24370814/how-to-capture-process-output-asynchronously-in-powershell
#smalltalk --stopOnSIGSEGV -I --quick --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"
$exe_file = 'C:\prg_sdk\stx_8\stx-8.0.0\build\stx\projects\smalltalk\stx.com'
#$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Transcript showCR: ''Kuk''. (ExternalBytes address: 10 size: 10) byteAt: 1"')
#$arguments = @('--eval', '"Transcript showCR: ''Kuk''. (ExternalBytes address: 10 size: 10) byteAt: 1"')
#$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Stdout nextPutLine: ''Kuk''. (ExternalBytes address: 10 size: 10) byteAt: 1"')
$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Stderr nextPutLine: ''Kuk''. (ExternalBytes address: 10 size: 10) byteAt: 1"')
#$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Transcript showCR: ''Kuk''"')
#$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Stdout nextPutLine:''KukOut''"')
#$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Stderr nextPutLine:''KukErr''"')
#$arguments = @('--stopOnSIGSEGV','-I','--quick','--eval', '"Transcript printCR:''KukCR''"')
$procTools = @"
using System;
using System.Diagnostics;
namespace Proc.Tools
{
public static class exec
{
public static int runCommand(string executable, string args = "", string cwd = "", string verb = "runas") {
//* Create your Process
Process process = new Process();
process.StartInfo.FileName = executable;
process.StartInfo.UseShellExecute = false;
process.StartInfo.CreateNoWindow = true;
process.StartInfo.RedirectStandardOutput = true;
process.StartInfo.RedirectStandardError = true;
//* Optional process configuration
if (!String.IsNullOrEmpty(args)) { process.StartInfo.Arguments = args; }
if (!String.IsNullOrEmpty(cwd)) { process.StartInfo.WorkingDirectory = cwd; }
if (!String.IsNullOrEmpty(verb)) { process.StartInfo.Verb = verb; }
//* Set your output and error (asynchronous) handlers
process.OutputDataReceived += new DataReceivedEventHandler(OutputStdoutHandler);
process.ErrorDataReceived += new DataReceivedEventHandler(OutputStderrHandler);
//* Start process and handlers
process.Start();
process.BeginOutputReadLine();
process.BeginErrorReadLine();
//* process.StandardOutput.ReadToEndAsync();
//* process.StandardError.ReadToEndAsync();
process.WaitForExit();
//* Return the commands exit code
return process.ExitCode;
}
public static void OutputStdoutHandler(object sendingProcess, DataReceivedEventArgs outLine) {
//* Do your stuff with the output (write to console/log/StringBuilder)
Console.WriteLine("Stdout:" + outLine.Data);
}
public static void OutputStderrHandler(object sendingProcess, DataReceivedEventArgs outLine) {
//* Do your stuff with the output (write to console/log/StringBuilder)
Console.WriteLine("Stderr:" + outLine.Data);
}
}
}
"@
# Shell has to exit after using Add-Type assembly - C# .NET limitation
$result = [Proc.Tools.exec]::runCommand($exe_file, $arguments, "C:\prg_sdk\stx_8\stx-8.0.0\build\stx\projects\smalltalk");
#Write-host $result
The testing St/X launcher for ruby:
begin
require 'open3'
rescue LoadError => e
p 'Error while loading open3.'
end
#stdout, stderr, exit_status = Open3.capture3(%q{stx.com --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"})
#stdout, stderr, exit_status = Open3.capture3(%q{stx.com --stopOnSIGSEGV -I --quick --eval "Stdout nextPutLine: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"})
#stdout, stderr, exit_status = Open3.capture3(%q{stx.com --stopOnSIGSEGV -I --quick --eval "Stderr nextPutLine: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"})
stdout, stderr, exit_status = Open3.capture3(%q{stx.com --stopOnSIGSEGV -I --quick --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"})
puts "STDOUT: " + stdout
puts "STDERR: " + stderr
puts "EXIT STATUS: " + (exit_status.success? ? 'succeeded' : 'failed')
Changed 5 years ago by
comment:5 Changed 5 years ago by
So, I did some more testing using the Ruby testing script above with
stdout, stderr, exit_status = Open3.capture3(%q{stx.com --stopOnSIGSEGV -I --quick --eval "Transcript showCR: 'Kuk'. (ExternalBytes address: 10 size: 10) byteAt: 1"})
and the stderr contained only 'Kuk'.
Then I added fflush(stderr) to debug.c and then the stderr contained 'Kuk' and the excpected message that the VM is suspended and waiting for the debugger. See the patch.
Could you please update to librun from build 172 (from my private CI) and try it with this one?
I'm sorry, I seems to be my fault after all...
comment:6 Changed 5 years ago by
I do confirm that adding fflush(stderr) fixes the issue with the message appearing again. I'm glad the launcher's code is fine for now. It is sometimes quite hard to find the source of the mistake.
During my attempts to identify the issue, I have found a space for improvement in the logging & execution part (powershell of the launcher; for all the stderr text to be also recorded in the log file. It appears only the stdout text is now being recorded.
- I'll try to create a patch for that.
- I'll also push the minor fixes for the user encoding to be obeyed also for the exception and the end separator.
comment:7 Changed 5 years ago by
I have create a completely different way of executing a code when user launches Smalltalk/X with his own switches. It uses Events in Powershell.
The advantages are:
1) completely separate
stdoutandstderr
2) asynchronous run. The output in powershell is independent form Smalltalk/X GUI.
3) will output everything to output & log file till end of the program or any crash may happend to powershell or Smalltalk/X
4) will log everything into the log file even when Smalltalk/X shows an error or asks user to run debug (e.g.dbg).
Additionally I have included all minor fixes. During these fixes I have identified a deficiency in the *batch* file options handing. I'll open separate ticket for that.
Changed 5 years ago by
| Attachment: | issue_188_from_3c054a4bb6d2_to_tip_revision.bundle added |
|---|
Mercurial patch bundle - includes all patches that were made for the asychronous behaviour + minor patches
comment:8 Changed 5 years ago by
| Status: | assigned → accepted |
|---|
comment:9 Changed 5 years ago by
| Status: | accepted → testing |
|---|
comment:10 Changed 5 years ago by
Patrik,
could you please rebase all required changes on top of e42b1ef2bc0c: Issue #184: fixed welcome message for Smalltalk/X 8.0.0 and generate the bundle again? It seems the bundle is based on some commit that is not in staging repository nor in upstream.
Changed 5 years ago by
| Attachment: | no_rebase_needed.jpg added |
|---|
Changed 5 years ago by
| Attachment: | 188_stx-projects-smalltalk-fork_1533_and_descendants.hg added |
|---|
bundle from tortoise after #184 patch
comment:11 Changed 5 years ago by
Hi Jan,
After talking to you. I now now I've been doing it against 6.x line not 8.x.x.... I really have to rebase.
Changed 5 years ago by
| Attachment: | launcher_188_bundle_smalltalk_1534_and_descendants.hg added |
|---|
launcher_188_bundle
comment:13 Changed 5 years ago by
| Status: | testing → needs_work |
|---|
I think there's a regression. Given the following invocation:
smalltalk -P "Stdout nextPutLine: 'xxx'. (ExternalBytes address: 10 size: 10) byteAt: 1"
On 211633e7aff2/stx.projects.smalltalk ("good") with NO changes to smalltalk.cfg (i.e., using the default version) I get the following (expected) output:
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
> hg log -r .
changeset: 1573:211633e7aff2
branch: jv
bookmark: master
parent: 1570:09e37fd93f8f
user: Jan Vrany <jan.vrany@fit.cvut.cz>
date: Fri Dec 29 19:49:47 2017 +0000
summary: Issue #184: fixed welcome message for Smalltalk/X 6.2.6
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
> hg diff smalltalk.cfg
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
> smalltalk -P "Stdout nextPutLine: 'xxx'. (ExternalBytes address: 10 size: 10) byteAt: 1"
"[INFO] PowerShell detected: ->TRUE<-.
"[INFO] The latest latest_powershell_version found: 2.0."
"[INFO] With the runtime being: v2.0.50727."
VERBOSE: [INFO] No log file found turning off the append mode.
VERBOSE:
VERBOSE: [INFO] Executing command: H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\stx.com "-P" "Stdout nextPutLine: 'xxx'. (ExternalBytes address: 10
size: 10) byteAt: 1" 2>&1 | Tee-Host | Out-File -Encoding UTF8 -FilePath H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\smalltalk_2018-02-01_utf8.log
-Width 150
VERBOSE: xxx
STX [error] (2018-02-01 08:29:01.424): Object [hard error]: signal 11
VERBOSE: Warning:
VERBOSE: Unexpected _error:
OS-Signal (segmentation violation)
No MiniDebugger functionality available
VERBOSE:
VM [sigsegv]: sigNo 11 context=69aab08 sp=69aaa70
VM [sigsegv]: pc=61dd1143 [4304]
VM [error] (18-02-01 08:29:01): sigsegv pc= 61dd1143
new: 2bd0000 .. 2dd0000 old: 7fff0000 .. 81ff0000
surv: 29c0000 .. 29c0000 .. 2bc0000
VM [error] (18-02-01 08:29:01): in process 5
last selector: byteAt:
last class: ExternalBytes
sigsegv 4635
sigsegv 4643
VERBOSE:
VERBOSE: [INFO] Exiting from PowerShell with code 0
VERBOSE: [INFO] End. Exiting correctly.
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
With your fixes, on revison a7fc36dbc4ba ("bad") with NO changes to smalltalk.cfg (i.e., using the default version) I get the following (incorrect) output:
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
> hg log -r .
changeset: 1580:a7fc36dbc4ba
branch: jv
bookmark: issue-188
tag: tip
user: Patrik Svestka <patrik.svestka@gmail.com>
date: Fri Jan 12 10:54:34 2018 +0100
summary: version 1.6.1 fixing stx_version_default value and adding information to version
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
> hg diff smalltalk.cfg
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
> smalltalk -P "Stdout nextPutLine: 'xxx'. (ExternalBytes address: 10 size: 10) byteAt: 1"
"[INFO] PowerShell detected: ->TRUE<-.
"[INFO] The latest latest_powershell_version found: 2.0."
"[INFO] With the runtime being: v2.0.50727."
VERBOSE: [INFO] No log file found turning off the append mode.
VERBOSE:
VERBOSE: [INFO] Creating a blank log file.
VERBOSE:
VERBOSE: [INFO] Executing command: H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\stx.com "-P" "Stdout nextPutLine: 'xxx'. (ExternalBytes address: 10
size: 10) byteAt: 1" 2>&1 | Out-File -Append -Encoding 'UTF8' -FilePath 'H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk\smalltalk_2018-02-01_utf8.log'
-Width 150
VERBOSE:
VERBOSE: [INFO] Exiting from PowerShell with code 0
VERBOSE: [INFO] End. Exiting correctly.
jv@WIN7 H:\Projects\SmalltalkX\sources\stx_8_0_0\build\stx\projects\smalltalk
As you see, with your changes no output coming from St/X itself is shown on a console. The .log file does contain the output, though.
Interestingly, when I run smalltalk with no command line arguments, I do see smalltalk output.
Now, after a quick look the difference seems to be that new version (a7fc36dbc4ba) does not use Tee-Host command.
Also, the other day you mentioned to try "asynchronous" mode, but looking to the smalltalk.cfg I found no mentioning of it so I don't know how to turn it on.
comment:14 Changed 5 years ago by
You are right, there is a regression. I'm sorry about that.
The issue is connected to the asynchronous nature of the output - the output buffer is not flushed and so it gets "eaten". I've tested it but apparently it was too simple test-case.
I'll think about the approach to take. I'll probably have to use Mutex and .flush() in order to make sure the output buffer is empty.
comment:15 Changed 5 years ago by
Jan, Here is attempt to fix the asynchronous mode. It should produce all the error messages.
Could you please try it out?
I'm now getting correctly, with the code you wrote above:
VERBOSE: [INFO] Executing asynchronously command: C:\prg_sdk\stx_8\stx-8.0.0\build\stx\projects\smalltalk\stx.com -P "Stdout nextPutLine: 'xxx'. (ExternalBytes address: 10 size: 10) byteAt: 1" | Out-File -Append -Encoding 'UTF8' -FilePath 'C:\prg_sdk\stx_8\stx-8.0.0\build\stx\projects\smalltalk\smalltalk_2018-02-05_u tf8.log' -Width 150 VERBOSE: [stdout]: xxx STX [error] (2018-02-05 12:36:17.137): Object [hard error]: signal 11 VERBOSE: Warning: Unexpected _error: VERBOSE: OS-Signal (segmentation violation) VERBOSE: VERBOSE: No MiniDebugger functionality available VM [sigsegv]: sigNo 11 context=693ab08 sp=693aa70 VM [sigsegv]: pc=61ddb323 [4304] VERBOSE: new: 27d0000 .. 29d0000 old: 7fff0000 .. 820f0000 VM [error] (18-02-05 12:36:16): sigsegv pc= 61ddb323 VERBOSE: surv: 29e0000 .. 29e0000 .. 2be0000 VM [error] (18-02-05 12:36:17): in process 5 VERBOSE: last selector: byteAt: VERBOSE: last class: ExternalBytes VERBOSE: sigsegv 4635 VERBOSE: sigsegv 4643 VERBOSE: VERBOSE: [INFO] Exiting from PowerShell with code 0 VERBOSE: [INFO] End. Exiting correctly.
With the error highlighted and written to the log file.
Changed 5 years ago by
Refix the asynchronous mode
comment:16 Changed 5 years ago by
| Status: | needs_work → testing |
|---|
comment:17 Changed 5 years ago by
Adding one more patch to the above attached bundle.
version 1.6.3
- Added new configuration option _numeric.start_sleep_in_debug for the user to adjust the refresh rate in the asynchronous mode
- Added Out.flush() and Error.Flush() so the streams are flushed
Changed 5 years ago by
| Attachment: | added_config_option_and_console_flush1552.patch added |
|---|
Adding flush to the powershell console and adding start_sleep config item
comment:18 Changed 5 years ago by
| Status: | testing → needs_work |
|---|
Patrik, I'm sorry but your latest fix - 9a0f13223e39 - suffer from the very same problem as I mentioned in comment 13.
comment:19 Changed 5 years ago by
Hi Jan,
The issue was probably that you were running powershell 2.0 which was not covered by these new patches, sorry about that. I have enabled PowerShell? 2.0 to run custom Smalltalk/X switches.
I have created a bundle from 211633e7aff2 (issue_188_from_211633e7aff2_to_tip_revision.bundle). Could you try it out if everything works for you now?
Changed 5 years ago by
| Attachment: | issue_188_from_211633e7aff2_to_tip_revision.bundle added |
|---|
Bundle from 1532:211633e7aff2
comment:20 Changed 5 years ago by
| Status: | needs_work → testing |
|---|
comment:21 Changed 5 years ago by
Excellent, latest bundle works, thanks!
However, I decided to rewrite your commit such that:
- All commits are in
jvbranch (Mercurial branch). I understand you need to branch in order to work on features for linger stretch of time, but you cand achieve kind of the same thong by using bookmarks. I have taken the decision (long time ago) to use bookmarks for that and use branch for long-term "forks". We discussed that already on a chat. - I prefixed the first line of a commit message ("summary") with "Win32 launcher:" so it's clear this commit addresses this particular part. Please do that in a future, especially when you're using your own versioning distinct from Smalltalk/X versioning (might be bit confusing at times).
Othere than that, I kept the commits as you sent them, including the author of the commit (so they;re still attributed to you). You may get these new commits by pulling from my private repositories.
Finally, no worry about already submitted patches for #191 - I'll fix them in similar manner once a get to review and test them.
comment:22 Changed 5 years ago by
| Resolution: | → fixed |
|---|---|
| Status: | testing → closed |
Fixed in series of commits
I think I understand where the issue could be. I have just two questions/requests.