Wild Horses on Missouri Creek

A few days ago, we found this bay stallion with his two mares just over the Colorado border on Missouri Creek near Dragon, Utah, an old gilsonite mining ghost town. As we stopped to watch them, he nervously paced back and forth protecting the mares that had trotted away when we pulled up. I was impressed by his defiance of the threat and his willingness to protect his own.

His beautiful bay coat is covered in dry mud which I'm sure was a cool roll in a recent rain slicked earth. The black mane and overall conformation makes me think he's descended from a fine Morgan line.

I wonder if we look out for those we love as well as this amazing stallion does his small harem. Are we willing to stand up to forces we do not recognize or understand? Do we overcome our own fears to watch over those who rely upon us? What can we learn from the Stallion of Missouri Creek?

HttpContext and Logging to Elasticsearch on a Background Thread

“HttpContext is not thread-safe. Reading or writing properties of the HttpContext outside of processing a request can result in a NullReferenceException.” (from docs.microsoft.com)

image

I am a big fan of Elasticsearch (ELK) logging and have built this into the Ioka.Services.Foundation using the Serilog libary, my current favorite .NET Core logging library. There are many ways to approach this and my intent is not to explore those but to show one way of taking on the task of logging in a background thread while preserving some request context detail in your log.

Following the recommendation on the above docs page, we copy the elements of the HttpContext that we need for our background thread logging using the LogContextFactory. Here’s a snippet of that code. For your scenario, you’ll want to modify what values you wish to preserve and you may wish to remove the fairly heavy duty user agent parser if you don’t care about seeing user agent data broken down in the log message.

public static LogContext Create(HttpContext context)
{
   return CreateFactory(() => context)();
}

