F18

koji ti je hernad dokument bio sporan ? koja faktura pa je nisi imao

bilo je 4-5 faktura koje nisam vidio dok nisam uradio full sync.

Pogledaj rupe u brojevima u ovoj listi http://redmine.bring.out.ba/issues/29641#note-23

sporan je račun 10-10-00424, za njega nije osvježen broj fiskalnog računa kod vzeljke

evo dijela log-a

vzeljka dobija nalog da osvježi "fakt_doks" u njemu ima dokuemnt 10-10-00424

"vzeljka";"2012-11-21 13:10:08.463152";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, my_use fakt_doks 
         osvjeziti dbf cache: ver: 1415 last_ver: 1416" 

// lokuje semafor
"vzeljka";"2012-11-21 13:10:08.760439";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:lock - END" 

// stanje tabele fakt_doks bilo FREE u momentu kada je vzeljka osvjezavala FAKT_DOKS

"vzeljka";"2012-11-21 13:10:08.875276";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(375) : 
          nuliraj ids-ove, table: fakt_doks, user: vzeljka set ids = NULL, stanje tabele: free" <<< FREE

// verzija je 1416

"vzeljka";"2012-11-21 13:10:09.22145";"UPDATE_SEMAPHORE_VERSION(630) : update semaphore version, table: 
          fmk.semaphores_fakt_doks, select version za vzeljka version = 1416" 

"vzeljka";"2012-11-21 13:10:09.66738";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 

// evo ga tu je dokument taj...
"vzeljka";"2012-11-21 13:10:09.726496";"IDS_SYNCHRO(30) : ids_synchro ids_queries: (hash): ids / (array): 1 / (array): 1 / 101000424    ;  ;  ; qry / (array): 1 / SELECT idfirma,idtipdok,brdok,partner,datdok,dindem,iznos,rabat,rezerv,m1,idpartner,idvrstep,datpl,idpm,dok_veza,oper_id,fisc_rn,dat_isp,dat_val,dat_otpr,fisc_st FROM fmk.fakt_doks WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || rpad(brdok,8)) IN ('101000424   ') ;  ; " 

"vzeljka";"2012-11-21 13:10:09.785895";"DELETE_IDS_IN_DBF(391) : delete_ids_in_dbf(), table: fakt_doks/ dbf_tag =1 pobrisao iz lokalnog dbf-a zapisa = 0" 

// jedan zapis došao sa servera
"vzeljka";"2012-11-21 13:10:09.907412";"FILL_DBF_FROM_SERVER(525) : fill_dbf_from_server(), table: fakt_doks, count: 1" 

// =================================================

// ovdje ernad štampa fiskalni račun za ovaj dokument

"hernad";"2012-11-21 13:10:10.03367";"FPRINT_READ_ERROR(1435) : FISC: fajl odgovora se pojavio" 

"hernad";"2012-11-21 13:10:10.045396";"MY_USE_SEMAPHORE_OFF(32) : stanje semafora : OFF" 

// lokuje fakt_doks
"hernad";"2012-11-21 13:10:10.057737";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:lock - END" 

// update semafor verzije na: 1417

"hernad";"2012-11-21 13:10:10.059368";"UPDATE_SEMAPHORE_VERSION(630) : update semaphore version, table: fmk.semaphores_fakt_doks, select version za hernad version = 1417" 

"hernad";"2012-11-21 13:10:10.059368";"PUSH_IDS_TO_SEMAPHORE(100) : push ids: fakt_doks / (array): 1 / 101000424    ; " 

"hernad";"2012-11-21 13:10:10.10042";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 

"hernad";"2012-11-21 13:10:10.107797";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 

// ==========================================================================

// vzeljkin nastavak

// ovdje već ima verziju 1417 ?!????????? <<<<<<<<<<<<<< tu je BUGGGGGGGG !!!!!!!!!!!!!!
// praktično nikada mi ovaj SET podataka koje je hernad napravio nije došao

"vzeljka";"2012-11-21 13:10:10.754243";"UPDATE_SEMAPHORE_VERSION(630) : update semaphore version, table: fmk.semaphores_fakt_doks, select version za vzeljka version = 1417" 

"vzeljka";"2012-11-21 13:10:11.069581";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server table: fakt_doks synchro cache:          2.55" 

znači postoji problem, naznačio sam ga kao BUG u ovom transkriptu log-a gdje je podatak izgubljen

praktično željka je krenula sa update-om podataka verzije 1416

u tom momentu je hernad uletio sa setovanje broja veze i napravio verziju 1417

i željka završava svoju transakciju sa verzijom 1417 ali nije uspjela dabiti u dbf praktično nikada taj podatak koji je promjenjen

interesantno je to zašto u hernad transakciji nema NULIRAJ_IDS.... ?!?????????

kada radim update, praktično mjenjam broj verzije IDS-a ? zar ne bi trebao nulirati

kao da je to problem u funkciji update_dbf_server_and_dbf

Moguće s obzirom da nije bilo prijava drugih korisnika ...

Ovakav način rada - jedan fakturiše, a drugi pravi fiskalne račune samo mi prakticiramo. Taj scenario očigledno reproducira bug

interesantno je to zašto u hernad transakciji nema NULIRAJ_IDS

nuliranje se izvrši nakon što se preuzmu id-ovi sa servera - iz semafora.

Nuliranje se ne vrši prilikom pushiranja novih podataka na server.

hm... ili možda onaj bug koji sam predvidio ranije na #29539

a to je ovaj komentar http://redmine.bring.out.ba/issues/29539#note-64

da to je to, nuliranje, pokupio sam set, ali je u međuvremenu uletio novi ID i jednostavno sam ga obrisao kada sam završio svoju transakciju

pogledaj koliko rupa ima u mojoj listi dokumenata.

tu se definitivno ne radi ni o kakvom bugu uzrokovan milisekundama - kod mene nije bilo u listi sinhroniziranio 4-5 dokumenata.

Bug je definitivno golem ko kuća, ali ga ne vidimo

i kod željke se 2 puta okinulo

UPDATE_SEMAPHORE_VERSION(630)

????

kada kažeš transakcija trebaš biti precizniji - misliš na traksakciju čitanja ili transakciju pisanja podataka.

generalno, unutar transakcije se dešava samo pisanje podataka.

Misilm da veliki broj rupa u mojoj listi nije uzrokovan tim kratkotrajnim konfliktom

Ernad Husremović je napisao/la:

pogledaj koliko rupa ima u mojoj listi dokumenata.

tu se definitivno ne radi ni o kakvom bugu uzrokovan milisekundama - kod mene nije bilo u listi sinhroniziranio 4-5 dokumenata.

Bug je definitivno golem ko kuća, ali ga ne vidimo

griješiš samo ti fakt_doks nije bio sinhronizovan, zato što si štampao fiskalne račune, fakt_fakt ti je bio korektan

ako si štampao račun u momentu kada je željka puširala svoju fakturu jednostavno ti se doks nije napunio

da.....

imamo update_semaphore_version() poziv u

nuliraj_ids.... funkciji

i u funkciji

ids_synchro()

uradio sam rewrite update_semaphore_version funkcija

to je ovaj i još 3 commit-a.

bilo je dosta dupliranja i nepotrebnog koda.

update_semaphore funkcija se pozivala na duplo kod operacija čitanja

Trenutak nuliranja semafora, rad drugih korisnika¶

takođe je bilo provjeravanja statusa semafora za tabelu kod operacije nuliranja.

To sam skroz izbacio jer se radi o operacijo čitanja.

Saša inači misli da je to razlog problema koji imamo u sinhroniziaciji, ali se ne slažem sa tim.

On je smatrao da treba ubaciti lock kod ove operacije.

Ja sam uradio nešto drugo: U jednom sql statementu vršim brisanje IDS-a (nakon što sam ih pročitao) i setovanje verzije semafora)

Time se se mogućnost "trenutka" o kome Saša govori u gornjim komentarima eliminiše.

ovo je još pametnije setovanje verzije nakon nuliranja

nemam potrebu čitati last_version u predhodnom statementu - jednostavno setujem ono što zateknem u last_version

Hajde molim te testiraj ovo sa željkom.

Podesite rad na testnom serveru (to je jasko osposobio) ili neka se ona zakači na tvoju testnu sesiju. pa simulirajte jučerašnje operacije.

Isprovocirajte gubitak stavki u fakt_doks.

Što se tiče scenarija sa fiskalnim uređajem, to možeš uraditi ovako.

Sada imaš mogućnost da klijent ima "D" ili nema "N" fiskalne funkcije. Ubaci varijantu "T".

U toj varijanti će sve fiskalne funkcije biti vidljive, ali će opcija čitanja answer fajla dummy - radiće sleep 4 sekunde i nakon toga će vraćati uspjeh.

Na taj način ćeš imati sa stanovišta problema identičan scenario.

ok, idem to napraviti

još cleanup-a update semaphor funkcije (ovaj i još jedan parent commit).

Sada je to funkcija koja se koristi samo nakon push operacije. Nakon read operacija se koristi druga funkcija nuliraj+update_semaphore_version_for_user

commit

napravio fprint test režim rada

ispravio bug u update_semaphore... funkciji

... i još ispravka bug-a commit u sql klauzuli

sad imam grešku

null value in column "version" violates non-null constraing

znači radim prvo pokretanje, kreiraju se baze i radi se full sinhro

također onda izgleda radi ovoga uđe u beskonačnu petlju i nonstop vrti osvježavanje te tabele iako je broj zapisa 0

ERROR: _sql_query: UPDATE fmk.semaphores_refer SET  ids=NULL , dat=NULL, 
        version=last_trans_version  
        WHERE user_code ='vsasa'
 err msg:ERROR:  null value in column "version" violates not-null constraint

a u tabeli imamo ovo:

trebalo bi nešto ovako ?

UPDATE fmk.semaphores_refer
SET 
   ids=NULL, 
   dat=NULL,
   version = ( CASE WHEN last_trans_version IS NULL THEN 0 ELSE last_trans_version END ) 
WHERE user_code = 'vsasa'

ne znam šta u slučaju kada je NULL, čime treba da se puni

postavio sam tako, evo sad ide

znači radim prvo pokretanje, kreiraju se baze i radi se full sinhro

ponovi situaciju prvog pokretanja nakon svih ovih ispravki koje si napravio.

potrebno je postići da se od prve izvrši inicijalizacija semafora i dbf-ova

ne znam šta u slučaju kada je NULL, čime treba da se puni

hm, 0 je vjerovatno ok, ali za svaki slučaj staviti -1 da se zna da se nije desila prva sinhronizacija ... ali u principu ovo se može izbjeći ako se kod prvog inserta stavi da je last_version = -1 a ne null

