Oslo, 26. november 2023
Endret 13. desember 2023
Utvidet logging i Visma Business
Det finnes en del loggingsfunksjoner i Visma Business (VBus). Når det opprettes en ny rad står det hvem som har opprettet den og når det skjedde. Og hver gang den endres står det hvem som endret den sist og når det skjedde. I Endringsloggdefinisjon kan vi sette opp logging av enkelte felt. Skoleeksempelet er endring av Bankkonto på leverandører; det kan være fristende rett før remittering av leverandører å endre kontonummeret, særlig rett før jul. Smart er det ikke, men om man skal emigrere til fjerntliggende land uten utleveringsavtale – så kan man kanskje slippe unna med det. I alle fall, det finnes muligheter for å logge endring av ethvert felt i VBus. Vi har noen som har satt opp logging av mange felt på ordrelinje og det gir naturligvis en skog av endringer som egentlig er vanskelig å dra nytte av. Det er mulig å forbedre denne endringsloggen slik at man kan koble fra den tabellen endringen gjelder og se alle loggførte endringer den aktive raden. I eksempelet under, har jeg bare vært opptatt av endring i kredittgrense på kunden (personopplysningene er av naturlige grunner for anledningen sladdet):
Hvis du stusser over Bedriftsendringslogg 2 er dette et DME-view som bearbeider Bedriftsendringslogg og legger Aktørnr, Ordrenr, Ordrelinjenr, ansvarsenhetsnr, etc. i egne kolonner med relasjoner til de aktuelle tabellene.
Dette ikke så praktisk om man setter opp logging av et stort antall kolonner. Noen har for eksempel ønsket seg logging av alle felt på Ordre og Ordrelinje. Da dokumentarkivet ble introdusert i VBus en gang i versjon 4, satte min tidligere kollega Jonny Eriksen i IT Innovation (som ble kjøpt av Proplan for å etablere seg i Oslo) opp en ganske fiks løsning; han la inn i ordrelagringsprosedyren en kopiering av Ordre og Ordrelinje til Ordredokument (med Dokumenttype=99) og Ordredokumentlinje. Dermed var full historikk på ordre og ordrelinje på plass. Det skal han ha, Jonny; han ser muligheter der andre ser problemer.
Jeg jobber jevnlig (og da mener jeg én eller flere ganger hver måned) med kunder som har pådratt seg inkonsistens i logistikken. Oftest er det at ordrelinje er i utakt med de underliggende reservasjonsradene eller de tilhørende produkttransaksjonene. Da kan VBus gå helt bananas. Og når det fører til at samme ordrelinje faktureres om igjen og om igjen inntil fakturamottaker nokså oppgitt ringer og spør Hva f*** driver dere med? kan nok en og annen i ledelsen gå bananas også. Ryddingen er for så vidt håndarbeid som må gjøres direkte i databasen eller med importrutinen i VBus. Strengt tatt ikke så spennende; det er vel som å luke bort ugress i blomsterbedet: Det må gjøres. Mer spennende er hvordan og hvorfor det skjer. Det er som om du kommer med bilen til verkstedet med knuste sidespeil og spør: Kan dere fikse det? Og Hvorfor er det slik? Da er svaret på det første Klart det! og på det andre Ingen idé, spør bilføreren om hvordan det skjedde. Jeg leter alltid etter et mønster når jeg får øye på slik inkonsistens og forsøker jevnlig å fremprovosere det. Når jeg klarer det, melder jeg det til Visma og er jeg heldig svarer de at dette skal vi løse i neste versjon. Det er ikke alltid jeg er heldig. På onsdag fikk jeg følgende tilbakemelding (case #00418865): Bug er reproduserbar fra versjon 8.00 så vidt vi vet. Fixen er satt til future versions, så vet ikke eksakt når det blir fikset. Det jeg leser er: Vi vet det er feil, men vi bryr oss ikke om det.
Inspirert av løsningen til Jonny, har jeg satt opp en DME-utvidelse med for logging av endringer på Ordre, Ordrelinje, Reservasjon og Produkttransaksjon – slik at det blir skrevet en kopi til disse tabellene hver gang en ordre lagres. Og så er det bare å vente på at en feil oppstår. Loggingen forteller oss ikke hvorfor det skjer, men når det skjer og hvordan disse tabellene var rett før og rett etter feilen skjedde. Her er et eksempel:
Feilen oppstod da en bruker kl. 11:05 den 14.09.2023 gjennomførte fakturamottaket av faktura 940070414 (se røde rammer nedenfor). Til tross for at det allerede var en produkttransaksjon (Ordrejournal 720299) med korrekt Antall, Lagerbevegelse, TransStatus (Avventer realisering), etc. med tilhørende reservasjonsrad som stemte både med ordrelinjen og denne opprinnelige produkttransaksjon, ble det allikevel opprettet en ny (med Ordrejournal 731198) som isolert sett ble behandlet rett - hvis den opprinnelige hadde blitt slettet eller fått Antall, Lagerbevegelse, Lagerkostnad, etc. satt til null og TransStatus endret til Antall korrigert. Men det som skjedde var at Antall på ordrelinje og reservasjonsrad, samt tilgang på den opprinnelige produkttransaksjon ble satt til 39 og TransStatus blanket ut. Ordrelinje og reservasjonsrad viste for så vidt det samme, men var helt i utakt med produkttransaksjonene (hver for seg og samlet):
Kl. 14:40 den 11.10.2023 satte en annen bruker Antall på ordrelinje til 0 (se blå rammer over). Det gjorde ikke inntrykk på reservasjonsrad og heller ikke på noen av produkttransaksjonene.
Jeg kan ikke si hvorfor feilen oppstod på denne ordrelinen – som ble fakturamottatt sammen med mange andre ordrelinjer på samme faktura uten at det skjedde noen feil på noen av de andre – men vi vet i det minste hvilken prosess som ble utført da feilen oppstod. Dermed er vi litt nærmere å forstå hvorfor. Det vil være fristende å spørre brukeren som gjennomførte fakturamottaket kl. 11:05 den 14.09.2023 om hva han eller hun gjorde i detalj, hva vedkommende gjorde rett før det skjedde, hvilket vindu som ble brukt, om det dukket opp noen feilmeldinger, etc. Men ingen har perfekt erindring med detaljer om det som skjedde for flere måneder siden (hvis du ser bort fra hun du er gift med). Løsning: Vi har en BIG-komponent som (sammen med en DME-utvidelse) loggfører hvilke vinduer som åpnes av hvem i hvilket firma med dato og kl.sl. og som sammen med en trigger også logger når de blir lukket. Dette ble opprinnelig laget for å se hvilke vinduer som aldri er i bruk, men har vist seg å være nyttig i feilsøking som her. Hvis du vil ha en slik logging installert, bør du nok informere de tillitsvalgte, siden det har et element av person-overvåkning. Det kan se slik ut:
GDPR-reglene sier noe om forutsetninger for å oppbevare personopplysninger. Og at de ikke skal oppbevares lenger enn det som er nødvendig for å oppnå formålet med oppbevaringen. Deretter skal opplysningene slettes. Det betyr ikke nødvendigvis at radene skal slettes, men at brukernavnet skal fjernes etter en tid.
Et annet eksempel på at utvidet logging er nødvendig for å forstå når feil oppstår er denne (meldt til Visma på case #00428692). Se bilde nedenfor.
Ordren er opprettet 19.10.2023, så den er opprettet i samme versjon som kunden har nå.
Reservasjon skjedde samme dag som en konsekvens av Reservasjon ved lagring i Ordrepref. OK.
Plukkliste ble skrevet ut 6. november kl. 07:35. OK.
Ferdigmelding skjedde 9. november kl. 08:21. OK.
Siste gang ordren ble lagret før faktureringen var 30. november kl. 09:52. OK. Se grønne rammer.
Ved fakturering skjer følgende feil (se røde rammer): Reservasjonen fra parti 214 (Rsv.nr 1, Ordrejournal 742971, Trans.nr 1) ignoreres; det samme med produkttransaksjonen. Det opprettes nye reservasjoner fra partiene 216 og 217 (Rsv.nr 2 og 3, Ordrejournal 748132, Trans.nr 1 og 2). Disse behandles for så vidt rett, men etter fakturering viser ordrelinjen at det er ferdigmeldt og fakturert 2, antall (rest) er 0 og ingen er reservert. Ordrelinjen er således som forventet. Men summen av reservasjonsradene viser at det er ferdigmeldt til sammen 4, hvorav 2 avventer realisering. Det samme viser produkttransaksjonene. Ferdigmeldt dato er feil både på produkttransaksjoner og reservasjon er feil; det er dato for når faktureringen skjedde, ikke da ferdigmeldingen skjedde. Når lagersaldo regenereres, blir lageret feil.
I et forsøk på å rette feilen, sletter jeg den opprinnelige reservasjonsraden (i VBus) altså Rsv.nr 1, Ordrejournal 742971, Trans.nr 1 (se blå rammer). Det lar seg gjøre uten feilmelding. Både reservasjoner og Produkttransaksjoner blir rett, men nå blir ordrelinjen feil; Ferdigmeldt blir satt til 0, til tross for at Fakt/real. er 2. Antall blir satt til 2:
Litt utvidet logging kan være nyttig.
Resten av min blogg kan du lese her: frode.antun.no/VBus/blogg