Those of you who attended our talk at the last User Conference in Vegas will know that we're a big fan of using system logs to help track down aberrant behaviour. Recently we were asked by RevSoft UK to help solve a recalcitrant problem that was being encountered by one of their clients.
Put simply, the client had upgraded to 9.2.1 from 9.2 and was finding that whilst they could use the System Editor++ to open rows, any attempts to open Stored Procedures would result in a system hang. The engine would report that it was "processing" but was unresponsive and could only be closed from the task manager.
The first thing that we did was confirm that the SE++ worked as expected in SYSPROG. It did. We then created a new application and repeated the test there. It still worked. We then created an application inheriting from the client application and tested there. It failed. So we knew that the issue was localised to the client application. The question was WHERE was it actually crashing? We created a profile log and ran the application to point of crash and we were able to determine that the system was hanging inside a UTILITY call from DIALOG_BOX.
Moving on to the next logical step we wrote a small program to look for programs in SYSPROG that also existed in the client application. This revealed only a few potential mismatches. Of particular interest was a localised version of CENTER_WINDOW that took only 1 parameter instead of 3 and a localised version of OBJ_CALL_EVENT that took 0 parameters instead of 12.
Looking at the SYSREPOSEVENTEXEs for the Open Source Code dialog it was apparent that it made heavy use of OBJ_CALL_EVENT but that the Open Row dialog didn't use it at all.
So problem solved... DELETE_ROW "SYSOBJ","$OBJ_CALL_EVENT*CLIENTAPP" log off, log back in and all would be good.
Except it wasn't. We still had the same problem.
Time for the next phase - we installed a linear hash log and what we saw was as follows :-
RD 48 SYSPROG*OIWINEXE**RTI_EDITOR_ENTITY_OPEN OK
RD 54 SYSPROG**RTI_EDITOR_ENTITY_OPEN OK
RD 67 SYSPROG**RTI_EDITOR_ENTITY_OPEN ERROR:100 FILE:0 GROUP:0
RD 48 CLIENTAPP*STPROCEXE**OBJ_CALL_EVENT OK
RD 43 $OBJ_CALL_EVENT*CLIENTAPP ERROR:100 FILE:0 GROUP:0
RD 13 SET_DIALOG_INFO ERROR:100 FILE:0 GROUP:0
RD 43 $SET_DIALOG_INFO OK
So interpreting this for you... firstly the code RD simply means "Read". The number following is a filehandle. The file corresponding to the file handle can be found earlier in the log.
RD 48 SYSPROG*OIWINEXE**RTI_EDITOR_ENTITY_OPEN OK
The system reads the SYSREPOS entry for RTI_EDITOR_ENTITY_OPEN and determines that it must read the RTI_EDITOR_ENTITY_OPEN from SYSREPOSWINEXES. As stated we can tell that this is reading from SYSREPOS as described above OR by deducing it from the key structure.
RD 54 SYSPROG**RTI_EDITOR_ENTITY_OPEN OK
The compiled window is read
RD 67 SYSPROG**RTI_EDITOR_ENTITY_OPEN ERROR:100 FILE:0 GROUP:0
The SYSREPOSLANGUAGES table is checked to see if any alternative language defintions have been set up for this window. There haven't been so we get an FS100 - REC_DNE_EXIST$. This is benign.
RD 48 CLIENTAPP*STPROCEXE**OBJ_CALL_EVENT OK
It then goes back to SYSREPOS because the CREATE quick event of the window tells it to run a procedure calleed OBJ_CALL_EVENT. So it looks for the SYSREPOS entry called CLIENTAPP*STPROCEXE**OBJ_CALL_EVENT. It find this entry and the next line
RD 43 $OBJ_CALL_EVENT*CLIENTAPP ERROR:100 FILE:0 GROUP:0
shows that it has been told that it will find this object code in SYSOBJ with a row id of $OBJ_CALL_EVENT*CLIENTAPP. This read fails (because earlier we deleted the code) - this is not quite so benign as now the CREATE event will fail.
The system then carries on with the Dialog Logic :-
RD 13 SET_DIALOG_INFO ERROR:100 FILE:0 GROUP:0
RD 43 $SET_DIALOG_INFO OK
Now note that it DOESN'T try and read $OBJ_CALL_EVENT*SYSPROG as an RTP27 call would. RTP27 would automatically traverse the inheritance chain looking for the object code. Rather it assumes that it has got the correct definition and continues. This is because OBJ_CALL_EVENT is a Quick Event on the CREATE of the Source Code Open Dialog so it is called via a REPOSITORY EXECUTE. When the REPOSITORY EXECUTE is unable to load the code, rather than error out it just ignores the failure. Consequently the CREATE event never runs and the Dialog (which starts life invisible) is never made visible. So it is there on the desktop awaiting input but can never be closed as it can not be seen. Earlier in the log we could see GET_REPOS_ENTITIES being called and this was a clue to the fact that the Dialog was operating.
So we went into the Application Manager and deleted the SYSREPOS entry for OBJ_CALL_EVENT, logged out, back in and all was well with the world again. And the moral of this story (apart from the one involving routines named the same way as system routines)? When dealing with items that are tracked in the Repository - use Repository methods to manipulate them!
Put simply, the client had upgraded to 9.2.1 from 9.2 and was finding that whilst they could use the System Editor++ to open rows, any attempts to open Stored Procedures would result in a system hang. The engine would report that it was "processing" but was unresponsive and could only be closed from the task manager.
The first thing that we did was confirm that the SE++ worked as expected in SYSPROG. It did. We then created a new application and repeated the test there. It still worked. We then created an application inheriting from the client application and tested there. It failed. So we knew that the issue was localised to the client application. The question was WHERE was it actually crashing? We created a profile log and ran the application to point of crash and we were able to determine that the system was hanging inside a UTILITY call from DIALOG_BOX.
Moving on to the next logical step we wrote a small program to look for programs in SYSPROG that also existed in the client application. This revealed only a few potential mismatches. Of particular interest was a localised version of CENTER_WINDOW that took only 1 parameter instead of 3 and a localised version of OBJ_CALL_EVENT that took 0 parameters instead of 12.
Looking at the SYSREPOSEVENTEXEs for the Open Source Code dialog it was apparent that it made heavy use of OBJ_CALL_EVENT but that the Open Row dialog didn't use it at all.
So problem solved... DELETE_ROW "SYSOBJ","$OBJ_CALL_EVENT*CLIENTAPP" log off, log back in and all would be good.
Except it wasn't. We still had the same problem.
Time for the next phase - we installed a linear hash log and what we saw was as follows :-
RD 48 SYSPROG*OIWINEXE**RTI_EDITOR_ENTITY_OPEN OK
RD 54 SYSPROG**RTI_EDITOR_ENTITY_OPEN OK
RD 67 SYSPROG**RTI_EDITOR_ENTITY_OPEN ERROR:100 FILE:0 GROUP:0
RD 48 CLIENTAPP*STPROCEXE**OBJ_CALL_EVENT OK
RD 43 $OBJ_CALL_EVENT*CLIENTAPP ERROR:100 FILE:0 GROUP:0
RD 13 SET_DIALOG_INFO ERROR:100 FILE:0 GROUP:0
RD 43 $SET_DIALOG_INFO OK
So interpreting this for you... firstly the code RD simply means "Read". The number following is a filehandle. The file corresponding to the file handle can be found earlier in the log.
RD 48 SYSPROG*OIWINEXE**RTI_EDITOR_ENTITY_OPEN OK
The system reads the SYSREPOS entry for RTI_EDITOR_ENTITY_OPEN and determines that it must read the RTI_EDITOR_ENTITY_OPEN from SYSREPOSWINEXES. As stated we can tell that this is reading from SYSREPOS as described above OR by deducing it from the key structure.
RD 54 SYSPROG**RTI_EDITOR_ENTITY_OPEN OK
The compiled window is read
RD 67 SYSPROG**RTI_EDITOR_ENTITY_OPEN ERROR:100 FILE:0 GROUP:0
The SYSREPOSLANGUAGES table is checked to see if any alternative language defintions have been set up for this window. There haven't been so we get an FS100 - REC_DNE_EXIST$. This is benign.
RD 48 CLIENTAPP*STPROCEXE**OBJ_CALL_EVENT OK
It then goes back to SYSREPOS because the CREATE quick event of the window tells it to run a procedure calleed OBJ_CALL_EVENT. So it looks for the SYSREPOS entry called CLIENTAPP*STPROCEXE**OBJ_CALL_EVENT. It find this entry and the next line
RD 43 $OBJ_CALL_EVENT*CLIENTAPP ERROR:100 FILE:0 GROUP:0
shows that it has been told that it will find this object code in SYSOBJ with a row id of $OBJ_CALL_EVENT*CLIENTAPP. This read fails (because earlier we deleted the code) - this is not quite so benign as now the CREATE event will fail.
The system then carries on with the Dialog Logic :-
RD 13 SET_DIALOG_INFO ERROR:100 FILE:0 GROUP:0
RD 43 $SET_DIALOG_INFO OK
Now note that it DOESN'T try and read $OBJ_CALL_EVENT*SYSPROG as an RTP27 call would. RTP27 would automatically traverse the inheritance chain looking for the object code. Rather it assumes that it has got the correct definition and continues. This is because OBJ_CALL_EVENT is a Quick Event on the CREATE of the Source Code Open Dialog so it is called via a REPOSITORY EXECUTE. When the REPOSITORY EXECUTE is unable to load the code, rather than error out it just ignores the failure. Consequently the CREATE event never runs and the Dialog (which starts life invisible) is never made visible. So it is there on the desktop awaiting input but can never be closed as it can not be seen. Earlier in the log we could see GET_REPOS_ENTITIES being called and this was a clue to the fact that the Dialog was operating.
So we went into the Application Manager and deleted the SYSREPOS entry for OBJ_CALL_EVENT, logged out, back in and all was well with the world again. And the moral of this story (apart from the one involving routines named the same way as system routines)? When dealing with items that are tracked in the Repository - use Repository methods to manipulate them!
Labels: LH, Logs, OeProfile, Repository
| Making Databases Happen |
USA +1 267 238 3814
|