Odd behavior using First & Filter together - getting *second* record not first unless wait long time

[PhilD]

The code I'm using consistently returns the next most recent entry in a SharePoint list as opposed to the most recent one. I built out a whole screen to test this so I could see everything going on. This allowed me to determine definitively that the filter part of the function is what causes this behavior. With the filter included it fails to find the very last qualifying record. Take the filter out and it works perfectly (except I need to have the filter of course).

Sequence is run code > add a record to SP > run code again in a minute or two and see failure. 

I'm at a loss... how can a documented function behave so intermittently? How are we supposed to build reliable code blocks when the simpliest little piece of code only sometimes returns the last record?

The only other thing that helps is waiting a LONG time (like 15 minutes). Then it works the first time but executing again even a few minutes later it fails the first time again. 

The target list is brand new, containing only plain text, number and date columns. Explicitly setting the ID using LookUp easily allows me to return the correct record, just not when I find it based on the filter condition. 

So to clarify, with the filter in place in the example below, I expect to get record ID: 5 but I consistently get ID: 6. If I execute the code again, I then get the correct result (5) which appears to demonstrate that  it is not the terms of the filter but that the last record is somehow not in a state that allows it to be returned in the result set the first time the code executes (even making all the records have filter parameters that qualify does not fix further demonstrating this).

Does not work

Events 

ID	EventClass	TaskID
8	Task	983	I want
7	Task	983	I get
6	Task	983
5	Task	983

   
    //find most recent previous entry matching conditions
    Refresh(Events);
    Set(varPreviousEvent,
        First(
            Sort(
               Filter(
                    Events,
                EventClass = varCurrentEventClass, TaskID = varTask.ID),
            ID, Descending)
        )
    );

Works

Events 

ID	EventClass	TaskID
8	Task	983	I want & I get
7	Task	983
6	Task	983
5	Task	983

    Refresh(Events);
    Set(varPreviousEvent,
        First(
            Sort(
                //Filter(
                    Events,
                //EventClass = varCurrentEventClass, TaskID = varTask.ID),
            ID, Descending)
        )
    );

Some things that didn't work:

• Substituting actual values instead of variables in filter.
• Collecting the list first, then filtering the collection (collection didn't include the very last result so didn't matter).
• Refreshing before, after, before & after.
• Switching the order of the Sort & Filter statements.
• Running the same block of code twice in succession.
• Using only one filter statement, tried both separately.
  
  

Update: I just recreated another SP list and a new app and was EASILY able to recreate this issue... code only works the *second* time you click the button unless you wait several minuts. I need to use this code block on the fly to find and update records and can't have it only work sometimes, when it feels like it. I really don't know what to do... I need this simple function in dozens of places around my app. Is this a bug? 

[mr-dang]

@Drrickryp, thanks for walking through some things Phil could try. 

@PhilD, I am thinking the test to run in this case is to see the values of varCurrentEventClass and varTask.ID.

• How are the variables defined?
• Where are the variables defined? What controls, what properties?

Insert labels on the screen to show the values of those variables. Interact with your app and confirm when they should change and identify when they do not.

[PhilD]

Good morning! That's exactly what I did actually. Keep in mind that I also at one point replaced all the variables with the hard-coded values they represented, and the results were the same. Additionally, once I directly copied into a new empty shell of a app, everything worked as expected. No other changes were made to the new app before testing. that's what really made this so unbelievable was sitting there watching my test screen with the various values not updating when I know they should have.

I'm wondering if somehow design changes I made along the way could have caused this. For example originally I had used some SharePoint lookup columns until I determine that patching them was problematic when values collided.

[PhilD]

Also thanks to @Drrickryp for this little nugget.

While the code below didn't work in my original app (for reasons still unknown) it works fine in the new one (as does everything else I was doing), this is more graceful and efficient way than returning a sorted set, filtering it and then taking the first one. Thanks for suggesting a more simple way! 

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEvent,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    );

[PhilD]

Apps are reverting back to their previous unreliable state. About half the time the formula below again ignores the latest entry and returns the second latest, regardless of refreshing before, after or both... This is happening even when the lastest and second latest entry are separated by several minutes.

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEvent,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    );

[PhilD]

At this point I'm giving up on what should be one of the more simple (but extremely important) aspects of my app, recording the time from one event to another, because a few lines of code cannot be relied on to accurately return the last record in a sorted set with SharePoint as the datasource. After all this, the same behavior persists.

Just wanted to let others know. I have already invested countless hours in reproducing and documenting this behavior and ultimately recreated the apps from scratch  which seemed to provide a fix for a while (although the reason this fixed my problem was also never explained). I simply have no more time to invest on this as we need to have something usable in place.

