Itgeneor364: Meerdere fouten in Invantive Data Hub bij verwisselen access token op Exact Online

Vragen
,
1

Bij de replicatie van Exact Online administraties in SQL Server met Invantive Data Hub (20.2.128-PROD+1918) krijgen we de volgende foutmeldingen:

2021-12-09 19:01:07.228 Information itgendhb087: Providerkenmerk waarden veranderd (1 rijen aangepast). (0 ms).
2021-12-09 19:01:07.228 Information itgendhb044: Run SQL statement: – alter persistent cache force refresh;
alter persistent cache refresh;
2021-12-09 19:01:07.228 Information itgensql264: Invantive SQL statement gestart.
2021-12-09 19:01:11.235 Information itgendch436: Data Cache gebeurtenis opgetreden. (itgendch668)
The table partition ‘1.145 - ExactOnlineREST.Budget.Budgets.1038848 (8 / 28)’ changes last version from 54 to 55.
…
2021-12-09 20:09:44.249 Information itgendch436: Data Cache gebeurtenis opgetreden. (itgendch099)
Met Succes vernieuwd 2.960 tabelpartities en 0 zonder actie, 12 zijn mislukt.
2021-12-09 20:09:46.749 Warning itgendhb173: Context: C:\jobs\sql\acme-load-exact-online.sql: – alter persistent cache force refresh; alter persistent cache refresh;
2021-12-09 20:09:46.843 Error itgencun016: Fout itgeneor364: Meerdere fouten in Invantive Data Hub.
Fout itgeneor364: Meerdere fouten in Invantive Data Hub.
One or more errors occurred.
Exact Online heeft minimaal 9,5 minuten nodig tussen elke aanvraag voor een nieuw toegangstoken.
The remote server returned an error: (400) Bad Request.
Probeer het over 317 seconden opnieuw.
Probeer het over 18 seconden opnieuw.
Probeer het over 362 seconden opnieuw.
Probeer het over 334 seconden opnieuw.
Probeer het over 326 seconden opnieuw.
Probeer het over 318 seconden opnieuw.
Probeer het over 293 seconden opnieuw.
Probeer het over 265 seconden opnieuw.
Probeer het over 259 seconden opnieuw.
Probeer het over 219 seconden opnieuw.
Probeer het over 365 seconden opnieuw.
Probeer het over 357 seconden opnieuw.
https://start.exactonline.nl/api/oauth2/token
2021-12-09 20:09:48.896 Error itgeneor364: System.Net.WebException
ValidationException
System.Net.WebException
ValidationException
at System.Net.HttpWebRequest.GetResponse()
at Invantive.Data.Providers.Http.HttpBasedProvider.DoRequest(GlobalState owner, ExecutionOptions executionOptions, HttpWebRequest request, String url, ObjectDefinition objectDefinition, QueryObject queryObject, String partitionCode, String callSafeNameOverrule, String anonymizedPostText, Boolean allowRetryOnNoConnectionMade, Boolean allowRetryOnConnectionLoss, ParameterList parameters, Guid nativeCallUid, Boolean throwExceptionOnNonSuccessfulStatusCode, Object requestBody, ExecutionStatistics& executionStatistics, ODataErrorProcessingInstructions& oDataErrorProcessingInstructions)

Hoe voorkomen we deze fout?

2

Deze foutmelding wordt primair veroorzaakt doordat het tijdelijke wachtwoord (het “access token”) vaker dan eens per 9,5 minuten vernieuwd wordt. De daadwerkelijke foutmelding vanuit Exact Online is:

Rate limit exceeded: access_token not expired

Het is mogelijk dat specifiek in Exact Online Nederland die limiet van 9,5 minuten nog niet gehanteerd wordt en dat die tussenliggende duur langzaam opgerekt wordt.

Uit de melding met code itgendch099 blijkt dat van de bijna 3.000 tabelpartities er 12 mislukt zijn. Meer dan 99% is dus succesvol verwerkt. De oorzaak van de Exact Online melding is onduidelijk; alle synchronisatie verloopt automatisch. Ook in andere Exact Online administraties zijn deze problemen niet massaal gesignaleerd.

De melding zal in de volgende release aangepast zijn zodat ook voor de systeembeheerder meteen duidelijk is of alle meldingen betrekking hebben op hetzelfde gewenste tijdstip of dat het om - in dit geval - 12 in de tijd totaal uiteenliggende meldingen ging. Ook zullen indien beschikbaar divisiecode van de Exact Online administratie en de tabelnaam opgenomen zijn in de melding.

Advies is om deze release in de week van 15 december te installeren en te kijken of de meldingen uitsluitsel geven.

Als workaround is advies om de synchronisatie nogmaals te draaien, bij voorkeur zonder force, dus bijvoorbeeld als de standaard vervalduur 20 uur is:

use all

alter persistent cache refresh when obsolete within '16 hours'

