OfficeDev / office-js

A repo and NPM package for Office.js, corresponding to a copy of what gets published to the official "evergreen" Office.js CDN, at https://appsforoffice.microsoft.com/lib/1/hosted/office.js.
https://learn.microsoft.com/javascript/api/overview
Other
686 stars 95 forks source link

When item changes happens during custom properties save, library sends the latest itemId to the server instead right one. #2769

Closed repl-kannan-d closed 1 year ago

repl-kannan-d commented 2 years ago

Provide required information needed to triage your issue

Your Environment

Expected behavior

If itemchanged after save custom properties request initiated, then request should go against previous itemId instead latest or current one.

Current behavior

If itemchanged after save custom properties request initiated, then request goes against the latest or current itemId.

Steps to reproduce

Below is the logs that i have added for troubleshooting.

Background: We are implementing taskpaneUI model for office outlook email. TaskPaneUI is pinned. So, the user could switch between different email items faster. We are syncing the timespent by user every 3secs to customProperties against each email item to track their time spent..There is window.setInterval calls itemSave for every 3 seconds. When i test this flow by switching the email item during the custom properties save is in progress, it updates the timeSpent against wrong item. This is critical bug, as save is initiated for different item, but since item is changed office js library sends the server request against wrong item.

If you see the above logs, item save is triggered for different itemId but acually the request goes to server for the current itemId.

load item AAMkAGJiNzkwZTg2LWVhYjItNDhiNC04NTVjLTZhZGY0Yjc0NTA4NABGAAAAAADSrfB+JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAABY6n+cAAA= customSettings.ts:21 loaded value {11/08/2022: 63.005} customSettings.ts:20 load item AAMkAGJiNzkwZTg2LWVhYjItNDhiNC04NTVjLTZhZGY0Yjc0NTA4NABGAAAAAADSrfB+JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAABfLppAAAA= customSettings.ts:21 loaded value {11/08/2022: 490.109} customSettings.ts:20 load item AAMkAGJiNzkwZTg2LWVhYjItNDhiNC04NTVjLTZhZGY0Yjc0NTA4NABGAAAAAADSrfB+JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAABY6n+cAAA= customSettings.ts:21 loaded value {11/08/2022: 63.005} customSettings.ts:8 save triggered AAMkAGJiNzkwZTg2LWVhYjItNDhiNC04NTVjLTZhZGY0Yjc0NTA4NABGAAAAAADSrfB+JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAABY6n+cAAA= customSettings.ts:40 delay load process (Item Changed at this stage and it just delays the load) customSettings.ts:35 save completed customSettings.ts:20 load item AAMkAGJiNzkwZTg2LWVhYjItNDhiNC04NTVjLTZhZGY0Yjc0NTA4NABGAAAAAADSrfB+JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAABfLppAAAA= customSettings.ts:21 loaded value {11/08/2022: 64.014}

https://outlook.office.com/owa/service.svc?action=SaveExtensionCustomProperties&app=Mail&n=565 x-owa-urlpostdata: %7B%22request%22%3A%7B%22__type%22%3A%22SaveExtensionCustomPropertiesParameters%3A%23Exchange%22%2C%22ExtensionId%22%3A%22e894ac5c-581c-4708-ba69-cc81f36f8392%22%2C%22ItemId%22%3A%22AAMkAGJiNzkwZTg2LWVhYjItNDhiNC04NTVjLTZhZGY0Yjc0NTA4NABGAAAAAADSrfB%2BJJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAABfLppAAAA%3D%22%2C%22CustomProperties%22%3A%22%7B%5C%22TotalSeconds%5C%22%3A%7B%5C%2211%2F08%2F2022%5C%22%3A64.014%7D%7D%22%7D%7D

Link to live example(s)

  1. _This couldn't be automated as ItemChanged event happens when the user moves to different item when taskPane is pinned. Main code changes related to calling save & load custom properties and interval is added here.. https://codesandbox.io/s/pedantic-river-g6bdpq?file=/index.js


Provide additional details




Context

We are implementing taskpaneUI model for office outlook email. TaskPaneUI is pinned. So, the user could switch between different email items faster. We are syncing the timespent by user every 3secs to customProperties against each email item to track their time spent..There is window.setInterval calls itemSave for every 3 seconds. When i test this flow by switching the email item during the custom properties save is in progress, it updates the timeSpent against wrong item. This is critical bug, as save is initiated for different item, but since item is changed office js library sends the server request against wrong item.

Useful logs