tražio sam gdje se desi prvi insert u tabelu semafora pa sam tu stavio -1, a izbacio ovaj gore CASE što si ubacio

da, ali opet na čistu bazu imam istu grešku "null value ...."

fazon je što u semaforima već imam ono gore stanje -1/NULL, znači zapis je već insertovan

pa onda nisam našao dobro mjesto gdje se dešava prvi insert.

treba njega naći i staviti -1 u last_trans_version

vjerovatno još negdje ima insert into fmk.semaphores_ ... koje ja nisam našao to pronađi.

Tvoj case je bio workaround za loše setovanu vrijednost last_trans_version kod prvog inserta. nađi prvi insert

ovo je moguće riješiti i tako da se u samoj tabeli kod kreiranja setuje default za last_trans_version = -1, i da se zabrani NULL vrijednost ovog polja.

Nije zgoreg to i učiniti kod nekog budućeg upgrade-a strukture baze

pa dobro ali šta će mi INSERT ????

kažem ti da u tabeli semafora već postoji zapis

i kada počistim loko bazu i pustim krene full sinhro i ovdje izbaci grešku zato što ne može update da napravi, znači ne radi se o tome da nema zapisa u semafor tabeli, pa insert ubaci ovo gore što si stavio

kažem ti da u tabeli semafora već postoji zapis

odakle se taj zapis pojavio ? pojavio se insertom.

Izbriši ga pa će ga aplikacija ponovo kreirati

znači ne radi se o tome da nema zapisa u semafor tabeli

insert NULL vrijednosti se dešavao kod dosadašnjih verzija. od sada će biti -1 i sve je onda riješeno.

i kada počistim loko bazu i pustim krene full sinhro i ovdje izbaci grešku zato što ne može update da napravi, znači ne radi se o tome da nema zapisa u semafor tabeli, pa insert ubaci ovo gore što si stavio

testni scenario treba biti: prazan zapis u fmk.semaphores_xyz i pobrisan dbf xyz

nije ovo dobro, sada sam pobrisao sporne semaphores tabele da se inseruju friški zapisi, sinhronizacija prođe, ali kada ponovo uđem u aplikaciju opet mi radi full sinhro svih tih tabela, valjda zato što je -1

kada se odradi full sinhro situacija u semaforu treba da bude

• za prazannu tabelu

version / last_trans_version
  -1            -1

nakon sinhronizacije

version / last_trans_version
   0    /         0

znači ovo je kvakak samo kod tabela koje nemaju zapisa

ili nešto slično.....

evo šta mi je ostalo nakon pokretanja u tabeli

user  / algoritam   / version  / last_trans_version 
 vsasa    full          -1               -1

možda ovo algoritam pravi problem ???

stavi ovako u sql statement:

version =  GREATEST(last_trans_version, 0)

tako će u tom slučaju setovati vrijednost 0 za last_trans_version=-1

http://gotochriswest.com/blog/2011/07/26/postgresql-max-of-two-or-more-fields/

ali jok !

treba u prvi insert staviti da je last_trans_verision = 0 ne treba nikakav greatest nakon toga

pokušaj sada pushirao sam tu promjenu

hm.... ne kontam što je u algoritmu "full" ???

a onda sam skontao, kod prazne semafor tabele "full" je default vrijednost polja ako se ne setuje kod inserta

da li je to ok ?

znači desila se full sinhro ali se nije setovao semafor na algoritam = free

također, opet je problem jer već imam setovano u tabelama semafora da je last_trans_number = -1

i ovo sa 0 neće proraditi, sada bi morao proći i ručno opet izbrisati sve semafor tabele

da li je to ok ?

ako nije do sada pravilo probleme ne vjerujem ni da će sada.

koliko se sjećam to polje se prvo nije koristilo a onda se koristi za praćenje statusa lock/free.

Ovo je loša praksa (prekrivanje jednog sadržaja drugim u aplikaciji)

Svejedno kod prvog inserta se onda može staviti "free" jer se to ionako ne koristi za oznaku algoritma sinhronizacije.

pa imamo poslije ispitivanje semafor statusa i ako pročita "full" vjerovatno to ne zna hendlirati

Saša Vranić je napisao/la:

pa imamo poslije ispitivanje semafor statusa i ako pročita "full" vjerovatno to ne zna hendlirati

mislim da to nije nikakav problem. Da jeste on bi davno iskočio

Saša Vranić je napisao/la:

također, opet je problem jer već imam setovano u tabelama semafora da je last_trans_number = -1

i ovo sa 0 neće proraditi, sada bi morao proći i ručno opet izbrisati sve semafor tabele

testni scenario treba biti: nema zapis u fmk.semaphores_xyz i pobrisan dbf xyz

Dovoljno je da test uradiš za jednu tabelu.

Ostale možeš kako god hoćeš - npr. možeš sa starijom verzijom inicijalizirati semafore

Ernad Husremović je napisao/la:

Saša Vranić je napisao/la:

pa imamo poslije ispitivanje semafor statusa i ako pročita "full" vjerovatno to ne zna hendlirati

mislim da to nije nikakav problem. Da jeste on bi davno iskočio

Ali da se više ne bi igrali nagađanja pogledao sam get_semaphore_status koja opet provjerava polje "algorithm" kako sam i pretpostavljao.

on jednostavno vraća njegov sadržaj.

pa da tu priču završimo pushirao sam commit koji sa prvim insertom u semafor tabelu stavlja status 'free'

Sigurno je default vrijednost kod kreiranja tabele semaphores stavljena 'full' u sql create skriptama

jeste, to sam ti gore rekao...

hoće li ovo ipak stvoriti problem na ostalim instalacijama ?

u svim tabelama koje nisu nikada pipnute u njihovom semaforu stoji

version / last_trans_version
   0             NULL

ako za takvog recimo izbrišemo loko bazu i pustimo full sinhro, to će rezultirati greškom opet

ipak je onaj moj CASE bio dobar :)

on je dobar workaround

pa dobro, praktično patch bi bio da se prije pokretanja na svim semafor tabelama odradi

update last_trans_version = 0 if last_trans_version is null

onda bi radilo

smjestio sam CASE tamo gdje pripada - u reset semaphores funkciju

testiraj sada

napravio si grešku, ispravio sam

ok, testirali smo unos nekih 10-ak dokumenata

i na kraju imamo rezultat

• vzeljka ima sve dokumente i sve brojeve veze popunjene ispravno
• bjasko - fali mi dokument 10-10-00318, sve ostale dokumente imam

znači desio se neki gaf opet

da li je u toku rada vašeg rada zastoja - lock situacija ?

// vzeljka puširala promjene....

"vzeljka";"2012-11-22 12:10:37.982081";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: fakt_fakt / (array): 1 / #2101000318    ; " 
"vzeljka";"2012-11-22 12:10:37.982081";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: fakt_doks / (array): 1 / 101000318    ; " 
"vzeljka";"2012-11-22 12:10:37.982081";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: fakt_doks2 / (array): 1 / 101000318    ; " 

// bjasko pokupio

// fakt_doks2

"bjasko";"2012-11-22 12:10:43.941015";"CREATE_QUERIES_FROM_IDS(309) : create_queries..(), ret[qry]=(array): 1 / SELECT idfirma,idtipdok,brdok,k1,k2,k3,k4,k5,n1,n2 FROM fmk.fakt_doks2 WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || rpad(brdok,8)) IN ('101000318   ') ; " 

"bjasko";"2012-11-22 12:10:44.003096";"CREATE_QUERIES_FROM_IDS(310) : create_queries..(), ret[ids]=(array): 1 / (array): 1 / 101000318    ;  ; " 

"bjasko";"2012-11-22 12:10:44.191059";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): ids / (array): 1 / (array): 1 / 101000318    ;  ;  ; qry / (array): 1 / SELECT idfirma,idtipdok,brdok,k1,k2,k3,k4,k5,n1,n2 FROM fmk.fakt_doks2 WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || rpad(brdok,8)) IN ('101000318   ') ;  ; " 

"bjasko";"2012-11-22 12:10:44.249105";"IDS_SYNCHRO(59) : ids_synchro ids_queries/2: (array): 1 / 101000318    ; " 

// fakt_fakt tabela

"bjasko";"2012-11-22 12:10:59.079672";"CREATE_QUERIES_FROM_IDS(309) : create_queries..(), ret[qry]=(array): 1 / ?U? ; 2 / SELECT idfirma,idtipdok,brdok,datdok,idpartner,dindem,zaokr,rbr,podbr,idroba,idroba_j,serbr,kolicina,cijena,rabat,porez,k1,k2,m1,txt,idvrstep,idpm,fisc_rn,c1,c2,c3,n1,n2 FROM fmk.fakt_fakt WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || rpad(brdok,8)) IN ('101000318   ') ; " 

"bjasko";"2012-11-22 12:10:59.139002";"CREATE_QUERIES_FROM_IDS(310) : create_queries..(), ret[ids]=(array): 1 / ?U? ; 2 / (array): 1 / 101000318    ;  ; " 

"bjasko";"2012-11-22 12:10:59.317747";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): ids / (array): 1 / ?U? ; 2 / (array): 1 / 101000318    ;  ;  ; qry / (array): 1 / ?U? ; 2 / SELECT idfirma,idtipdok,brdok,datdok,idpartner,dindem,zaokr,rbr,podbr,idroba,idroba_j,serbr,kolicina,cijena,rabat,porez,k1,k2,m1,txt,idvrstep,idpm,fisc_rn,c1,c2,c3,n1,n2 FROM fmk.fakt_fakt WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || rpad(brdok,8)) IN ('101000318   ') ;  ; " 

"bjasko";"2012-11-22 12:11:00.397958";"IDS_SYNCHRO(59) : ids_synchro ids_queries/2: (array): 1 / 101000318    ; " 

"bjasko";"2012-11-22 12:11:00.633711";"RUN_SQL_QUERY(191) : QRY OK: run_sql_query: SELECT idfirma,idtipdok,brdok,datdok,idpartner,dindem,zaokr,rbr,podbr,idroba,idroba_j,serbr,kolicina,cijena,rabat,porez,k1,k2,m1,txt,idvrstep,idpm,fisc_rn,c1,c2,c3,n1,n2 FROM fmk.fakt_fakt WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || rpad(brdok,8)) IN ('101000318   ')" 

Opet fakt_doks nema ?!??????

Ernad Husremović je napisao/la:

da li je u toku rada vašeg rada zastoja - lock situacija ?

jeste, ja sam puširao fiskalni račun i reklo mi je da je lokovano, pa je čekao da se tabela oslobodi i nakon toga update odradio

Opet fakt_doks nema ?!??????

