Can you post your code of the scheduled job here?

Out of my head, it might be possible that the items do not have enough items in inventory to support the order. Did you check that? 

public override string Execute()
        {

            Thread.CurrentThread.CurrentCulture = new CultureInfo("nb-NO");

            OnStatusChanged(String.Format("Starting execution of {0}", this.GetType()));

            int orderCounter = 0;

            var orderResult = SearchClient.Instance.Search<HistoricalOrder>()
                .Filter(x => x.OrderCompleted.Match(false)).Take(1000).GetResult();

            
            if (orderResult != null && orderResult.Count() > 0)
            {
                var shippingService = ServiceLocator.Current.GetInstance<IShippingService>();
                var orderRepository = ServiceLocator.Current.GetInstance<IOrderRepository>();
                
                foreach(var order in orderResult)
                {
                    try
                    {
                        var trackingNumbers = shippingService.GetTrackingByOrderReference(order.OrderNumber);
                        if (trackingNumbers != null && trackingNumbers.Count > 0)
                        {
                            order.OrderTrackingNumbers = trackingNumbers;

                            SearchClient.Instance.Index(order);

                            orderCounter++;

                            var purchaseOrder = OrderContext.Current.GetPurchaseOrder(order.OrderNumber);
                            

                            if(purchaseOrder != null)
                            {                                
                                var statusChanges = false;

                                foreach(var shipment in purchaseOrder.OrderForms.First().Shipments)
                                {
                                    if(OrderStatusManager.GetOrderShipmentStatus((Shipment)shipment) != OrderShipmentStatus.Shipped)
                                    {
                                        OrderStatusManager.CompleteOrderShipment((Shipment)shipment);
                                        statusChanges = true;
                                        
                                    }
                                }

                                if (statusChanges)                                
                                    orderRepository.Save(purchaseOrder);
                                
                                //Semi-crude method of detecting if order is complete
                                //for the purposes of this job. 

                                if(purchaseOrder.OrderForms.First().Shipments.Count == order.OrderTrackingNumbers.Count)
                                {
                                    order.OrderCompleted = true;
                                    order.DeliveryStatus = purchaseOrder.Status;
                                    SearchClient.Instance.Index(order);

                                    foreach(var shipment in purchaseOrder.GetFirstForm().Shipments)
                                        ArchiveProducts((Shipment)shipment);
                            }

                            }

                        }
                    }
                    catch (Exception ex)
                    {
                        var logService = ServiceLocator.Current.GetInstance<ILogService>();

                        logService.Log("Error updating order", "UpdateOrderStatus-job", ex, LogLevels.Error);
                        logService.Log("Offending order: " + order.Id + " " + order.OrderNumber, LogLevels.Error);
                    }
                }
            }


            //For long running jobs periodically check if stop is signaled and if so stop execution
            if (_stopSignaled)
            {
                return "Stop of job was called";
            }

            return String.Format("Job completed, {0} orders updated", orderCounter);
        }


        /// <summary>
        /// Shipments collected in store should be exempt when
        /// counting shipments towards tracking numbers
        /// </summary>
        /// <param name="shipments"></param>
        /// <returns></returns>
        private int NonCollectInStoreShipmentCount(ShipmentCollection shipments)
        {
            return shipments.Count(x => x.ShippingMethodName != "Hent i butikk");
        }


        private void ArchiveProducts(Shipment shipment)
        {
            if(_startPage.ProductArchive != null)
            {                
                foreach (var item in shipment.LineItems)
                {
                    var content = _referenceConverter.GetContentLink(item.Code);

                    if (content != null)
                    {
                        _contentRepository.Move(content, _startPage.ProductArchive, AccessLevel.NoAccess, AccessLevel.NoAccess);
                    }
                }
            }

            
        }