Thank you for taking the time to report an issue. Our triage team will respond to you in less than 72 hours. Normally, response time is <10 hours Monday through Friday. We do not triage on weekends.

repl-kannan-d commented 2 years ago

Hi @JuaneloJuanelo , Any updates on this?

JuaneloJuanelo commented 2 years ago

we are investigating, but quick question for you, is this issue only happening in OUtlook for the Web? i wonder if it repros in Windows and Mac?

repl-kannan-d commented 2 years ago

Thanks for the update. I have tested it only on Office Web.. If required, we will do it on desktop.. Technically, it seems to be bug office.js and i am not sure whether the code flow is different for web and desktop

JuaneloJuanelo commented 2 years ago

@repl-kannan-d can you please confirm the Win32 behavior?

repl-kannan-d commented 2 years ago

@JuaneloJuanelo I don't have windows32 os but using windows 10 pro 64 bit OS.. Would you like to know the desktop app behaviour on this environment?

repl-kannan-d commented 2 years ago

@JuaneloJuanelo Can you please let me know if you need the above inputs from me?

exextoc commented 2 years ago

@repl-kannan-d Thanks for your patience. We are unable to repro the issue at our end. Can you please share the add-in manifest to OutlookExtensibility@M365x27035562.onmicrosoft.com so that we can debug it better?

repl-kannan-d commented 2 years ago

@exextoc As requested i have sent mainfest to that specific address.. If its not reproducible, can we schedule a call to discuss this. I can probably show the issue.

exextoc commented 2 years ago

@repl-kannan-d We are not able to install your addin with shared manifest.xml. It is showing this error to us:

This app can't be installed. The manifest file doesn't conform to the schema definition. The 'http://schemas.microsoft.com/office/appforoffice/1.1:Id' element is invalid - The value 'abc' is invalid according to its datatype 'http://schemas.microsoft.com/office/appforoffice/1.1:UUID' - The Pattern constraint failed... The 'http://schemas.microsoft.com/office/appforoffice/1.1:Id' element is invalid - The value 'abc' is invalid according to its datatype 'http://schemas.microsoft.com/office/appforoffice/1.1:UUID' - The Pattern constraint failed. The Pattern constraint failed.

Also, what we meant by "sharing manifest" is "share your addin code by having hosted links of it in your manifest". We noticed that your manifest has "localhost" web-links. So even after install addin will not work for us. So, if you manifest can point to hosted addin code that will be great. We want to install your addin and try to repro the issue.

repl-kannan-d commented 2 years ago

Got it.. I will share the details via Email.

repl-kannan-d commented 2 years ago

Attaching the video for reproducing the issue and corresponding developer logs. Timer is running to save the duration every 3 secs,, so need to switch the email when its about to trigger the save action to reproduce the issue.

https://user-images.githubusercontent.com/13565405/195027295-a0a91184-cfdc-4d7d-a7ae-4086dc95a8d8.mp4

outlook.office.com-1665473457812.log

repl-kannan-d commented 2 years ago

@exextoc @JuaneloJuanelo Hi Team, any update on this?

repl-kannan-d commented 2 years ago

@exextoc @JuaneloJuanelo Hi Team, Did you get a chance to look at the live extension that i had shared via email?

repl-kannan-d commented 1 year ago

@exextoc @JuaneloJuanelo Hi Team, were you able to check this out? I have configured the sepearate instance for reproducing the issue, which is running more than a month.

exextoc commented 1 year ago

@repl-kannan-d We have not been able to repro the mentioned issue with the addin provided by you. Save trigger and completed happens for same item id even when there is an item change in between.

save triggered AAMkADM4Njc1ZTAxLTcyNjYtNDFlZC04Njc2LTE4YTBiNzYzZGMxOABGAAAAAAAc3MLROjmhTpRixNWzgcKmBwAto3MUwcnVRK1p0zn8YW+TAAAAAAEMAAAto3MUwcnVRK1p0zn8YW+TAADu5HjIAAA=

Item changed. New itemId AAMkADM4Njc1ZTAxLTcyNjYtNDFlZC04Njc2LTE4YTBiNzYzZGMxOABGAAAAAAAc3MLROjmhTpRixNWzgcKmBwAto3MUwcnVRK1p0zn8YW+TAAAAAAEMAAAto3MUwcnVRK1p0zn8YW+TAADu5HjGAAA=

save completed AAMkADM4Njc1ZTAxLTcyNjYtNDFlZC04Njc2LTE4YTBiNzYzZGMxOABGAAAAAAAc3MLROjmhTpRixNWzgcKmBwAto3MUwcnVRK1p0zn8YW+TAAAAAAEMAAAto3MUwcnVRK1p0zn8YW+TAADu5HjIAAA=