dobro sada traži u logu sljedeći kontakt bjasko usera sa fakt_doks

mislim sljedeće korištenje fakt_doks od strane bjasko usera

evo momenta

// bjasko je setovao broj fiskalnog racuna 

"bjasko";"2012-11-22 12:10:24.953895";"SQL_TABLE_UPDATE(84) : sql table update, poceo" 

// napravio je verziju 1094

"bjasko";"2012-11-22 12:10:24.953895";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : 
             END: update semaphore version after push bjasko last_ver=      1094" 
"bjasko";"2012-11-22 12:10:24.953895";"PUSH_IDS_TO_SEMAPHORE(138) : END push_ids_to_semaphore" 
"bjasko";"2012-11-22 12:10:24.953895";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
          fakt_doks / (array): 1 / 101000315    ; " 
"bjasko";"2012-11-22 12:10:24.953895";"PUSH_IDS_TO_SEMAPHORE(95) : START push_ids_to_semaphore" 
"bjasko";"2012-11-22 12:10:27.542251";"LOCK_SEMAPHORE(123) : table: fakt_doks, status:free START" 

// vzeljka to preuzela, verziju 1094

"vzeljka";"2012-11-22 12:10:27.574385";"DBF_SEMAPHORE_SYNCHRO(247) : 
          dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1093 last_ver: 1094" 
"vzeljka";"2012-11-22 12:10:27.800353";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : 
         END: nuliraj ids-ove - user: vzeljka" 

....

// vzeljka pravi račun 00318

"vzeljka";"2012-11-22 12:10:37.927215";"FAKT_AZUR_SQL(199) : FAKT, sql azuriranje dokumenta: 10-10-00318    - start" 
"vzeljka";"2012-11-22 12:10:37.982081";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 
"vzeljka";"2012-11-22 12:10:37.982081";"LOCK_SEMAPHORE(169) : table: fakt_doks2, status:free - END" 
"vzeljka";"2012-11-22 12:10:37.982081";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 
"vzeljka";"2012-11-22 12:10:37.982081";"LOCK_SEMAPHORE(169) : table: fakt_fakt, status:free - END" 
"vzeljka";"2012-11-22 12:10:37.982081";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : 
          END: update semaphore version after push vzeljka last_ver=       727" 
"vzeljka";"2012-11-22 12:10:37.982081";"PUSH_IDS_TO_SEMAPHORE(96) : 
          push ids: fakt_doks2 / (array): 1 / 101000318    ; " 

// verzija fakt_doks = 1095 (koju željka setuje)

"vzeljka";"2012-11-22 12:10:37.982081";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : 
          END: update semaphore version after push vzeljka last_ver=      1095" 

"vzeljka";"2012-11-22 12:10:37.982081";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
           fakt_doks / (array): 1 / 101000318    ; " 
"vzeljka";"2012-11-22 12:10:37.982081";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : 
          END: update semaphore version after push vzeljka last_ver=       823" 
"vzeljka";"2012-11-22 12:10:37.982081";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
          fakt_fakt / (array): 1 / #2101000318    ; " 

// bjasko setuje svoj "fakt_doks" na verziju 1094 (iako je željka setovala na 1095
// OVAJ DIO MI UOPŠTE NIJE JASAN !!! ZAŠTO JE DO NJEGA UOPŠTE DOŠLO ???????
// JASKO JE NAPRAVIO PUSH verzije 1094, zašto je radio dbf_semaphore_synchro() ?????

"bjasko";"2012-11-22 12:10:39.106287";"DBF_SEMAPHORE_SYNCHRO(247) : 
        dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1093 last_ver: 1094" 
"bjasko";"2012-11-22 12:10:39.280188";"MY_USE(189) : my_use table:fakt_doks / rdd: 
       SEMAPHORE alias: FAKT_DOKS exclusive: .F. new: .F." 
"bjasko";"2012-11-22 12:10:39.472227";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : 
       START: nuliraj ids-ove - user: bjasko" 

// zeljka zavrsava azuriranje računa
"vzeljka";"2012-11-22 12:10:37.982081";"F18_FREE_TABLES(103) : 
         uspjesno izvrseno oslobadjanje tabela (array): 1 / fakt_fakt ; 2 / fakt_doks ; 3 / fakt_doks2 ; " 
"vzeljka";"2012-11-22 12:10:40.54621";"FAKT_AZUR_SQL(274) : FAKT, azuriranje dokumenta - END" 

END: update semaphore version after push vzeljka last_ver= 1095"

treba dodati kod logiranja ime tabele

END: update semaphore version after push: vzeljka / fakt_doks / last_ver= 1095"

čitanjem gornjeg loga jedna stvar je nejasna - to su vremena

1. vzelljka 12:10:37 - ver semaphore: 1095
2. bjasko 12:10:39 - ver semaphore 1093->1094
3. vzeljka radi free_tables 12:10:37
4. ali ažuriranje dokumenta - SQL transakcije se završava u 12:10:40, znači nakon jaska

znači ovaj dio gdje bjasko radio DBF_SEMAPHORE_SYNCHRO mi uopšte nije jasan, zašto ga je radio ????

bjasko je setovao sa update_rec_server.... verziju 1094 i onda je radio i dbf_semaphore_synchro jer je utvrđeno da je kod njega verzija 1093 a treba setovati na 1094

ovaj problem možemo dosta jednostavno reproducirati.

unutar fakt_azur funkcije treba staviti hb_idle ... jedno 5 sekundi nakon što se uradi push ids-ova.

Tako da namjerno usporimo transakciju ažuriranja. Time ćeš moći pri svakom ažuriranju (a unutar koga ti vršiš update fiskalnog računa) imati efekat "gutanja" fakt_doks dokumenta.

Uradi to.

znači: naš slijedeći cilj je postići jednostavnu reprodukcija bug-a

pogledaj,

https://github.com/knowhow/F18_knowhow/blob/a728578dd5a60baa21f409680bf56c68fafc7088/fakt/fakt_azuriranje.prg#L255

push_.... je unutar transakcije

gdje misliš da stavim ?

bojim se da me ne razumiješ

nakon ovih linija stavi hb_IdleSleep( 5 sekundi)

time ćeš transakciju produžiti i na taj način ćeš moći bez problema reproducirati bug sa željkom. To očekujem

Očekujem da ćeš od tri želkina ažuriranja svaki put moži uloviti u tih 5 sekundi da ti izmjenom fiskalnog računa "progutaš" fakt_doks.

Tek kada se to postigne slijedi rad na otklanjanju bug-a

stavi na liniju 260

obratiti pažnju na funkciju

• update_rec_server....

ona radi lock prvo, i ako je lock-ovano ona čeka i vrti.... i to je ok

kada se tabela unlock-uje, ona radi SQL_DELETE, SQL_INSERT i push IDS-ova na server....

A šta je sa podacima koji su došli u toku trajanja lock-a ???

Oni se nikada ne osvježe praktično, prebrišu se

a nije nije... pardon to smo riješili

Kako ovo treba raditi¶

- lock obezbjeđuje da nijedan drugi user ne može vršiti pushiranje novih podataka
- na read operacije nema locka

1. jedan korisnik samo smije pushirati nove podatke u tabelu
2. svi korisnici mogu čitati podatke
3. čitanje mora biti moguće i u toku dok neki korisnik pushira podatke

Ernad Husremović je napisao/la:

čitanjem gornjeg loga jedna stvar je nejasna - to su vremena

1. vzelljka 12:10:37 - ver semaphore: 1095
2. bjasko 12:10:39 - ver semaphore 1093->1094
3. vzeljka radi free_tables 12:10:37
4. ali ažuriranje dokumenta - SQL transakcije se završava u 12:10:40, znači nakon jaska

između free_tables i end_transaction je proteklo 3 sekunde. u tom periodu je jasko vidio verziju 1094 kao posljednu. Tako to i treba - on ne vidi ni željkine ids-ove ni posljednju verziju dok se transakcija ne završi ...

Hm ali to je tako i zamišljeno. To je sasvim ok.

Jasko je kod sljedećeg preuzimanja trebao pokupiti ids-ove od verzije 1095 ?!

Zar po okončanju željkine transakcije nije last_semaphore_version bila 1095 kod svih usera ?! (iza vremena 12:10:40)

takođe, svi useri su po okončanju transakcije morali imati ids-ove u fakt_doks od ovog spornog dokumenta ... to bjasko nije nikako mogao izbrisati, pošto je transakcija bila u toku ... tek nakon transakcije id-ovi su se trebali pojaviti konkretno id u fakt_doks spornog dokumenta.

// bjasko setuje svoj "fakt_doks" na verziju 1094 (iako je željka setovala na 1095
// OVAJ DIO MI UOPŠTE NIJE JASAN !!! ZAŠTO JE DO NJEGA UOPŠTE DOŠLO ???

bjasko u toku transakcije uopšte ne vidi željkine promjene - sve dok je transakcija u toku. on iz tabele čita 1094 last_version, a njegova version = 1093

sve je ok.

// JASKO JE NAPRAVIO PUSH verzije 1094, zašto je radio dbf_semaphore_synchro() ?????

Jasko nije napravio nikakav "push". Jasko je osvježio id-ove koje je tada vidio - a oni su bili zaključno sa verzijom 1094

To je sasvim ok.

On je radio dbf_semaphore_synchro zato što je vidio razliku podataka server njegova kopija 1093->1094

To je sve ok ...

Ono što nije prikazano jeste šta se prilikom sljedećeg pokušaja otvaranja/korištenja dbf-a fakt_doks od strane bjaska desilo.

Koju je verzija semafora fakt_doks čitao ? Trebao je čitati 1095 koju je željka nakon transakcije postavila. Ako je to tako, ako su u semafori id-ovi od te verzije, sve funkcioniše kako treba, barem u ovom dijelu koda.

ovako sam uradio:

vzeljka ažurira račun, kada se pojavila poruka "spavam" (traje 5 sekundi) ja sam pustio opciju "R"

nije mi javljala da je lokovano išta....

tom prilikom sam uočio samo sync fakt_fakt na dnu....

i kada sam odradio refresh - fakat nema dokumenta 00324

kod željke sve normalno

// vzeljka krenula u azuriranje dokumenta 00324

"vzeljka";"2012-11-22 14:00:56.824783";"FAKT_AZUR_SQL(199) : 
             FAKT, sql azuriranje dokumenta: 10-10-00324    - start" 
"vzeljka";"2012-11-22 14:00:56.886356";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 
"vzeljka";"2012-11-22 14:00:56.886356";"F18_FREE_TABLES(103) : 
            uspjesno izvrseno oslobadjanje tabela (array): 
            1 / fakt_fakt ; 2 / fakt_doks ; 3 / fakt_doks2 ; " 