It has occured to me that the problem might be inventory related - but at the time of job execution the stock is succesfully reserved, and can not be in conflict with other orders (since every SKU only has a stock of one, it's not available to other customers from the point of entering checkout). 

Also, stock or no stock, what possible logic is there in removing lineitem from an order that is already paid by customer? The order totals are correct on the affected orders even after line item(s) are removed. 

If this turns out to be the case - would this be resolved by enabling back-orders for the items? I mean we would still have the problem with why the assigned stock fails, but at least maybe the lineitems won't vanish. 

That is very strange, IOrderRepository.Save should not make change to the order like that. Can you add log to your scheduled job - preferrably serialize your order into json - before and after the save? 

I agree that this is very strange. At first I thought that the line items were in some workflow triggered by OrderstatusManager.CompleteOrdershipment, so I added a check that compared lineitem count of shipments before and after that call, but nothing was being removed there.

Also, when capturing the payment we send the line items to the payment provider (DIBS) and they're not removed at the time of capture. 

The save is the last thing that happens to the order (and we don't touch it afterwards), so I can't imagine another explanation. 

I'll add the logging you requested and wait for it to happen again, but in the mean time if there are any conditions that would cause this to happen (I guess in the Save-method of the PurchaseOrderProvider?) we'd love to know. 

The LineItems must be explicitly removed, by calling certain workflows, or by some APIs like UpdateInventoryOrRemoveLineItem. Unless you have a custom provider, then the default provider should not remove any lineitems 

Jørgen, do you still have any of the "broken" orders available?

I was thinking that it could be of use to inspect its data that I blog about here: https://world.episerver.com/blogs/jafet-valdez/dates/2018/6/tools-of-the-trade---diagnosing-orders-with-errors/

One thing to look for is if the LineItems that are missing in CM/UI still exist in the database. Run the script and check if you see anything odd about those orders.

Jafet, sure, we still have the broken orders. Tried reproducing the error again after adding the logging Quan requested - we're at 40 orders with no errors, so kind of frustrating. 

I'll try looking at the data using your information tomorrow, thanks a lot for the suggestion :)

Quan - so we finally figured this one out, and it's a weird one, to be sure. 

The problem happens on rare occations and occurs when the workflow for validating LineItems runs upon order completion (by excecution of OrderStatusManager.CompleteOrderShipment) - ValidateLineItemsActivity.ValidateItems. 

The check that decides the LineItem should be removed is this one: 

if (!entryRow.IsActive || requestDate < minAvailableDate || requestDate > entryRow.EndDate)
{
	AddWarningSafe(Warnings, "LineItemRemoved-" + lineItem.LineItemId.ToString(),
	String.Format("Item \"{0}\" has been removed from the cart because it is not available.", LineItem.DisplayName));
	lineItemsToRemove.Add(lineItem);
                        
	continue;
}

The reason why the check fails is that requestDate is (at least some times) wrong. This comes from FrameworkContext.Current.CurrentDateTime and should be the current time as UTC, but this is not always correct in our experience. 

For instance a variant was added and published 26.06.18 - 14.57 local time. Database shows 12.57 UTC as the time of availability both in price, inventory and publish date. Customer buys the product 15.01 local time and LineItem is removed in the order completion process. 

Our logs show that requestDate from FrameworkContext was 27.06.2018 11.28.37 (which is completely wrong, regardless of UTC), whereas the time stamp of the log was 2018-06-27T13:01:11.1106243Z (Z meaning zulu or UTC) which is correct. 

The check then, decides that request is earlier than allowed point of sale and deletes the LineItem. 

It should be mentionet that the site is running as an Azure App Service and the code is executed in a scheduled job. Time Zone is set to W.European in Application Settings for the App Service.

I have no idea what causes FrameworkContext to return the wrong time, but the biggest problem - and what I find to be a major design flaw - is that the workflows will continue to capture the order for the full amount (after removing the line item, leaving no log or message as to what has happened) - I can think of absolutely no scenario where this could possibly be the desired outcome. 

So I was right after all ;). IOrderRepository did not do it. OrderStatusManager.CompleteOrderShipment (via a workflow) does. But nice investigation regardless - good job.

Now back to the main question - why. FrameworkContext.Current is stored in HttpContext if it presents, or an internal field if it does not. The problem is your scheduled job is most likely run without a HttpContext, therefore FrameworkContext.Current will be created one and reused in a static field. That's why the time is so off.

I can't remember why it was there at the first place - it was possible that we want to have something that is consistent in the entire request. But it has the pitfall as above - and we should fix it regardless.

You didn't mention your exact version, but a workaround is to modify the activity and make sure it use DateTime.UtcNow instead of FrameworkContext.Current.CurrentDateTime 

Thanks for the clarification :) 

The reason I initially believed IOrderRepository to be the cause was because I had set the code up to throw an exception if the LineItem total count across the shipments was different before/after CompleteOrderShipment - this exception was never thrown for some reason. 

Anyway, it's good to finally have resolved this. Thanks for all the quick responses, Quan!

This is fixed in Commerce 12.8.0, which will be released shortly (any minute now) :) 

Commerce 12.8.0 is available now