Hierbij wordt gebruik gemaakt van een iets kortere duur dan de standaard vervalduur van bijvoorbeeld 20 uur zodat alleen de tabelpartities die vlot gaan vervallen en nog niet bijgewerkt zijn bijgewerkt worden.

Voor meer achtergrond zie ook de volgende gerelateerde berichten:

3

Het probleem is reproduceerbaar bij de replicatie van grotere aantallen Exact Online administraties via het onderstaande SQL-script.

Na het aanmelden wordt omstreeks 13:29:31.348 een access token verkregen:

13:29:31.348 itgencmr128: Got OAuth access token using headless interactive control. (ExactOnlineAll) (45.063 ms)

Na een tijdje wachten op input werd om 13:47:41.273 het SQL-script gestart. Het access token was toen al verlopen (correct). Voordat de administraties gekopieerd worden naar SQL Server wordt tussentijds nogmaals een nieuw access token opgehaald:

13:48:05.617 itgenoda495: Got OAuth access token using headless interactive control. (ExactOnlineRest) (2.750 ms)

Toen alle ExactOnlineREST-gebaseerde tabellen klaar waren, werd gewisseld naar de XML-tabellen zoals BalanceLinesPerPeriod:

13:51:28.228 itgensql264: Invantive SQL statement started.
**** 13:51:57.189 Warning itgendhb173: Context: select count(*) from balancelinesperperiod
13:51:57.203 Error itgeneor364: Exact Online requires at least 9,5 minutes between each request for a new access token.
De externe server heeft een fout geretourneerd: (400) Ongeldige opdracht.
Please try again after 13-12-2021 13:54:52 (UTC) after waiting for 192 seconds.
-DEFAULT
13:51:57.204 Question itgencun002: Show details? Question? [y/N]
y
System.Net.WebException
ValidationException
bij System.Net.HttpWebRequest.GetResponse()
bij Invantive.Data.Providers.Http.HttpBasedProvider.DoRequest(GlobalState owner, ExecutionOptions executionOptions, HttpWebRequest request, String url, ObjectDefinition objectDefinition, QueryObject queryObject, String partitionCode, String callSafeNameOverrule, String anonymizedPostText, Boolean allowRetryOnNoConnectionMade, Boolean allowRetryOnConnectionLoss, ParameterList parameters, Guid nativeCallUid, Boolean throwExceptionOnNonSuccessfulStatusCode, Object requestBody, ExecutionStatistics& executionStatistics, ODataErrorProcessingInstructions& oDataErrorProcessingInstructions) in C:\Users\gle3.WS212\Documents\ws-master\Invantive.SQL\src\Invantive.Data.Providers\Http\HttpBasedProvider.cs:regel 2136

Door vervolgens enige tijd te wachtgen kon de uitvoering alsnog succesvol afgerond worden:

17:02:30.855 itgensql264: Invantive SQL statement started.
17:02:32.128 itgenoda495: Got OAuth access token using headless interactive control. (ExactOnlineRest) (192 ms)

Het lijkt er op dat de gebundelde Exact Online SQL-driver voor zowel REST als XML niet goed samenwerkt bij een wisseling van het access token.

Dit zal verder geanalyseerd worden en toegevoegd als een Antwoord.

SQL replicatie script

use all

select count(*)
from transactionlinesincremental

select count(*)
from glaccountsincremental

select count(*)
from contactsincremental

select count(*)
from addressesincremental

select count(*)
from salesorderlinesincremental

select count(*)
from salesinvoicelinesincremental

select count(*)
from exactonlinerest..journals

select count(*)
from exactonlinerest..costcenters

select count(*)
from exactonlinerest..costunits

select count(*)
from balancelinesperperiod

select count(*)
from aroutstandingitems

select count(*)
from apoutstandingitems
4

In afwachting van een meer definitieve oplossing zoals Exact Online alle veranderingen afgerond heeft, kan een sleep van 600 seconden toegevoegd worden, waarna de foutmelding niet meer optreedt:

use all

select count(*)
from transactionlinesincremental

select count(*)
from glaccountsincremental

select count(*)
from contactsincremental

select count(*)
from addressesincremental

select count(*)
from salesorderlinesincremental

select count(*)
from salesinvoicelinesincremental

select count(*)
from exactonlinerest..journals

select count(*)
from exactonlinerest..costcenters

select count(*)
from exactonlinerest..costunits

begin
  dbms_lock.sleep(600);
end;

select count(*)
from balancelinesperperiod

select count(*)
from aroutstandingitems

select count(*)
from apoutstandingitems
5

Van de problemen met de minimale interval tussen twee access token verwisselingen speelde in december nog het probleem dat queries die eerst REST API benaderden en daarna de XML API van Exact Online een itgeneor364 optrad.

Dit probleem is opgelost in release 20.2.205, beschikbaar op https://releasenotes.invantive.com.