"vzeljka";"2012-11-22 14:00:56.886356";"LOCK_SEMAPHORE(169) : table: fakt_doks2, status:free - END" 
"vzeljka";"2012-11-22 14:00:56.886356";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 
"vzeljka";"2012-11-22 14:00:56.886356";"LOCK_SEMAPHORE(169) : table: fakt_fakt, status:free - END" 
"vzeljka";"2012-11-22 14:00:56.886356";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
           update semaphore version after push 
           user: vzeljka, tabela: fmk.semaphores_fakt_doks2, last_ver=       733" 
"vzeljka";"2012-11-22 14:00:56.886356";"PUSH_IDS_TO_SEMAPHORE(96) : 
            push ids: fakt_doks2 / (array): 1 / 101000324    ; " 

// fakt_doks je verzija = 1106

"vzeljka";"2012-11-22 14:00:56.886356";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
           update semaphore version after push 
           user: vzeljka, tabela: fmk.semaphores_fakt_doks, last_ver=      1106" 
"vzeljka";"2012-11-22 14:00:56.886356";"PUSH_IDS_TO_SEMAPHORE(96) : 
           push ids: fakt_doks / (array): 1 / 101000324    ; " 
"vzeljka";"2012-11-22 14:00:56.886356";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
           update semaphore version after push 
           user: vzeljka, tabela: fmk.semaphores_fakt_fakt, last_ver=       829" 
"vzeljka";"2012-11-22 14:00:56.886356";"PUSH_IDS_TO_SEMAPHORE(96) : 
           push ids: fakt_fakt / (array): 1 / #2101000324    ; " 

// 
// bjasko radi sinhronizaciju u tom momentu.....
// znači opcija "R" otvara tabele O_FAKT, O_FAKT_DOKS itd...

// bjasko uzima da je zadnja transakcija = 1105 ?!???????? (pa ja nije se još željkina transakcija završila

"bjasko";"2012-11-22 14:00:59.131318";"DBF_SEMAPHORE_SYNCHRO(247) : 
           dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1104 last_ver: 1105" 

// i krećem da postavi svoj IDS
"bjasko";"2012-11-22 14:00:59.246961";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
           nuliraj ids-ove - user: bjasko" 

// 
// zeljka završila ažuriranje dokumenta OVDJE JE KRAJ TRANSAKCIJE ... tabele oslobođene !!!!
// praktično tek sada imamo živu verziju = 1106
//

"vzeljka";"2012-11-22 14:01:04.551739";"FAKT_AZUR_SQL(268) : FAKT, azuriranje dokumenta - END" 

//
// bjasko
//

"bjasko";"2012-11-22 14:01:04.808149";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : 
          END: nuliraj ids-ove - user: bjasko" 

// >>>>>>>>>>>>>>>>>
// >>>>>>>>>>>>>>>>> ovo je momenat kada bjasko u fakt_doks IDS nema ništa !!!!!!

"bjasko";"2012-11-22 14:01:04.86854";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
          ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"bjasko";"2012-11-22 14:01:04.927914";"UPDATE_DBF_FROM_SERVER(84) : 
          update_dbf_from_server table: fakt_doks synchro cache:          5.74" 
// <<<<<<<<<<<<<<<<< osvježio je ništa !!!!!!!
// <<<<<<<<<<<<<<<<<
//
// evo ga osvježava fakt_doks2 i fakt_fakt i tu ima podataka i IDS je pun !

"bjasko";"2012-11-22 14:01:06.260037";"DBF_SEMAPHORE_SYNCHRO(247) : 
          dbf_semaphore_synchro/1, my_usefakt_doks2 osvjeziti dbf cache: ver: 731 last_ver: 733" 
"bjasko";"2012-11-22 14:01:06.3781";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
          nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:06.492218";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: 
          nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:06.550703";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
          ids / (array): 1 / (array): 1 / 101000323    ; 2 / 101000324    ;  ;  ; qry / (array): 1 / SELECT 
          idfirma,idtipdok,brdok,k1,k2,k3,k4,k5,n1,n2 FROM fmk.fakt_doks2 WHERE (rpad( idfirma,2) || rpad(
          idtipdok,2)  || rpad(brdok,8)) IN ('101000323   ','101000324   ') ;  ; " 
"bjasko";"2012-11-22 14:01:06.608286";"DELETE_IDS_IN_DBF(383) : delete_ids_in_dbf(), 
          table: fakt_doks2/ dbf_tag =1 pobrisao iz lokalnog dbf-a zapisa = 0" 
"bjasko";"2012-11-22 14:01:06.728374";"FILL_DBF_FROM_SERVER(475) : fill_dbf_from_server(), 
          table: fakt_doks2, count: 2" 
"bjasko";"2012-11-22 14:01:06.786271";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server table: 
          fakt_doks2 synchro cache:          0.47" 

// 
// željka ...
// 

"vzeljka";"2012-11-22 14:01:06.951327";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, 
          my_usefakt_fakt osvjeziti dbf cache: ver: 828 last_ver: 829" 
"vzeljka";"2012-11-22 14:01:07.070263";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
          nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-22 14:01:07.188417";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: 
          nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-22 14:01:07.248225";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
          ids / (array): 1 / ?U? ; 2 / ?U? ;  ; qry / (array): 1 / ?U? ; 2 / ?U? ;  ; " 
"vzeljka";"2012-11-22 14:01:07.304338";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server table: 
          fakt_fakt synchro cache:          0.30" 
"vzeljka";"2012-11-22 14:01:08.760513";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, 
          my_usefakt_doks2 osvjeziti dbf cache: ver: 732 last_ver: 733" 
"vzeljka";"2012-11-22 14:01:09.393943";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
         nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-22 14:01:09.514564";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-22 14:01:09.571236";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"vzeljka";"2012-11-22 14:01:09.637221";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server table: fakt_doks2 synchro cache:          0.81" 
"vzeljka";"2012-11-22 14:01:10.034676";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1105 last_ver: 1106" 
"vzeljka";"2012-11-22 14:01:10.155126";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-22 14:01:10.268932";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-22 14:01:10.330699";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"vzeljka";"2012-11-22 14:01:10.388631";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server table: fakt_doks synchro cache:          0.30" 
"vzeljka";"2012-11-22 14:01:12.398809";"ZAPP(293) : ZAP exclusive: FAKT_PRIPR" 

// 
// bjasko
// 

"bjasko";"2012-11-22 14:01:13.053418";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, 
          my_usefakt_fakt osvjeziti dbf cache: ver: 828 last_ver: 829" 
"bjasko";"2012-11-22 14:01:13.171362";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
          nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:13.303169";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: 
          nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:13.362276";"IDS_SYNCHRO(31) : 
         ids_synchro ids_queries: (hash): ids / (array): 1 / ?U? ; 2 / (array): 1 / 101000324    ;  ;  ; 
         qry / (array): 1 / ?U? ; 2 / SELECT 
         idfirma,idtipdok,brdok,datdok,idpartner,dindem,zaokr,rbr,podbr,idroba,idroba_j,
         serbr,kolicina,cijena,rabat,porez,k1,k2,m1,txt,idvrstep,idpm,fisc_rn,c1,c2,c3,n1,n2 
         FROM fmk.fakt_fakt WHERE (rpad( idfirma,2) || rpad( idtipdok,2)  || 
         rpad(brdok,8)) IN ('101000324   ') ;  ; " 
"bjasko";"2012-11-22 14:01:13.425396";"DELETE_IDS_IN_DBF(383) : delete_ids_in_dbf(), 
         table: fakt_fakt/ dbf_tag =1 pobrisao iz lokalnog dbf-a zapisa = 0" 
"bjasko";"2012-11-22 14:01:13.547654";"FILL_DBF_FROM_SERVER(475) : fill_dbf_from_server(), 
         table: fakt_fakt, count: 1" 
"bjasko";"2012-11-22 14:01:13.610549";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server 
         table: fakt_fakt synchro cache:          0.50" 
"bjasko";"2012-11-22 14:01:19.065912";"MY_USE_SEMAPHORE_OFF(32) : stanje semafora : OFF" 
"bjasko";"2012-11-22 14:01:19.2423";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:lock - END" 
"bjasko";"2012-11-22 14:01:19.298884";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
        update semaphore version after push 
        user: bjasko, tabela: fmk.semaphores_fakt_doks, last_ver=      1107" 
"bjasko";"2012-11-22 14:01:19.298884";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(500) : START: 
        update semaphore version after push" 
"bjasko";"2012-11-22 14:01:19.298884";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
        fakt_doks / (array): 1 / 101000314    ; " 
"bjasko";"2012-11-22 14:01:20.24858";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 
"bjasko";"2012-11-22 14:01:20.311634";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 
"bjasko";"2012-11-22 14:01:32.836146";"DBF_SEMAPHORE_SYNCHRO(247) : 
        dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1106 last_ver: 1107" 
"bjasko";"2012-11-22 14:01:32.956152";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
        nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:33.071985";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: 
        nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:33.13014";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
        ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"bjasko";"2012-11-22 14:01:33.186397";"UPDATE_DBF_FROM_SERVER(84) : 
        update_dbf_from_server table: fakt_doks synchro cache:          0.29" 

evo ga dakle, izvući ću samo bitan dio:

// fakt_doks je verzija = 1106

"vzeljka";"2012-11-22 14:00:56.886356";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
           update semaphore version after push 
           user: vzeljka, tabela: fmk.semaphores_fakt_doks, last_ver=      1106" 
"vzeljka";"2012-11-22 14:00:56.886356";"PUSH_IDS_TO_SEMAPHORE(96) : 
           push ids: fakt_doks / (array): 1 / 101000324    ; " 

// 
// bjasko radi sinhronizaciju u tom momentu.....
// znači opcija "R" otvara tabele O_FAKT, O_FAKT_DOKS itd...
//
// bjasko uzima da je zadnja transakcija = 1105 ?!???????? (pa ja nije se još željkina transakcija završila

"bjasko";"2012-11-22 14:00:59.131318";"DBF_SEMAPHORE_SYNCHRO(247) : 
           dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1104 last_ver: 1105" 

// i krećem da postavi svoj IDS
// nuliranje mu je dozvoljeno 
//

"bjasko";"2012-11-22 14:00:59.246961";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
           nuliraj ids-ove - user: bjasko" 

// 
// zeljka završila ažuriranje dokumenta OVDJE JE KRAJ TRANSAKCIJE ... tabele oslobođene !!!!
// praktično tek sada imamo živu verziju = 1106
//

"vzeljka";"2012-11-22 14:01:04.551739";"FAKT_AZUR_SQL(268) : FAKT, azuriranje dokumenta - END" 

