oleg-shilo/cs-script

CS-Script file with async calls suddenly terminates

Closed this issue · 19 comments

UweKeim commented

This is a follow up to #326 as it uses that very .NET 7.0 NuGet package class library of mine.

Following behavior as an overview (details below):

  • Have a script with an async Main entry point.
  • Doing async/await things inside.
  • Running with latest CS-Script 4.x.
  • Suddenly the running script terminates at some point inside my own .NET 7 library. No error is printed. No nothing.

I then did this:

  • Located the automatically generated project (e.g. at "C:\Users\ukeim\AppData\Local\Temp\csscript.core\cache-361889454.build\do-deploy.cs").
  • Opened the generated .SLN file with VS 2022.
  • Compiled and run from within VS 2022.

To my surprise when running the VS 2022 compiled version, everything works as expected. No sudden termination, everything runs through successfully.

(I'm not sure whether the whole async/await is a red herring or a potential cause. I'm also not sure whether my external library might be the cause or not).

More details

This is a stripped down version of my entry script:

//css_import ..\_References\Direct\DevelopmentTools\CentralScripts\afx.cs;

using System;
using ZetaSoftware.CentralScripts;
using System.Threading.Tasks;

public static class Processor
{
    public static async Task<int> Main()
    {
        Afx.Init();
        return await Afx.RunMain(async () => await processTasks());
    }

    private static async Task processTasks()
    {
        var upl = FileSyncUtilities.CreateUploadManager();

        // Inside this call the script terminates without any error messages.
        await upl.ClearFolder(@"C:\MyPath"); 
    }
}

And this is how I call it:

CD /d %~dp0 

SET CSSCRIPT_DIR=%~dp0\..\_References\Direct\DevelopmentTools\cs-script-win

"%~dp0\..\_References\Direct\DevelopmentTools\cs-script-win\cscs.exe" /dbg "%~dp0\do-deploy.cs" %*

I placed logging statements inside my library, and also put everything inside try..catch...logging sections. Still, nothing is every printed after some function call inside my library which somehow terminates the running script immediately.

(In case it is relevant, it is a RestSharp API call to a REST endpoint).

Again, if I run the CS-Script generated .SLN from within VS, no matter whether with or without debugger, everything runs smoothly.

What I tried

I searched all kind of methods on how to get more debug information:

  • Looking into Windows Event Log.
  • Trying SysInternal Process Monitor to see what is actually getting called.
  • Using the VS Code CS-Script extension. Unfortunately it constantly made VS Code freeze with high CPU load, so it is unusable to me and I uninstalled it.

Non of this helped my in any way.

My questions

  • Can you imagine a way of why my script fails?
  • Is there some documented way to get some tracing/debbuging output of what's going on behind the scenes during actual script execution?
  • How to fix this erroneous behavior?

Update 1

I've added the following code right to the beginning of my async Main entry point:

AppDomain.CurrentDomain.FirstChanceException +=
    delegate(object? sender, System.Runtime.ExceptionServices.FirstChanceExceptionEventArgs eventArgs)
    {
        Logging.Log("First chance exception caught:");
        Logging.Log(eventArgs.Exception.Message);
        Logging.Log(eventArgs.Exception.ToString());
        Logging.Log(eventArgs.Exception.StackTrace);
    };

AppDomain.CurrentDomain.UnhandledException += 
    delegate(object sender, UnhandledExceptionEventArgs eventArgs)
{
    Logging.Log("First chance exception caught:");
    Logging.Log(((Exception)eventArgs.ExceptionObject).ToString());
};

This finally generated some error logging:

First chance exception caught:
The input string 'System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,Processor+<Main>d__0]' was not in a correct format.
System.FormatException: The input string 'System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,Processor+<Main>d__0]' was not in a correct format.
   at System.Number.ThrowOverflowOrFormatException(ParsingStatus status, ReadOnlySpan`1 value, TypeCode type)
   at System.Number.ThrowOverflowOrFormatException(ParsingStatus status, ReadOnlySpan`1 value, TypeCode type)
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()

The first error message is:

The input string 'System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,Processor+<Main>d__0]' was not in a correct format.

I'm still not sure what this means and how I could fix this. I also do not have a clue why this does not happen when compiling and running inside Visual Studio.

But at least something is printed now before my process gets terminated.

Do you have any clue what might be the cause of this behavior?

oleg-shilo commented

Hi Uwe, I have a pretty good idea of what can cause this problem.

Async Main makes very little sense in CLI as async/await model is designed to resolve UI marshalling problems in single-threaded applications. And CLI apps are not exposed to these problems.

Anyway, the script engine does not expect static Main to be async, so it is possible that it exits before the method finishes the execution.

This is the execution routine:

object retval = null;

if (method.GetParameters().Length != 0)
    retval = method.Invoke(new object(), new object[] { (Object)scriptArgs });
else
    retval = method.Invoke(new object(), null);

if (retval != null)
    try
    {
        Environment.ExitCode = int.Parse(retval.ToString());
    }
    catch { }

Of course, since async int Main is a valid syntax, cs-script must respect that. So I have updated the code and the next release will check if the return object is a task:

. . .
if (retval != null)
{
    if (retval is Task<int>)
    {
        Environment.ExitCode = (retval as Task<int>).Result;
    }
    else if (retval is Task)
    {
        (retval as Task).Wait();
    }
    else
    {
        try
        {
            Environment.ExitCode = int.Parse(retval.ToString());
        }
        catch { }
        }
    }
}

It will be available in the very next release.
Until then you can address the problem by ensuring your main is not async:

using System;
using ZetaSoftware.CentralScripts;
using System.Threading.Tasks;

public static class Processor
{
    public static int Main() => main().Result;
    
    public static async Task<int> main()
    {
        Afx.Init();
        return await Afx.RunMain(async () => await processTasks());
    }
    . . .
  • ❤️1
  • 🚀1
UweKeim commented

Thank you very much Oleg!

I've read that calling .Result to get the result of an async call might cause a deadlock.

I'm not that into async/await from a "behind the scenes" perspective, so I hope you actually are 😊 and the solution you come up with does not cause such kind of deadlocks.

Regarding your above code:

...
try
{
    Environment.ExitCode = int.Parse(retval.ToString());
}
catch { }
...

Wouldn't it be cleaner and faster to use int.TryParse instead of that try...catch block?

E.g.:

if (int.TryParse(retval?.ToString(), out var i)) Environment.ExitCode = i;
oleg-shilo commented

I've read that calling .Result to get the result of an async call might cause a deadlock.

AFAIU, it will not as it resumes in the thread-pool context. It is not a UI scenario so the whole use of async/await here is rather artificial.
Nevertheless, I have changed the implementation to use await but for readability reasons:

public async void InvokeStaticMain(Assembly compiledAssembly, string[] scriptArgs)
{
    . . .
    if (retval != null)
    {
        if (retval is Task<int>)
        {
            Environment.ExitCode = await (retval as Task<int>);
        }
        else if (retval is Task)
        {
            await (retval as Task);
        }
        else
        {
            if (int.TryParse(retval?.ToString(), out var i)
                Environment.ExitCode = i;
        }
   }

As for TryParse it was the old code before inline out var became available. It will not impact the speed (only a single call per script process) but it does read a little better.

Txs

  • ❤️1
oleg-shilo commented

Reopening it as an enhancement

  • 👍1
UweKeim commented

I've tried my initial code of this issue with the latest release 4.6.5 and still get the erroneous behavior and my script being terminated with:

First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()

Did I misunderstand this, or should 4.6.5 have fixed the issue?

This error is gone though now and does not occur anymore:

First chance exception caught:
The input string 'System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,Processor+<Main>d__0]' was not in a correct format.
System.FormatException: The input string 'System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,Processor+<Main>d__0]' was not in a correct format.
   at System.Number.ThrowOverflowOrFormatException(ParsingStatus status, ReadOnlySpan`1 value, TypeCode type)
   at System.Number.ThrowOverflowOrFormatException(ParsingStatus status, ReadOnlySpan`1 value, TypeCode type)

So something did improve, just not everything yet 🙂

Update 1

I've now tried your above suggestion with the non-async Main method:

public static int Main() => main().Result;
    
public static async Task<int> main()
{
    Afx.Init();
    return await Afx.RunMain(async () => await processTasks());
}

This made my script now finally actually work and process the async function calls inside my .NET 7 library correctly.

Still, the above exceptions still occur:

First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
  • 👀1
oleg-shilo commented

Hi Uwe,

Yes, the release contains the change that I added to address the issue you are having:

        if (retval is Task<int>)
        {
            Environment.ExitCode = await (retval as Task<int>);
        }
        else if (retval is Task)
        {
            await (retval as Task);
        }

However, that was a correct change to allow waiting in case of the async Main but.... I did not have confidence in FULLY addressing the issue.

The problem itself has nothing to do with scripting.
Imagine this scenario:

  • You have your app with async Main compiled as exe/dll.
  • Now, try to load this assembly with Assembly.LoadFrom, locate the static main with the reflection and invoke it.

I do not see how this can be done any differently (compared to the CS-Script engine implementation).

Thus I am really puzzled about this one. My personal approach would be to drop completely async from the script.
It does not make much sense to use it if there is no UI context. I suspect it is your case.

Saying that can you please share with me the script sample that exhibits the problem. I can reproduce in my environment.
If I experiment with it I might find some work around...

  • 👍1
UweKeim commented

Thanks, Oleg, I'll try to assemble an example.

I'm using a library with async methods so I do think I need to use async "all the way up", too.

UweKeim commented

I could generate the error even without having an external library.

This script:

using System;
using System.Threading.Tasks;

public static class Processor
{
    public static async Task<int>Main()
    {
        AppDomain.CurrentDomain.FirstChanceException +=
            delegate(object? sender, System.Runtime.ExceptionServices.FirstChanceExceptionEventArgs eventArgs)
            {
                Console.Out.WriteLine("First chance exception caught:");
                Console.Out.WriteLine(eventArgs.Exception.Message);
                Console.Out.WriteLine(eventArgs.Exception.ToString());
                Console.Out.WriteLine(eventArgs.Exception.StackTrace);
            };

        AppDomain.CurrentDomain.UnhandledException += 
            delegate(object sender, UnhandledExceptionEventArgs eventArgs)
        {
            Console.Out.WriteLine("First chance exception caught:");
            Console.Out.WriteLine(((Exception)eventArgs.ExceptionObject).ToString());
        };
        
        // --
        
        await Console.Out.WriteLineAsync("Start.");
        
        await Console.Out.WriteLineAsync("End.");
        return 0;
    }
}

ran with the Windows version of "cscs.exe" produces this output:

Start.
End.
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
First chance exception caught:
Object synchronization method was called from an unsynchronized block of code.
System.ApplicationException: Object synchronization method was called from an unsynchronized block of code.
   at System.Threading.Mutex.ReleaseMutex()
   at System.Threading.Mutex.ReleaseMutex()
oleg-shilo commented

Great. Thank you I was able to reproduce it.

Basically... there is no problem with either your code or script engine.

What you are printing is the information about the caught exception of the script engine synchronization algorithm:
image

  • ❤️1
oleg-shilo commented

The problem is that .NET implementation of Mutex throws when you try to System.Threading.Mutex.ReleaseMutex if it is not owned by the calling thread. A silly idea really. It should return the error if you ask me.

Thus one has either track the owned state of the mutex object (subclass it and keep instance variable synchronized) or just catch the exception. I opted for the latter technique.

But considering how much confusion it can create, I'll probably rework it to keep the locked state.

  • 👍1
UweKeim commented

This comment on Stack Overflow states the same:

Mutex has thread affinity, which means you can't use it with async code, so Semaphore is a better choice if you can use it (named Semaphores are not supported under Linux at the moment, for example).

oleg-shilo commented

Yep, it is the same.

In this case, mutex is used for process (not thread) synchronization.
And it does not trigger any problems nor fails to do the job. At least it was only 1-2 strange user reports that looked like a fundamental failure of Mutex. But it was in .NET Framework and at the phase when Microsoft and Mono team was still experimenting with their Mutex implementations. It was long time ago and since then there were no reports of any failure.

The problem you reported here is not a functional failure but an inconvenience of the Mutex API.

  • ❤️1
UweKeim commented

With v4.7.0.0 no more warnings occur.

Still, my async methods return before actually executing, when running it this way:

public static async Task<int> Main()
{
    Afx.Init();
    return await Afx.RunMain(async () => await processTasks());
}

private static async Task processTasks()
{
    // ...
}

Only way to make it working correctly is when using your suggested approach:

public static int Main() => doMain().Result;

public static async Task<int> doMain()
{
    Afx.Init();
    return await Afx.RunMain(async () => await processTasks());
}

private static async Task processTasks()
{
    // ...
}

No big deal, just a little bit "odd" 🙂.

Should this work from your point-of-view with my first example, or is it intended to always only run with a non-async Main method?

oleg-shilo commented

Interesting...

The second last code sample you shared (with await Console.Out.WriteLineAsync("End.");) does not exhibit the problem. But this one does:

public static async Task<int> Main()
{
    return await Task.Run<int>(processTasks); // wait asynchronously
}

static int processTasks()
{
    try
    {
        System.Threading.Thread.Sleep(2000);
        return 7;
    }
    finally
    {
        Console.WriteLine("Done...");
    }
}

Ironically this behaviour was caused by my change "Nevertheless, I have changed the implementation to use await but for readability reasons"

When I changed it back to Task.Result it started working as intended.

object retval = null;

if (method.GetParameters().Length != 0)
    retval = method.Invoke(new object(), new object[] { (Object)scriptArgs });
else
    retval = method.Invoke(new object(), null);

if (retval != null)
{
    if (retval is Task<int>)
    {
        // Environment.ExitCode = await (retval as Task<int>);
        Environment.ExitCode = (retval as Task<int>).Result;
    }
    else if (retval is Task)
    {
        (retval as Task).Wait();
    }
    else
    {
        if (int.TryParse(retval?.ToString(), out var i))
            Environment.ExitCode = i;
    }
}

Give me a week, I need to implement a few things for better .NET Tool" support.
I will make a new release then.

  • 👍1
  • ❤️1
oleg-shilo commented

Done. PLease get v4.7.1.0 release and it will have the change we just discussed above

  • 👍1
UweKeim commented

Works perfectly, both from my Windows CS-Script scripts, as well as from my CI/CD scripts that use CS-Script under Ubuntu Linux.

Awesome ♥️

oleg-shilo commented

Fantastic.
Glad we managed to get it to a successful outcome.

  • 👍1
  • ❤️1
UweKeim commented

Just one more question for which I don't feel to open a new issue:

Is there any hidden meaning about that assemblies1111 string at this location?:

cs-script/src/cscs/NuGet.Core.cs

Line 593 in 1e6cbc7

Console.WriteLine("Mapping packages to assemblies1111...");

I'm confused by the "1111" but on the other hand there probably is a reason which I obviously do not understand.

  • 😄1
oleg-shilo commented

LOL
image
It's just a typo. Or some leftovers after the experiments.
Fixed now.
Txs

  • 😄1