Obviously this is an extreme disappointment and will certainly make us think twice before using PowerApps again for anything this substantial.

[Paul_C]

Hi @PhilD,

I'm sorry to hear you've been experiencing any trouble, let alone this much!

This sounds like it could be a bug, in which case we would love to fix it. 
It sounds to me, like I believe it seems to you, that the Refresh() function might not be working correctly and the Set() function might be getting executed for the Refresh() actually completes. Perhaps this is an oversimplification, though.

In any case, would you mind trying to but the Set() function in a separate button so that you can trigger it manually? So do everything normally and then, after the refresh, wait about a minute. Then click the button which has the Set() function. Does it work reliably then?

Clearly this wouldn't be a solution even if it does work, but it might go a long way to helping us understand the problem in the hopes of fixing the bug.

Also, if you wouldn't mind getting fresh session Id of a session where the issue repros, that could be helpful, as well.

[PhilD]

Thanks @Paul_C

Your assessment is spot on with the behavior I'm witnessing. I did some tests just now and tried to summarize what I'm seeing and the steps I took. I hope this helps. 

Session ID 

Session ID: e4116311-e996-475d-a7a1-72d3a278ea71
PowerApps 3.18111.15

Testing and results

Code indicated in blue is supplied at bottom of post 

• Run Full code - this code first gets the latest qualifying record and updates it before writing a brand new record.  All subsequent runs, the lookup does not "see" the latest record that was added, even after waiting several minutes between runs. 
• Run Button 1 > then wait > then run Button 2 - the lookup still does not "see" the latest record that was added. If however I run Button 2 again (without running Button 1, it returns the correct result every time). This appears to be the "smoking gun" but not sure what it means.
• Add item meeting criteria directly to SP list (Events) > then run Button 2 - the lookup still does not "see" the latest record that was added. If however I run Button 2 again (without running Button 1, it returns the correct result every time).  This is the same result as the test above.

Actual code used in test

Full code - all operations together (note highlighted block)

Set(varStartOperationTime,Now()); 

//put code below to test
//**********************************************




    //Set(varTask,LookUp(Tasks,ID=Value(TextInput_varOperation1.Text))); //set TaskID var manually
    
    Refresh(Tasks);
    Set(varTask,GalleryCurrentUserTasks.Selected); //set TaskID var the same as in prod

//SET EVENT STATUS MINUTES VARIABLES***************************************************************************
    //New
    //set the event class of the current event so we know which type to update later with the minutes in this status. choices are 'Employee' or 'Task' 

    Set(varCurrentEventClass,"Task"); // ** update to match current event class **
	
    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEvent,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    ); 

//END EVENT SET STATUS MINUTES VARIABLES***************************************************************************

    // catch errors and record to a table
    If(!IsEmpty(Errors(Events).Record),  
        Patch(
        Errors, //don't change
        {ID: Blank()}, //don't change
        {Title: "Events table error"},
        {Error: First(Errors(Events)).Error}, //don't change
        {Column: First(Errors(Events)).Column}, //don't change
        {Message: First(Errors(Events)).Message}, //don't change
        {Record: First(Errors(Events)).Record.ID}, //don't change
        {ErrorDate:Now()}, //don't change
		{App:varThisAppName}, //don't change
        {Comments:"Writing event status minutes during test operation 1"}  // ** update this to indicate current context of error **
        );
        Revert(Events)
    );

//WRITE PREVIOUS EVENT STATUS MINUTES ***************************************************************************
    //set the event's time to use in the calculation
    Set(varPreviousEventTime,varPreviousEvent.Time);
    
    // calculated minutes between previous time & now
    Set(varPreviousEventStatusMinutes,DateDiff(varPreviousEventTime,Now(),Minutes));

    //now write calculated number of minutes to previous event row determined earlier
    //Refresh(Events);
    Patch(
    Events,
    varPreviousEvent,
    {StatusMinutes:varPreviousEventStatusMinutes}
    );

//END WRITE PREVIOUS EVENT STATUS MINUTES ***************************************************************************