//
// bjasko nulira svoju transakciju
// i pojela maca dokument !!!!!!!
//

"bjasko";"2012-11-22 14:01:04.808149";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : 
          END: nuliraj ids-ove - user: bjasko" 

// >>>>>>>>>>>>>>>>>
// >>>>>>>>>>>>>>>>> ovo je momenat kada bjasko u fakt_doks IDS nema ništa !!!!!!

"bjasko";"2012-11-22 14:01:04.86854";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
          ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"bjasko";"2012-11-22 14:01:04.927914";"UPDATE_DBF_FROM_SERVER(84) : 
          update_dbf_from_server table: fakt_doks synchro cache:          5.74" 
// <<<<<<<<<<<<<<<<< osvježio je ništa !!!!!!!
// <<<<<<<<<<<<<<<<<
//
// evo ga osvježava fakt_doks2 i fakt_fakt i tu ima podataka i IDS je pun !

"bjasko";"2012-11-22 14:01:06.260037";"DBF_SEMAPHORE_SYNCHRO(247) : 
          dbf_semaphore_synchro/1, my_usefakt_doks2 osvjeziti dbf cache: ver: 731 last_ver: 733" 
"bjasko";"2012-11-22 14:01:06.3781";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(558) : START: 
          nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-22 14:01:06.492218";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(568) : END: 
          nuliraj ids-ove - user: bjasko" 
.....

sporan je dio čitanja podataka i nuliranja....

u momenut čitanja podataka za bjaska:

fakt_doks je bio verzija 1105 / uzeo je neke tada podatke

u momentu kada je bjasko radio NULIRANJE_IDS-a :

-> željka završila transakciju i setovala je na 1106 -> puširala i IDS

bjasko je setovao na zadnju aktuelnu verziju 1106, umjesto na 1105 i praktično ispraznio svoj IDS (a bio je željkin dokument)

tu je bug !!!!

praktično dio čitanja podataka nije zaštićen lokovima...

Saša Vranić je napisao/la:

sporan je dio čitanja podataka i nuliranja....

u momenut čitanja podataka za bjaska:

fakt_doks je bio verzija 1105 / uzeo je neke tada podatke

u momentu kada je bjasko radio NULIRANJE_IDS-a :

-> željka završila transakciju i setovala je na 1106 -> puširala i IDS

bjasko je setovao na zadnju aktuelnu verziju 1106, umjesto na 1105 i praktično ispraznio svoj IDS (a bio je željkin dokument)

tu je bug !!!!

što će ga reći, preskočio je jednu verziju

ovo je momenat kada bjasko u fakt_doks IDS nema ništa !!!!!!

a koju verziju semafora bjasko čita ? onu što je vzeljka postavila u transakciji ?

last_transaction_version je kako treba (željkino) ali ids je prazan (nema željkinih stavki ?!)

to mi je čudno. to je nemoguće

Treba dodati logirati version, last_transaction_version u ovom trenutku da nam sve bude jasno

Dodaj ono iščitavanje verzije semafora u unutar funkcija nuliranja i update-a semafora

if log_level() > 6 
  versions = get_semaphore_version_h()
  logiraj versions["version"] i ["last_trasaction_version"]
endif

bjasko je setovao na zadnju aktuelnu verziju 1106, umjesto na 1105 i praktično ispraznio svoj IDS (a bio je željkin dokument)

šta je setovao ? svoje polje "version" u semaforima ?

Ja i dalje ne vidim to što govoriš.

To znači da je u toku transakcije vidljivo to što željka radi ?

Ovako kako je podešeno najbolje da u toku umentute pauze, dok transakcija traje, pročitaš stanje fmk.semaphores_fakt_doks tabele kao user bjasko.

Umetni dvije pauze unutar transakcije:

begin sql transakcije
...

sleep(5) sekundi prije pusha   <<<<<<< šta vidi bjasko u semaphores tabeli u ovom intervalu

push ids operacije ...

sleep(5) seknudi nakon pusha <<<<<<< šta vidi bjasko u ovom intervalu
...
kraj sql transakcije 

Momenti ponovo¶

A u momenut čitanja podataka za bjaska:

fakt_doks je bio verzija 1105 / uzeo je neke tada podatke

u momentu kada je bjasko radio NULIRANJE_IDS-a :

željka završila transakciju i setovala je na 1106 -> puširala i IDS

Gornje pauze i testovi će izbaciti priču o "momentima".

Ovdje je glavno pitanje šta korisnik bjasko vidi, a šta ne vidi u periodu trajanja željkine transakcije. Naravno mislim na stanje tabele semafora.

Ernad Husremović je napisao/la:

bjasko je setovao na zadnju aktuelnu verziju 1106, umjesto na 1105 i praktično ispraznio svoj IDS (a bio je željkin dokument)

šta je setovao ? svoje polje "version" u semaforima ?

Ja i dalje ne vidim to što govoriš.

To znači da je u toku transakcije vidljivo to što željka radi ?

Ovako kako je podešeno najbolje da u toku umentute pauze, dok transakcija traje, pročitaš stanje fmk.semaphores_fakt_doks tabele kao user bjasko.

Umetni dvije pauze unutar transakcije:

[...]

da, setovao je svoje polje version na 1106 (prema zanjem aktuelnom što je željka puširala) i tom prilikom rekao IDS = NULL (ipraznio svoj ids), mislim da je tada imao u IDS-u da pokupi podatke transakcije 1106 - a on to nij e uradio

bjaskova trenutna verzija 1104, uzeo podatke IDS-a verzije 1105

zatim setuje/nulira IDS i setuje sa verzije 1104 -> 1106 svoju verziju i tom prilikom prazni IDS polje

zašto na 1106 ? zato što je željka završila svoju transakciju i sa 1105 setovala na 1106

... tako da ono što mu je željka postavila sa verzijom 1106 u IDS - gubi !

ako u funkciju nuliraj_ids.... postavimo da prvo iščita šta ima pa da to logira, trebali bi da znamo šta je tu bilo prije nuliranja ids-a

recimo, nakon ovog prvog test-a smo pokušali još dva puta

1) imamo isto stanje podataka, željka ažurira sa spavanjem -> ja radim opciju "R" -> sve ok na kraju
2) željka napravila jedan dokument, pa zatim pravi novi i u momemtu kada spava transakcija ja ponavljam ovo isto -> opet stanje ok na kraju

napravio sam novi commit - stavio sam operaciju čitanja ids polja, update-a verzije semafora i nuliranja u jednu sql transakciju

provjeri samo da li je ispravna SQL sintaksa pa napravi gornje testove

zatim setuje/nulira IDS i setuje sa verzije 1104 -> 1106 svoju verziju i tom prilikom prazni IDS polje
zašto na 1106 ? zato što je željka završila svoju transakciju i sa 1105 setovala na 1106

ako stavimo sve bjasko operacije unutar jedne SQL trasakcije, bjasko bi morao vidjeti IDS i verziju onakvu kako je započeo transakciju.

Saša Vranić je napisao/la:

recimo, nakon ovog prvog test-a smo pokušali još dva puta

1) imamo isto stanje podataka, željka ažurira sa spavanjem -> ja radim opciju "R" -> sve ok na kraju
2) željka napravila jedan dokument, pa zatim pravi novi i u momemtu kada spava transakcija ja ponavljam ovo isto -> opet stanje ok na kraju

znači da nismo uspjeli reproducirati sa sigurnošću bug ! To nije dobro.

Ernad Husremović je napisao/la:

napravio sam novi commit - stavio sam operaciju čitanja ids polja, update-a verzije semafora i nuliranja u jednu sql transakciju

provjeri samo da li je ispravna SQL sintaksa pa napravi gornje testove

ne kontam šta bi ovo trebalo da radi:

select ids .... ;
update set ids = null ;

i vraća TRUE jer je update zadnja komanda... selekta nikada ni ne vidimo

pretpostavljam da si htjeo ovo:

BEGIN;
_ids := SELECT ids .....
update ids = null ....
END;

uh dobro si.

ovo uopšte ne vraća select

ali to što si napisao ne radi u sql-u ...

ovo ne može unutar jednog sql izraza, moraju se koristiti funkcije sql_table_update funkcije sa begin, end... i imati 2 poziva prema serveru

Ernad Husremović je napisao/la:

ali to što si napisao ne radi u sql-u ...

znam :) nego samo ono što treba da se desi

http://stackoverflow.com/questions/6763692/postgres-update-after-select

aaaaaa momenat momenat, ne vjeruješ ti meni :)

update fmk.semaphores_fmk_test set version=999 where user_code='hernad' returing version, last_trans_version =>

vratiće stanje polja nakon update operacije

napravio sam novi commit koji onu one sql transakciju razbija na više upita prema serveru, ali opet transakcija

Saša Vranić je napisao/la:

aaaaaa momenat momenat, ne vjeruješ ti meni :)

i dalje nisam siguran da smo riješili problem. Ako ti to znači šta ne vjerujem ni tebi ni sebi.

Reprodukcija bug-a nije 100% sigurna, što znači da ni uzrok nije jasan

testirao pauze - transakcija izoluje sve promjene - promjene se ne vide dok se transakcija ne okonča.

Sada će biti interesantno napraviti gornji test.

izbrisao sam pauze

kod testova ih vrati ali nemoj više commit-ovati

Prije ovoga smo napravili opet jedan test sa grupom faktura nekih 10, sada je sve ok, imamo isto stanje.

Moguće je da smo problem riješili.

Sutra ćemo napraviti opet veliki test sa 30-ak faktura i simultanim radom. Sada moram ići.

treba napraviti te testova sa dužim pauzama. bez obzira na njih, ne bi se smjelo dešavati "gutanje" dokumenata

Slično kao pauze unutar ažuriranja, pauzu treba dodati
pauzu treba dodati i pauzu između selecta i update-a ovdje

jutros nastavili testove, i evo od 15 dokumenata jedan je opet izgubljen, ali nažalost ne mogu se sjetiti šta sam uradio i u kojem momentu...

znači kod željke je sleep prije i nakon puširanja...

opcija da štampam fiskalni račun uporedo sa njom nije u pitanju, dobijam fakt_doks zauzet i čekam na retry i nakon toga mi se osvježi fino doks...

fali mi dokument 10-10-00342

u nekoj fazi sam lupio F5 i tačno sam vidio da je samo fakt_fakt i fakt_doks2 osvježen, odmah sam znao da će dokument faliti, ali ne mogu se sjetiti u kojoj fazi (mislim na to u kojem je dijelu bila željka sa unosom)