public static Func CreateFactory(Func httpContextFactory)
{
   if (null == httpContextFactory) throw new ArgumentNullException(nameof(httpContextFactory));
   return new Func(() =>
   {
      try
      {
         var httpCtx = httpContextFactory();
         var httpRequestFeature = httpCtx.Request.HttpContext.Features.Get();
         var context = new LogContext();
         context["_ThreadId"] = Environment.CurrentManagedThreadId.ToString(); 
         context["_Source"] = Assembly.GetEntryAssembly().GetName().Name;
         context["_IpAddress"] = httpCtx.Connection.RemoteIpAddress.ToString();
         context["_UserId"] = httpCtx.Request.Headers["APPUID"].Count > 0 
            ? httpCtx.Request.Headers["APPUID"][0] 
            : context["_UserId"];
         context["_HttpMethod"] = httpCtx.Request.Method;

In the controller we call the Create method to get a copy of what we need to pass into the background thread async method called DoMathWithLogging (cheesy name for demo purposes only) like this:

public async Task<ActionResult<IEnumerable<string>>> Get()
{
    var msg1 = "Another message";
    var msg3 = new CustomError { Name = "Second", Message = "Second other message" };
    _logger.Debug("This is a debug message. {msg1}, {@msg3}", msg1, msg3);

    var logContext = LogContextFactory.Create(this.HttpContext);
    var result = await _mathDemoProvider.DoMathWithLogging(logContext, _logger);

    return new string[] 
    {
        logContext["_UserId"],
        logContext["_RequestId"],
        result.ToString()
    };
}

Now in the DoMathWithLogging method, we use the ILog interface With method to pass the LogContext object into the logger to preserve what we have copied from HttpContext to the LogContext object.

public async Task<long> DoMathWithLogging(LogContext logContext, ILog logger)
{
    long x = 0;
    try
    {
        var rand = new Random();
        for (int i = 0; i < 10; i++)
        {
            x = 1000 * (long)rand.NextDouble();
            Thread.Sleep(10);
        }
        Thread.Sleep(100);
        var c = 0;
        x = 77 / c;
    }
    catch (Exception e)
    {
        //uses new logger with saved context as this 
        //is not on the request background thread
        logger.With(logContext).Error(e, "Error: value of {LargeValue}", x);
    }
    return x;
}

Note that in our demo code, we deliberately throw a divide by zero error and log it. And now in the implementation of the With method looks like this, capturing the current thread in the “_ThreadId-With” property on the context.

public ILog With(LogContext context)
{
    context["_ThreadId-With"] = Environment.CurrentManagedThreadId.ToString();
    var list = _enrichers.Where(x => x.GetType() != typeof(LogEnricher)).ToList();
    list.Insert(0, new LogEnricher(context, null));
    return new Log(_config, _level, () => _index, _failureSink, _failureCallback, list.ToArray());
}

In the With method, we insert a new log enricher for the Serilog logger. This allows us to capture the copied context values in the log messages, such as the Error logged like this:

{
  "_index": "test",
  "_type": "logevent",
  "_id": "JAdXF2oB9fWPG6gy8H_9",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2019-04-13T15:36:40.2296224+00:00",
    "level": "Error",
    "messageTemplate": "Error: value of {LargeValue}",
    "message": "Error: value of 0",
    "exception": {
      "Depth": 0,
      "ClassName": "",
      "Message": "Attempted to divide by zero.",
      "Source": "Ioka.Services.Demo",
      "StackTraceString": "   at Ioka.Services.Demo.Providers.MathLoggingDemoProvider.DoMathWithLogging(LogContext logContext, ILog logger) in D:\\Code\\Github\\Ioka.Services.Foundation\\src\\Ioka.Services.Demo\\Providers\\MathLoggingDemoProvider.cs:line 30",
      "RemoteStackTraceString": "",
      "RemoteStackIndex": -1,
      "HResult": -2147352558,
      "HelpURL": null
    },
    "fields": {
      "LargeValue": 0,
      "_UserId": "root",
      "_IpAddress": "::ffff:172.18.0.1",
      "_Source": "Ioka.Services.Demo",
      "_MachineName": "6cf7fdb5f3cf",
      "_ThreadId": "14",
      "_HttpMethod": "GET",
      "_RequestId": "50d32de9-df69-4aee-ae48-075f22b8ac2d",
      "_Url": "https://localhost:44370/api/Values",
      "_Query": "Microsoft.AspNetCore.Http.Internal.QueryCollection",
      "_WebUser": null,
      "_Browser": "Chrome 73.0.3683 Windows 10",
      "_Header_Connection": "keep-alive",
      "_Header_Accept": "text/plain",
      "_Header_Accept-Encoding": "gzip, deflate, br",
      "_Header_Accept-Language": "en-US,en;q=0.9",
      "_Header_Host": "localhost:44370",
      "_Header_Referer": "https://localhost:44370/api-docs/index.html",
      "_Header_User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36",
      "_ThreadId-With": "14"
    }
  },
  "fields": {
    "@timestamp": [
      "2019-04-13T15:36:40.229Z"
    ]
  },
  "sort": [
    1555169800229
  ]
}

Note the "_ThreadId-With" property above has the same vs!he as the request thread is. This is because not all async methods will run on a background thread. In previous versions of this code, I forced a long running task to spin up on another thread to verify this. Generally I would not recommend that in practice.

Also note the "_RequestId" property which would allow you to filter in Kibana for all entries with that value in order to trace all log entries for a given request. This can be a very useful tool when you're trying to figure out what happened.

This is the first of many upcoming posts on the code and use of the Ioka.Services.Foundation. The code base is not intended for production use but to provide a guide when you create your own internal libraries to spin up a set of .NET Core microservices that have a common set of fundamental elements that will make working on them, supporting them and using them easier.

Be Not Afraid

In Matthew chapter 25, Jesus relates the parable of the talents. A talent then was a great deal of money. One received five, another two and another one. When their master returned to see what they had done, he found the first two had been faithful and worked hard to improve their lot. The third responded thus:

"And I was afraid, and went and hid thy talent in the earth:" (verse 25)

Let us not be afraid. Let us go and do as the Lord has commanded us. Let us use the gifts he has given us, exercising faith to act and minister to the needs of others. If we set aside our fear, we will be blessed as we build on our faith to serve the Lord and his children.

Trying to Be a Latter-day Saint

The name of the church I attend is The Church of Jesus Christ of Latter-day Saints.

Paul called the members of the church in the meridian of time saints. Those who believed in Christ and sought to understand and practice the gospel of repentance which he had taught were known then as saints. Not because they had performed miracles but because they relied on the miracles of Christ, especially that of the Atonement.

They were not perfect. Nor are his latter-day saints. As we strive to become like him, let us remember the words of one who serves him.

“If we don’t try, we’re just latter-day sinners; if we don’t persevere, we’re latter-day quitters; and if we don’t allow others to try, we’re just latter-day hypocrites” ~Dale G. Renlund, a member of the Quorum of the Twelve Apostles.

And They Followed Him

While Jesus and his disciples were leaving Jericho, there were two blind men sitting by the road. Think of them as ourselves. Are we too blind?

These men called out to Jesus and begged for mercy. He stopped and asked them what they wanted him to do for them. Of course they asked to receive their sight. Matthew records the Master's response in this way.

Matthew 20:34 (KJV): "So Jesus had compassion on them, and touched their eyes: and immediately their eyes received sight, and they followed him."

In such a short sentence Matthew conveys some great lessons. First, is the Lord's great capacity for compassion. Second, that Christ will touch those on whom he has compassion. Third, that we can receive immediate blessings from Him through faith. And finally, that the mark of true disciples who have received their sight is that they follow Him.

Do you call out to Him in faith? Will you see? Will you follow Him?

Recognize the Lord in Our Lives

When Jesus entered Jerusalem for the last time, he looked out upon her and wept for its wickedness and imminent destruction. These were his people and they, except for a few, had not recognized him, as had been prophesied, yet he had compassion on them.

Luke 19 (KJV)

41 ¶ And when he was come near, he beheld the city, and wept over it,

42 Saying, If thou hadst known, even thou, at least in this thy day, the things which belong unto thy peace! but now they are hid from thine eyes.

43 For the days shall come upon thee, that thine enemies shall cast a trench about thee, and compass thee round, and keep thee in on every side,

44 And shall lay thee even with the ground, and thy children within thee; and they shall not leave in thee one stone upon another; because thou knewest not the time of thy visitation.

I hope that we will each learn to recognize the works of the Lord in our own lives, that we will embrace him and love to serve him as we serve others.

Take a moment today to recognize someone in your path as one you can lift a little with a kind word or a hug. Listen for a moment and see them as the Lord might. Then you will bring a little of the Lord's peace into their life and your life.

We Are Made Alive in Christ

"...we are made alive in Christ because of our faith; yet we keep the law because of the commandments. And we talk of Christ, we rejoice in Christ, we preach of Christ, we prophesy of Christ, and we write according to our prophecies, that our children may know to what source they may look for a remission of their sins." ~2 Nephi 25:25-26 (Book of Mormon)

We are God's children living in a fallen mortal state where we are tested that we might prove worthy to return and live with him. But we all fall short. We are not perfect as we must be to live with God. In His infinite wisdom God provided a plan whereby we might overcome our imperfections. This great plan of happiness requires a saviour to step forward and pay the price for our sins. God's firstborn in the spirit stepped forward and said, "Here am I. Send me."

It is through the grace of his atoning sacrifice that we may be made clean and worthy to enter into God's kingdom. I am so grateful for this blessing in our lives. Let us embrace our Saviour Jesus Christ and follow him in every way we can.

Seeking Something Better

The idea of "Something Better" has been on my mind lately. In life, work, everything. There is much good to choose from. How do we choose the better part? How do we store up that which moth nor rust can corrupt?

I read these words of Christ today: "But rather seek ye the kingdom of God; and all these things shall be added unto you... For where your treasure is, there will your heart be also." ~Mark 12:31,34 (KJV)

As we ask ourselves, which is better, let us keep in mind those words. Which thing sets me on the path to find and build the kingdom of God? Let us seek the Lord's guidance in all that we do and then do that something better.