Start a subprocess in the Before hook, get terminal control characters in its output

[mikavilpas]

Hi, I'm using ecukes for omnisharp-emacs, and it's a great fit. The project used to work with a local http server and all tests would run fine. Now I'm adding support for having the server as a subprocess, and communicating with the process's input and output streams.

I'm running into a problem where the subprocess gets as its input some control characters, like ^[[6n and ^[[?1h^[=^[[6n. The output of the subprocess is json data, and these cause problems with deserialization. They also don't occur when running emacs interactively, that is, "normally".

I'm a bit confused by this. Would you have any idea what to do about these characters?

[mikavilpas]

Here's a small batch of my test output where you can see the position of the characters.

{"Event":"log","Body":{"LogLevel":"INFORMATION","Name":"OmniSharp.ScriptCs.ScriptCsProjectSystem","Message":"Detecting CSX files in '/home/mika/git/omnisharp-emacs/test/MinimalSolution'."},"Seq":8,"Type":"event"}
{"Event":"log","Body":{"LogLevel":"INFORMATION","Name":"OmniSharp.ScriptCs.ScriptCsProjectSystem","Message":"Could not find any CSX files"},"Seq":9,"Type":"event"}
{"Event":"log","Body":{"LogLevel":"INFORMATION","Name":"OmniSharp.Startup","Message":"Solution has finished loading"},"Seq":10,"Type":"event"}
{"Event":"started","Body":null,"Seq":11,"Type":"event"}
�[?1h�=�[6n{"Event":"ProjectAdded","Body":{"MsBuildProject":{"ProjectGuid":"3b841abf-eea2-4be2-b14f-20ee639f10bf","Path":"/home/mika/git/omnisharp-emacs/test/MinimalSolution/minimal/minimal.csproj","AssemblyName":"minimal","TargetPath":"@(_OutDirItem->'%(FullPath)/$(TargetFileName)')","TargetFramework":".NETFramework,Version=v4.0","SourceFiles":["/home/mika/git/omnisharp-emacs/test/MinimalSolution/minimal/MyClass.cs","/home/mika/git/omnisharp-emacs/test/MinimalSolution/minimal/MyClassContainer.cs"]},"DnxProject":null},"Seq":12,"Type":"event"}
{"Event":"ProjectChanged","Body":{"MsBuildProject":{"ProjectGuid":"3b841abf-eea2-4be2-b14f-20ee639f10bf","Path":"/home/mika/git/omnisharp-emacs/test/MinimalSolution/minimal/minimal.csproj","AssemblyName":"minimal","TargetPath":"@(_OutDirItem->'%(FullPath)/$(TargetFileName)')","TargetFramework":".NETFramework,Version=v4.0","SourceFiles":["/home/mika/git/omnisharp-emacs/test/MinimalSolution/minimal/MyClass.cs","/home/mika/git/omnisharp-emacs/test/MinimalSolution/minimal/MyClassContainer.cs"]},"DnxProject":null},"Seq":13,"Type":"event"}
�[H�[2J�[6n"Arguments":{"FileName":"\/home\/mika\/git\/omnisharp-emacs\/test\/MinimalSolution\/minimal\/MyClassContainer.cs", "Line":"7", "Column":"13", "Buffer":"using System;\n\nnamespace minimal\n{\n    public class Target {}\n    public class JumpSite {\n        Target foo; \/\/ go to definition from here\n    }\n}"}, "Command":"updatebuffer", "Seq":1}
�[6n{"Request_seq":1,"Command":"updatebuffer","Running":true,"Success":true,"Message":null,"Body":true,"Seq":14,"Type":"response"}
{"Event":"log","Body":{"LogLevel":"INFORMATION","Name":"OmniSharp.Middleware.LoggingMiddleware","Message":"/updatebuffer: 200 78ms"},"Seq":15,"Type":"event"}
{"Arguments":{"FileName":"\/home\/mika\/git\/omnisharp-emacs\/test\/MinimalSolution\/minimal\/MyClass.cs", "Line":"9", "Column":"10", "Buffer":"using System;\n\nnamespace minimal\n{\n    public class MyClass\n    {\n        public MyClass ()\n        {\n        }\n    }\n}"}, "Command":"updatebuffer", "Seq":2}
�[6n{"Request_seq":2,"Command":"updatebuffer","Running":true,"Success":true,"Message":null,"Body":true,"Seq":16,"Type":"response"}
{"Event":"log","Body":{"LogLevel":"INFORMATION","Name":"OmniSharp.Middleware.LoggingMiddleware","Message":"/updatebuffer: 200 1ms"},"Seq":17,"Type":"event"}

[rejeep]

It might have to do with how Espuds works as it tries to do thing as similar to a real human as possible. How are you communicating with the process? If you are using things like process-send-string, this seems a bit odd.

[mikavilpas]

Yes, I'm using process-send-string. I have a process filter function that parses the output from the process.

As the process output is asynchronous, I created this helper function to wait or timeout a request. I think waiting might have something to do with the error (just a guess).

Here's the way it works just in case it's useful: I have a global alist of response handler functions stored. Each request gets associated a handler when it's sent to the background process, and when a response comes, the handler is removed.

Using this I detect which requests are completed:

(defun omnisharp--wait-until-request-completed (request-id
                                                &optional timeout-seconds)
  (setq timeout-seconds (or timeout-seconds 2))

  (let ((start-time (current-time)))
    (while (omnisharp--handler-exists-for-request request-id)
      (when (> (cadr (time-subtract (current-time) start-time))
               timeout-seconds)
        (progn
          (let ((msg (format "Request %s did not complete in %s seconds"
                             request-id timeout-seconds)))
            (omnisharp--log msg)
            (error msg))))
      (accept-process-output nil 0.01)))
  request-id)

The waiting code I essentially copied from the cider emacs package for clojure development. I originally used with-timeout but had the same problem with that.

Now I switched to using buttercup and the problem is gone, so I think your guess might be right.

[mikavilpas]

I ran the tests using TERM=xterm cask exec ecukes --no-win --quiet using a bash script, in case it makes a difference.