jutros nastavili testove, i evo od 15 dokumenata jedan je opet izgubljen, ali nažalost ne mogu se sjetiti šta sam uradio i u kojem momentu...
znači kod željke je sleep prije i nakon puširanja...

Rekonstruiši događaje na osnovu logova. Ako nešto fali, dopuni log funkcije.

nisam siguran šta će user dobiti u update statementu za last_trans_version

zato dodaj version, last_trans_version logiranje kako stoji u note-92 u ovu tačku na početku SQL transakcije (prije prvog selecta), ali i nakon upate-a na kraju transakcije

Time ćeš imati egzaktne pokazatelje vezano za tvoje sumnje "u momentu čitanja jedan broj, u momentu nuliranja drugi broj last_trans_version"

generalno, detaljnije logiranje version, last_trans_version mora otkriti uzrok bug-a.

i evo mislim potpuno identična situacija log-a kao i jučer....

//
// bjasko setuje broj fiskalnog računa
//

"bjasko";"2012-11-23 09:31:27.991638";"MY_USE_SEMAPHORE_OFF(32) : stanje semafora : OFF" 

"bjasko";"2012-11-23 09:31:28.185268";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:lock - END" 

"bjasko";"2012-11-23 09:31:28.243148";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(500) : START: 
          update semaphore version after push" 
"bjasko";"2012-11-23 09:31:28.243148";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
          fakt_doks / (array): 1 / 101000337    ; " 

// pravi verziju 1134

"bjasko";"2012-11-23 09:31:28.243148";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
         update semaphore version after push 
         user: bjasko, tabela: fmk.semaphores_fakt_doks, last_ver=      1134" 

// 
// vzeljka ce da pusti racun
// lokuje tabele
//

"vzeljka";"2012-11-23 09:31:28.504736";"LOCK_SEMAPHORE(169) : table: fakt_fakt, status:lock - END" 
"vzeljka";"2012-11-23 09:31:28.504736";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:lock - END" 
"vzeljka";"2012-11-23 09:31:28.504736";"LOCK_SEMAPHORE(169) : table: fakt_doks2, status:lock - END" 

//
// bjasko završava sa svojom transakcijom - oslobađa semafor
//
// bjasko ovdje oslobodio fakt_doks ?????? iako ga je željka lokovala
//

<<<<<<<<<<<<<< krtitična tačka 1

"bjasko";"2012-11-23 09:31:29.144417";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 
"bjasko";"2012-11-23 09:31:29.205468";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 

//
// vzeljka nastavlja
// 

"vzeljka";"2012-11-23 09:31:29.713279";"F18_LOCK_TABLES(60) : uspjesno izvrsen lock tabela (array): 
          1 / fakt_fakt ; 2 / fakt_doks ; 3 / fakt_doks2 ; " 

"vzeljka";"2012-11-23 09:31:29.770457";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 

// osvježava verziju 1134 

"vzeljka";"2012-11-23 09:31:30.340577";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, 
           my_usefakt_doks osvjeziti dbf cache: ver: 1133 last_ver: 1134" 
"vzeljka";"2012-11-23 09:31:30.405377";"GET_IDS_FROM_SEMAPHORE(163) : START get_ids_from_semaphore" 
"vzeljka";"2012-11-23 09:31:30.695387";"GET_IDS_FROM_SEMAPHORE(210) : END get_ids_from_semaphore" 
"vzeljka";"2012-11-23 09:31:30.750314";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(559) : START: 
          nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-23 09:31:30.857439";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(569) : END: 
          nuliraj ids-ove - user: vzeljka" 
"vzeljka";"2012-11-23 09:31:30.925942";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
          ids / (array): 1 / (array): 1 / 101000337    ;  ;  ; qry / (array): 1 / SELECT... 
"vzeljka";"2012-11-23 09:31:30.983572";"DELETE_IDS_IN_DBF(397) : delete_ids_in_dbf(), 
          table: fakt_doks/ dbf_tag =1 pobrisao iz lokalnog dbf-a zapisa = 1" 
"vzeljka";"2012-11-23 09:31:31.113772";"FILL_DBF_FROM_SERVER(475) : fill_dbf_from_server(), 
          table: fakt_doks, count: 1" 
"vzeljka";"2012-11-23 09:31:31.351628";"UPDATE_DBF_FROM_SERVER(84) : update_dbf_from_server 
          table: fakt_doks synchro cache:          0.95" 

//
// željka ažurira dokument
//

"vzeljka";"2012-11-23 09:31:31.925532";"MY_USE_SEMAPHORE_OFF(32) : stanje semafora : OFF" 
"vzeljka";"2012-11-23 09:31:32.055744";"FAKT_AZUR_SQL(199) : 
           FAKT, sql azuriranje dokumenta: 10-10-00342    - start" 
"vzeljka";"2012-11-23 09:31:32.11371";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(500) : START: 
           update semaphore version after push" 
"vzeljka";"2012-11-23 09:31:32.11371";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
          fakt_fakt / (array): 1 / #2101000342    ; " 
"vzeljka";"2012-11-23 09:31:32.11371";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
          update semaphore version after push 
          user: vzeljka, tabela: fmk.semaphores_fakt_fakt, last_ver=       847" 
"vzeljka";"2012-11-23 09:31:32.11371";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
          fakt_doks / (array): 1 / 101000342    ; " 
"vzeljka";"2012-11-23 09:31:32.11371";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(500) : START: 
          update semaphore version after push" 

// pravi verziju 1135

"vzeljka";"2012-11-23 09:31:32.11371";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
          update semaphore version after push 
          user: vzeljka, tabela: fmk.semaphores_fakt_doks, last_ver=      1135" 
"vzeljka";"2012-11-23 09:31:32.11371";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: 
          fakt_doks2 / (array): 1 / 101000342    ; " 
"vzeljka";"2012-11-23 09:31:32.11371";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(500) : START: 
          update semaphore version after push" 
"vzeljka";"2012-11-23 09:31:32.11371";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
          update semaphore version after push 
          user: vzeljka, tabela: fmk.semaphores_fakt_doks2, last_ver=       751" 
"vzeljka";"2012-11-23 09:31:32.11371";"LOCK_SEMAPHORE(169) : table: fakt_fakt, status:free - END" 
"vzeljka";"2012-11-23 09:31:32.11371";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 
"vzeljka";"2012-11-23 09:31:32.11371";"LOCK_SEMAPHORE(169) : table: fakt_doks2, status:free - END" 
"vzeljka";"2012-11-23 09:31:32.11371";"F18_FREE_TABLES(103) : 
          uspjesno izvrseno oslobadjanje tabela (array): 1 / fakt_fakt ; 2 / fakt_doks ; 3 / fakt_doks2 ; " 
"vzeljka";"2012-11-23 09:31:32.11371";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 

//
// bjasko treba da osvježi verziju 1134 
// 
// i dalje mi nije jasno zašto je jasko ovo radio ?????? on je napravio promjenu 1134 ???????
// zašto je okinuo sinhronizaciju ?????
//

<<<<<<<<<<<<<<<<< kritična tačka 2

"bjasko";"2012-11-23 09:31:42.779163";"DBF_SEMAPHORE_SYNCHRO(247) : dbf_semaphore_synchro/1, 
        my_usefakt_doks osvjeziti dbf cache: ver: 1133 last_ver: 1134" 
"bjasko";"2012-11-23 09:31:42.839557";"GET_IDS_FROM_SEMAPHORE(163) : START get_ids_from_semaphore" 
"bjasko";"2012-11-23 09:31:44.073371";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(559) : START: 
        nuliraj ids-ove - user: bjasko" 

//
// željka završila transakciju ažuriranja dokumenta
//

"vzeljka";"2012-11-23 09:31:54.720832";"FAKT_AZUR_SQL(272) : FAKT, azuriranje dokumenta - END" 

//
// bjasko nulira svoje IDS-ove
//

"bjasko";"2012-11-23 09:31:54.939046";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(569) : END: 
        nuliraj ids-ove - user: bjasko" 

// opet doks IDS = ?????????

"bjasko";"2012-11-23 09:31:55.000099";"IDS_SYNCHRO(31) : ids_synchro ids_queries: (hash): 
        ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"bjasko";"2012-11-23 09:31:55.061568";"UPDATE_DBF_FROM_SERVER(84) : 
        update_dbf_from_server table: fakt_doks synchro cache:         12.22" 

pa i nije situacija kao jučer, imamo sada ove dvije kritične tačke

1) bjasko odradio odradio unlock fakt_doks iako ga je vzeljka lock-ovala

2) bjasko napravio sinhronizaciju podataka sa verzijom koju je on napravio

1) bjasko odradio odradio unlock fakt_doks iako ga je vzeljka lock-ovala

postoji timeout vrijeme kod unlocka - nakon tog vremena user može unlockovati tabelu čak iako je u stanju "locked"

to je uvedeno da se ne bi desili dead lock-ovi (nekon je zaključao i u po te transakcije ispao iz aplikacije npr)

radi pauza koje si uveo vjerovatno je to vrijeme okinuto. Treba to vrijeme treba povećati u toku ovih testova jer si kod svih operacija ažuriranja vještački izazvao sporost.

ako je ovaj nasilni (timeout) unlock od strane jaska izazvao gutanje te stavke, test koji si radio NIJE REPREZENTATIVAN

evo, napravio sam tako.... opet smo kuckali i opet sam isprovocirao problem

• imao sam da osvježim jedan dokument
• željka pravila novi i bila u procesu ažuriranja između ona dva sleep-a
• ja sam rekao F5 u pregledu i dobio sao fakt_fakt osvježen

sada ćemo da vidimo log

evo dijela log-a

//
// vzeljka ažurira dokument i pravi verziju "1160" 
//

"vzeljka";"2012-11-23 10:53:30.062435";"FAKT_AZUR_SQL(199) : 
          FAKT, sql azuriranje dokumenta: 10-10-00355    - start" 
"vzeljka";"2012-11-23 10:53:30.11817";"MY_USE_SEMAPHORE_ON(38) : stanje semafora : ON" 
"vzeljka";"2012-11-23 10:53:30.11817";"F18_FREE_TABLES(103) : 
          uspjesno izvrseno oslobadjanje tabela (array): 1 / fakt_fakt ; 2 / fakt_doks ; 3 / fakt_doks2 ; " 
"vzeljka";"2012-11-23 10:53:30.11817";"LOCK_SEMAPHORE(169) : table: fakt_doks2, status:free - END" 
"vzeljka";"2012-11-23 10:53:30.11817";"LOCK_SEMAPHORE(169) : table: fakt_doks, status:free - END" 
"vzeljka";"2012-11-23 10:53:30.11817";"LOCK_SEMAPHORE(169) : table: fakt_fakt, status:free - END" 
"vzeljka";"2012-11-23 10:53:30.11817";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(543) : END: 
          update semaphore version after push 
          user: vzeljka, tabela: fmk.semaphores_fakt_doks, last_ver=      1160" 