If(CheckboxOperation1.Value=true, //allows for testing code with and without writing a new event more easily
//WRITE NEW EVENT ***************************************************************************
    //write timestamped event for **current** update
        //Refresh(Events);
        Patch(
        Events,
        {ID: Blank()}, // faster than using "Defaults" as only one call is needed
            {Title: varThisAppName & " New Test Event Operation 1"},
            {EventClass:varCurrentEventClass}, // set earlier, no need to change
            {EventType:"New Event Test operation 1"}, // ** update this to indicate current context **
            {TaskID:varTask.ID}, // auto number row ID from SharePoint list
            {TaskStatus:"New Event Test Assigned"},    
            {EmpStatus:"New Event Test Assigned"},     
            {Time:Now()}
        );

	// catch errors and record to a table
    If(!IsEmpty(Errors(Events)), //don't change
        Patch(
        Errors, //don't change
        {ID: Blank()}, //don't change
        {Title: "Events Error"}, //don't change
        {Error: First(Errors(Events)).Error}, //don't change
        {Column: First(Errors(Events)).Column}, //don't change
        {Message: First(Errors(Events)).Message}, //don't change
        {Record: First(Errors(Events)).Record.ID}, //don't change
        {ErrorDate:Now()}, //don't change
		{App:varThisAppName}, //don't change
        {Comments:"Writing new event during test operation 1"} // ** update this to indicate current context **
        );
        Revert(Events) //don't change
    )

//END WRITE NEW EVENT ***************************************************************************

); 





//**********************************************
//put code above to test
Set(varEndOperationTime,Now()); //don't change this
Set(varOperationSeconds,DateDiff(varStartOperationTime,varEndOperationTime,Milliseconds))//don't change this

Button 1 (highlighted code removed)

Thanks @Paul_C



Your assessment is spot on with the behavior I'm witnessing. The difficult thing is getting it to reliably repeat in order to troubleshoot. I'm fairly certain that I already performed the operations in separate operations as you suggested and it proved to fix the issue but I am going to perform the test again. I will provide an update and session info if I can reproduce.



Session ID of app after recreating the issue at 11/20/2008 10:14 am EST

Session ID: e4116311-e996-475d-a7a1-72d3a278ea71
PowerApps 3.18111.15


Full code - all operations together

Set(varStartOperationTime,Now()); 

//put code below to test
//**********************************************




    //Set(varTask,LookUp(Tasks,ID=Value(TextInput_varOperation1.Text))); //set TaskID var manually
    
    Refresh(Tasks);
    Set(varTask,GalleryCurrentUserTasks.Selected); //set TaskID var the same as in prod

//SET EVENT STATUS MINUTES VARIABLES***************************************************************************
    //New
    //set the event class of the current event so we know which type to update later with the minutes in this status. choices are 'Employee' or 'Task' 

    Set(varCurrentEventClass,"Task"); // ** update to match current event class **
	


//END EVENT SET STATUS MINUTES VARIABLES***************************************************************************

    // catch errors and record to a table
    If(!IsEmpty(Errors(Events).Record),  
        Patch(
        Errors, //don't change
        {ID: Blank()}, //don't change
        {Title: "Events table error"},
        {Error: First(Errors(Events)).Error}, //don't change
        {Column: First(Errors(Events)).Column}, //don't change
        {Message: First(Errors(Events)).Message}, //don't change
        {Record: First(Errors(Events)).Record.ID}, //don't change
        {ErrorDate:Now()}, //don't change
		{App:varThisAppName}, //don't change
        {Comments:"Writing event status minutes during test operation 1"}  // ** update this to indicate current context of error **
        );
        Revert(Events)
    );

//WRITE PREVIOUS EVENT STATUS MINUTES ***************************************************************************
    //set the event's time to use in the calculation
    Set(varPreviousEventTime,varPreviousEvent.Time);
    
    // calculated minutes between previous time & now
    Set(varPreviousEventStatusMinutes,DateDiff(varPreviousEventTime,Now(),Minutes));

    //now write calculated number of minutes to previous event row determined earlier
    //Refresh(Events);
    Patch(
    Events,
    varPreviousEvent,
    {StatusMinutes:varPreviousEventStatusMinutes}
    );

//END WRITE PREVIOUS EVENT STATUS MINUTES ***************************************************************************