Are you facing this issue in your desktop app also?

exextoc commented 1 year ago

@repl-kannan-d Does this issue occur every time or do you face this issue occasionally?

repl-kannan-d commented 1 year ago

It's not happening everytime.. It happens when you try it as mentioned above on my comment Attaching the video for reproducing the issue and corresponding developer logs. Timer is running to save the duration every 3 secs,, so need to switch the email when its about to trigger the save action to reproduce the issue. ... if you try it correctly 1 out of 5 times possibly we could reproduce it.. Also Pls go over the video attached and the corresponding log as well.. Pls let me know if aren't still reproduce.. We can schedule the meeting and go over it.

repl-kannan-d commented 1 year ago

@exextoc

exextoc commented 1 year ago

The add-in manifest provided by you https://zerotime-oemail.ti.replicon.com/manifest.xml is not valid anymore. Could you please reupload your manifest? Also, would it be possible for you to share the add-in source code so that we can look into it independently?

repl-kannan-d commented 1 year ago

@exextoc Looks like you were using wrong URL for testing.. I have forwarded the email which have the correct link https://kannand-zerotime-oemail.pg.replicondev.net/manifest.xml and also the partial source code which i shared long time back.. Please try to reproduce the issue on the above instance and let me know how it goes. Thanks

exextoc commented 1 year ago

@repl-kannan-d Revisited the logs that you have attached at outlook.office.com-1665473457812.log

Checked all the instances where there is an item changed between save trigger and save completed, but could find any instance where its saving against new id. The save completed always shows same item id as the previous save trigger.

If you could point a time stamp in the video where you see the problem, it will help.

customProperties.ts:64 save triggered +JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAACDCpCuAAA=
ManualTimeCapture.tsx:307 Item changed. New itemId +JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAACDCpCtAAA= customProperties.ts:46 save completed +JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAACDCpCuAAA= customProperties.ts:64 save triggered +JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAACDCpCtAAA= ManualTimeCapture.tsx:307 Item changed. New itemId +JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAACDCpCuAAA= customProperties.ts:46 save completed +JJe4RoPxQT1KSwg0BwAyIoCjosMtQ7Fk1Mr5ZYFaAAAAAAEMAAAyIoCjosMtQ7Fk1Mr5ZYFaAACDCpCtAAA=

Attaching still from the video as well. image

repl-kannan-d commented 1 year ago

@exextoc Hi,, I have took the screenshot of the problematic place from the same logs... image

Actually i was switching between two different emails.. Highlighted in Green is one email and non highlighted one is another emaill. If you open the logs on notepad++ and select the second part of itemId you can find out that.. For the highlighted itemId, initial value was 1.001(you can notice that from logs).. and another email(its around 326 seconds)... Highlighted them on Yellow....

The problematic part where the issue occured is highlighted on Red.... After that event, you could notice that for the highlighted itemId(in green) vaue is changed to 327 when its loaded instead of 1.001.

So what happens on highlighted by red lines flow.? -- Save is triggered for nonHighlighted item, before the save for that itemId gets complete, ItemId gets changed.. So this time, internally office JS saves the value for the newly loaded ItemId, instead of saving it against the one which triggered(non highlighted item)... That's the reason, after this step, we could see that value is changed to 327 for item which originally had a value as 1.001.

Note: Save Completed one doesn't reflect the actual itemId.. It was added to track the completeness of the request.

Hope this is clear.

repl-kannan-d commented 1 year ago

If you set the Network to Fast 3G or Slow 3G on developer tools, it could help to reproduce the issue fast and also try to switch the item exactly at 3secs as i did on the video.. image

exextoc commented 1 year ago

@repl-kannan-d We are able to repro the issue on our end. Thanks for sharing the details. It has been put on our backlog. We, unfortunately, have no timelines to share at this point.

Internal tracking id: Eg: Office:184522

repl-kannan-d commented 1 year ago

Great, thanks @exextoc . Picking up this sooner would be appreciated as this is critical bug on customProperties.saveAsync method which causes the data to be saved against wrong emailItem.

exextoc commented 1 year ago

@repl-kannan-d - We are trying to investigate the issue, but looks like the add-in is no more active. Can you please reply with updated add-in details?

microsoft-github-policy-service[bot] commented 1 year ago

This issue has been automatically marked as stale because it is marked as needing author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. Thank you for your interest in Office Add-ins!