"vzeljka";"2012-11-23 10:53:30.11817";"UPDATE_SEMAPHORE_VERSION_AFTER_PUSH(500) : START: 
          update semaphore version after push" 
"vzeljka";"2012-11-23 10:53:30.11817";"PUSH_IDS_TO_SEMAPHORE(96) : push ids: fakt_doks / (array): 1 / 101000355    ; " 

//
// bjasko, tu radi F5 u pregledu

// treba da osvježi 1159, jer je to zatekao
//

"bjasko";"2012-11-23 10:53:42.690322";"DBF_SEMAPHORE_SYNCHRO(247) : 
         dbf_semaphore_synchro/1, my_usefakt_doks osvjeziti dbf cache: ver: 1158 last_ver: 1159" 

"bjasko";"2012-11-23 10:53:42.746136";"GET_IDS_FROM_SEMAPHORE(164) : START get_ids_from_semaphore" 

"bjasko";"2012-11-23 10:53:42.80403";"GET_IDS_FROM_SEMAPHORE(178) : 
          prije SELECT, tabela: fakt_doks, version: 1158 last version: 1159" 

<<<<<<<<<<<<<<<<<<<<<<<<<<<<< ulijeće 1160 ........

"bjasko";"2012-11-23 10:53:42.80403";"GET_IDS_FROM_SEMAPHORE(205) : 
          nakon UPDATE tabela: fakt_doks, version: 1160 last version: 1160" 

//
// vzeljka zavrsava transakciju
// 

"vzeljka";"2012-11-23 10:53:52.725706";"FAKT_AZUR_SQL(272) : FAKT, azuriranje dokumenta - END" 

//
// bjasko nulira svoj IDS
//

"bjasko";"2012-11-23 10:53:53.393945";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(559) : START: 
         nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-23 10:53:53.518833";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(569) : END: 
         nuliraj ids-ove - user: bjasko" 
"bjasko";"2012-11-23 10:53:53.576173";"IDS_SYNCHRO(31) : 
         ids_synchro ids_queries: (hash): ids / (array): 1 / ?U? ;  ; qry / (array): 1 / ?U? ;  ; " 
"bjasko";"2012-11-23 10:53:53.64597";"UPDATE_DBF_FROM_SERVER(84) : 
         update_dbf_from_server table: fakt_doks synchro cache:         10.90" 

itd.... idu i fakt_fakt i fakt_doks2.....

ovo je opasno:

"bjasko";"2012-11-23 10:53:42.80403";"GET_IDS_FROM_SEMAPHORE(178) : 
          prije SELECT, tabela: fakt_doks, version: 1158 last version: 1159" 

// u selektu sam dobio IDS verzije 1159

// update uradio na 1160, ali nikada nisam pokupio taj IDS

"bjasko";"2012-11-23 10:53:42.80403";"GET_IDS_FROM_SEMAPHORE(205) : 
          nakon UPDATE tabela: fakt_doks, version: 1160 last version: 1160" 

// pobrisao IDS
"bjasko";"2012-11-23 10:53:53.393945";"NULIRAJ_IDS_AND_UPDATE_MY_SEMAPHORE_VER(559) : START: 
         nuliraj ids-ove - user: bjasko" 

rezime nije u transakciji, rezime je da

get_ids_from_semaphore()

mora biti pod lock-om, praktično tada niko ne smije upisivati ništa u moj IDS dok ja ne pokupim i setujem na verziju koju sam zatekao....

• ako sam zatekao da je moja verzija 1158 a zadnja da je 1159, ja moram pokupiti IDS i setovati svoju verziju na 1159
• ako sam zatekao da je moja verzija 42 a zadnja verzija je 3121, ja moram pokupiti taj IDS i setovati svoju verziju na 3121

praktično ovaj kod:

lock(table)

>>> _ids := "SELECT ids" 

>>> "UPDATE semaphore SET ids = NULL" 

unlock(table)

u ovom periodu mi niko ništa ne smije upisati

da bude reprezentativnije, događaj je ovakav:

bjasko                                        vzeljka
=============                                 ===================

// verzija 500 
_ids := "SELECT ids" => ["101000421", ...]

                                        <<<< stigla verzija 501
                                        <<<< u IDS-u dobio i ["101000422"]
// u svom selektu nemam ovaj 000422
// dokument uopšte 

// nuliram IDS i setujem verziju na 501
"UPDATE SET ids = NULL verzija = 501" 

// praktično pojedem taj dokument

a trebalo bi da se odvije ovo:

bjasko                                        vzeljka
=============                                 ===================

lock( fakt_doks )

// verzija 500 
_ids := "SELECT ids" => ["101000421", ...]

                                               <<<< zeljki vrti loop da je fakt_doks zauzet

// nuliram IDS i setujem verziju na 500
"UPDATE SET ids = NULL verzija = 500" 

unlock( fakt_doks )

                                               <<<< zeljka pravi verziju 501
                                               <<<< u IDS-u dobio i ["101000422"]

taj lock bi bio jako kratak, praktično lock samo dok ne uradi

• SELECT
• UPDATE

ali je problem što je tabela već lock-ovana od strane željke....

to sam i prije 15 dana isto uočio na prvim testovima a evo se pokazalo sada sa novim logiranjem i tačno

saša, dosta puta sam rekao, ali to očigledno nismo apsolvirali

Ovo je polazište. Molim te da ga pažljivo pročitaš http://redmine.bring.out.ba/issues/29667#note-83

Ta priča o lock/free operacija na aplikativnom nivu kod operacija čitanja JE NEPRIHVATLJIVA.

To ne može biti rješenje. Vratili bi se onda na verzije prije 1.3.x i žalbe klijenata kako je sve zakočilo.

Saša Vranić je napisao/la:

to sam i prije 15 dana isto uočio na prvim testovima a evo se pokazalo sada sa novim logiranjem i tačno

Jedino je tačno da nismo postigli cilj, stvar ne funkcioniše. To što ti zadnjih 15 dana ponavljaš nije rješenje.

Dobro, log nam je sada fino pokazao stvar, jesi uočio šta se desilo ?

Ja sam iznjeo problematiku, a šta je rješenje... to ne znam.

rezime nije u transakciji, rezime je da get_ids_from_semaphore() mora biti pod lock-om, praktično tada niko ne smije upisivati ništa u moj IDS dok ja ne pokupim i setujem na verziju

Dobro. Vidim da svu svoju energiju i analizu usmjeravaš na potvrdu teze: "mora lock kod čitanja".

Pokušaću skrenuti priču ka mogućim rješenjima, ako SQL transakcija ne može obaviti posao ovako kako smo uradili:

a) napraviti stored proceduru koja će obaviti one dvije operacije select radi uzimanja brojeva, pa onda update verzije semafora

b) napraviti još jedno ids_other polje u koje će drugi korisnici stavljati ids-ove tako da se eliminiše situacija "jedan prebrisao drugoga" ...

c) neka kombinacija a i b

Saša Vranić je napisao/la:

Dobro, log nam je sada fino pokazao stvar, jesi uočio šta se desilo ?

Ja sam iznjeo problematiku, a šta je rješenje... to ne znam.

ne nisam dovoljno detalljno pročio. zakači log u cjelosti od jutros, u kom vremenskom period se desio konflikt. takođe sortiraj log po vremenu - od starijeg ka novijem (ako je to potrebno)

Što se tiče ovog problema, radi na njemu do 14:00 max.

Svakako će analiza loga ili testovi sa željkom biti najkorisniji u tom periodu da što više "ogolimo" - izolujemo problem.

Nakon toga se ponovo vrati na pripreme za ramaglas, nastavi tamo gdje si stao kod prijave ovog bug-a.

Vezano za primjer koji si gore naveo note-126:

// nuliram IDS i setujem verziju na 501

"UPDATE SET ids = NULL verzija = 501"

// praktično pojedem taj dokument

u toku tvoje SQL transakcije željka završi svoju SQL transakciju.

To mi je nejasno s obzirom da obje transakcije rade update iste tabele fmk.semaphores_fakt_doks

Pokušaj detaljnije analzirati stanje tabele semafori tokom ovog procesa ... nije mi jasno kako SQL transkcije jedna "drugoj upadaju u riječ"

možda treba promijeniti stepen izolacije SQL transakcija ... to sam kod full synca radio i iščitavao.

common/semaphores_full_algoritam.prg: run_sql_query("BEGIN; SET TRANSACTION ISOLATION LEVEL SERIALIZABLE")

Jedina stvar koja mi je sinula je sljedeća

• može li biti da sam imamo u IDS-u markiran dokument 10-10-000400 a da u fakt_doks tabeli na serveru taj dokument još nije stigao ?

ovo govorim iz onih razloga što se dešavalo da nestaju stavke, recimo na jednoj radnoj stanici fin imamo 10 stavki naloga a na drugoj imamo 15 itd...

Ernad Husremović je napisao/la:

Saša Vranić je napisao/la:

Dobro, log nam je sada fino pokazao stvar, jesi uočio šta se desilo ?

Ja sam iznjeo problematiku, a šta je rješenje... to ne znam.

ne nisam dovoljno detalljno pročio. zakači log u cjelosti od jutros, u kom vremenskom period se desio konflikt. takođe sortiraj log po vremenu - od starijeg ka novijem (ako je to potrebno)

pa stavljao sam dijelove loga koji su bitni sa komentarima šta se događalo

Nisam uopšte usmjerio energiju na lock/nelock samo analiziram šta se desilo i radi čega, a to je prikazano u ovim isječcima logova

u 126 komentaru kažeš:

bjasko                                        vzeljka
=============                                 ===================

BEGIN SQL bjasko

// verzija 500 
_ids := "SELECT ids" => ["101000421", ...]

                                        <<<< stigla verzija 501
                                        <<<< u IDS-u dobio i ["101000422"]
// u svom selektu nemam ovaj 000422
// dokument uopšte 

// nuliram IDS i setujem verziju na 501
"UPDATE SET ids = NULL verzija = 501"  <<<<<<<<<<<< zar u toku bjasko transakcije nije čitavo vrijeme nevidljivo ono što rade drugi .... može biti da i nije
                                                              <<<<<<<<<<<< ... može biti da po okončanju željkine transakcije bjasko vidi to što je pushirala željka

// praktično pojedem taj dokument

COMMIT bjasko

Saša Vranić je napisao/la:

Jedina stvar koja mi je sinula je sljedeća

• može li biti da sam imamo u IDS-u markiran dokument 10-10-000400 a da u fakt_doks tabeli na serveru taj dokument još nije stigao ?