If(CheckboxOperation1.Value=true, //allows for testing code with and without writing a new event more easily
//WRITE NEW EVENT ***************************************************************************
    //write timestamped event for **current** update
        //Refresh(Events);
        Patch(
        Events,
        {ID: Blank()}, // faster than using "Defaults" as only one call is needed
            {Title: varThisAppName & " New Test Event Operation 1"},
            {EventClass:varCurrentEventClass}, // set earlier, no need to change
            {EventType:"New Event Test operation 1"}, // ** update this to indicate current context **
            {TaskID:varTask.ID}, // auto number row ID from SharePoint list
            {TaskStatus:"New Event Test Assigned"},    
            {EmpStatus:"New Event Test Assigned"},     
            {Time:Now()}
        );

	// catch errors and record to a table
    If(!IsEmpty(Errors(Events)), //don't change
        Patch(
        Errors, //don't change
        {ID: Blank()}, //don't change
        {Title: "Events Error"}, //don't change
        {Error: First(Errors(Events)).Error}, //don't change
        {Column: First(Errors(Events)).Column}, //don't change
        {Message: First(Errors(Events)).Message}, //don't change
        {Record: First(Errors(Events)).Record.ID}, //don't change
        {ErrorDate:Now()}, //don't change
		{App:varThisAppName}, //don't change
        {Comments:"Writing new event during test operation 1"} // ** update this to indicate current context **
        );
        Revert(Events) //don't change
    )

//END WRITE NEW EVENT ***************************************************************************

); 





//**********************************************
//put code above to test
Set(varEndOperationTime,Now()); //don't change this
Set(varOperationSeconds,DateDiff(varStartOperationTime,varEndOperationTime,Milliseconds))//don't change this

Button 2 (removed highlighted code run in separate operation)

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEvent,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    ); 

[Paul_C]

Thanks @PhilD!

Two interesting things to try separately:

A) Try repeating the Refresh command multiple times. E.g.:

Button 2 

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Refresh(Events);
    Set(varPreviousEvent,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    ); 

 (maybe even try 3 or 4 times, just to see if it behaves differently) 

B) What I originally meant was to put the Refresh and the Set in different buttons, for instance:

Button 2 

Refresh(Events);

<Long manual delay after clicking Button2 but before clicking Button3>

Button 3 

    Set(varPreviousEvent,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    ); 

These two things will help test if the problem is the next line of code running before Refresh() finishes (B)) or if it's some weird issue where refresh needs to happen twice (A)).

[PhilD]

Thank you @Paul_C... I have answers to your questions and some additional info that I think will be helpful.

Answer to your questions

A) I had tried this in my previous testing but did it again. This has no affect, even if the refresh line is repeated many times.

B) I separated the operations as you suggested and it still behaved the same.

New info/results

I think I have found a "smoking gun". Repeating the refresh either in or outside the operation has no affect but repeating the entire lookup over makes a difference. 

I built this with four separate variables, in four separate lookups, that were repeated one after the other in the same operation with the refresh happening at different places as noted in the steps below.

1. With a refresh occurring before all four lookups - first pass failed, subsequent passes successful.
2. Same but with no refresh on any of the lookups - all passes failed.
3. Same but with refresh only on fourth pass of the lookup - all passes failed.
4. Same but with refresh only on first pass of the lookup - all passes failed.
5. Same but with refresh only on first & fourth pass of the lookup - all passes failed.
6. With a refresh occurring before all four lookups (code shown below in code window) - first pass failed, subsequent passes successful (same as #1 repeated to ensure nothing had changed).
7. Same but with refresh only on first & second  pass of the lookup - first pass failed, subsequent passes successful.
8. Same but with refresh only on first & third pass of the lookup - all passes failed.
9. Same but with refresh only on first, second & fourth pass of the lookup - first pass failed, subsequent passes successful.

• Separately refreshing between any of these did not change the results above.
• Waiting for a period of time did affect things... for example, for # 7 above if I waited around 7 minutes from the last test, all passes were successful (even the first one)!

I was very careful to record these results accurately. It does appear that in addition to the sequence of the code, that the time in between execution is playing a role as well making this even more difficult to troubleshoot in actual use.

Bottom line, a lookup should find the last record without having to wait 7-10 minutes. Unless the lookup was executed literally at the exact moment the record was added (before the write was complete) it should be found, similar to the way a gallery can display it moments after it is added.

In any event, I hope this is helpful and looking forward to hearing from you.

Code

Relevant part of "Operation 1" button code used for the steps above. 

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEventFirstPass,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    );

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEventSecondPass,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    );

        //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEventThirdPass,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    );

    //find last qualifying record by looking up the first one in a sorted, filtered set
    Refresh(Events);
    Set(varPreviousEventFourthPass,
        LookUp(Sort(Events,ID, Descending),               
            EventClass = varCurrentEventClass && TaskID = varTask.ID
        )
    );

Example

This shows step 1 results from above

Session info

Session ID: 09994b95-6acb-4207-a42b-3101d494e4d4
PowerApps 3.18111.15

[Paul_C]

Thank you, @PhilD!

The behavior is strange and hard to reproduce, which makes it hard for us to investigate the issue. You've provided a ton of information for us though, thank you once again! I'm going to let the area experts for this part of the product investigate with the information you've genrously provided.