SQL transakcija bi trebala da obezbjedi integritet. To znači da bi drugi korisnik trebao da vidi ili sve ili ništa.

Tvoje pitanje govori da još dosta toga nagađamo. Sve mi kazuje da nismo dijagnostiku završili.

Saša Vranić je napisao/la:

Nisam uopšte usmjerio energiju na lock/nelock samo analiziram šta se desilo i radi čega, a to je prikazano u ovim isječcima logova

Objasniću ti šta mislim pod ovim.

Kod dijagnostike treba hipoteze staviti po strani da bi se analiza što objektivnije uradila.

Hipoteze treba imati na umu kod postavljanja - pripreme testova, ali unutar samog testa treba se što više odmaknuti (ostaviti po strani) hipoteze.

Hipoteze će postati činjenice na osnnovu dobre analize, u našem slučaju kvalitetnom izolacijom bug-a, kvalitetnom i jasnom prezentacijom workaround-a i mogućih rješenja.

ja ću se prebaciti na ove druge stvari, već sam dobro skašen od ovoga

http://www.postgresql.org/docs/9.1/static/transaction-iso.html#MVCC-ISOLEVEL-TABLE

defaultni "READ COMMITED" isoltaion level transakcije omogućava da se u toku transakcije VIDE stvari drugih transakcija koje su završene

Korisnici mogu vidjeti nonrepeatable read i phantom read.

• nonrepeatable read
  • A transaction re-reads data it has previously read and finds that data has been modified by another transaction (that committed since the initial read).

• phantom read
  • A transaction re-executes a query returning a set of rows that satisfy a search condition and finds that the set of rows satisfying the condition has changed due to another recently-committed transaction.

Ukratko ako u toku bjasko transakcije vzeljka uspješno obavi transakciju, po njenom okončanju on će u toku svoje transakcije vidjeti stavke koje je željka napravila.

Postavlja se pitanje šta će se desiti kada stavim maksimalni isolation level ?

- Da li će nakon toga posljednja - bjaskova transakcija "ubiti" željkinu ? Hm to nema smisla ... to vodi gubitku podataka
- Da li će jaskova transakcija biti ponovo izvršena - to bi bilo rješenje.

Saša Vranić je napisao/la:

ja ću se prebaciti na ove druge stvari, već sam dobro skašen od ovoga

Ma da to je najbolje. Ovo je fakat pravo "pipavo" i zamorno ... Čovjeku se mozak bukvalno "skvrči" od razmišljanja na ovu temu :)

U svakom slučaju puno si pomogao da se približimo uzroku problema.

a generalno, ako postavim break point između

• SELECT IDS
• UPDATE IDS

i sačekam da željka ubaci dokument mogu vidjeti šta se desilo sa mojim semaforom

desit će pretpostavljam ovo:

IDS = SELECT IDS verzija 500 < imat ću tu jedan dokument za pokupiti

break point < čekam

željka završi svoju transakciju > puširat će mi na moj semafor još jedan dokument i setovati verziju na 501

<<< ja nastavim

UPDATE IDS = NULL i setujem na verziju tekuću a to je 501 tako da ću ovo što mi je željka ubacila samo prebrisati

... i to je praktično ono što nam se događa ovdje

Da ... do je čista reprodukcija problema

Hajde probajte sa varijantom u kojoj se ovo nuliranje obavlja sa

run_sql_query("BEGIN; SET TRANSACTION ISOLATION LEVEL SERIALIZABLE")

umjesto sa običnim "BEGIN" -om kako je sada

još samo to probajte: )

ovdje stavite run_sql_query( BEGIN; SET TRANSACTION ISOLATION LEVEL SERIALIZABLE )

UPDATE IDS = NULL i setujem na verziju tekuću a to je 501 tako da ću ovo što mi je željka ubacila samo prebrisati

verzija će biti 500, to znam.

Ali ne znam kakve ću id-ove imati nakon izlaska iz transakcije.

1) da li će moj NULL pobijediti (što nije dobro) ?
2) ili će ostati željkino stanje (znači ostaće i id-ove koje sam ja htio nulirati - ovo je takođe prihvatljivo jer nećemo imati gubitak podataka
3) ili će se transakcija ponoviti radi neuspjeha

hmmm ... ovo treće je najvjerovatnije to što će se desiti.

Onda moramo hendlirati situaciju kada je transakcija neispješna !

šta to znači trebamo imati

BEGIN SERIALIZATION ISOLATION

   select ---
   update ... <<<<< ovdje će se desiti error ?

END

ali će se onda desiti gledajući ovaj kod QUIT iz aplikacije ?

nešto slično se ovdje dešava: http://wiki.postgresql.org/wiki/SSI

trebala bi se desiti greška

sql_table_update(nil, "BEGIN; SET TRANSACTION ISOLATION LEVEL SERIALZABLE")

NE FUNKCIONIŠE !

treba

run_sql_query( "BEGIN; SET TRANSACTION ISOLATION LEVEL SERIALZABLE" )

dodao sam commit koji radi rollback a nakon toga radi retry a ne QUIT !

stanje semafora fakt_doks prije testa

"bjasko";"free           ";1164;1164
"vzeljka";"free           ";1164;1164

ja u pregledu i čekam, željka u međuvremenu napravila jedan dokument, stanje semafora:

"bjasko";"free           ";1164;1165;"2012-02-09 11:26:18.824021";"vzeljka";"";"{"101000360   "}" 
"vzeljka";"free           ";1165;1165;"2012-01-23 09:35:12.188754";"vzeljka";"";"" 

sada željka pravi novi dokument i ažurira ga ali ja hoću da radim refresh podataka, stavio sam break point na SELECT/UPDATE

uradio sam SELECT i stao sam.....

željka napravila promjene.... snimila dokument, stanje semafora mi je ovakvo:

"bjasko";"free           ";1164;1166;"2012-02-09 11:26:18.824021";"vzeljka";"";"{"101000360   ","101000361   "}" 
"vzeljka";"free           ";1166;1166;"2012-01-23 09:35:12.188754";"vzeljka";"";"" 

BINGO !!!! evo ga novi dokument !!! iako ga nema u ovom mom SELECT-u koji sam napravio.

i moj ga UPDATE sroka !!!!!

O tome ja govorim čitavo vrijeme.

E sada pošto sam ubacio ovo SET TRANSACTION.... rezultiralo mi je greškom kako si i rekao. CURRENT TRANSACTION ABORTED... i izbacio me.

Saša Vranić je napisao/la:

E sada pošto sam ubacio ovo SET TRANSACTION.... rezultiralo mi je greškom kako si i rekao. CURRENT TRANSACTION ABORTED... i izbacio me.

a šta je sa verzijom koja handlira grešku ? da li ponovi transakciju ?

ne ne, to je prije ovoga što si ti napravio... idem sada sa ovim novim bildom

moralo bi da je ponovi - da uradi rollback (čime bi rekao - ok ja nisam ništa uradio) i da ponovi select, ali ovaj put sa željkinim dokumentima ...

I to bi bilo praktično rješenje problema.

Mislim da smo napokon blizu rješenja :)

stanje semafora:

"bjasko";"free           ";1166;1166;"" 
"vzeljka";"free           ";1166;1166;"" 

moj SELECT, stanje semafora

"bjasko";"free           ";1166;1167;"{"101000362   "}" 
"vzeljka";"free           ";1167;1167;"" 

ja čekam ...

željka ažurirala novi dokument, stanje semafora:

"bjasko";"free           ";1166;1168;"{"101000362   ","101000363   "}" 
"vzeljka";"free           ";1168;1168;"" 

dobio sam opet grešku: ERROR TRANSACTION .....

pa sam zatim dobio nešto novo: ERROR: COULD NOT SERIALIZE ACCESS DUE TO CURRENT...

i onda zaobiđe ovaj kod koji si stavio, zato što je _update_obj = FALSE nije NIL :)

sad ću postaviti i tu provjeru

nešto interneta nestade....

commit

ispravio sam grešaka....

sada kada sam pokrenuo isti test, desio se rollback i ponovo je ušao u funkciju i očitao mi kompletan IDS

međutim, opet u konačnici nisam imao taj dokument, pa idem ponoviti ponovo proceduru... da nisam nešto propustio

ne mogu se zakačiti više za testni pgsql... nešto je puklo oko interneta, redmine jedva radi

bringouts-MacBook:common bringout$ ping 192.168.45.170
PING 192.168.45.170 (192.168.45.170): 56 data bytes
Request timeout for icmp_seq 0
Request timeout for icmp_seq 1
Request timeout for icmp_seq 2
Request timeout for icmp_seq 3

je li sada progulilo ?

svejedno, dodao sam return nakon rekurzivnog poziva ... mislim da je to bilo problematično.

napravi pull novi pa testiraj sa novim buildom

ovo je nepotrebno:

https://github.com/knowhow/F18_knowhow/blob/36972feef850d6480f1bd058595838f32b08cd51/common/semaphores_ids_algoritam.prg#L285

jer smo već u get_ids_... nulirali

ne da je nepotrebno nego je suvišno

izbacio to i ispravio ovu grešku sa return, praktično return treba da vrati get_ids_.... zato što ona vraća niz

commit

Saša Vranić je napisao/la:

izbacio to i ispravio ovu grešku sa return, praktično return treba da vrati get_ids_.... zato što ona vraća niz

commit

od nas dvojice jednog pametnog čovjeka bi mog'o napravit'

izbaci altd iz repozitorija ako ti je ostalo

buni se travis https://travis-ci.org/knowhow/F18_knowhow/builds/3327966/#L101

ok :)

sada sam napravio test i uspješno dobio 2 promjene....

idem sada izbaciti i iz ažuriranja one sleep itd....

by the way nemoj se zaboraviti prijaviti na trello trebaće mi to

e sada jedna stvar koju sam primjetio je da kada se radi update_rec... verzija se ne setuje kako treba

znači nakon update-a podataka imam:

user     /   version    / last_version 
------------------------------------------
bjasko   /    100       /    102
vzeljka  /    101       /    102        <<<<<<<<< kod željke se ne setuje 102 kao verzija, nego ostane na 101

ovo si garant ti nešto čačkao

i još jedna stvar, kod ovog ponavljanja treba uvesti da se ne pojavljuju alerti

Znači sada sam testirao rad i sada fino osvježava i dobijem sve što je naknadno došlo u semafore...

Ostalo još da se naprave

• isključiti ALERT-e kod ovih retry operacija
• pronaći uzrok problema što se ne setuje ova verzija

isključio alert poruke u ovom slučaju.... commit

setovanje version i last_trans_version

ispravljeno, sada se setuje verzija dobro